middleware: Log 5xx json_errors in JsonErrorHandler.

django.request logs responses with 5xx response codes (our configuration
of the logger prevents it from logging 4xx as well which it normally
does too). However, it does it without the traceback which results in
quite unhelpful log message that look like
"Bad Gateway:/api/v1/users/me/apns_device_token" - particularly
confusing when sent via email to server admins.

The solution here is to do the logging ourselves, using Django's
log_response() (which is meant for this purpose), and including the
traceback. Django tracks (via response._has_been_logged attribute) that
the response has already been logged, and knows to not duplicate that
action. See log_response() in django's codebase for these details.

Fixes #19596.

zerver/middleware.py

@@ -26,6 +26,7 @@ from django.shortcuts import render
 from django.utils import translation
 from django.utils.cache import patch_vary_headers
 from django.utils.deprecation import MiddlewareMixin
+from django.utils.log import log_response
 from django.utils.translation import gettext as _
 from django.views.csrf import csrf_failure as html_csrf_failure
 from django_scim.middleware import SCIMAuthCheckMiddleware
@@ -456,7 +457,22 @@ class JsonErrorHandler(MiddlewareMixin):
                 return json_unauthorized(www_authenticate="session")
 
         if isinstance(exception, JsonableError):
-            return json_response_from_error(exception)
+            response = json_response_from_error(exception)
+            if response.status_code >= 500:
+                # Here we use Django's log_response the way Django uses
+                # it normally to log error responses. However, we make the small
+                # modification of including the traceback to make the log message
+                # more helpful. log_response takes care of knowing not to duplicate
+                # the logging, so Django won't generate a second log message.
+                log_response(
+                    "%s: %s",
+                    response.reason_phrase,
+                    request.path,
+                    response=response,
+                    request=request,
+                    exc_info=True,
+                )
+            return response
         if RequestNotes.get_notes(request).error_format == "JSON" and not settings.TEST_SUITE:
             capture_exception(exception)
             json_error_logger = logging.getLogger("zerver.middleware.json_error_handler")

zerver/tests/test_push_notifications.py

@@ -477,11 +477,9 @@ class PushBouncerNotificationTest(BouncerTestCase):
                     "ConnectionError while trying to connect to push notification bouncer",
                     502,
                 )
-                self.assertEqual(
-                    error_log.output,
-                    [
-                        f"ERROR:django.request:Bad Gateway: {endpoint}",
-                    ],
+                self.assertIn(
+                    f"ERROR:django.request:Bad Gateway: {endpoint}\nTraceback",
+                    error_log.output[0],
                 )
 
             with responses.RequestsMock() as resp, self.assertLogs(level="WARNING") as warn_log:
@@ -489,11 +487,11 @@ class PushBouncerNotificationTest(BouncerTestCase):
                 result = self.client_post(endpoint, {"token": token}, subdomain="zulip")
                 self.assert_json_error(result, "Received 500 from push notification bouncer", 502)
                 self.assertEqual(
-                    warn_log.output,
-                    [
-                        "WARNING:root:Received 500 from push notification bouncer",
-                        f"ERROR:django.request:Bad Gateway: {endpoint}",
-                    ],
+                    warn_log.output[0],
+                    "WARNING:root:Received 500 from push notification bouncer",
+                )
+                self.assertIn(
+                    f"ERROR:django.request:Bad Gateway: {endpoint}\nTraceback", warn_log.output[1]
                 )
 
         # Add tokens