PB-511: Django request context in logs - #minor

.pylintrc

@@ -276,6 +276,7 @@ function-naming-style=snake_case
 good-names=i,
            j,
            k,
+           f,
            ex,
            fd,
            Run,

README.md

@@ -44,6 +44,9 @@ All features can be fully configured from the configuration file.
   - [Usage](#usage)
   - [Django Request Filter Constructor](#django-request-filter-constructor)
   - [Django Request Config Example](#django-request-config-example)
+- [Django request log records](#django-request-log-records)
+  - [Usage \& Configuration](#usage--configuration)
+    - [Configure the filter `DjangoAppendRequestFilter`](#configure-the-filter-djangoappendrequestfilter)
 - [Filter out LogRecord attributes based on their types](#filter-out-logrecord-attributes-based-on-their-types)
   - [Attribute Type Filter Constructor](#attribute-type-filter-constructor)
   - [Attribute Type Filter Config Example](#attribute-type-filter-config-example)
@@ -507,6 +510,34 @@ filters:
 
 **NOTE**: `JsonDjangoRequest` only support the special key `'()'` factory in the configuration file (it doesn't work with the normal `'class'` key).
 
+## Django request log records
+
+To add context information from the current request to log records. For this the filter `DjangoAppendRequestFilter` must be added as well as the middleware `AddRequestToLogMiddleware`.
+
+### Usage & Configuration
+
+Add `logging_utilities.request_middleware.AddRequestToLogMiddleware` to the `settings.MIDDLEWARE` list.
+
+#### Configure the filter `DjangoAppendRequestFilter`
+
+```yaml
+filters:
+  django_request_meta:
+    (): logging_utilities.filters.django_append_request.DjangoAppendRequestFilter
+    request_attributes:
+      - path
+      - method
+      - META.QUERY_STRING
+    always_add: True
+```
+
+| Parameter    | Type | Default | Description                                    |
+|--------------|------|---------|------------------------------------------------|
+| `attributes` | list | None    | All request attributes that match any of the dotted keys of the list will be added to the jsonifiable object. When `None` then no attributes are added (default behavior). |
+| `always_add` | bool | False   | By default empty attributes are omitted. If set, empty attributes will be added with value `-` |
+
+
+
 ## Filter out LogRecord attributes based on their types
 
 If different libraries or different parts of your code log different object types under the same

logging_utilities/filters/django_append_request.py

@@ -0,0 +1,49 @@
+import functools
+from logging import LogRecord
+from typing import Optional
+
+from django.core.handlers.wsgi import WSGIRequest
+
+
+def r_getattr(obj, attr, *args):
+
+    def _getattr(obj, attr):
+        if isinstance(obj, dict):
+            return obj.get(attr)
+        return getattr(obj, attr, *args)
+
+    return functools.reduce(_getattr, [obj] + attr.split('.'))
+
+
+class DjangoAppendRequestFilter():
+    """Logging Django request attributes
+
+    This filter adds Django request context attributes to the log record.
+    """
+
+    def __init__(
+        self, request: Optional[WSGIRequest] = None, request_attributes=None, always_add=False
+    ):
+        """Initialize the filter
+
+        Args:
+            request_attributes: (WSGIRequest | None)
+                Request from which to read the attributes from.
+            attributes: (list | None)
+                Request attributes that should be added to log entries
+            always_add: bool
+                Always add attributes even if they are missing. Missing attributes with have the
+                value "-".
+        """
+        self.request = request
+        self.attributes = request_attributes if request_attributes else list()
+        self.always_add = always_add
+
+    def filter(self, record: LogRecord) -> bool:
+        request = self.request
+        for attr in self.attributes:
+            val = r_getattr(request, attr, "-")
+            if self.always_add or val != "-":
+                setattr(record, "request." + attr, val)
+
+        return True

logging_utilities/request_middleware.py

@@ -0,0 +1,115 @@
+import logging
+from typing import Any
+from typing import Callable
+from typing import Optional
+from typing import Type
+from typing import TypeVar
+
+from django.core.handlers.wsgi import WSGIRequest
+
+from logging_utilities.filters.django_append_request import \
+    DjangoAppendRequestFilter
+
+# Create a generic variable that can be 'WrappedRequest', or any subclass.
+T = TypeVar('T', bound='WrappedRequest')
+
+
+class WrappedRequest(WSGIRequest):
+    """WrappedRequest adds the 'logging_filter' field to a standard request to track it.
+    """
+
+    @classmethod
+    def from_parent(
+        cls: Type[T], parent: WSGIRequest, logging_filter: Optional[DjangoAppendRequestFilter]
+    ) -> T:
+        return cls(parent.environ, logging_filter)
+
+    def __init__(self, environ: Any, logging_filter: Optional[DjangoAppendRequestFilter]) -> None:
+        super().__init__(environ)
+        self.logging_filter = logging_filter
+
+
+class AddRequestToLogMiddleware():
+    """Middleware that adds a logging filter *DjangoAppendRequestFilter* to the request.
+    """
+
+    def __init__(self, get_response: Callable[[WSGIRequest], Any], root: str = ""):
+        self.root = root
+        self.get_response = get_response
+
+    def __call__(self, request: WSGIRequest) -> Any:
+        w_request = WrappedRequest.from_parent(request, None)
+        response = self.process_request(w_request)
+        if not response:
+            response = self.get_response(w_request)
+        response = self.process_response(w_request, response)
+
+        return response
+
+    def _find_loggers(self) -> dict[str, logging.Logger]:
+        """Return loggers part of root.
+        """
+        result: dict[str, logging.Logger] = {}
+        prefix = self.root + "."
+        for name, log in logging.Logger.manager.loggerDict.items():
+            if not isinstance(log, logging.Logger) or not name.startswith(prefix):
+                continue  # not under self.root
+            result[name] = log
+        # also add root logger
+        result[self.root] = logging.getLogger(self.root)
+        return result
+
+    def _find_handlers(self) -> list[logging.Handler]:
+        """List handlers of all loggers
+        """
+        handlers = set()
+        for logger in self._find_loggers().values():
+            for handler in logger.handlers:
+                handlers.add(handler)
+        return list(handlers)
+
+    def _find_handlers_with_filter(self, filter_cls: type) -> dict[logging.Handler, list[Any]]:
+        """Dict of handlers mapped to their filters.
+        Only include handlers that have at least one filter of type *filter_cls*.
+        """
+        result = {}
+        for logger in self._find_handlers():
+            attrs = []
+            for f in logger.filters:
+                if isinstance(f, filter_cls):
+                    attrs.extend(f.attributes)
+            if attrs:
+                result[logger] = attrs
+        return result
+
+    def _add_filter(self, f: DjangoAppendRequestFilter) -> None:
+        """Add the filter to relevant handlers.
+        Relevant handlers are once that already include a filter of the same type.
+        This is how we "overrite" the filter with the current request.
+        """
+        filter_cls = type(f)
+        for handler, attrs in self._find_handlers_with_filter(filter_cls).items():
+            f.attributes = attrs
+            handler.addFilter(f)
+
+    def process_request(self, request: WrappedRequest) -> Any:
+        """Add a filter that includes the current request. Add the filter to the request to be
+        removed again later.
+        """
+        request.logging_filter = DjangoAppendRequestFilter(request)
+        self._add_filter(request.logging_filter)
+        return self.get_response(request)
+
+    def _remove_filter(self, f: DjangoAppendRequestFilter) -> None:
+        """Remove the filter from any handlers that may have it.
+        """
+        filter_cls = type(f)
+        for handler in self._find_handlers_with_filter(filter_cls):
+            handler.removeFilter(f)
+
+    def process_response(self, request: WrappedRequest, response: Any) -> Any:
+        """Remove the filter if set.
+        """
+        if request.logging_filter:
+            self._remove_filter(request.logging_filter)
+        return response

tests/test_django_attribute.py

@@ -16,7 +16,8 @@
 else:
     dictionary = OrderedDict
 
-settings.configure()
+if not settings.configured:
+    settings.configure()
 
 logger = logging.getLogger(__name__)
 

tests/test_django_request.py

@@ -0,0 +1,96 @@
+import json
+import logging
+import sys
+import unittest
+from collections import OrderedDict
+
+from django.conf import settings
+from django.test import RequestFactory
+
+from logging_utilities.filters.django_append_request import \
+    DjangoAppendRequestFilter
+from logging_utilities.formatters.json_formatter import JsonFormatter
+
+# From python3.7, dict is ordered
+if sys.version_info.major >= 3 and sys.version_info.minor >= 7:
+    dictionary = dict
+else:
+    dictionary = OrderedDict
+
+if not settings.configured:
+    settings.configure()
+
+logger = logging.getLogger(__name__)
+
+
+class DjangoAppendRequestFilterTest(unittest.TestCase):
+
+    def setUp(self) -> None:
+        self.factory = RequestFactory()
+
+    @classmethod
+    def _configure_django_filter(cls, _logger, django_filter):
+        _logger.setLevel(logging.DEBUG)
+        for handler in _logger.handlers:
+            handler.setFormatter(JsonFormatter(add_always_extra=True))
+            handler.addFilter(django_filter)
+
+    def test_django_request_log(self):
+        request = self.factory.get("/some_path?test=some_value")
+        with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx:
+            test_logger = logging.getLogger("test_formatter")
+            self._configure_django_filter(
+                test_logger,
+                DjangoAppendRequestFilter(
+                    request, request_attributes=["path", "method", "META.QUERY_STRING"]
+                )
+            )
+
+            test_logger.debug("first message")
+            test_logger.info("second message")
+
+        message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message1,
+            dictionary([("levelname", "DEBUG"), ("name", "test_formatter"),
+                        ("message", "first message"), ("request.method", "GET"),
+                        ("request.path", "/some_path"),
+                        ("request.META.QUERY_STRING", "test=some_value")])
+        )
+        message2 = json.loads(ctx.output[1], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message2,
+            dictionary([("levelname", "INFO"), ("name", "test_formatter"),
+                        ("message", "second message"), ("request.method", "GET"),
+                        ("request.path", "/some_path"),
+                        ("request.META.QUERY_STRING", "test=some_value")])
+        )
+
+    def test_django_request_log_always_add(self):
+        request = self.factory.get("/some_path?test=some_value")
+        with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx:
+            test_logger = logging.getLogger("test_formatter")
+            self._configure_django_filter(
+                test_logger,
+                DjangoAppendRequestFilter(
+                    request, request_attributes=["does", "not", "exist"], always_add=True
+                )
+            )
+
+            test_logger.debug("first message")
+            test_logger.info("second message")
+
+        message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message1,
+            dictionary([("levelname", "DEBUG"), ("name", "test_formatter"),
+                        ("message", "first message"), ("request.does", "-"), ("request.not", "-"),
+                        ("request.exist", "-")])
+        )
+        message2 = json.loads(ctx.output[1], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message2,
+            dictionary([("levelname", "INFO"), ("name", "test_formatter"),
+                        ("message", "second message"), ("request.does", "-"), ("request.not", "-"),
+                        ("request.exist", "-")])
+        )

tests/test_request_middleware.py

@@ -0,0 +1,62 @@
+import json
+import logging
+import sys
+import unittest
+from collections import OrderedDict
+
+from django.conf import settings
+from django.test import RequestFactory
+
+from logging_utilities.filters.django_append_request import \
+    DjangoAppendRequestFilter
+from logging_utilities.formatters.json_formatter import JsonFormatter
+from logging_utilities.request_middleware import AddRequestToLogMiddleware
+
+# From python3.7, dict is ordered
+if sys.version_info.major >= 3 and sys.version_info.minor >= 7:
+    dictionary = dict
+else:
+    dictionary = OrderedDict
+
+if not settings.configured:
+    settings.configure()
+
+logger = logging.getLogger(__name__)
+
+
+class AddRequestToLogMiddlewareTest(unittest.TestCase):
+
+    def setUp(self) -> None:
+        self.factory = RequestFactory()
+
+    @classmethod
+    def _configure_django_filter(cls, _logger):
+        for handler in _logger.handlers:
+            handler.setFormatter(JsonFormatter(add_always_extra=True))
+            django_filter = DjangoAppendRequestFilter(
+                request_attributes=["method", "path", "META.QUERY_STRING", "headers"]
+            )
+            handler.addFilter(django_filter)
+
+    def test_request_log(self):
+
+        def test_handler(request):
+            logger.info("test message")
+            return "some response"
+
+        with self.assertLogs(logger, level=logging.DEBUG) as ctx:
+            self._configure_django_filter(logger)
+            my_header = {"HTTP_CUSTOM_KEY": "VALUE"}
+            request = self.factory.get("/some_path?test=some_value", **my_header)
+            middleware = AddRequestToLogMiddleware(test_handler, root="tests")
+            middleware(request)
+
+        message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+        print(message1)
+        self.assertDictEqual(
+            message1,
+            dictionary([("levelname", "INFO"), ("name", __name__), ("message", "test message"),
+                        ("request.method", "GET"), ("request.path", "/some_path"),
+                        ("request.META.QUERY_STRING", "test=some_value"),
+                        ('request.headers', "{'Cookie': '', 'Custom-Key': 'VALUE'}")])
+        )