Windows API lane hangs in the MCP concurrency tests and has cancelled every nightly since 20 August

[sunt05]

Every scheduled run of build-publish_to_pypi.yml from 20 August to 7 September (19 runs, e.g. 34075203398, 34005586564, 33938085189) ends cancelled after about an hour. In each run the three Windows API cross-CPython tests jobs (cp312, cp313, cp314) reach the 45-minute timeout-minutes in test-api-cross-python-reusable.yml (#1563) while every Linux and macOS job passes.

The Windows cp312 log of run 34075203398 reports 1849 test results, the last being test/mcp/test_protocol_handshake.py::test_prompts_advertise_all_three at 02:49:58, and then nothing until the cancellation at 03:14:17. The next node in collection order is test_concurrent_query_knowledge_does_not_block_event_loop, followed by test_concurrent_query_knowledge_and_search_schema. Both are marked slow, so they run only in the all tier, and both pass on Linux and macOS in the same run in 2.5 to 4.7 s. #1709 (19 August) is what made them run against the installed suews-mcp executable; the last green nightly is 19 August. The cp314 Windows job stops at the same test.

Consequences so far:

• No TestPyPI dev build since 2026.8.19.dev0.
• No Windows API coverage for 19 days: the all tier on Windows (cp312, cp313, cp314) is also the only place the UMEP/QGIS lane runs. The Linux and macOS API jobs completed green in the same runs.
• Physics coverage is unaffected: -m "physics and slow and not core" collects nothing, so the nightly's physics tier selects the same 166 tests as the merge queue.
• Nothing reports a failed scheduled run; the observability job runs only on pull_request and merge_group.

This is a defect on Windows, not a case for a platform skip or a longer cap: the same two tests finish in seconds on the other platforms, and Windows API coverage is coverage the project wants. Two things to fix, and one to add:

1. The hang. Reproduce on a Windows workflow_dispatch with tier all and only the Windows platform. Both tests spawn the suews-mcp server over stdio and gather two tool calls, so the candidates are the stdio client on the Windows proactor event loop, a server subprocess that does not exit so the session teardown blocks, or the worker thread the tool bodies offload to (fix(mcp): offload sync tool bodies to a worker thread (closes #1412) #1439) never returning on Windows. Fix the cause in suews_mcp or the test harness.
2. The wider Windows time gap. On identical node sets Windows takes 789 s where Linux takes 541 s in the merge queue, and 1206 to 1324 s where Linux takes 860 to 1075 s in the last green nightly. Profile the Windows lane (subprocess spawn cost, temporary-directory I/O, path resolution) and fix what is found rather than budgeting for it; the 45-minute cap should stop being load-bearing.
3. Detection. A per-test timeout via pytest-timeout (thread method; the signal method is Unix-only) so a hang is reported with the test's name instead of hidden by a job cancellation, and a final job on schedule runs that opens or updates a pinned issue when any job fails or is cancelled and closes it on the next green run.

[sunt05]

First Windows run with per-test stack dumps: run 34213324788, workflow_dispatch, Windows only, tier all, branch of #1763 at bf78158 (master 52c41b6 plus the timeout configuration). The Windows build and its physics tier passed in 17 min. The API lane (job 102024135955) stopped after 17 min, and not at the MCP tests.

Where it stopped. test/core/test_parallel_error_isolation.py::test_parallel_output_matches_serial (added by #1742, marked xfail for gh#1741). It started at 10:26:40Z after test_valid_batch_after_failure_runs_clean passed; the faulthandler dump fired at 10:31:40Z (5 min) and pytest-timeout ended the process at 10:36:41Z (10 min). Both dumps show the same main-thread stack:

test/core/test_parallel_error_isolation.py, line 131, in test_parallel_output_matches_serial
    assert bytes(out_p) == bytes(out_s)
_pytest/assertion/rewrite.py, line 498, in _call_reprcompare
_pytest/assertion/__init__.py, line 226, in pytest_assertrepr_compare
_pytest/assertion/util.py, line 197, in assertrepr_compare
_pytest/assertion/_compare_any.py, line 76, in _compare_eq_any
_pytest/assertion/_compare_sequence.py, line 34, in <genexpr>
    line.rstrip() for line in difflib.ndiff(right_formatting, left_formatting)
difflib.py, line 872, in compare ... line 957, in _fancy_replace ... line 997, in _fancy_helper (repeated)
difflib.py, line 939, in _fancy_replace
    cruncher.ratio() > best_ratio:
difflib.py, line 619, in ratio / line 454, in get_matching_blocks / line 385, in find_longest_match

The second thread in the dump is the pytest-timeout timer. So the assertion fails, as the xfail expects, and the time goes into pytest's assertion explanation: difflib.ndiff over the pretty-printed reprs of two multi-megabyte byte strings, which is quadratic in the number of differing lines. On this Windows runner it does not finish in ten minutes. The compiled kernel is not involved after the two runs return.

What this means for the nightly. This test is api and core without slow, so it is in the standard tier as well as all: since #1742 merged on 7 September, every Windows API lane, including the merge queue, has been exposed to it. Before #1763 that would have shown as a 45-minute cancellation with no trace; with #1763 it is a named failure with the stack above at 10 minutes. The CI-metrics artefact for the lane is lost when the process ends this way, which is a limitation to note, not a blocker.

Not yet reproduced. The two MCP concurrency tests were never reached in this run, so the original hang behind the 20 August to 7 September cancellations is still unreproduced under stack capture. The next Windows run needs the assertion above fixed first (compare the arrays with numpy.array_equal and report the first differing index, so a failing comparison explains itself in constant time); that fix is a separate small PR, tracked from here.

[sunt05]

Second Windows run, this time reaching the MCP tests: run 34220818899, workflow_dispatch, Windows only, tier all, #1763's branch at db16f30 (master with #1767 merged in). Windows build and physics tier green in 13 min; API lane (job 102047130970) failed at 12:15:00Z.

Reproduced. The five handshake tests passed at 12:05:00Z (absolute suews-mcp path, 30 s read timeout, list-type requests only). test_concurrent_query_knowledge_does_not_block_event_loop started at 12:05:00Z and never returned: faulthandler dump at 12:10:00Z, pytest-timeout dump at 12:15:00Z, identical frames.

Where the client is. The main thread is inside asyncio.run(...) from test_protocol_handshake.py:361, in the event loop's poll:

asyncio/windows_events.py, line 774, in _poll
    status = _overlapped.GetQueuedCompletionStatus(self._iocp, ms)
asyncio/windows_events.py, line 445, in select
asyncio/base_events.py, line 1961, in _run_once
asyncio/base_events.py, line 645, in run_forever
asyncio/runners.py, line 118, in run
test/mcp/test_protocol_handshake.py, line 361, in test_concurrent_query_knowledge_does_not_block_event_loop
    baseline, envelopes, elapsed = asyncio.run(

The only other thread is the pytest-timeout timer. The client is idle, waiting for stdio I/O that never arrives; nothing is spinning on the client side.

What the server did. Captured stderr from the server subprocess holds exactly one line of substance:

[09/08/26 12:05:01] INFO     Processing request of type CallToolRequest    server.py:733

That is the first tool call the test makes, the single warm-up query_knowledge baseline that precedes the concurrent gather. It was received by the server within a second of the test starting and no response was written in the following ten minutes. The concurrency part of the test was never reached.

What this narrows. The blocked operation is the server side of one query_knowledge call over stdio on Windows, in the suews-mcp process launched by the bare command name with the test's custom env (the SDK passes only its allow-listed variables plus that dictionary). The same tool completes in-process on Windows (test_real_cli_smoke.py::test_query_knowledge_returns_provenance_metadata passed in this lane), and the server itself answers list-type requests over the same transport. So the difference sits between "server received CallToolRequest" and "server wrote the response": the tool body's run_suews_cli subprocess under that environment, or the response path back to stdio. The server's own CLI timeout is 600 s, the same as the per-test budget, so a stalled CLI subprocess would not surface as an error envelope before the test is ended. A server-side dump (a timer in the server process that writes all thread stacks to stderr, with the flag passed explicitly through StdioServerParameters.env) is the next capture; the full job log is preserved for that analysis.

[sunt05]

Third Windows run, with a server-side stack capture inside suews-mcp (opt-in, enabled through StdioServerParameters.env, commit 3db2554 on branch sunt05/fix-windows-mcp-hang): run 34349161574, Windows cp312, tier all, API job 102462904159. Same client picture as before (idle in the IOCP poll, first CallToolRequest received at 12:41:31Z, per-test timeout at 12:51:30Z). The server dump names the blocked operation.

Server process (pid 5820), every 60 s the same stack. The AnyIO worker thread running query_knowledge has already run the suews knowledge query subprocess and is post-processing its results:

numpy/_core/multiarray.py, line 11 in <module>          <- create_module of numpy's compiled _multiarray_umath: never returns
numpy/_core/__init__.py, line 24 in <module>
numpy/__config__.py, line 4 in <module>
numpy/__init__.py, line 122 in <module>
supy/data_model/core/config.py, line 25 in <module>
supy/data_model/core/__init__.py, line 8 in <module>
supy/data_model/__init__.py, line 15 in <module>
suews_mcp/tools/knowledge.py, line 95 in _legacy_names_in_text   <- lazy import of supy.data_model.core.field_renames
suews_mcp/tools/knowledge.py, line 116 in _annotate_match
suews_mcp/tools/knowledge.py, line 159 in _apply_size_policy
suews_mcp/tools/knowledge.py, line 276 in query_knowledge
anyio/_backends/_asyncio.py, line 1100 in run            <- worker thread

The other threads: the main thread idle in asyncio/windows_events.py _poll inside FastMCP.run; a second AnyIO worker idle; the diagnostic reporter thread. No thread is running a subprocess for the tool; the CLI child had completed.

So the blocked operation is the import of numpy's compiled extension module, triggered lazily by _legacy_names_in_text importing supy.data_model.core.field_renames, executed on an AnyIO worker thread of the MCP server on Windows. read_knowledge_manifest, the list-type requests and the in-process CLI paths never take that lazy import, which is why they pass. A real MCP client on Windows hits exactly this on its first query_knowledge.

The mechanism of the load never completing (the DLL loader lock against a thread created during numpy or OpenBLAS initialisation, or the import lock held elsewhere) is the remaining question; the fix direction is to stop importing the data model, and with it numpy, lazily on a worker thread: import what _legacy_names_in_text needs when the server starts on the main thread, or read the rename registry without pulling in the data model. Verification is a Windows dispatch in which both concurrency tests pass.

[sunt05]

Cause

The server-side stack capture (run 34349161574, Windows cp312 job 102462904159) identifies the blocked call. All nine one-minute dumps between 12:41 and 12:51 are identical:

Thread 0x00000df0 (the anyio worker running the tool body):
  <frozen importlib._bootstrap_external>, line 1293 in create_module
  ...
  numpy/_core/multiarray.py, line 11 in <module>
  numpy/__init__.py, line 122
  supy/data_model/core/config.py, line 25
  supy/data_model/__init__.py, line 15
  suews_mcp/tools/knowledge.py, line 95 in _legacy_names_in_text
  suews_mcp/tools/knowledge.py, line 116 in _annotate_match
  suews_mcp/tools/knowledge.py, line 159 in _apply_size_policy
  suews_mcp/tools/knowledge.py, line 276 in query_knowledge
  anyio/_backends/_asyncio.py, line 1100 in run

The main thread is idle in the proactor poll, and the suews knowledge query subprocess had already completed - the stall is entirely in result post-processing.

query_knowledge annotates each match with the legacy field names it mentions (#1402), which needs ALL_FIELD_RENAMES from supy's data-model layer. That import was made lazily inside the tool body, and FastMCP dispatches tool bodies onto an anyio worker thread (#1412). It pulls in the whole data model and, with it, numpy: about 630 modules and several compiled extensions. read_knowledge_manifest and the handshake requests never touch the data model, which is why the handshake tests pass and this one does not.

create_module here is LoadLibraryExW on numpy's _multiarray_umath, and it never returns. Two observations pin it to the Windows loader rather than to CPython's import machinery:

• In the same dumps, an unrelated thread's threading.Thread.start() also never returns, waiting on the new thread's _started event. A new thread cannot begin running until it has completed DLL_THREAD_ATTACH, which requires the loader lock; so the loader lock is held for the whole ten minutes by the thread doing the load. A stall in CPython's per-module import lock would leave thread creation unaffected.
• The identical import on the main thread of the same interpreter, on the same machine and in the same job, completes in about a second: test/mcp/test_canonical_questions.py runs 19 in-process query_knowledge calls through this exact code path in 23 seconds (12:04:34Z to 12:04:57Z).

Once the loader is wedged, every later query_knowledge call blocks on the same module lock, so the session never recovers. This is not a test artefact: a real MCP client on Windows loses the tool for the life of the server on its first call.

Fix

#1771 loads the rename registry once, eagerly, during server start-up on the main thread, before FastMCP builds its event loop and worker-thread pool. Tool bodies then only read the cached mapping, so no worker thread imports a compiled extension. The temporary capture instrumentation is reverted in the same PR.

Windows verification run for the fix: 34357532223.

[sunt05]

The hang is fixed by #1771 (merged ce29700). Cause: query_knowledge lazily imported supy.data_model.core.field_renames inside the tool body, which runs on an anyio worker thread; on Windows the numpy extension load in that import never returned (stack capture above). The registry is now loaded once in _build_server on the calling thread, and tool bodies read the cache.

Verified on Windows cp312 with the API all tier: runs 34357532223 and 34362146566 both pass (2132 passed, 7 skipped, 1 xfailed; both concurrency tests green).

What remains of this issue is the second item, the Windows API-lane time gap: the lane took 23 min in both verification runs against 9 to 13 min for the same nodes on Linux and macOS. Detection (#1763: per-test timeout with stacks; #1764: scheduled-run report) is in place, so a recurrence now fails the job with the culprit named rather than hitting the cap. Leaving this open for the profiling of that gap.

[sunt05]

Closing: both items are resolved.

1. The hang: fixed by Load the field-rename registry at server start, not on a worker thread #1771 (the field-rename registry loaded at server start rather than lazily on a worker thread). Every Windows API lane has been green since, including the nightly of 10 September, the first green scheduled run since 19 August (Nightly scheduled run is failing #1768 closed on it). Cap each request in the MCP concurrency tests at 120 s #1772 adds a 120 s per-request ceiling to the two concurrency tests so a silent server fails the test by name rather than running to the job cap, and Make the MCP concurrency tests measure serial-versus-concurrent contrast #1793 makes those tests measure completion spread rather than a fixed wall-clock factor.

2. The wider Windows time gap: measured on identical node ids in Convert each legacy table set once per pytest session, not once per test #1791. Windows costs 1.35x Linux almost uniformly across every test file (1.37 to 1.48x), so runner speed explains the gap and no test pattern does; the one file materially above that ratio, the legacy-table round-trip at 1.66x, now converts each table set once per session (194 s to 169 s on Windows). The remaining uniform factor is the runner, not the suite. With the API lane on xdist workers (Measure the api lane serial against xdist workers on all three platforms #1786 measured, Run the api lane on xdist workers per platform with a serial escape hatch #1788 switches), the Windows lane drops from 23 min serial to 12 min.

Refs #1771, #1772, #1786, #1788, #1791, #1793.