Asserting pytest log output makes it hard to diagnose errors #1085

New issue

Open

opened 2025-12-26 16:58:19 +00:00 by ma27 · 2 comments

ma27 commented

2025-12-26 16:58:19 +00:00

Member

Describe the bug

Given the following error in CI: https://buildkite.com/lix-project/lix/builds/7221#019b4856-8559-45ac-a8a0-f13c59ce4fc0
The failure was a mistake on my side in https://gerrit.lix.systems/c/lix/+/4796?tab=checks

However, it seems unnecessarily painful to investigate assertion errors like

lix> E       assert 'test_eval[subset:matrix] PASSED' in "============================= test session starts ==============================\nplatform darwin -- Python 3.13.9, pytest-8.4.2, pluggy-1.6.0\nrootdir: /nix/var/nix/builds/nix-build-lix-2.95.0pre20251222-dev_95a5e53.drv-0/b/pytest-of-_nixbld1/pytest-0/popen-gw6/test_toml_matrix_subset_files00/test-home/functional2\nconfigfile: pyproject.toml\nplugins: xdist-3.8.0, timeout-2.4.0\ncollected 7 items\n\nlang/test_lang.py::test_parser[NOTSET] SKIPPED (got empty parameter ...) [ 14%]\nlang/test_lang.py::test_xfail_parser[NOTSET] SKIPPED (got empty para...) [ 28%]\nlang/test_lang.py::test_eval[subset:matrix] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED                                                                   [ 42%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_eval[subset:matrix-hello] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED                                                                   [ 57%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_eval[subset:eval-okay-1] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED                                                                   [ 71%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_xfail_eval[NOTSET] SKIPPED (got empty parame...) [ 85%]\nlang/test_lang.py::test_invalid_configuration[NOTSET] SKIPPED (got e...) [100%]\n\n========================= 3 passed, 4 skipped in 0.51s ========================="

especially given that pytest tries very hard to make assertion errors understandable.

It's also debatable whether this should fail in this case: the test still passed, however a warning was logged before reporting the test to be passed, so strictly speaking, the test-case failed even though the code is valid (and the problem lies somewhere else). If we want to prevent None in the env, we should fail hard one place or another.

Additionally, I question that the output from pytest is supposed to be machine-readable and thus sufficiently stable.

Steps To Reproduce

n/a

Expected behavior

Use something like https://docs.pytest.org/en/7.1.x/how-to/output.html#creating-junitxml-format-files as format to parse when having to assert if a pytest test passed (assuming that this is a legit use-case as we're testing a test library here).

`nix --version` output

Observable on 4d67200b80.

Additional context

cc @commentatorforall

## Describe the bug Given the following error in CI: https://buildkite.com/lix-project/lix/builds/7221#019b4856-8559-45ac-a8a0-f13c59ce4fc0 The failure was a mistake on my side in https://gerrit.lix.systems/c/lix/+/4796?tab=checks However, it seems unnecessarily painful to investigate assertion errors like ``` lix> E assert 'test_eval[subset:matrix] PASSED' in "============================= test session starts ==============================\nplatform darwin -- Python 3.13.9, pytest-8.4.2, pluggy-1.6.0\nrootdir: /nix/var/nix/builds/nix-build-lix-2.95.0pre20251222-dev_95a5e53.drv-0/b/pytest-of-_nixbld1/pytest-0/popen-gw6/test_toml_matrix_subset_files00/test-home/functional2\nconfigfile: pyproject.toml\nplugins: xdist-3.8.0, timeout-2.4.0\ncollected 7 items\n\nlang/test_lang.py::test_parser[NOTSET] SKIPPED (got empty parameter ...) [ 14%]\nlang/test_lang.py::test_xfail_parser[NOTSET] SKIPPED (got empty para...) [ 28%]\nlang/test_lang.py::test_eval[subset:matrix] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED [ 42%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_eval[subset:matrix-hello] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:00Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED [ 57%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_eval[subset:eval-okay-1] \n-------------------------------- live log call ---------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\nPASSED [ 71%]\n------------------------------ live log teardown -------------------------------\n2025-12-23T01:35:01Z [ WARNING] [functional2.testlib.fixtures.env] environment variable 'BUILD_TEST_ENV' is none\n\nlang/test_lang.py::test_xfail_eval[NOTSET] SKIPPED (got empty parame...) [ 85%]\nlang/test_lang.py::test_invalid_configuration[NOTSET] SKIPPED (got e...) [100%]\n\n========================= 3 passed, 4 skipped in 0.51s =========================" ``` especially given that pytest tries very hard to make assertion errors understandable. It's also debatable whether this should fail in this case: the test still passed, however a warning was logged before reporting the test to be passed, so strictly speaking, the test-case failed even though the code is valid (and the problem lies somewhere else). If we want to prevent `None` in the env, we should fail hard one place or another. Additionally, I question that the output from pytest is supposed to be machine-readable and thus sufficiently stable. ## Steps To Reproduce n/a ## Expected behavior Use something like https://docs.pytest.org/en/7.1.x/how-to/output.html#creating-junitxml-format-files as format to parse when having to assert if a pytest test passed (assuming that this is a legit use-case as we're testing a test library here). ## `nix --version` output Observable on 4d67200b802b90b54c97e4be92a8f78282fcac4e. ## Additional context cc @commentatorforall

ma27 added the

bug

testing

labels

2025-12-26 16:58:19 +00:00

commentatorforall added this to the functional2 project

2025-12-26 17:59:05 +00:00

commentatorforall commented

2025-12-26 18:04:12 +00:00

Member

.... i see the frustration and unreadability.
No, the current output is not supposed to be machine readable, but human readable.
In the future, we want to use pytest-tap to make things machine readable and also integrate it into meson better, but there's an open meson bug preventing us from doing so. While yes, the test should technically have passed, imo it still shouldn't as it not throws a new warning it previously didn't => unintentional change => either update the exected output or fix the warning

.... i see the frustration and unreadability. No, the current output is *not* supposed to be machine readable, but human readable. In the future, we want to use pytest-tap to make things machine readable and also integrate it into meson better, but there's an open meson bug preventing us from doing so. While yes, the test should technically have passed, imo it still shouldn't as it not throws a new warning it previously didn't => unintentional change => either update the exected output or fix the warning

commentatorforall commented

2025-12-26 18:09:41 +00:00

Member

potentially won't-fix or status/blocked as otoh this is kinda intended as-is, but would be fixed if we could use pytest-tap instead (which is blocked on the upstream meson issue which has been open for three years, with a poke last year

potentially won't-fix or status/blocked as otoh this is kinda intended as-is, but would be fixed if we could use pytest-tap instead (which is blocked on the [upstream meson issue](https://github.com/mesonbuild/meson/issues/11185) which has been open for three years, with a poke last year