[Django] #27539: assertNumQueries fails if debug cursor wrapper fills
Django
---------------------------------------------+------------------------
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
---------------------------------------------+------------------------
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....
--
Ticket URL: <https://code.djangoproject.com/ticket/27539>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Tim Graham):
* stage: Unreviewed => Accepted
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:1>
Django
Reporter: Malcolm Box | Owner: Henry Dang
Type: Bug | Status: assigned
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Henry Dang):
* owner: nobody => Henry Dang
* status: new => assigned
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:2>
Django
Reporter: Malcolm Box | Owner: (none)
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Henry Dang):
* status: assigned => new
* owner: Henry Dang => (none)
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:3>
Django
Reporter: Malcolm Box | Owner: (none)
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by 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)
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:4>
Django
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:5>
Django
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:6>
Django
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by reficul31):
Skimming over the code. I think the best solution i could think of once
the count reaches 9000 we start removing queries from the back of the
queue as queries_log is a deque . But I do have a question. Should the
method to remove the queries_log be put in BaseDatabaseWrapper or can we
just remove them manually in the CaptureQueriesContext? Or we could just
throw an error?? But the problem will recurr and the following tests will
also start throwing the same error.
Replying to [comment:6 Aymeric Augustin]:
> The test framework should clear `connection.queries` between each test.
Do you want to clear all the queries or can it just be like a pop function
where as a query comes in another one is deleted?
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:7>
Django
Reporter: Malcolm Box | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:8>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by reficul31):
* status: new => assigned
* owner: nobody => reficul31
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:9>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by reficul31):
* needs_better_patch: 0 => 1
* has_patch: 0 => 1
* needs_docs: 0 => 1
Comment:
[https://github.com/django/django/pull/8013| 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?
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:10>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 1
Easy pickings: 0 | UI/UX: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:11>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 1
Easy pickings: 0 | UI/UX: 0
Changes (by reficul31):
* Attachment "error.txt" added.
This is the file with the error traceback.
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by reficul31):
* needs_docs: 1 => 0
Comment:
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)
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:12>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: assigned
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Comment (by 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.
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:13>
Django
Reporter: Malcolm Box | Owner: reficul31
Component: Testing framework | Version: 1.10
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Changes (by Tim Graham <timograham@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"92e286498acd4f4562be11c21879856de8f47252" 92e28649]:
{{{
#!CommitTicketReference repository=""
revision="92e286498acd4f4562be11c21879856de8f47252"
Fixed #27539 -- Made TransactionTestCase._pre_setup() clear the
queries_log so it's less likely to overflow.
TransactionTestCase.assertNumQueries() fails in an overflow situation.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:14>
Django
Reporter: Malcolm Box | Owner: reficul31
Type: Bug | Status: closed
Keywords: | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
Comment (by Tim Graham <timograham@…>):
In [changeset:"e36598f963ae492ea4f3afe73d4e70b5a097f93a" e36598f]:
{{{
#!CommitTicketReference repository=""
revision="e36598f963ae492ea4f3afe73d4e70b5a097f93a"
Refs #27539 -- Fixed typo in TransactionTestCase._pre_setup() comment.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/27539#comment:15>