Fixed #12012 -- Added support for logging. Thanks to Vinay Sajip for his draft…

Fixed #12012 -- Added support for logging. Thanks to Vinay Sajip for his draft patch, and to the many people who gave feedback during development of the patch.

git-svn-id: http://code.djangoproject.com/svn/django/trunk@13981 bcc190cf-cafb-0310-a4f2-bffc1f526a37

django/conf/__init__.py

@@ -16,6 +16,7 @@ from django.utils import importlib
 
 ENVIRONMENT_VARIABLE = "DJANGO_SETTINGS_MODULE"
 
+
 class LazySettings(LazyObject):
     """
     A lazy proxy for either global Django settings or a custom settings object.
@@ -114,6 +115,16 @@ class Settings(object):
             os.environ['TZ'] = self.TIME_ZONE
             time.tzset()
 
+        # Settings are configured, so we can set up the logger if required
+        if self.LOGGING_CONFIG:
+            # First find the logging configuration function ...
+            logging_config_path, logging_config_func_name = self.LOGGING_CONFIG.rsplit('.', 1)
+            logging_config_module = importlib.import_module(logging_config_path)
+            logging_config_func = getattr(logging_config_module, logging_config_func_name)
+
+            # ... then invoke it with the logging settings
+            logging_config_func(self.LOGGING)
+
 class UserSettingsHolder(object):
     """
     Holder for user configured settings.

django/conf/global_settings.py

@@ -498,6 +498,34 @@ MESSAGE_STORAGE = 'django.contrib.messages.storage.user_messages.LegacyFallbackS
 # Default values of MESSAGE_LEVEL and MESSAGE_TAGS are defined within
 # django.contrib.messages to avoid imports in this settings file.
 
+###########
+# LOGGING #
+###########
+
+# The callable to use to configure logging
+LOGGING_CONFIG = 'django.utils.log.dictConfig'
+
+# The default logging configuration. This sends an email to
+# the site admins on every HTTP 500 error. All other log
+# records are sent to the bit bucket.
+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,
+        },
+    }
+}
+
 ###########
 # TESTING #
 ###########

django/conf/project_template/settings.py

@@ -94,3 +94,26 @@ INSTALLED_APPS = (
     # Uncomment the next line to enable admin documentation:
     # 'django.contrib.admindocs',
 )
+
+# 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.
+# 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,
+    'handlers': {
+        'mail_admins': {
+            'level': 'ERROR',
+            'class': 'django.utils.log.AdminEmailHandler'
+        }
+    },
+    'loggers': {
+        'django.request':{
+            'handlers': ['mail_admins'],
+            'level': 'ERROR',
+            'propagate': True,
+        },
+    }
+}

django/core/handlers/base.py

+import logging
 import sys
 
 from django import http
@@ -5,6 +6,9 @@ from django.core import signals
 from django.utils.encoding import force_unicode
 from django.utils.importlib import import_module
 
+logger = logging.getLogger('django.request')
+
+
 class BaseHandler(object):
     # Changes that are always applied to a response (in this order).
     response_fixes = [
@@ -118,6 +122,11 @@ class BaseHandler(object):
 
                 return response
             except http.Http404, e:
+                logger.warning('Not Found: %s' % request.path,
+                            extra={
+                                'status_code': 404,
+                                'request': request
+                            })
                 if settings.DEBUG:
                     from django.views import debug
                     return debug.technical_404_response(request, e)
@@ -131,6 +140,11 @@ class BaseHandler(object):
                         finally:
                             receivers = signals.got_request_exception.send(sender=self.__class__, request=request)
             except exceptions.PermissionDenied:
+                logger.warning('Forbidden (Permission denied): %s' % request.path,
+                            extra={
+                                'status_code': 403,
+                                'request': request
+                            })
                 return http.HttpResponseForbidden('<h1>Permission denied</h1>')
             except SystemExit:
                 # Allow sys.exit() to actually exit. See tickets #1023 and #4701
@@ -155,7 +169,6 @@ class BaseHandler(object):
         available would be an error.
         """
         from django.conf import settings
-        from django.core.mail import mail_admins
 
         if settings.DEBUG_PROPAGATE_EXCEPTIONS:
             raise
@@ -164,14 +177,14 @@ class BaseHandler(object):
             from django.views import debug
             return debug.technical_500_response(request, *exc_info)
 
-        # When DEBUG is False, send an error message to the admins.
-        subject = 'Error (%s IP): %s' % ((request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS and 'internal' or 'EXTERNAL'), request.path)
-        try:
-            request_repr = repr(request)
-        except:
-            request_repr = "Request repr() unavailable"
-        message = "%s\n\n%s" % (self._get_traceback(exc_info), request_repr)
-        mail_admins(subject, message, fail_silently=True)
+        logger.error('Internal Server Error: %s' % request.path,
+            exc_info=exc_info,
+            extra={
+                'status_code': 500,
+                'request':request
+            }
+        )
+
         # If Http500 handler is not installed, re-raise last exception
         if resolver.urlconf_module is None:
             raise exc_info[1], None, exc_info[2]
@@ -179,11 +192,6 @@ class BaseHandler(object):
         callback, param_dict = resolver.resolve500()
         return callback(request, **param_dict)
 
-    def _get_traceback(self, exc_info=None):
-        "Helper function to return the traceback as a string"
-        import traceback
-        return '\n'.join(traceback.format_exception(*(exc_info or sys.exc_info())))
-
     def apply_response_fixes(self, request, response):
         """
         Applies each of the functions in self.response_fixes to the request and

django/core/handlers/modpython.py

+import logging
 import os
 from pprint import pformat
+import sys
 from warnings import warn
 
 from django import http
@@ -9,6 +11,9 @@ from django.core.urlresolvers import set_script_prefix
 from django.utils import datastructures
 from django.utils.encoding import force_unicode, smart_str, iri_to_uri
 
+logger = logging.getLogger('django.request')
+
+
 # NOTE: do *not* import settings (or any module which eventually imports
 # settings) until after ModPythonHandler has been called; otherwise os.environ
 # won't be set up correctly (with respect to settings).
@@ -200,6 +205,13 @@ class ModPythonHandler(BaseHandler):
             try:
                 request = self.request_class(req)
             except UnicodeDecodeError:
+                logger.warning('Bad Request (UnicodeDecodeError): %s' % request.path,
+                    exc_info=sys.exc_info(),
+                    extra={
+                        'status_code': 400,
+                        'request': request
+                    }
+                )
                 response = http.HttpResponseBadRequest()
             else:
                 response = self.get_response(request)

django/core/handlers/wsgi.py

-from threading import Lock
+import logging
 from pprint import pformat
+import sys
+from threading import Lock
 try:
     from cStringIO import StringIO
 except ImportError:
@@ -12,6 +14,9 @@ from django.core.urlresolvers import set_script_prefix
 from django.utils import datastructures
 from django.utils.encoding import force_unicode, iri_to_uri
 
+logger = logging.getLogger('django.request')
+
+
 # See http://www.w3.org/Protocols/rfc2616/rfc2616-sec10.html
 STATUS_CODE_TEXT = {
     100: 'CONTINUE',
@@ -236,6 +241,13 @@ class WSGIHandler(base.BaseHandler):
             try:
                 request = self.request_class(environ)
             except UnicodeDecodeError:
+                logger.warning('Bad Request (UnicodeDecodeError): %s' % request.path,
+                    exc_info=sys.exc_info(),
+                    extra={
+                        'status_code': 400,
+                        'request': request
+                    }
+                )
                 response = http.HttpResponseBadRequest()
             else:
                 response = self.get_response(request)

django/db/backends/util.py

 import datetime
 import decimal
+import logging
 from time import time
 
 from django.utils.hashcompat import md5_constructor
 
+logger = logging.getLogger('django.db.backends')
+
 class CursorDebugWrapper(object):
     def __init__(self, cursor, db):
         self.cursor = cursor
@@ -15,11 +18,15 @@ class CursorDebugWrapper(object):
             return self.cursor.execute(sql, params)
         finally:
             stop = time()
+            duration = stop - start
             sql = self.db.ops.last_executed_query(self.cursor, sql, params)
             self.db.queries.append({
                 'sql': sql,
-                'time': "%.3f" % (stop - start),
+                'time': "%.3f" % duration,
             })
+            logger.debug('(%.3f) %s; args=%s' % (duration, sql, params),
+                extra={'duration':duration, 'sql':sql, 'params':params}
+            )
 
     def executemany(self, sql, param_list):
         start = time()
@@ -27,10 +34,14 @@ class CursorDebugWrapper(object):
             return self.cursor.executemany(sql, param_list)
         finally:
             stop = time()
+            duration = stop - start
             self.db.queries.append({
                 'sql': '%s times: %s' % (len(param_list), sql),
-                'time': "%.3f" % (stop - start),
+                'time': "%.3f" % duration,
             })
+            logger.debug('(%.3f) %s; args=%s' % (duration, sql, param_list),
+                extra={'duration':duration, 'sql':sql, 'params':param_list}
+            )
 
     def __getattr__(self, attr):
         if attr in self.__dict__:

django/middleware/common.py

+import logging
 import re
 
 from django.conf import settings
@@ -7,6 +8,9 @@ from django.utils.http import urlquote
 from django.core import urlresolvers
 from django.utils.hashcompat import md5_constructor
 
+logger = logging.getLogger('django.request')
+
+
 class CommonMiddleware(object):
     """
     "Common" middleware for taking care of some basic operations:
@@ -38,6 +42,12 @@ class CommonMiddleware(object):
         if 'HTTP_USER_AGENT' in request.META:
             for user_agent_regex in settings.DISALLOWED_USER_AGENTS:
                 if user_agent_regex.search(request.META['HTTP_USER_AGENT']):
+                    logger.warning('Forbidden (User agent): %s' % request.path,
+                        extra={
+                            'status_code': 403,
+                            'request': request
+                        }
+                    )
                     return http.HttpResponseForbidden('<h1>Forbidden</h1>')
 
         # Check for a redirect based on settings.APPEND_SLASH

django/middleware/csrf.py

@@ -6,6 +6,7 @@ against request forgeries from other sites.
 """
 
 import itertools
+import logging
 import re
 import random
 
@@ -20,6 +21,8 @@ _POST_FORM_RE = \
 
 _HTML_TYPES = ('text/html', 'application/xhtml+xml')
 
+logger = logging.getLogger('django.request')
+
 # Use the system (hardware-based) random number generator if it exists.
 if hasattr(random, 'SystemRandom'):
     randrange = random.SystemRandom().randrange
@@ -169,14 +172,26 @@ class CsrfViewMiddleware(object):
                 # we can use strict Referer checking.
                 referer = request.META.get('HTTP_REFERER')
                 if referer is None:
+                    logger.warning('Forbidden (%s): %s' % (REASON_NO_COOKIE, request.path),
+                        extra={
+                            'status_code': 403,
+                            'request': request,
+                        }
+                    )
                     return reject(REASON_NO_REFERER)
 
                 # The following check ensures that the referer is HTTPS,
                 # the domains match and the ports match - the same origin policy.
                 good_referer = 'https://%s/' % request.get_host()
                 if not referer.startswith(good_referer):
-                    return reject(REASON_BAD_REFERER %
-                                  (referer, good_referer))
+                    reason = REASON_BAD_REFERER % (referer, good_referer)
+                    logger.warning('Forbidden (%s): %s' % (reason, request.path),
+                        extra={
+                            'status_code': 403,
+                            'request': request,
+                        }
+                    )
+                    return reject(reason)
 
             # If the user didn't already have a CSRF cookie, then fall back to
             # the Django 1.1 method (hash of session ID), so a request is not
@@ -190,6 +205,12 @@ class CsrfViewMiddleware(object):
                     # No CSRF cookie and no session cookie. For POST requests,
                     # we insist on a CSRF cookie, and in this way we can avoid
                     # all CSRF attacks, including login CSRF.
+                    logger.warning('Forbidden (%s): %s' % (REASON_NO_COOKIE, request.path),
+                        extra={
+                            'status_code': 403,
+                            'request': request,
+                        }
+                    )
                     return reject(REASON_NO_COOKIE)
             else:
                 csrf_token = request.META["CSRF_COOKIE"]
@@ -199,8 +220,20 @@ class CsrfViewMiddleware(object):
             if request_csrf_token != csrf_token:
                 if cookie_is_new:
                     # probably a problem setting the CSRF cookie
+                    logger.warning('Forbidden (%s): %s' % (REASON_NO_CSRF_COOKIE, request.path),
+                        extra={
+                            'status_code': 403,
+                            'request': request,
+                        }
+                    )
                     return reject(REASON_NO_CSRF_COOKIE)
                 else:
+                    logger.warning('Forbidden (%s): %s' % (REASON_BAD_TOKEN, request.path),
+                        extra={
+                            'status_code': 403,
+                            'request': request,
+                        }
+                    )
                     return reject(REASON_BAD_TOKEN)
 
         return accept()

django/utils/log.py

+import logging
+from django.core import mail
+
+# Make sure a NullHandler is available
+# This was added in Python 2.7/3.2
+try:
+    from logging import NullHandler
+except ImportError:
+    class NullHandler(logging.Handler):
+        def emit(self, record):
+            pass
+
+# Make sure that dictConfig is available
+# This was added in Python 2.7/3.2
+try:
+    from logging.config import dictConfig
+except ImportError:
+    from django.utils.dictconfig import dictConfig
+
+# Ensure the creation of the Django logger
+# with a null handler. This ensures we don't get any
+# 'No handlers could be found for logger "django"' messages
+logger = logging.getLogger('django')
+if not logger.handlers:
+    logger.addHandler(NullHandler())
+
+class AdminEmailHandler(logging.Handler):
+    """An exception log handler that emails log entries to site admins
+
+    If the request is passed as the first argument to the log record,
+    request data will be provided in the
+    """
+    def emit(self, record):
+        import traceback
+        from django.conf import settings
+
+        try:
+            request = record.request
+
+            subject = '%s (%s IP): %s' % (
+                record.levelname,
+                (request.META.get('REMOTE_ADDR') in settings.INTERNAL_IPS and 'internal' or 'EXTERNAL'),
+                request.path
+            )
+            request_repr = repr(request)
+        except:
+            subject = 'Error: Unknown URL'
+            request_repr = "Request repr() unavailable"
+
+        if record.exc_info:
+            stack_trace = '\n'.join(traceback.format_exception(*record.exc_info))
+        else:
+            stack_trace = 'No stack trace available'
+
+        message = "%s\n\n%s" % (stack_trace, request_repr)
+        mail.mail_admins(subject, message, fail_silently=True)

django/views/decorators/http.py

@@ -10,15 +10,18 @@ except ImportError:
 from calendar import timegm
 from datetime import timedelta
 from email.Utils import formatdate
+import logging
 
 from django.utils.decorators import decorator_from_middleware, available_attrs
 from django.utils.http import parse_etags, quote_etag
 from django.middleware.http import ConditionalGetMiddleware
 from django.http import HttpResponseNotAllowed, HttpResponseNotModified, HttpResponse
 
-
 conditional_page = decorator_from_middleware(ConditionalGetMiddleware)
 
+logger = logging.getLogger('django.request')
+
+
 def require_http_methods(request_method_list):
     """
     Decorator to make a view only accept particular request methods.  Usage::
@@ -33,6 +36,12 @@ def require_http_methods(request_method_list):
     def decorator(func):
         def inner(request, *args, **kwargs):
             if request.method not in request_method_list:
+                logger.warning('Method Not Allowed (%s): %s' % (request.method, request.path),
+                    extra={
+                        'status_code': 405,
+                        'request': request
+                    }
+                )
                 return HttpResponseNotAllowed(request_method_list)
             return func(request, *args, **kwargs)
         return wraps(func, assigned=available_attrs(func))(inner)
@@ -111,9 +120,21 @@ def condition(etag_func=None, last_modified_func=None):
                     if request.method in ("GET", "HEAD"):
                         response = HttpResponseNotModified()
                     else:
+                        logger.warning('Precondition Failed: %s' % request.path,
+                            extra={
+                                'status_code': 412,
+                                'request': request
+                            }
+                        )
                         response = HttpResponse(status=412)
                 elif if_match and ((not res_etag and "*" in etags) or
                         (res_etag and res_etag not in etags)):
+                    logger.warning('Precondition Failed: %s' % request.path,
+                        extra={
+                            'status_code': 412,
+                            'request': request
+                        }
+                    )
                     response = HttpResponse(status=412)
                 elif (not if_none_match and if_modified_since and
                         request.method == "GET" and

django/views/generic/simple.py

+import logging
+
 from django.template import loader, RequestContext
 from django.http import HttpResponse, HttpResponseRedirect, HttpResponsePermanentRedirect, HttpResponseGone
 
+logger = logging.getLogger('django.request')
+
+
 def direct_to_template(request, template, extra_context=None, mimetype=None, **kwargs):
     """
     Render a given template with any extra URL parameters in the context as
@@ -46,4 +51,9 @@ def redirect_to(request, url, permanent=True, query_string=False, **kwargs):
         klass = permanent and HttpResponsePermanentRedirect or HttpResponseRedirect
         return klass(url % kwargs)
     else:
+        logger.warning('Gone: %s' % request.path,
+                    extra={
+                        'status_code': 410,
+                        'request': request
+                    })
         return HttpResponseGone()

docs/index.txt

@@ -176,6 +176,7 @@ Other batteries included
     * :doc:`Internationalization <topics/i18n/index>`
     * :doc:`Jython support <howto/jython>`
     * :doc:`"Local flavor" <ref/contrib/localflavor>`
+    * :doc:`Logging <topics/logging>`
     * :doc:`Messages <ref/contrib/messages>`
     * :doc:`Pagination <topics/pagination>`
     * :doc:`Redirects <ref/contrib/redirects>`

docs/ref/settings.txt

@@ -1008,6 +1008,36 @@ See :ref:`using-translations-in-your-own-projects`.
 
 .. setting:: LOGIN_REDIRECT_URL
 
+LOGGING
+-------
+
+Default: A logging configuration dictionary.
+
+A data structure containing configuration information. The contents of
+this data structure will be passed as the argument to the
+configuration method described in :setting:`LOGGING_CONFIG`.
+
+The default logging configuration passes HTTP 500 server errors to an
+email log handler; all other log messages are given to a NullHandler.
+
+.. versionadded:: 1.3
+
+LOGGING_CONFIG
+--------------
+
+Default: ``'django.utils.log.dictConfig'``
+
+A path to a callable that will be used to configure logging in the
+Django project. Points at a instance of Python's `dictConfig`_
+configuration method by default.
+
+If you set :setting:`LOGGING_CONFIG` to ``None``, the logging
+configuration process will be skipped.
+
+.. _dictConfig: http://docs.python.org/library/logging.html#logging.dictConfig
+
+.. versionadded:: 1.3
+
 LOGIN_REDIRECT_URL
 ------------------
 

docs/releases/1.3.txt

@@ -109,3 +109,13 @@ encouraged you redeploy your Django instances using :doc:`mod_wsgi
 What's new in Django 1.3
 ========================
 
+Logging
+~~~~~~~
+
+Django 1.3 adds framework-level support for Python's logging module.
+This means you can now esaily configure and control logging as part of
+your Django project. A number of logging handlers and logging calls
+have been added to Django's own code as well -- most notably, the
+error emails sent on a HTTP 500 server error are now handled as a
+logging activity. See :doc:`the documentation on Django's logging
+interface </topics/logging>` for more details.

docs/topics/index.txt

@@ -20,6 +20,7 @@ Introductions to all the key parts of Django you'll need to know:
    conditional-view-processing
    email
    i18n/index
+   logging
    pagination
    serialization
    settings

tests/modeltests/model_package/tests.py

@@ -10,7 +10,6 @@ class Advertisment(models.Model):
 __test__ = {'API_TESTS': """
 >>> from models.publication import Publication
 >>> from models.article import Article
->>> from django.contrib.auth.views import Site
 
 >>> p = Publication(title="FooBar")
 >>> p.save()