From 18b4cda27a78a8bf0e8c586d168e166bdf4c4ee1 Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 20:59:40 -0400 Subject: [PATCH 1/6] Reimplement async support --- django_structlog/celery/middlewares.py | 11 ++++ django_structlog/middlewares/request.py | 62 ++++++++++++++-------- docs/api_documentation.rst | 2 +- test_app/tests/middlewares/test_celery.py | 39 ++++++++++++-- test_app/tests/middlewares/test_request.py | 14 +++-- 5 files changed, 92 insertions(+), 36 deletions(-) diff --git a/django_structlog/celery/middlewares.py b/django_structlog/celery/middlewares.py index c0f1dda0..7ce2e386 100644 --- a/django_structlog/celery/middlewares.py +++ b/django_structlog/celery/middlewares.py @@ -1,7 +1,11 @@ +from asgiref.sync import iscoroutinefunction, markcoroutinefunction + from ..celery.receivers import receiver_before_task_publish, receiver_after_task_publish class CeleryMiddleware: + sync_capable = True + async_capable = True """ ``CeleryMiddleware`` initializes ``celery`` signals to pass ``django``'s request information to ``celery`` worker's logger. @@ -19,6 +23,13 @@ def __init__(self, get_response=None): before_task_publish.connect(receiver_before_task_publish) after_task_publish.connect(receiver_after_task_publish) + if iscoroutinefunction(self.get_response): + markcoroutinefunction(self) def __call__(self, request): + if iscoroutinefunction(self): + return self.__acall__(request) return self.get_response(request) + + async def __acall__(self, request): + return await self.get_response(request) diff --git a/django_structlog/middlewares/request.py b/django_structlog/middlewares/request.py index bd230b15..d5bd44e5 100644 --- a/django_structlog/middlewares/request.py +++ b/django_structlog/middlewares/request.py @@ -1,11 +1,12 @@ -import asyncio import uuid import structlog +from asgiref.sync import iscoroutinefunction, markcoroutinefunction from django.core.exceptions import PermissionDenied from django.http import Http404 from django.utils.decorators import sync_and_async_middleware from asgiref import sync +from django.utils.deprecation import warn_about_renamed_method from .. import signals @@ -102,39 +103,56 @@ def bind_user_id(request): structlog.contextvars.bind_contextvars(user_id=user_id) -class SyncRequestMiddleware(BaseRequestMiddleWare): +class RequestMiddleware(BaseRequestMiddleWare): sync_capable = True - async_capable = False + async_capable = True + + def __init__(self, get_response): + super().__init__(get_response) + if iscoroutinefunction(self.get_response): + markcoroutinefunction(self) def __call__(self, request): + if iscoroutinefunction(self): + return self.__acall__(request) self.prepare(request) response = self.get_response(request) self.handle_response(request, response) return response - -class AsyncRequestMiddleware(BaseRequestMiddleWare): - sync_capable = False - async_capable = True - - async def __call__(self, request): + async def __acall__(self, request): await sync.sync_to_async(self.prepare)(request) response = await self.get_response(request) await sync.sync_to_async(self.handle_response)(request, response) return response -class RequestMiddleware(SyncRequestMiddleware): - """``RequestMiddleware`` adds request metadata to ``structlog``'s logger context automatically. - - >>> MIDDLEWARE = [ - ... # ... - ... 'django_structlog.middlewares.RequestMiddleware', - ... ] - - """ - - +@warn_about_renamed_method( + class_name="django-structlog.middlewares", + old_method_name="SyncRequestMiddleware", + new_method_name="RequestMiddleware", + deprecation_warning=DeprecationWarning, +) +class SyncRequestMiddleware(RequestMiddleware): + pass + + +@warn_about_renamed_method( + class_name="django-structlog.middlewares", + old_method_name="AsyncRequestMiddleware", + new_method_name="RequestMiddleware", + deprecation_warning=DeprecationWarning, +) +class AsyncRequestMiddleware(RequestMiddleware): + pass + + +@warn_about_renamed_method( + class_name="django-structlog.middlewares", + old_method_name="request_middleware_router", + new_method_name="RequestMiddleware", + deprecation_warning=DeprecationWarning, +) @sync_and_async_middleware def request_middleware_router(get_response): """``request_middleware_router`` select automatically between async or sync middleware. @@ -147,6 +165,4 @@ def request_middleware_router(get_response): ... ] """ - if asyncio.iscoroutinefunction(get_response): - return AsyncRequestMiddleware(get_response) - return SyncRequestMiddleware(get_response) + return RequestMiddleware(get_response) diff --git a/docs/api_documentation.rst b/docs/api_documentation.rst index 8ad9da72..0f5b2aa1 100644 --- a/docs/api_documentation.rst +++ b/docs/api_documentation.rst @@ -10,7 +10,7 @@ django_structlog :show-inheritance: .. automodule:: django_structlog.middlewares - :members: RequestMiddleware, request_middleware_router + :members: RequestMiddleware :undoc-members: :show-inheritance: diff --git a/test_app/tests/middlewares/test_celery.py b/test_app/tests/middlewares/test_celery.py index 785adca7..bf067d8c 100644 --- a/test_app/tests/middlewares/test_celery.py +++ b/test_app/tests/middlewares/test_celery.py @@ -12,16 +12,47 @@ def test_call(self): receiver_after_task_publish, ) - mock_get_response = Mock() mock_request = Mock() + mock_response = Mock() + + def get_response(request): + return mock_response + with patch( "celery.utils.dispatch.signal.Signal.connect", autospec=True ) as mock_connect: - middleware = middlewares.CeleryMiddleware(mock_get_response) + middleware = middlewares.CeleryMiddleware(get_response) + + response = middleware(mock_request) + self.assertEqual(mock_response, response) + + mock_connect.assert_has_calls( + [ + call(before_task_publish, receiver_before_task_publish), + call(after_task_publish, receiver_after_task_publish), + ] + ) + + async def test_async(self): + from celery.signals import before_task_publish, after_task_publish + from django_structlog.celery.receivers import ( + receiver_before_task_publish, + receiver_after_task_publish, + ) - middleware(mock_request) - mock_get_response.assert_called_once_with(mock_request) + mock_request = Mock() + mock_response = Mock() + + async def get_response(request): + return mock_response + + with patch( + "celery.utils.dispatch.signal.Signal.connect", autospec=True + ) as mock_connect: + middleware = middlewares.CeleryMiddleware(get_response) + response = await middleware(mock_request) + self.assertEqual(mock_response, response) mock_connect.assert_has_calls( [ call(before_task_publish, receiver_before_task_publish), diff --git a/test_app/tests/middlewares/test_request.py b/test_app/tests/middlewares/test_request.py index e6d03d7f..66673887 100644 --- a/test_app/tests/middlewares/test_request.py +++ b/test_app/tests/middlewares/test_request.py @@ -643,14 +643,13 @@ async def test_async(self): async def async_get_response(request): return mock_response - middleware = middlewares.request_middleware_router(async_get_response) - self.assertIsInstance(middleware, middlewares.request.AsyncRequestMiddleware) + middleware = middlewares.RequestMiddleware(async_get_response) mock_request = Mock() with patch( - "django_structlog.middlewares.request.AsyncRequestMiddleware.prepare" + "django_structlog.middlewares.request.RequestMiddleware.prepare" ) as mock_prepare, patch( - "django_structlog.middlewares.request.AsyncRequestMiddleware.handle_response" + "django_structlog.middlewares.request.RequestMiddleware.handle_response" ) as mock_handle_response: response = await middleware(mock_request) self.assertEqual(response, mock_response) @@ -663,14 +662,13 @@ def test_sync(self): def get_response(request): return mock_response - middleware = middlewares.request_middleware_router(get_response) - self.assertIsInstance(middleware, middlewares.request.SyncRequestMiddleware) + middleware = middlewares.RequestMiddleware(get_response) mock_request = Mock() with patch( - "django_structlog.middlewares.request.SyncRequestMiddleware.prepare" + "django_structlog.middlewares.request.RequestMiddleware.prepare" ) as mock_prepare, patch( - "django_structlog.middlewares.request.SyncRequestMiddleware.handle_response" + "django_structlog.middlewares.request.RequestMiddleware.handle_response" ) as mock_handle_response: response = middleware(mock_request) self.assertEqual(response, mock_response) From 979b500a9dcaf117e198874054e2cf1f406d408c Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 21:08:42 -0400 Subject: [PATCH 2/6] ignore coverage of deprecated function --- django_structlog/middlewares/request.py | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-) diff --git a/django_structlog/middlewares/request.py b/django_structlog/middlewares/request.py index d5bd44e5..2b4d84e0 100644 --- a/django_structlog/middlewares/request.py +++ b/django_structlog/middlewares/request.py @@ -155,14 +155,4 @@ class AsyncRequestMiddleware(RequestMiddleware): ) @sync_and_async_middleware def request_middleware_router(get_response): - """``request_middleware_router`` select automatically between async or sync middleware. - - Use as a replacement for `django_structlog.middlewares.RequestMiddleware` - - >>> MIDDLEWARE = [ - ... # ... - ... 'django_structlog.middlewares.request_middleware_router', - ... ] - - """ - return RequestMiddleware(get_response) + return RequestMiddleware(get_response) # pragma: no cover From 3fd799b594c9bb9c90a5dcb9b16afb3650930704 Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 21:35:48 -0400 Subject: [PATCH 3/6] Remove django-toolbar --- config/settings/local.py | 14 +------------- config/urls.py | 6 ------ requirements/local-base.txt | 1 - 3 files changed, 1 insertion(+), 20 deletions(-) diff --git a/config/settings/local.py b/config/settings/local.py index e58a6f33..44c36fad 100644 --- a/config/settings/local.py +++ b/config/settings/local.py @@ -1,7 +1,7 @@ import structlog from .base import * # noqa: F403 -from .base import env +from .base import env, MIDDLEWARE # GENERAL # ------------------------------------------------------------------------------ @@ -41,18 +41,6 @@ # https://docs.djangoproject.com/en/dev/ref/settings/#email-port EMAIL_PORT = 1025 -# django-debug-toolbar -# ------------------------------------------------------------------------------ -# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#prerequisites -INSTALLED_APPS += ["debug_toolbar"] # noqa F405 -# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#middleware -MIDDLEWARE += ["debug_toolbar.middleware.DebugToolbarMiddleware"] # noqa F405 -# https://django-debug-toolbar.readthedocs.io/en/latest/configuration.html#debug-toolbar-config -DEBUG_TOOLBAR_CONFIG = { - "DISABLE_PANELS": ["debug_toolbar.panels.redirects.RedirectsPanel"], - "SHOW_TEMPLATE_CONTEXT": True, -} -# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#internal-ips INTERNAL_IPS = ["127.0.0.1", "10.0.2.2"] if env("USE_DOCKER") == "yes": import socket diff --git a/config/urls.py b/config/urls.py index da48bc48..0bffaba3 100644 --- a/config/urls.py +++ b/config/urls.py @@ -62,9 +62,3 @@ def uncaught_exception_view(request): re_path(r"^500/", default_views.server_error), re_path(r"^uncaught_exception/", uncaught_exception_view), ] - if "debug_toolbar" in settings.INSTALLED_APPS: - import debug_toolbar - - urlpatterns = [ - re_path(r"^__debug__/", include(debug_toolbar.urls)) - ] + urlpatterns diff --git a/requirements/local-base.txt b/requirements/local-base.txt index de6e9503..3595bc81 100644 --- a/requirements/local-base.txt +++ b/requirements/local-base.txt @@ -42,7 +42,6 @@ pylint-celery==0.3 # https://github.com/PyCQA/pylint-celery # ------------------------------------------------------------------------------ factory-boy==3.2.1 # https://github.com/FactoryBoy/factory_boy -django-debug-toolbar==3.8.1 # https://github.com/jazzband/django-debug-toolbar django-extensions==3.2.1 # https://github.com/django-extensions/django-extensions django-coverage-plugin==3.0.0 # https://github.com/nedbat/django_coverage_plugin pytest-django==4.5.2 # https://github.com/pytest-dev/pytest-django From 14da9d8fe2b83b9d05987307dfd67ad00a1f0d33 Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 22:51:22 -0400 Subject: [PATCH 4/6] Bump version and remove dead code --- README.rst | 34 +++ django_structlog/__init__.py | 2 +- django_structlog/middlewares/request.py | 51 +--- django_structlog/signals.py | 16 -- docs/changelog.rst | 17 ++ docs/events.rst | 6 - test_app/tests/middlewares/test_request.py | 256 --------------------- 7 files changed, 64 insertions(+), 318 deletions(-) diff --git a/README.rst b/README.rst index 2f1266f1..c50412da 100644 --- a/README.rst +++ b/README.rst @@ -339,6 +339,40 @@ Json file (\ ``logs/json.log``\ ) Upgrade Guide ============= +.. _upgrade_5.0: + +Upgrading to 5.0+ +^^^^^^^^^^^^^^^^^ + +Changes you may need to do +~~~~~~~~~~~~~~~~~~~~~~~~~~ + +1. Make sure you use ``django_structlog.middlewares.RequestMiddleware`` +----------------------------------------------------------------------- + +If you used any of the experimental async or sync middlewares, you do not need to anymore. +Make sure you use ``django_structlog.middlewares.RequestMiddleware`` instead of any of the other request middlewares commented below: + +.. code-block:: python + + MIDDLEWARE += [ + # "django_structlog.middlewares.request_middleware_router", # <- remove + # "django_structlog.middlewares.requests.SyncRequestMiddleware", # <- remove + # "django_structlog.middlewares.requests.AsyncRequestMiddleware", # <- remove + "django_structlog.middlewares.RequestMiddleware", # <- make sure you use this one + "django_structlog.middlewares.CeleryMiddleware", + ] + +They will be removed in another major version. + +2. ``django_structlog.signals.bind_extra_request_failed_metadata`` was removed +------------------------------------------------------------------------------ + +The signal ``bind_extra_request_failed_metadata`` was removed since it was never called. + +Remove your custom signal. + + .. _upgrade_4.0: Upgrading to 4.0+ diff --git a/django_structlog/__init__.py b/django_structlog/__init__.py index 6de28e20..c0302d74 100644 --- a/django_structlog/__init__.py +++ b/django_structlog/__init__.py @@ -4,6 +4,6 @@ name = "django_structlog" -VERSION = (4, 1, 1) +VERSION = (5, 0, 0) __version__ = ".".join(str(v) for v in VERSION) diff --git a/django_structlog/middlewares/request.py b/django_structlog/middlewares/request.py index 2b4d84e0..341888d8 100644 --- a/django_structlog/middlewares/request.py +++ b/django_structlog/middlewares/request.py @@ -2,8 +2,6 @@ import structlog from asgiref.sync import iscoroutinefunction, markcoroutinefunction -from django.core.exceptions import PermissionDenied -from django.http import Http404 from django.utils.decorators import sync_and_async_middleware from asgiref import sync from django.utils.deprecation import warn_about_renamed_method @@ -23,22 +21,20 @@ def get_request_header(request, header_key, meta_key): class BaseRequestMiddleWare: def __init__(self, get_response): self.get_response = get_response - self._raised_exception = False def handle_response(self, request, response): - if not self._raised_exception: - self.bind_user_id(request) - signals.bind_extra_request_finished_metadata.send( - sender=self.__class__, - request=request, - logger=logger, - response=response, - ) - logger.info( - "request_finished", - code=response.status_code, - request=self.format_request(request), - ) + self.bind_user_id(request) + signals.bind_extra_request_finished_metadata.send( + sender=self.__class__, + request=request, + logger=logger, + response=response, + ) + logger.info( + "request_finished", + code=response.status_code, + request=self.format_request(request), + ) structlog.contextvars.clear_contextvars() def prepare(self, request): @@ -64,34 +60,11 @@ def prepare(self, request): request=self.format_request(request), user_agent=request.META.get("HTTP_USER_AGENT"), ) - self._raised_exception = False @staticmethod def format_request(request): return "%s %s" % (request.method, request.get_full_path()) - def process_exception(self, request, exception): - if isinstance(exception, (Http404, PermissionDenied)): - # We don't log an exception here, and we don't set that we handled - # an error as we want the standard `request_finished` log message - # to be emitted. - return - - self._raised_exception = True - - self.bind_user_id(request) - signals.bind_extra_request_failed_metadata.send( - sender=self.__class__, - request=request, - logger=logger, - exception=exception, - ) - logger.exception( - "request_failed", - code=500, - request=self.format_request(request), - ) - @staticmethod def bind_user_id(request): if hasattr(request, "user") and request.user is not None: diff --git a/django_structlog/signals.py b/django_structlog/signals.py index 70370c7a..2b8e39cc 100644 --- a/django_structlog/signals.py +++ b/django_structlog/signals.py @@ -31,19 +31,3 @@ ... structlog.contextvars.bind_contextvars(user_email=getattr(request.user, 'email', '')) """ - -bind_extra_request_failed_metadata = django.dispatch.Signal() -""" Signal to add extra ``structlog`` bindings from ``django``'s failed request and exception. - -:param logger: the logger to bind more metadata or override existing bound metadata -:param exception: the exception resulting of the request - ->>> from django.dispatch import receiver ->>> from django_structlog import signals ->>> import structlog ->>> ->>> @receiver(signals.bind_extra_request_failed_metadata) -... def bind_user_email(request, logger, exception, **kwargs): -... structlog.contextvars.bind_contextvars(user_email=getattr(request.user, 'email', '')) - -""" diff --git a/docs/changelog.rst b/docs/changelog.rst index ecfad479..32089b54 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -1,6 +1,23 @@ Change Log ========== +5.0.0 (March 23th, 2023) +------------------------ + +See: :ref:`upgrade_5.0` + +*Changes:* + - ``RequestMiddleware`` and ``CeleryMiddleware`` now properly support async views + +*Removed:* + - ``django_structlog.signals.bind_extra_request_failed_metadata`` + +*Deprecates:* + - :class:`django_structlog.middlewares.request_middleware_router` + - :class:`django_structlog.middlewares.requests.AsyncRequestMiddleware` + - :class:`django_structlog.middlewares.requests.SyncRequestMiddleware` + + 4.1.1 (February 7th, 2023) -------------------------- diff --git a/docs/events.rst b/docs/events.rst index e51026ca..7586e6bb 100644 --- a/docs/events.rst +++ b/docs/events.rst @@ -14,8 +14,6 @@ Request Events +------------------+---------+------------------------------+ | request_finished | INFO | request completed normally | +------------------+---------+------------------------------+ -| request_failed | ERROR | unhandled exception occurred | -+------------------+---------+------------------------------+ Request Bound Metadata ^^^^^^^^^^^^^^^^^^^^^^ @@ -60,10 +58,6 @@ These metadata appear once along with their associated event +------------------+------------------+--------------------------------------------------------------+ | request_finished | code | request's status code | +------------------+------------------+--------------------------------------------------------------+ -| request_failed | exception | exception traceback (requires format_exc_info_) | -+------------------+------------------+--------------------------------------------------------------+ - -.. _format_exc_info: https://www.structlog.org/en/stable/api.html#structlog.processors.format_exc_info CeleryMiddleware ---------------- diff --git a/test_app/tests/middlewares/test_request.py b/test_app/tests/middlewares/test_request.py index 66673887..61d0f235 100644 --- a/test_app/tests/middlewares/test_request.py +++ b/test_app/tests/middlewares/test_request.py @@ -1,13 +1,10 @@ import logging -import traceback import uuid from unittest import mock from unittest.mock import patch, Mock from django.contrib.auth.models import AnonymousUser, User -from django.core.exceptions import PermissionDenied from django.dispatch import receiver -from django.http import Http404, HttpResponseNotFound, HttpResponseForbidden from django.test import TestCase, RequestFactory import structlog @@ -16,7 +13,6 @@ from django_structlog.signals import ( bind_extra_request_metadata, bind_extra_request_finished_metadata, - bind_extra_request_failed_metadata, ) @@ -251,54 +247,6 @@ def get_response(_response): self.assertIn("user_id", record.msg) self.assertEqual(mock_user.id, record.msg["user_id"]) - def test_log_user_in_request_finished_with_exception(self): - mock_response = Mock() - mock_response.status_code.return_value = 200 - expected_uuid = "00000000-0000-0000-0000-000000000000" - - mock_user = User.objects.create() - - request = self.factory.get("/foo") - - middleware = middlewares.RequestMiddleware(None) - exception = Exception() - - def get_response(_response): - request.user = mock_user - try: - raise exception - except Exception as e: - middleware.process_exception(request, e) - self.exception_traceback = traceback.format_exc() - return mock_response - - middleware.get_response = get_response - - with patch("uuid.UUID.__str__", return_value=expected_uuid), self.assertLogs( - "django_structlog.middlewares.request", logging.INFO - ) as log_results: - middleware(request) - - self.assertEqual(2, len(log_results.records)) - record = log_results.records[0] - - self.assertEqual("INFO", record.levelname) - self.assertEqual("request_started", record.msg["event"]) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertNotIn("user_id", record.msg) - - record = log_results.records[1] - - self.assertEqual("ERROR", record.levelname) - self.assertEqual("request_failed", record.msg["event"]) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("exception", record.msg) - self.assertEqual(self.exception_traceback.strip(), record.msg["exception"]) - self.assertIn("user_id", record.msg) - self.assertEqual(mock_user.id, record.msg["user_id"]) - def test_signal_bind_extra_request_metadata(self): @receiver(bind_extra_request_metadata) def receiver_bind_extra_request_metadata( @@ -383,210 +331,6 @@ def get_response(_response): self.assertIn("user_id", record.msg) self.assertEqual(mock_user.id, record.msg["user_id"]) - def test_signal_bind_extra_request_failed_metadata(self): - expected_exception = Exception() - - @receiver(bind_extra_request_failed_metadata) - def receiver_bind_extra_request_metadata( - sender, signal, request=None, logger=None, exception=None - ): - self.assertEqual(exception, expected_exception) - structlog.contextvars.bind_contextvars( - user_email=getattr(request.user, "email", "") - ) - - request = self.factory.get("/foo") - - mock_user = User.objects.create(email="foo@example.com") - - request.user = mock_user - middleware = middlewares.RequestMiddleware(None) - - mock_response = Mock() - - def get_response(_response): - middleware.process_exception(request, expected_exception) - return mock_response - - middleware.get_response = get_response - - with self.assertLogs( - "django_structlog.middlewares.request", logging.INFO - ) as log_results: - middleware(request) - - self.assertEqual(2, len(log_results.records)) - record = log_results.records[0] - - self.assertEqual("INFO", record.levelname) - self.assertIn("event", record.msg) - self.assertEqual("request_started", record.msg["event"]) - self.assertIn("request_id", record.msg) - self.assertNotIn("user_email", record.msg) - self.assertIn("user_id", record.msg) - self.assertEqual(mock_user.id, record.msg["user_id"]) - record = log_results.records[1] - - self.assertEqual("ERROR", record.levelname) - self.assertIn("event", record.msg) - self.assertEqual("request_failed", record.msg["event"]) - self.assertIn("request_id", record.msg) - self.assertIn("user_email", record.msg) - self.assertEqual(mock_user.email, record.msg["user_email"]) - self.assertIn("user_id", record.msg) - self.assertEqual(mock_user.id, record.msg["user_id"]) - - def test_process_request_error(self): - expected_uuid = "00000000-0000-0000-0000-000000000000" - - request = self.factory.get("/foo") - request.user = AnonymousUser() - - middleware = middlewares.RequestMiddleware(None) - - exception = Exception("This is an exception") - - def get_response(_response): - """Simulate an exception""" - try: - raise exception - except Exception as e: - middleware.process_exception(request, e) - self.exception_traceback = traceback.format_exc() - - middleware.get_response = get_response - - with patch("uuid.UUID.__str__", return_value=expected_uuid), self.assertLogs( - logging.getLogger("django_structlog"), logging.INFO - ) as log_results: - middleware(request) - - self.assertEqual(2, len(log_results.records)) - record = log_results.records[0] - self.assertEqual("INFO", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - record = log_results.records[1] - self.assertEqual("ERROR", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - self.assertIn("code", record.msg) - self.assertEqual(record.msg["code"], 500) - self.assertIn("exception", record.msg) - self.assertEqual(self.exception_traceback.strip(), record.msg["exception"]) - self.assertIn("request", record.msg) - - with self.assertLogs(__name__, logging.INFO) as log_results: - self.logger.info("hello") - self.assertEqual(1, len(log_results.records)) - record = log_results.records[0] - self.assertNotIn("request_id", record.msg) - self.assertNotIn("user_id", record.msg) - - def test_process_request_403_are_processed_as_regular_requests(self): - expected_uuid = "00000000-0000-0000-0000-000000000000" - - request = self.factory.get("/foo") - request.user = AnonymousUser() - - middleware = middlewares.RequestMiddleware(None) - - exception = PermissionDenied() - - def get_response(_response): - """Simulate an exception""" - middleware.process_exception(request, exception) - return HttpResponseForbidden() - - middleware.get_response = get_response - - with patch("uuid.UUID.__str__", return_value=expected_uuid), self.assertLogs( - logging.getLogger("django_structlog"), logging.INFO - ) as log_results: - middleware(request) - - self.assertEqual(2, len(log_results.records)) - record = log_results.records[0] - self.assertEqual("INFO", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - record = log_results.records[1] - self.assertEqual("INFO", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - self.assertIn("code", record.msg) - self.assertEqual(record.msg["code"], 403) - self.assertNotIn("exception", record.msg) - self.assertIn("request", record.msg) - - with self.assertLogs(__name__, logging.INFO) as log_results: - self.logger.info("hello") - self.assertEqual(1, len(log_results.records)) - record = log_results.records[0] - self.assertNotIn("request_id", record.msg) - self.assertNotIn("user_id", record.msg) - - def test_process_request_404_are_processed_as_regular_requests(self): - expected_uuid = "00000000-0000-0000-0000-000000000000" - - request = self.factory.get("/foo") - request.user = AnonymousUser() - - middleware = middlewares.RequestMiddleware(None) - - exception = Http404() - - def get_response(_response): - """Simulate an exception""" - middleware.process_exception(request, exception) - return HttpResponseNotFound() - - middleware.get_response = get_response - - with patch("uuid.UUID.__str__", return_value=expected_uuid), self.assertLogs( - logging.getLogger("django_structlog"), logging.INFO - ) as log_results: - middleware(request) - - self.assertEqual(2, len(log_results.records)) - record = log_results.records[0] - self.assertEqual("INFO", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - record = log_results.records[1] - self.assertEqual("INFO", record.levelname) - self.assertIn("request_id", record.msg) - self.assertEqual(expected_uuid, record.msg["request_id"]) - self.assertIn("user_id", record.msg) - self.assertIsNone(record.msg["user_id"]) - - self.assertIn("code", record.msg) - self.assertEqual(record.msg["code"], 404) - self.assertNotIn("exception", record.msg) - self.assertIn("request", record.msg) - - with self.assertLogs(__name__, logging.INFO) as log_results: - self.logger.info("hello") - self.assertEqual(1, len(log_results.records)) - record = log_results.records[0] - self.assertNotIn("request_id", record.msg) - self.assertNotIn("user_id", record.msg) - def test_should_log_request_id_from_request_x_request_id_header(self): mock_response = Mock() mock_response.status_code.return_value = 200 From 60823e3cbf188137ef32a4778f1b2297ebb99df1 Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 22:52:32 -0400 Subject: [PATCH 5/6] Remove unused variable --- test_app/tests/middlewares/test_request.py | 1 - 1 file changed, 1 deletion(-) diff --git a/test_app/tests/middlewares/test_request.py b/test_app/tests/middlewares/test_request.py index 61d0f235..4244045c 100644 --- a/test_app/tests/middlewares/test_request.py +++ b/test_app/tests/middlewares/test_request.py @@ -21,7 +21,6 @@ def setUp(self): self.factory = RequestFactory() self.logger = structlog.getLogger(__name__) self.log_results = None - self.exception_traceback = None def tearDown(self): structlog.contextvars.clear_contextvars() From 04040effbdfefce3644515d3e860111f24d1f058 Mon Sep 17 00:00:00 2001 From: Jules Robichaud-Gagnon Date: Wed, 22 Mar 2023 23:21:18 -0400 Subject: [PATCH 6/6] Fix doc --- django_structlog/middlewares/request.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/django_structlog/middlewares/request.py b/django_structlog/middlewares/request.py index 341888d8..64d1a25f 100644 --- a/django_structlog/middlewares/request.py +++ b/django_structlog/middlewares/request.py @@ -77,6 +77,15 @@ def bind_user_id(request): class RequestMiddleware(BaseRequestMiddleWare): + """``RequestMiddleware`` adds request metadata to ``structlog``'s logger context automatically. + + >>> MIDDLEWARE = [ + ... # ... + ... 'django_structlog.middlewares.RequestMiddleware', + ... ] + + """ + sync_capable = True async_capable = True