Unexpected traceback output in test_concurrent_futures and crash

[serhiy-storchaka]

Crash report

When I run tests in single-process mode I get unexpected traceback output but tests was marked as passed:

Details

$ ./python -m test -r
== CPython 3.13.0a0 (heads/regretest-no-remove-test-module:eb7766baa4, Sep 13 2023, 10:58:19) [GCC 11.4.0]
== Linux-5.15.0-79-generic-x86_64-with-glibc2.35 little-endian
== Python build: debug
== cwd: /home/serhiy/py/cpython/build/test_python_worker_3200061æ
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
Using random seed 68644298
0:00:00 load avg: 0.75 Run 463 tests sequentially
...
0:12:03 load avg: 1.72 [191/463] test.test_concurrent_futures.test_process_pool
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
0:12:21 load avg: 1.52 [192/463] test_codecencodings_tw
...
0:25:47 load avg: 1.21 [361/463] test.test_concurrent_futures.test_deadlock
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 201, in send_bytes
    self._send_bytes(m[offset:offset + size])
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 422, in _send_bytes
    self._send(buf)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 385, in _send
    n = write(self._handle, buf)
        ^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: 'NoneType' object cannot be interpreted as an integer
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 201, in send_bytes
    self._send_bytes(m[offset:offset + size])
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 422, in _send_bytes
    self._send(buf)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 385, in _send
    n = write(self._handle, buf)
        ^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: 'NoneType' object cannot be interpreted as an integer
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 201, in send_bytes
    self._send_bytes(m[offset:offset + size])
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 422, in _send_bytes
    self._send(buf)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 385, in _send
    n = write(self._handle, buf)
        ^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: 'NoneType' object cannot be interpreted as an integer
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
0:26:01 load avg: 1.10 [362/463] test_bigaddrspace
...
0:26:20 load avg: 1.08 [368/463] test.test_concurrent_futures.test_init
Traceback (most recent call last):
  File "/home/serhiy/py/cpython/Lib/multiprocessing/queues.py", line 250, in _feed
    send_bytes(obj)
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 185, in send_bytes
    self._check_closed()
  File "/home/serhiy/py/cpython/Lib/multiprocessing/connection.py", line 138, in _check_closed
    raise OSError("handle is closed")
OSError: handle is closed
0:26:23 load avg: 1.15 [369/463] test_eof
...

Then Python crashed after reporting total success:

Total duration: 38 min 29 sec
Total tests: run=40,827 skipped=1,248
Total test files: run=453/463 skipped=10 resource_denied=10
Result: SUCCESS
Fatal Python error: Segmentation fault

Current thread 0x00007fb61c438740 (most recent call first):
  Garbage-collecting
  <no Python frame>
Помилка адресування (збережено знімок оперативної пам’яті)

The last line is "Segfault (core dumped)" in Ukrainian, but I have no core dump because ulimit -c was 0.

I ran tests with a modification of #108952 which does not remove test module or any imported during testing modules before or after running a test.

cc @vstinner

Linked PRs

• gh-109370: Support closing Connection and PipeConnection from other thread #109397
• gh-109370: Fix unexpected traceback output in test_concurrent_futures #109780
• [3.11] gh-109370: Fix unexpected traceback output in test_concurrent_futures (GH-109780) #109882
• [3.12] gh-109370: Fix unexpected traceback output in test_concurrent_futures (GH-109780) #111934

[serhiy-storchaka]

Simple

./python -m test test_concurrent_futures.test_process_pool

and

./python -m test test_concurrent_futures.test_deadlock

produce similar tracebacks, but without a crash.

[serhiy-storchaka]

Surprisingly, it is 3.13-only issue.

cc @vstinner

[vstinner]

I ran tests with a modification of #108952

Can you please give precise instructions on how to reproduce the issue? Should I patch Python? The command to reproduce the issue is ./python -m test -r?

[serhiy-storchaka]

There are two issues which may be related or not related:

1. Output of tracebacks. Perhaps not caught exceptions in threads?
2. Crash at shutdown.

Tracebacks are easy reproducible by running two tests. I did not try to reproduce the crash, because running all tests takes almost 40 minutes, and it may be order-depending. I ran full tests several times with other changes to libregrtest and found other crash, but not this one.

I am not sure that my change to libregrtest was related. It was equivalent to the following patch:

Details

diff --git a/Lib/test/libregrtest/main.py b/Lib/test/libregrtest/main.py
index ba493ae179..98a98e4ea6 100644
--- a/Lib/test/libregrtest/main.py
+++ b/Lib/test/libregrtest/main.py
@@ -293,8 +293,6 @@ def run_tests_sequentially(self, runtests):
         else:
             tracer = None
 
-        save_modules = sys.modules.keys()
-
         jobs = runtests.get_jobs()
         if jobs is not None:
             tests = count(jobs, 'test')
@@ -317,11 +315,6 @@ def run_tests_sequentially(self, runtests):
 
             result = self.run_test(test_name, runtests, tracer)
 
-            # Unload the newly imported modules (best effort finalization)
-            for module in sys.modules.keys():
-                if module not in save_modules and module.startswith("test."):
-                    support.unload(module)
-
             if result.must_stop(self.fail_fast, self.fail_env_changed):
                 break
 
diff --git a/Lib/test/libregrtest/single.py b/Lib/test/libregrtest/single.py
index de60566287..5c54419cfa 100644
--- a/Lib/test/libregrtest/single.py
+++ b/Lib/test/libregrtest/single.py
@@ -76,10 +76,6 @@ def _load_run_test(result: TestResult, runtests: RunTests) -> None:
     # Load the test module and run the tests.
     test_name = result.test_name
     module_name = abs_module_name(test_name, runtests.test_dir)
-
-    # Remove the module from sys.module to reload it if it was already imported
-    sys.modules.pop(module_name, None)
-
     test_mod = importlib.import_module(module_name)
 
     if hasattr(test_mod, "test_main"):

I.e. simply remove all removing of test modules before and after running a test. Actually, removing a module from sys.modules did not clear it (yet one mistake in this code), because remaining reference from the test module kept them alive, so I am not sure how it could affect finalization at all.

[serhiy-storchaka]

I figured out what is wrong with tracebacks. They are triggered by closing the queue's writer connection in terminate_broken() in #107219. There are two issues:

1. One is simple. _check_closed() should raise OSError with errno=EPIPE. It makes the queue thread to quit silently instead of printing a traceback and hanging.
2. The other one is caused by using (closing) the connection from other thread when it is in the middle of reading/writing. Connection should be only used from one thread. But does it include closing?

[vstinner]

One is simple. _check_closed() should raise OSError with errno=EPIPE. It makes the queue thread to quit silently instead of printing a traceback and hanging.

Do you want to propose a fix for this? It may be a good start.

[serhiy-storchaka]

#109397