django how to see sql query when running tests?

Question

One of my django application unit test fails with

DatabaseError: ORA-00942: table or view does not exist

I would like to see actual SQL query that caused this error. Do you know how to achieve that?

Rosaliarosalie

Is this helpful ? #1074712 – Roughcast

Not exactly. I don't want to include 'print connection.queries' in the test case because in order to execute that line I would need first to catch an exception. If I catch that exception the test will pass which is not good. Reraising this exception is not very elegant, I'm looking for some better solution. – Rosaliarosalie

Another thing is that 'print' doesn't work with tests - at least for me... – Rosaliarosalie

One way or another you're going to have to catch the exception in order to display any information at the moment of the error. I don't see anything inelegant with reraising the exception -- just use the raise keyword all by itself and it'll pass through with the stack trace intact. – Hamartia

Oh, actually, I guess there is another solution -- you can log at the DEBUG level and configure your logger to write all SQL queries to the log as they happen. See docs.djangoproject.com/en/dev/topics/logging – Hamartia

In recent versions of cx_Oracle you can set the environment variable DPI_DEBUG_LEVEL to 24 and then run your program, see Low Level SQL Tracing in cx_Oracle. The environment variable values are shown in ODPI-C Debugging. Using the value 16+8=24 will give SQL statements & errors. – Sympathize

Answer 1

The best solution I found so far is debugsqlshell custom django management command provided by django-debugtoolbar.

Rosaliarosalie

Could you elaborate on how to use the debugsqlshell command to run a test. That is not explained in the documentation of django-debugtoolbar. – Bolan

@Bolan it doesn't I believe mnowotka misunderstood the question. Well, actually, just figured out that he is the TS, so here is -1 for wrong accepted answer – Attentive

Answer 2

Another option is to use CaptureQueriesContext (tested with pytest).

from django.db import connection
from django.test.utils import CaptureQueriesContext


def test_foo():
    with CaptureQueriesContext(connection) as ctx:
        # code that runs SQL queries
        print(ctx.captured_queries)

Sources:

• https://blog.ploetzli.ch/2019/showing-sql-queries-with-pytest-and-django/
• How to force django to print each executed sql query

Phrixus

This is the simplest and cleanest answer as it lets you capture queries for any arbitrarily small section of code, which if you are looking to troubleshoot a problem or optimize queries is what you want. – Licking

Answer 3

If you want to print/log all SQL queries from the tests, try subclassing TestCase like this:

from django.conf import settings
from django.template import Template, Context
import sys
from django.db import connection
from django.test import TestCase

class LoggingTestCase(TestCase):

  @staticmethod
  def setUpClass():
    # The test runner sets DEBUG to False. Set to True to enable SQL logging.
    settings.DEBUG = True
    super(LoggingTestCase, LoggingTestCase).setUpClass()

  @staticmethod
  def tearDownClass():
    super(LoggingTestCase, LoggingTestCase).tearDownClass()

    time = sum([float(q['time']) for q in connection.queries])
    t = Template("{{count}} quer{{count|pluralize:\"y,ies\"}} in {{time}} seconds:\n\n{% for sql in sqllog %}[{{forloop.counter}}] {{sql.time}}s: {{sql.sql|safe}}{% if not forloop.last %}\n\n{% endif %}{% endfor %}")
    print >> sys.stderr, t.render(Context({'sqllog': connection.queries, 'count': len(connection.queries), 'time': time}))

    # Empty the query list between TestCases.    
    connection.queries = []

Then use LoggingTestCase instead of TestCase as the base class in your tests. Just remember to call this tearDownClass if you override it.

Jovitta

You should call the super setUpClass too. When you don't, things are missing, for example fixture loading. – Aarau

@Aarau good point, fixed now. If you downvoted, please consider un-downvoting, see: stackoverflow.com/help/privileges/vote-down – Jovitta

Django really doesn't allow you to set some environment variable to print out all queries? – Ogrady

How to override settings for tests. – Manumission

Answer 4

You can also do the following to get the queries (and then for instance print it or evaluate it in your test).

Actually you shouldn't alter django.conf.settings nowadays, therefore I use override_settings.

from django.db import connection, reset_queries
from django.test import override_settings, TransactionTestCase

class TransactionTests(TransactionTestCase):

    @override_settings(DEBUG=True)
    def test_sql(self):
        reset_queries()
        try:
            # Code that uses the ORM goes here
        except Exception as e:
            pass
        self.assertEqual(connection.queries, [])

TestCase might also be suitable, see the differences in this answer.

See the Django documentation for details for SQL output.

Nazarius

Answer 5

Another option is to use connection.execute_wrapper() in your test as follows:

from django.db import connection

def logger(execute, sql, params, many, context):
    print(sql, params)
    return execute(sql, params, many, context)

class GizmoTest(TestCase):

    def test_with_sql_logging(self):
        with connection.execute_wrapper(logger):
            code_that_uses_database()

Tested with Django 2.2.

Discrepancy

Answer 6

Its not the cleanest solution but if you just quickly want to debug without installing additional packages you could look for the execute() method in django/db.

For Oracle I guess it is in:

django/db/backends/oracle/base.py and look for:

def execute

For PostgreSQL it is in:

django/db/backends/postgresql_psycopg2/base.py

In CursorWrapper there is a execute() method.

Both are catching IntegrityError and DatabaseError, you can add a print statement there.

For ppl who want to see all sql queries, put the print statement right after the function call.

Sosna

Answer 7

In the case of pytest and pytest-django just create a fixture for it

@pytest.fixture
def debug_queries(db):
    """ Because pytest run tests with DEBUG=False
        the regular query logging will not work, use this fixture instead
    """
    from django.db import connection
    from django.test.utils import CaptureQueriesContext
    with CaptureQueriesContext(connection):
        yield connection

then in your tests

@pytest.mark.django_db
def test__queries(debug_queries):
    # run your queries here

of course, your logging config should enable logging of queries, something like this:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '%(asctime)s - %(levelname)s - %(name)s - %(message)s',
        },
    },
    'handlers': {
        'default': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'standard',
            'stream': 'ext://sys.stdout',
        },
    },
    'loggers': {
        'django.db.backends': {
            'level': 'DEBUG',
            'handlers': ['default'],
            'propagate': False,
        },
    }
}

Attentive

SQL queries are not printed out. – Gynaecology

This worked for me! Do you know if it's possible to use the settings fixture from pytest-django to set the logger for tests? I tried to use it but it did not work for logging in this case. – Turd

@Turd not sure what you mean by using settings fixture. What exactly you are trying to achieve? – Attentive

@EugeneK pytest-django has settings fixture that can override the settings pytest-django.readthedocs.io/en/latest/… I was thinking that maybe I could use it as an argument for debug_queries so I do not need to add logging config in test.settings.py and just use the fixture if needed. – Turd

@Turd you can always set logger level to DEBUG inside the debug_queries fixture, no need to hack settings. Don't forget to restore the level when the fixture exits – Attentive

Answer 8

This was the solution which worked for me (Django 3.1):

from django.test import TestCase


class TestSomething(TestCase):
    @override_settings(DEBUG=True)
    def test_something(self):
        pass
    
    def tearDown(self):
        from django.db import connection
        for query in connection.queries:
            print(f"✅ {query['sql']}\n")

source

Goods

Answer 9

You can change console level to DEBUG in settings. It worked on Django 1.9.

LOGGING = {
...
'handlers': {
    'console': {
        'level': 'DEBUG',
        'class': 'logging.StreamHandler',
        'formatter': 'simple'
        },
    }
...
}

Action

Does not work "For performance reasons, SQL logging is only enabled when settings.DEBUG is set to True, regardless of the logging level or handlers that are installed." docs.djangoproject.com/en/1.11/topics/logging/… – Altar

Answer 10

All the options here were too complicated/and too many things could go wrong. This works on django >= 1.11+ <= 4.x [tested it on the main branch] (until they break it in the future..)

It works by ignoring settings.DEBUG entirely and just injecting the CursorDebugWrapper to be used always, thus logging the SQLs that ran.

import inspect
from collections import deque
from contextlib import contextmanager
from unittest import mock

from django.db import connections
from django.db.backends import utils


@contextmanager
def print_queries(using="default"):
    """
    [debug] Prints out all the queries in real time

    To avoid messing with django's logging and get the SQL working inside
    tests where `DEBUG` can be set to `False`, this bypasses all that and
    goes straight for the kill.

    Example:

        class TestSomething(TestCase):
            def test_something(self):
                with print_queries():
                    Model.objects.create(a=1, b=2)

        def test_something():
            with print_queries():
                Model.objects.create(a=1, b=2)

    """

    def fake_maker(self, cursor):
        """
        Normally `make_cursor` uses `CursorWrapper` which does NOT debug.
        """
        return utils.CursorDebugWrapper(cursor, self)

    class Snitch(deque):
        """
        Modified version of `deque` that `print()`s out all the items inserted to it.
        """

        def append(self, item):
            current_frame = inspect.currentframe().f_back
            while True:
                info = inspect.getframeinfo(current_frame)
                if "/django/" in info.filename:
                    current_frame = current_frame.f_back
                    continue
                break

            print("*", item["sql"], item["time"], f"{info.filename}:{info.lineno}")
            return super().append(item)

    connection_ = connections[using]
    mock_maker = mock.patch("django.db.backends.base.base.BaseDatabaseWrapper.make_cursor", fake_maker)
    mock_deque = mock.patch.object(connection_, "queries_log", Snitch(maxlen=connection_.queries_log.maxlen))

    with mock_maker, mock_deque:
        yield

Use it like this:

def test_whatever():
    ...
    with print_queries():
        Model.objects.create(a=1, b=2)  # any query here
    ...

Output looks like:

* SELECT .. FROM "table" WHERE ... 0.001 /full/path/file.py:136
* SELECT .. FROM "table" WHERE ... 0.001 /full/path/file.py:245

Will tell you where in your code the query is being made.

Vickeyvicki

Answer 11

I combined a couple of existing answers into a utility function I've found handy to have when debugging individual tests:

import traceback
from django.db import connections

@contextmanager
def log_queries():
    """
    Prints queries and their tracebacks when they are executed.

    Usage:
    
        with log_queries():
            do_something_with_the_database()
    """

    db = connections["default"]

    def print_stack_in_project(
        execute, sql, params, many, context
    ):
        try:
            return execute(sql, params, many, context)
        finally:
            query = db.queries_log[-1]
            print(f"[{query['time']}] {query['sql']}")
            traceback.print_stack()
            print()  # to separate stacks

    with db.execute_wrapper(print_stack_in_project):
        yield

Underlie

For completeness of solutions, one quick way to check the SQL being executed in cx_Oracle and python-oracledb Thick mode is to set the environment variable DPI_DEBUG_LEVEL to 16 before running the app, see Low Level SQL Tracing. This won't give the values of bind variables nor give the Python stack. – Sympathize

Answer 12

You can also just use the logger

paste this into your root conftest.py

@pytest.fixture#(autouse=True)
def debug_true(settings):
    import logging
    dblog = logging.getLogger('django.db.backends')
    dblog.setLevel(logging.DEBUG)
    dblog.propagate = False
    dblog.addHandler(logging.StreamHandler())
    settings.DEBUG = True

Vickeyvicki