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 diff --git a/docs/internals/contributing/writing-code/unit-tests.txt b/docs/internals/contributing/writing-code/unit-tests.txt index 6067e9635d..df50a636b8 100644 --- a/docs/internals/contributing/writing-code/unit-tests.txt +++ b/docs/internals/contributing/writing-code/unit-tests.txt @@ -286,7 +286,7 @@ For example, suppose that the failing test that works on its own is .. code-block:: bash - $ ./runtests.py --bisect basic.tests.ModelTest.test_eq + $ ./runtests.py --bisect basic.tests.ModelTest.test_eq will try to determine a test that interferes with the given one. First, the test is run with the first half of the test suite. If a failure occurs, the @@ -302,7 +302,7 @@ failure. So: .. code-block:: bash - $ ./runtests.py --pair basic.tests.ModelTest.test_eq + $ ./runtests.py --pair basic.tests.ModelTest.test_eq will pair ``test_eq`` with every test label. @@ -313,7 +313,7 @@ the first one: .. code-block:: bash - $ ./runtests.py --pair basic.tests.ModelTest.test_eq queries transactions + $ ./runtests.py --pair basic.tests.ModelTest.test_eq queries transactions You can also try running any set of tests in reverse using the ``--reverse`` option in order to verify that executing tests in a different order does not @@ -321,8 +321,16 @@ cause any trouble: .. code-block:: bash - $ ./runtests.py basic --reverse + $ ./runtests.py basic --reverse + +If you wish to examine the SQL being run in failing tests, you can turn on +:ref:`SQL logging ` using the ``--debug-sql`` option. If you +combine this with ``--verbosity=2``, all SQL queries will be output. + +.. code-block:: bash + + $ ./runtests.py basic --debug-sql .. versionadded:: 1.8 - The ``--reverse`` option was added. + The ``--reverse`` and ``--debug-sql`` options were added. diff --git a/docs/ref/django-admin.txt b/docs/ref/django-admin.txt index de556b28b7..570766f18d 100644 --- a/docs/ref/django-admin.txt +++ b/docs/ref/django-admin.txt @@ -1449,6 +1449,14 @@ This may help in debugging tests that aren't properly isolated and have side effects. :ref:`Grouping by test class ` is preserved when using this option. +.. django-admin-option:: --debug-sql + +.. versionadded:: 1.8 + +The ``--debug-sql`` option can be used to enable :ref:`SQL logging +` for failing tests. If :djadminopt:`--verbosity` is ``2``, +then queries in passing tests are also output. + testserver -------------------------------- diff --git a/docs/releases/1.8.txt b/docs/releases/1.8.txt index dc0ce839bb..c4e4e34894 100644 --- a/docs/releases/1.8.txt +++ b/docs/releases/1.8.txt @@ -625,8 +625,9 @@ Tests allows you to test that two JSON fragments are not equal. * Added options to the :djadmin:`test` command to preserve the test database - (:djadminopt:`--keepdb`) and to run the test cases in reverse order - (:djadminopt:`--reverse`). + (:djadminopt:`--keepdb`), to run the test cases in reverse order + (:djadminopt:`--reverse`), and to enable SQL logging for failing tests + (:djadminopt:`--debug-sql`). * Added the :attr:`~django.test.Response.resolver_match` attribute to test client responses. diff --git a/docs/topics/logging.txt b/docs/topics/logging.txt index a1ed176da8..5dbd01c383 100644 --- a/docs/topics/logging.txt +++ b/docs/topics/logging.txt @@ -439,6 +439,8 @@ Messages to this logger have the following extra context: * ``request``: The request object that generated the logging message. +.. _django-db-logger: + ``django.db.backends`` ~~~~~~~~~~~~~~~~~~~~~~ diff --git a/docs/topics/testing/advanced.txt b/docs/topics/testing/advanced.txt index 7865056e31..c995d5ec5c 100644 --- a/docs/topics/testing/advanced.txt +++ b/docs/topics/testing/advanced.txt @@ -355,7 +355,7 @@ behavior. This class defines the ``run_tests()`` entry point, plus a selection of other methods that are used to by ``run_tests()`` to set up, execute and tear down the test suite. -.. class:: DiscoverRunner(pattern='test*.py', top_level=None, verbosity=1, interactive=True, failfast=True, keepdb=False, reverse=False, **kwargs) +.. class:: DiscoverRunner(pattern='test*.py', top_level=None, verbosity=1, interactive=True, failfast=True, keepdb=False, reverse=False, debug_sql=False, **kwargs) ``DiscoverRunner`` will search for tests in any file matching ``pattern``. @@ -386,6 +386,11 @@ execute and tear down the test suite. and have side effects. :ref:`Grouping by test class ` is preserved when using this option. + If ``debug_sql`` is ``True``, failing test cases will output SQL queries + logged to the :ref:`django.db.backends logger ` as well + as the traceback. If ``verbosity`` is ``2``, then queries in all tests are + output. + Django may, from time to time, extend the capabilities of the test runner by adding new arguments. The ``**kwargs`` declaration allows for this expansion. If you subclass ``DiscoverRunner`` or write your own test @@ -402,7 +407,7 @@ execute and tear down the test suite. subclassed test runner to add options to the list of command-line options that the :djadmin:`test` command could use. - The ``keepdb`` and the ``reverse`` arguments were added. + The ``keepdb``, ``reverse``, and ``debug_sql`` arguments were added. Attributes ~~~~~~~~~~ diff --git a/tests/runtests.py b/tests/runtests.py index 6ff5421772..f742c57bbb 100755 --- a/tests/runtests.py +++ b/tests/runtests.py @@ -217,7 +217,7 @@ def teardown(state): setattr(settings, key, value) -def django_tests(verbosity, interactive, failfast, keepdb, reverse, test_labels): +def django_tests(verbosity, interactive, failfast, keepdb, reverse, test_labels, debug_sql): state = setup(verbosity, test_labels) extra_tests = [] @@ -232,6 +232,7 @@ def django_tests(verbosity, interactive, failfast, keepdb, reverse, test_labels) failfast=failfast, keepdb=keepdb, reverse=reverse, + debug_sql=debug_sql, ) # Catch warnings thrown in test DB setup -- remove in Django 1.9 with warnings.catch_warnings(): @@ -386,6 +387,9 @@ if __name__ == "__main__": parser.add_argument( '--selenium', action='store_true', dest='selenium', default=False, help='Run the Selenium tests as well (if Selenium is installed)') + parser.add_argument( + '--debug-sql', action='store_true', dest='debug_sql', default=False, + help='Turn on the SQL query logger within tests') options = parser.parse_args() # mock is a required dependency @@ -421,6 +425,7 @@ if __name__ == "__main__": else: failures = django_tests(options.verbosity, options.interactive, options.failfast, options.keepdb, - options.reverse, options.modules) + options.reverse, options.modules, + options.debug_sql) if failures: sys.exit(bool(failures)) diff --git a/tests/test_runner/test_debug_sql.py b/tests/test_runner/test_debug_sql.py new file mode 100644 index 0000000000..7bc0950d84 --- /dev/null +++ b/tests/test_runner/test_debug_sql.py @@ -0,0 +1,102 @@ +import unittest + +from django.db import connection +from django.test import TestCase +from django.test.runner import DiscoverRunner +from django.utils import six + +from .models import Person + + +@unittest.skipUnless(connection.vendor == 'sqlite', 'Only run on sqlite so we can check output SQL.') +class TestDebugSQL(unittest.TestCase): + + class PassingTest(TestCase): + def runTest(self): + Person.objects.filter(first_name='pass').count() + + class FailingTest(TestCase): + def runTest(self): + Person.objects.filter(first_name='fail').count() + self.fail() + + class ErrorTest(TestCase): + def runTest(self): + Person.objects.filter(first_name='error').count() + raise Exception + + def _test_output(self, verbosity): + runner = DiscoverRunner(debug_sql=True, verbosity=0) + suite = runner.test_suite() + suite.addTest(self.FailingTest()) + suite.addTest(self.ErrorTest()) + suite.addTest(self.PassingTest()) + old_config = runner.setup_databases() + stream = six.StringIO() + resultclass = runner.get_resultclass() + runner.test_runner( + verbosity=verbosity, + stream=stream, + resultclass=resultclass, + ).run(suite) + runner.teardown_databases(old_config) + + stream.seek(0) + return stream.read() + + def test_output_normal(self): + full_output = self._test_output(1) + for output in self.expected_outputs: + self.assertIn(output, full_output) + for output in self.verbose_expected_outputs: + self.assertNotIn(output, full_output) + + def test_output_verbose(self): + full_output = self._test_output(2) + for output in self.expected_outputs: + self.assertIn(output, full_output) + for output in self.verbose_expected_outputs: + self.assertIn(output, full_output) + + if six.PY3: + expected_outputs = [ + ('''QUERY = 'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = ('*', 'error');'''), + ('''QUERY = 'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = ('*', 'fail');'''), + ] + else: + expected_outputs = [ + ('''QUERY = u'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = (u'*', u'error');'''), + ('''QUERY = u'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = (u'*', u'fail');'''), + ] + + verbose_expected_outputs = [ + 'runTest (test_runner.test_debug_sql.FailingTest) ... FAIL', + 'runTest (test_runner.test_debug_sql.ErrorTest) ... ERROR', + 'runTest (test_runner.test_debug_sql.PassingTest) ... ok', + ] + if six.PY3: + verbose_expected_outputs += [ + ('''QUERY = 'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = ('*', 'pass');'''), + ] + else: + verbose_expected_outputs += [ + ('''QUERY = u'SELECT COUNT(%s) AS "__count" ''' + '''FROM "test_runner_person" WHERE ''' + '''"test_runner_person"."first_name" = %s' ''' + '''- PARAMS = (u'*', u'pass');'''), + ]