From 43503b093a35ca4707c16d865f10929960bfa0b8 Mon Sep 17 00:00:00 2001 From: Carl Meyer Date: Wed, 22 Jun 2011 06:01:44 +0000 Subject: [PATCH] Fixed #16288 -- Enabled django.request exception logger regardless of DEBUG setting. Thanks Matt Bennett for report and draft patch; Vinay Sajip and Russell Keith-Magee for review. git-svn-id: http://code.djangoproject.com/svn/django/trunk@16444 bcc190cf-cafb-0310-a4f2-bffc1f526a37 --- django/conf/__init__.py | 41 ++++++ django/conf/global_settings.py | 7 ++ django/conf/project_template/settings.py | 9 +- django/core/handlers/base.py | 8 +- django/utils/log.py | 17 +++ docs/internals/deprecation.txt | 5 + docs/releases/1.4.txt | 41 ++++++ docs/topics/logging.txt | 34 +++++ .../regressiontests/logging_tests/__init__.py | 0 tests/regressiontests/logging_tests/models.py | 0 tests/regressiontests/logging_tests/tests.py | 117 ++++++++++++++++++ tests/regressiontests/views/views.py | 11 ++ 12 files changed, 285 insertions(+), 5 deletions(-) create mode 100644 tests/regressiontests/logging_tests/__init__.py create mode 100644 tests/regressiontests/logging_tests/models.py create mode 100644 tests/regressiontests/logging_tests/tests.py diff --git a/django/conf/__init__.py b/django/conf/__init__.py index 8964b1bfb3f..c99b307c6d1 100644 --- a/django/conf/__init__.py +++ b/django/conf/__init__.py @@ -135,6 +135,9 @@ class Settings(BaseSettings): logging_config_module = importlib.import_module(logging_config_path) logging_config_func = getattr(logging_config_module, logging_config_func_name) + # Backwards-compatibility shim for #16288 fix + compat_patch_logging_config(self.LOGGING) + # ... then invoke it with the logging settings logging_config_func(self.LOGGING) @@ -165,3 +168,41 @@ class UserSettingsHolder(BaseSettings): settings = LazySettings() + + +def compat_patch_logging_config(logging_config): + """ + Backwards-compatibility shim for #16288 fix. Takes initial value of + ``LOGGING`` setting and patches it in-place (issuing deprecation warning) + if "mail_admins" logging handler is configured but has no filters. + + """ + # Shim only if LOGGING["handlers"]["mail_admins"] exists, + # but has no "filters" key + if "filters" not in logging_config.get( + "handlers", {}).get( + "mail_admins", {"filters": []}): + + warnings.warn( + "You have no filters defined on the 'mail_admins' logging " + "handler: adding implicit debug-false-only filter. " + "See http://docs.djangoproject.com/en/dev/releases/1.4/" + "#request-exceptions-are-now-always-logged", + PendingDeprecationWarning) + + filter_name = "require_debug_false" + + filters = logging_config.setdefault("filters", {}) + while filter_name in filters: + filter_name = filter_name + "_" + + def _callback(record): + from django.conf import settings + return not settings.DEBUG + + filters[filter_name] = { + "()": "django.utils.log.CallbackFilter", + "callback": _callback + } + + logging_config["handlers"]["mail_admins"]["filters"] = [filter_name] diff --git a/django/conf/global_settings.py b/django/conf/global_settings.py index ab31c15da3f..fedea55bac4 100644 --- a/django/conf/global_settings.py +++ b/django/conf/global_settings.py @@ -525,9 +525,16 @@ LOGGING_CONFIG = 'django.utils.log.dictConfig' LOGGING = { 'version': 1, 'disable_existing_loggers': False, + 'filters': { + 'require_debug_false': { + '()': 'django.utils.log.CallbackFilter', + 'callback': lambda r: not DEBUG + } + }, 'handlers': { 'mail_admins': { 'level': 'ERROR', + 'filters': ['require_debug_false'], 'class': 'django.utils.log.AdminEmailHandler' } }, diff --git a/django/conf/project_template/settings.py b/django/conf/project_template/settings.py index e719dec5db1..794522b202f 100644 --- a/django/conf/project_template/settings.py +++ b/django/conf/project_template/settings.py @@ -125,15 +125,22 @@ INSTALLED_APPS = ( # A sample logging configuration. The only tangible logging # performed by this configuration is to send an email to -# the site admins on every HTTP 500 error. +# the site admins on every HTTP 500 error when DEBUG=False. # See http://docs.djangoproject.com/en/dev/topics/logging for # more details on how to customize your logging configuration. LOGGING = { 'version': 1, 'disable_existing_loggers': False, + 'filters': { + 'require_debug_false': { + '()': 'django.utils.log.CallbackFilter', + 'callback': lambda r: not DEBUG + } + }, 'handlers': { 'mail_admins': { 'level': 'ERROR', + 'filters': ['require_debug_false'], 'class': 'django.utils.log.AdminEmailHandler' } }, diff --git a/django/core/handlers/base.py b/django/core/handlers/base.py index 7cae42e651e..55290973c37 100644 --- a/django/core/handlers/base.py +++ b/django/core/handlers/base.py @@ -198,10 +198,6 @@ class BaseHandler(object): if settings.DEBUG_PROPAGATE_EXCEPTIONS: raise - if settings.DEBUG: - from django.views import debug - return debug.technical_500_response(request, *exc_info) - logger.error('Internal Server Error: %s' % request.path, exc_info=exc_info, extra={ @@ -210,6 +206,10 @@ class BaseHandler(object): } ) + if settings.DEBUG: + from django.views import 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: raise exc_info[1], None, exc_info[2] diff --git a/django/utils/log.py b/django/utils/log.py index 969a9d96093..d0f5109e85c 100644 --- a/django/utils/log.py +++ b/django/utils/log.py @@ -70,3 +70,20 @@ class AdminEmailHandler(logging.Handler): reporter = ExceptionReporter(request, is_email=True, *exc_info) html_message = self.include_html and reporter.get_traceback_html() or None mail.mail_admins(subject, message, fail_silently=True, html_message=html_message) + + +class CallbackFilter(logging.Filter): + """ + A logging filter that checks the return value of a given callable (which + takes the record-to-be-logged as its only parameter) to decide whether to + log a record. + + """ + def __init__(self, callback): + self.callback = callback + + + def filter(self, record): + if self.callback(record): + return 1 + return 0 diff --git a/docs/internals/deprecation.txt b/docs/internals/deprecation.txt index 131f813f83b..cd65a89e227 100644 --- a/docs/internals/deprecation.txt +++ b/docs/internals/deprecation.txt @@ -210,6 +210,11 @@ their deprecation, as per the :ref:`Django deprecation policy * Legacy ways of calling :func:`~django.views.decorators.cache.cache_page` will be removed. + * The backward-compatibility shim to automatically add a debug-false + filter to the ``'mail_admins'`` logging handler will be removed. The + :setting:`LOGGING` setting should include this filter explicitly if + it is desired. + * 2.0 * ``django.views.defaults.shortcut()``. This function has been moved to ``django.contrib.contenttypes.views.shortcut()`` as part of the diff --git a/docs/releases/1.4.txt b/docs/releases/1.4.txt index 7cc3fb1bc2d..0635ecefee5 100644 --- a/docs/releases/1.4.txt +++ b/docs/releases/1.4.txt @@ -387,3 +387,44 @@ releases 8.0 and 8.1 was near (November 2010.) Django 1.4 takes that policy further and sets 8.2 as the minimum PostgreSQL version it officially supports. + +Request exceptions are now always logged +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + +When :doc:`logging support ` was added to Django in 1.3, the +admin error email support was moved into the +:class:`django.utils.log.AdminEmailHandler`, attached to the +``'django.request'`` logger. In order to maintain the established behavior of +error emails, the ``'django.request'`` logger was called only when +:setting:`DEBUG` was `False`. + +To increase the flexibility of request-error logging, the ``'django.request'`` +logger is now called regardless of the value of :setting:`DEBUG`, and the +default settings file for new projects now includes a separate filter attached +to :class:`django.utils.log.AdminEmailHandler` to prevent admin error emails in +`DEBUG` mode:: + + 'filters': { + 'require_debug_false': { + '()': 'django.utils.log.CallbackFilter', + 'callback': lambda r: not DEBUG + } + }, + 'handlers': { + 'mail_admins': { + 'level': 'ERROR', + 'filters': ['require_debug_false'], + 'class': 'django.utils.log.AdminEmailHandler' + } + }, + +If your project was created prior to this change, your :setting:`LOGGING` +setting will not include this new filter. In order to maintain +backwards-compatibility, Django will detect that your ``'mail_admins'`` handler +configuration includes no ``'filters'`` section, and will automatically add +this filter for you and issue a pending-deprecation warning. This will become a +deprecation warning in Django 1.5, and in Django 1.6 the +backwards-compatibility shim will be removed entirely. + +The existence of any ``'filters'`` key under the ``'mail_admins'`` handler will +disable this backward-compatibility shim and deprecation warning. diff --git a/docs/topics/logging.txt b/docs/topics/logging.txt index 06050af899d..91370382146 100644 --- a/docs/topics/logging.txt +++ b/docs/topics/logging.txt @@ -501,3 +501,37 @@ Python logging module. :ref:`Filtering error reports`. .. _django-sentry: http://pypi.python.org/pypi/django-sentry + + +Filters +------- + +Django provides one log filter in addition to those provided by the +Python logging module. + +.. class:: CallbackFilter(callback) + + .. versionadded:: 1.4 + + This filter accepts a callback function (which should accept a single + argument, the record to be logged), and calls it for each record that passes + through the filter. Handling of that record will not proceed if the callback + returns False. + + This filter is used as follows in the default :setting:`LOGGING` + configuration to ensure that the :class:`AdminEmailHandler` only sends error + emails to admins when :setting:`DEBUG` is `False`:: + + 'filters': { + 'require_debug_false': { + '()': 'django.utils.log.CallbackFilter', + 'callback': lambda r: not DEBUG + } + }, + 'handlers': { + 'mail_admins': { + 'level': 'ERROR', + 'filters': ['require_debug_false'], + 'class': 'django.utils.log.AdminEmailHandler' + } + }, diff --git a/tests/regressiontests/logging_tests/__init__.py b/tests/regressiontests/logging_tests/__init__.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/tests/regressiontests/logging_tests/models.py b/tests/regressiontests/logging_tests/models.py new file mode 100644 index 00000000000..e69de29bb2d diff --git a/tests/regressiontests/logging_tests/tests.py b/tests/regressiontests/logging_tests/tests.py new file mode 100644 index 00000000000..fe8b1694214 --- /dev/null +++ b/tests/regressiontests/logging_tests/tests.py @@ -0,0 +1,117 @@ +from __future__ import with_statement + +import copy + +from django.conf import compat_patch_logging_config +from django.test import TestCase +from django.utils.log import CallbackFilter + + +# logging config prior to using filter with mail_admins +OLD_LOGGING = { + 'version': 1, + 'disable_existing_loggers': False, + 'handlers': { + 'mail_admins': { + 'level': 'ERROR', + 'class': 'django.utils.log.AdminEmailHandler' + } + }, + 'loggers': { + 'django.request': { + 'handlers': ['mail_admins'], + 'level': 'ERROR', + 'propagate': True, + }, + } +} + + + +class PatchLoggingConfigTest(TestCase): + """ + Tests for backward-compat shim for #16288. These tests should be removed in + Django 1.6 when that shim and DeprecationWarning are removed. + + """ + def test_filter_added(self): + """ + Test that debug-false filter is added to mail_admins handler if it has + no filters. + + """ + config = copy.deepcopy(OLD_LOGGING) + compat_patch_logging_config(config) + + self.assertEqual( + config["handlers"]["mail_admins"]["filters"], + ['require_debug_false']) + + + def test_filter_configuration(self): + """ + Test that the debug-false filter is a CallbackFilter with a callback + that works as expected (returns ``not DEBUG``). + + """ + config = copy.deepcopy(OLD_LOGGING) + compat_patch_logging_config(config) + + flt = config["filters"]["require_debug_false"] + + self.assertEqual(flt["()"], "django.utils.log.CallbackFilter") + + callback = flt["callback"] + + with self.settings(DEBUG=True): + self.assertEqual(callback("record is not used"), False) + + with self.settings(DEBUG=False): + self.assertEqual(callback("record is not used"), True) + + + def test_no_patch_if_filters_key_exists(self): + """ + Test that the logging configuration is not modified if the mail_admins + handler already has a "filters" key. + + """ + config = copy.deepcopy(OLD_LOGGING) + config["handlers"]["mail_admins"]["filters"] = [] + new_config = copy.deepcopy(config) + compat_patch_logging_config(new_config) + + self.assertEqual(config, new_config) + + def test_no_patch_if_no_mail_admins_handler(self): + """ + Test that the logging configuration is not modified if the mail_admins + handler is not present. + + """ + config = copy.deepcopy(OLD_LOGGING) + config["handlers"].pop("mail_admins") + new_config = copy.deepcopy(config) + compat_patch_logging_config(new_config) + + self.assertEqual(config, new_config) + + +class CallbackFilterTest(TestCase): + def test_sense(self): + f_false = CallbackFilter(lambda r: False) + f_true = CallbackFilter(lambda r: True) + + self.assertEqual(f_false.filter("record"), False) + self.assertEqual(f_true.filter("record"), True) + + def test_passes_on_record(self): + collector = [] + def _callback(record): + collector.append(record) + return True + f = CallbackFilter(_callback) + + f.filter("a record") + + self.assertEqual(collector, ["a record"]) diff --git a/tests/regressiontests/views/views.py b/tests/regressiontests/views/views.py index 732ff280ca9..7d59257ef77 100644 --- a/tests/regressiontests/views/views.py +++ b/tests/regressiontests/views/views.py @@ -134,6 +134,16 @@ def raises_template_does_not_exist(request): def send_log(request, exc_info): logger = getLogger('django.request') + # The default logging config has a logging filter to ensure admin emails are + # only sent with DEBUG=False, but since someone might choose to remove that + # filter, we still want to be able to test the behavior of error emails + # with DEBUG=True. So we need to remove the filter temporarily. + admin_email_handler = [ + h for h in logger.handlers + if h.__class__.__name__ == "AdminEmailHandler" + ][0] + orig_filters = admin_email_handler.filters + admin_email_handler.filters = [] logger.error('Internal Server Error: %s' % request.path, exc_info=exc_info, extra={ @@ -141,6 +151,7 @@ def send_log(request, exc_info): 'request': request } ) + admin_email_handler.filters = orig_filters def non_sensitive_view(request): # Do not just use plain strings for the variables' values in the code