Force all API loggers to be structured (#4331)

Author: sarayourfriend

api/conf/settings/logging.py

@@ -31,72 +31,101 @@ def health_check_filter(record: LogRecord) -> bool:
     "GC_DEBUG_LOGGING", cast=lambda x: x.split("|") if x else [], default=""
 )
 
+# This shared_processors approach is modified from structlog's
+# documentation for how to handle non-structured logs in a structured format
+# https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
+timestamper = structlog.processors.TimeStamper(fmt="iso")
+
+shared_processors = [
+    structlog.contextvars.merge_contextvars,
+    structlog.stdlib.add_logger_name,
+    structlog.stdlib.add_log_level,
+    structlog.stdlib.PositionalArgumentsFormatter(),
+    structlog.processors.CallsiteParameterAdder(
+        {
+            structlog.processors.CallsiteParameter.FILENAME,
+            structlog.processors.CallsiteParameter.FUNC_NAME,
+            structlog.processors.CallsiteParameter.LINENO,
+        }
+    ),
+    structlog.processors.StackInfoRenderer(),
+    structlog.processors.format_exc_info,
+    structlog.processors.UnicodeDecoder(),
+]
+
+
+# These loggers duplicate django-structlog's request start/finish
+# logs, as well as our nginx request logs. We want to keep only the
+# start/finish logs and the nginx logs for access logging, otherwise
+# we are just duplicating information!
+_UNWANTED_LOGGERS = {
+    "uvicorn.access",
+    "django.request",
+}
+
+
+def suppress_unwanted_logs(record: LogRecord) -> bool:
+    return (
+        record.name not in _UNWANTED_LOGGERS
+        and "GET /healthcheck" not in record.getMessage()
+    )
+
+
 # Logging configuration
 LOGGING = {
-    # NOTE: Most of this is inherited from the default configuration
     "version": 1,
     "disable_existing_loggers": False,
     "filters": {
-        "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"},
-        "require_debug_true": {"()": "django.utils.log.RequireDebugTrue"},
-        "health_check": {
+        "suppress_unwanted_logs": {
             "()": "django.utils.log.CallbackFilter",
-            "callback": health_check_filter,
+            "callback": suppress_unwanted_logs,
         },
     },
     "formatters": {
-        "console": {
-            "format": "[{asctime} - {name} - {lineno:>3}][{levelname}] {message}",
-            "style": "{",
-        },
         "structured": {
             "()": structlog.stdlib.ProcessorFormatter,
-            "processor": structlog.processors.JSONRenderer()
-            if LOG_PROCESSOR == "json"
-            else structlog.dev.ConsoleRenderer(),
+            "processor": (
+                structlog.processors.JSONRenderer()
+                if LOG_PROCESSOR == "json"
+                else structlog.dev.ConsoleRenderer()
+            ),
+            "foreign_pre_chain": [
+                timestamper,
+                # Explanations from https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
+                # Add the log level and a timestamp to the event_dict if the log entry
+                # is not from structlog.
+                structlog.stdlib.add_log_level,
+                # Add extra attributes of LogRecord objects to the event dictionary
+                # so that values passed in the extra parameter of log methods pass
+                # through to log output.
+                structlog.stdlib.ExtraAdder(),
+            ]
+            + shared_processors,
         },
     },
     "handlers": {
-        # Default console logger
-        "console": {
-            "level": LOG_LEVEL,
-            "class": "logging.StreamHandler",
-            "formatter": "console",
-        },
         "console_structured": {
             "level": LOG_LEVEL,
             "class": "logging.StreamHandler",
             "formatter": "structured",
+            "filters": ["suppress_unwanted_logs"],
         },
     },
+    "root": {
+        "handlers": ["console_structured"],
+        "level": LOG_LEVEL,
+        "propagate": False,
+    },
     "loggers": {
-        # Application
-        "django_structlog": {
-            "handlers": ["console_structured"],
-            "level": LOG_LEVEL,
-            "propagate": False,
-        },
-        "api": {
-            "handlers": ["console_structured"],
-            "level": LOG_LEVEL,
-            "propagate": False,
-        },
-        # External
         "django": {
-            "handlers": ["console"],
+            "handlers": ["console_structured"],
             # Keep this at info to avoid django internal debug logs;
             # we just want our own debug logs when log level is set to debug
             "level": "INFO",
             "propagate": False,
         },
-        "uvicorn.error": {  # Using just "uvicorn" will re-enable access logs
-            "handlers": ["console"],
-            "level": LOG_LEVEL,
-            "propagate": False,
-        },
-        # Default handler for all other loggers
-        "": {
-            "handlers": ["console"],
+        "uvicorn": {
+            "handlers": ["console_structured"],
             "level": LOG_LEVEL,
         },
     },
@@ -105,22 +134,11 @@ def health_check_filter(record: LogRecord) -> bool:
 # https://django-structlog.readthedocs.io/en/latest/getting_started.html
 structlog.configure(
     processors=[
-        structlog.contextvars.merge_contextvars,
+        timestamper,
         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.CallsiteParameterAdder(
-            {
-                structlog.processors.CallsiteParameter.FILENAME,
-                structlog.processors.CallsiteParameter.FUNC_NAME,
-                structlog.processors.CallsiteParameter.LINENO,
-            }
-        ),
-        structlog.processors.StackInfoRenderer(),
-        structlog.processors.format_exc_info,
-        structlog.processors.UnicodeDecoder(),
+    ]
+    + shared_processors
+    + [
         structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
     ],
     logger_factory=structlog.stdlib.LoggerFactory(),