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..a7fbd4e 100644 --- a/README.md +++ b/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) 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..949a850 --- /dev/null +++ b/logging_utilities/thread_context.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() 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"])