[subinterpreters] test__xxsubinterpreters fails randomly

@vstinner

BPO	37224
Nosy	@vstinner, @ericsnowcurrently, @koobs, @miss-islington, @shihai1991, @aeros
PRs	bpo-37224: Fix test__xxsubinterpreters failure and GIL handling in interp_destroy() #16293 bpo-37224: Improve test__xxsubinterpreters.DestroyTests #18058 [3.8] bpo-37224: Improve test__xxsubinterpreters.DestroyTests (GH-18058) #18318 bpo-37224: Using threading.Event to make sure the thread is running already. #26598 bpo-37224: Wait for subinterpreter to be running #26717 bpo-37224: Fix the sequence of unlock/lock of MUTEX. #26733 bpo-37224: To fix the random failed test cases of test___xxsubinterpreters in multiprocess. #27240 [3.10] bpo-37224: To fix the random failed test cases of test___xxsubinterpreters in multiprocess. (GH-27240) #27452 [3.9] bpo-37224: To fix the random failed test cases of test___xxsubinterpreters in multiprocess. (GH-27240) #27453
Files	3.x.koobs-freebsd-564d-build-973-test-stdio.txt add_printf_to_get_details_from_race_condition.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2021-07-29.17:32:05.013>
created_at = <Date 2019-06-11.00:58:01.578>
labels = ['expert-subinterpreters', 'tests', '3.9', '3.10', '3.11']
title = '[subinterpreters] test__xxsubinterpreters fails randomly'
updated_at = <Date 2021-07-29.17:32:05.010>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-07-29.17:32:05.010>
actor = 'lukasz.langa'
assignee = 'none'
closed = True
closed_date = <Date 2021-07-29.17:32:05.013>
closer = 'lukasz.langa'
components = ['Tests', 'Subinterpreters']
creation = <Date 2019-06-11.00:58:01.578>
creator = 'vstinner'
dependencies = []
files = ['49224', '50160']
hgrepos = []
issue_num = 37224
keywords = ['patch']
message_count = 51.0
messages = ['345162', '345163', '345219', '345415', '347486', '352508', '352509', '352510', '352514', '352516', '352592', '352835', '354658', '354659', '354661', '354662', '354677', '354876', '355221', '355520', '356631', '357347', '357349', '357350', '357361', '357364', '357365', '357378', '357671', '357672', '358358', '358359', '358373', '358552', '359699', '360024', '360025', '360027', '360029', '360209', '361130', '361353', '361354', '361387', '363992', '371160', '372561', '377749', '394974', '395021', '397809']
nosy_count = 7.0
nosy_names = ['vstinner', 'python-dev', 'eric.snow', 'koobs', 'miss-islington', 'shihai1991', 'aeros']
pr_nums = ['16293', '18058', '18318', '26598', '26717', '26733', '27240', '27452', '27453']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue37224'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

https://buildbot.python.org/all/#/builders/224/builds/5

0:46:02 load avg: 1.53 [259/423/1] test__xxsubinterpreters failed -- running: test_httplib (1 min 6 sec), test_mmap (16 min 42 sec)
beginning 6 repetitions
123456
..Exception in thread Thread-28:
Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\threading.py", line 923, in _bootstrap_inner
    self.run()
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 51, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 182
test test__xxsubinterpreters failed -- Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 492, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

(...)

FAIL: test_still_running (test.test__xxsubinterpreters.DestroyTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 765, in test_still_running
    interpreters.destroy(interp)
AssertionError: RuntimeError not raised

See bpo-33356.

Fail on x86 Gentoo Refleaks 3.x:
https://buildbot.python.org/all/#/builders/1/builds/618

3:15:59 load avg: 6.93 [339/423/1] test__xxsubinterpreters failed -- running: test_multiprocessing_spawn (19 min 36 sec)
beginning 6 repetitions
123456
.Exception in thread Thread-17:
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/threading.py", line 923, in _bootstrap_inner
    self.run()
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test__xxsubinterpreters.py", line 51, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 108
test test__xxsubinterpreters failed -- Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test__xxsubinterpreters.py", line 765, in test_still_running
    interpreters.destroy(interp)
AssertionError: RuntimeError not raised

(...)

test_after_destroying (test.test__xxsubinterpreters.ListAllTests) ... ok
test_initial (test.test__xxsubinterpreters.ListAllTests) ... ok
test_SystemExit (test.test__xxsubinterpreters.RunStringTests) ... ok
test_already_running (test.test__xxsubinterpreters.RunStringTests) ... spam
Exception in thread Thread-31:
Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/threading.py", line 923, in _bootstrap_inner
    self.run()
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test__xxsubinterpreters.py", line 51, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 190
FAIL
test_bad_id (test.test__xxsubinterpreters.RunStringTests) ... ok
test_bad_script (test.test__xxsubinterpreters.RunStringTests) ... ok
test_bytes_for_script (test.test__xxsubinterpreters.RunStringTests) ... ok
test_create_thread (test.test__xxsubinterpreters.RunStringTests) ... ok
test_does_not_exist (test.test__xxsubinterpreters.RunStringTests) ... ok
test_error_id (test.test__xxsubinterpreters.RunStringTests) ... ok
test_execution_namespace_is_main (test.test__xxsubinterpreters.RunStringTests) ... ok
test_failure (test.test__xxsubinterpreters.RunStringTests) ... ok
test_fork (test.test__xxsubinterpreters.RunStringTests) ... ok
test_in_thread (test.test__xxsubinterpreters.RunStringTests) ... ok
test_invalid_syntax (test.test__xxsubinterpreters.RunStringTests) ... ok
test_main_reused (test.test__xxsubinterpreters.RunStringTests) ... ok
test_shared_overwrites (test.test__xxsubinterpreters.RunStringTests) ... ok
test_shared_overwrites_default_vars (test.test__xxsubinterpreters.RunStringTests) ... ok
test_still_running_at_exit (test.test__xxsubinterpreters.RunStringTests) ... skipped 'blocking forever'
test_success (test.test__xxsubinterpreters.RunStringTests) ... ok
test_sys_exit (test.test__xxsubinterpreters.RunStringTests) ... ok
test_with_shared (test.test__xxsubinterpreters.RunStringTests) ... ok
test_bytes (test.test__xxsubinterpreters.ShareableTypeTests) ... ok
test_int (test.test__xxsubinterpreters.ShareableTypeTests) ... ok
test_non_shareable_int (test.test__xxsubinterpreters.ShareableTypeTests) ... ok
test_singletons (test.test__xxsubinterpreters.ShareableTypeTests) ... ok
test_types (test.test__xxsubinterpreters.ShareableTypeTests) ... ok

======================================================================
FAIL: test_already_running (test.test__xxsubinterpreters.RunStringTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/buildbot/buildarea/cpython/3.x.ware-gentoo-x86.refleak/build/Lib/test/test__xxsubinterpreters.py", line 855, in test_already_running
    interpreters.run_string(self.id, 'print("spam")')
AssertionError: RuntimeError not raised

Failure on AppVeyor on my PR 14029 (which is unrelated):

test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests) ... Exception in thread Thread-8:
Traceback (most recent call last):
  File "C:\projects\cpython\lib\threading.py", line 923, in _bootstrap_inner
    self.run()
  File "C:\projects\cpython\lib\threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "C:\projects\cpython\lib\test\test__xxsubinterpreters.py", line 51, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 46
FAIL

FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test__xxsubinterpreters.py", line 492, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

test__xxsubinterpreters passed when run again.

The test still fails times to times:
https://buildbot.python.org/all/#/builders/80/builds/644

FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 492, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

Upon digging through Modules/_xxsubinterpretersmodule.c, I noticed that on line 2059, PyInterpreterState_Delete(interp); is commented out (

cpython/Modules/_xxsubinterpretersmodule.c

Line 2059 in bf16991

//PyInterpreterState_Delete(interp);

).

This was done when _xxsubinterpretersmodule.c was first added by Eric Snow (

cpython/Modules/_xxsubinterpretersmodule.c

Line 2059 in bf16991

//PyInterpreterState_Delete(interp);

), so it seems to have been done intentionally but I don't understand why.

Is this because Py_EndInterpreter() is supposed to shutdown the interpreter, so PyInterpreterState_Delete() isn't needed? If so, that still doesn't particularly explain why it was commented out. Perhaps Eric can elaborate.

Note that I'm not particularly experienced with the c-api, I'm just trying to take a stab at understanding why the buildbot failure is occuring.

Clarification: In the above comment when I was referring to the commit made by Eric Snow, I meant to link to 7f8bfc9.

Upon further reading of the documentation and some experimentation, it would definitely not make sense to call PyInterpreterState_Delete here (since we're only closing the sub-interpreter in the current thread), so that's not the issue. I still have no idea as to why it's commented out there, but that's besides the point.

I think I may have found the potential cause of the test failure though. Looking into test_still_running(), it's clear that the intention is for a RuntimeError to be raised if interpreters.destroy() is called on a currently running interpreter:

    def test_still_running(self):
        main, = interpreters.list_all()
        interp = interpreters.create()
        with _running(interp):
            with self.assertRaises(RuntimeError):
                interpreters.destroy(interp)
            self.assertTrue(interpreters.is_running(interp))

However, within interp_destroy (

cpython/Modules/_xxsubinterpretersmodule.c

Line 2024 in 56a4514

interp_destroy(PyObject *self, PyObject *args, PyObject *kwds)

), it is apparent that the RuntimeError is ONLY raised when attempting to destroy the current interpreter:

    if (interp == current) {
        PyErr_SetString(PyExc_RuntimeError,
                        "cannot destroy the current interpreter");
        return NULL;
    }

When attempting to destroy a running interpreter, NULL is returned without raising the RuntimeError:

    if (_ensure_not_running(interp) < 0) {
        return NULL;
    }

This was my first guess at a solution:

    if (_ensure_not_running(interp) < 0) {
        PyErr_SetString(PyExc_RuntimeError,
                        "cannot destroy a running interpreter")
        return NULL;
    }

But, within _ensure_not_running() (

cpython/Modules/_xxsubinterpretersmodule.c

Line 1842 in 56a4514

_ensure_not_running(PyInterpreterState *interp)

), a RuntimeError is supposed to be raised from:

    if (is_running) {
        PyErr_Format(PyExc_RuntimeError, "interpreter already running");
        return -1;
    }

Initially, I was unsure of the difference between PyErr_SetString() and PyErr_Format(), so I referred to the documentation. PyErr_Format() is similar, but it also returns NULL. If I'm not mistaken doesn't mean that the return -1 within the if (is_running) bock is effectively ignored? If so, this would potentially explain the problem...

I think the appropriate solution would be to replace PyErr_Format() with PyErr_SetString() within _ensure_not_running(). Also, I think it would be more useful to additionally raise the RuntimeError within interp_destroy() if the interpreter is running, to provide a more useful and specific error message. "cannot destroy a running interpreter" is far more useful for debugging purposes than a more generic "interpreter already running".

I plan on opening a PR to make these changes in the next few days. Let me know what you think Victor.

Clarification:
"If I'm not mistaken doesn't mean that the return -1 within ..."

Should instead be:
"If I'm not mistaken doesn't this mean that the return -1 within ..."

(I am really looking forward to moving issue over to GitHub at some point. It's nice to be able to edit comments and properly format code blocks...)

Upon further consideration, I don't think this will address the issue. If the RuntimeError was not being raised, this failure would be consistent rather than intermittent.

I think I have have gotten a bit mixed up, even if the return value of PyErr_Format is NULL, it would not implicitly return NULL upon being called and exit the function early (like a macro could) . I'm not experienced with programming in C, I only started learning it more recently (Python, Java, and C# have been my primary languages) when I started contributing to CPython in June.

Instead, I suspect this is likely a concurrency issue, where multiple threads are trying to access the same sub-interpreter during interp_destroy(). The solution will likely involve finding the correct place for a lock. I'll continue to work on this and see if I can find a solution.

Is there a currently reliable way of accessing the GIL functions within the sub-interpreters, without causing deadlock issues? I was trying to follow the advice in the documentation (https://docs.python.org/3/c-api/init.html?highlight=global%20interpreter%20lock#bugs-and-caveats).

"It is highly recommended that you don’t switch sub-interpreters between a pair of matching PyGILState_Ensure() and PyGILState_Release() calls."

But it seemed that any attempt to use any of the PyGIL* calls within interp_destroy() in a meaningful way resulted in a deadlock, even if it was done away from the sub-interpreter switching.

My next idea would be to add a conditional check to see if the current thread has ownership of the GIL, and using PyEval_RestoreThread() to acquire it if it doesn't. This would be followed by releasing the GIL with PyThreadState_Get() at the end of the function. I'll try experimenting with that idea next.

I marked bpo-33356 as a duplicate of this issue:

Windows10 3.x: test_already_running() failed once, but passed when run again: ...
AMD64 FreeBSD 10-STABLE Non-Debug 3.x: ...

I have a few spare cycles to take another stab at this issue. I can say with some certainty that the failure in test__xxsubinterpreters.DestroyTests does not occur on the latest commit to master (3.9):

$ ./python -m test test__xxsubinterpreters --match DestroyTests -j200 -F -v

OK
0:09:28 load avg: 80.87 [2188] test__xxsubinterpreters passed
test_all (test.test__xxsubinterpreters.DestroyTests) ... ok
test_already_destroyed (test.test__xxsubinterpreters.DestroyTests) ... ok
test_bad_id (test.test__xxsubinterpreters.DestroyTests) ... ok
test_does_not_exist (test.test__xxsubinterpreters.DestroyTests) ... ok
test_from_current (test.test__xxsubinterpreters.DestroyTests) ... ok
test_from_other_thread (test.test__xxsubinterpreters.DestroyTests) ... ok
test_from_sibling (test.test__xxsubinterpreters.DestroyTests) ... ok
test_main (test.test__xxsubinterpreters.DestroyTests) ... ok
test_one (test.test__xxsubinterpreters.DestroyTests) ... ok
test_still_running (test.test__xxsubinterpreters.DestroyTests) ... ok

== Tests result: INTERRUPTED ==
Test suite interrupted by signal SIGINT.

2188 tests OK.

So at this point it seems to be a matter of looking through the diff between 3.8 vs 3.9 for any relevant code paths, and attempting to determine what change resolved the failure for 3.9. It might also be useful to determine if it occurred when the tests were first added in 3.8 or if some other commit introduced a subtle regression.

Failure on AMD64 FreeBSD Shared 3.x (full log attached):

======================================================================
FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test__xxsubinterpreters.py", line 478, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

...

2 tests failed:
test__xxsubinterpreters test_interpreters

...

test_already_running (test.test_interpreters.TestInterpreterRun) ... spam
Stderr:
Exception in thread Thread-19:
Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/threading.py", line 950, in _bootstrap_inner
    self.run()
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/threading.py", line 888, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_interpreters.py", line 45, in run
    interp.run(dedent(f"""
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/support/interpreters.py", line 94, in run
    _interpreters.run_string(self._id, src_str)
RuntimeError: unrecognized interpreter ID 111
FAIL

...

test test_interpreters failed
test_send_recv_same_interpreter (test.test_interpreters.TestSendRecv) ... ok
======================================================================
FAIL: test_still_running (test.test_interpreters.TestInterpreterDestroy)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_interpreters.py", line 309, in test_still_running
    interp.close()
AssertionError: RuntimeError not raised

======================================================================
FAIL: test_subinterpreter (test.test_interpreters.TestInterpreterIsRunning)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_interpreters.py", line 207, in test_subinterpreter
    self.assertTrue(interp.is_running())
AssertionError: False is not true

======================================================================
FAIL: test_already_running (test.test_interpreters.TestInterpreterRun)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_interpreters.py", line 383, in test_already_running
    self.interp.run('print("spam")')
AssertionError: RuntimeError not raised
Stderr:
Exception in thread Thread-19:
Traceback (most recent call last):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/threading.py", line 950, in _bootstrap_inner
    self.run()
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/threading.py", line 888, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/test_interpreters.py", line 45, in run
    interp.run(dedent(f"""
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-564d/build/Lib/test/support/interpreters.py", line 94, in run
    _interpreters.run_string(self._id, src_str)
RuntimeError: unrecognized interpreter ID 111

Ran 40 tests in 20.251s
FAILED (failures=3)
1 test failed again:
test_interpreters
== Tests result: FAILURE then FAILURE ==

...

1 test failed:
test_interpreters

...

2 re-run tests:
test__xxsubinterpreters test_interpreters

AMD64 Windows8.1 Refleaks 3.x:
https://buildbot.python.org/all/#/builders/157/builds/218

2:51:27 load avg: 3.54 [275/423/2] test__xxsubinterpreters crashed (Exit code 3221225477) -- running: test_regrtest (2 hour 49 min), test_distutils (1 min 56 sec), test_pydoc (1 min 36 sec)
beginning 6 repetitions
123456
...Windows fatal exception: access violation

Thread 0x000004dc (most recent call first):
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 766 in setUp
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 547 in _callSetUp
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 589 in run
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 653 in __call__
(...)

The test still fails randomly: AMD64 Windows8.1 Refleaks 3.8
https://buildbot.python.org/all/#/builders/200/builds/48

test_subinterpreter failed twice on Refleaks which runs tests 6 times in a row.

First run:

0:33:58 load avg: 4.78 [204/423/1] test__xxsubinterpreters failed -- running: test_multiprocessing_spawn (12 min 42 sec), test_io (7 min 28 sec), test_tarfile (39.2 sec)
beginning 6 repetitions
123456
...Exception in thread Thread-38:
Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\threading.py", line 932, in _bootstrap_inner
    self.run()
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 51, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 250
test test__xxsubinterpreters failed -- Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 495, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

Second run:

FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\buildarea\3.8.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 495, in test_subinterpreter
    self.assertTrue(interpreters.is_running(interp))
AssertionError: False is not true

Recent test_still_running() failure on AMD64 Windows8.1 Refleaks 3.10:
https://buildbot.python.org/all/#/builders/638/builds/19

1:22:17 load avg: 3.00 [393/427/2] test__xxsubinterpreters failed -- running: test_pydoc (9 min 7 sec), test_venv (2 min 54 sec), test_dbm_dumb (1 min 12 sec)
beginning 6 repetitions
123456
.Warning -- Uncaught thread exception: RuntimeError
Exception in thread Thread-16 (run):
Traceback (most recent call last):
  File "D:\buildarea\3.10.ware-win81-release.refleak\build\lib\threading.py", line 1006, in _bootstrap_inner
    self.run()
  File "D:\buildarea\3.10.ware-win81-release.refleak\build\lib\threading.py", line 943, in run
    self._target(*self._args, **self._kwargs)
  File "D:\buildarea\3.10.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 46, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 125
test test__xxsubinterpreters failed -- Traceback (most recent call last):
  File "D:\buildarea\3.10.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 753, in test_still_running
    self.assertTrue(interpreters.is_running(interp),
AssertionError: False is not true : Interp 125 should be running before destruction.

OK, I try to take a look after Kyle leaves temporarily. But I haven't replicate this issue in my vm in recent days :(

I use this add_printf_to_get_details_from_race_condition.patch to get some details of the running subinterpreter.

The successful output of test_already_running:
test_already_running (test.test__xxsubinterpreters.RunStringTests) ... In interp_create, the current state is: 0x23ee8f0
In interp_list_all, the current state is: 0x23ee8f0 # Entering _running().
Before interp runs, the current state is: 0x2489590 # Running the interp in thread.
In interp_list_all, the current state is: 0x23ee8f0 # Running interpreters.list() in _running().
Before interp runs, the current state is: 0x23ee8f0 # Running the interp in test_already_running().
After interp runs, the current state is: 0x25cf0e0 # Running the interp in thread.
In interp_list_all, the current state is: 0x23ee8f0 # Clearing the created interps.

The failed output of test_already_running:
test_already_running (test.test__xxsubinterpreters.RunStringTests) ... In interp_create, the current state is: 0x23e58f0
In interp_list_all, the current state is: 0x23e58f0
In interp_list_all, the current state is: 0x23e58f0 # Compared to the successful output of test_already_running, the interp doesn't run in time.
Before interp runs, the current state is: 0x23e58f0
spam
After interp runs, the current state is: 0x24fdfc0
In interp_list_all, the current state is: 0x23e58f0
FAIL

======================================================================
FAIL: test_already_running (test.test__xxsubinterpreters.RunStringTests)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/shihai/cpython/Lib/test/test__xxsubinterpreters.py", line 835, in test_already_running
    with self.assertRaises(RuntimeError):
AssertionError: RuntimeError not raised

Ran 123 tests in 71.968s

FAILED (failures=1, skipped=6)
Warning -- Uncaught thread exception: RuntimeError
Exception in thread Thread-8 (run):
Traceback (most recent call last):
  File "/home/shihai/cpython/Lib/threading.py", line 1009, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/home/shihai/cpython/Lib/threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/shihai/cpython/Lib/test/test__xxsubinterpreters.py", line 49, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 60
test test__xxsubinterpreters failed.

According to above details, there are several possible explanations:
1.Some race condition break the opcode execution order.
I checked the eval function. I didn't find that any condition will disrupt the execution order.
2.The running thread hasn't get the GIL in time.
"RuntimeError: unrecognized interpreter ID 60" proves that the interp has been executed in _running(), but later than the test_already_running. So I creates PR 26598. But I catch the error again with PR 26598.
3.the running thread can't get the time slice of CPU.
By running python with add_printf_to_get_details_from_race_condition.patch, I find that the thread created in _running() has be executed, but the interp hasn't been executed immediately in run(). At the same time, the done.set() has been executed in run(), so I guess the real reason is the thread created in _running() hasn't get the time slice of CPU to run interp in run() in multiprocess.

Pls correct me if I am wrong.

Navigation Menu

Repository navigation

[subinterpreters] test__xxsubinterpreters fails randomly #81405

32 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

[subinterpreters] test__xxsubinterpreters fails randomly #81405

Description

Activity

vstinner commented on Jun 11, 2019

vstinner commented on Jun 11, 2019

vstinner commented on Jun 11, 2019

vstinner commented on Jun 12, 2019

vstinner commented on Jul 8, 2019

aeros commented on Sep 16, 2019

aeros commented on Sep 16, 2019

aeros commented on Sep 16, 2019

aeros commented on Sep 16, 2019

aeros commented on Sep 16, 2019

aeros commented on Sep 17, 2019

aeros commented on Sep 20, 2019

vstinner commented on Oct 14, 2019

32 remaining items

aeros commented on Mar 12, 2020

koobs commented on Jun 10, 2020

vstinner commented on Jun 29, 2020

vstinner commented on Oct 1, 2020

vstinner commented on Jun 3, 2021

shihai1991 commented on Jun 3, 2021

shihai1991 commented on Jul 19, 2021

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions