test_threading.test_4_daemon_threads() crash randomly

[vstinner]

On Linux, when I stress test test_threading.test_4_daemon_threads(), it does crash randomly:

./python -m test test_threading -m test_4_daemon_threads -j50 -F --fail-env-changed  

gdb traceback:

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00000000006e02f4 in PyInterpreterState_ThreadHead (interp=0xdddddddddddddddd) at Python/pystate.c:1961

warning: Source file is more recent than executable.
1961	    return interp->threads.head;
[Current thread is 1 (Thread 0x7fcbb8ff96c0 (LWP 510515))]
Missing separate debuginfos, use: dnf debuginfo-install bzip2-libs-1.0.8-13.fc38.x86_64 glibc-2.37-5.fc38.x86_64 libffi-3.4.4-2.fc38.x86_64 libgcc-13.2.1-1.fc38.x86_64 openssl-libs-3.0.9-2.fc38.x86_64 xz-libs-5.4.1-1.fc38.x86_64 zlib-1.2.13-3.fc38.x86_64
(gdb) where
#0  0x00000000006e02f4 in PyInterpreterState_ThreadHead (interp=0xdddddddddddddddd) at Python/pystate.c:1961
#1  0x0000000000703090 in _Py_DumpTracebackThreads (fd=2, interp=0xdddddddddddddddd, current_tstate=0x24a34e0) at Python/traceback.c:1331
#2  0x000000000071bcef in faulthandler_dump_traceback (fd=2, all_threads=1, interp=0xa53688 <_PyRuntime+92712>) at ./Modules/faulthandler.c:195
#3  0x000000000071bfed in faulthandler_fatal_error (signum=11) at ./Modules/faulthandler.c:313
#4  <signal handler called>
#5  0x000000000069f808 in take_gil (tstate=0x24a34e0) at Python/ceval_gil.c:360
#6  0x00000000006a03ab in PyEval_RestoreThread (tstate=0x24a34e0) at Python/ceval_gil.c:714
#7  0x000000000074dd93 in portable_lseek (self=0x7fcc186c3590, posobj=0x0, whence=1, suppress_pipe_error=false) at ./Modules/_io/fileio.c:934
#8  0x000000000074de88 in _io_FileIO_tell_impl (self=0x7fcc186c3590) at ./Modules/_io/fileio.c:997
#9  0x000000000074ea4c in _io_FileIO_tell (self=0x7fcc186c3590, _unused_ignored=0x0) at ./Modules/_io/clinic/fileio.c.h:460
(...)

gdb debug:

(gdb) frame 5
#5  0x000000000069f808 in take_gil (tstate=0x24a34e0) at Python/ceval_gil.c:360
360	    struct _gil_runtime_state *gil = ceval->gil;
(gdb) l
355	    }
356	
357	    assert(_PyThreadState_CheckConsistency(tstate));
358	    PyInterpreterState *interp = tstate->interp;
359	    struct _ceval_state *ceval = &interp->ceval;
360	    struct _gil_runtime_state *gil = ceval->gil;
361	
362	    /* Check that _PyEval_InitThreads() was called to create the lock */
363	    assert(gil_created(gil));
364	

(gdb) p /x ceval
$1 = 0xdddddddddddddddd

(gdb) p /x tstate->interp
$2 = 0xdddddddddddddddd


(gdb) p /x tstate
$5 = 0x24a34e0

(gdb) p /x _PyRuntime._finalizing._value 
$3 = 0xab8fa8

(gdb) p /x _PyRuntime._finalizing_id 
$4 = 0x7fcc49fce740

I don't understand why the test didn't exit: _PyThreadState_MustExit() should return, no?

I don't understand why assert(_PyThreadState_CheckConsistency(tstate)); didn't fail.

Maybe Py_Finalize() was called between the pre-check:

    if (_PyThreadState_MustExit(tstate)) {
        /* bpo-39877: If Py_Finalize() has been called and tstate is not the
           thread which called Py_Finalize(), exit immediately the thread.

           This code path can be reached by a daemon thread after Py_Finalize()
           completes. In this case, tstate is a dangling pointer: points to
           PyThreadState freed memory. */
        PyThread_exit_thread();
    }

    assert(_PyThreadState_CheckConsistency(tstate));

and the code:

    PyInterpreterState *interp = tstate->interp;
    struct _ceval_state *ceval = &interp->ceval;
    struct _gil_runtime_state *gil = ceval->gil;

Linked PRs

• gh-110052: Fix faulthandler for freed tstate #110069
• [3.12] gh-110052: Fix faulthandler for freed tstate (#110069) #110071
• [3.11] gh-110052: Fix faulthandler for freed tstate (#110069) #110072

[vstinner]

See also issue gh-110031 which looks similar.

[vstinner]

The regression was introduced by PR gh-109794: #109794 (comment)

[ericsnowcurrently]

I'm looking into this.

./python -m test test_threading -m test_4_daemon_threads -j50 -F --fail-env-changed

I haven't been able to get a crash in over 16 minutes (but I certainly believe you).

[vstinner]

I haven't been able to get a crash in over 16 minutes (but I certainly believe you).

What is your operating system? I reproduced the crash on Linux. I didn't try other operating systems.

If you want to make daemon threads crashes more likely, add sleep(1) at the end of PyInterpreterState_Delete(), after free_interpreter().

[ericsnowcurrently]

What is your operating system? I reproduced the crash on Linux. I didn't try other operating systems.

It's an 8-core, 24GB RAM Hyper-V Ubuntu VM running on a Windows laptop.

If you want to make daemon threads crashes more likely, add sleep(1) at the end of PyInterpreterState_Delete(), after free_interpreter().

I'll try it.

[ericsnowcurrently]

gdb traceback:
,,,
gdb debug:
...
I don't understand why the test didn't exit: _PyThreadState_MustExit() should return, no?

Yeah, that's the critical question.

[ericsnowcurrently]

Here's the critical part from gh-109794:

diff --git a/Python/pystate.c b/Python/pystate.c
index dcc6c112215b3..570b5242600c0 100644
--- a/Python/pystate.c
+++ b/Python/pystate.c
@@ -2964,11 +2964,26 @@ _PyThreadState_MustExit(PyThreadState *tstate)
        tstate->interp->runtime to support calls from Python daemon threads.
        After Py_Finalize() has been called, tstate can be a dangling pointer:
        point to PyThreadState freed memory. */
+    unsigned long finalizing_id = _PyRuntimeState_GetFinalizingID(&_PyRuntime);
     PyThreadState *finalizing = _PyRuntimeState_GetFinalizing(&_PyRuntime);
     if (finalizing == NULL) {
+        // XXX This isn't completely safe from daemon thraeds,
+        // since tstate might be a dangling pointer.
         finalizing = _PyInterpreterState_GetFinalizing(tstate->interp);
+        finalizing_id = _PyInterpreterState_GetFinalizingID(tstate->interp);
     }
-    return (finalizing != NULL && finalizing != tstate);
+    // XXX else check &_PyRuntime._main_interpreter._initial_thread
+    if (finalizing == NULL) {
+        return 0;
+    }
+    else if (finalizing == tstate) {
+        return 0;
+    }
+    else if (finalizing_id == PyThread_get_thread_ident()) {
+        /* gh-109793: we must have switched interpreters. */
+        return 0;
+    }
+    return 1;
 }

The most obvious possibility is that we switched to a different thread state during finalization in the thread where finalization is happening and the thread state belongs to the same interpreter. However, that isn't an expected use case for PyThread_Swap() and I'm pretty sure we don't have any code that does that.

[ericsnowcurrently]

If you want to make daemon threads crashes more likely, add sleep(1) at the end of PyInterpreterState_Delete(), after free_interpreter().

I'll try it.

No failures in 13 minutes.

[vstinner]

No failures in 13 minutes.

How do you build Python? Which configure options?

I'm usually using ./configure --with-pydebug to get assertions.

[ericsnowcurrently]

Basically: ./configure --with-pydebug CFLAGS=-O0

[ericsnowcurrently]

Is this issue tied to any buildbot/CI failures?

[terryjreedy]

6/12 core Win 10, standard PCBuild/build.bat -d

...
0:00:31 load avg: 76.65 [ 87/1] test_threading failed (1 failure)
test test_threading failed -- Traceback (most recent call last):
  File "f:\dev\3x\Lib\test\test_threading.py", line 1172, in test_4_daemon_threads
    rc, out, err = assert_python_ok('-c', script)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "f:\dev\3x\Lib\test\support\script_helper.py", line 166, in assert_python_ok
    return _assert_python(True, *args, **env_vars)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "f:\dev\3x\Lib\test\support\script_helper.py", line 151, in _assert_python
    res.fail(cmd_line)
  File "f:\dev\3x\Lib\test\support\script_helper.py", line 76, in fail
    raise AssertionError("Process return code is %d\n"
AssertionError: Process return code is 3221225477
command line: ['f:\\dev\\3x\\PCbuild\\amd64\\python_d.exe', '-X', 'faulthandler', '-c', "if True:\n            import os\n            import random\n            import sys\n            import time\n            import threading\n\n            thread_has_run = set()\n\n            def random_io():\n                '''Loop for a while sleeping random tiny amounts and doing some I/O.'''\n                import test.test_threading as mod\n                while True:\n                    with open(mod.__file__, 'rb') as in_f:\n                        stuff = in_f.read(200)\n                        with open(os.devnull, 'wb') as null_f:\n                            null_f.write(stuff)\n                            time.sleep(random.random() / 1995)\n                    thread_has_run.add(threading.current_thread())\n\n            def main():\n                count = 0\n                for _ in range(40):\n                    new_thread = threading.Thread(target=random_io)\n                    new_thread.daemon = True\n                    new_thread.start()\n                    count += 1\n                while len(thread_has_run) < count:\n                    time.sleep(0.001)\n                # Trigger process shutdown\n                sys.exit(0)\n\n            main()\n            "]

stdout:
---

---

stderr:
---
Windows fatal exception: access violation