PB-511: Django request context in logs

Middleware and filter that can be combined to add django request fields to all
logs within the scope of the request.
Middleware adds request object to a thread local variable. Filter adds the
request from thread to log record. Existing json filter can be used to
decide which request fields should be added to the log.

.pylintrc

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

README.md

@@ -44,6 +44,8 @@ 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 add request to log records](#django-add-request-to-log-records)
+  - [Usage \& Configuration](#usage--configuration)
 - [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 +509,69 @@ filters:
 
 **NOTE**: `JsonDjangoRequest` only support the special key `'()'` factory in the configuration file (it doesn't work with the normal `'class'` key).
 
+## Django add request to log records
+
+Combine the use of the middleware `RequestVarMiddleware` with the filters `DjangoAppendRequestFilter` and `JsonDjangoRequest` to add request context to each log entry.
+
+### Usage & Configuration
+
+Add `RequestVarMiddleware` to the django `settings.MIDDLEWARE` list. This will store the request value in a thread local variable.
+
+For example:
+
+```python
+MIDDLEWARE = (
+    ...,
+    'logging_utilities.django_middlewares.request_var.RequestVarMiddleware',
+    ...,
+)
+```
+
+Configure the logging filter `DjangoAppendRequestFilter` to add the request from the thread variable to the log record:
+
+```yaml
+filters:
+  add_request:
+    (): logging_utilities.filters.django_append_request.DjangoAppendRequestFilter
+    attr_name: request
+```
+
+| Parameter   | Type | Default      | Description                                    |
+|-------------|------|--------------|------------------------------------------------|
+| `attr_name` | str  | http_request | Attribute name of the attribute of the log record on which to store the request. |
+| `var_name`  | str  | request      | Name of the thread local variable from which to read the request. |
+
+Configure the logging filter `JsonDjangoRequest` to add request fields to the json log output.
+
+For example:
+
+```yaml
+filters:
+  django_fields:
+    (): logging_utilities.filters.django_request.JsonDjangoRequest
+    attr_name: request
+    include_keys:
+      - request.path
+      - request.method
+      - request.headers
+      - request.META
+```
+
+Make sure the `attr_name` of both filters match.
+
+Make sure to add the filters in the correct order, for example:
+
+```yaml
+handlers:
+  console:
+    formatter: json
+    filters:
+      # These filters modify the record in-place, and as the record is passed serially to each handler
+      - add_request
+      - django_fields
+
+```
+
 ## Filter out LogRecord attributes based on their types
 
 If different libraries or different parts of your code log different object types under the same
@@ -1305,3 +1370,5 @@ From version 1.x.x to version 2.x.x there is the following breaking change:
 ## Credits
 
 The JSON Formatter implementation has been inspired by [MyColorfulDays/jsonformatter](https://github.com/MyColorfulDays/jsonformatter)
+
+The Request Var middleware has been inspired by [kindlycat/django-request-vars](https://github.com/kindlycat/django-request-vars)

logging_utilities/django_middlewares/request_var.py

@@ -0,0 +1,37 @@
+from threading import local
+
+REQUEST_VARS = local()
+
+
+def set_variable(key, val):
+    setattr(REQUEST_VARS, key, val)
+
+
+def get_variable(key, default=None):
+    return getattr(REQUEST_VARS, key, default)
+
+
+def del_variable(key):
+    if hasattr(REQUEST_VARS, key):
+        del REQUEST_VARS.__dict__[key]
+
+
+def clear_thread_variable():
+    REQUEST_VARS.__dict__.clear()
+
+
+class RequestVarMiddleware(object):
+    """Django middleware that stores request to thread local variable 'request'.
+    """
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        set_variable('request', request)
+        response = self.get_response(request)
+        clear_thread_variable()
+        return response
+
+    def process_exception(self, request, exception):
+        clear_thread_variable()

logging_utilities/filters/django_append_request.py

@@ -0,0 +1,32 @@
+from logging import LogRecord
+
+from logging_utilities.django_middlewares.request_var import get_variable
+
+
+class DjangoAppendRequestFilter():
+    """Logging Django request attributes
+
+    This filter adds the django request from a thread variable to the log record.
+    """
+
+    def __init__(self, attr_name='http_request', var_name='request'):
+        """Initialize the filter
+
+        Args:
+            attr_name: str
+                The name of the attribute that stores the HttpRequest object. The default is
+                'http_request'.
+                (Note that django sometimes stores an "HttpRequest" under the attribute "request".
+                This is however not the default as django also stores other types of objects under
+                this attribute name.)
+            var_name: str
+                The name of the thread variable where the request is stored.
+        """
+        self.attr_name = attr_name
+        self.var_name = var_name
+
+    def filter(self, record: LogRecord) -> bool:
+        request = get_variable(self.var_name)
+        if request:
+            setattr(record, self.attr_name, request)
+        return True

tests/test_django_append_request.py

@@ -0,0 +1,90 @@
+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.django_middlewares.request_var import set_variable
+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):
+        _logger.setLevel(logging.DEBUG)
+        for handler in _logger.handlers:
+            handler.setFormatter(JsonFormatter(add_always_extra=True))
+
+    def test_django_append_request_default_values(self):
+        with self.assertLogs('test_logger', level=logging.DEBUG) as ctx:
+            test_logger = logging.getLogger("test_logger")
+            set_variable("request", "some value")
+            self._configure_django_filter(test_logger)
+            test_logger.addFilter(DjangoAppendRequestFilter())
+
+            test_logger.debug("some message")
+
+        message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message1,
+            dictionary([("levelname", "DEBUG"), ("name", "test_logger"),
+                        ("message", "some message"), ("http_request", "some value")])
+        )
+
+    def test_django_append_request(self):
+        test_cases = [
+            {
+                'logger_name': 'test_1',
+                'var_key': 'request',
+                'var_val': "some value",
+                'attr_name': 'http_request',
+                'expect_value': "some value",
+                'log_message': 'a log message has appeared',
+            },
+            {
+                'logger_name': 'test_2',
+                'var_key': 'request',
+                'var_val': self.factory.get("/some_path"),
+                'attr_name': 'request',
+                'expect_value': "<WSGIRequest: GET '/some_path'>",
+                'log_message': 'another log message has appeared',
+            },
+        ]
+
+        for tc in test_cases:
+            with self.assertLogs(tc['logger_name'], level=logging.DEBUG) as ctx:
+                test_logger = logging.getLogger(tc['logger_name'])
+                set_variable(tc['var_key'], tc['var_val'])
+                self._configure_django_filter(test_logger)
+                test_logger.addFilter(
+                    DjangoAppendRequestFilter(attr_name=tc['attr_name'], var_name=tc['var_key'])
+                )
+
+                test_logger.debug(tc['log_message'])
+
+            message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+            self.assertDictEqual(
+                message1,
+                dictionary([("levelname", "DEBUG"), ("name", tc['logger_name']),
+                            ("message", tc['log_message']), (tc['attr_name'], tc['expect_value'])])
+            )

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_log_request_context.py

@@ -0,0 +1,117 @@
+import json
+import logging
+import sys
+import time
+import unittest
+from collections import OrderedDict
+from concurrent.futures import ThreadPoolExecutor
+
+from django.conf import settings
+from django.test import RequestFactory
+
+from logging_utilities.django_middlewares.request_var import \
+    RequestVarMiddleware
+from logging_utilities.filters.django_append_request import \
+    DjangoAppendRequestFilter
+from logging_utilities.filters.django_request import JsonDjangoRequest
+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 AddRequestToLogTest(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))
+            handler.addFilter(DjangoAppendRequestFilter(attr_name="request"))
+            handler.addFilter(
+                JsonDjangoRequest(
+                    include_keys=["request.path", "request.META.QUERY_STRING"], attr_name="request"
+                )
+            )
+
+    def test_log_request_context(self):
+
+        def test_handler(request):
+            logger.info("some value")
+            return "some response"
+
+        with self.assertLogs(logger, level=logging.DEBUG) as ctx:
+            # Global config of filter
+            self._configure_django_filter(logger)
+            request = self.factory.get("/some_path?test=some_value")
+            middleware = RequestVarMiddleware(test_handler)
+            middleware(request)
+
+        print(ctx.output[0])
+        message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary)
+        self.assertDictEqual(
+            message1,
+            dictionary([
+                ("levelname", "INFO"),
+                ("name", "tests.test_django_log_request_context"),
+                ("message", "some value"),
+                (
+                    "request",
+                    dictionary([("path", "/some_path"),
+                                ("META", dictionary([("QUERY_STRING", "test=some_value")]))])
+                ),
+            ])
+        )
+
+
+class MultiprocessLoggingTest(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))
+            handler.addFilter(DjangoAppendRequestFilter(attr_name="request"))
+            handler.addFilter(JsonDjangoRequest(include_keys=["request.path"], attr_name="request"))
+
+    def test_threaded_logging(self):
+
+        def test_handler(request):
+            time.sleep(1)
+            logger.info(request.path)
+            return "some response"
+
+        paths = [
+            "/first_path",
+            "/second_path",
+            "/third_path",
+        ]
+
+        def execute_request(path):
+            request = self.factory.get(path)
+            middleware = RequestVarMiddleware(test_handler)
+            middleware(request)
+
+        with self.assertLogs(logger, level=logging.DEBUG) as ctx:
+            # Global config of filter
+            self._configure_django_filter(logger)
+            with ThreadPoolExecutor() as executor:
+                futures = []
+                for path in paths:
+                    futures.append(executor.submit(execute_request, path))
+
+        for output in ctx.output:
+            msg = json.loads(output, object_pairs_hook=dictionary)
+            self.assertEqual(msg["message"], msg["request"]["path"])