Debugging guide
It’s just too easy to make errors. Sometimes, it’s not obvious to understand the behavior of pytest-dependency: test get skipped although their dependencies succeed or the other way round, the dependency marker does not seem have any effect and tests are executed although their dependency fail.
This section intends to give an overview of the tools that pytest provides to investigate the situation in detail, which hopefully helps to understand what happens.
Example
We consider the following example in this guide:
from enum import Enum
import pytest
class Color(Enum):
RED = 1
GREEN = 2
BLUE = 3
def __str__(self):
return self.name
def get_starship(name):
fleet = pytest.importorskip("fleet")
return fleet.get_ship(name)
@pytest.fixture(scope="module", params=range(2))
def prepenv(request):
pass
@pytest.mark.dependency()
@pytest.mark.xfail(reason="deliberate fail")
def test_a():
assert False
@pytest.mark.dependency()
def test_b():
pass
@pytest.mark.dependency(depends=["test_a"])
def test_c():
pass
@pytest.mark.dependency(depends=["test_b"])
def test_d():
pass
@pytest.mark.dependency(depends=["test_b", "test_c"])
def test_e():
pass
class TestClass(object):
@pytest.mark.dependency()
def test_a(self):
pass
@pytest.mark.dependency()
@pytest.mark.xfail(reason="deliberate fail")
def test_b(self):
assert False
@pytest.mark.dependency(depends=["test_b"])
def test_c(self):
pass
@pytest.mark.dependency()
@pytest.mark.parametrize("c", [ Color.RED, Color.GREEN, Color.BLUE, ])
def test_colors(c):
pass
@pytest.mark.dependency(depends=["test_colors"])
def test_multicolored():
pass
@pytest.mark.dependency(depends=["test_colors[Color.RED]"])
def test_alert():
pass
@pytest.mark.dependency(depends=["test_f"])
def test_g():
pass
@pytest.mark.dependency(name="h")
def test_h():
pass
@pytest.mark.dependency(depends=["test_b"])
def test_k():
s = get_starship("NCC-1701")
@pytest.mark.dependency()
def test_l(prepenv):
pass
@pytest.mark.dependency(depends=["test_b"], scope='session')
def test_m():
pass
@pytest.mark.dependency(depends=["test_h"])
def test_o():
pass
@pytest.mark.dependency()
def test_p():
pass
@pytest.mark.dependency(depends=["test_p"])
def test_q(prepenv):
pass
@pytest.mark.dependency(depends=["test_a"])
@pytest.mark.dependency(name="r")
def test_r():
pass
@pytest.mark.dependency(depends=["test_l"])
def test_s():
pass
This example contains several cases where the presumably intended behavior of the code differs from what happens in practice. We will show below how diagnostic tools in pytest may be used to unravel the discrepancies. The results that may (or may not) be surprising include:
The test method test_c in class TestClass depending on test_b is run, although the test method test_b fails.
All instances of test_colors succeed. Yet test_multicolored that only depends on test_colors is skipped.
Similarly test_alert depending only on test_colors[Color.RED] is skipped, although test_colors with the parameter value Color.RED succeeds.
test_k depending only on test_b is skipped, although test_b succeeds.
Same with test_m depending only on test_b is skipped.
test_o depending only on test_h is skipped, although test_h succeeds.
test_q depending only on test_p is skipped, although test_p succeeds.
test_r is run, although test_a fails.
test_s depending only on test_l is skipped, although test_l succeeds.
Diagnostic tools
There are different ways to request diagnostic output from pytest. We will discuss how they may be used to better understand the behavior of pytest-dependency.
pytest summary
You can request a short summary from pytest including information on
skipped tests using the -rs command line option:
$ pytest -rs debugging.py
============================= test session starts ==============================
platform linux -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/user
plugins: dependency-0.6.0
collected 25 items
debugging.py x.s.s.x....sss.s.s.sss..s [100%]
=========================== short test summary info ============================
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_c depends on test_a
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_e depends on test_c
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_multicolored depends on test_colors
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_alert depends on test_colors[Color.RED]
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_g depends on test_f
SKIPPED [1] debugging.py:15: could not import 'fleet': No module named 'fleet'
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_q[0] depends on test_p
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_q[1] depends on test_p
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_m depends on test_b
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_o depends on test_h
SKIPPED [1] /usr/lib/python3.10/site-packages/pytest_dependency.py:101: test_s depends on test_l
================== 12 passed, 11 skipped, 2 xfailed in 0.05s ===================
This summary indicates if a test has been skipped by pytest-dependency in the first place. In the present example, the summary hints that test_k has been skipped due to another reason, unrelated to pytest-dependency. If the test has been skipped by pytest-dependency, the summary displays the name of the missing dependency.
Verbose pytest output
A list of all tests with their respective outcome will be displayed if
you call pytest with the --verbose command line option:
$ pytest --verbose debugging.py
============================= test session starts ==============================
platform linux -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /home/user
plugins: dependency-0.6.0
collecting ... collected 25 items
debugging.py::test_a XFAIL (deliberate fail) [ 4%]
debugging.py::test_b PASSED [ 8%]
debugging.py::test_c SKIPPED (test_c depends on test_a) [ 12%]
debugging.py::test_d PASSED [ 16%]
debugging.py::test_e SKIPPED (test_e depends on test_c) [ 20%]
debugging.py::TestClass::test_a PASSED [ 24%]
debugging.py::TestClass::test_b XFAIL (deliberate fail) [ 28%]
debugging.py::TestClass::test_c PASSED [ 32%]
debugging.py::test_colors[RED] PASSED [ 36%]
debugging.py::test_colors[GREEN] PASSED [ 40%]
debugging.py::test_colors[BLUE] PASSED [ 44%]
debugging.py::test_multicolored SKIPPED (test_multicolored depends o...) [ 48%]
debugging.py::test_alert SKIPPED (test_alert depends on test_colors[...) [ 52%]
debugging.py::test_g SKIPPED (test_g depends on test_f) [ 56%]
debugging.py::test_h PASSED [ 60%]
debugging.py::test_k SKIPPED (could not import 'fleet': No module na...) [ 64%]
debugging.py::test_l[0] PASSED [ 68%]
debugging.py::test_q[0] SKIPPED (test_q[0] depends on test_p) [ 72%]
debugging.py::test_l[1] PASSED [ 76%]
debugging.py::test_q[1] SKIPPED (test_q[1] depends on test_p) [ 80%]
debugging.py::test_m SKIPPED (test_m depends on test_b) [ 84%]
debugging.py::test_o SKIPPED (test_o depends on test_h) [ 88%]
debugging.py::test_p PASSED [ 92%]
debugging.py::test_r PASSED [ 96%]
debugging.py::test_s SKIPPED (test_s depends on test_l) [100%]
================== 12 passed, 11 skipped, 2 xfailed in 0.06s ===================
The verbose listing is particular useful, because it shows the pytest node id for each test, which is not always obvious. As explained in Section Names, this node id is the basis to form the default test name that need to be used to reference the test in the dependencies.
From this list we can understand why test_multicolored has been skipped: it depends on test_colors. But test_colors is parametrized and thus the parameter value is included in the node id. As a result, a dependency by the name test_colors can not be found. The same thing happens in the case of test_s: it depends on test_l, but the latter uses a parametrized fixture, so it indirectly takes a parameter value and that value must be included in the reference for the dependency.
In the case of test_alert, the parameter value is included in the dependency test_colors[Color.RED]. But in the node id as displayed in the verbose list, that test appears as test_colors[RED]. Note that class Color overrides the string representation operator and that affects how the parameter value appears in the node id in this case.
The verbose list also displays the execution order of the tests. In the present example, this order differs from the order in the source code. That is the reason why both instances of test_q are skipped: they are executed before the dependency test_p. So the outcome of the latter is yet unknown at the moment that the dependency is checked.
Logging
pytest-dependency emits log messages when registering test results and when checking dependencies for a test. You can request these log messages to be displayed at runtime using log command line options in the pytest call. Beware that this may produce a large amount of output, even for medium size test suites. We will present only a few fragments of the output here. Consider the start of that output, covering the first test test_a:
$ pytest --log-cli-format='%(levelname)s: %(message)s' --log-cli-level=DEBUG debugging.py
============================= test session starts ==============================
platform linux -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/user
plugins: dependency-0.6.0
collected 25 items
debugging.py::test_a
-------------------------------- live log setup --------------------------------
DEBUG: register setup debugging.py::test_a passed in session scope
DEBUG: register setup test_a passed in module scope
-------------------------------- live log call ---------------------------------
DEBUG: register call debugging.py::test_a skipped in session scope
DEBUG: register call test_a skipped in module scope
XFAIL (deliberate fail) [ 4%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::test_a passed in session scope
DEBUG: register teardown test_a passed in module scope
It is shown how the test outcome for each of the three test phases (setup, call, and teardown) is registered in pytest-dependency. It is also shown which name is used to register the test outcome depending on the scope.
Considering the relevant fragments of the output, we can check why TestClass::test_c is not skipped:
debugging.py::test_b
-------------------------------- live log setup --------------------------------
DEBUG: register setup debugging.py::test_b passed in session scope
DEBUG: register setup test_b passed in module scope
-------------------------------- live log call ---------------------------------
DEBUG: register call debugging.py::test_b passed in session scope
DEBUG: register call test_b passed in module scope
PASSED [ 8%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::test_b passed in session scope
DEBUG: register teardown test_b passed in module scope
debugging.py::TestClass::test_b
-------------------------------- live log setup --------------------------------
DEBUG: register setup debugging.py::TestClass::test_b passed in session scope
DEBUG: register setup TestClass::test_b passed in module scope
DEBUG: register setup test_b passed in class scope
-------------------------------- live log call ---------------------------------
DEBUG: register call debugging.py::TestClass::test_b skipped in session scope
DEBUG: register call TestClass::test_b skipped in module scope
DEBUG: register call test_b skipped in class scope
XFAIL (deliberate fail) [ 28%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::TestClass::test_b passed in session scope
DEBUG: register teardown TestClass::test_b passed in module scope
DEBUG: register teardown test_b passed in class scope
debugging.py::TestClass::test_c
-------------------------------- live log setup --------------------------------
DEBUG: check dependencies of test_c in module scope ...
DEBUG: ... test_b succeeded
DEBUG: register setup debugging.py::TestClass::test_c passed in session scope
DEBUG: register setup TestClass::test_c passed in module scope
DEBUG: register setup test_c passed in class scope
-------------------------------- live log call ---------------------------------
DEBUG: register call debugging.py::TestClass::test_c passed in session scope
DEBUG: register call TestClass::test_c passed in module scope
DEBUG: register call test_c passed in class scope
PASSED [ 32%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::TestClass::test_c passed in session scope
DEBUG: register teardown TestClass::test_c passed in module scope
DEBUG: register teardown test_c passed in class scope
The dependency test_b is checked in module scope. If that dependency was meant to reference the method of the same class, it would either need to be referenced as test_b in class scope or as TestClass::test_b in module scope or as debugging.py::TestClass::test_b in session scope. The way it is formulated in the example, it actually references the test function test_b, which succeeds.
A similar case is test_m:
debugging.py::test_b
-------------------------------- live log setup --------------------------------
DEBUG: register setup debugging.py::test_b passed in session scope
DEBUG: register setup test_b passed in module scope
-------------------------------- live log call ---------------------------------
DEBUG: register call debugging.py::test_b passed in session scope
DEBUG: register call test_b passed in module scope
PASSED [ 8%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::test_b passed in session scope
DEBUG: register teardown test_b passed in module scope
debugging.py::test_m
-------------------------------- live log setup --------------------------------
DEBUG: check dependencies of test_m in session scope ...
DEBUG: ... test_b is unknown
INFO: skip test_m because it depends on test_b
DEBUG: register setup debugging.py::test_m skipped in session scope
DEBUG: register setup test_m skipped in module scope
SKIPPED (test_m depends on test_b) [ 84%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::test_m passed in session scope
DEBUG: register teardown test_m passed in module scope
The dependency test_b is checked in session scope. There is no test that matches this name. If that dependency was mean to reference the test function test_b in the example, it would either need to be referenced as debugging.py::test_b in session scope or as test_b in module scope.
A slightly different situation is given in the case of test_o:
debugging.py::test_h
-------------------------------- live log setup --------------------------------
DEBUG: register setup h passed in session scope
DEBUG: register setup h passed in module scope
-------------------------------- live log call ---------------------------------
DEBUG: register call h passed in session scope
DEBUG: register call h passed in module scope
PASSED [ 60%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown h passed in session scope
DEBUG: register teardown h passed in module scope
debugging.py::test_o
-------------------------------- live log setup --------------------------------
DEBUG: check dependencies of test_o in module scope ...
DEBUG: ... test_h is unknown
INFO: skip test_o because it depends on test_h
DEBUG: register setup debugging.py::test_o skipped in session scope
DEBUG: register setup test_o skipped in module scope
SKIPPED (test_o depends on test_h) [ 88%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown debugging.py::test_o passed in session scope
DEBUG: register teardown test_o passed in module scope
In the pytest.mark.dependency() marker for test_h in the
example, the name is overridden as h. The outcome of that test is
registered using that name. It can thus not be found by the name
test_h.
Considering the case of test_r:
debugging.py::test_r
-------------------------------- live log setup --------------------------------
DEBUG: register setup r passed in session scope
DEBUG: register setup r passed in module scope
-------------------------------- live log call ---------------------------------
DEBUG: register call r passed in session scope
DEBUG: register call r passed in module scope
PASSED [ 96%]
------------------------------ live log teardown -------------------------------
DEBUG: register teardown r passed in session scope
DEBUG: register teardown r passed in module scope
That test has no dependencies. The error in the example is that the
pytest.mark.dependency() marker is applied twice to the test.
That doesn’t work in pytest, only the last invocation is effective.
As a result, the second invocation setting a name, effectively clears
the dependency list that was set in the first invocation.