Opened 8 years ago

Closed 7 years ago

Last modified 7 years ago

#27539 closed Bug (fixed)

assertNumQueries fails if debug cursor wrapper fills

Reported by: Malcolm Box Owned by: reficul31
Component: Testing framework Version: 1.10
Severity: Normal Keywords:
Cc: Triage Stage: Accepted
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: yes
Easy pickings: no UI/UX: no

Description

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....

Attachments (1)

error.txt (1.1 KB ) - added by reficul31 8 years ago.
This is the file with the error traceback.

Download all attachments as: .zip

Change History (14)

comment:1 by Tim Graham, 8 years ago

Triage Stage: UnreviewedAccepted

comment:4 by reficul31, 8 years ago

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)

comment:5 by Tim Graham, 8 years ago

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.

comment:6 by Aymeric Augustin, 8 years ago

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

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

in reply to:  6 comment:7 by reficul31, 8 years ago

Last edited 8 years ago by reficul31 (previous) (diff)

comment:8 by reficul31, 8 years ago

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 clear the assertNumQueries test fails.

Version 1, edited 8 years ago by reficul31 (previous) (next) (diff)

comment:9 by reficul31, 8 years ago

Owner: changed from nobody to reficul31
Status: newassigned

comment:10 by reficul31, 8 years ago

Has patch: set
Needs documentation: set
Patch needs improvement: set

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?

Last edited 8 years ago by Tim Graham (previous) (diff)

comment:11 by Tim Graham, 8 years ago

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.

by reficul31, 8 years ago

Attachment: error.txt added

This is the file with the error traceback.

comment:12 by reficul31, 8 years ago

Needs documentation: unset

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)

Last edited 8 years ago by Tim Graham (previous) (diff)

comment:13 by Tim Graham, 8 years ago

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.

comment:14 by Tim Graham <timograham@…>, 7 years ago

Resolution: fixed
Status: assignedclosed

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.

comment:15 by Tim Graham <timograham@…>, 7 years ago

In e36598f:

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

Note: See TracTickets for help on using tickets.
Back to Top