Nonsensical coverage result: covered line right after non-covered line

[aaugustin]

Describe the bug

In the screenshot below, line 1364 is marked as not covered and line 1367 is marked as covered.

This cannot happen. The only way to get to line 1367 is by going through line 1364.

To Reproduce

Python version 3.11.2 (installed with pyenv on macOS)

Coverage version 7.2.2 with C extension

Output of `coverage debug sys`

-- sys ------------------------------------------------------- coverage_version: 7.2.2 coverage_module: /Users/myk/Desktop/venv/lib/python3.11/site-packages/coverage/__init__.py tracer: -none- CTracer: available plugins.file_tracers: -none- plugins.configurers: -none- plugins.context_switchers: -none- configs_attempted: .coveragerc setup.cfg tox.ini pyproject.toml configs_read: -none- config_file: None config_contents: -none- data_file: -none- python: 3.11.2 (main, Apr 2 2023, 07:49:19) [Clang 14.0.0 (clang-1400.0.29.202)] platform: macOS-13.1-arm64-arm-64bit implementation: CPython executable: /Users/myk/Desktop/venv/bin/python def_encoding: utf-8 fs_encoding: utf-8 pid: 85045 cwd: /Users/myk/Desktop path: /Users/myk/Desktop/venv/bin /Users/myk/.pyenv/versions/3.11.2/lib/python311.zip /Users/myk/.pyenv/versions/3.11.2/lib/python3.11 /Users/myk/.pyenv/versions/3.11.2/lib/python3.11/lib-dynload /Users/myk/Desktop/venv/lib/python3.11/site-packages environment: HOME = /Users/myk PYENV_SHELL = zsh command_line: /Users/myk/Desktop/venv/bin/coverage debug sys sqlite3_sqlite_version: 3.39.5 sqlite3_temp_store: 0 sqlite3_compile_options: ATOMIC_INTRINSICS=1, BUG_COMPATIBLE_20160819, CCCRYPT256, COMPILER=clang-14.0.0, DEFAULT_AUTOVACUUM, DEFAULT_CACHE_SIZE=2000, DEFAULT_CKPTFULLFSYNC, DEFAULT_FILE_FORMAT=4, DEFAULT_JOURNAL_SIZE_LIMIT=32768, DEFAULT_LOOKASIDE=1200,102, DEFAULT_MEMSTATUS=0, DEFAULT_MMAP_SIZE=0, DEFAULT_PAGE_SIZE=4096, DEFAULT_PCACHE_INITSZ=20, DEFAULT_RECURSIVE_TRIGGERS, DEFAULT_SECTOR_SIZE=4096, DEFAULT_SYNCHRONOUS=2, DEFAULT_WAL_AUTOCHECKPOINT=1000, DEFAULT_WAL_SYNCHRONOUS=1, DEFAULT_WORKER_THREADS=0, ENABLE_API_ARMOR, ENABLE_BYTECODE_VTAB, ENABLE_COLUMN_METADATA, ENABLE_DBSTAT_VTAB, ENABLE_FTS3, ENABLE_FTS3_PARENTHESIS, ENABLE_FTS3_TOKENIZER, ENABLE_FTS4, ENABLE_FTS5, ENABLE_LOCKING_STYLE=1, ENABLE_NORMALIZE, ENABLE_PREUPDATE_HOOK, ENABLE_RTREE, ENABLE_SESSION, ENABLE_SNAPSHOT, ENABLE_SQLLOG, ENABLE_STMT_SCANSTATUS, ENABLE_UNKNOWN_SQL_FUNCTION, ENABLE_UPDATE_DELETE_LIMIT, HAS_CODEC_RESTRICTED, HAVE_ISNAN, MALLOC_SOFT_LIMIT=1024, MAX_ATTACHED=10, MAX_COLUMN=2000, MAX_COMPOUND_SELECT=500, MAX_DEFAULT_PAGE_SIZE=8192, MAX_EXPR_DEPTH=1000, MAX_FUNCTION_ARG=127, MAX_LENGTH=2147483645, MAX_LIKE_PATTERN_LENGTH=50000, MAX_MMAP_SIZE=1073741824, MAX_PAGE_COUNT=1073741823, MAX_PAGE_SIZE=65536, MAX_SQL_LENGTH=1000000000, MAX_TRIGGER_DEPTH=1000, MAX_VARIABLE_NUMBER=500000, MAX_VDBE_OP=250000000, MAX_WORKER_THREADS=8, MUTEX_UNFAIR, OMIT_AUTORESET, OMIT_LOAD_EXTENSION, STMTJRNL_SPILL=131072, SYSTEM_MALLOC, TEMP_STORE=1, THREADSAFE=2, USE_URI

Reproduction:

myk@mYk:~/Desktop $ python -m venv venv

myk@mYk:~/Desktop $ . venv/bin/activate

(venv) myk@mYk:~/Desktop $ pip install coverage
Collecting coverage
  Using cached coverage-7.2.2-cp311-cp311-macosx_11_0_arm64.whl (199 kB)
Installing collected packages: coverage
Successfully installed coverage-7.2.2

(venv) myk@mYk:~/Desktop $ git clone https://github.com/aaugustin/websockets
Cloning into 'websockets'...
remote: Enumerating objects: 8953, done.
remote: Counting objects: 100% (279/279), done.
remote: Compressing objects: 100% (147/147), done.
remote: Total 8953 (delta 153), reused 199 (delta 112), pack-reused 8674
Receiving objects: 100% (8953/8953), 2.58 MiB | 9.77 MiB/s, done.
Resolving deltas: 100% (6310/6310), done.

(venv) myk@mYk:~/Desktop $ cd websockets

(venv) myk@mYk:Desktop/websockets ‹main›$ git checkout f075aac67e15cdf4bc06078e23b82eac5fb2d758
HEAD is now at f075aac Restore semantics of tests.

(venv) myk@mYk:Desktop/websockets ‹f075aac›$ PYTHONPATH=src coverage run --source src/websockets  -m unittest
....................................................................................................................................................................................................................................................ss......................................................................................................................................................................................................................................................................................................................................................................................................................................................s.s......................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
----------------------------------------------------------------------
Ran 1285 tests in 1.985s

OK (skipped=4)

(venv) myk@mYk:Desktop/websockets ‹f075aac›$ coverage html
Wrote HTML report to htmlcov/index.html

Then open the HTML coverage report for src/websockets/legacy/protocol.py and scroll to line 1364.

This isn't a minimal example at all but at least it's reproducible.

Expected behavior

I expect the missing line to be marked as covered.

Indeed, it is exercised by:

• tests.legacy.test_protocol.ClientTests.test_local_close_connection_lost_timeout_after_close
• tests.legacy.test_protocol.ServerTests.test_local_close_connection_lost_timeout_after_close

If you change the missing line and raise an exception, these tests fail with that exception.

Additional context

You cannot reproduce the issue on the main branch because I chose to ignore the problem: python-websockets/websockets@901e434#diff-3851a087134dc94d4edce57e405054b17b85aed1639b8f62f1a79ba582345c3fR1365

If you look at this commit, you will also see another similar problem in the test suite. The lines marked as not executed are definitely executed; if you change them, tests fail.

[kevin-brown]

Picking this up for the PyCon 2023 sprints.

[kevin-brown]

After trying to reproduce this in Windows Subsystem for Linux (Ubuntu 20.02 LTS, Python 3.8) using Coverage 7.2.2 and the python-websockets repository both on the given commit and the latest main commit, I was not able to reproduce this issue.

Because I was not able to get a certain group of tests to run locally. likely related to my unusual execution environment, I tried to reproduce this issue with the subset of tests affecting the lines mentioned.

PYTHONPATH=src coverage run --source .  -m unittest tests.legacy.test_protocol
coverage html

The result is all tests pass and the lines which were not being marked in the original report are showing up as covered wihtin the HTML report. Additionally, the tests which were covered by pragma: no cover show as being covered when that flag is removed. As a result, I am not able to reproduce this issue locally.

[justlund]

Removing if self.debug: from exclude_lines makes things a bit clearer.

Nothing between lines 1357 and 1367 is covered, but the second await self.wait_for_connection_lost() on line 1367 is covered.

[justlund]

Running with --timid

$ PYTHONPATH=src coverage run --timid --source src/websockets  -m unittest tests.legacy.test_protocol
..............................................................................................................................................................................................................................................................................Traceback (most recent call last):
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/__main__.py", line 18, in <module>
    main(module=None)
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/main.py", line 102, in __init__
    self.runTests()
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/main.py", line 274, in runTests
    self.result = testRunner.run(self.test)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/runner.py", line 217, in run
    test(result)
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/suite.py", line 122, in run
    test(result)
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/suite.py", line 122, in run
    test(result)
  File "/Users/justin/.pyenv/versions/3.11.2/lib/python3.11/unittest/suite.py", line 84, in __call__
    return self.run(*args, **kwds)
  File "/Users/justin/ws/tmp/venv8/lib/python3.11/site-packages/coverage/pytracer.py", line 265, in _trace
    self.data_stack.pop()
IndexError: pop from empty list
/Users/justin/ws/tmp/venv8/lib/python3.11/site-packages/coverage/pytracer.py:321: CoverageWarning: Trace function changed, data is likely wrong: None != <bound method PyTracer._trace of <PyTracer at 0x10fcd7fd0: 1584 data points in 16 files>> (trace-changed)
  self.warn(

[aaugustin]

Oh, yes, I've also hit this error ("pop from empty list") while running the test suite with coverage. I don't know if it's related.

[Newtoneiro]

Successfully reproduced this on manjaro 23.0.4 the following way:

1. Cloned both coverage and websockets repos.
2. Made sure, the coverage is at version 7.2.2 with C extension (althrough the problem occurs with the latest version as well)
3. Checked out on f075aac67e15cdf4bc06078e23b82eac5fb2d758 in the websocket repo
4. Created and activated venv in the cloned coverage repo
5. Installed dependencies with python3 -m pip install -r requirements/dev.in
6. In the websocket repo run the coverage with command given in reproduction example (PYTHONPATH=src python3 {path_to_cloned_coverage_repo} run --source src/websockets -m unittest, then python3 {path_to_cloned_coverage_repo} html)
7. The output in browser shows:
   

[Newtoneiro]

Hey so a quick update from my side - I recon that the issue may be related to the if await line ( 1356 on above picture). I've made some experiments and the behavior seems highly indeterministic - everything below this line, and the last line in the block gets marked as uncovered, even though it is nonsensical.

My hypothesis get's partially confirmed by commenting out the if await block:

We can see that now the line is covered properly.

I've encountered some troubles debugging the code - it seems like there is some problem with multithreading and the debugger loses the trace of the code. It would be highly appreciated if someone could help me better understand the code structure - since it's my entry issue to this project :)

[Newtoneiro]

After a long session of testing and researching - I've arrived at the conclusion that the problem itself is caused by CPython update. The line seems to be covered correctly up to version 3.11.* and above version 3.11.* (python >= 3.12.0). It seems like the experimental Python version (3.13.0a1) makes the coverage behave correctly again, but throws some other errors in the console.

Conclusion

I believe that the issue is related to the CPython change from 3.10 to 3.11, but it seems like it does behave correctly in newer versions.

I believe the issue is outdated and thus can be closed. @nedbat

Related issues:

• issue related to broken coverage in cpython
• Commit message regarding the topic: (collector.py:363)
  

[Radkoski002]

Together with @Newtoneiro, we've created a minimal reproduction codebox based on Timeout context manager from websockets library.

It turns out that this issue is most likely related to asyncio library implementation in python 3.11, because as @Newtoneiro said before the problem doesn't exist in other python versions we've tested (3.8, 3.9, 3.10, 3.12, 3.13a) .

[aaugustin]

That's good new at least for me -- I only run coverage on the latest Python version so 3.12 saves me :-)