Down the debugging rabbit-hole | Gunnar Grimnes
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: BadYieldErrorWTF?
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!