Break out commits for review.

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

@@ -7,6 +7,7 @@
 from django.db.models import Count
 from django.db.models.signals import pre_delete
 from django.dispatch import Signal, receiver
+
 from rest_framework.permissions import SAFE_METHODS
 from simple_history.models import HistoricalRecords
 from simple_history.signals import pre_create_historical_record

readthedocs/embed/v3/views.py

@@ -1,10 +1,11 @@
 """Views for the EmbedAPI v3 app."""
 
-import logging
 import re
 from urllib.parse import urlparse
 import requests
 
+import structlog
+
 from selectolax.parser import HTMLParser
 
 from django.conf import settings
@@ -24,7 +25,7 @@
 from readthedocs.projects.constants import PUBLIC
 from readthedocs.storage import build_media_storage
 
-log = logging.getLogger(__name__)
+log = structlog.get_logger(__name__)
 
 
 class EmbedAPIBase(CachedResponseMixin, APIView):
@@ -341,6 +342,15 @@ def get(self, request):  # noqa
             'content': content,
             'external': external,
         }
+        log.info(
+            'EmbedAPI successful response.',
+            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,
+            hoverxref_version=request.META.get('HTTP_X_HOVERXREF_VERSION'),
+        )
         return Response(response)
 
 

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):
@@ -142,6 +143,17 @@ def get(self, request):
                 status=status.HTTP_404_NOT_FOUND
             )
 
+        log.info(
+            'EmbedAPI successful response.',
+            project_slug=project.slug,
+            version_slug=version.slug,
+            doct=doc,
+            section=section,
+            path=path,
+            url=url,
+            referer=request.META.get('HTTP_REFERER'),
+            hoverxref_version=request.META.get('HTTP_X_HOVERXREF_VERSION'),
+        )
         return Response(response)
 
 

readthedocs/settings/base.py

@@ -5,6 +5,8 @@
 import subprocess
 import socket
 
+import structlog
+
 from celery.schedules import crontab
 
 from readthedocs.core.settings import Settings
@@ -249,6 +251,7 @@ def USE_PROMOS(self):  # noqa
         'readthedocs.core.middleware.ReferrerPolicyMiddleware',
         'django_permissions_policy.PermissionsPolicyMiddleware',
         'simple_history.middleware.HistoryRequestMiddleware',
+        'readthedocs.core.logs.ReadTheDocsRequestMiddleware',
     )
 
     AUTHENTICATION_BACKENDS = (
@@ -797,18 +800,27 @@ def DOCKER_LIMITS(self):
                 'format': LOG_FORMAT,
                 'datefmt': '%d/%b/%Y %H:%M:%S',
             },
+            # structlog
+            "plain_console": {
+                "()": structlog.stdlib.ProcessorFormatter,
+                "processor": structlog.dev.ConsoleRenderer(),
+            },
+            "key_value": {
+                "()": structlog.stdlib.ProcessorFormatter,
+                "processor": structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']),
+            },
         },
         'handlers': {
             'console': {
                 'level': 'INFO',
                 'class': 'logging.StreamHandler',
-                'formatter': 'default'
+                'formatter': 'default',
             },
             'debug': {
                 'level': 'DEBUG',
                 'class': 'logging.handlers.RotatingFileHandler',
                 'filename': os.path.join(LOGS_ROOT, 'debug.log'),
-                'formatter': 'default',
+                'formatter': 'key_value',
             },
             'null': {
                 'class': 'logging.NullHandler',
@@ -820,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',

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

@@ -119,3 +119,6 @@ django-debug-toolbar==3.2.2
 django-csp==3.7
 # For setting the permissions-policy security header
 django-permissions-policy==4.5.0
+
+django-structlog==2.2.0
+structlog==21.3.0