Merge pull request #62 from geoadmin/feat-PB-511-django-request-log

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

Author: benschs

.pylintrc

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

README.md

@@ -55,6 +55,8 @@ All features can be fully configured from the configuration file.
 - [Logger Level Filter](#logger-level-filter)
   - [Logger Level Filter Constructor](#logger-level-filter-constructor)
   - [Logger Level Filter Config Example](#logger-level-filter-config-example)
+- [Django middleware request context](#django-middleware-request-context)
+- [Log thread context](#log-thread-context)
 - [Basic Usage](#basic-usage)
   - [Case 1. Simple JSON Output](#case-1-simple-json-output)
   - [Case 2. JSON Output Configured within Python Code](#case-2-json-output-configured-within-python-code)
@@ -64,6 +66,7 @@ All features can be fully configured from the configuration file.
   - [Case 6. Add parts of Django Request to JSON Output](#case-6-add-parts-of-django-request-to-json-output)
   - [Case 7. Add all Log Extra as Dictionary to the Standard Formatter (including Django log extra)](#case-7-add-all-log-extra-as-dictionary-to-the-standard-formatter-including-django-log-extra)
   - [Case 8. Add Specific Log Extra to the Standard Formatter](#case-8-add-specific-log-extra-to-the-standard-formatter)
+  - [Case 9. Django add request info to all log records](#case-9-django-add-request-info-to-all-log-records)
 - [Breaking Changes](#breaking-changes)
   - [Version 4.x.x Breaking Changes](#version-4xx-breaking-changes)
   - [Version 3.x.x Breaking Changes](#version-3xx-breaking-changes)
@@ -620,6 +623,41 @@ handlers:
 
 **NOTE**: `LevelFilter` only support the special key `'()'` factory in the configuration file (it doesn't work with the normal `'class'` key).
 
+## Django middleware request context
+
+`AddToThreadContextMiddleware` is a [Middleware](https://docs.djangoproject.com/en/5.1/topics/http/middleware/) with which you can add the [Django](https://www.djangoproject.com/) [HttpRequest](https://docs.djangoproject.com/en/5.1/ref/request-response/#httprequest-objects) to thread local variables. The request object is added to a global variable in `logging_utilities.thread_context` and can be accessed in the following way:
+
+```python
+from logging_utilities.thread_context import thread_context
+
+getattr(thread_context, 'request')
+```
+
+## Log thread context
+
+`AddThreadContextFilter` provides a logging filter that will add data from the thread local store `logging_utilities.thread_context` to the log record. To set data on the thread store do the following:
+
+```python
+from logging_utilities.thread_context import thread_context
+
+setattr(thread_context, 'key', data)
+```
+
+Configure the filter to decide which data should be added and how it should be named:
+
+```yaml
+filters:
+  add_request:
+    (): logging_utilities.filters.add_thread_context_filter.AddThreadContextFilter
+    contexts:
+    - logger_key: log_record_key
+      context_key: key
+```
+
+| 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. |
+
 ## Basic Usage
 
 ### Case 1. Simple JSON Output
@@ -1279,6 +1317,57 @@ output:
 2020-11-19 13:42:29,424 - DEBUG - your_logger - My log with extras - extra1=23
 ```
 
+### Case 9. Django add request info to all log records
+
+Combine the use of the middleware `AddToThreadContextMiddleware` with the filters `AddThreadContextFilter` and `JsonDjangoRequest`, as well as the `JsonFormatter` to add request context to each log entry.
+
+Activate the [middleware](https://docs.djangoproject.com/en/5.1/topics/http/middleware/#activating-middleware):
+
+```python
+MIDDLEWARE = (
+    ...,
+    'logging_utilities.django_middlewares.add_request_context.AddToThreadContextMiddleware',
+    ...,
+)
+```
+
+Configure the filters `AddThreadContextFilter` and `JsonDjangoRequest` to add the request from the thread variable to the log record and make it json encodable. Use the `JsonFormatter` to format the request values
+
+```yaml
+filters:
+  add_request:
+    (): logging_utilities.filters.add_thread_context_filter.AddThreadContextFilter
+    contexts:
+    - context_key: request # Must be value 'request' as this is how the middleware adds the value.
+      logger_key: request
+  request_fields:
+    (): logging_utilities.filters.django_request.JsonDjangoRequest
+    attr_key: request # Must match the above logger_key
+    include_keys:
+      - request.path
+      - request.method
+formatters:
+  json:
+    (): logging_utilities.formatters.json_formatter.JsonFormatter
+    fmt:
+      time: asctime
+      level: levelname
+      logger: name
+      module: module
+      message: message
+      request:
+        path: request.path
+        method: request.method
+handlers:
+  console:
+    formatter: json
+    filters:
+      # Make sure to add the filters in the correct order.
+      # These filters modify the record in-place, and as the record is passed serially to each handler.
+      - add_request
+      - request_fields
+```
+
 ## Breaking Changes
 
 ### Version 4.x.x Breaking Changes
@@ -1305,3 +1394,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,9 @@
+from threading import local
+
+
+class ThreadContext(local):
+    """ThreadContext is a store for data that is thread specific.
+    """
+
+
+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__)