Configure logging

caprover_deploy.sh

@@ -6,4 +6,3 @@ docker push iterativ/vbv-lernwelt-django
 
 # deploy to caprover
 caprover deploy -h https://captain.control.iterativ.ch -a vbv-lernwelt -i docker.io/iterativ/vbv-lernwelt-django
-

server/config/settings/base.py

@@ -7,7 +7,7 @@ from pathlib import Path
 import structlog
 from environs import Env
 
-from vbv_lernwelt.core.utils import add_app_info
+from vbv_lernwelt.core.utils import structlog_add_app_info
 
 SERVER_ROOT_DIR = Path(__file__).resolve(strict=True).parent.parent.parent
 # vbv_lernwelt/
@@ -135,6 +135,7 @@ AUTH_PASSWORD_VALIDATORS = [
 # ------------------------------------------------------------------------------
 # https://docs.djangoproject.com/en/dev/ref/settings/#middleware
 MIDDLEWARE = [
+    "vbv_lernwelt.core.middleware.security.GetIpBehindReverseProxyMiddleWare",
     "django.middleware.security.SecurityMiddleware",
     "corsheaders.middleware.CorsMiddleware",
     "whitenoise.middleware.WhiteNoiseMiddleware",
@@ -248,10 +249,6 @@ VBV_DJANGO_LOGGING_CONF = env(
 
 if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR":
     timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
-    pre_chain = [
-        structlog.stdlib.add_log_level,
-        timestamper,
-    ]
     LOGGING = {
         "version": 1,
         "disable_existing_loggers": False,
@@ -259,7 +256,10 @@ if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR":
             "colored": {
                 "()": structlog.stdlib.ProcessorFormatter,
                 "processor": structlog.dev.ConsoleRenderer(colors=True),
-                "foreign_pre_chain": pre_chain,
+                "foreign_pre_chain": [
+                    structlog.stdlib.add_log_level,
+                    timestamper,
+                ],
             },
         },
         "handlers": {
@@ -298,14 +298,25 @@ if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR":
         cache_logger_on_first_use=True,
     )
 else:
+    shared_processors = [
+        structlog.threadlocal.merge_threadlocal,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.add_logger_name,
+        structlog_add_app_info,
+        structlog.processors.TimeStamper(fmt="iso"),
+    ]
+
     LOGGING = {
         "version": 1,
         "disable_existing_loggers": True,
         "formatters": {
             "json": {
-                "()": "pythonjsonlogger.jsonlogger.JsonFormatter",
+                "()": structlog.stdlib.ProcessorFormatter,
-                "format": "%(asctime)s %(msecs)03d %(process)d %(thread)d %(levelname)s %(name)s %(filename)s %(lineno)d %(funcName)s %(message)s",  # noqa I004
+                "processors": [
-                "datefmt": "%Y-%m-%dT%H:%M:%S",
+                    structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+                    structlog.processors.JSONRenderer()
+                ],
+                "foreign_pre_chain": shared_processors,
             },
         },
         "handlers": {
@@ -332,7 +343,7 @@ else:
                 "level": "WARNING",
                 "propagate": False,
             },
-            "vbc_lernwelt": {
+            "vbv_lernwelt": {
                 "handlers": ["console", "file"],
                 "level": "DEBUG",
                 "propagate": False,
@@ -346,16 +357,7 @@ else:
     }
 
     structlog.configure(
-        processors=[
+        processors=shared_processors + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter,],
-            structlog.threadlocal.merge_threadlocal,
-            structlog.stdlib.filter_by_level,
-            add_app_info,
-            structlog.stdlib.PositionalArgumentsFormatter(),
-            structlog.processors.StackInfoRenderer(),
-            structlog.processors.format_exc_info,
-            structlog.processors.UnicodeDecoder(),
-            structlog.stdlib.render_to_log_kwargs,
-        ],
         context_class=dict,
         logger_factory=structlog.stdlib.LoggerFactory(),
         wrapper_class=structlog.stdlib.BoundLogger,

server/example.env

@@ -1,3 +1,3 @@
 export VBV_DATABASE_URL='postgres://vbv_lernwelt@localhost:5432/vbv_lernwelt'
-export VBV_DJANGO_LOGGING_CONF=VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR
+#export VBV_DJANGO_LOGGING_CONF=VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR
 export VBV_DJANGO_DEBUG=True

server/requirements/requirements-dev.txt

@@ -89,6 +89,8 @@ django-extensions==3.1.5
     # via -r requirements-dev.in
 django-htmx==1.8.0
     # via -r requirements.in
+django-ipware==4.0.2
+    # via -r requirements.in
 django-model-utils==4.2.0
     # via -r requirements.in
 django-ratelimit==3.0.1

server/requirements/requirements.in

@@ -22,6 +22,7 @@ django-htmx
 dj-database-url
 django-click
 django-ratelimit
+django-ipware
 
 psycopg2-binary
 gunicorn

server/requirements/requirements.txt

@@ -43,6 +43,8 @@ django-cors-headers==3.11.0
     # via -r requirements.in
 django-htmx==1.8.0
     # via -r requirements.in
+django-ipware==4.0.2
+    # via -r requirements.in
 django-model-utils==4.2.0
     # via -r requirements.in
 django-ratelimit==3.0.1

server/vbv_lernwelt/core/middleware/security.py

@@ -1,6 +1,9 @@
 import uuid
 
 import structlog
+from django.core.exceptions import PermissionDenied
+from django.http import Http404
+from ipware import get_client_ip
 from structlog.threadlocal import bind_threadlocal, clear_threadlocal
 
 from vbv_lernwelt.core.models import SecurityRequestResponseLog
@@ -8,6 +11,19 @@ from vbv_lernwelt.core.models import SecurityRequestResponseLog
 logger = structlog.get_logger(__name__)
 
 
+class GetIpBehindReverseProxyMiddleWare:
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        client_ip, _is_routable = get_client_ip(request)
+        request.META['REMOTE_ADDR'] = client_ip
+
+        response = self.get_response(request)
+
+        return response
+
+
 class SecurityRequestResponseLoggingMiddleware:
     def __init__(self, get_response):
         self.get_response = get_response
@@ -74,3 +90,19 @@ class SecurityRequestResponseLoggingMiddleware:
 
     def __call__(self, request):
         return self.log_request_response(request)
+
+    def process_exception(self, request, exception):
+        if isinstance(exception, (Http404, PermissionDenied)):
+            # We don't log an exception here, and we don't set that we handled
+            # an error as we want the standard `request_finished` log message
+            # to be emitted.
+            return
+
+        self._raised_exception = True
+
+        self.bind_user_id(request),
+        logger.exception(
+            "request_failed",
+            code=500,
+            request=self.format_request(request),
+        )

server/vbv_lernwelt/core/utils.py

@@ -1,11 +1,12 @@
 import logging
 
+import structlog
 from django.conf import settings
 from rest_framework.throttling import UserRateThrottle
 from structlog.types import EventDict
 
 
-def add_app_info(
+def structlog_add_app_info(
     logger: logging.Logger, method_name: str, event_dict: EventDict
 ) -> EventDict:
     event_dict["django_app"] = "vbv_lernwelt"
@@ -15,6 +16,20 @@ def add_app_info(
     return event_dict
 
 
+def structlog_inject_context_dict(test, level, event_dict):
+    """
+    Add the structlog context dict to log events generated by the stdlib logging library.
+    """
+    context_class = structlog.get_config().get('context_class')
+
+    if context_class:
+        for key, value in context_class().items():
+            if key not in event_dict:
+                event_dict[key] = value
+
+    return event_dict
+
+
 class HourUserRateThrottle(UserRateThrottle):
     scope = "hour-throttle"
 

server/vbv_lernwelt/simpletodo/serializers.py

@@ -1,8 +1,11 @@
+import structlog
 from rest_framework import serializers
 from rest_framework.serializers import ModelSerializer
 
 from vbv_lernwelt.simpletodo.models import SimpleTask, SimpleList
 
+logger = structlog.get_logger(__name__)
+
 
 class SimpleTaskSerializer(ModelSerializer):
     list_title = serializers.CharField(max_length=100)
@@ -27,4 +30,6 @@ class SimpleTaskSerializer(ModelSerializer):
         simple_list, _ = SimpleList.objects.get_or_create(title=list_title, user=user)
 
         validated_data["list"] = simple_list
+
+        logger.debug("Creating task", title=validated_data.get('title'), list_title=list_title)
         return super().create(validated_data)