Log which channel failed when a test item times out

[davidanthoff]

Why

This CI run failed with a test item reported as a one-hour timeout that had actually passed 17/17 in 9.8 seconds:

99 tests ran, 98 passed, 1 errored.
  [ERROR] Luenb. estimator methods
    Test Summary:                        | Pass  Total  Time
    …:Luenb. estimator methods           |   17     17  9.8s
    Test item 'Luenb. estimator methods' timed out after 3600.0 seconds

The test process was healthy the whole hour. Reconstructed from the run's artifacts:

time	event
22:48:13	process eaff155c reports the previous item passed — its last message the controller ever processed
22:48:14	controller handles started(Luenb. estimator methods), arms the 3600 + 10 s deadline
~22:48:24	the process finishes the item (17/17, 9.8 s), disarms its watchdog, calls JSONRPC.send(…, passed, …)
~22:48:35	the same process runs the next item and passes it 4/4 in 1.5 s
22:48 → 23:48	the other two processes report normally throughout; only this one is silent to the controller
23:48:24	the deadline fires — item errored, process killed

Its stdout kept flowing (both test summaries are in the run's captured process_outputs), and it disarmed its own hang watchdog normally, which means run_testitem returned and execution reached the JSONRPC.send on the very next line. Nothing was stolen, nothing crashed, nothing restarted. What went silent was the JSON-RPC socket, and neither side logged anything.

What this changes

A test process talks to the controller over two independent channels: the JSON-RPC socket carrying every result, and the stdout/stderr pipes carrying captured output. The controller's per-item timer is the sole authority on whether an item is still running, so a timeout only ever proves that the result never arrived — never that the item is still executing. Which of the two channels went quiet is exactly what separates "the test hung" from "the connection died", and nothing in the log said which.

The timeout warning now carries that evidence: seconds since the last JSON-RPC message from the process, seconds since its last output, whether the process's own hang watchdog left a diagnostics dump, and — via isdefined, since the compat bound still allows a JSONRPC without it — how far behind the connection's outbound queue is (julia-vscode/JSONRPC.jl#111 adds that accessor). On the incident above it would have read:

┌ Warning: Test item 'Luenb. estimator methods' timed out after 3600.0 seconds
│   seconds_since_last_message = 3600.3
│   seconds_since_last_output = 5.3
│   watchdog_dump = false

— i.e. the connection died, the test did not. Getting to that conclusion previously meant downloading the run's artifacts and reconstructing the timeline by hand.

No behaviour change. The item is still reported errored exactly as before; nothing branches on the new timestamps. The _read_diagnostics call moved above the warning so it can report whether a dump exists, which is the only reordering.

Deliberately not in this PR

Making the controller recover — telling "the item hung" apart from "the result was lost" and re-running the item on a healthy process instead of failing it — is what would have turned that run green, but it needs a second source of truth about process progress (a status probe on timeout, a periodic heartbeat, or extending the worker's existing watchdog thread, which already has a file channel that survives both a wedged main thread and a broken connection). That is a separate design question; these diagnostics are what tell us which mechanism to build if it recurs.

Testing

Pkg.test(): 1036 passed, 0 failed, 1 errored, against a baseline on origin/main of 1034 passed, 0 failed, 1 errored. The single error is identical in both — ArgumentError: Package Logging not found in current path at test_worker_lifecycle.jl:235 — a pre-existing missing test-target dependency, untouched by this change and worth a separate one-line fix.

test_timeout.jl goes 7 → 17 assertions: the new test item covers the unknown-yet, connection-died and genuine-hang shapes, and that the result splats into the log call the way the handler uses it.

One thing worth noting for review: test_jsonrpc_controller.jl reported 73 assertions on baseline and 65 on this branch. That is not a regression — its count is timing-dependent (it loops for n in started … @test, so how many notifications land inside its sleep window varies). Re-running that file alone three times per worktree gave 81/84/68 on this branch and 71/77/75 on baseline, all passing.

🤖 Generated with Claude Code