Repository: jrobichaud/django-structlog

Issue:
request(middleware): Use log levels when logging responses
Would be nice if error levels were used when logging responses. Similar to Django's request handler:

https://github.com/django/django/blob/main/django/utils/log.py#L233-L249

Would simplify integration with structlog's stdlibs `filter_by_level` that filters based on method name and `add_log_level` that adds the log level. I currently add my processor for adding status_code -> level. But having issues with a custom filter to exclude log levels based on `level` instead of `method_name` since I think the python logging framework drops my log either way based on the `method_name` when setting logging level to warning for example.

Opinionated request, understandable if it does not go through.

Discussion:

Patch:
diff --git a/django_structlog/app_settings.py b/django_structlog/app_settings.py
index e54b01b..6f5e914 100644
--- a/django_structlog/app_settings.py
+++ b/django_structlog/app_settings.py
@@ -1,3 +1,5 @@
+import logging
+
 from django.conf import settings
 
 
@@ -9,5 +11,9 @@ class AppSettings:
     def CELERY_ENABLED(self):
         return getattr(settings, self.PREFIX + "CELERY_ENABLED", False)
 
+    @property
+    def STATUS_4XX_LOG_LEVEL(self):
+        return getattr(settings, self.PREFIX + "STATUS_4XX_LOG_LEVEL", logging.WARNING)
+
 
 app_settings = AppSettings()
diff --git a/django_structlog/middlewares/request.py b/django_structlog/middlewares/request.py
index bf0375d..5a11f5a 100644
--- a/django_structlog/middlewares/request.py
+++ b/django_structlog/middlewares/request.py
@@ -1,3 +1,4 @@
+import logging
 import uuid
 
 import structlog
@@ -7,6 +8,7 @@ from django.http import Http404
 from asgiref import sync
 
 from .. import signals
+from ..app_settings import app_settings
 
 logger = structlog.getLogger(__name__)
 
@@ -31,7 +33,14 @@ class BaseRequestMiddleWare:
                 logger=logger,
                 response=response,
             )
-            logger.info(
+            if response.status_code >= 500:
+                level = logging.ERROR
+            elif response.status_code >= 400:
+                level = app_settings.STATUS_4XX_LOG_LEVEL
+            else:
+                level = logging.INFO
+            logger.log(
+                level,
                 "request_finished",
                 code=response.status_code,
                 request=self.format_request(request),
@@ -112,9 +121,9 @@ class RequestMiddleware(BaseRequestMiddleWare):
     """``RequestMiddleware`` adds request metadata to ``structlog``'s logger context automatically.
 
     >>> MIDDLEWARE = [
-        ...     # ...
-        ...     'django_structlog.middlewares.RequestMiddleware',
-        ... ]
+    ...     # ...
+    ...     'django_structlog.middlewares.RequestMiddleware',
+    ... ]
 
     """
 
diff --git a/docs/celery.rst b/docs/celery.rst
index 70a8d07..09c4a67 100644
--- a/docs/celery.rst
+++ b/docs/celery.rst
@@ -1,3 +1,5 @@
+.. _celery_integration:
+
 Celery Integration
 ==================
 
diff --git a/docs/changelog.rst b/docs/changelog.rst
index f012f44..1627e28 100644
--- a/docs/changelog.rst
+++ b/docs/changelog.rst
@@ -17,6 +17,7 @@ See: :ref:`upgrade_6.0`
         - :class:`django_structlog.middlewares.SyncRequestMiddleware`
         - :class:`django_structlog.middlewares.AsyncRequestMiddleware`
         - :class:`django_structlog.middlewares.request_middleware_router`
+    - ``4XX`` status codes now log by default as ``WARNING`` and ``5XX`` as ``ERROR``. The behaviour of ``4XX`` can be customized with :ref:`configuration`. See `#308 <https://github.com/jrobichaud/django-structlog/issues/308>`_. Special thanks to `@adinhodovic <https://github.com/adinhodovic>`_.
 
 
 5.3.0 (June 30, 2023)
diff --git a/docs/configuration.rst b/docs/configuration.rst
new file mode 100644
index 0000000..7ff608f
--- /dev/null
+++ b/docs/configuration.rst
@@ -0,0 +1,25 @@
+.. _configuration:
+
+Configuration
+=============
+
+In your ``settings.py`` you can customize ``django-structlog``.
+
+Example:
+
+.. code-block:: python
+
+    import logging
+    DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL = logging.INFO
+
+
+Settings
+--------
+
++---------------------------------------+---------+-----------------+-------------------------------+
+| Key                                   | Type    | Default         | Description                   |
++=======================================+=========+=================+===============================+
+| DJANGO_STRUCTLOG_CELERY_ENABLED       | boolean | False           | See :ref:`celery_integration` |
++---------------------------------------+---------+-----------------+-------------------------------+
+| DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL | int     | logging.WARNING | Log level of 4XX status codes |
++---------------------------------------+---------+-----------------+-------------------------------+
diff --git a/docs/events.rst b/docs/events.rst
index 5cbce35..90c9e1d 100644
--- a/docs/events.rst
+++ b/docs/events.rst
@@ -7,15 +7,15 @@ Django's RequestMiddleware
 Request Events
 ^^^^^^^^^^^^^^
 
-+------------------+---------+------------------------------+
-| Event            | Type    | Description                  |
-+==================+=========+==============================+
-| request_started  | INFO    | Django received a request    |
-+------------------+---------+------------------------------+
-| request_finished | INFO    | request completed normally   |
-+------------------+---------+------------------------------+
-| request_failed   | ERROR   | unhandled exception occurred |
-+------------------+---------+------------------------------+
++------------------+--------------------+----------------------------------------------------+
+| Event            | Type               | Description                                        |
++==================+====================+====================================================+
+| request_started  | INFO               | Django received a request                          |
++------------------+--------------------+----------------------------------------------------+
+| request_finished | INFO/WARNING/ERROR | request completed with status (2XX or 3XX)/4XX/5XX |
++------------------+--------------------+----------------------------------------------------+
+| request_failed   | ERROR              | unhandled exception occurred                       |
++------------------+--------------------+----------------------------------------------------+
 
 Request Bound Metadata
 ^^^^^^^^^^^^^^^^^^^^^^
diff --git a/docs/index.rst b/docs/index.rst
index dd8bdd6..2c4c189 100644
--- a/docs/index.rst
+++ b/docs/index.rst
@@ -11,6 +11,7 @@ Contents, indices and tables
 
   getting_started
   celery
+  configuration
   api_documentation
   events
   example_outputs


Test patch:
diff --git a/test_app/tests/middlewares/test_request.py b/test_app/tests/middlewares/test_request.py
index 2685854..d69c8c6 100644
--- a/test_app/tests/middlewares/test_request.py
+++ b/test_app/tests/middlewares/test_request.py
@@ -7,8 +7,13 @@ 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
+from django.http import (
+    Http404,
+    HttpResponseNotFound,
+    HttpResponseForbidden,
+    HttpResponseServerError,
+)
+from django.test import TestCase, RequestFactory, override_settings
 import structlog
 
 from django_structlog import middlewares
@@ -31,7 +36,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_without_user(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         def get_response(_response):
@@ -61,7 +66,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_with_null_user(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         def get_response(_response):
@@ -92,7 +97,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_anonymous(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         def get_response(_response):
@@ -125,7 +130,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_user(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         def get_response(_response):
@@ -161,7 +166,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_user_uuid(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         def get_response(_response):
@@ -189,7 +194,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_process_request_user_without_id(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
 
         def get_response(_response):
             with self.assertLogs(__name__, logging.INFO) as log_results:
@@ -215,7 +220,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_log_user_in_request_finished(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         mock_user = User.objects.create()
@@ -252,7 +257,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_log_user_in_request_finished_with_exception(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         expected_uuid = "00000000-0000-0000-0000-000000000000"
 
         mock_user = User.objects.create()
@@ -308,7 +313,7 @@ class TestRequestMiddleware(TestCase):
             )
 
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
 
         def get_response(_response):
             with self.assertLogs(__name__, logging.INFO) as log_results:
@@ -335,7 +340,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_signal_bind_extra_request_finished_metadata(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
 
         @receiver(bind_extra_request_finished_metadata)
         def receiver_bind_extra_request_metadata(
@@ -520,7 +525,7 @@ class TestRequestMiddleware(TestCase):
         self.assertIsNone(record.msg["user_id"])
 
         record = log_results.records[1]
-        self.assertEqual("INFO", record.levelname)
+        self.assertEqual("WARNING", record.levelname)
         self.assertIn("request_id", record.msg)
         self.assertEqual(expected_uuid, record.msg["request_id"])
         self.assertIn("user_id", record.msg)
@@ -569,6 +574,57 @@ class TestRequestMiddleware(TestCase):
         self.assertIn("user_id", record.msg)
         self.assertIsNone(record.msg["user_id"])
 
+        record = log_results.records[1]
+        self.assertEqual("WARNING", 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)
+        self.assertFalse(hasattr(request, "_raised_exception"))
+
+    @override_settings(DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL=logging.INFO)
+    def test_process_request_4XX_can_be_personalized(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)
@@ -589,9 +645,55 @@ class TestRequestMiddleware(TestCase):
         self.assertNotIn("user_id", record.msg)
         self.assertFalse(hasattr(request, "_raised_exception"))
 
+    def test_process_request_500_are_processed_as_errors(self):
+        expected_uuid = "00000000-0000-0000-0000-000000000000"
+
+        request = self.factory.get("/foo")
+        request.user = AnonymousUser()
+
+        middleware = middlewares.RequestMiddleware(None)
+
+        def get_response(_response):
+            return HttpResponseServerError()
+
+        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.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)
+        self.assertFalse(hasattr(request, "_raised_exception"))
+
     def test_should_log_request_id_from_request_x_request_id_header(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         x_request_id = "my-fake-request-id"
 
         def get_response(_response):
@@ -615,7 +717,7 @@ class TestRequestMiddleware(TestCase):
 
     def test_should_log_correlation_id_from_request_x_correlation_id_header(self):
         mock_response = Mock()
-        mock_response.status_code.return_value = 200
+        mock_response.status_code = 200
         x_correlation_id = "my-fake-correlation-id"
 
         def get_response(_response):