Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

Ticket 20752: Error signals are not reliable, especially when dealing with database errors #1778

Closed
wants to merge 7 commits into from

4 participants

@schacki

This is a pull request for ticket https://code.djangoproject.com/ticket/20752

I have changed the core handler in a way such that:

  • the initial error is logged as expected, so the root cause of the trouble is visible and not covered by any other exceptions
  • all connected handlers are completely executed as expected, so no unexpected side-effects from one handler to the other
  • any exceptions from the handlers are logged to the error log, so no errors pass silently, even if therec are multiple.

I have also added unit tests to check that the log entries are created as expected. Since we are dealing with "real" log messages in these test cases, the log messages are more complicated than in the tests for the Django logging. Therefore, I also amended the django.test.utils.patch.logger.

Please check, if the additional log messages for "Request Signal Handler Error" contain the content, that you would expect.

Juergen Scha... added some commits
Juergen Schackmann Changed the core handler such that the correct initial error is logge…
…d as expected and that all signal reivers are executed. Any subsequent errors are logged as well. Unit test has been added, but does not work due to issues with getting the logging output
66cf5ec
Juergen Schackmann Changed the core handler such that the correct initial error is logge…
…d as expected and that all signal reivers are executed. Any subsequent errors are logged as well. Unit test has been added, but does not work due to issues with getting the logging output
844637b
Juergen Schackmann Updated and added unit tests and the patch_logger c3ea26d
Juergen Schackmann Updated and added unit tests and the patch_logger 83c7afe
Juergen Schackmann Refactored the got_request_exception handling into handle_uncaught_ex…
…ception, commented the source, updated unit tests. Made sure that the initial uncaught exception is the main focus, since it is the root cause.
2fdc90c
django/core/handlers/base.py
((45 lines not shown))
return response
+ def handle_got_request_exception_signal(self, sender, request):
+ signal_responses = signals.got_request_exception.send_robust(
+ sender=sender, request=request)
+ for signal_response in signal_responses:
+ if isinstance(signal_response[1], Exception):
+ logger.error('Request Signal Handler Error: %s', request.path,
+ #TODO: should we add the exc_info of the original error here?
@ptone Collaborator
ptone added a note

I'd check settings.DEBUG_PROPAGATE_EXCEPTIONS, and then raise immediately - otherwise just log

@schacki
schacki added a note

ok

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
((45 lines not shown))
return response
+ def handle_got_request_exception_signal(self, sender, request):
@ptone Collaborator
ptone added a note

by convention - 'handle_' as a prefix is used for methods that actually handle an exception condition. This is more of a utility around sending the signal, so while I don't want to bikeshed the naming of it, I'll just say that starting with handle_ is probably not a good choice.

@schacki
schacki added a note

then let's call it "manage_got_request_exception_signal"

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
@@ -150,8 +148,13 @@ def get_response(self, request):
callback, param_dict = resolver.resolve404()
response = callback(request, **param_dict)
except:
- signals.got_request_exception.send(sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
+ # Get the exception info now and handle the current exception.
+ # Only then manage the got_request_excpetion.
+ # Just in case another exception is thrown later.
+ response = self.handle_uncaught_exception(request, resolver,
@ptone Collaborator
ptone added a note

Is there a reason you have changed the order of signals and the 'handle_uncaught_exception'? This may seem to be something that should have not consequence, but without a reason, why take the chance that this would be backwards incompatable with someone who has some crazy setup of coupling a signal receiver and the resolve500 path?

@schacki
schacki added a note

my motivation for this change was the following: if i first send the signal and then call handle_uncaught_excpetion, sys.exc_info() might not refer to the issue that was catched in line 150, but it might refer to any exceptions that were called during the signal execution. consequenntly, the log might refer to an issue that does not relate to the root cause and debugging becomes very, very difficult (which was also mentioned in the ticket). but to make sure that whatever happens during signal handling is catched, I do log any additinal errors separately.

frankly, i do not fully understand your comment on " setup of coupling a signal receiver and the resolve500 path". no matter what signal handlers one might couple here, the inital design generated a a log anyway. from my understanding of the code, whatever happens during "handle_got_request_exception_signal" cannot influence the outcome of "handle_uncaught_exception". it seems like i am missing something here?

@ptone Collaborator
ptone added a note

Sorry for the confused wording - what I mean is someone who has written both a custom signal receiver, and a custom 500 handler, where they do some step in the signal receiver which is required by the 500 handler. To be sure, this would not be a great idea to couple these two things together (not to mention, you shouldn't really do much if anything to the "state" of Django in such a broken condition).

If the handle_uncaught_exception absorbed the signal sending function, would it be sufficient to capture sys.exc_info() into a local, then send signals, then call the 500 view machinery?

@schacki
schacki added a note

actually, my inital version was like that:

exc_info=sys.exc_info()
self.handle_got_request_exception_signal(sender=self.class, request=request)
response = self.handle_uncaught_exception(request, resolver, exc_info)

but after reviewing the code (not only mine), i came to the conclusion that it does not make any difference logic wise; so i decided to go for the cleaner version.

so if it is that what you are proposing, i am happy to do so.
btw: what log message would you propose for any errors in the handlers?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@schacki

I have changed the code as follows:
Refactored the got_request_exception handling into handle_uncaught_exception. This makes to code much cleaner and the process more transparent
The inital exception, that triggered the handle_uncaught_exception is the main focus. I.e. this exception is logged first, this exception is raised if settings.DEBUG_PROPAGATE_EXCEPTIONS is True. This makes debugging and analyzing the root cause of all the trouble much easier (which was one of the reasons, why this ticket was raised), nevertheless all follow-up errors are still logged.
Implemented proposal from ptone, to make the resolve500 more robust.
Commented the code in handle_uncaught_exception to make the process and ideas behind it clearer.

@schacki

I have changed the code as follows:

  • Refactored the got_request_exception handling into handle_uncaught_exception. This makes to code much cleaner and the process more transparent

  • The inital exception, that triggered the handle_uncaught_exception is the main focus. I.e. this exception is logged first, this exception is raised if settings.DEBUG_PROPAGATE_EXCEPTIONS is True. This makes debugging and analyzing the root cause of all the trouble much easier (which was one of the reasons, why this ticket was raised), nevertheless all follow-up errors are still logged.

  • Implemented proposal from ptone, to make the resolve500 more robust.

  • Commented the code in handle_uncaught_exception to make the process and ideas behind it clearer.

django/test/utils.py
@@ -404,8 +404,15 @@ def patch_logger(logger_name, log_level):
and provides a simple mock-like list of messages received
"""
calls = []
- def replacement(msg):
- calls.append(msg)
+ def replacement(msg, path='', exc_info='', extra=''):
@apollo13 Owner

Path/exc_info/extra should be just **kwargs and then added as (msg, kwargs)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
tests/view_tests/tests/test_defaults.py
@@ -1,9 +1,16 @@
from __future__ import unicode_literals
+import logging
+
+from django.utils.six import StringIO
+
+from django.core.signals import got_request_exception
+from django.dispatch import receiver
from django.contrib.contenttypes.models import ContentType
@apollo13 Owner

Import order

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
tests/view_tests/tests/test_defaults.py
((4 lines not shown))
+
+ def test_server_error_without_handler_error(self):
+ """
+ The server_error view raises a 500 status and while handling
+ the error, the next error is raised.
+ """
+
+ @receiver(got_request_exception)
+ def handler(sender, **kwargs):
+ pass
+
+ try:
+ with patch_logger('django.request', 'error') as calls:
+ try:
+ response = self.client.get('/views/raises_unhandled_exception/')
+ except Exception, e:
@apollo13 Owner

Exception as e

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
tests/view_tests/tests/test_defaults.py
((30 lines not shown))
+
+ def test_server_error_with_handler_error(self):
+ """
+ The server_error view raises a 500 status and while handling
+ the error, the next error is raised.
+ """
+
+ @receiver(got_request_exception)
+ def handler(sender, **kwargs):
+ raise Exception('Bad Handler')
+
+ try:
+ with patch_logger('django.request', 'error') as calls:
+ try:
+ response = self.client.get('/views/raises_unhandled_exception/')
+ except Exception, e:
@apollo13 Owner

Exception as e

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
@@ -164,10 +165,11 @@ def get_response(self, request):
callback, param_dict = resolver.resolve403()
response = callback(request, **param_dict)
except:
- signals.got_request_exception.send(
- sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request,
- resolver, sys.exc_info())
+ # Get the exception info now and handle the current exception.
@apollo13 Owner

I'd remove the duplicated comments and just leave one comment where they had been previously

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
@@ -226,15 +241,46 @@ def handle_uncaught_exception(self, request, resolver, exc_info):
}
)
+ # Check whether the handlers executed as expected or if the handlers
+ # itself raised further exceptions
+ for signal_response in signal_responses:
+ if isinstance(signal_response[1], Exception):
+ logger.error('Got Request Exception Handler Error: %s', request.path,
+ #TODO: should we add the exc_info of the original error here?
+ exc_info='',
@apollo13 Owner

I think exc_info is usually (None, None, None) if no data can be found.

EDIT:// the exception probably doesn't know it's exc_info?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
((26 lines not shown))
# Return an HttpResponse that displays a friendly error message.
- callback, param_dict = resolver.resolve500()
- return callback(request, **param_dict)
+ try:
+ callback, param_dict = resolver.resolve500()
+ return callback(request, **param_dict)
+ except:
@apollo13 Owner

except Exception unless we really have a good reason for a bare except.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@apollo13
Owner

Please squash the changes into a single commit and rename it according to https://docs.djangoproject.com/en/dev/internals/contributing/committing-code/#committing-guidelines then I can commit it,

django/test/utils.py
@@ -487,9 +487,11 @@ def patch_logger(logger_name, log_level):
and provides a simple mock-like list of messages received
"""
calls = []
-
@apollo13 Owner

Please restore this empty line and add another after the definition of replacement

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
@@ -98,13 +98,11 @@ def get_response(self, request):
resolver_match = resolver.resolve(request.path_info)
callback, callback_args, callback_kwargs = resolver_match
request.resolver_match = resolver_match
-
@apollo13 Owner

Restore this empty line and the one below

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
django/core/handlers/base.py
((26 lines not shown))
# Return an HttpResponse that displays a friendly error message.
- callback, param_dict = resolver.resolve500()
- return callback(request, **param_dict)
+ try:
+ callback, param_dict = resolver.resolve500()
+ return callback(request, **param_dict)
+ except Exception:
+ # Last Resort: and just in the highly unlikely case that somehting
+ # has gone wrong here, we return a minimal error message to the
+ # user and log the issue.
+
+ logger.error('500 Resolve Error: %s', request.path,
@apollo13 Owner

Tests for this feature seem yet to be missing, and I would rename the message a bit ala 'Error in 500 callback'

@schacki
schacki added a note

This feature is tested in view_tests.tests.test_defaults.py with test_server_error_with_handler_error (line 74ff)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Juergen Schackmann refining tests d1600a1
@apollo13
Owner

@schacki According to github this is still unmergeable.

@timgraham
Owner

@schacki do you have interest and time to finish this sometime or should we close it?

@timgraham
Owner

Please send a new PR if you can update this, thanks!

@timgraham timgraham closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Oct 17, 2013
  1. Changed the core handler such that the correct initial error is logge…

    Juergen Schackmann authored
    …d as expected and that all signal reivers are executed. Any subsequent errors are logged as well. Unit test has been added, but does not work due to issues with getting the logging output
  2. Changed the core handler such that the correct initial error is logge…

    Juergen Schackmann authored
    …d as expected and that all signal reivers are executed. Any subsequent errors are logged as well. Unit test has been added, but does not work due to issues with getting the logging output
  3. Updated and added unit tests and the patch_logger

    Juergen Schackmann authored
  4. Updated and added unit tests and the patch_logger

    Juergen Schackmann authored
Commits on Oct 19, 2013
  1. Refactored the got_request_exception handling into handle_uncaught_ex…

    Juergen Schackmann authored
    …ception, commented the source, updated unit tests. Made sure that the initial uncaught exception is the main focus, since it is the root cause.
Commits on May 16, 2014
  1. merge with master, incorporated propsoals from apollo13

    Juergen Schackmann authored
Commits on Jun 21, 2014
  1. refining tests

    Juergen Schackmann authored
This page is out of date. Refresh to see the latest.
View
92 django/core/handlers/base.py
@@ -149,8 +149,11 @@ def get_response(self, request):
callback, param_dict = resolver.resolve404()
response = callback(request, **param_dict)
except:
- signals.got_request_exception.send(sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
+ response = self.handle_uncaught_exception(
+ request,
+ resolver,
+ sys.exc_info()
+ )
except PermissionDenied:
logger.warning(
@@ -163,10 +166,11 @@ def get_response(self, request):
callback, param_dict = resolver.resolve403()
response = callback(request, **param_dict)
except:
- signals.got_request_exception.send(
- sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request,
- resolver, sys.exc_info())
+ response = self.handle_uncaught_exception(
+ request,
+ resolver,
+ sys.exc_info()
+ )
except SuspiciousOperation as e:
# The request logger receives events for any problematic request
@@ -184,29 +188,32 @@ def get_response(self, request):
callback, param_dict = resolver.resolve400()
response = callback(request, **param_dict)
except:
- signals.got_request_exception.send(
- sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request,
- resolver, sys.exc_info())
-
+ response = self.handle_uncaught_exception(
+ request,
+ resolver,
+ sys.exc_info()
+ )
except SystemExit:
# Allow sys.exit() to actually exit. See tickets #1023 and #4701
raise
- except: # Handle everything else.
- # Get the exception info now, in case another exception is thrown later.
- signals.got_request_exception.send(sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
-
+ except: # Handle everything else.
+ response = self.handle_uncaught_exception(
+ request,
+ resolver,
+ sys.exc_info()
+ )
try:
# Apply response middleware, regardless of the response
for middleware_method in self._response_middleware:
response = middleware_method(request, response)
response = self.apply_response_fixes(request, response)
- except: # Any exception should be gathered and handled
- signals.got_request_exception.send(sender=self.__class__, request=request)
- response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
-
+ except: # Any exception should be gathered and handled
+ response = self.handle_uncaught_exception(
+ request,
+ resolver,
+ sys.exc_info()
+ )
return response
def handle_uncaught_exception(self, request, resolver, exc_info):
@@ -219,9 +226,19 @@ def handle_uncaught_exception(self, request, resolver, exc_info):
caused by anything, so assuming something like the database is always
available would be an error.
"""
+
+ # First trigger the got_request_exception Signal to make sure that
+ # all handlers are executed; collect the responses to check for
+ # errors later on.
+ signal_responses = signals.got_request_exception.send_robust(
+ sender=self.__class__, request=request)
+
+ # After all handlers have been executed, check DEBUG_PROPAGATE_EXCEPTIONS
if settings.DEBUG_PROPAGATE_EXCEPTIONS:
raise
+ # Log the "inital" error, which was basically the root cause and
+ # which is the most valuable resource for debugging.
logger.error('Internal Server Error: %s', request.path,
exc_info=exc_info,
extra={
@@ -230,15 +247,46 @@ def handle_uncaught_exception(self, request, resolver, exc_info):
}
)
+ # Check whether the handlers executed as expected or if the handlers
+ # itself raised further exceptions
+ for signal_response in signal_responses:
+ if isinstance(signal_response[1], Exception):
+ logger.error('Got Request Exception Handler Error: %s', request.path,
+ #since we do not have a exc_info from the signal handlers
+ exc_info=(None, None, None),
+ extra={
+ 'status_code': 500,
+ 'request': request,
+ 'error': signal_response[1]
+ }
+ )
+
+ # After everything is logged, check if we are in DEBUG mode
if settings.DEBUG:
return debug.technical_500_response(request, *exc_info)
# If Http500 handler is not installed, re-raise last exception
if resolver.urlconf_module is None:
six.reraise(*exc_info)
+
# Return an HttpResponse that displays a friendly error message.
- callback, param_dict = resolver.resolve500()
- return callback(request, **param_dict)
+ try:
+ callback, param_dict = resolver.resolve500()
+ return callback(request, **param_dict)
+ except Exception:
+ # Last Resort: and just in the highly unlikely case that somehting
+ # has gone wrong here, we return a minimal error message to the
+ # user and log the issue.
+
+ logger.error('Error in 500 Callback: %s', request.path,
+ exc_info=sys.exc_info(),
+ extra={
+ 'status_code': 500,
+ 'request': request
+ }
+ )
+ return http.HttpResponseServerError('<h1>Server Error (500)</h1>',
+ content_type='text/html')
def apply_response_fixes(self, request, response):
"""
View
6 django/test/utils.py
@@ -489,7 +489,11 @@ def patch_logger(logger_name, log_level):
calls = []
def replacement(msg, *args, **kwargs):
- calls.append(msg % args)
+ if kwargs:
+ calls.append((msg % args, kwargs))
+ else:
+ calls.append(msg % args)
+
logger = logging.getLogger(logger_name)
orig = getattr(logger, log_level)
setattr(logger, log_level, replacement)
View
4 tests/logging_tests/tests.py
@@ -370,13 +370,13 @@ 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.assertEqual(calls[0][0], 'dubious')
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.assertEqual(calls[0][0], 'dubious')
@override_settings(
ADMINS=(('admin', 'admin@example.com'),),
View
63 tests/view_tests/tests/test_defaults.py
@@ -1,8 +1,16 @@
from __future__ import unicode_literals
+
+import logging
+
+from django.core.signals import got_request_exception
+from django.dispatch import receiver
from django.test import TestCase
from django.test.utils import (setup_test_template_loader,
- restore_template_loaders, override_settings)
+ restore_template_loaders, override_settings, patch_logger)
+from django.utils.six import StringIO
+
+from django.contrib.contenttypes.models import ContentType
from ..models import UrlArticle
@@ -36,6 +44,59 @@ def test_server_error(self):
response = self.client.get('/server_error/')
self.assertEqual(response.status_code, 500)
+
+ def test_server_error_without_handler_error(self):
+ """
+ The server_error view raises a 500 status and no further error is
+ raised while handling the error.
+ """
+
+ @receiver(got_request_exception)
+ def handler(sender, **kwargs):
+ pass
+
+ try:
+ with patch_logger('django.request', 'error') as calls:
+ try:
+ response = self.client.get('/views/raises_unhandled_exception/')
+ except Exception as e:
+ # We need to catch the exceptions and check, if it is a 'Bad
+ # Request' or 'Bad Handler', since the Test Client will reraise
+ # these.
+ if str(e) not in ('Bad Request','Bad Handler'):
+ raise
+ self.assertEqual(len(calls), 1)
+ self.assertEqual(calls[0][0], 'Internal Server Error: /views/raises_unhandled_exception/')
+
+ finally:
+ got_request_exception.disconnect(handler)
+
+ def test_server_error_with_handler_error(self):
+ """
+ The server_error view raises a 500 status and while handling
+ the error, the next error is raised.
+ """
+
+ @receiver(got_request_exception)
+ def handler(sender, **kwargs):
+ raise Exception('Bad Handler')
+
+ try:
+ with patch_logger('django.request', 'error') as calls:
+ try:
+ response = self.client.get('/views/raises_unhandled_exception/')
+ except Exception as e:
+ # We need to catch the exceptions and check, if it is a 'Bad
+ # Request' or 'Bad Handler', since the Test Client will reraise
+ # these.
+ if str(e) not in ('Bad Request','Bad Handler'):
+ raise
+ self.assertEqual(len(calls), 2)
+ self.assertEqual(calls[0][0], 'Internal Server Error: /views/raises_unhandled_exception/')
+ self.assertTrue(calls[1][0], 'Got Request Exception Handler Error: %s')
+ finally:
+ got_request_exception.disconnect(handler)
+
def test_custom_templates(self):
"""
Test that 404.html and 500.html templates are picked by their respective
View
1  tests/view_tests/urls.py
@@ -56,6 +56,7 @@
url(r'raises403/$', views.raises403),
url(r'raises404/$', views.raises404),
url(r'raises500/$', views.raises500),
+ url(r'raises_unhandled_exception/$', views.raises_unhandled_exception),
# i18n views
url(r'^i18n/', include('django.conf.urls.i18n')),
View
4 tests/view_tests/views.py
@@ -46,6 +46,10 @@ def raises500(request):
except Exception:
return technical_500_response(request, *sys.exc_info())
+def raises_unhandled_exception(request):
+ # We need to raise an unhandled Excpeption to test the handling
+ # in the core handler
+ raise Exception('Bad Request')
def raises400(request):
raise SuspiciousOperation
Something went wrong with that request. Please try again.