diff --git a/tests/logging_tests/tests.py b/tests/logging_tests/tests.py index c8de1e415e..86c207882f 100644 --- a/tests/logging_tests/tests.py +++ b/tests/logging_tests/tests.py @@ -1,7 +1,7 @@ import logging from contextlib import contextmanager from io import StringIO -from unittest import mock +from unittest import TestCase, mock from admin_scripts.tests import AdminScriptTestCase @@ -10,6 +10,7 @@ from django.core import mail from django.core.exceptions import DisallowedHost, PermissionDenied, SuspiciousOperation from django.core.files.temp import NamedTemporaryFile from django.core.management import color +from django.http import HttpResponse from django.http.multipartparser import MultiPartParserError from django.test import RequestFactory, SimpleTestCase, override_settings from django.test.utils import LoggingCaptureMixin @@ -20,6 +21,7 @@ from django.utils.log import ( RequireDebugFalse, RequireDebugTrue, ServerFormatter, + log_response, ) from django.views.debug import ExceptionReporter @@ -665,3 +667,122 @@ class LogFormattersTests(SimpleTestCase): self.assertRegex( logger_output.getvalue(), r"^\[[/:,\w\s\d]+\] %s\n" % log_msg ) + + +class LogResponseRealLoggerTests(TestCase): + + request = RequestFactory().get("/test-path/") + + def assertResponseLogged(self, logger_cm, msg, levelno, status_code, request): + self.assertEqual( + records_len := len(logger_cm.records), + 1, + f"Unexpected number of records for {logger_cm=} in {levelno=} (expected 1, " + f"got {records_len}).", + ) + record = logger_cm.records[0] + self.assertEqual(record.getMessage(), msg) + self.assertEqual(record.levelno, levelno) + self.assertEqual(record.status_code, status_code) + self.assertEqual(record.request, request) + + def test_missing_response_raises_attribute_error(self): + with self.assertRaises(AttributeError): + log_response("No response provided", response=None, request=self.request) + + def test_missing_request_logs_with_none(self): + response = HttpResponse(status=403) + with self.assertLogs("django.request", level="INFO") as cm: + log_response(msg := "Missing request", response=response, request=None) + self.assertResponseLogged(cm, msg, logging.WARNING, 403, request=None) + + def test_logs_5xx_as_error(self): + response = HttpResponse(status=508) + with self.assertLogs("django.request", level="ERROR") as cm: + log_response( + msg := "Server error occurred", response=response, request=self.request + ) + self.assertResponseLogged(cm, msg, logging.ERROR, 508, self.request) + + def test_logs_4xx_as_warning(self): + response = HttpResponse(status=418) + with self.assertLogs("django.request", level="WARNING") as cm: + log_response( + msg := "This is a teapot!", response=response, request=self.request + ) + self.assertResponseLogged(cm, msg, logging.WARNING, 418, self.request) + + def test_logs_2xx_as_info(self): + response = HttpResponse(status=201) + with self.assertLogs("django.request", level="INFO") as cm: + log_response(msg := "OK response", response=response, request=self.request) + self.assertResponseLogged(cm, msg, logging.INFO, 201, self.request) + + def test_custom_log_level(self): + response = HttpResponse(status=403) + with self.assertLogs("django.request", level="DEBUG") as cm: + log_response( + msg := "Debug level log", + response=response, + request=self.request, + level="debug", + ) + self.assertResponseLogged(cm, msg, logging.DEBUG, 403, self.request) + + def test_logs_only_once_per_response(self): + response = HttpResponse(status=500) + with self.assertLogs("django.request", level="ERROR") as cm: + log_response("First log", response=response, request=self.request) + log_response("Second log", response=response, request=self.request) + self.assertResponseLogged(cm, "First log", logging.ERROR, 500, self.request) + + def test_exc_info_output(self): + response = HttpResponse(status=500) + try: + raise ValueError("Simulated failure") + except ValueError as exc: + with self.assertLogs("django.request", level="ERROR") as cm: + log_response( + "With exception", + response=response, + request=self.request, + exception=exc, + ) + self.assertResponseLogged( + cm, "With exception", logging.ERROR, 500, self.request + ) + self.assertIn("ValueError", "\n".join(cm.output)) # Stack trace included + + def test_format_args_are_applied(self): + response = HttpResponse(status=500) + with self.assertLogs("django.request", level="ERROR") as cm: + log_response( + "Something went wrong: %s (%d)", + "DB error", + 42, + response=response, + request=self.request, + ) + msg = "Something went wrong: DB error (42)" + self.assertResponseLogged(cm, msg, logging.ERROR, 500, self.request) + + def test_logs_with_custom_logger(self): + handler = logging.StreamHandler(log_stream := StringIO()) + handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s")) + + custom_logger = logging.getLogger("my.custom.logger") + custom_logger.setLevel(logging.DEBUG) + custom_logger.addHandler(handler) + self.addCleanup(custom_logger.removeHandler, handler) + + response = HttpResponse(status=404) + log_response( + msg := "Handled by custom logger", + response=response, + request=self.request, + logger=custom_logger, + ) + + self.assertEqual( + f"WARNING:my.custom.logger:{msg}", log_stream.getvalue().strip() + )