From ee99aea0a3231acb91db0345c912b7e5f787983c Mon Sep 17 00:00:00 2001 From: Benjamin Sugden Date: Mon, 2 Sep 2024 12:58:37 +0200 Subject: [PATCH] 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 | 1 + README.md | 63 +++++++++ .../django_middlewares/__init__.py | 0 .../django_middlewares/add_request_context.py | 15 ++ .../filters/add_thread_context_filter.py | 28 ++++ logging_utilities/thread_context.py | 8 ++ tests/test_add_request_context.py | 27 ++++ tests/test_add_thread_context_filter.py | 99 ++++++++++++++ tests/test_django_attribute.py | 3 +- tests/test_log_request_context.py | 129 ++++++++++++++++++ 10 files changed, 372 insertions(+), 1 deletion(-) create mode 100644 logging_utilities/django_middlewares/__init__.py create mode 100644 logging_utilities/django_middlewares/add_request_context.py create mode 100644 logging_utilities/filters/add_thread_context_filter.py create mode 100644 logging_utilities/thread_context.py create mode 100644 tests/test_add_request_context.py create mode 100644 tests/test_add_thread_context_filter.py create mode 100644 tests/test_log_request_context.py diff --git a/.pylintrc b/.pylintrc index b4370cf..76b87f4 100644 --- a/.pylintrc +++ b/.pylintrc @@ -276,6 +276,7 @@ function-naming-style=snake_case good-names=i, j, k, + tc, ex, fd, Run, diff --git a/README.md b/README.md index b12773b..375b946 100644 --- a/README.md +++ b/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) diff --git a/logging_utilities/django_middlewares/__init__.py b/logging_utilities/django_middlewares/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/logging_utilities/django_middlewares/add_request_context.py b/logging_utilities/django_middlewares/add_request_context.py new file mode 100644 index 0000000..41114a3 --- /dev/null +++ b/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 diff --git a/logging_utilities/filters/add_thread_context_filter.py b/logging_utilities/filters/add_thread_context_filter.py new file mode 100644 index 0000000..4c78f11 --- /dev/null +++ b/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 diff --git a/logging_utilities/thread_context.py b/logging_utilities/thread_context.py new file mode 100644 index 0000000..b194809 --- /dev/null +++ b/logging_utilities/thread_context.py @@ -0,0 +1,8 @@ +from threading import local + + +class ThreadContext(local): + pass + + +thread_context = ThreadContext() diff --git a/tests/test_add_request_context.py b/tests/test_add_request_context.py new file mode 100644 index 0000000..00f1d94 --- /dev/null +++ b/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) diff --git a/tests/test_add_thread_context_filter.py b/tests/test_add_thread_context_filter.py new file mode 100644 index 0000000..f719a24 --- /dev/null +++ b/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': "", + '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'])]) + ) diff --git a/tests/test_django_attribute.py b/tests/test_django_attribute.py index 46ec882..fe7be29 100644 --- a/tests/test_django_attribute.py +++ b/tests/test_django_attribute.py @@ -16,7 +16,8 @@ else: dictionary = OrderedDict -settings.configure() +if not settings.configured: + settings.configure() logger = logging.getLogger(__name__) diff --git a/tests/test_log_request_context.py b/tests/test_log_request_context.py new file mode 100644 index 0000000..f3404d0 --- /dev/null +++ b/tests/test_log_request_context.py @@ -0,0 +1,129 @@ +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.add_request_context import \ + AddToThreadContextMiddleware +from logging_utilities.filters.add_thread_context_filter import \ + AddThreadContextFilter +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( + AddThreadContextFilter( + contexts=[{ + 'logger_key': 'request', 'context_key': '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 = AddToThreadContextMiddleware(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_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( + AddThreadContextFilter( + contexts=[{ + 'logger_key': 'request', 'context_key': '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 = AddToThreadContextMiddleware(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"])