pytest.main(...) hangs but works if run with subprocess.check_output

[tjprescott]

In my code, I call pytest.main(arguments) to run Pytest.

        arguments = ['-p', 'no:warnings', '--no-print-logs', '--junit-xml', log_path]
        arguments.extend(test_paths)
        if parallel:
            arguments += ['-n', 'auto']
        if pytest_args:
            arguments += pytest_args
        logger.info('Running: pytest {}'.format(' '.join(arguments)))
        return pytest.main(arguments)

This code hangs when run on OSX (10.14.1) but works fine on Windows.

If I change the last line to instead essentially call pytest through subprocess.check_output it executes fine. It also works if I simply copy-paste the command to my terminal. This behavior is observed whether I specify -n=auto or not, which is why I'm posting this here instead of in pytest-xdist. Is there something I'm doing wrong here?

Pip List

pytest (4.0.0)
pytest-forked (0.2)
pytest-xdist (1.24.1)

OS Info

Python (Darwin) 2.7.10 (default, Aug 17 2018, 17:41:52) 
[GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.0.42)]

[tjprescott]

If I run the command with --debug, here is the snippet of the trace where it hangs:

[worker-gw2] sending logfinish {'nodeid': 'azure/cli/command_modules/redis/tests/latest/test_redis_scenario.py::RedisCacheTests::test_redis_cache', 'location': ('../../../env/lib/python2.7/site-packages/azure_devtools/scenario_tests/preparers.py', 26, 'RedisCacheTests.test_redis_cache')}
[worker-gw2] sending runtest_protocol_complete {'duration': 1.1219720840454102, 'item_index': 0}
[worker-gw2] sending workerfinished {'workeroutput': {'exitstatus': 1}}

Essentially, it has reported that the worker (and the only test) is finished, but processing stops at that point until I kill the process.

[blueyed]

Does using -s as an argument to pytest make a difference?

[nicoddemus]

--debug is useful, thanks. Can you please also post --debug without -n=auto? Thanks

[tjprescott]

The run hangs when I run with Python 2.7 (default on OSX). If I run on Python 3 it seems to work without modification. -s doesn't help with Python 2.

[tjprescott]

If run in series on Python 2 with debug, I get this trace:

================================================================================ test session starts ================================================================================
platform darwin -- Python 2.7.10, pytest-4.0.0, py-1.7.0, pluggy-0.8.0 -- /Users/travisprescott/github/azure-cli/env/bin/python
using: pytest-4.0.0 pylib-1.7.0
setuptools registered plugins:
  pytest-xdist-1.24.1 at /Users/travisprescott/github/azure-cli/env/lib/python2.7/site-packages/xdist/looponfail.py
  pytest-xdist-1.24.1 at /Users/travisprescott/github/azure-cli/env/lib/python2.7/site-packages/xdist/plugin.py
  pytest-forked-0.2 at /Users/travisprescott/github/azure-cli/env/lib/python2.7/site-packages/pytest_forked/__init__.pyc
rootdir: /Users/travisprescott/github/azure-cli/src/command_modules/azure-cli-redis, inifile:
plugins: xdist-1.24.1, forked-0.2
collected 1 item                                                                                                                                                                    

src/command_modules/azure-cli-redis/azure/cli/command_modules/redis/tests/latest/test_redis_scenario.py 

It then hangs.

[nicoddemus]

hmmm didn't you see writing pytestdebug information to c:\pytest\pytestdebug.log at the start of the output?

[tjprescott]

Ah, yes, that was the line just prior to "test session starts"

[nicoddemus]

Does that file exist in your machine? I was under the impression it would get written even if the process never finished.

[tjprescott]

It does. I can send you the file for each case, one where is hangs on Python 2, and one where it succeeds in Python 3. Should I send it to the email in your profile?

[cdeil]

We also have CI builds where pytest hangs. They are on Python 2.7 and with pytest 4.0, see https://github.com/gammapy/gammapy/pull/1940#issuecomment-441052014 .

I tried setting PYTEST_DEBUG=1, but then there's too much output in the log and the CI services abort the build - not sure how to figure out why pytest hangs. I'll try reproducing the issue locally.

[cdeil]

I can reproduce the issue locally on MacOS with this conda env.yml like this:

git clone https://github.com/gammapy/gammapy.git
cd gammapy
time conda env create -f env.yml
conda activate gammapy-gh-1940
time python setup.py test -V

pytest hangs forever at very high CPU load. This shows continued printout of such lines:

$ PYTEST_DEBUG=1 time python setup.py test -V 
<snip>
early skip of rewriting module: h5py [assertion]
early skip of rewriting module: multiprocessing.random [assertion]
<snip>

These commands should let you reproduce the issue locally. If needed, I could try to create a more minimal conda environment or docker image that shows the issue.

It looks like pytest 4.0 has a serious issue under Python 2.7 for some environments, no?

[nicoddemus]

It does. I can send you the file for each case, one where is hangs on Python 2, and one where it succeeds in Python 3. Should I send it to the email in your profile?

Please post it here in an issue, thanks (you can drag and drop the files to the issue text box directly)

[nicoddemus]

@cdeil thanks for posting a reproducible case, unfortunately I'm on Windows and I can't recreate your environment:

ResolvePackageNotFound:
  - healpy
  - sherpa

healpy and sherpa probably are not available on Windows.

The early skip of rewriting module messages are expected, unless they appear for the same module more than once (which should not really happen).

Can you pass options to pytest with your setup.py test invocation? Could you please try -s, and --assert=plain, to see how that behaves? Also, now that you have reproduced the problem locally, can you attach the produced log here? Thanks, appreciate it. 👍

It looks like pytest 4.0 has a serious issue under Python 2.7 for some environments, no?

Not sure if this is an issue with Python 2.7 specifically, nothing that came out in 2.7 comes to mind (we only changed some pytest warnings into errors, really).

Also, what happens if you use 3.10.1 instead of 4.0.0?

[cdeil]

@nicoddemus - Can you try this simpler env?

conda create -n pytest-4434 python=2.7 cython numpy scipy astropy regions click pyyaml pytest
conda activate pytest-4434

and then the same:

git clone https://github.com/gammapy/gammapy.git
cd gammapy
time python setup.py test -V

or

pytest -v gammapy

will hang.
Now I see it hangs here:

gammapy/__init__.py::test

Does this mean it collected the gammapy.test function in the top-level package as a test to execute? That shouldn't happen (and didn't with other pytest versions). cc @astrofrog

https://github.com/gammapy/gammapy/blob/9981b0baefed1e16cfa8b19e8cbb7d2a9f4f3f63/gammapy/_astropy_init.py#L36

@nicoddemus - I'll try to follow your other suggestions locally. Maybe I should try to make a Docker image that has the issue, then you can execute it and have a look more easily?

[cdeil]

What's happening is that pytest calls pytest again:
https://gist.github.com/cdeil/b1ab5916546103d64f34c788100c63f7
So this is another symptom of something wrong in the Astropy package-template how the pytest function is implemented in astropy_init.py.
Probably the same underlying issue as for the issue reported here: #4390

So it might not be connected to the issue reported by @tjprescott here originally, although it also sounds like you might be calling pytest recursively?

I still don't know what to do here. Should _astropy_init.py be patched?
Or should an entry be made in setup.cfg to prevent that __init__.py::test is collected as a test and recursively called?
Given that this issue only appeared with never versions of pytest and on some platform, maybe something can be improved in pytest?

[nicoddemus]

@cdeil can you try with pytest 3.10? I ask because you have the environment on your hand so it should be simple to try it.

pytest has been collected packages (and tests within them) for some time now (3.8? I think) so I want to know if the problem is related with that.

[cdeil]

With pytest 3.10 I get this, i.e. no tests are collected at all:
https://gist.github.com/cdeil/d5029fab585fe68df77fb91685570b78

With pytest 3.7, I get this AttributeError
https://gist.github.com/cdeil/4c950865e6e2da8f30d0ece8858b98d5

pytest 3.6 is the last version where it works.
I see that 8 days ago @pllim and @bsipocz did https://github.com/astropy/ci-helpers/pull/340 i.e remove the pin to pytest < 3.6 in our CI.
That explains why we're seeing the issues now.

Still not sure what to do here. Maybe we should simply exclude gammapy.test which is the runner from the test collection? What's the best way to do this?

https://github.com/gammapy/gammapy/blob/9981b0baefed1e16cfa8b19e8cbb7d2a9f4f3f63/gammapy/_astropy_init.py#L36

[nicoddemus]

@cdeil thanks a lot for testing things out. You are right, the problem seems to be with the fact that the test runner will start executing things when imported directly. Somewhere we need to add an if __name__ == "__main__" guard to avoid this.

Can you jump on Gitter real quick? I suspect we might be able to solve this quickly on chat.

[nicoddemus]

@cdeil and I figured the problem after some quick poking around: gammpy.__init__ provides a test() function which starts a test run using astropy's runner. The test function is generated by _astropy_init.py.

pytest since 3.8 collects __init__, and was looking at this module and executing test() as a function.

Setting __test__ = False on the function itself prevents pytest considering it a test function. 👍

[astrofrog]

@nicoddemus - thank you for diagnosing this!

[cdeil]

@nicoddemus - You are awesome!

@tjprescott - Are you also accidentally running pytest from pytest like we are? Or is it a different one? If the second, I am really sorry for derailing your issue report; I should have opened a separate issue.

@astrofrog - I will send PRs with the one-line change for the Astropy and package-template repos.

[tjprescott]

@cdeil I'm not sure what you mean by "running pytest from pytest". I was simply trying to call pytest.main(…) which works fine in Python 3 but hangs in Python 2. I have a workaround where I use subprocess.call to do the same thing and it doesn't hang, so I'm doing that.

[tjprescott]

Here are the debug logs.

failed_pytestdebug.log
success_pytestdebug.log

[nicoddemus]

Hi @tjprescott,

Unfortunately the logs don't tell much, all hooks have been called in what seems to be the correct order. 😕

Given that you have found a workaround and we have ran out of ways to debug this, I propose we close this issue.

[nicoddemus]

Thanks. I'm sorry we couldn't get to the bottom of your problem.

[tjprescott]

No worries. It's entirely possible I was just "doing it wrong". Thanks for looking into it.