Minimal implementation of structlog for EmbedAPI

Use structlog _only_ for EmbedAPI v2/v3 for now. We will do a test in production
to this and decide the migration path for the whole codebase.

Author: humitos

readthedocs/core/apps.py

@@ -11,3 +11,6 @@ class CoreAppConfig(AppConfig):
 
     def ready(self):
         import readthedocs.core.signals  # noqa
+
+        # Import `readthedocs.core.logs` to set up structlog
+        import readthedocs.core.logs  # noqa

readthedocs/core/logs.py

@@ -0,0 +1,44 @@
+import structlog
+
+from django_structlog.middlewares.request import RequestMiddleware
+
+logger = structlog.getLogger(__name__)
+
+
+class ReadTheDocsRequestMiddleware(RequestMiddleware):
+    """
+    ``ReadTheDocsRequestMiddleware`` adds request metadata to ``structlog``'s logger context.
+
+    This middleware overrides the original ``format_request`` to log the full
+    URL instead of just its path.
+
+    >>> MIDDLEWARE = [
+    ...     # ...
+    ...     'readthedocs.core.logs.ReadTheDocsRequestMiddleware',
+    ... ]
+
+    """
+
+    def format_request(self, request):
+        return request.build_absolute_uri()
+
+structlog.configure(
+    processors=[
+        structlog.stdlib.filter_by_level,
+        structlog.processors.TimeStamper(fmt='iso'),
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.PositionalArgumentsFormatter(),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.format_exc_info,
+        structlog.processors.UnicodeDecoder(),
+        # TODO: research a little how to combine both (``wrap_for_formatter``
+        # for regular logging and ``render_to_log_kwargs`` for NewRelic)
+        # structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        structlog.stdlib.render_to_log_kwargs,
+    ],
+    context_class=structlog.threadlocal.wrap_dict(dict),
+    logger_factory=structlog.stdlib.LoggerFactory(),
+    wrapper_class=structlog.stdlib.BoundLogger,
+    cache_logger_on_first_use=True,
+)

readthedocs/core/signals.py

@@ -8,7 +8,6 @@
 from django.db.models.signals import pre_delete
 from django.dispatch import Signal, receiver
 
-from django_structlog.signals import bind_extra_request_metadata
 from rest_framework.permissions import SAFE_METHODS
 from simple_history.models import HistoricalRecords
 from simple_history.signals import pre_create_historical_record
@@ -147,14 +146,4 @@ def add_extra_historical_fields(sender, **kwargs):
         history_instance.extra_history_browser = request.headers.get('User-Agent')
 
 
-@receiver(bind_extra_request_metadata)
-def bind_user_username(request, logger, **kwargs):
-    logger.bind(user_username=getattr(request.user, 'username', ''))
-
-
-@receiver(bind_extra_request_metadata)
-def rewrite_request(request, logger, **kwargs):
-    logger.bind(absolute_url=request.build_absolute_uri())
-
-
 signals.check_request_enabled.connect(decide_if_cors)

readthedocs/embed/v3/views.py

@@ -344,7 +344,8 @@ def get(self, request):  # noqa
         }
         log.info(
             'EmbedAPI successful response.',
-            project=self.unresolved_url.project.slug if not external else domain,
+            project_slug=self.unresolved_url.project.slug if not external else None,
+            domain=domain if external else None,
             url=url,
             referer=request.META.get('HTTP_REFERER'),
             external=external,

readthedocs/embed/views.py

@@ -143,11 +143,9 @@ def get(self, request):
             )
 
         log.info(
-            'EmbedAPI successful response. '
-            'project=%s version=%s doc=%s section=%s path=%s '
-            'url=%s referer=%s hoverxref-version=%s',
-            project=project.slug,
-            version=version.verbose_name,
+            'EmbedAPI successful response.',
+            project_slug=project.slug,
+            version_slug=version.slug,
             doct=doc,
             section=section,
             path=path,

readthedocs/settings/base.py

@@ -1,10 +1,10 @@
 # pylint: disable=missing-docstring
 
+import logging
 import os
 import subprocess
 import socket
 
-import requests
 import structlog
 
 from celery.schedules import crontab
@@ -27,27 +27,7 @@
 
 
 _ = gettext = lambda s: s
-log = structlog.get_logger(__name__)
-
-def send_to_newrelic(logger, log_method, event_dict):
-
-    if 'request' in event_dict:
-        # WSGIRequest is not JSONSerializable
-        event_dict.pop('request')
-
-    # Uses the New Relic Log API
-    # https://docs.newrelic.com/docs/logs/log-management/log-api/introduction-log-api/
-    headers = {"Api-Key": ''}
-
-    # Our log message and all the event context is sent as a JSON string
-    # in the POST body
-    # https://docs.newrelic.com/docs/logs/log-management/log-api/introduction-log-api/#json-content
-    payload = {
-        "message": f"{log_method} - {event_dict['event']}",
-    }
-    payload.update(event_dict)
-    requests.post("https://log-api.newrelic.com/log/v1", json=payload, headers=headers)
-    return event_dict
+log = logging.getLogger(__name__)
 
 
 class CommunityBaseSettings(Settings):
@@ -271,7 +251,7 @@ def USE_PROMOS(self):  # noqa
         'readthedocs.core.middleware.ReferrerPolicyMiddleware',
         'django_permissions_policy.PermissionsPolicyMiddleware',
         'simple_history.middleware.HistoryRequestMiddleware',
-        'django_structlog.middlewares.RequestMiddleware',
+        'readthedocs.core.logs.ReadTheDocsRequestMiddleware',
     )
 
     AUTHENTICATION_BACKENDS = (
@@ -816,6 +796,11 @@ def DOCKER_LIMITS(self):
         'version': 1,
         'disable_existing_loggers': True,
         'formatters': {
+            'default': {
+                'format': LOG_FORMAT,
+                'datefmt': '%d/%b/%Y %H:%M:%S',
+            },
+            # structlog
             "plain_console": {
                 "()": structlog.stdlib.ProcessorFormatter,
                 "processor": structlog.dev.ConsoleRenderer(),
@@ -829,7 +814,7 @@ def DOCKER_LIMITS(self):
             'console': {
                 'level': 'INFO',
                 'class': 'logging.StreamHandler',
-                'formatter': 'plain_console',
+                'formatter': 'default',
             },
             'debug': {
                 'level': 'DEBUG',
@@ -847,6 +832,12 @@ def DOCKER_LIMITS(self):
                 # Always send from the root, handlers can filter levels
                 'level': 'INFO',
             },
+            'django_structlog': {
+                'handlers': ['console'],
+                'level': 'INFO',
+                # Don't double log at the root logger for these.
+                'propagate': False,
+            },
             'readthedocs': {
                 'handlers': ['debug', 'console'],
                 'level': 'DEBUG',
@@ -859,25 +850,6 @@ def DOCKER_LIMITS(self):
             },
         },
     }
-    structlog.configure(
-        processors=[
-            structlog.stdlib.filter_by_level,
-            structlog.processors.TimeStamper(fmt="iso"),
-            structlog.stdlib.add_logger_name,
-            structlog.stdlib.add_log_level,
-            structlog.stdlib.PositionalArgumentsFormatter(),
-            structlog.processors.StackInfoRenderer(),
-            structlog.processors.format_exc_info,
-            structlog.processors.UnicodeDecoder(),
-            send_to_newrelic,
-            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
-        ],
-        context_class=structlog.threadlocal.wrap_dict(dict),
-        logger_factory=structlog.stdlib.LoggerFactory(),
-        wrapper_class=structlog.stdlib.BoundLogger,
-        cache_logger_on_first_use=True,
-    )
-
 
     # MailerLite API for newsletter signups
     MAILERLITE_API_SUBSCRIBERS_URL = 'https://api.mailerlite.com/api/v2/subscribers'

readthedocs/settings/dev.py

@@ -57,6 +57,7 @@ def DATABASES(self):  # noqa
     def LOGGING(self):  # noqa - avoid pep8 N802
         logging = super().LOGGING
         logging['handlers']['console']['level'] = 'DEBUG'
+        logging['formatters']['default']['format'] = '[%(asctime)s] ' + self.LOG_FORMAT
         # Allow Sphinx and other tools to create loggers
         logging['disable_existing_loggers'] = False
         return logging

readthedocs/settings/docker_compose.py

@@ -77,6 +77,7 @@ def RTD_EMBED_API_EXTERNAL_DOMAINS(self):
     @property
     def LOGGING(self):
         logging = super().LOGGING
+        logging['handlers']['console']['formatter'] = 'plain_console'
         logging['loggers'].update({
             # Disable S3 logging
             'boto3': {

requirements/docker.txt

@@ -31,3 +31,6 @@ tox==3.24.4
 
 # AWS utilities to use against MinIO
 awscli==1.22.5
+
+# Used together with structlog to have nicer logs locally
+rich==10.14.0

requirements/pip.txt

@@ -120,4 +120,4 @@ django-csp==3.7
 # For setting the permissions-policy security header
 django-permissions-policy==4.5.0
 
-django-structlog==2.1.3
+django-structlog==2.2.0