Fixed #26688 -- Fixed HTTP request logging inconsistencies.

* Added logging of 500 responses for instantiated responses.
* Added logging of all 4xx and 5xx responses.

django/core/handlers/base.py

@@ -5,6 +5,7 @@ from django.conf import settings
 from django.core.exceptions import ImproperlyConfigured, MiddlewareNotUsed
 from django.db import connections, transaction
 from django.urls import get_resolver, set_urlconf
+from django.utils.log import log_response
 from django.utils.module_loading import import_string
 
 from .exception import convert_exception_to_response, get_exception_response
@@ -87,10 +88,11 @@ class BaseHandler:
         if not getattr(response, 'is_rendered', True) and callable(getattr(response, 'render', None)):
             response = response.render()
 
-        if response.status_code == 404:
-            logger.warning(
-                'Not Found: %s', request.path,
-                extra={'status_code': 404, 'request': request},
+        if response.status_code >= 400:
+            log_response(
+                '%s: %s', response.reason_phrase, request.path,
+                response=response,
+                request=request,
             )
 
         return response

django/core/handlers/exception.py

@@ -11,10 +11,9 @@ from django.core.exceptions import (
 from django.http import Http404
 from django.http.multipartparser import MultiPartParserError
 from django.urls import get_resolver, get_urlconf
+from django.utils.log import log_response
 from django.views import debug
 
-logger = logging.getLogger('django.request')
-
 
 def convert_exception_to_response(get_response):
     """
@@ -47,18 +46,22 @@ def response_for_exception(request, exc):
             response = get_exception_response(request, get_resolver(get_urlconf()), 404, exc)
 
     elif isinstance(exc, PermissionDenied):
-        logger.warning(
+        response = get_exception_response(request, get_resolver(get_urlconf()), 403, exc)
+        log_response(
             'Forbidden (Permission denied): %s', request.path,
-            extra={'status_code': 403, 'request': request},
+            response=response,
+            request=request,
+            exc_info=sys.exc_info(),
         )
-        response = get_exception_response(request, get_resolver(get_urlconf()), 403, exc)
 
     elif isinstance(exc, MultiPartParserError):
-        logger.warning(
+        response = get_exception_response(request, get_resolver(get_urlconf()), 400, exc)
+        log_response(
             'Bad request (Unable to parse request body): %s', request.path,
-            extra={'status_code': 400, 'request': request},
+            response=response,
+            request=request,
+            exc_info=sys.exc_info(),
         )
-        response = get_exception_response(request, get_resolver(get_urlconf()), 400, exc)
 
     elif isinstance(exc, SuspiciousOperation):
         if isinstance(exc, (RequestDataTooBig, TooManyFieldsSent)):
@@ -85,6 +88,12 @@ def response_for_exception(request, exc):
     else:
         signals.got_request_exception.send(sender=None, request=request)
         response = handle_uncaught_exception(request, get_resolver(get_urlconf()), sys.exc_info())
+        log_response(
+            '%s: %s', response.reason_phrase, request.path,
+            response=response,
+            request=request,
+            exc_info=sys.exc_info(),
+        )
 
     # Force a TemplateResponse to be rendered.
     if not getattr(response, 'is_rendered', True) and callable(getattr(response, 'render', None)):
@@ -112,12 +121,6 @@ def handle_uncaught_exception(request, resolver, exc_info):
     if settings.DEBUG_PROPAGATE_EXCEPTIONS:
         raise
 
-    logger.error(
-        'Internal Server Error: %s', request.path,
-        exc_info=exc_info,
-        extra={'status_code': 500, 'request': request},
-    )
-
     if settings.DEBUG:
         return debug.technical_500_response(request, *exc_info)
 

django/middleware/csrf.py

@@ -16,6 +16,7 @@ from django.utils.cache import patch_vary_headers
 from django.utils.crypto import constant_time_compare, get_random_string
 from django.utils.deprecation import MiddlewareMixin
 from django.utils.http import is_same_domain
+from django.utils.log import log_response
 
 logger = logging.getLogger('django.security.csrf')
 
@@ -146,14 +147,14 @@ class CsrfViewMiddleware(MiddlewareMixin):
         return None
 
     def _reject(self, request, reason):
-        logger.warning(
+        response = _get_failure_view()(request, reason=reason)
+        log_response(
             'Forbidden (%s): %s', reason, request.path,
-            extra={
-                'status_code': 403,
-                'request': request,
-            }
+            response=response,
+            request=request,
+            logger=logger,
         )
-        return _get_failure_view()(request, reason=reason)
+        return response
 
     def _get_token(self, request):
         if settings.CSRF_USE_SESSIONS:

django/utils/cache.py

@@ -17,7 +17,6 @@ An example: i18n middleware would need to distinguish caches by the
 "Accept-language" header.
 """
 import hashlib
-import logging
 import re
 import time
 
@@ -28,13 +27,12 @@ from django.utils.encoding import force_bytes, iri_to_uri
 from django.utils.http import (
     http_date, parse_etags, parse_http_date_safe, quote_etag,
 )
+from django.utils.log import log_response
 from django.utils.timezone import get_current_timezone_name
 from django.utils.translation import get_language
 
 cc_delim_re = re.compile(r'\s*,\s*')
 
-logger = logging.getLogger('django.request')
-
 
 def patch_cache_control(response, **kwargs):
     """
@@ -106,14 +104,13 @@ def set_response_etag(response):
 
 
 def _precondition_failed(request):
-    logger.warning(
+    response = HttpResponse(status=412)
+    log_response(
         'Precondition Failed: %s', request.path,
-        extra={
-            'status_code': 412,
-            'request': request,
-        },
+        response=response,
+        request=request,
     )
-    return HttpResponse(status=412)
+    return response
 
 
 def _not_modified(request, response=None):

django/utils/log.py

@@ -9,6 +9,8 @@ from django.core.management.color import color_style
 from django.utils.module_loading import import_string
 from django.views.debug import ExceptionReporter
 
+request_logger = logging.getLogger('django.request')
+
 # Default logging for Django. This sends an email to the site admins on every
 # HTTP 500 error. Depending on DEBUG, all other log records are either sent to
 # the console (DEBUG=True) or discarded (DEBUG=False) by means of the
@@ -192,3 +194,37 @@ class ServerFormatter(logging.Formatter):
 
     def uses_server_time(self):
         return self._fmt.find('{server_time}') >= 0
+
+
+def log_response(message, *args, response=None, request=None, logger=request_logger, level=None, exc_info=None):
+    """
+    Log errors based on HttpResponse status.
+
+    Log 5xx responses as errors and 4xx responses as warnings (unless a level
+    is given as a keyword argument). The HttpResponse status_code and the
+    request are passed to the logger's extra parameter.
+    """
+    # Check if the response has already been logged. Multiple requests to log
+    # the same response can be received in some cases, e.g., when the
+    # response is the result of an exception and is logged at the time the
+    # exception is caught so that the exc_info can be recorded.
+    if getattr(response, '_has_been_logged', False):
+        return
+
+    if level is None:
+        if response.status_code >= 500:
+            level = 'error'
+        elif response.status_code >= 400:
+            level = 'warning'
+        else:
+            level = 'info'
+
+    getattr(logger, level)(
+        message, *args,
+        extra={
+            'status_code': response.status_code,
+            'request': request,
+        },
+        exc_info=exc_info,
+    )
+    response._has_been_logged = True

django/views/decorators/http.py

@@ -2,7 +2,6 @@
 Decorators for views based on HTTP headers.
 """
 
-import logging
 from calendar import timegm
 from functools import wraps
 
@@ -11,11 +10,10 @@ from django.middleware.http import ConditionalGetMiddleware
 from django.utils.cache import get_conditional_response
 from django.utils.decorators import decorator_from_middleware
 from django.utils.http import http_date, quote_etag
+from django.utils.log import log_response
 
 conditional_page = decorator_from_middleware(ConditionalGetMiddleware)
 
-logger = logging.getLogger('django.request')
-
 
 def require_http_methods(request_method_list):
     """
@@ -32,11 +30,13 @@ def require_http_methods(request_method_list):
         @wraps(func)
         def inner(request, *args, **kwargs):
             if request.method not in request_method_list:
-                logger.warning(
+                response = HttpResponseNotAllowed(request_method_list)
+                log_response(
                     'Method Not Allowed (%s): %s', request.method, request.path,
-                    extra={'status_code': 405, 'request': request}
+                    response=response,
+                    request=request,
                 )
-                return HttpResponseNotAllowed(request_method_list)
+                return response
             return func(request, *args, **kwargs)
         return inner
     return decorator

docs/topics/logging.txt

@@ -468,7 +468,8 @@ posted using this name but instead using one of the loggers below.
 
 Log messages related to the handling of requests. 5XX responses are
 raised as ``ERROR`` messages; 4XX responses are raised as ``WARNING``
-messages.
+messages. Requests that are logged to the ``django.security`` logger aren't
+logged to ``django.request``.
 
 Messages to this logger have the following extra context:
 

tests/logging_tests/tests.py

@@ -6,15 +6,18 @@ from admin_scripts.tests import AdminScriptTestCase
 
 from django.conf import settings
 from django.core import mail
+from django.core.exceptions import PermissionDenied
 from django.core.files.temp import NamedTemporaryFile
 from django.core.management import color
+from django.http.multipartparser import MultiPartParserError
 from django.test import RequestFactory, SimpleTestCase, override_settings
-from django.test.utils import LoggingCaptureMixin, patch_logger
+from django.test.utils import LoggingCaptureMixin
 from django.utils.log import (
     DEFAULT_LOGGING, AdminEmailHandler, CallbackFilter, RequireDebugFalse,
     RequireDebugTrue, ServerFormatter,
 )
 
+from . import views
 from .logconfig import MyEmailBackend
 
 # logging config prior to using filter with mail_admins
@@ -106,16 +109,95 @@ class DefaultLoggingTests(SetupDefaultLoggingMixin, LoggingCaptureMixin, SimpleT
         self.assertEqual(self.logger_output.getvalue(), '')
 
 
+class LoggingAssertionMixin(object):
+
+    def assertLogsRequest(self, url, level, msg, status_code, logger='django.request', exc_class=None):
+        with self.assertLogs(logger, level) as cm:
+            try:
+                self.client.get(url)
+            except views.UncaughtException:
+                pass
+            self.assertEqual(
+                len(cm.records), 1,
+                "Wrong number of calls for logger %r in %r level." % (logger, level)
+            )
+            record = cm.records[0]
+            self.assertEqual(record.getMessage(), msg)
+            self.assertEqual(record.status_code, status_code)
+            if exc_class:
+                self.assertIsNotNone(record.exc_info)
+                self.assertEqual(record.exc_info[0], exc_class)
+
+
 @override_settings(DEBUG=True, ROOT_URLCONF='logging_tests.urls')
-class HandlerLoggingTests(SetupDefaultLoggingMixin, LoggingCaptureMixin, SimpleTestCase):
+class HandlerLoggingTests(SetupDefaultLoggingMixin, LoggingAssertionMixin, LoggingCaptureMixin, SimpleTestCase):
 
     def test_page_found_no_warning(self):
         self.client.get('/innocent/')
         self.assertEqual(self.logger_output.getvalue(), '')
 
+    def test_redirect_no_warning(self):
+        self.client.get('/redirect/')
+        self.assertEqual(self.logger_output.getvalue(), '')
+
     def test_page_not_found_warning(self):
-        self.client.get('/does_not_exist/')
-        self.assertEqual(self.logger_output.getvalue(), 'Not Found: /does_not_exist/\n')
+        self.assertLogsRequest(
+            url='/does_not_exist/',
+            level='WARNING',
+            status_code=404,
+            msg='Not Found: /does_not_exist/',
+        )
+
+    def test_page_not_found_raised(self):
+        self.assertLogsRequest(
+            url='/does_not_exist_raised/',
+            level='WARNING',
+            status_code=404,
+            msg='Not Found: /does_not_exist_raised/',
+        )
+
+    def test_uncaught_exception(self):
+        self.assertLogsRequest(
+            url='/uncaught_exception/',
+            level='ERROR',
+            status_code=500,
+            msg='Internal Server Error: /uncaught_exception/',
+            exc_class=views.UncaughtException,
+        )
+
+    def test_internal_server_error(self):
+        self.assertLogsRequest(
+            url='/internal_server_error/',
+            level='ERROR',
+            status_code=500,
+            msg='Internal Server Error: /internal_server_error/',
+        )
+
+    def test_internal_server_error_599(self):
+        self.assertLogsRequest(
+            url='/internal_server_error/?status=599',
+            level='ERROR',
+            status_code=599,
+            msg='Unknown Status Code: /internal_server_error/',
+        )
+
+    def test_permission_denied(self):
+        self.assertLogsRequest(
+            url='/permission_denied/',
+            level='WARNING',
+            status_code=403,
+            msg='Forbidden (Permission denied): /permission_denied/',
+            exc_class=PermissionDenied,
+        )
+
+    def test_multi_part_parser_error(self):
+        self.assertLogsRequest(
+            url='/multi_part_parser_error/',
+            level='WARNING',
+            status_code=400,
+            msg='Bad request (Unable to parse request body): /multi_part_parser_error/',
+            exc_class=MultiPartParserError,
+        )
 
 
 @override_settings(
@@ -401,19 +483,25 @@ class SetupConfigureLogging(SimpleTestCase):
 
 
 @override_settings(DEBUG=True, ROOT_URLCONF='logging_tests.urls')
-class SecurityLoggerTest(SimpleTestCase):
+class SecurityLoggerTest(LoggingAssertionMixin, SimpleTestCase):
 
     def test_suspicious_operation_creates_log_message(self):
-        with patch_logger('django.security.SuspiciousOperation', 'error') as calls:
-            self.client.get('/suspicious/')
-            self.assertEqual(len(calls), 1)
-            self.assertEqual(calls[0], 'dubious')
+        self.assertLogsRequest(
+            url='/suspicious/',
+            level='ERROR',
+            msg='dubious',
+            status_code=400,
+            logger='django.security.SuspiciousOperation',
+        )
 
     def test_suspicious_operation_uses_sublogger(self):
-        with patch_logger('django.security.DisallowedHost', 'error') as calls:
-            self.client.get('/suspicious_spec/')
-            self.assertEqual(len(calls), 1)
-            self.assertEqual(calls[0], 'dubious')
+        self.assertLogsRequest(
+            url='/suspicious_spec/',
+            level='ERROR',
+            msg='dubious',
+            status_code=400,
+            logger='django.security.DisallowedHost',
+        )
 
     @override_settings(
         ADMINS=[('admin', 'admin@example.com')],

tests/logging_tests/urls.py

@@ -1,9 +1,16 @@
 from django.conf.urls import url
+from django.urls import path
 
 from . import views
 
 urlpatterns = [
     url(r'^innocent/$', views.innocent),
+    path('redirect/', views.redirect),
     url(r'^suspicious/$', views.suspicious),
     url(r'^suspicious_spec/$', views.suspicious_spec),
+    path('internal_server_error/', views.internal_server_error),
+    path('uncaught_exception/', views.uncaught_exception),
+    path('permission_denied/', views.permission_denied),
+    path('multi_part_parser_error/', views.multi_part_parser_error),
+    path('does_not_exist_raised/', views.does_not_exist_raised),
 ]

tests/logging_tests/views.py

@@ -1,14 +1,48 @@
-from django.core.exceptions import DisallowedHost, SuspiciousOperation
-from django.http import HttpResponse
+from django.core.exceptions import (
+    DisallowedHost, PermissionDenied, SuspiciousOperation,
+)
+from django.http import (
+    Http404, HttpResponse, HttpResponseRedirect, HttpResponseServerError,
+)
+from django.http.multipartparser import MultiPartParserError
 
 
 def innocent(request):
     return HttpResponse('innocent')
 
 
+def redirect(request):
+    return HttpResponseRedirect('/')
+
+
 def suspicious(request):
     raise SuspiciousOperation('dubious')
 
 
 def suspicious_spec(request):
     raise DisallowedHost('dubious')
+
+
+class UncaughtException(Exception):
+    pass
+
+
+def uncaught_exception(request):
+    raise UncaughtException('Uncaught exception')
+
+
+def internal_server_error(request):
+    status = request.GET.get('status', 500)
+    return HttpResponseServerError('Server Error', status=int(status))
+
+
+def permission_denied(request):
+    raise PermissionDenied()
+
+
+def multi_part_parser_error(request):
+    raise MultiPartParserError('parsing error')
+
+
+def does_not_exist_raised(request):
+    raise Http404('Not Found')