From 500c4389e9d40ef3830ab460576b856d63a564f8 Mon Sep 17 00:00:00 2001 From: Benjamin Sugden Date: Thu, 29 Aug 2024 11:33:11 +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 | 67 ++++++++++ .../django_middlewares/__init__.py | 0 .../django_middlewares/request_var.py | 37 ++++++ .../filters/django_append_request.py | 32 +++++ tests/test_django_append_request.py | 90 ++++++++++++++ tests/test_django_attribute.py | 3 +- tests/test_django_log_request_context.py | 117 ++++++++++++++++++ tests/test_request_vars.py | 37 ++++++ 9 files changed, 383 insertions(+), 1 deletion(-) create mode 100644 logging_utilities/django_middlewares/__init__.py create mode 100644 logging_utilities/django_middlewares/request_var.py create mode 100644 logging_utilities/filters/django_append_request.py create mode 100644 tests/test_django_append_request.py create mode 100644 tests/test_django_log_request_context.py create mode 100644 tests/test_request_vars.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..4434538 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,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) 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/request_var.py b/logging_utilities/django_middlewares/request_var.py new file mode 100644 index 0000000..2a1fb2b --- /dev/null +++ b/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() diff --git a/logging_utilities/filters/django_append_request.py b/logging_utilities/filters/django_append_request.py new file mode 100644 index 0000000..21cf5d1 --- /dev/null +++ b/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 diff --git a/tests/test_django_append_request.py b/tests/test_django_append_request.py new file mode 100644 index 0000000..0f41a08 --- /dev/null +++ b/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': "", + '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'])]) + ) 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_django_log_request_context.py b/tests/test_django_log_request_context.py new file mode 100644 index 0000000..5a51ea2 --- /dev/null +++ b/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"]) diff --git a/tests/test_request_vars.py b/tests/test_request_vars.py new file mode 100644 index 0000000..5d947b3 --- /dev/null +++ b/tests/test_request_vars.py @@ -0,0 +1,37 @@ +import logging +import unittest + +from django.conf import settings +from django.test import RequestFactory + +from logging_utilities.django_middlewares.request_var import \ + RequestVarMiddleware +from logging_utilities.django_middlewares.request_var import get_variable +from logging_utilities.formatters.json_formatter import JsonFormatter + +if not settings.configured: + settings.configure() + + +class RequestVarsMiddlewareTest(unittest.TestCase): + + def setUp(self) -> None: + self.factory = RequestFactory() + + @classmethod + def _configure_django_filter(cls, _logger, django_filter): + _logger.setLevel(logging.DEBUG) + for handler in _logger.handlers: + handler.setFormatter(JsonFormatter(add_always_extra=True)) + handler.addFilter(django_filter) + + def test_django_request_log(self): + + def test_handler(request): + r_from_var = get_variable('request') + self.assertEqual(request, r_from_var) + return "some response" + + request = self.factory.get("/some_path?test=some_value") + middleware = RequestVarMiddleware(test_handler) + middleware(request)