Fixed #26688 -- Fixed HTTP request logging inconsistencies.

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

6 files changed, 78 insertions, 39 deletions

diff --git a/django/core/handlers/base.py b/django/core/handlers/base.py
index 80cc8b3281..be2e90beaf 100644
--- a/django/core/handlers/base.py
+++ b/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
diff --git a/django/core/handlers/exception.py b/django/core/handlers/exception.py
index e98bec262a..3fe6e4d3dd 100644
--- a/django/core/handlers/exception.py
+++ b/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)
 
diff --git a/django/middleware/csrf.py b/django/middleware/csrf.py
index 10f878834d..98830f7774 100644
--- a/django/middleware/csrf.py
+++ b/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:
diff --git a/django/utils/cache.py b/django/utils/cache.py
index 7117d40526..0e0428fc11 100644
--- a/django/utils/cache.py
+++ b/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):
diff --git a/django/utils/log.py b/django/utils/log.py
index 2c3d4ed5e3..2de6dbbb59 100644
--- a/django/utils/log.py
+++ b/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
diff --git a/django/views/decorators/http.py b/django/views/decorators/http.py
index 1c8502fb1e..673302be83 100644
--- a/django/views/decorators/http.py
+++ b/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