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

.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/add_request_context.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/filters/add_thread_context_filter.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/thread_context.py

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

tests/test_add_request_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_thread_context_filter.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_django_attribute.py

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