Down the debugging rabbit-hole

The story of a 4 hour fun debugging adventure with pytests and tornado

We use Tornado as an async webserver for our python projects, and often pytest for testing.

The two of them come together nicely in pytest-tornado, which gives you pytest-marks for async/coroutine tests and pytest-fixtures for setting up/tearing down your application.

So, we set off to write some tests for a new project, we first added a login test:

test_login.py

@pytest.mark.gen_test
def test_login(http, login_credentials):

    r = yield http.post('/api/login', body=login_credentials)
    return = {"Cookie": str(r.headers["Set-Cookie"])}

It passes! Great!

Now, we added a test of upload a schema, the details don't matter, it posts some JSON. Since it has to login first, we reuse the login method, which already returns the cookie we need:

test_schema.py

from test.test_login import test_login

@pytest.mark.gen_test
def test_schema(http):

    headers = yield test_login(http)

    http.post('/api/schema', body=[...], headers=headers)

    [... actually test something ...]

It also works!

Next test: test_answers -- again the details don't matter, it logs in, makes some HTTP requests and tests some things.

test_answers.py

from test.test_login import test_login

@pytest.mark.gen_test
def test_schema(http):

    headers = yield test_login(http)

    http.post('/api/answers', body=[...], headers=headers)

    [... actually test something ...]

Aaaand.... it fails with:

>       yield test_login()

test_answers.py:11:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
env/lib/python3.6/site-packages/tornado/gen.py:1055: in run
    value = future.result()
env/lib/python3.6/site-packages/tornado/concurrent.py:238: in result
    raise_exc_info(self._exc_info)
<string>:4: in raise_exc_info
    ???
env/lib/python3.6/site-packages/tornado/gen.py:1143: in handle_yield
    self.future = convert_yielded(yielded)
env/lib/python3.6/functools.py:803: in wrapper
    return dispatch(args[0].__class__)(*args, **kw)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

yielded = <generator object test_login at 0x102420728>

    def convert_yielded(yielded):
        """Convert a yielded object into a `.Future`.

        The default implementation accepts lists, dictionaries, and Futures.

        If the `~functools.singledispatch` library is available, this function
        may be extended to support additional types. For example::

            @convert_yielded.register(asyncio.Future)
            def _(asyncio_future):
                return tornado.platform.asyncio.to_tornado_future(asyncio_future)

        .. versionadded:: 4.1
        """
        # Lists and dicts containing YieldPoints were handled earlier.
        if yielded is None:
            return moment
        elif isinstance(yielded, (list, dict)):
            return multi(yielded)
        elif is_future(yielded):
            return yielded
        elif isawaitable(yielded):
            return _wrap_awaitable(yielded)
        else:
>           raise BadYieldError("yielded unknown object %r" % (yielded,))
E           tornado.gen.BadYieldError: yielded unknown object <generator object test_login at 0x102420728>

env/lib/python3.6/site-packages/tornado/gen.py:1283: BadYieldError

WTF?

So there must be a stupid error, we check for typos, we go back and start copy/pasting code from the working test_schema to make sure we didn't type @pytest.mark.test_gen or something. The failure remains.

After a while we reach the state where test_schema.py and test_answer.py is byte-for-byte identical, but answers fails and schema passes. We go home and rethink our lives.

Next day, we realise that when called on just one of those files, pytest will run TWO tests, it will find the test_login through the import as well as the test in the files we invoke on. And the order will be different, it will order the file alphabetically - so in case of test_answers it will first run that test, then test_login, but for test_schema the login test will run first.

WTF?

Renaming test_answers to test_manswers (sorted after login) confirms it, it then works.

But why does the order matter? Digging a bit deeper, we see that the value returned from test_login is in both cases of type generator. But Tornado is happy with one of them, but not the other. In the convert_yielded function (which among other things lets tornado also work with await/async generators), Tornado uses inspect.isawaitable to check if the passed generator can actually be a future. This is False when the test fails.

This is the code for isawaitable:

def isawaitable(object):
    """Return true if object can be passed to an ``await`` expression."""
    return (isinstance(object, types.CoroutineType) or
            isinstance(object, types.GeneratorType) and
                bool(object.gi_code.co_flags & CO_ITERABLE_COROUTINE) or
            isinstance(object, collections.abc.Awaitable))

It's the co_flags line that causes out problem - in the working case, the flag for being an iterable coroutine is set. co_flags is pretty deep in the python internals, containing a number of flags for the interpreter (the inspect docs has the full list). Our CO_ITERABLE_COROUTINE flag was added in in PEP492, which says that:

The [types.coroutine()] function applies CO_ITERABLE_COROUTINE flag to generator- function's code object, making it return a coroutine object.

And here the rabbit hole ends! We can inspect types.coroutine:

        # Check if 'func' is a generator function.
        # (0x20 == CO_GENERATOR)
        if co_flags & 0x20:
            if func.__name__ == 'test_b':
                import ipdb; ipdb.set_trace()
            # TODO: Implement this in C.
            co = func.__code__
            func.__code__ = CodeType(
                co.co_argcount, co.co_kwonlyargcount, co.co_nlocals,
                co.co_stacksize,
                co.co_flags | 0x100,  # 0x100 == CO_ITERABLE_COROUTINE
                co.co_code,
                co.co_consts, co.co_names, co.co_varnames, co.co_filename,
                co.co_name, co.co_firstlineno, co.co_lnotab, co.co_freevars,
                co.co_cellvars)
            return func

And there the function __code__ object is modified in place, setting the flag! Setting a breakpoint there lets us see that pytest-tornado calls tornado.gen.coroutine on our function, which in turn calls types.coroutine:

    # On Python 3.5, set the coroutine flag on our generator, to allow it
    # to be used with 'await'.
    wrapped = func
    if hasattr(types, 'coroutine'):
        func = types.coroutine(func)

And this is how the test_login function only works if once called first as a pytest.

¯\_(ツ)_/¯

In the end, that's the explanation, but there is no real solution - we cannot rely on having the tests in alphabetical order, so we move the reusable code out to it's own function:

@pytest.mark.gen_test
def test_login(http, login_credentials):
    return ( yield do_login(http, login_credentials) )

@coroutine
def do_login(http, login_credentials):
    r = yield http.post('/api/login', body=login_credentials)
    return = {"Cookie": str(r.headers["Set-Cookie"])}

Then we only import the do_login function elsewhere. You were probably not meant to reuse actual test functions like this anyway.

In fact, in python2 there is no isawaitable and both tests will fail, and only in python3 do you get this weird only if in the right alphabetical order bug.

That's it! 4 hours of weirdness later. Note that normally Pytest + tornado are actually pretty good friends! Next time we'll write a blogpost about how well it works!