Digging into a Test Failure

We recently encountered an issue with some unit tests at work that I spent some time investigating, and a colleague suggested I write it up as a blog post. I think it serves as a good example of a principle I’m constantly espousing to coworkers–don’t be afraid to dig down into the libraries and frameworks your application uses!

The issue showed up in some unit tests we have for a Python web application that uses the Django framework. We’re using PyMySQL as our database backend and pytest as our test harness with the pytest-django plugin to facilitate things. Some functionality in the application relies on checking the current date against data in the database so to make our tests straightforward my colleague added the freezegun Python library which allows mocking Python’s datetime module:

import datetime
from freezegun import freeze_time

def test():
    with freeze_time("2012-01-14"):
        assert datetime.datetime.now() == datetime.datetime(2012, 1, 14)

Everything was working well until another colleague made some changes that made our tests hit a previously untested code path and she encountered this confusing stack trace:

File "<…>/site-packages/django/db/backends/utils.py", line 68, in execute
     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
   File "<…>/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers
     return executor(sql, params, many, context)
   File "<…>/site-packages/django/db/backends/utils.py", line 85, in _execute
     return self.cursor.execute(sql, params)
   File "<…>/site-packages/django/db/backends/mysql/base.py", line 71, in execute
     return self.cursor.execute(query, args)
   File "<…>/site-packages/pymysql/cursors.py", line 168, in execute
     query = self.mogrify(query, args)
   File "<…>/site-packages/pymysql/cursors.py", line 147, in mogrify
     query = query % self._escape_args(args, conn)
   File "<…>/site-packages/pymysql/cursors.py", line 127, in _escape_args
     return {key: conn.literal(val) for (key, val) in args.items()}
   File "<…>/site-packages/pymysql/cursors.py", line 127, in 
     return {key: conn.literal(val) for (key, val) in args.items()}
   File "<…>/site-packages/pymysql/connections.py", line 467, in literal
     return self.escape(obj, self.encoders)
   File "<…>/site-packages/pymysql/connections.py", line 460, in escape
     return converters.escape_item(obj, self.charset, mapping=mapping)
   File "<…>/site-packages/pymysql/converters.py", line 27, in escape_item
     val = encoder(val, mapping)
   File "<…>/site-packages/pymysql/converters.py", line 118, in escape_unicode
     return u"'%s'" % _escape_unicode(value)
   File "<…>/site-packages/pymysql/converters.py", line 73, in _escape_unicode
     return value.translate(_escape_table)
 AttributeError: 'FakeDate' object has no attribute 'translate'

What the heck is going on here? From a cursory reading of the stack trace it looks like something in PyMySQL is breaking and it definitely seems like freezegun is involved given the mention of FakeDate there. My first instinct was to do what I always do in this situation: start reading the code! The last line in the stack trace is in PyMySQL, which is open source and hosted on GitHub, so let’s go take a look!

Note

When doing this you’ll want to ensure that you are looking at the right version of the code! For our application I looked at our requirements.txt file and saw the line PyMySQL==0.9.3 which meant I needed to look at the source for version 0.9.3. On GitHub you can usually find a branch or tag for release versions of a project by clicking the button that defaults to Branch: master.

Selecting the v0.9.3 tag on the PyMySQL GitHub repository.

Once we’re looking at the right version of the code we can find the file mentioned in the stack trace: pymysql/converters.py, line 73 in a function named _escape_unicode. That function looks like this:

def _escape_unicode(value, mapping=None):
    """escapes *value* without adding quote.
    Value should be unicode
    """
    return value.translate(_escape_table)

We can see right away in the function’s inline documentation that the value parameter should be unicode. The exception from the stack trace said it was a FakeDate object which explains why things are broken, but how did we wind up in this state? Let’s work our way up the stack and see if we can find out. The next frame is in escape_unicode which at a glance doesn’t look interesting, but the one above that is escape_item which looks like this:

def escape_item(val, charset, mapping=None):
    if mapping is None:
        mapping = encoders
    encoder = mapping.get(type(val))

    # Fallback to default when no encoder found
    if not encoder:
        try:
            encoder = mapping[text_type]
        except KeyError:
            raise TypeError("no default type converter defined")

    if encoder in (escape_dict, escape_sequence):
        val = encoder(val, charset, mapping)
    else:
        val = encoder(val, mapping)
    return val

The stack goes through what’s numbered as line 16 in this snippet, calling the encoder function which in this case is escape_unicode. Reading through this function it looks like it looks in the mapping dict (which can be passed in as a parameter or default to encoders) to find an encoder function using the type of the val parameter as the key. If it doesn’t find a dict entry it defaults to using the one for text_type. By now I’m starting to get the beginnings of a theory for why things are broken but let’s look around a little more to make sure we understand what’s happening. We’ll look further up the stack to see if the caller is passing in the mapping parameter in a moment but what does the default encoders look like? It’s right in the same file we’re currently looking at and it looks like this:

encoders = {
    bool: escape_bool,
    int: escape_int,
    long_type: escape_int,
    float: escape_float,
    str: escape_str,
    text_type: escape_unicode,
    tuple: escape_sequence,
    list: escape_sequence,
    set: escape_sequence,
    frozenset: escape_sequence,
    dict: escape_dict,
    type(None): escape_None,
    datetime.date: escape_date,
    datetime.datetime: escape_datetime,
    datetime.timedelta: escape_timedelta,
    datetime.time: escape_time,
    time.struct_time: escape_struct_time,
    Decimal: escape_object,
}

Ok, so this is a straightforward mapping from a bunch of built-in Python types to functions that escape them (presumably for inserting them as parameters in a SQL query, since we’re in the PyMySQL source). We remember from before that the val parameter is actually a FakeDate instance which is not in this list which means that it’s likely that we’re hitting that fallback path using text_type. We can see right here that text_type maps to escape_unicode so that fits our current theory pretty well! It seems like freezegun changes the type of Python’s datetime.date type to use its own FakeDate type, and PyMySQL understandably doesn’t know how to encode that type.

At this point I wanted to take a look at the freezegun source to see if there was anything I was missing. Thankfully it’s also available on GitHub and it’s a very small library consisting of just an __init__.py file that simply exports the freeze_time function from api.py. The first thing I did when loading that file was to search for FakeDate. There are quite a few hits but skimming over them I saw two interesting lines. First was the definition of the FakeDate class which is a little confusing to read:

class FakeDate(with_metaclass(FakeDateMeta, real_date)):
    # ...

This class seems to be using some Python metaclass trickery (which we won’t delve into) but also deriving from real_date. Searching the file for real_date we can find that it’s simply defined as the original datetime.date type. The other line I found interesting was where freezegun actually changes out the built-in types:

        # Change the modules
        datetime.datetime = FakeDatetime
        datetime.date = FakeDate

This makes sense, the whole purpose of the freezegun module is for code using the datetime module to use mock types instead. At the bottom of api.py I stumbled upon something interesting, some code that seemed to be written to work around this exact problem!

# Setup converters for pymysql
try:
    import pymysql.converters
except ImportError:
    pass
else:
    pymysql.converters.encoders[FakeDate] = pymysql.converters.encoders[real_date]
    pymysql.converters.encoders[FakeDatetime] = pymysql.converters.encoders[real_datetime]

So why wasn’t it working? You may recall a few paragraphs before I said we would look further up the stack to see what the caller of escape_item was passing, so let’s do that. The next frame up the stack is the Connection.escape method in connections.py, but that method just takes a mapping argument and passes it along. If we go up one more frame we find something interesting—the Connection.literal method calls self.escape(obj, self.encoders), so it’s not using the default encoders we saw above!

    def literal(self, obj):
        """Alias for escape()
        Non-standard, for internal use; do not use this in your applications.
        """
        return self.escape(obj, self.encoders)

So where does self.encoders get set? Since this is Python the first place I would look is the Connection.__init__ method, which is where Python classes do their initialization. We can find that up a bit in this same source file and searching for self.encoders in there we find this bit of code:

        if conv is None:
            conv = converters.conversions

        # Need for MySQLdb compatibility.
        self.encoders = {k: v for (k, v) in conv.items() if type(k) is not int}
        self.decoders = {k: v for (k, v) in conv.items() if type(k) is int}

Ok, so the Connection class uses the default encoders with one change, but it stores the result as a member of the class. This is important! I realized that if the database connection was created before any code imported the freezegun module the workaround freezegun was attempting to do would have no effect because it would only change the module-level encoders, not the class member! So when does the database connection get created in our test session? At the beginning of this story I mentioned that we’re using pytest-django, so I went looking at its documentation and it talks about how it creates the test database. At this point things were getting a little complicated and I wanted to see if I could find a simple workaround to unblock my colleague so she could finish the work she was doing. I knew it was simple enough to get access to the Django database connection, so could I use that to modify the Connection.encoders field to do the right thing?

I found even this to be a bit complicated because freezegun does not export its FakeDate type at all but I was able to come up with a very hacky workaround that I wrote as a pytest fixture in our conftest.py file:

import pytest
from django.db import connection

@pytest.fixture(scope="session", autouse=True)
def fix_pymysql_freezegun_encoding(django_db_setup):
    """Work around an ordering issue with freezegun and PyMySQL's parameter encoding."""
    import freezegun
    from datetime import date as original_date, datetime as original_datetime

    date_encoder = connection.connection.encoders[original_date]
    datetime_encoder = connection.connection.encoders[original_datetime]
    with freezegun.freeze_time():
        from datetime import date, datetime

        connection.connection.encoders[date] = date_encoder
        connection.connection.encoders[datetime] = datetime_encoder

This worked, but it felt very hacky! I pushed this fix to my colleague’s branch so she could continue working and prepared to move on in life. While writing this blog post I found myself wondering if I could find a more reasonable solution. I tried various combinations of pytest hooks and still could not make things work. I was starting to doubt my own sanity! I had skimmed the Django MySQL db backend code during my initial investigations but after seeing a call to pymysql.install_as_MySQLdb() in our codebase I went back to give it another look and found this code:

from MySQLdb.converters import conversions

# ...

django_conversions = {
    **conversions,
    **{FIELD_TYPE.TIME: backend_utils.typecast_time},
}

And then a bit farther down in the file that django_conversions variable is passed in to the Connection class, overriding the default set of encoders:

class DatabaseWrapper(BaseDatabaseWrapper):
    # ...
    def get_connection_params(self):
        kwargs = {
            'conv': django_conversions,
            'charset': 'utf8',
        }
        # ...

Suddenly things made more sense! The workaround that freezegun was doing isn’t taking effect because the Django code had already made its own copy of encoders and was overriding the default! Armed with this knowledge (and this helpful StackOverflow answer on how to run a fixture before an existing fixture) I replaced the hacky fixture in our conftest.py with this pair of fixtures:

@pytest.fixture(scope="session")
def before_db_setup():
    """Ensure that freezegun's monkeypatching of PyMySQL's parameter encoding dict happens before
    the database connection is created, and also propogate it down into Django's MySQL backend."""
    # This is here because freezegun will modify pymysql.converters on import.
    import freezegun  # noqa
    import pymysql.converters
    from django.db.backends.mysql.base import django_conversions

    # django_conversions is a copy of pymysql.converters.encoders with a few additional items, so
    # copy over the entries for freezegun's types to it.
    for k, v in pymysql.converters.encoders.items():
        if k not in django_conversions:
            django_conversions[k] = v


@pytest.fixture(scope="session")
def django_db_setup(before_db_setup, django_db_setup):
    pass

This worked! I can’t say I love it but it seems better than the previous version anyway. My colleague opened an issue on the freezegun project and I added this information there so at least it’s a known quantity. I’m not sure what the right fix would be here, honestly. freezegun could certainly add a Django-specific workaround alongside its PyMySQL workaround. My gut feeling is that PyMySQL‘s implementation is brittle—any time you’re trying to match on exact types like that your code will fail if someone subclasses one of the types you do handle. I think the best fix might be to change PyMySQL’s escape_item function to use isinstance instead of looking up the type directly, like:

def escape_item(val, charset, mapping=None):
    if mapping is None:
        mapping = encoders
    for ty, encoder in mapping:
      if isinstance(val, ty):
        break
    else:
        try:
          encoder = mapping[text_type]
        except KeyError:
           raise TypeError("no default type converter defined")
    # ...

This ought to fix the problem even without freezegun‘s workaround since freezegun‘s FakeDate type is a subclass of datetime.date, so isinstance on a FakeDate object will return True when asked if it is a datetime.date. This would also future-proof against any other cases where someone has subclassed a built-in type.

If you take just one thing away from this blog post, let it be that you shouldn’t be afraid to dig in and read the source of your dependencies. We often get stuck in a mindset where we treat the libraries we use as black boxes when most of the time that’s not the case! I’ve often found myself looking at the Python source to see what exactly one of the built-in modules does. If you’re really daring you can even get all the way down and read the Linux kernel source! (It gets kind of hairy down there but it’s possible!) Don’t feel like you have to settle for working around issues in your dependencies just because you don’t know exactly where things are broken. Dig in and find out!

The logical next step here is that if you find a bug in one of your dependencies you should open a bug report for it and if possible submit a fix!