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

@@ -135,6 +135,9 @@ def __init__(self, settings_module):
             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 @@ def __dir__(self):
 
 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]

django/conf/global_settings.py

@@ -525,9 +525,16 @@
 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'
         }
     },

django/conf/project_template/settings.py

@@ -125,15 +125,22 @@
 
 # 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'
         }
     },

django/core/handlers/base.py

@@ -198,10 +198,6 @@ def handle_uncaught_exception(self, request, resolver, exc_info):
         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 @@ def handle_uncaught_exception(self, request, resolver, exc_info):
             }
         )
 
+        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]

django/utils/log.py

@@ -70,3 +70,20 @@ def emit(self, record):
         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

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

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 </topics/logging/>` 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.

docs/topics/logging.txt

@@ -501,3 +501,37 @@ Python logging module.
     :ref:`Filtering error reports<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'
+            }
+        },

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"])

tests/regressiontests/views/views.py

@@ -134,13 +134,24 @@ 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={
             'status_code': 500,
             '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