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,89 @@
+import structlog
+
+from django_structlog.middlewares.request import RequestMiddleware
+
+
+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()
+
+
+class NewRelicProcessor:
+
+    """
+    New Relic structlog's processor.
+
+    It adds extra fields. Borrowed from
+    https://github.com/newrelic/newrelic-python-agent/blob/c1764f8a/newrelic/api/log.py#L39
+
+    It must be *before*
+    ``structlog.stdlib.ProcessorFormatter.remove_processors_meta`` to have
+    access to ``_record`` key.
+    """
+
+    def __call__(self, logger, method_name, event_dict):
+        # Import ``newrelic`` here because it's only installed in production
+        from newrelic.api.log import format_exc_info  # noqa
+        from newrelic.api.time_trace import get_linking_metadata  # noqa
+
+        if not isinstance(event_dict, dict):
+            return event_dict
+
+        record = event_dict.get('_record')
+        if record is None:
+            return event_dict
+
+        event_dict.update(get_linking_metadata())
+
+        output = {
+            # "timestamp": int(record.created * 1000),
+            # "message": record.getMessage(),
+            "message": event_dict['event'],
+            # "log.level": record.levelname,
+            # "logger.name": record.name,
+            "thread.id": record.thread,
+            "thread.name": record.threadName,
+            "process.id": record.process,
+            "process.name": record.processName,
+            "file.name": record.pathname,
+            "line.number": record.lineno,
+        }
+
+        if record.exc_info:
+            output.update(format_exc_info(record.exc_info))
+
+        event_dict.update(output)
+        return event_dict
+
+
+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(),
+        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,
+)

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

@@ -2,7 +2,6 @@
 
 import functools
 import json
-import logging
 import re
 
 from django.shortcuts import get_object_or_404
@@ -15,6 +14,8 @@
 from rest_framework.response import Response
 from rest_framework.views import APIView
 
+import structlog
+
 from readthedocs.api.v2.mixins import CachedResponseMixin
 from readthedocs.api.v2.permissions import IsAuthorizedToViewVersion
 from readthedocs.builds.constants import EXTERNAL
@@ -25,7 +26,7 @@
 from readthedocs.projects.models import Project
 from readthedocs.storage import build_media_storage
 
-log = logging.getLogger(__name__)
+log = structlog.get_logger(__name__)
 
 
 def escape_selector(selector):
@@ -143,11 +144,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': ['null'],
+                '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

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,5 @@ 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
+structlog==21.3.0