assertNumQueries fails if debug cursor wrapper fills

[Malcolm Box]

Recently I had a test fail that went like this:

with assertNumQueries(5):
   response = self.client.get('/a/view')
   # Various checks that the response had the correct data

This was failing with AssertionError: 0 queries executed, 5 expected yet was hitting the database and returning the correct data. The failure only happened when running certain subsets of the test suite - but not if run in isolation.

Eventually I tracked this down to the following code in CaptureQueriesContext

    @property
    def captured_queries(self):
        return self.connection.queries[self.initial_queries:self.final_queries]

    def __enter__(self):
        self.force_debug_cursor = self.connection.force_debug_cursor
        self.connection.force_debug_cursor = True
        self.initial_queries = len(self.connection.queries_log)
        self.final_queries = None
        request_started.disconnect(reset_queries)
        return self

and this code in BaseDatabaseWrapper:

class BaseDatabaseWrapper(object):
    queries_limit = 9000

    def __init__(self, settings_dict, alias=DEFAULT_DB_ALIAS,
        # Query logging in debug mode or when explicitly enabled.
        self.queries_log = deque(maxlen=self.queries_limit)

This means that if the queries log hits 9K entries, assertNumQueries will no longer see there as being any new queries, and will return 0 for the captured_queries, which is rather tricky to debug.

The minimal solution would be for CaptureQueriesContext to check if self.initial_queries is >= than queries_limit and noisily fail if so, since the test won't work if it is.

I don't yet have a better solution....

[reficul31]

I am sorry but I was unable to reproduce the bug with the following test.

def test_assert_num_queries(self):
        person = Person.objects.create(name='test')
        with self.assertNumQueries(1):
            self.client.get("/test_utils/get_person/%s/" % person.pk)

[Tim Graham]

To reproduce this using your example, my understanding is that self.client.get("/test_utils/get_person/%s/" % person.pk) must run over 9K queries.

[Aymeric Augustin]

The test framework should clear connection.queries between each test.

If a test does more than 9k queries, well... IT'S OVER NINE THOUSAND.

[reficul31]

So I have been working on this ticket and I have a question. Should the check to see if the len(self.queries_log) >= self.queries_log.maxlen be put in the make_debug_cursor or should it be put in the base of the CursorDebugWrapper class? If we put it in CursorDebugWrapper we will need to have all the executesql statements between a try and catch block. Currently the check is placed in the make_debug_cursor() and an Exception is thrown once the len(self.queries_log) >= self.queries_log.maxlen. Another question I have is whether I should throw an exception or I should just clear the queries_log. If I use self.queries_log.clear the assertNumQueries test fails. Also how about a change from version 1.10 to master?

[reficul31]

​PR
I wasn't able to find docs that were stated clearly the limit of query log is 9000. Is an update of documentation in order?

[Tim Graham]

This isn't the approach that Aymeric suggested, "The test framework should clear connection.queries between each test." I think the place to do that might be TransactionTestCase._pre_setup(). Also, the test should temporarily change queries_limit to a small value so that the test doesn't have to make 9,000 queries.

I can't think of any required documentation updates right now.

There isn't a need to change the ticket's version -- that indicates when the ticket was reported.

[reficul31]

This is the file with the error traceback.

[reficul31]

Thank you @timograham for the help. I have attached a file with the traceback. I might be wrong but I strongly feel the clear queries_log method should be placed in the __exit__ of the CaptureQueriesContext. Again I might be wrong but TransactionTestCase as far as I could understand was for the resetting of the Database settings. Whereas the queries_log is stored in the BaseDatabaseWrapper object. To reset the log after every test case we could do it in _AssertNumQueries.__exit__ method. Also resetting the log after every testcase might work but I was thinking in an unlikely scenario where a single test sends over 9000 queries.(I know unrealistic but imagine)

[Tim Graham]

The issue we're try to solve is if the entire test suite runs over 9K queries, assertNumQueries() doesn't work. Your solution will only reset the query count if assertNumQueries() is used. 9K queries might run before that, that's why Aymeric suggested clearing the queries at the start of each test.

We're not trying to solve or consider the case of a single test running over 9K queries. If that happens to someone, they can open a new ticket.

[Tim Graham <timograham@…>]

In 92e28649:

Fixed #27539 -- Made TransactionTestCase._pre_setup() clear the queries_log so it's less likely to overflow.

TransactionTestCase.assertNumQueries() fails in an overflow situation.

[Tim Graham <timograham@…>]

In e36598f:

Refs #27539 -- Fixed typo in TransactionTestCase._pre_setup() comment.