Open aaugustin opened 1 year ago
Picking this up for the PyCon 2023 sprints.
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.
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.
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(
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.
Successfully reproduced this on manjaro 23.0.4
the following way:
coverage
and websockets
repos.coverage
is at version 7.2.2 with C extension
(althrough the problem occurs with the latest version as well)f075aac67e15cdf4bc06078e23b82eac5fb2d758
in the websocket
repovenv
in the cloned coverage
repopython3 -m pip install -r requirements/dev.in
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
)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 :)
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.
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:
collector.py:363
)
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) .
That's good new at least for me -- I only run coverage on the latest Python version so 3.12 saves me :-)
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_URIReproduction:
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: https://github.com/aaugustin/websockets/commit/901e434fac7bf60018c950bdaf85b9946cc4309d#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.