Fixed #24118 -- Added --debug-sql option for tests.

Added a --debug-sql option for tests and runtests.py which outputs the
SQL logger for failing tests. When combined with --verbosity=2, it also
outputs the SQL for passing tests.

Thanks to Berker, Tim, Markus, Shai, Josh and Anssi for review and
discussion.

1 files changed, 62 insertions, 5 deletions

diff --git a/django/test/runner.py b/django/test/runner.py
index 65f55c4176..73a5a9d175 100644
--- a/django/test/runner.py
+++ b/django/test/runner.py
@@ -1,4 +1,5 @@
 from importlib import import_module
+import logging
 import os
 import unittest
 from unittest import TestSuite, defaultTestLoader
@@ -8,6 +9,47 @@ from django.core.exceptions import ImproperlyConfigured
 from django.test import SimpleTestCase, TestCase
 from django.test.utils import setup_test_environment, teardown_test_environment
 from django.utils.datastructures import OrderedSet
+from django.utils.six import StringIO
+
+
+class DebugSQLTextTestResult(unittest.TextTestResult):
+    def __init__(self, stream, descriptions, verbosity):
+        self.logger = logging.getLogger('django.db.backends')
+        self.logger.setLevel(logging.DEBUG)
+        super(DebugSQLTextTestResult, self).__init__(stream, descriptions, verbosity)
+
+    def startTest(self, test):
+        self.debug_sql_stream = StringIO()
+        self.handler = logging.StreamHandler(self.debug_sql_stream)
+        self.logger.addHandler(self.handler)
+        super(DebugSQLTextTestResult, self).startTest(test)
+
+    def stopTest(self, test):
+        super(DebugSQLTextTestResult, self).stopTest(test)
+        self.logger.removeHandler(self.handler)
+        if self.showAll:
+            self.debug_sql_stream.seek(0)
+            self.stream.write(self.debug_sql_stream.read())
+            self.stream.writeln(self.separator2)
+
+    def addError(self, test, err):
+        super(DebugSQLTextTestResult, self).addError(test, err)
+        self.debug_sql_stream.seek(0)
+        self.errors[-1] = self.errors[-1] + (self.debug_sql_stream.read(),)
+
+    def addFailure(self, test, err):
+        super(DebugSQLTextTestResult, self).addFailure(test, err)
+        self.debug_sql_stream.seek(0)
+        self.failures[-1] = self.failures[-1] + (self.debug_sql_stream.read(),)
+
+    def printErrorList(self, flavour, errors):
+        for test, err, sql_debug in errors:
+            self.stream.writeln(self.separator1)
+            self.stream.writeln("%s: %s" % (flavour, self.getDescription(test)))
+            self.stream.writeln(self.separator2)
+            self.stream.writeln("%s" % err)
+            self.stream.writeln(self.separator2)
+            self.stream.writeln("%s" % sql_debug)
 
 
 class DiscoverRunner(object):
@@ -20,9 +62,9 @@ class DiscoverRunner(object):
     test_loader = defaultTestLoader
     reorder_by = (TestCase, SimpleTestCase)
 
-    def __init__(self, pattern=None, top_level=None,
-                 verbosity=1, interactive=True, failfast=False, keepdb=False, reverse=False,
-                 **kwargs):
+    def __init__(self, pattern=None, top_level=None, verbosity=1,
+                 interactive=True, failfast=False, keepdb=False,
+                 reverse=False, debug_sql=False, **kwargs):
 
         self.pattern = pattern
         self.top_level = top_level
@@ -32,6 +74,7 @@ class DiscoverRunner(object):
         self.failfast = failfast
         self.keepdb = keepdb
         self.reverse = reverse
+        self.debug_sql = debug_sql
 
     @classmethod
     def add_arguments(cls, parser):
@@ -47,6 +90,9 @@ class DiscoverRunner(object):
         parser.add_argument('-r', '--reverse', action='store_true', dest='reverse',
             default=False,
             help='Reverses test cases order.')
+        parser.add_argument('-d', '--debug-sql', action='store_true', dest='debug_sql',
+            default=False,
+            help='Prints logged SQL queries on failure.')
 
     def setup_test_environment(self, **kwargs):
         setup_test_environment()
@@ -115,12 +161,20 @@ class DiscoverRunner(object):
         return reorder_suite(suite, self.reorder_by, self.reverse)
 
     def setup_databases(self, **kwargs):
-        return setup_databases(self.verbosity, self.interactive, self.keepdb, **kwargs)
+        return setup_databases(
+            self.verbosity, self.interactive, self.keepdb, self.debug_sql,
+            **kwargs
+        )
+
+    def get_resultclass(self):
+        return DebugSQLTextTestResult if self.debug_sql else None
 
     def run_suite(self, suite, **kwargs):
+        resultclass = self.get_resultclass()
         return self.test_runner(
             verbosity=self.verbosity,
             failfast=self.failfast,
+            resultclass=resultclass,
         ).run(suite)
 
     def teardown_databases(self, old_config, **kwargs):
@@ -266,7 +320,7 @@ def partition_suite(suite, classes, bins, reverse=False):
                 bins[-1].add(test)
 
 
-def setup_databases(verbosity, interactive, keepdb=False, **kwargs):
+def setup_databases(verbosity, interactive, keepdb=False, debug_sql=False, **kwargs):
     from django.db import connections, DEFAULT_DB_ALIAS
 
     # First pass -- work out which databases actually need to be created,
@@ -326,4 +380,7 @@ def setup_databases(verbosity, interactive, keepdb=False, **kwargs):
         connections[alias].settings_dict['NAME'] = (
             connections[mirror_alias].settings_dict['NAME'])
 
+    if debug_sql:
+        for alias in connections:
+            connections[alias].force_debug_cursor = True
     return old_names, mirrors