[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']

[vstinner]

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

[vstinner]

See bpo-33356.

[vstinner]

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

[vstinner]

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.

[vstinner]

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

[aeros]

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.

[aeros]

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.

[aeros]

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

[aeros]

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.

[aeros]

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...)

[aeros]

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.

[aeros]

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.

[vstinner]

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: ...