support for a multiprocessing inside a subprocess?

[mmerickel]

I'm working on https://github.com/Pylons/hupper. It's a forking process monitor. I've tried a lot of permutations of pytest-cov and haven't found any success.

The process hierarchy is this:

$ py.test --cov-report=term-missing --cov=hupper --cov=tests
|- (a) tests/test_it.py (run by py.test process)
   |- (b) tests/myapp (run by test_it tests using subprocess)
      |- (c) tests/myapp (re-run by myapp via hupper using multiprocessing)

Here is an example output, but first some observations:

1. The tests didn't pass when I ran them with --cov flags enabled. This is because of the "No data was collected" messages in the worker process (this is process c in the above diagram). There should definitely be data collected if things were working correctly.
2. Some coverage data is missing. For example you can see that some code was executed in tests/myapp/__main__.py however lines 1-10 are missing, which are at module scope. What?
3. After the run is over I have a .coverage.alai.27676.269523 file left over. Presumably this file is not getting combined with the rest of the output, but that's just a guess.
4. Almost nothing in the hupper library itself is covered. However it's used in both processes b and c.

$ env/bin/py.test --cov-report=term-missing --cov=hupper --cov=tests
============================= test session starts ==============================
platform darwin -- Python 3.5.2, pytest-3.0.3, py-1.4.31, pluggy-0.4.0
rootdir: /Users/michael/work/oss/hupper, inifile: setup.cfg
plugins: cov-2.4.0
collected 2 items

tests/test_it.py FF

---------- coverage: platform darwin, python 3.5.2-final-0 -----------
Name                      Stmts   Miss  Cover   Missing
-------------------------------------------------------
hupper/__init__.py            3      3     0%   4-9
hupper/compat.py             39     39     0%   2-62
hupper/interfaces.py         12     12     0%   1-44
hupper/ipc.py                10      8    20%   1-60
hupper/polling.py            43     43     0%   1-62
hupper/reloader.py          133    131     2%   1-204, 241-266
hupper/watchdog.py           26     26     0%   2-40
hupper/winapi.py             86     86     0%   1-153
hupper/worker.py            123     70    43%   1-24, 29, 34, 42, 55-60, 74-76, 80, 90-166, 175, 179, 186-187, 191-192, 196, 200-204
tests/__init__.py             0      0   100%
tests/myapp/__init__.py       0      0   100%
tests/myapp/__main__.py      45     18    60%   1-10, 23, 28-32, 35-36, 39, 57-58
tests/test_it.py             19      2    89%   13, 25
tests/util.py                68      0   100%
-------------------------------------------------------
TOTAL                       607    438    28%


=================================== FAILURES ===================================
_____________________ test_myapp_reloads_when_touching_ini _____________________

    def test_myapp_reloads_when_touching_ini():
        with util.TestApp('myapp', ['--reload']) as app:
            app.wait_for_response(interval=1)
            util.touch('myapp/foo.ini')
            app.wait_for_response()
            app.stop()

            assert len(app.response) == 2
>           assert app.stderr == ''
E           assert 'Coverage.py ... collected.\n' == ''
E             - Coverage.py warning: No data was collected.

tests/test_it.py:12: AssertionError
___________________ test_myapp_reloads_when_touching_pyfile ____________________

    def test_myapp_reloads_when_touching_pyfile():
        with util.TestApp('myapp', ['--reload']) as app:
            app.wait_for_response(interval=1)
            util.touch('myapp/__main__.py')
            app.wait_for_response()
            app.stop()

            assert len(app.response) == 2
>           assert app.stderr == ''
E           assert 'Coverage.py ... collected.\n' == ''
E             - Coverage.py warning: No data was collected.

tests/test_it.py:24: AssertionError
=========================== 2 failed in 6.61 seconds ===========================

I'd really appreciate any insights here as I have no experience getting coverage reports when in a multiprocessing/subprocess environment but as far as I can tell my setup follows the guidelines (each process has pytest-cov installed and environment variables are propagated).

[mmerickel]

FWIW I also dumped the environs for both the monitor (process b) and the worker (process c).

(a) py.test

 'COV_CORE_CONFIG': '/Users/michael/work/oss/hupper/.coveragerc',
 'COV_CORE_DATAFILE': '/Users/michael/work/oss/hupper/.coverage',
 'COV_CORE_SOURCE': 'hupper:tests',
 '_COVERAGE_RCFILE': '.coveragerc',

(b) monitor

 'COV_CORE_CONFIG': '/Users/michael/work/oss/hupper/.coveragerc',
 'COV_CORE_DATAFILE': '/Users/michael/work/oss/hupper/.coverage',
 'COV_CORE_SOURCE': 'hupper:tests',
 '_COVERAGE_RCFILE': '/Users/michael/work/oss/hupper/.coveragerc',

(a) worker

 'COV_CORE_CONFIG': '/Users/michael/work/oss/hupper/.coveragerc',
 'COV_CORE_DATAFILE': '/Users/michael/work/oss/hupper/.coverage',
 'COV_CORE_SOURCE': 'hupper:tests',
 '_COVERAGE_RCFILE': '/Users/michael/work/oss/hupper/.coveragerc',

This at least confirms that the environ variables are available to all of the processes.

[ionelmc]

Does it still happen if you remove the coverage filter (eg: only use --cov without any package/path)?

[mmerickel]

Yes I get the same result.

[mmerickel]

@ionelmc Do you have any hints or initial thoughts? I'm happy to try and dig into this but I don't know much about this domain. I just know that pytest-cov is monkeypatching some calls to invoke coverage in each process and then combining the coverage results. My first guess is that it not running coverage on one of the processes or the results from that process are squashing some other results, causing them to appear to be missing.

[mmerickel]

I discovered that if I drop concurrency = multiprocessing from my .coveragerc file the tests pass at least. But the coverage itself is not improved.

[ionelmc]

Is anything like exec being used in the code (besides what exec-ing multiprocessing does)?

[ionelmc]

Ok, with some configuration changes I get this:

hupper/ipc.py                                                                  10      8      0      0    20.00%   1-60
hupper/reloader.py                                                            133    131     32      1     1.82%   1-204, 241-266, 238->241
hupper/worker.py                                                              123     70     30      5    45.75%   1-24, 29, 34, 42, 55-60, 74-76, 80, 90-166, 175, 179, 186-187, 191-192, 196, 200-204, 50->44, 54->55, 68->63, 70->63, 174->175
tests/__init__.py                                                               0      0      0      0   100.00%
tests/myapp/cli.py                                                             45     16     18      7    57.14%   1-10, 23, 30-34, 37-38, 41, 24->26, 27->45, 29->30, 36->37, 40->41, 45->49, 49->52
tests/test_it.py                                                               19      0      0      0   100.00%
tests/util.py                                                                  69      0     10      2    97.47%   37->exit, 43->45

Is that expected result?

[ionelmc]

I'm afraid you need to adopt a src layout to make this work well. I disabled all source filtering to get the result above ...

The problem is that when you put sources=hupper coverage thinks of it as ./hupper (as a path) and not the module that goes in site-packages.

[ionelmc]

See Pylons/hupper#7

[mmerickel]

Wow thanks @ionelmc. Let me respond inline.

Is anything like exec being used in the code (besides what exec-ing multiprocessing does)?

No. There is just a subprocess.Popen to open a process that is using multiprocessing.

Is that expected result?

It is not. There are several lines at module scope that are not tracked. For example, in both processes b and c the reloader.py, ipc.py, worker.py and tests/myapp/cli.py are imported so if coverage were working in any of those it would be different.

The problem is that when you put sources=hupper coverage thinks of it as ./hupper (as a path) and not the module that goes in site-packages.

What if I use include instead of source? I could also be more explicit about the source path, but as of yet I've just been running it outside of tox so the source is being tested directly.

[ionelmc]

I'll investigate further, probably an answer next week. Feel free to find different configuration (like using include) but I doubt it would fix the lack of measurements in reloader.py (unless it's an unlikely configuration bug :-))

[mmerickel]

I went into this at least a little bit deeper but I'm still pretty confused. It doesn't appear as if coverage is watching the subprocess at all, except that there is some minimal amount of coverage reported for a couple of the modules.

I found https://coverage.readthedocs.io/en/coverage-4.2/subprocess.html#configuring-python-for-sub-process-coverage for handling subprocess coverage, but it seems to me that pytest-cov is handling this in its own way via a .pth file, except it isn't calling coverage.process_startup. I imagine the issue is something to do with this.

[mmerickel]

@ionelmc Any chance to look at this? Is there an example somewhere of a working subprocess setup I can look at?

[ionelmc]

Well the test have lots of stuff with subprocesses. But they are quite simplistic, compared to your project. I still want to figure this out ... lets see when I get to it 😔

[mmerickel]

Here's my latest coverage report:

Name                       Stmts   Miss     Cover   Missing
-----------------------------------------------------------
src/hupper/__init__.py         3      0   100.00%
src/hupper/compat.py          36     17    52.78%   10, 16-17, 21-22, 27-28, 34-41, 46-50
src/hupper/interfaces.py      12      0   100.00%
src/hupper/ipc.py             10      2    80.00%   55, 58
src/hupper/reloader.py       136     82    39.71%   62, 84-90, 93-94, 103-115, 124-132, 135-177, 180-186, 189-190, 193-195, 199-200, 203-204, 207-208, 248-273
src/hupper/worker.py         123     37    69.92%   55-57, 93-99, 106-130, 133-135, 138-139, 142-159, 175, 186-187, 201
tests/__init__.py              0      0   100.00%
tests/conftest.py             15      0   100.00%
tests/myapp/__init__.py        0      0   100.00%
tests/myapp/__main__.py        3      3     0.00%   1-4
tests/myapp/cli.py            45     16    64.44%   1-10, 23, 30-34, 37-38, 41
tests/test_it.py              22      0   100.00%
tests/test_reloader.py        63      0   100.00%
tests/util.py                 67      0   100.00%
-----------------------------------------------------------
TOTAL                        535    157    70.65%

This is after tweaking the coveragerc a bit more. Many of these lines I would expect to be covered, such as everything in hupper/ipc.py and tests/myapp/__main__.py and a lot of tests/myapp/cli.py.

1. It definitely looks like coverage is not being run in one or more of the processes and is not being combined into the final report. It's hard to pin down though because I'd expect a lot of it to be covered by both b and c. Definitely there is coverage for everything in process a.

2. Coverage is not being combined properly between python 2 and 3. The coverage in compat.py changes based on whether I run tox -e py27,py35,coverage or tox -e py35,py27,coverage.

[ionelmc]

I think I figured out what the problem is: pytest-cov uses "multiprocessing finalizers" and that don't seem to work with proc.terminate(). The integration tests we have now don't try to do anything crazy like .terminate() (we have some harmless .join()).

Anyway, meanwhile I'm looking for a solution, any idea how to make mp reliably run some code in a process even if it's .terminate()-d?

[ionelmc]

Ok, one thing that works is something like signal.signal(signal.SIGTERM, lambda n, f: multiprocessing_finish(cov)) but this is very heavy-handed:

• perhaps users want their own handling for SIGTERM
• not portable on Windows

I'm starting to lean towards looking a solution in multiprocessing, rather than workaround in pytest-cov ...

[schlamar]

IMO we should shift the burden to the user in such a special case. If the user is terminating a coverage process it should be his responsibility to clean up everything. To assist we could help with a shortcut for multiprocessing_finish(cov) so he doesn't need a reference to the coverage object. The user can then use signal.signal(...) on his own.

According to the docs SIGTERM should be available on Windows, too. Are you sure that this is not working?

[mmerickel]

Thanks for the ideas.

Ok, one thing that works is something like signal.signal(signal.SIGTERM, lambda n, f: multiprocessing_finish(cov)) but this is very heavy-handed:

I'm not sure how to test this. The cov object is not globally accessible for me to add that snippet somewhere inside my code to try it out. I guess I can hack pytest_cov.embed to add the signal.

Are you sure this is an issue with multiprocessing? I think at least part of the issue is that coverage does not appear to be running in the subprocess b (not c which is run via multiprocessing).

[ionelmc]

I thought the problem was process „c”.

And about the API and „cov” object, we can fix it so it's usable from user's code.

[mmerickel]

Some examples of why I think the issue is mostly b:

1. src/hupper/ipc.py the uncovered lines are sendfd and add_child, but not recvfd. The first two are used in the monitor b, and the last is used in the worker c.

2. Almost all of the non-module-scope code in src/hupper/reloader.py is uncovered, only executed in b.

3. The worker_main is covered in src/hupper/worker.py (used in c) but not the Worker object itself which is used only in b.

To be clear b is also a subprocess that's terminated via the test harness and so could suffer from improper cleanup as well but I don't know how to check that.

[jbarlow83]

My test suite calls subprocesses that run multiprocessing using pytest-cov, and it also fails to pick up anything that happens inside my worker processes, while it does collect work done in the initial subprocess.

It so happens my multiprocessing is handled by a library (ruffus) that allows one to switch to multithreading and take cares of the details somewhat transparently. I held my nose, switched on multithreading, and pytest-cov picked up everything. (And hey, 74%... not a bad start.) My tests terminate processes normally by closing a process pool.

The results in the multiprocessing case are the same whether or not concurrency = multiprocessing is set in .coveragerc, so it seems as if that doesn't work or doesn't matter.

I also tried coverage run -m py.test manually with the various environmental variable and sitecustomize hacks before finding pytest-cov and that does not work either.

[ionelmc]

Alright, give the master branch a try. Suggested use:

# in the subprocess
from pytest_cov.embed import cleanup_on_sigterm
cleanup_on_sigterm()

Full example: https://github.com/pytest-dev/pytest-cov/blob/master/tests/test_pytest_cov.py#L783-L784

[mmerickel]

So I've finally revisited this after rewriting hupper to use subprocess instead of multiprocessing. I'm happy to say that pytest_cov.embed.cleanup() fixes my coverage issues.

That being said, cleanup_on_sigterm is not immediately usable because it squashes the actual sigterm. I had to write my own sigterm handler... I don't know if this is the best way though:

import signal
import pytest_cov.embed

def cleanup(*_):
    pytest_cov.embed.cleanup()
    sys.exit(1)
signal.signal(signal.SIGTERM, cleanup)

[ionelmc]

Feel free to use pytest_cov.embed.cleanup() then (it's also new api).

I could make cleanup_on_sigterm wrap the old signal handler I guess. Opinions?

[mmerickel]

I can confirm this fix has improved my coverage reports. It's used here: Pylons/hupper@88da99e

One final note... it might be smart to register this by default when pytest_cov.embed.init is invoked. 1) This would not require saving the active_cov global, and 2) it would be less of a gotcha for folks doing coverage in subprocesses.

I wish I knew a good way to do this on windows as well but http://stackoverflow.com/a/35792192/704327 doesn't paint a pretty picture.

[ionelmc]

On Fri, May 12, 2017 at 5:33 AM, Michael Merickel ***@***.***> wrote: One final note... it might be smart to register this by default when pytest_cov.embed.init is invoked. 1) This would not require saving the active_cov global, and 2) it would be less of a gotcha for folks doing coverage in subprocesses.

​Can you expand on this?​ You mean automatically registering the signal handler?

[mmerickel]

​Can you expand on this?​ You mean automatically registering the signal
handler?

Yeah that's what I was suggesting. pytest-cov jumps through hoops to register a pth and get in on the coverage game early - I think it makes sense it would try to cleanup as well.

[ionelmc]

What if there's already a registered sig handler? Should we wrap the old sigterm handler?

[mmerickel]

What if there's already a registered sig handler? Should we wrap the old sigterm handler?

That'd probably make sense. I wish there was a way to guarantee cleanup on windows as well but I don't really know of one. At the end of the day the use-case of getting coverage on a subprocess that is designed to not exit normally is obviously not an ideal approach.

[ionelmc]

I think this should be enough: 509f77f#diff-6926f77e5b0c63b4908e3ed385e64a20

Comment or make PR if you want something else.