Merge branch 'feature/multi-handler-redux' into develop

README.rst

@@ -135,26 +135,16 @@ Finally, run syncdb to create the models for statistic logging::
 South migrations are included in case migrations are needed when upgrading to
 new versions.
 
-To enable logging, create a DEBUG_LOGGING_CONFIG setting that looks like this::
+Requests are logged when they contain a 'DJANGO_DEBUG_LOGGING' header set to
+True.  This header is added automatically by the 'log_urls' command when it is
+used.  To prevent any performance impact from the rendering of the Debug Toolbar, it
+is not shown when this header is present.
 
-    DEBUG_LOGGING_CONFIG = {
-        'ENABLED': True,
-    }
-
-To prevent any performance impact from the rendering of the Debug Toolbar, it
-is not shown.
-
-When logging is enabled, requests generated while there is an active test run
-will create debug log records.  For the best results, don't use the site while
-a test run is in progress.
+For the best results, don't use the site while a test run is in progress.
 
 Settings
 --------
 
-* ``ENABLED``: If enabled, the debug logger will log the performance details of
-  each request. The debug toolbar interface will not be shown until logging is
-  disabled again.
-
 * ``SQL_EXTRA``: This setting determines whether the full details of each query
   are logged, or just the number of queries and the total time.  It defaults to
   ``False``.

debug_logging/formatters.py

@@ -0,0 +1,43 @@
+from logging import Formatter
+
+from django.template import Context, Template
+
+
+class DjangoTemplatedFormatter(Formatter):
+
+    def __init__(self, fmt=None, datefmt=None):
+        """
+        Initialize the formatter either with the specified format string, or a
+        default as described above. Allow for specialized date formatting with
+        the optional datefmt argument (if omitted, you get the ISO8601 format).
+        """
+        self._fmt = fmt or "{{ message }}"
+        self.datefmt = datefmt
+
+    def format(self, record):
+        """
+        Format the specified record as text.
+
+        The record's attribute dictionary is used as the context and the format
+        provided on init is used as the template. Before formatting the
+        dictionary, a couple of preparatory steps are carried out. The message
+        attribute of the record is computed using LogRecord.getMessage(). If
+        the formatting string contains "%(asctime)", formatTime() is called to
+        format the event time. If there is exception information, it is
+        formatted using formatException() and appended to the message.
+        """
+        record.message = record.getMessage()
+        if "{{ asctime }}" in self._fmt:
+            record.asctime = self.formatTime(record, self.datefmt)
+        t = Template(self._fmt)
+        s = t.render(Context(record.__dict__))
+        if record.exc_info:
+            # Cache the traceback text to avoid converting it multiple times
+            # (it's constant anyway)
+            if not record.exc_text:
+                record.exc_text = self.formatException(record.exc_info)
+        if record.exc_text:
+            if s[-1:] != "\n":
+                s = s + "\n"
+            s = s + record.exc_text
+        return s

debug_logging/management/commands/log_urls.py

@@ -6,11 +6,14 @@
 from django.test.client import Client
 from django.core.management.base import BaseCommand, CommandError
 
+from debug_logging.settings import LOGGING_CONFIG
+from debug_logging.handlers import DBHandler
+
 
 class Command(BaseCommand):
     help = 'Hit a list of urls in sequence so that the requests will be logged'
     args = "url_list [url_list ...]"
-    
+
     option_list = BaseCommand.option_list + (
         make_option('-s', '--manual-start',
             action='store_true',
@@ -47,34 +50,41 @@ class Command(BaseCommand):
             help='Run the test authenticated with the PASSWORD provided.'
         ),
     )
-    
+
     def status_update(self, msg):
         if not self.quiet:
             print msg
-    
+
     def status_ticker(self):
         if not self.quiet:
             sys.stdout.write('.')
             sys.stdout.flush()
-    
+
     def handle(self, *url_lists, **options):
         from django.conf import settings
         from debug_logging.models import TestRun
         from debug_logging.utils import (get_project_name, get_hostname,
                                          get_revision)
-        
+
         verbosity = int(options.get('verbosity', 1))
         self.quiet = verbosity < 1
         self.verbose = verbosity > 1
-
+
+        # Dtermine if the DBHandler is used
+        if True in [isinstance(handler, DBHandler) for handler in
+                    LOGGING_CONFIG["LOGGING_HANDLERS"]]:
+            self.has_dbhandler = True
+        else:
+            self.has_dbhandler = False
+
         # Check for a username without a password, or vice versa
         if options['username'] and not options['password']:
             raise CommandError('If a username is provided, a password must '
                                'also be provided.')
         if options['password'] and not options['username']:
             raise CommandError('If a password is provided, a username must '
                                'also be provided.')
-        
+
         # Create a TestRun object to track this run
         filters = {}
         panels = settings.DEBUG_TOOLBAR_PANELS
@@ -83,80 +93,88 @@ def handle(self, *url_lists, **options):
             filters['hostname'] = get_hostname()
         if 'debug_logging.panels.revision.RevisionLoggingPanel' in panels:
             filters['revision'] = get_revision()
-
-        # Check to see if there is already a TestRun object open
-        existing_runs = TestRun.objects.filter(end__isnull=True, **filters)
-        if existing_runs:
-            if options['manual_start']:
-                # If the --manual-start option was specified, error out because
-                # there is already an open TestRun
-                raise CommandError('There is already an open TestRun.')
-
-            # Otherwise, close it so that we can open a new one
-            for existing_run in existing_runs:
-                existing_run.end = datetime.now()
-                existing_run.save()
-
+
+        if self.has_dbhandler:
+            # Check to see if there is already a TestRun object open
+            existing_runs = TestRun.objects.filter(end__isnull=True, **filters)
+            if existing_runs:
+                if options['manual_start']:
+                    # If the --manual-start option was specified, error out
+                    # because there is already an open TestRun
+                    raise CommandError('There is already an open TestRun.')
+
+                # Otherwise, close it so that we can open a new one
+                for existing_run in existing_runs:
+                    existing_run.end = datetime.now()
+                    existing_run.save()
+
+                if options['manual_end']:
+                    # If the --manual-end option was specified, we can now exit
+                    self.status_update('The TestRun was successfully closed.')
+                    return
             if options['manual_end']:
-                # If the --manual-end option was specified, we can now exit
-                self.status_update('The TestRun was successfully closed.')
+                # The --manual-end option was specified, but there was no
+                # existing run to close.
+                raise CommandError('There is no open TestRun to end.')
+
+            filters['start'] = datetime.now()
+            test_run = TestRun(**filters)
+
+            if options['name']:
+                test_run.name = options['name']
+            if options['description']:
+                test_run.description = options['description']
+
+            test_run.save()
+
+            if options['manual_start']:
+                # The TestRun was successfully created
+                self.status_update('A new TestRun was successfully opened.')
                 return
-        if options['manual_end']:
-            # The --manual-end option was specified, but there was no existing
-            # run to close.
-            raise CommandError('There is no open TestRun to end.')
-
-        filters['start'] = datetime.now()
-        test_run = TestRun(**filters)
-
-        if options['name']:
-            test_run.name = options['name']
-        if options['description']:
-            test_run.description = options['description']
-
-        test_run.save()
-
-        if options['manual_start']:
-            # The TestRun was successfully created
-            self.status_update('A new TestRun was successfully opened.')
-            return
-
+
         urls = []
         for url_list in url_lists:
             with open(url_list) as f:
                 urls.extend([l.strip() for l in f.readlines()
                              if not l.startswith('#')])
-        
+
         self.status_update('Beginning debug logging run...')
-        
+
         client = Client()
-        
+
         if options['username'] and options['password']:
             client.login(username=options['username'],
                          password=options['password'])
-        
+
         for url in urls:
             try:
-                response = client.get(url)
-            except KeyboardInterrupt, e:
-                # Close out the log entry
-                test_run.end = datetime.now()
-                test_run.save()
-
+                response = client.get(url, DJANGO_DEBUG_LOGGING=True)
+            except KeyboardInterrupt as e:
+                if self.has_dbhandler:
+                    # Close out the log entry
+                    test_run.end = datetime.now()
+                    test_run.save()
+
                 raise CommandError('Debug logging run cancelled.')
-            except:
+            except Exception as e:
                 if self.verbose:
-                    self.status_update('\nSkipped %s because of an error'
-                                       % url)
-                    continue
+                    self.status_update('\nSkipped %s because of error: %s'
+                                       % (url, e))
+                continue
             if response and response.status_code == 200:
                 self.status_ticker()
             else:
-                self.status_update('\nURL %s responded with code %s'
-                                   % (url, response.status_code))
-
-        # Close out the log entry
-        test_run.end = datetime.now()
-        test_run.save()
-
+                if self.verbose:
+                    try:
+                        self.status_update('\nURL %s responded with code %s'
+                                           % (url, response.status_code))
+                    except NameError as e:
+                        self.status_update('\nSkipped %s because of error: %s'
+                                           % (url, e))
+
+        if self.has_dbhandler:
+            # Close out the log entry
+            test_run.end = datetime.now()
+            test_run.save()
+
         self.status_update('done!\n')

debug_logging/middleware.py

@@ -5,68 +5,65 @@
 
 from debug_toolbar.toolbar.loader import DebugToolbar
 from debug_toolbar.middleware import DebugToolbarMiddleware
-from debug_logging.handlers import DBHandler
+from debug_logging.settings import LOGGING_CONFIG
 
 logger = logging.getLogger('debug.logger')
-logger.setLevel(logging.DEBUG)
-logger.addHandler(DBHandler())
+for HandlerClass in LOGGING_CONFIG["LOGGING_HANDLERS"]:
+    logger.addHandler(HandlerClass)
 
 
 class DebugLoggingMiddleware(DebugToolbarMiddleware):
     """
     Extends the Debug Toolbar middleware with some extras for logging stats.
     """
-
-    def __init__(self):
-        super(DebugLoggingMiddleware, self).__init__()
-
-        # Determine whether logging is enabled
-        self.logging_enabled = False
-        if hasattr(settings, 'DEBUG_LOGGING_CONFIG'):
-            if settings.DEBUG_LOGGING_CONFIG.get('ENABLED', False):
-                self.logging_enabled = True
+
+    def _logging_enabled(self, request):
+        return request.META.get('DJANGO_DEBUG_LOGGING', False)
 
     def _show_toolbar(self, request):
-        if self.logging_enabled:
+        if self._logging_enabled(request):
             # If logging is enabled, don't show the toolbar
             return False
         return super(DebugLoggingMiddleware, self)._show_toolbar(request)
-    
+
     def process_request(self, request):
+        if self._logging_enabled(request):
+            request.debug_logging = LOGGING_CONFIG
+            request.debug_logging['ENABLED'] = True
         response = super(DebugLoggingMiddleware, self).process_request(request)
-
-        if self.logging_enabled:
-            blacklist = settings.DEBUG_LOGGING_CONFIG.get('BLACKLIST', [])
-
+
+        if self._logging_enabled(request):
             # If the debug-logging frontend is in use, add it to the blacklist
+            blacklist = request.debug_logging['BLACKLIST']
             try:
                 debug_logging_prefix = reverse('debug_logging_index')
                 blacklist.append(debug_logging_prefix)
             except NoReverseMatch:
                 pass
-            
+
             # Don't log requests to urls in the blacklist
             for blacklist_url in blacklist:
                 if request.path.startswith(blacklist_url):
                     return response
-            
+
             # Add an attribute to the request to track stats, and log the
             # request path
             request.debug_logging_stats = {'request_path': request.path}
-            
+
             self.debug_toolbars[request] = DebugToolbar(request)
             for panel in self.debug_toolbars[request].panels:
                 panel.process_request(request)
-        
+
         return response
-    
+
     def process_response(self, request, response):
         response = super(DebugLoggingMiddleware, self).process_response(
             request, response)
-        
+
         if response.status_code == 200:
-            if self.logging_enabled and hasattr(request, 'debug_logging_stats'):
-                # If logging is enabled, log the stats to the selected handler                
+            if self._logging_enabled(request) and \
+              hasattr(request, 'debug_logging_stats'):
+                # If logging is enabled, log the stats to the selected handler
                 logger.debug(request.debug_logging_stats)
-        
+
         return response