diff --git a/.pylintrc b/.pylintrc index b4370cf..c294605 100644 --- a/.pylintrc +++ b/.pylintrc @@ -276,6 +276,7 @@ function-naming-style=snake_case good-names=i, j, k, + f, ex, fd, Run, diff --git a/README.md b/README.md index b12773b..25a6c03 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 request log records](#django-request-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,44 @@ filters: **NOTE**: `JsonDjangoRequest` only support the special key `'()'` factory in the configuration file (it doesn't work with the normal `'class'` key). +## Django request log records + +To add context information from the current request to each log record. For this the filter `DjangoAppendRequestFilter` must be added as well as the middleware `AddRequestToLogMiddleware`. + +### Usage & Configuration + +Add `logging_utilities.django_middlewares.request_middleware.AddRequestToLogMiddleware` to the django `settings.MIDDLEWARE` list + +For example: + +```python +MIDDLEWARE = ( + ..., + 'logging_utilities.django_middlewares.request_middleware.AddRequestToLogMiddleware', + ..., +) +``` + +Configure the logging filter `DjangoAppendRequestFilter`: + +```yaml +filters: + django_request_meta: + (): logging_utilities.filters.django_append_request.DjangoAppendRequestFilter + attributes: + - path + - method + - META.QUERY_STRING + always_add: True +``` + +| Parameter | Type | Default | Description | +|--------------|------|---------|------------------------------------------------| +| `attributes` | list | None | All request attributes that match any of the dotted keys of this list will be added to the log record. When `None` then no attributes are added (default behavior). | +| `always_add` | bool | False | By default empty attributes are omitted. If set, empty attributes will be added with value `-` | + + + ## Filter out LogRecord attributes based on their types If different libraries or different parts of your code log different object types under the same 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_middleware.py b/logging_utilities/django_middlewares/request_middleware.py new file mode 100644 index 0000000..89f5e7a --- /dev/null +++ b/logging_utilities/django_middlewares/request_middleware.py @@ -0,0 +1,115 @@ +import logging +from typing import Any +from typing import Callable +from typing import Optional +from typing import Type +from typing import TypeVar + +from django.core.handlers.wsgi import WSGIRequest + +from logging_utilities.filters.django_append_request import \ + DjangoAppendRequestFilter + +# Create a generic variable that can be 'WrappedRequest', or any subclass. +T = TypeVar('T', bound='WrappedRequest') + + +class WrappedRequest(WSGIRequest): + """WrappedRequest adds the 'logging_filter' field to a standard request to track it. + """ + + @classmethod + def from_parent( + cls: Type[T], parent: WSGIRequest, logging_filter: Optional[DjangoAppendRequestFilter] + ) -> T: + return cls(parent.environ, logging_filter) + + def __init__(self, environ: Any, logging_filter: Optional[DjangoAppendRequestFilter]) -> None: + super().__init__(environ) + self.logging_filter = logging_filter + + +class AddRequestToLogMiddleware(): + """Middleware that adds a logging filter *DjangoAppendRequestFilter* to the request. + """ + + def __init__(self, get_response: Callable[[WSGIRequest], Any], root_logger: str = ""): + self.root_logger = root_logger + self.get_response = get_response + + def __call__(self, request: WSGIRequest) -> Any: + w_request = WrappedRequest.from_parent(request, None) + response = self.process_request(w_request) + if not response: + response = self.get_response(w_request) + response = self.process_response(w_request, response) + + return response + + def _find_loggers(self) -> dict[str, logging.Logger]: + """Return loggers part of root. + """ + result: dict[str, logging.Logger] = {} + prefix = self.root_logger + "." + for name, log in logging.Logger.manager.loggerDict.items(): + if not isinstance(log, logging.Logger) or not name.startswith(prefix): + continue # not under self.root_logger + result[name] = log + # also add root logger + result[self.root_logger] = logging.getLogger(self.root_logger) + return result + + def _find_handlers(self) -> list[logging.Handler]: + """List handlers of all loggers + """ + handlers = set() + for logger in self._find_loggers().values(): + for handler in logger.handlers: + handlers.add(handler) + return list(handlers) + + def _find_handlers_with_filter(self, filter_cls: type) -> dict[logging.Handler, list[Any]]: + """Dict of handlers mapped to their filters. + Only include handlers that have at least one filter of type *filter_cls*. + """ + result = {} + for handler in self._find_handlers(): + attrs = [] + for f in handler.filters: + if isinstance(f, filter_cls): + attrs.extend(f.attributes) + if attrs: + result[handler] = attrs + return result + + def _add_filter(self, f: DjangoAppendRequestFilter) -> None: + """Add the filter to relevant handlers. + Relevant handlers are once that already include a filter of the same type. + This is how we "overrite" the filter with the current request. + """ + filter_cls = type(f) + for handler, attrs in self._find_handlers_with_filter(filter_cls).items(): + f.attributes = attrs + handler.addFilter(f) + + def process_request(self, request: WrappedRequest) -> Any: + """Add a filter that includes the current request. Add the filter to the request to be + removed again later. + """ + request.logging_filter = DjangoAppendRequestFilter(request) + self._add_filter(request.logging_filter) + return self.get_response(request) + + def _remove_filter(self, f: DjangoAppendRequestFilter) -> None: + """Remove the filter from any handlers that may have it. + """ + filter_cls = type(f) + for handler in self._find_handlers_with_filter(filter_cls): + handler.removeFilter(f) + + def process_response(self, request: WrappedRequest, response: Any) -> Any: + """Remove the filter if set. + """ + if request.logging_filter: + self._remove_filter(request.logging_filter) + return response diff --git a/logging_utilities/filters/django_append_request.py b/logging_utilities/filters/django_append_request.py new file mode 100644 index 0000000..498ba99 --- /dev/null +++ b/logging_utilities/filters/django_append_request.py @@ -0,0 +1,47 @@ +import functools +from logging import LogRecord +from typing import Optional + +from django.core.handlers.wsgi import WSGIRequest + + +def request_getattr(obj, attr, *args): + + def _getattr(obj, attr): + if isinstance(obj, dict): + return obj.get(attr) + return getattr(obj, attr, *args) + + return functools.reduce(_getattr, [obj] + attr.split('.')) + + +class DjangoAppendRequestFilter(): + """Logging Django request attributes + + This filter adds Django request context attributes to the log record. + """ + + def __init__(self, request: Optional[WSGIRequest] = None, attributes=None, always_add=False): + """Initialize the filter + + Args: + request: (WSGIRequest | None) + Request from which to read the attributes from. + attributes: (list | None) + Request attributes that should be added to log entries. + always_add: bool + Always add attributes even if they are missing. Missing attributes with have the + value "-". + """ + self.request = request + self.attributes = attributes if attributes else list() + self.always_add = always_add + + def filter(self, record: LogRecord) -> bool: + request = self.request + for attr in self.attributes: + val = request_getattr(request, attr, "-") + if self.always_add or val != "-": + setattr(record, "request." + attr, val) + + return True 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_request.py b/tests/test_django_request.py new file mode 100644 index 0000000..5514abf --- /dev/null +++ b/tests/test_django_request.py @@ -0,0 +1,113 @@ +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.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, 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): + request = self.factory.get("/some_path?test=some_value") + with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx: + test_logger = logging.getLogger("test_formatter") + self._configure_django_filter( + test_logger, + DjangoAppendRequestFilter( + request, attributes=["path", "method", "META.QUERY_STRING"] + ) + ) + + test_logger.debug("first message") + test_logger.info("second message") + + message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary) + self.assertDictEqual( + message1, + dictionary([("levelname", "DEBUG"), ("name", "test_formatter"), + ("message", "first message"), ("request.method", "GET"), + ("request.path", "/some_path"), + ("request.META.QUERY_STRING", "test=some_value")]) + ) + message2 = json.loads(ctx.output[1], object_pairs_hook=dictionary) + self.assertDictEqual( + message2, + dictionary([("levelname", "INFO"), ("name", "test_formatter"), + ("message", "second message"), ("request.method", "GET"), + ("request.path", "/some_path"), + ("request.META.QUERY_STRING", "test=some_value")]) + ) + + def test_django_request_log_always_add(self): + request = self.factory.get("/some_path?test=some_value") + with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx: + test_logger = logging.getLogger("test_formatter") + self._configure_django_filter( + test_logger, + DjangoAppendRequestFilter( + request, attributes=["does", "not", "exist"], always_add=True + ) + ) + + test_logger.debug("first message") + test_logger.info("second message") + + message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary) + self.assertDictEqual( + message1, + dictionary([("levelname", "DEBUG"), ("name", "test_formatter"), + ("message", "first message"), ("request.does", "-"), ("request.not", "-"), + ("request.exist", "-")]) + ) + message2 = json.loads(ctx.output[1], object_pairs_hook=dictionary) + self.assertDictEqual( + message2, + dictionary([("levelname", "INFO"), ("name", "test_formatter"), + ("message", "second message"), ("request.does", "-"), ("request.not", "-"), + ("request.exist", "-")]) + ) + + def test_django_request_log_no_request(self): + with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx: + test_logger = logging.getLogger("test_formatter") + self._configure_django_filter( + test_logger, + DjangoAppendRequestFilter(request=None, attributes=["path"], always_add=True) + ) + + test_logger.debug("first message") + + message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary) + self.assertDictEqual( + message1, + dictionary([("levelname", "DEBUG"), ("name", "test_formatter"), + ("message", "first message"), ("request.path", "-")]) + ) diff --git a/tests/test_django_request_middleware.py b/tests/test_django_request_middleware.py new file mode 100644 index 0000000..50d8367 --- /dev/null +++ b/tests/test_django_request_middleware.py @@ -0,0 +1,63 @@ +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_middleware import \ + AddRequestToLogMiddleware +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 AddRequestToLogMiddlewareTest(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)) + django_filter = DjangoAppendRequestFilter( + attributes=["method", "path", "META.QUERY_STRING", "headers"] + ) + handler.addFilter(django_filter) + + def test_request_log(self): + + def test_handler(request): + logger.info("test message") + return "some response" + + with self.assertLogs(logger, level=logging.DEBUG) as ctx: + self._configure_django_filter(logger) + my_header = {"HTTP_CUSTOM_KEY": "VALUE"} + request = self.factory.get("/some_path?test=some_value", **my_header) + middleware = AddRequestToLogMiddleware(test_handler, root_logger="tests") + middleware(request) + + message1 = json.loads(ctx.output[0], object_pairs_hook=dictionary) + print(message1) + self.assertDictEqual( + message1, + dictionary([("levelname", "INFO"), ("name", __name__), ("message", "test message"), + ("request.method", "GET"), ("request.path", "/some_path"), + ("request.META.QUERY_STRING", "test=some_value"), + ('request.headers', "{'Cookie': '', 'Custom-Key': 'VALUE'}")]) + )