coveragepy
coveragepy copied to clipboard
nedbat
crash using concurrency multiprocessing
Originally reported by Lorenzo Boffelli (Bitbucket: lboff, GitHub: lboff)
Hello, I am using pytest with pytest-cov and coverage. I wrote some tests where I run a process (multiprocessing.Process) The process uses gunicorn and start three worker. the test call a API server by one of the three worker.
-
If I do not add the option concurrency=multiprocessing I get always the same coverage. I think only the process startup is measured but the code executed after the process receive the API request is not reported as executed.
-
If I add the concurrency=multiprocessing it seems the code executed after the process receive the API request is reported as executed but coverage crash like reported below.
I can not add here the code at the moment but I can eventually exec other tests you could suggest and try to troubleshoot together
Thanks Lorenzo
Traceback (most recent call last):
File ".tox/dev/bin/py.test", line 11, in <module>
sys.exit(main())
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/config.py", line 49, in main
return config.hook.pytest_cmdline_main(config=config)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 724, in __call__
return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 338, in _hookexec
return self._inner_hookexec(hook, methods, kwargs)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 333, in <lambda>
_MultiCall(methods, kwargs, hook.spec_opts).execute()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 596, in execute
res = hook_impl.function(*args)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/main.py", line 119, in pytest_cmdline_main
return wrap_session(config, _main)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/main.py", line 114, in wrap_session
exitstatus=session.exitstatus)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 724, in __call__
return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 338, in _hookexec
return self._inner_hookexec(hook, methods, kwargs)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 333, in <lambda>
_MultiCall(methods, kwargs, hook.spec_opts).execute()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 595, in execute
return _wrapped_call(hook_impl.function(*args), self.execute)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 249, in _wrapped_call
wrap_controller.send(call_outcome)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/terminal.py", line 363, in pytest_sessionfinish
outcome.get_result()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 279, in get_result
_reraise(*ex) # noqa
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 264, in __init__
self.result = func()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 596, in execute
res = hook_impl.function(*args)
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/pytest_cov/plugin.py", line 160, in pytest_sessionfinish
self.cov_controller.finish()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/pytest_cov/engine.py", line 141, in finish
self.cov.stop()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/coverage/control.py", line 692, in stop
self.collector.stop()
File "/home/vnapi/vnapi/.tox/dev/local/lib/python2.7/site-packages/coverage/collector.py", line 277, in stop
** "Expected current collector to be %r, but it's %r" % (self, self._collectors[-1])
_pytest.assertion.reinterpret.AssertionError: Expected current collector to be <Collector at 0x7fc71b219a90: CTracer>, but it's <Collector at 0x7fc712037650: CTracer>**
- Bitbucket: https://bitbucket.org/ned/coveragepy/issue/488
Original comment by Nodar Nutsubidze (Bitbucket: nodarn, GitHub: Unknown)
This is probably the most annoying issue I deal with periodically. The most general reason for this that I have seen is that the test is failing for some reason and as mentioned above just disabling the coverage completely and running the test will usually show you where the issue is, once you fix that associated issue in your test and re-enable coverage everything will work as expected.
In certain cases this is still an issue at which point you want to pull your hair out because coverage/collector.py for some reason does not have any debug logging that you can turn on which means one must code logging into it by hand which is not efficient to say the least.
My paste to see what was going on was this:
#!python
$ hg diff
diff -r [25a6e0a6063e (bb)](https://bitbucket.org/ned/coveragepy/commits/25a6e0a6063e) coverage/collector.py
--- a/coverage/collector.py Wed Jun 14 08:31:56 2017 -0400
+++ b/coverage/collector.py Wed Jun 14 12:48:11 2017 -0500
@@ -273,6 +273,7 @@
def start(self):
"""Start collecting trace information."""
+ self.log("At the start, num_collectors: {}".format(len(self._collectors)))
if self._collectors:
self._collectors[-1].pause()
@@ -287,10 +288,12 @@
if tracer0:
traces0 = getattr(tracer0, 'traces', [])
+ self.log("Starting tracer fn0: {} traces0: {}".format(fn0, traces0))
try:
# Install the tracer on this thread.
fn = self._start_tracer()
- except:
+ except Exception as ex:
+ self.log("Failure: {}".format(ex))
if self._collectors:
self._collectors[-1].resume()
raise
@@ -298,6 +301,7 @@
# If _start_tracer succeeded, then we add ourselves to the global
# stack of collectors.
self._collectors.append(self)
+ self.log("Added ourselves to the global stack of collectors. Num: {}".format(len(self._collectors)))
# Replay all the events from fullcoverage into the new trace function.
for args in traces0:
@@ -311,10 +315,17 @@
# threads.
if self.threading:
self.threading.settrace(self._installation_trace)
+ def log(self, msg):
+ with open('/tmp/coverage_log.txt', 'a') as fp:
+ fp.write(msg + '\n')
def stop(self):
"""Stop collecting trace information."""
assert self._collectors
+ self.log("Stopping. Current # of collectors: {}".format(len(self._collectors)))
+ if self._collectors[-1] is not self:
+ self.log("Expected current collector to be %r, but it's %r" % (self, self._collectors[-1]))
+ return
assert self._collectors[-1] is self, (
"Expected current collector to be %r, but it's %r" % (self, self._collectors[-1])
)
@@ -323,7 +334,9 @@
# Remove this Collector from the stack, and resume the one underneath
# (if any).
+ self.log("Stopping. Removing an item from the stack")
self._collectors.pop()
+ self.log("Stopping. Done removing, new length: {}".format(len(self._collectors)))
if self._collectors:
self._collectors[-1].resume()
As seen above I use a return when a failure is seen instead of the assert. Now by no means am I suggesting this patch be used, this is just some test code to figure out what is going in at the time. The output that I get based on this diff is as follows:
#!text
At the start, num_collectors: 0
Starting tracer fn0: None traces0: []
Added ourselves to the global stack of collectors. Num: 1
At the start, num_collectors: 1
Starting tracer fn0: None traces0: []
Added ourselves to the global stack of collectors. Num: 2
Stopping. Current # of collectors: 2
Expected current collector to be <Collector at 0xb6bbe56c: CTracer>, but it's <Collector at 0xb6b49ecc: CTracer>
Stopping. Current # of collectors: 2
Stopping. Removing an item from the stack
Stopping. Done removing, new length: 1
Also after running the coverage with the return instead of the assert I saw some Exceptions that were caught which I can look at further instead of just being in the weeds. Hopefully this can shed some light into this issue.
Original comment by Lorenzo Boffelli (Bitbucket: lboff, GitHub: lboff)
Hello Ned, I am sorry but I still can not give to you the code but I can let you access to it through my PC (i.e. Team viewer) Are you interested to investigate? Thanks Lorenzo
Original comment by Edoardo Biraghi (Bitbucket: skedo, GitHub: skedo)
I can not give you the code to reproduce the error, but removing the lines below, I can run my coverage. I am quite sure the coverage is not working properly :)
#!python
# coverage/collector.py 276-279
assert self._collectors[-1] is self, (
"Expected current collector to be %r, but it's %r" % (self, self._collectors[-1])
)
It seems there is a problem how the Tracers are stacked into self._collectors.
Original comment by Lorenzo Boffelli (Bitbucket: lboff, GitHub: lboff)
I asked to have the permission to give you access to the code. I am also trying to reproduce it in another way Give me some more time to understand what I can do.
@lboff is there any way to give me access to the code? Or a reproducible example?
Original comment by Lorenzo Boffelli (Bitbucket: lboff, GitHub: lboff)
Here the original command executed through tox and pytest-cov. It reports the issue
py.test -x -v -s --cov-report html --cov-config .coveragerc --cov-report term --cov /home/vnapi/vnapi/.tox/dev/lib/python2.7/site-packages/vnapi tests/test_fnc_api_customer.py
The concurrency is in the config file
[run]
omit=*_version.py
concurrency=multiprocessing
Here the test executed using coverage
.tox/py27/bin/coverage run --source .tox/py27/lib/python2.7/site-packages/vnapi --concurrency=multiprocessing .tox/py27/bin/py.test ./tests/test_fnc_api_customer.py
In this case I am not getting any error but if I generate the report It is not correct It does not cover some code I am sure it is executed
Thanks Lorenzo
Can you try running the test without the pytest_cov plugin? Something like: coverage run -m py.test
@nedbat, thank you for the question. Issue was that we had the unit test (link) that was testing jupyter noebook using nbval plugin and gc.collect() was called in the end:
pytest.main(
[
"--nbval-lax",
"notebooks/relative_camera_views_transform_and_warping_demo.ipynb",
]
)
# NB: Force a gc collect run as it can take a little bit for
# the cleanup to happen after the notebook and we get
# a double context crash!
gc.collect()
I didn't debug further, as the test was already deprecated, I deleted it and the issue was fixed.
Got similar issue when doing multiprocessing unittest. python3.8, pytest version 7.3.2, coverage version 7.2.7
│ /opt/conda/lib/python3.8/site-packages/coverage/cmdline.py:866 in do_run │ │ │ │ 863 │ │ │ code_ran = False │ │ 864 │ │ │ raise │ │ 865 │ │ finally: │ │ ❱ 866 │ │ │ self.coverage.stop() │ │ 867 │ │ │ if code_ran: │ │ 868 │ │ │ │ self.coverage.save() │ │ 869 │ │ │ │ /opt/conda/lib/python3.8/site-packages/coverage/control.py:649 in stop │ │ │ │ 646 │ │ │ │ self._instances.pop() │ │ 647 │ │ if self._started: │ │ 648 │ │ │ assert self._collector is not None │ │ ❱ 649 │ │ │ self._collector.stop() │ │ 650 │ │ self._started = False │ │ 651 │ │ │ 652 │ def _atexit(self, event: str = "atexit") -> None: │ │ │ │ /opt/conda/lib/python3.8/site-packages/coverage/collector.py:373 in stop │ │ │ │ 370 │ │ │ print("self._collectors:") │ │ 371 │ │ │ for c in self._collectors: │ │ 372 │ │ │ │ print(f" {c!r}\n{c.origin}") │ │ ❱ 373 │ │ assert self._collectors[-1] is self, ( │ │ 374 │ │ │ f"Expected current collector to be {self!r}, but it's {self._collectors[-1]! │ │ 375 │ │ ) │ │ 376 │ ╰──────────────────────────────────────────────────────────────────────────────────────────────────╯ AssertionError: Expected current collector to be <Collector at 0x7f87b2616c10: CTracer>, but it's <Collector at 0x7f87b1c4e8e0: CTracer>
I'm seeing this problem too with Python 3.11.4, pytest 7.4.0, and coverage 7.3.0 ("with C extension"). I was able to boil it down to a simple case, testGoo.py.
import os
if "COVERAGE_PROCESS_START" in os.environ:
import coverage
coverage.process_startup()
def testGoo() -> None:
assert True
I'm using a conda environment but don't think it matters. So I execute it this way,
% rm -rf .coverage
% COVERAGE_PROCESS_START=/dev/null conda run -n 2.0 coverage run -m pytest testGoo.py
My .coveragerc isn't empty, but it doesn't seem to matter, so I use /dev/null here. The test passes but outputs assertion failures as reported here and elsewhere online.
self._collectors:
<Collector at 0x7f6927afd990: CTracer>
<module> : /ms/foss/anaconda/envs/2.0/bin/coverage:11
main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:973
command_line : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:684
do_run : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:858
start : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py:631
_init_for_start : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py:531
__init__ : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/collector.py:136
<Collector at 0x7f6922020e50: CTracer>
<module> : /ms/foss/anaconda/envs/2.0/bin/coverage:11
main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:973
command_line : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:684
do_run : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py:861
run : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/execfile.py:211
<module> : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pytest/__main__.py:5
console_main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/config/__init__.py:189
main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/config/__init__.py:166
__call__ : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_hooks.py:433
_hookexec : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_manager.py:112
_multicall : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_callers.py:80
pytest_cmdline_main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:317
wrap_session : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:270
_main : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:323
__call__ : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_hooks.py:433
_hookexec : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_manager.py:112
_multicall : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_callers.py:80
pytest_collection : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:334
perform_collect : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:669
genitems : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/main.py:836
collect_one_node : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/runner.py:547
__call__ : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_hooks.py:433
_hookexec : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_manager.py:112
_multicall : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pluggy/_callers.py:80
pytest_make_collect_report : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/runner.py:372
from_call : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/runner.py:341
<lambda> : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/runner.py:372
collect : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/python.py:531
_inject_setup_module_fixture : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/python.py:545
obj : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/python.py:310
_getobj : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/python.py:528
_importtestmodule : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/python.py:617
import_path : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/pathlib.py:565
import_module : /ms/foss/anaconda/envs/2.0/lib/python3.11/importlib/__init__.py:126
_gcd_import : <frozen importlib._bootstrap>:1204
_find_and_load : <frozen importlib._bootstrap>:1176
_find_and_load_unlocked : <frozen importlib._bootstrap>:1147
_load_unlocked : <frozen importlib._bootstrap>:690
exec_module : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/_pytest/assertion/rewrite.py:178
<module> : /home/me/goo/testGoo.py:4
process_startup : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py:1397
start : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py:631
_init_for_start : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py:531
__init__ : /ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/collector.py:136
Traceback (most recent call last):
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py", line 861, in do_run
runner.run()
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/execfile.py", line 211, in run
exec(code, main_mod.__dict__)
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/pytest/__main__.py", line 5, in <module>
raise SystemExit(pytest.console_main())
SystemExit: 0
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/ms/foss/anaconda/envs/2.0/bin/coverage", line 11, in <module>
sys.exit(main())
^^^^^^
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py", line 973, in main
status = CoverageScript().command_line(argv)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py", line 684, in command_line
return self.do_run(options, args)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/cmdline.py", line 866, in do_run
self.coverage.stop()
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/control.py", line 659, in stop
self._collector.stop()
File "/ms/foss/anaconda/envs/2.0/lib/python3.11/site-packages/coverage/collector.py", line 373, in stop
assert self._collectors[-1] is self, (
^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError: Expected current collector to be <Collector at 0x7f6927afd990: CTracer>, but it's <Collector at 0x7f6922020e50: CTracer>
ERROR conda.cli.main_run:execute(49): `conda run coverage run -m pytest testGoo.py` failed. (See above for error)
So the test calls coverage.process_start() in a pytest process already being run by the coverage script. My understanding of the docs is that this is unnecessary but harmless. Removing that call eliminates the failures. Simplifying my case to this simple example obscures why I'm calling the function at all. The call is actually in a separate module meant to be imported by apps that use my library to ensure other tests that fork those apps measure their coverage too. I'm importing it in a test, equivalent to the above, to test other aspects of that module.
I hope this helps solve it. Thanks for supporting this useful and important package.
