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]

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

[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]

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

---

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]

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)

---

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 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]

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

[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?