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( - 'Forbidden (Permission denied): %s', request.path, - extra={'status_code': 403, 'request': request}, - ) response = get_exception_response(request, get_resolver(get_urlconf()), 403, exc) + log_response( + 'Forbidden (Permission denied): %s', request.path, + response=response, + request=request, + exc_info=sys.exc_info(), + ) elif isinstance(exc, MultiPartParserError): - logger.warning( - 'Bad request (Unable to parse request body): %s', request.path, - extra={'status_code': 400, 'request': request}, - ) response = get_exception_response(request, get_resolver(get_urlconf()), 400, exc) + log_response( + 'Bad request (Unable to parse request body): %s', request.path, + response=response, + request=request, + exc_info=sys.exc_info(), + ) 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 diff --git a/docs/topics/logging.txt b/docs/topics/logging.txt index 3a0aa9c249..5772df0341 100644 --- a/docs/topics/logging.txt +++ b/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: diff --git a/tests/logging_tests/tests.py b/tests/logging_tests/tests.py index 0330fdccf5..e38a193693 100644 --- a/tests/logging_tests/tests.py +++ b/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')], diff --git a/tests/logging_tests/urls.py b/tests/logging_tests/urls.py index fa2c0fcd02..d5cdb7c17d 100644 --- a/tests/logging_tests/urls.py +++ b/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), ] diff --git a/tests/logging_tests/views.py b/tests/logging_tests/views.py index cb7112e435..a40a517233 100644 --- a/tests/logging_tests/views.py +++ b/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')