crash using concurrency multiprocessing

[nedbat]

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.

1) 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.

2) 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

[nedbat]

@nodarn Do you have a reproducible case I can try?

[nedbat]

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.

[nedbat]

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

[nedbat]

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.

[nedbat]

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.

[nedbat]

@lboff is there any way to give me access to the code? Or a reproducible example?

[nedbat]

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

[nedbat]

Can you try running the test without the pytest_cov plugin? Something like: coverage run -m py.test

[mathfac]

Our project Habitat-API is also affected by the same issue, no solution found yet.

[nedbat]

@mathfac Can you give me a way to reproduce the issue?

[mathfac]

@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.

[skydoorkai]

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>

[ellabebop]

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.