How to Debug a Hanging Test Using pytest

Bob, Wed 18 March 2020, Testing

APIs, debugging, learning, pip, pytest, pytest-timeout, requests, testing, time, tricks

Today a wanted to share a neat trick that might save you some headache: debugging a hanging test.

Setup

Let's write some really simple (contrived) code to test:

from time import sleep

def call_api():
    return dict(
        status=200,
        response=[1, 2, 3])


def sum_numbers(numbers):
    return sum(numbers)

And some test code to test it:

from script import sum_numbers, call_api


def test_sum_numbers():
    assert sum_numbers([1, 2, 3]) == 6
    assert sum_numbers([4, 5]) == 9


def test_call_api():
    resp = call_api()
    assert resp['status'] == 200
    assert resp['response'] == [1, 2, 3]

Run pytest and: 2 passed in 0.03s - all good.

Now let's emulate a hanging test by adding a sleep of 60 seconds in call_api

Oops:

(venv) [[email protected] test-debug]$ pytest
===================================================================== test session starts ======================================================================
platform darwin -- Python 3.8.0, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /Users/bobbelderbos/code/test-debug
plugins: timeout-1.3.4
collected 2 items

test_script.py . (hangs here)

Eventually you'll get there (2 passed in 60.06s (0:01:00)), but this might be far worse.

Even with 1 or 2 minutes delay, you need to fix it. Tests need to be fast, because you will constantly run them to refactor and adding new features.

Debugging timeouts

I discovered a neat plugin for this: pytest-timeout. With your virtualenv enabled:

pip install pytest-timeout

Let's use it:

(venv) [[email protected] test-debug]$ pytest --timeout=3
test_script.py .F                                                                                                                                        [100%]

=========================================================================== FAILURES ===========================================================================
________________________________________________________________________ test_call_api _________________________________________________________________________

def test_call_api():
>       resp = call_api()

test_script.py:10:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

def call_api():
>       sleep(60)
E       Failed: Timeout >3.0s

script.py:5: Failed
=================================================================== short test summary info ====================================================================
FAILED test_script.py::test_call_api - Failed: Timeout >3.0s
================================================================= 1 failed, 1 passed in 3.07s

How cool is that, no?

A more complex use case

What if the bug is in some external module though?

Here I pulled a fork of requests and:

And ... boom!

(venv) [[email protected] test-debug]$ pytest --timeout=3
===================================================================== test session starts ======================================================================
platform darwin -- Python 3.8.0, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /Users/bobbelderbos/code/test-debug
plugins: timeout-1.3.4
timeout: 3.0s
timeout method: signal
timeout func_only: False
collected 2 items

test_script.py .F                                                                                                                                        [100%]

=========================================================================== FAILURES ===========================================================================
________________________________________________________________________ test_call_api _________________________________________________________________________

    def test_call_api():
>       resp = call_api()

test_script.py:10:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
script.py:5: in call_api
    requests.get('https://pybit.es')
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

url = 'https://pybit.es', params = None, kwargs = {}

    def get(url, params=None, **kwargs):
        r"""Sends a GET request.

        :param url: URL for the new :class:`Request` object.
        :param params: (optional) Dictionary or bytes to be sent in the query string for the :class:`Request`.
        :param \*\*kwargs: Optional arguments that ``request`` takes.
        :return: :class:`Response <Response>` object
        :rtype: requests.Response
        """
>       time.sleep(60)
E       Failed: Timeout >3.0s

Getting more debug info

What if the failing code is more layers down?

Sometimes the issue is really nested and pytest-timeout might not be that smart.

In that case you can swap the default signal of the --timeout_method flag for thread and it will dump a complete stacktrace!

This can be very useful for debugging:

(venv) [[email protected] test-debug]$ pytest --timeout=3 --timeout_method=thread
===================================================================== test session starts ======================================================================
platform darwin -- Python 3.8.0, pytest-5.4.1, py-1.8.1, pluggy-0.13.1
rootdir: /Users/bobbelderbos/code/test-debug
plugins: timeout-1.3.4
timeout: 3.0s
timeout method: thread <== using "thread now"
timeout func_only: False
collected 2 items

test_script.py .
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (4523748800) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
...
many calls
...

File "/Users/bobbelderbos/code/test-debug/venv/lib/python3.8/site-packages/_pytest/python.py", line 184, in pytest_pyfunc_call
    result = testfunction(**testargs)
File "/Users/bobbelderbos/code/test-debug/test_script.py", line 10, in test_call_api
    resp = call_api()
File "/Users/bobbelderbos/code/test-debug/script.py", line 5, in call_api
    requests.get('https://pybit.es')
File "/Users/bobbelderbos/Downloads/requests.org/requests/api.py", line 71, in get <== external module
    time.sleep(60)

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
(venv) [[email protected] test-debug]$

Really cool stuff.

I hope this is useful. Comment below next time this saves you some debugging time ...


Keep Calm and Code in Python!

-- Bob