Machete Mode: Tags for Frames
Translation prepared as part of an online course “Python Developer. Professional“.
We also invite everyone to an open demo lesson What’s New in Python 3.10. In this webinar, we’ll talk about the most important PEPs included in the next Python 3.10 release. In particular, how the work with types will change.
Today I had to solve the riddle of Python code execution, and took advantage of the debugging trick in machete modeto figure out what’s the matter. If you have never heard this term before, I will explain that the “machete” mode is when you use a rough time code to obtain information in any way.
This is how it was. I have added a new parameterized test to the test suite coverage.py… Everything was working very slowly, so I ran it displaying the timings:
Well, oddly enough, two tests are called, but four calls to my test setup function and four to interrupt are also called. I just recently converted this set from unittest.TestCaseand I have some weird shims to reduce code churn. Thinking about re-setting, I thought that either my shims were somehow wrong, or I came across an edge scenario of how pytest runs tests.
But how do you understand why the setting is called twice each time the test is run? I decided to use a tool that I had used often in the past and write down the information I got from the stack somewhere.
def setup_test(self):
import inspect
project_home = "/Users/ned/coverage"
site_packages = ".tox/py39/lib/python3.9/site-packages/"
with open("/tmp/foo.txt", "a") as foo:
print("setup_test", file=foo)
for t in inspect.stack()[::-1]:
# t is (frame, filename, lineno, function, code_context, index)
frame, filename, lineno, function = t[:4]
filename = os.path.relpath(filename, project_home)
filename = filename.replace(site_packages, "")
show = "%30s : %s:%d" % (function, filename, lineno)
print(show, file=foo)Here is my test setup function that gets called too often. I used a low-level logging method: adding to a temporary file. For each frame in the call stack, I write the name of the function and the location where it is defined. The file paths are long and repetitive, so I make them relative and get rid of the package paths I’m using.
After running the code, I got four stack traces, one for each call to the setup. But they all turned out the same:
setup_test
<module> : igor.py:424
main : igor.py:416
do_test_with_tracer : igor.py:216
run_tests : igor.py:133
main : _pytest/config/__init__.py:84
__call__ : pluggy/hooks.py:286
_hookexec : pluggy/manager.py:93
<lambda> : pluggy/manager.py:84
_multicall : pluggy/callers.py:187
pytest_cmdline_main : _pytest/main.py:243
wrap_session : _pytest/main.py:206
_main : _pytest/main.py:250
__call__ : pluggy/hooks.py:286
_hookexec : pluggy/manager.py:93
<lambda> : pluggy/manager.py:84
_multicall : pluggy/callers.py:187
pytest_runtestloop : _pytest/main.py:271
__call__ : pluggy/hooks.py:286
_hookexec : pluggy/manager.py:93
<lambda> : pluggy/manager.py:84
_multicall : pluggy/callers.py:187
pytest_runtest_protocol : flaky/flaky_pytest_plugin.py:94
pytest_runtest_protocol : _pytest/runner.py:78
runtestprotocol : _pytest/runner.py:87
call_and_report : flaky/flaky_pytest_plugin.py:138
call_runtest_hook : _pytest/runner.py:197
from_call : _pytest/runner.py:226
<lambda> : _pytest/runner.py:198
__call__ : pluggy/hooks.py:286
_hookexec : pluggy/manager.py:93
<lambda> : pluggy/manager.py:84
_multicall : pluggy/callers.py:187
pytest_runtest_setup : _pytest/runner.py:116
prepare : _pytest/runner.py:362
setup : _pytest/python.py:1468
fillfixtures : _pytest/fixtures.py:296
_fillfixtures : _pytest/fixtures.py:469
getfixturevalue : _pytest/fixtures.py:479
_get_active_fixturedef : _pytest/fixtures.py:502
_compute_fixture_value : _pytest/fixtures.py:587
execute : _pytest/fixtures.py:894
__call__ : pluggy/hooks.py:286
_hookexec : pluggy/manager.py:93
<lambda> : pluggy/manager.py:84
_multicall : pluggy/callers.py:187
pytest_fixture_setup : _pytest/fixtures.py:936
call_fixture_func : _pytest/fixtures.py:795
connect_to_pytest : tests/mixins.py:33
setup_test : tests/test_process.py:1651I was hoping there would be slightly different traces for the first and second calls, and this difference would give me a hint. Since everything is identical in the stack, then it should be in loops. But how do you get them off the stack?
If I was familiar with the code in question, one trace could point to the right place. But pytest is not transparent to me and I didn’t want to start digging into it. I have multiple pytest functions, so it seems to be a tricky one.
The stack traces were the same as they only show the static aspects of the calls: who is calling what and where. But for specific instances of function calls, the stacks are different. The topmost block is the same (one execution of the main program), and the lowest block is variable (four executions of the test setup function). If we find the topmost frame that differs from stack to stack, we know which loop calls the setup function twice.
The first thing that came to my mind was to print the id of the frame object, but the id is reused, since the objects themselves are reused from the free memory lists. Instead, why not assign tags to them? Each frame has its own set of local variables, which are stored in a dictionary associated with the frame. In each frame, I write an integer, that is, the number of times we have seen this frame.
The frame loop will now check the local variables of each frame. If our visits are not there, then they are initialized to zero, and if there are, then they are increased by one. The number of visits is added to the stack display and we can work:
def setup_test(self):
import inspect
project_home = "/Users/ned/coverage"
site_packages = ".tox/py39/lib/python3.9/site-packages/"
with open("/tmp/foo.txt", "a") as foo:
print("setup_test", file=foo)
for t in inspect.stack()[::-1]:
# t is (frame, filename, lineno, function, code_context, index)
frame, filename, lineno, function = t[:4]
visits = frame.f_locals.get("$visits", 0) ## new
frame.f_locals["$visits"] = visits + 1 ## new
filename = os.path.relpath(filename, project_home)
filename = filename.replace(site_packages, "")
show = "%30s : %d %s:%d" % (function, visits, filename, lineno)
print(show, file=foo)Now the stacks are still the same, but the number of visits is different. Here is the stack of the second call to test setup:
setup_test
<module> : 1 igor.py:424
main : 1 igor.py:416
do_test_with_tracer : 1 igor.py:216
run_tests : 1 igor.py:133
main : 1 _pytest/config/__init__.py:84
__call__ : 1 pluggy/hooks.py:286
_hookexec : 1 pluggy/manager.py:93
<lambda> : 1 pluggy/manager.py:84
_multicall : 1 pluggy/callers.py:187
pytest_cmdline_main : 1 _pytest/main.py:243
wrap_session : 1 _pytest/main.py:206
_main : 1 _pytest/main.py:250
__call__ : 1 pluggy/hooks.py:286
_hookexec : 1 pluggy/manager.py:93
<lambda> : 1 pluggy/manager.py:84
_multicall : 1 pluggy/callers.py:187
pytest_runtestloop : 1 _pytest/main.py:271
__call__ : 1 pluggy/hooks.py:286
_hookexec : 1 pluggy/manager.py:93
<lambda> : 1 pluggy/manager.py:84
_multicall : 1 pluggy/callers.py:187
pytest_runtest_protocol : 1 flaky/flaky_pytest_plugin.py:94
pytest_runtest_protocol : 0 _pytest/runner.py:78
runtestprotocol : 0 _pytest/runner.py:87
call_and_report : 0 flaky/flaky_pytest_plugin.py:138
call_runtest_hook : 0 _pytest/runner.py:197
from_call : 0 _pytest/runner.py:226
<lambda> : 0 _pytest/runner.py:198
__call__ : 0 pluggy/hooks.py:286
_hookexec : 0 pluggy/manager.py:93
<lambda> : 0 pluggy/manager.py:84
_multicall : 0 pluggy/callers.py:187
pytest_runtest_setup : 0 _pytest/runner.py:116
prepare : 0 _pytest/runner.py:362
setup : 0 _pytest/python.py:1468
fillfixtures : 0 _pytest/fixtures.py:296
_fillfixtures : 0 _pytest/fixtures.py:469
getfixturevalue : 0 _pytest/fixtures.py:479
_get_active_fixturedef : 0 _pytest/fixtures.py:502
_compute_fixture_value : 0 _pytest/fixtures.py:587
execute : 0 _pytest/fixtures.py:894
__call__ : 0 pluggy/hooks.py:286
_hookexec : 0 pluggy/manager.py:93
<lambda> : 0 pluggy/manager.py:84
_multicall : 0 pluggy/callers.py:187
pytest_fixture_setup : 0 _pytest/fixtures.py:936
call_fixture_func : 0 _pytest/fixtures.py:795
connect_to_pytest : 0 tests/mixins.py:33
setup_test : 0 tests/test_process.py:1651Ones are frames that did not change from the first to the second call, and zeros are new frames. And now we see that in flaky_pytest_plugin.py there is a loop that calls the setting a second time.
Standard situation: as soon as you find the answer, everything becomes obvious. I am using the pytest-flaky plugin to automatically repeat tests that fail. My new slow test is not just slow, it still fails (at the moment), so pytest-flaky runs it again.
The real mystery was not why the setting was called twice, but why the test was run once. I checked: not only did the setup run twice, the body of the test was run twice as well.
When the test succeeded, the execution disappeared twice as pytest-flaky did not restart it.
Here comes the classic debugging story in machete mode, that is, problems were easier to catch with dynamic tools rather than static ones. I broke some crude code to get the information I wanted, not knowing if it would work, but it did.
By the way, it may be silly to put this column in the display, but this is an easy way to see the cyclical nature of test execution. Here’s the fourth call stack:
setup_test
<module> : 3 igor.py:424
main : 3 igor.py:416
do_test_with_tracer : 3 igor.py:216
run_tests : 3 igor.py:133
main : 3 _pytest/config/__init__.py:84
__call__ : 3 pluggy/hooks.py:286
_hookexec : 3 pluggy/manager.py:93
<lambda> : 3 pluggy/manager.py:84
_multicall : 3 pluggy/callers.py:187
pytest_cmdline_main : 3 _pytest/main.py:243
wrap_session : 3 _pytest/main.py:206
_main : 3 _pytest/main.py:250
__call__ : 3 pluggy/hooks.py:286
_hookexec : 3 pluggy/manager.py:93
<lambda> : 3 pluggy/manager.py:84
_multicall : 3 pluggy/callers.py:187
pytest_runtestloop : 3 _pytest/main.py:271
__call__ : 1 pluggy/hooks.py:286
_hookexec : 1 pluggy/manager.py:93
<lambda> : 1 pluggy/manager.py:84
_multicall : 1 pluggy/callers.py:187
pytest_runtest_protocol : 1 flaky/flaky_pytest_plugin.py:94
pytest_runtest_protocol : 0 _pytest/runner.py:78
runtestprotocol : 0 _pytest/runner.py:87
call_and_report : 0 flaky/flaky_pytest_plugin.py:138
call_runtest_hook : 0 _pytest/runner.py:197
from_call : 0 _pytest/runner.py:226
<lambda> : 0 _pytest/runner.py:198
__call__ : 0 pluggy/hooks.py:286
_hookexec : 0 pluggy/manager.py:93
<lambda> : 0 pluggy/manager.py:84
_multicall : 0 pluggy/callers.py:187
pytest_runtest_setup : 0 _pytest/runner.py:116
prepare : 0 _pytest/runner.py:362
setup : 0 _pytest/python.py:1468
fillfixtures : 0 _pytest/fixtures.py:296
_fillfixtures : 0 _pytest/fixtures.py:469
getfixturevalue : 0 _pytest/fixtures.py:479
_get_active_fixturedef : 0 _pytest/fixtures.py:502
_compute_fixture_value : 0 _pytest/fixtures.py:587
execute : 0 _pytest/fixtures.py:894
__call__ : 0 pluggy/hooks.py:286
_hookexec : 0 pluggy/manager.py:93
<lambda> : 0 pluggy/manager.py:84
_multicall : 0 pluggy/callers.py:187
pytest_fixture_setup : 0 _pytest/fixtures.py:936
call_fixture_func : 0 _pytest/fixtures.py:795
connect_to_pytest : 0 tests/mixins.py:33
setup_test : 0 tests/test_process.py:1651Threes change to ones in _pytest/main.py:271, that is, in a test run loop, which is cool!
Learn more about the course “Python Developer. Professional“
Watch the webinar What’s New in Python 3.10
