Coveragepy: os.path.relpath fails when saving a coverage file with coverage 5 in a folder from a different Windows drive

[ogrisel]

Describe the bug

In the scikit-learn test suite we have a test that launches a subprocess and the atexit registry triggers the saving of a coverage file in a tempfolder in d:\ while the current working directory has been changed by pytest --pyargs to c:\ in the meantime.

E                   AssertionError: Error in atexit._run_exitfuncs:
E                   Traceback (most recent call last):
E                     File "c:\miniconda\envs\testvenv\lib\ntpath.py", line 562, in relpath
E                       path_drive, start_drive))
E                   ValueError: path is on mount 'D:', start on mount 'c:'

cmd        = ['c:\\miniconda\\envs\\testvenv\\python.exe', 'C:\\Users\\VSSADM~1\\AppData\\Local\\Temp\\tmp32ajt78f_src_test_sklearn.py']
coverage_rc = None
cwd        = 'c:\\miniconda\\envs\\testvenv\\lib\\site-packages'
...

I do not understand why the traceback starts at atexit._run_exitfuncs and then goes to ntpath.relpath directly without going through the function of the coverage module. I suspect that the culprit is:

https://github.com/nedbat/coveragepy/blob/coverage-5.0/coverage/sqldata.py#L982

When rolling back to coverage 4.5.3, the problem disappears.

To Reproduce

This problems happens with coverage 5.0 and Python 3.7.5 with the latest pytest and pytest-cov.

It seems tricky to reproduce, in particular I do not understand why this only happens in the subprocess tests of scikit-learn and never in the main process itself. Maybe the current working directory is restored to the d:\ tempfolder prior to writing the coverage files?

Anyhow the details can be found in the CI logs of this pull request where I have patched the ntpath.relpath function to display more debug info:

https://github.com/scikit-learn/scikit-learn/pull/15909

I will open a PR to fix the issue in coveragepy.

It looks similar to #824 but the error message is actually different.

[nedbat]

Ironically, the relpath line in question is only there to help with a different Windows problem. Perhaps catching a ValueError from relpath, and skipping it will be enough?

[ogrisel]

Will do this.

[ogrisel]

Done in #896.

[nedbat]

Fixed in c09c2c203286db3cae1148bd02b1db9a9d524af1

[asottile]

awesome -- thanks for the triage and fix on this! this is affecting pytest's testsuite as well (it was quite a bit harder to track down in python3 as the stacktrace doesn't mention coverage at all! fortunately our maintenance branch showed the failures in python2)

for completeness (and perhaps so others can find in google), here are the traces we saw:

2.x

E         -  'Traceback (most recent call last):',
E         -  '  File "C:\\hostedtoolcache\\windows\\Python\\2.7.16\\x64\\Lib\\atexit.py", line 24, in _run_exitfuncs',
E         -  '    func(*targs, **kargs)',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\control.py", line 525, in _atexit',
E         -  '    self.stop()',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\control.py", line 613, in save',
E         -  '    data = self.get_data()',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\control.py", line 667, in get_data',
E         -  '    if self._collector and self._collector.flush_data():',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\collector.py", line 427, in flush_data',
E         -  '    self.covdata.add_arcs(self.mapped_file_dict(self.data))',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 468, in add_arcs',
E         -  '    self._choose_lines_or_arcs(arcs=True)',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 493, in _choose_lines_or_arcs',
E         -  '    with self._connect() as con:',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 298, in _connect',
E         -  '    self._create_db()',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 247, in _create_db',
E         -  '    with db:',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 1008, in __enter__',
E         -  '    self._connect()',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\site-packages\\coverage\\sqldata.py", line 982, in _connect',
E         -  '    filename = os.path.relpath(self.filename)',
E         -  '  File "d:\\a\\1\\s\\.tox\\py27-lsof-nobyte-numpy\\lib\\ntpath.py", line 529, in relpath',
E         -  '    % (path_prefix, start_prefix))',
E         -  'ValueError: path is on drive D:, start on drive c:']

3.x

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "d:\a\1\s\.tox\py37-twisted-numpy\lib\ntpath.py", line 562, in relpath
    path_drive, start_drive))
ValueError: path is on mount 'D:', start on mount 'C:'

[ogrisel]

Why the Python 3 traceback is a mystery to me. I also wasted some time debugging at random because of this. Anybody has an idea why it is the case?

[ogrisel]

Maybe the frame objects have already been garbage collected? That seems weird.

[gaborbernat]

I've ran into this with virtualenv CI too - see https://dev.azure.com/pypa/virtualenv/_build/results?buildId=16409&view=logs&jobId=18fdbe60-1f00-5bb0-ebb2-c0f5cf5b2053&j=6ae96b06-827a-58da-753b-f69475679149&t=1bc2b072-5378-5303-372a-95d81e0bbf25; any planned release with a fix?

[nedbat]

Fixed in c09c2c20

[nedbat]

This is now available in coverage==5.0.1