Pytest gives exit code 127

[khaeru]

I have a step in a GitHub Actions CI job that has a single invocation of pytest, like so:

    - name: Run test suite using pytest
      env:
        # For test_cli.test_dl; see code in message_ix.cli.dl
        GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }}
      working-directory: message_ix
      run: |
        pytest message_ix -m "not nightly" -rA --verbose --cov-report=xml --color=yes
      shell: bash

Pytest runs successfully, and all tests pass (see here):

…
XFAIL message_ix/tests/test_core.py::test_add_horizon[args7-kwargs7-None]
XFAIL message_ix/tests/test_core.py::test_add_horizon[args8-kwargs8-None]
==== 113 passed, 2 deselected, 5 xfailed, 4 warnings in 509.99s (0:08:29) =====

However, the overall CI step and job fails, because pytest is apparently returning exit code 127—which, according to the docs, should never happen.

Further information:

• This occurs only on Windows Server 2019 job runners; not on (Ubuntu) Linux or macOS.
• I experimented with modifying the line like so:

      run: |
        pytest message_ix -m "not nightly" -rA --verbose --cov-report=xml --color=yes || echo "Spurious exit code $? from pytest"

  …and indeed the message "Spurious exit code 127 from pytest" is printed.
• In bash, exit code 127 is for a command not found; but the only command here is pytest, which is clearly found, because it runs.
• I wonder if this may be something in the tests that I am running that somehow "leaks through" pytest; but I am at a total loss as to how to identify and debug that.

Output of `pip list`, including pytest

From https://github.com/iiasa/message_ix/pull/453/checks?check_run_id=2253546265#step:17

Package                       Version
----------------------------- --------------------
alabaster                     0.7.12
argon2-cffi                   20.1.0
async-generator               1.10
asyncssh                      2.5.0
atomicwrites                  1.4.0
attrs                         20.3.0
Babel                         2.9.0
backcall                      0.2.0
bleach                        3.3.0
certifi                       2020.12.5
cffi                          1.14.5
chardet                       4.0.0
click                         7.1.2
cloudpickle                   1.6.0
colorama                      0.4.4
coverage                      5.5
cryptography                  3.4.7
cycler                        0.10.0
dask                          2021.3.1
decorator                     5.0.1
defusedxml                    0.7.1
descartes                     1.1.0
docutils                      0.16
entrypoints                   0.3
et-xmlfile                    1.0.1
fsspec                        0.8.7
genno                         1.3.0
iam-units                     2021.3.22
idna                          2.10
imagesize                     1.2.0
iniconfig                     1.1.1
ipykernel                     5.5.3
ipython                       7.22.0
ipython-genutils              0.2.0
ipywidgets                    7.6.3
ixmp                          3.2.1.dev71+g33404fd
jedi                          0.18.0
Jinja2                        2.11.3
JPype1                        1.2.1
jsonschema                    3.2.0
jupyter                       1.0.0
jupyter-client                6.1.12
jupyter-console               6.4.0
jupyter-core                  4.7.1
jupyterlab-pygments           0.1.2
jupyterlab-widgets            1.0.0
kiwisolver                    1.3.1
latexcodec                    2.0.1
llvmlite                      0.36.0
locket                        0.2.1
MarkupSafe                    1.1.1
matplotlib                    3.4.1
message-ix                    3.2.1.dev49+gbe45b14
mistune                       0.8.4
mizani                        0.7.3
nbclient                      0.5.3
nbconvert                     6.0.7
nbformat                      5.1.3
nest-asyncio                  1.5.1
notebook                      6.3.0
numba                         0.53.1
numpy                         1.20.2
numpydoc                      1.1.0
openpyxl                      3.0.7
packaging                     20.9
palettable                    3.3.0
pandas                        1.2.3
pandocfilters                 1.4.3
parso                         0.8.2
partd                         1.1.0
patsy                         0.5.1
pickleshare                   0.7.5
Pillow                        8.2.0
Pint                          0.17
pip                           21.0.1
plotly                        4.14.3
plotnine                      0.8.0
pluggy                        0.13.1
prometheus-client             0.9.0
prompt-toolkit                3.0.18
py                            1.10.0
pyam-iamc                     0.10.0
pybtex                        0.24.0
pybtex-docutils               1.0.0
pycparser                     2.20
Pygments                      2.8.1
pyparsing                     2.4.7
pyrsistent                    0.17.3
pytest                        6.2.2
pytest-cov                    2.11.1
python-dateutil               2.8.1
pytz                          2021.1
pywin32                       300
pywinpty                      0.5.7
PyYAML                        5.4.1
pyzmq                         22.0.3
qtconsole                     5.0.3
QtPy                          1.9.0
requests                      2.25.1
retrying                      1.3.3
scipy                         1.6.2
seaborn                       0.11.1
Send2Trash                    1.5.0
setuptools                    49.2.1
setuptools-scm                6.0.1
six                           1.15.0
snowballstemmer               2.1.0
sparse                        0.12.0
Sphinx                        3.5.3
sphinx-rtd-theme              0.5.1
sphinxcontrib-applehelp       1.0.2
sphinxcontrib-bibtex          2.2.0
sphinxcontrib-devhelp         1.0.2
sphinxcontrib-htmlhelp        1.0.3
sphinxcontrib-jsmath          1.0.1
sphinxcontrib-qthelp          1.0.3
sphinxcontrib-serializinghtml 1.1.4
statsmodels                   0.12.2
terminado                     0.9.4
testpath                      0.4.4
toml                          0.10.2
toolz                         0.11.1
tornado                       6.1
traitlets                     5.0.5
urllib3                       1.26.4
wcwidth                       0.2.5
webencodings                  0.5.1
wheel                         0.36.2
widgetsnbextension            3.5.1
xarray                        0.17.0
xlrd                          1.2.0

[asottile]

maybe try debugging where the exit is coming from?

import sys
import pytest
import traceback
try:
    pytest.main(sys.argv[1:])
except BaseException:
    traceback.print_exc()
    raise

[khaeru]

Excellent, thanks. I'll try that and report back.

[khaeru]

Tried the following:

1. Saved the code above as debug.py, and changed the workflow line invoking it to:

     run: |
       python debug.py message_ix -m "not nightly" -rA --verbose --color=yes || echo "Spurious exit code $? from pytest"

   Result: the same—all tests complete, "Spurious exit code 127 from pytest". It seems that the except BaseException: block does not run. See https://github.com/iiasa/message_ix/runs/2259199425#step:18:5791
2. Added sys.exit(0) at the end of the script.
   Result: the same; see https://github.com/iiasa/message_ix/runs/2259273012#step:18:5791
3. Added instead os._exit(0) at the end of the script.
   Result: see https://github.com/iiasa/message_ix/runs/2259331033#step:18:5784
   • Seems that some of the final lines ("PASSED", "XFAIL", etc.) are not flushed to stdout.
   • The summary/conclusion line from pytest ("==== 113 passed, 2 deselected, 5 xfailed, 4 warnings …") is also not printed.
   • "Spurious exit code…" etc. does not appear, so the script actually has exited with 0.

Comparing (2) and (3), it seems that something between sys.exit() (higher-level) and os._exit() (lower-level) is calling the latter with code 127 rather than 0—or something like that?

I don't know much about these internals of Python, or of pytest—are things inserted there that might have such an effect?

[asottile]

my guess then is segmentation fault in some teardown? -- what happens if you don't use bash for windows (often you'll get a better error message from cmd.exe or at least an exit code that's googleable)

[khaeru]

what happens if you don't use bash for windows (often you'll get a better error message from cmd.exe or at least an exit code that's googleable)

When I let GitHub Actions choose the shell, it uses pwsh instead of bash. The only difference is that the code is "False" rather than 127: https://github.com/iiasa/message_ix/pull/453/checks?check_run_id=2260473963#step:18:5761

segmentation fault in some teardown

I am using pytest-cov, and out of curiosity I looked and realized it adds stuff to atexit in its embed.py—so I tried to disable that in the workflow (ensure the packages are not installed). However, the result is the same.

Is there atexit teardown in pytest itself that I could somehow hack to debug this?

[asottile]

it's probably not atexit -- it's probably when the interpreter runs destructors of globals while tearing down the process

does this reproduce when you run locally on windows? there's free VMs you can try out at https://modern.ie provided by microsoft

[asottile]

the other idea is to enable faulthandler, though I thought it was on by default 🤔 -- maybe try running with -s (maybe the faulthandler output is being suppressed?)

[khaeru]

the other idea is to enable faulthandler, though I thought it was on by default thinking -- maybe try running with -s (maybe the faulthandler output is being suppressed?)

Thanks for this clue. We had indeed disabled faulthandler in order to work around an issue of noisy yet harmless console output, due either to JPype or some code that we run using it; see jpype-project/jpype#561. On re-enabling it, I see logs such as this one where faulthandler output is shown during teardown:

==== 91 passed, 25 deselected, 4 xfailed, 4 warnings in 196.61s (0:03:16) =====
Windows fatal exception: access violation

Thread 0x0000100c (most recent call first):
  File "C:\hostedtoolcache\windows\Python\3.8.8\x64\lib\site-packages\jpype\_core.py", line 340 in _JTerminate
Spurious exit code False from pytest
Error: Process completed with exit code 1.

…however, also this one, where there is no faulthandler output, but we still get the strange exit code:

==== 113 passed, 2 deselected, 5 xfailed, 4 warnings in 379.25s (0:06:19) =====
Spurious exit code False from pytest
Error: Process completed with exit code 1.

I guess the current issue could also be due to the old Java code we are running via JPype, or perhaps JPype itself. This could explain why it is beyond the reach of pytest/faulthandler to capture and display: whatever bug in Java is only triggered after pytest has finished and the other code is being torn down.

Unfortunately I am out of time (and my depth, not being a Java dev) to debug this further, so I filed iiasa/ixmp#411 and introduced a workaround in iiasa/message_ix#453. I will close this for now, and re-open or file a new issue if future work shows pytest to be the culprit after all.

Thanks very much @asottile for your responsiveness and helpful suggestions, they're greatly appreciated 👏🏽