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.

Author: benschs

.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,65 @@ 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 `AddToThreadContextMiddleware` with the filters `AddThreadContextFilter` and `JsonDjangoRequest` to add request context to each log entry.
+
+### Usage & Configuration
+
+Add `AddToThreadContextMiddleware` 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.add_request_context.AddToThreadContextMiddleware',
+    ...,
+)
+```
+
+Configure the logging filter `AddThreadContextFilter` to add the request from the thread variable to the log record. the middleware `AddToThreadContextMiddleware` will add the request to the variable name `request`, so make sure the context_key has this value.
+
+```yaml
+filters:
+  add_request:
+    (): logging_utilities.filters.add_thread_context_filter.AddThreadContextFilter
+    contexts:
+    - logger_key: http_request
+      context_key: request
+```
+
+| Parameter  | Type | Default | Description                                    |
+|------------|------|---------|------------------------------------------------|
+| `contexts` | list | empty   | List of values to add to the log record. Dictionary must contain value for 'context_key' to read value from thread local variable. Dictionary must also contain 'logger_key' to set the value on the log record. |
+
+Configure the logging filter `JsonDjangoRequest` to add request fields to the json log output.
+
+For example:
+
+```yaml
+filters:
+  request_fields:
+    (): logging_utilities.filters.django_request.JsonDjangoRequest
+    include_keys:
+      - http_request.path
+      - http_request.method
+```
+
+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
+      - request_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 +1366,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/__init__.py

@@ -0,0 +1,15 @@
+from logging_utilities.thread_context import thread_context
+
+
+class AddToThreadContextMiddleware(object):
+    """Django middleware that stores request to thread local variable.
+    """
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        setattr(thread_context, 'request', request)
+        response = self.get_response(request)
+        setattr(thread_context, 'request', None)
+        return response

logging_utilities/django_middlewares/add_request_context.py

@@ -0,0 +1,28 @@
+import logging
+from logging import LogRecord
+from typing import List
+
+from logging_utilities.thread_context import thread_context
+
+
+class AddThreadContextFilter(logging.Filter):
+    """Add local thread attributes to the log record.
+    """
+
+    def __init__(self, contexts: List[dict] = None) -> None:
+        """Initialize the filter
+
+        Args:
+            contexts (List[dict], optional):
+                List of values to add to the log record. Dictionary must contain value for
+                'context_key' to read value from thread local variable. Dictionary must also contain
+                'logger_key' to set the value on the log record.
+        """
+        self.contexts: List[dict] = [] if contexts is None else contexts
+        super().__init__()
+
+    def filter(self, record: LogRecord) -> bool:
+        for ctx in self.contexts:
+            if getattr(thread_context, ctx['context_key'], None) is not None:
+                setattr(record, ctx['logger_key'], getattr(thread_context, ctx['context_key']))
+        return True

logging_utilities/filters/add_thread_context_filter.py

@@ -0,0 +1,8 @@
+from threading import local
+
+
+class ThreadContext(local):
+    pass
+
+
+thread_context = ThreadContext()

logging_utilities/thread_context.py

@@ -0,0 +1,27 @@
+import unittest
+
+from django.conf import settings
+from django.test import RequestFactory
+
+from logging_utilities.django_middlewares.add_request_context import \
+    AddToThreadContextMiddleware
+from logging_utilities.thread_context import thread_context
+
+if not settings.configured:
+    settings.configure()
+
+
+class AddToThreadContextMiddlewareTest(unittest.TestCase):
+
+    def setUp(self) -> None:
+        self.factory = RequestFactory()
+
+    def test_add_request(self):
+
+        def test_handler(request):
+            r_from_var = getattr(thread_context, 'request', None)
+            self.assertEqual(request, r_from_var)
+
+        request = self.factory.get("/some_path?test=some_value")
+        middleware = AddToThreadContextMiddleware(test_handler)
+        middleware(request)

tests/test_add_request_context.py

@@ -0,0 +1,99 @@
+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.add_thread_context_filter import \
+    AddThreadContextFilter
+from logging_utilities.formatters.json_formatter import JsonFormatter
+from logging_utilities.thread_context import thread_context
+
+if not settings.configured:
+    settings.configure()
+
+# From python3.7, dict is ordered
+if sys.version_info.major >= 3 and sys.version_info.minor >= 7:
+    dictionary = dict
+else:
+    dictionary = OrderedDict
+
+logger = logging.getLogger(__name__)
+
+
+class AddThreadContextFilterTest(unittest.TestCase):
+
+    def setUp(self) -> None:
+        self.factory = RequestFactory()
+
+    @classmethod
+    def _configure_json_filter(cls, _logger):
+        _logger.setLevel(logging.DEBUG)
+        for handler in _logger.handlers:
+            handler.setFormatter(JsonFormatter(add_always_extra=True))
+
+    def test_add_thread_context_no_request(self):
+        with self.assertLogs('test_logger', level=logging.DEBUG) as ctx:
+            test_logger = logging.getLogger("test_logger")
+            self._configure_json_filter(test_logger)
+            test_logger.addFilter(
+                AddThreadContextFilter(
+                    contexts=[{
+                        'logger_key': 'http_request', 'context_key': 'request'
+                    }]
+                )
+            )
+            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")])
+        )
+
+    def test_add_thread_context(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'])
+                setattr(thread_context, tc['var_key'], tc['var_val'])
+                self._configure_json_filter(test_logger)
+                test_logger.addFilter(
+                    AddThreadContextFilter(
+                        contexts=[{
+                            'logger_key': tc['attr_name'], 'context_key': tc['var_key']
+                        }]
+                    )
+                )
+
+                test_logger.debug(tc['log_message'])
+                setattr(thread_context, tc['var_key'], None)
+
+            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_add_thread_context_filter.py

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