[Free Threading] test_external_inspection: flaky "[WinError 299] Only part of a ReadProcessMemory or WriteProcessMemory request was completed" error on GHA Windows CI

[vstinner]

Bug report

I saw this error twice today.

Windows (free-threading) / Build and test (x64, tail-call): https://github.com/python/cpython/actions/runs/36895107589/job/110480146055?pr=158040

FAIL: test_tlbc_cache_refresh_after_growth (test.test_external_inspection.TestGetStackTrace.test_tlbc_cache_refresh_after_growth)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\cpython\cpython\Lib\test\test_external_inspection.py", line 2384, in test_tlbc_cache_refresh_after_growth
    self.assertEqual(
    ~~~~~~~~~~~~~~~~^
        result.returncode, 0,
        ^^^^^^^^^^^^^^^^^^^^^
        f"stdout: {result.stdout}\nstderr: {result.stderr}",
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
AssertionError: 1 != 0 : stdout: 
stderr: OSError: [WinError 299] Only part of a ReadProcessMemory or WriteProcessMemory request was completed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<string>", line 38, in <module>
    wait_for_leaf_frames(u, 2)
    ~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "<string>", line 17, in wait_for_leaf_frames
    traces = u.get_stack_trace()
OSError: ReadProcessMemory failed for PID 2764 at address 0x1 (size 80, partial read 0 bytes): Windows error 299

cc @pablogsal

CPython versions tested on:

CPython main branch

Operating systems tested on:

Windows

Linked PRs

• gh-158574: Stabilize TLBC cache refresh tests #158801
• [3.15] gh-158574: Stabilize TLBC cache refresh tests (GH-158801) #158817
• [3.14] gh-158574: Stabilize TLBC cache refresh tests (GH-158801) #158818

[vstinner]

So far, I failed to reproduce the issue on my Windows 11 VM by running:

python -m test test_external_inspection -v -m test_tlbc_cache_refresh_after_growth

[vstinner]

On my Windows VM, 4 test_external_inspection tests fail:

======================================================================
FAIL: test_empty_native_thread_stack (test.test_external_inspection.TestGetStackTrace.test_empty_native_thread_stack) (cache_frames=False, native=False)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 1706, in test_empty_native_thread_stack
    _get_stack_trace_with_retry(
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^
        unwinder, condition=lambda trace: len(trace[0].threads) == 2,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 267, in _get_stack_trace_with_retry
    for _ in busy_retry(timeout):
             ~~~~~~~~~~^^^^^^^^^
  File "C:\victor\python\main\Lib\test\support\__init__.py", line 2796, in busy_retry       
    raise AssertionError(msg)
AssertionError: timeout (30.0 seconds)

======================================================================
FAIL: test_empty_native_thread_stack (test.test_external_inspection.TestGetStackTrace.test_empty_native_thread_stack) (cache_frames=False, native=True)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 1706, in test_empty_native_thread_stack
    _get_stack_trace_with_retry(
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^
        unwinder, condition=lambda trace: len(trace[0].threads) == 2,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 267, in _get_stack_trace_with_retry
    for _ in busy_retry(timeout):
             ~~~~~~~~~~^^^^^^^^^
  File "C:\victor\python\main\Lib\test\support\__init__.py", line 2796, in busy_retry       
    raise AssertionError(msg)
AssertionError: timeout (30.0 seconds)

======================================================================
FAIL: test_empty_native_thread_stack (test.test_external_inspection.TestGetStackTrace.test_empty_native_thread_stack) (cache_frames=True, native=False)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 1706, in test_empty_native_thread_stack
    _get_stack_trace_with_retry(
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^
        unwinder, condition=lambda trace: len(trace[0].threads) == 2,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 267, in _get_stack_trace_with_retry
    for _ in busy_retry(timeout):
             ~~~~~~~~~~^^^^^^^^^
  File "C:\victor\python\main\Lib\test\support\__init__.py", line 2796, in busy_retry       
    raise AssertionError(msg)
AssertionError: timeout (30.0 seconds)

======================================================================
FAIL: test_empty_native_thread_stack (test.test_external_inspection.TestGetStackTrace.test_empty_native_thread_stack) (cache_frames=True, native=True)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 1706, in test_empty_native_thread_stack
    _get_stack_trace_with_retry(
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~^
        unwinder, condition=lambda trace: len(trace[0].threads) == 2,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "C:\victor\python\main\Lib\test\test_external_inspection.py", line 267, in _get_stack_trace_with_retry
    for _ in busy_retry(timeout):
             ~~~~~~~~~~^^^^^^^^^
  File "C:\victor\python\main\Lib\test\support\__init__.py", line 2796, in busy_retry       
    raise AssertionError(msg)
AssertionError: timeout (30.0 seconds)

----------------------------------------------------------------------
Ran 45 tests in 159.956s

FAILED (failures=4, skipped=2)
test test_external_inspection failed

[maurycy]

I'm not a Windows expert by any means (and I have no way to reproduce, so I won't take this one), but the 0x1 address caught my attention, and 80 is very round suggesting some sizeof:

OSError: ReadProcessMemory failed for PID 2764 at address 0x1 (size 80, partial read 0 bytes): Windows error 299

Obviously, perhaps we should use TRANSIENT_ERRORS in this (and more) external inspection tests. That won't fix test_empty_native_thread_stack timeouts which are separate problems, though.

[vstinner]

Another example on "AMD64 Windows PGO NoGIL Tailcall PR" buildbot: https://buildbot.python.org/#/builders/1869/builds/163

FAIL: test_tlbc_cache_refresh_after_slot_fill (test.test_external_inspection.TestGetStackTrace.test_tlbc_cache_refresh_after_slot_fill)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\bbarea\pull_request.itamaro-win64-srv-22-aws.nogil.tailcall.pgo\build\Lib\test\test_external_inspection.py", line 2446, in test_tlbc_cache_refresh_after_slot_fill
    self.assertEqual(
    ~~~~~~~~~~~~~~~~^
        result.returncode, 0,
        ^^^^^^^^^^^^^^^^^^^^^
        f"stdout: {result.stdout}\nstderr: {result.stderr}",
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
AssertionError: 1 != 0 : stdout: 
stderr: OSError: [WinError 299] Only part of a ReadProcessMemory or WriteProcessMemory request was completed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<string>", line 40, in <module>
    cached = lines(u, 2)
  File "<string>", line 18, in lines
    traces = u.get_stack_trace()
OSError: ReadProcessMemory failed for PID 11328 at address 0x1 (size 80, partial read 0 bytes): Windows error 299


----------------------------------------------------------------------
Ran 1 test in 0.088s

FAILED (failures=1)

[itamaro]

fwiw we're hitting this in our internal CI too, on macOS arm64 free-threaded 3.14 builds (mach_vm_read_overwrite failed ... address 0x1 (size 80), and garbled UnicodeDecodeErrors), so it's not Windows-only.

it also shows up on the macOS and centos9 buildbots, e.g. https://buildbot.python.org/#/builders/1714/builds/1678, https://buildbot.python.org/#/builders/1610/builds/4084.

It repros on Linux under load: 19/960 runs fail on main (free-threaded debug build, 32 parallel loops). With gh-158801 it's 0/2880, and 0/1920 on 3.14 with a small backport (no InterpreterInfo, f.lineno, no cache_frames).

+1 to gh-158801, and I think it should be backported to 3.15 and 3.14 :)