Logging: Setup django-structlog

config/django/base.py

@@ -83,8 +83,6 @@
 
 ROOT_URLCONF = "config.urls"
 
-print(os.path.join(APPS_DIR, "templates"))
-
 TEMPLATES = [
     {
         "BACKEND": "django.template.backends.django.DjangoTemplates",
@@ -174,6 +172,13 @@
 
 DEFAULT_AUTO_FIELD = "django.db.models.BigAutoField"
 
+from config.settings.loggers.settings import *  # noqa
+from config.settings.loggers.setup import LoggersSetup  # noqa
+
+INSTALLED_APPS, MIDDLEWARE = LoggersSetup.setup_settings(INSTALLED_APPS, MIDDLEWARE)
+LoggersSetup.setup_structlog()
+LOGGING = LoggersSetup.setup_logging()
+
 from config.settings.celery import *  # noqa
 from config.settings.cors import *  # noqa
 from config.settings.email_sending import *  # noqa
@@ -189,6 +194,4 @@
 INSTALLED_APPS, MIDDLEWARE = DebugToolbarSetup.do_settings(INSTALLED_APPS, MIDDLEWARE)
 
 
-SHELL_PLUS_IMPORTS = [
-    "from styleguide_example.blog_examples.print_qs_in_shell.utils import print_qs"
-]
+SHELL_PLUS_IMPORTS = ["from styleguide_example.blog_examples.print_qs_in_shell.utils import print_qs"]

config/settings/debug_toolbar/setup.py

@@ -1,9 +1,5 @@
-import logging
-
 from django.urls import include, path
 
-logger = logging.getLogger("configuration")
-
 
 def show_toolbar(*args, **kwargs) -> bool:
     """
@@ -30,7 +26,6 @@ def show_toolbar(*args, **kwargs) -> bool:
     try:
         import debug_toolbar  # noqa
     except ImportError:
-        logger.info("No installation found for: django_debug_toolbar")
         return False
 
     return True
@@ -44,7 +39,6 @@ class DebugToolbarSetup:
     @staticmethod
     def do_settings(INSTALLED_APPS, MIDDLEWARE, middleware_position=None):
         _show_toolbar: bool = show_toolbar()
-        logger.info(f"Django Debug Toolbar in use: {_show_toolbar}")
 
         if not _show_toolbar:
             return INSTALLED_APPS, MIDDLEWARE

config/settings/loggers/settings.py

@@ -0,0 +1,16 @@
+import logging
+from enum import Enum
+
+from config.env import env, env_to_enum
+
+
+class LoggingFormat(Enum):
+    DEV = "dev"
+    JSON = "json"
+    LOGFMT = "logfmt"
+
+
+LOGGING_FORMAT = env_to_enum(LoggingFormat, env("LOGGING_FORMAT", default=LoggingFormat.DEV.value))
+
+DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL = logging.INFO
+DJANGO_STRUCTLOG_CELERY_ENABLED = True

config/settings/loggers/setup.py

@@ -0,0 +1,141 @@
+import logging
+
+import structlog
+
+
+class IgnoreFilter(logging.Filter):
+    def filter(self, record):
+        return False
+
+
+class LoggersSetup:
+    """
+    We use a class, just for namespacing convenience.
+    """
+
+    @staticmethod
+    def setup_settings(INSTALLED_APPS, MIDDLEWARE, middleware_position=None):
+        INSTALLED_APPS = INSTALLED_APPS + ["django_structlog"]
+
+        django_structlog_middleware = "django_structlog.middlewares.RequestMiddleware"
+
+        if middleware_position is None:
+            MIDDLEWARE = MIDDLEWARE + [django_structlog_middleware]
+        else:
+            # Grab a new copy of the list, since insert mutates the internal structure
+            _middleware = MIDDLEWARE[::]
+            _middleware.insert(middleware_position, django_structlog_middleware)
+
+            MIDDLEWARE = _middleware
+
+        return INSTALLED_APPS, MIDDLEWARE
+
+    @staticmethod
+    def setup_structlog():
+        from config.settings.loggers.settings import LOGGING_FORMAT, LoggingFormat
+
+        logging_format = LOGGING_FORMAT
+
+        extra_processors = []
+
+        if logging_format == LoggingFormat.DEV:
+            extra_processors = [
+                structlog.processors.format_exc_info,
+            ]
+
+        if logging_format in [LoggingFormat.JSON, LoggingFormat.LOGFMT]:
+            dict_tracebacks = structlog.processors.ExceptionRenderer(
+                structlog.processors.ExceptionDictTransformer(show_locals=False)
+            )
+            extra_processors = [
+                dict_tracebacks,
+            ]
+
+        structlog.configure(
+            processors=[
+                structlog.contextvars.merge_contextvars,
+                structlog.stdlib.filter_by_level,
+                structlog.processors.TimeStamper(fmt="iso", utc=True),
+                structlog.stdlib.add_logger_name,
+                structlog.stdlib.add_log_level,
+                structlog.stdlib.PositionalArgumentsFormatter(),
+                structlog.processors.StackInfoRenderer(),
+                structlog.dev.set_exc_info,
+                *extra_processors,
+                structlog.processors.UnicodeDecoder(),
+                structlog.processors.CallsiteParameterAdder(
+                    {
+                        structlog.processors.CallsiteParameter.FILENAME,
+                        structlog.processors.CallsiteParameter.FUNC_NAME,
+                        structlog.processors.CallsiteParameter.LINENO,
+                    }
+                ),
+                structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+            ],
+            logger_factory=structlog.stdlib.LoggerFactory(),
+            cache_logger_on_first_use=True,
+        )
+
+    @staticmethod
+    def setup_logging():
+        from config.settings.loggers.settings import LOGGING_FORMAT, LoggingFormat
+
+        logging_format = LOGGING_FORMAT
+        formatter = "dev"
+
+        if logging_format == LoggingFormat.DEV:
+            formatter = "dev"
+
+        if logging_format == LoggingFormat.JSON:
+            formatter = "json"
+
+        if logging_format == LoggingFormat.LOGFMT:
+            formatter = "logfmt"
+
+        return {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "dev": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processor": structlog.dev.ConsoleRenderer(),
+                },
+                "logfmt": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processor": structlog.processors.LogfmtRenderer(),
+                },
+                "json": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processor": structlog.processors.JSONRenderer(),
+                },
+            },
+            "filters": {
+                "ignore": {
+                    "()": "config.settings.loggers.setup.IgnoreFilter",
+                },
+            },
+            "handlers": {
+                "console": {
+                    "class": "logging.StreamHandler",
+                    "formatter": formatter,
+                }
+            },
+            "loggers": {
+                # We want to get rid of the runserver logs
+                "django.server": {"propagate": False, "handlers": ["console"], "filters": ["ignore"]},
+                # We want to get rid of the logs for 4XX and 5XX
+                "django.request": {"propagate": False, "handlers": ["console"], "filters": ["ignore"]},
+                "django_structlog": {
+                    "handlers": ["console"],
+                    "level": "INFO",
+                },
+                "celery": {
+                    "handlers": ["console"],
+                    "level": "INFO",
+                },
+                "styleguide_example": {
+                    "handlers": ["console"],
+                    "level": "INFO",
+                },
+            },
+        }

gunicorn.conf.py

@@ -1,8 +1,134 @@
-# If you are not having memory issues, just delete this.
-# This is primarily to prevent memory leaks
-# Based on https://devcenter.heroku.com/articles/python-gunicorn
-# Based on https://adamj.eu/tech/2019/09/19/working-around-memory-leaks-in-your-django-app/
-# https://docs.gunicorn.org/en/latest/settings.html#max-requests
-# https://docs.gunicorn.org/en/latest/settings.html#max-requests-jitter
-max_requests = 1200
-max_requests_jitter = 100
+# https://mattsegal.dev/django-gunicorn-nginx-logging.html
+# https://albersdevelopment.net/2019/08/15/using-structlog-with-gunicorn/
+
+import logging
+import logging.config
+import re
+
+import structlog
+
+
+def combined_logformat(logger, name, event_dict):
+    if event_dict.get("logger") == "gunicorn.access":
+        message = event_dict["event"]
+
+        parts = [
+            r"(?P<host>\S+)",  # host %h
+            r"\S+",  # indent %l (unused)
+            r"(?P<user>\S+)",  # user %u
+            r"\[(?P<time>.+)\]",  # time %t
+            r'"(?P<request>.+)"',  # request "%r"
+            r"(?P<status>[0-9]+)",  # status %>s
+            r"(?P<size>\S+)",  # size %b (careful, can be '-')
+            r'"(?P<referer>.*)"',  # referer "%{Referer}i"
+            r'"(?P<agent>.*)"',  # user agent "%{User-agent}i"
+        ]
+        pattern = re.compile(r"\s+".join(parts) + r"\s*\Z")
+        m = pattern.match(message)
+        res = m.groupdict()
+
+        if res["user"] == "-":
+            res["user"] = None
+
+        res["status"] = int(res["status"])
+
+        if res["size"] == "-":
+            res["size"] = 0
+        else:
+            res["size"] = int(res["size"])
+
+        if res["referer"] == "-":
+            res["referer"] = None
+
+        event_dict.update(res)
+        method, path, version = res["request"].split(" ")
+
+        event_dict["method"] = method
+        event_dict["path"] = path
+        event_dict["version"] = version
+
+    return event_dict
+
+
+def gunicorn_event_name_mapper(logger, name, event_dict):
+    logger_name = event_dict.get("logger")
+
+    if logger_name not in ["gunicorn.error", "gunicorn.access"]:
+        return event_dict
+
+    GUNICORN_BOOTING = "gunicorn.booting"
+    GUNICORN_REQUEST = "gunicorn.request_handling"
+    GUNICORN_SIGNAL = "gunicorn.signal_handling"
+
+    event = event_dict["event"].lower()
+
+    if logger_name == "gunicorn.error":
+        event_dict["message"] = event
+
+        if event.startswith("starting"):
+            event_dict["event"] = GUNICORN_BOOTING
+
+        if event.startswith("listening"):
+            event_dict["event"] = GUNICORN_BOOTING
+
+        if event.startswith("using"):
+            event_dict["event"] = GUNICORN_BOOTING
+
+        if event.startswith("booting"):
+            event_dict["event"] = GUNICORN_BOOTING
+
+        if event.startswith("handling signal"):
+            event_dict["event"] = GUNICORN_SIGNAL
+
+    if logger_name == "gunicorn.access":
+        event_dict["event"] = GUNICORN_REQUEST
+
+    return event_dict
+
+
+timestamper = structlog.processors.TimeStamper(fmt="iso", utc=True)
+pre_chain = [
+    # Add the log level and a timestamp to the event_dict if the log entry
+    # is not from structlog.
+    structlog.stdlib.add_log_level,
+    structlog.stdlib.add_logger_name,
+    timestamper,
+    combined_logformat,
+    gunicorn_event_name_mapper,
+]
+
+# https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L47
+CONFIG_DEFAULTS = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "root": {"level": "INFO", "handlers": ["default"]},
+    "loggers": {
+        "gunicorn.error": {"level": "INFO", "handlers": ["default"], "propagate": False, "qualname": "gunicorn.error"},
+        "gunicorn.access": {
+            "level": "INFO",
+            "handlers": ["default"],
+            "propagate": False,
+            "qualname": "gunicorn.access",
+        },
+        "django_structlog": {
+            "level": "INFO",
+            "handlers": [],
+            "propagate": False,
+        },
+    },
+    "handlers": {
+        "default": {
+            "class": "logging.StreamHandler",
+            "formatter": "json_formatter",
+        },
+    },
+    "formatters": {
+        "json_formatter": {
+            "()": structlog.stdlib.ProcessorFormatter,
+            "processor": structlog.processors.JSONRenderer(),
+            "foreign_pre_chain": pre_chain,
+        }
+    },
+}
+
+logging.config.dictConfig(CONFIG_DEFAULTS)

requirements/base.txt

@@ -13,6 +13,7 @@ django-filter==25.2
 django-extensions==4.1
 django-cors-headers==4.9.0
 django-storages==1.14.6
+django-structlog[celery]==9.1.1
 
 drf-jwt==1.19.2