Properly handle exceptions

Fixes #19

django_structlog/middlewares/request.py

@@ -2,6 +2,8 @@
 
 import structlog
 import traceback
+from django.http import Http404
+
 from .. import signals
 
 logger = structlog.getLogger(__name__)
@@ -18,6 +20,7 @@ class RequestMiddleware:
     """
 
     def __init__(self, get_response):
+        self._has_error = False
         self.get_response = get_response
 
     def __call__(self, request):
@@ -41,24 +44,30 @@ def __call__(self, request):
                 request=request,
                 user_agent=request.META.get("HTTP_USER_AGENT"),
             )
-            try:
-                response = self.get_response(request)
-
-            except Exception as e:
-                traceback_object = e.__traceback__
-                formatted_traceback = traceback.format_tb(traceback_object)
-
-                logger.error(
-                    "request_failed",
-                    error_message=str(e),
-                    error_traceback=formatted_traceback,
-                    code=500,
-                    request=request,
-                )
-                raise
-            else:
+            self._has_error = False
+            response = self.get_response(request)
+            if not self._has_error:
                 logger.info(
                     "request_finished", code=response.status_code, request=request
                 )
 
         return response
+
+    def process_exception(self, request, exception):
+        if isinstance(exception, Http404):
+            # 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._has_error = True
+
+        traceback_object = exception.__traceback__
+        formatted_traceback = traceback.format_tb(traceback_object)
+        logger.exception(
+            "request_failed",
+            code=500,
+            request=request,
+            error=exception,
+            error_traceback=formatted_traceback,
+        )

django_structlog_demo_project/test_app/tests/middlewares/test_request.py

@@ -3,6 +3,7 @@
 
 from django.contrib.auth.models import AnonymousUser
 from django.dispatch import receiver
+from django.http import Http404, HttpResponseNotFound
 from django.test import TestCase, RequestFactory
 import structlog
 
@@ -155,20 +156,24 @@ def test_process_request_error(self):
         expected_uuid = "00000000-0000-0000-0000-000000000000"
         self.log_results = None
 
-        def get_response(_response):
-            raise Exception("This is an exception")
-
         request = self.factory.get("/foo")
         request.user = AnonymousUser()
 
-        middleware = middlewares.RequestMiddleware(get_response)
+        middleware = middlewares.RequestMiddleware(None)
+
+        exception = Exception("This is an exception")
+
+        def get_response(_response):
+            """ Simulate an exception """
+            middleware.process_exception(request, exception)
+
+        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, self.assertRaises(Exception) as e:
+        ) as log_results:
             middleware(request)
 
-        self.assertEqual("This is an exception", str(e.exception))
-
         self.assertEqual(2, len(log_results.records))
         record = log_results.records[0]
         self.assertEqual("INFO", record.levelname)
@@ -186,11 +191,63 @@ def get_response(_response):
 
         self.assertIn("code", record.msg)
         self.assertEqual(record.msg["code"], 500)
-        self.assertIn("error_message", record.msg)
-        self.assertEqual(record.msg["error_message"], "This is an exception")
+        self.assertIn("error", record.msg)
+        self.assertEqual(record.msg["error"], exception)
         self.assertIn("error_traceback", record.msg)
         self.assertEqual(type(record.msg["error_traceback"]), list)
         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"
+        self.log_results = None
+
+        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("error", record.msg)
+        self.assertNotIn("error_traceback", 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))

docs/changelog.rst

@@ -1,9 +1,15 @@
 Change Log
 ==========
 
+1.4.0 (November 27, 2019)
+-------------------------
+
+*Bugfix:*
+    - Exception logging not working properly with ``DEBUG = False``. See `#19 <https://github.com/jrobichaud/django-structlog/issues/19>`_. Special thanks to `@danpalmer <https://github.com/danpalmer>`_
+
 
 1.3.3 (October 6, 2019)
---------------------------
+-----------------------
 
 *Bugfix:*
     - Fix support of different primary key for ``User`` model. See `#13 <https://github.com/jrobichaud/django-structlog/issues/13>`_. Special thanks to `@dhararon <https://github.com/dhararon>`_

docs/events.rst

@@ -51,7 +51,9 @@ These metadata appear once along with their associated event
 +------------------+------------------+------------------------+
 | request_finished | code             | request's status code  |
 +------------------+------------------+------------------------+
-| request_failed   | exception        | exception as string    |
+| request_failed   | error            | exception object       |
++------------------+------------------+------------------------+
+| request_failed   | error_traceback  | exception's traceback  |
 +------------------+------------------+------------------------+
 
 

requirements/base.txt

@@ -20,6 +20,6 @@ django-redis==4.10.0  # https://github.com/niwinz/django-redis
 djangorestframework==3.9.2  # https://github.com/encode/django-rest-framework
 coreapi==2.3.3  # https://github.com/core-api/python-client
 
-structlog>=19,<20
+structlog>=19.2.0,<20
 colorama>=0.4.1
 django-ipware==2.1.0

requirements/ci.txt

@@ -19,7 +19,7 @@ django-redis==4.10.0  # https://github.com/niwinz/django-redis
 djangorestframework==3.9.2  # https://github.com/encode/django-rest-framework
 coreapi==2.3.3  # https://github.com/core-api/python-client
 
-structlog>=19,<20
+structlog>=19.2.0,<20
 colorama>=0.4.1
 
 Werkzeug==0.15.2  # https://github.com/pallets/werkzeug