Django 1.9 Mysterious Test Failure

Post by Saul Shanabrook

This morning, I have been trying to upgrade my django-dumper library to work with Django 1.9. It started off pretty painlessly, but when I ran the tests I saw that one test case was failing.

class NoModelTest(TestCase):  
    model = models.SimpleModel

    def setUp(self):
        self.c = Client()
        self.slug = 'someslug'
        self.url = '/simple/' + self.slug + '/'
        self.access_instance = lambda: self.c.get(self.url)

    def test_404_no_cache(self):
        'access a 404 path twice and make sure it hits the database each time'
        with self.assertNumQueries(1):
            with self.assertRaises(self.model.DoesNotExist):
                self.access_instance()

        with self.assertNumQueries(1):
            with self.assertRaises(self.model.DoesNotExist):
                self.access_instance()

This is supposed to just check and make sure that 404's are not
being cached. However, it was failing before it even got to check that important part. It said that it was using 2 database queries, instead of 1, for self.access_instance().

======================================================================
FAIL: test_404_no_cache (test.test_full_stack.NoModelTest)  
access a 404 path twice and make sure it hits the database each time  
----------------------------------------------------------------------
Traceback (most recent call last):  
  File "/usr/src/app/test/test_full_stack.py", line 36, in test_404_no_cache
    self.access_instance()
  File "/usr/local/lib/python3.5/site-packages/django/test/testcases.py", line 93, in __exit__
    query['sql'] for query in self.captured_queries
AssertionError: 2 != 1 : 2 queries executed, 1 expected  
Captured queries were:  
SELECT "test_simplemodel"."id", "test_simplemodel"."slug" FROM "test_simplemodel" WHERE "test_simplemodel"."slug" = 'someslug'  
SELECT "test_simplemodel"."id", "test_simplemodel"."slug" FROM "test_simplemodel" LIMIT 21  

On all other Django versions, this test passed fine.

As you can see, that second query shouldn't be happening. It shouldn't be getting all models. So somewhere Django 1.9 was causing an extra DB query for just this case. On non 404 requests, the same number of queries was being executed. Also, I checked calling the view directly, and that resulted in only one query as well. So some Django code between the actual view logic and the test case was causing an extra query.

I looked through the Django 1.9.0 release notes, but couldn't find anything that seemed relevent.

So I began to hunt through the executed code for where this query happened. First I enabled logging of all SQL queries in my tests, by adding this to my settings:

import os

LOGGING = {  
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'DEBUG',
        },
    },
    'loggers': {
        'django.db.backends': {
            'handlers': ['console'],
            'level': 'DEBUG',
        }
    },
}

Then I just had to figure out where that second query was coming from. I installed pudb (a GUI wrapper around pdb) and added a import pudb; pudb.set_trace() inside my view, before it raises the DoesNotExist exception. Then I proceeded to switch between stepping through the executed code (with i and n) and viewing the output with o. If I saw the next SQL line in the output, I knew I had executed that code that caused the query already.

It was a bit tedious, because if I went by it, then I had to restart my tests and re insert breakpoints where I wanted to stop. Eventually I found the cuprit. It was logging this 404 with the AdminEmailHandler.

I was able to avoid this by disabling all logging, for my tests:

LOGGING_CONFIG = None  

So moral of the story? I am not sure. Django's release seems really complete, but the comment for this change in Django 1.9 didn't help me much:

To make it easier to write custom logging configurations, Django’s default logging configuration no longer defines django.request and django.security loggers. Instead, it defines a single django logger, filtered at the INFO level, with two handlers:

  • console: filtered at the INFO level and only active if DEBUG=True.
  • mail_admins: filtered at the ERROR level and only active if DEBUG=False. If you aren’t overriding Django’s default logging, you should see minimal changes in behavior, but you might see some new logging to the runserver console, for example.

If you are overriding Django’s default logging, you should check to see how your configuration merges with the new defaults.

I still don't fully understand why AdminEmailHandler is now enabled, when it wasn't before. And why this handler causes a database query, even though I don't have any mail handlers set up and it is obviously not sending any mail.

I am sure there are easier ways to diagnose this problem and I would love to hear about them. Maybe edit the Django source temporarily to add an import pudb; pudb.set_trace() into where it makes DB queries, then I could have looked up the stack trace from there to see where it originated from.