From 6b2f6f6440973817b82a8eebe4a833407c88b891 Mon Sep 17 00:00:00 2001 From: David Anthoff Date: Thu, 20 Aug 2026 22:42:38 -0700 Subject: [PATCH] Log which channel failed when a test item times out MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A test item that had passed 17/17 in 9.8 seconds was reported as having timed out after 3600 seconds, failing a CI leg: https://github.com/JuliaControl/ModelPredictiveControl.jl/actions/runs/32420160289 The test process was healthy throughout. Its stdout kept flowing to the controller — both that item's test summary and the *next* item's are in the run's captured process output — and it disarmed its own hang watchdog normally, meaning `run_testitem` returned and reached the `JSONRPC.send` on the very next line. What went silent was the JSON-RPC socket: every result the process sent after `started(…)` was lost, on a connection whose output pipe was fine, and neither side logged a thing. A test process talks to the controller over two independent channels, and the controller's per-item timer is the sole authority on whether an item is still running. A timeout therefore only ever proves that the *result* never arrived — never that the item is still executing. Which of the two channels went quiet is what separates "the test hung" from "the connection died", and nothing in the log said. 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 watchdog left a diagnostics dump, and — on a JSONRPC that can report it — how far behind the connection's outbound queue is. On the incident above it would have read seconds_since_last_message = 3600.3 seconds_since_last_output = 5.3 watchdog_dump = false instead of "your test hung". Reconstructing that took the run's artifacts after the fact. No behaviour change: the item is still reported errored exactly as before, and nothing branches on the new timestamps. `outbound_backlog` is reached through `isdefined`, because the compat bound still allows a JSONRPC without it. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 1 + src/state.jl | 10 +++++++ src/testitemcontroller.jl | 55 ++++++++++++++++++++++++++++++++++----- src/testprocess.jl | 5 ++++ test/test_timeout.jl | 39 +++++++++++++++++++++++++++ 5 files changed, 104 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0ce550f..4ea1fe3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- A test item timeout is now logged with the evidence for *which* channel failed: how long it has been since the test process last sent a JSON-RPC message, how long since it last produced output, whether the process's own hang watchdog left a diagnostics dump, and — on a JSONRPC that can report it — how far behind the connection's outbound queue is. A test process talks to the controller over two independent channels, and a timeout only ever proves that the *result* never arrived. Output still arriving while the socket has gone quiet means the connection died, not the test; before this the two were indistinguishable without reconstructing the run from its artifacts afterwards. - An environment activation that has not finished is now reported with a warning naming the test process and how long it has been waiting, repeating every `activation_progress_seconds` (a new `TestItemController` keyword, default 120). Activation covers the test process's own precompilation, so a slow one is legitimate and is not interrupted — but a run that stalls there no longer goes silent between the `Activating` status and whatever eventually gives up. - The JSON-RPC protocol gained a client → controller `shutdown` notification for a graceful shutdown: every run is cancelled, every test process is terminated (force-killed if it does not exit within the grace period) and the controller exits once they are gone. - `write_junit_xml(io_or_path, ::TestrunResult; root)` writes a test run as JUnit XML, the one report format every CI system ingests. Test items are grouped into one `` per source file and one `` per (item × run profile); captured output goes to `` with ANSI escape sequences stripped, and performance statistics become ``. It is a pure function of a `TestrunResult`, so a result file written by one process can be converted by another. diff --git a/src/state.jl b/src/state.jl index 259e0eb..836f63c 100644 --- a/src/state.jl +++ b/src/state.jl @@ -42,6 +42,14 @@ mutable struct TestProcessState # Exit info captured when the OS process dies (set in _launch_julia_process! catch) last_exit_code::Union{Nothing,Int} last_term_signal::Union{Nothing,Int} + # Last time anything was heard from this process, on each of its two independent + # channels: the JSON-RPC socket that carries every result, and the stdout/stderr pipes + # that carry captured output. Diagnostics only — nothing branches on these. They exist + # because the two can diverge: a process whose socket has gone silent while its output + # still flows is a broken connection, not a hung test, and without both timestamps that + # distinction is invisible in the log. + last_message_at::Union{Nothing,Float64} + last_output_at::Union{Nothing,Float64} end function TestProcessState(id::String, env::ProcessEnv; @@ -76,6 +84,8 @@ function TestProcessState(id::String, env::ProcessEnv; Dict{Tuple{String,String},@NamedTuple{output::String, duration::Union{Nothing,Float64}}}(), # loaded_setups nothing, # last_exit_code nothing, # last_term_signal + nothing, # last_message_at + nothing, # last_output_at ) end diff --git a/src/testitemcontroller.jl b/src/testitemcontroller.jl index 7b5bfe8..8a3c82f 100644 --- a/src/testitemcontroller.jl +++ b/src/testitemcontroller.jl @@ -1528,6 +1528,46 @@ function _handle_termination_during_run!(c::TestItemController, msg::TestProcess return end +# The outbound half of a process's JSON-RPC connection, when the JSONRPC in use can report +# it. That queue is unbounded, so a peer that has stopped reading never makes a send fail — +# the messages simply accumulate, undelivered. Guarded by `isdefined` because the compat +# bound still allows a JSONRPC without the accessor. +function _outbound_backlog(ps::TestProcessState) + ps.endpoint === nothing && return nothing + isdefined(JSONRPC, :outbound_backlog) || return nothing + return try + JSONRPC.outbound_backlog(ps.endpoint) + catch + nothing + end +end + +""" +What the controller knows about a process at the moment one of its items timed out, as +`@warn` key/value pairs. + +A test process talks to the controller over two independent channels: the JSON-RPC socket +that carries every result, and the stdout/stderr pipes that carry captured output. A timeout +is only evidence that the *result* never arrived, and these two clocks are what separate the +cases. Output still arriving while the socket has gone quiet means the connection died, not +the test — which is exactly what happened in +, where a +test item that had passed 17/17 in 9.8 seconds was reported as a one-hour hang and the only +way to tell was to reconstruct it from the run's artifacts afterwards. +""" +function _timeout_evidence(ps::TestProcessState, diagnostics::Union{Nothing,AbstractString}) + now = time() + elapsed(t) = t === nothing ? nothing : round(now - t, digits=1) + backlog = _outbound_backlog(ps) + return ( + seconds_since_last_message = elapsed(ps.last_message_at), + seconds_since_last_output = elapsed(ps.last_output_at), + watchdog_dump = diagnostics !== nothing, + outbound_queued = backlog === nothing ? nothing : backlog.queued, + outbound_blocked_seconds = backlog === nothing ? nothing : round(backlog.blocked_seconds, digits=1), + ) +end + function handle!(c::TestItemController, msg::TestItemTimeoutMsg) if !haskey(c.test_runs, msg.testrun_id) || !haskey(c.test_processes, msg.testprocess_id) return false @@ -1553,13 +1593,16 @@ function handle!(c::TestItemController, msg::TestItemTimeoutMsg) item_label = item !== nothing ? item.label : msg.testitem_id timeout_val = wu !== nothing && wu.timeout !== nothing ? wu.timeout : "?" - @warn "Test item '$(item_label)' timed out after $(timeout_val) seconds" - - # Attach whatever the test process's watchdog managed to dump before we report the item - # as errored, so the backtrace shows up as that item's output. The dump is absent when - # the item wedged without ever reaching a GC safepoint, or when the process has no spare - # thread to run the watchdog on — both degrade to today's behaviour. + # Read before the warning, so it can report whether the process's own watchdog believed + # the item was still running. The dump is absent when the item wedged without ever + # reaching a GC safepoint, or when the process has no spare thread to run the watchdog + # on — so its absence is evidence, not proof. diagnostics = _read_diagnostics(msg.testprocess_id) + + @warn "Test item '$(item_label)' timed out after $(timeout_val) seconds" testprocess_id=msg.testprocess_id _timeout_evidence(ps, diagnostics)... + + # Attach whatever the watchdog managed to dump, so the backtrace shows up as that item's + # output. if diagnostics !== nothing c.callbacks.on_append_output(msg.testrun_id, msg.testitem_id, test_env_id, replace(diagnostics, "\n"=>"\r\n")) end diff --git a/src/testprocess.jl b/src/testprocess.jl index c6cce1e..d3b42ba 100644 --- a/src/testprocess.jl +++ b/src/testprocess.jl @@ -268,6 +268,7 @@ function start(testprocess_id, reactor_channel, ps::TestProcessState, env::Proce current_output_testitem_id = nothing while !eof(pipe_out) data = readavailable(pipe_out, token) + ps.last_output_at = time() data_as_string = String(data) # Capture raw output for crash diagnostics @@ -445,6 +446,10 @@ function start(testprocess_id, reactor_channel, ps::TestProcessState, env::Proce end @debug "Dispatching message from test server" testprocess_id method=msg.method + # Stamped here rather than in the dispatcher so it covers + # every method, including ones with no handler. + ps.last_message_at = time() + dispatch_testprocess_msg(endpoint, msg, (reactor_channel, ps)) end diff --git a/test/test_timeout.jl b/test/test_timeout.jl index 1273c36..370c82f 100644 --- a/test/test_timeout.jl +++ b/test/test_timeout.jl @@ -35,3 +35,42 @@ passed = filter(e -> e.event == :passed, result.events) @test length(passed) >= 1 end + +@testitem "Timeout warning carries the evidence for which channel failed" setup=[TestHelpers] begin + using TestItemControllers: TestProcessState, ProcessEnv, _timeout_evidence + + # A timeout only ever proves that the *result* never arrived. A test process talks to + # the controller over two independent channels — the JSON-RPC socket carrying results + # and the stdout/stderr pipes carrying output — and which of them went quiet is what + # separates "the test hung" from "the connection died". These are the numbers that make + # that visible in the log instead of only in a post-mortem of the run's artifacts. + env = ProcessEnv(nothing, "file:///tmp/BasicPackage", "BasicPackage", "julia", String[], nothing, "Normal", Dict{String,Union{String,Nothing}}()) + ps = TestProcessState("proc-1", env) + + # Nothing heard on either channel yet: reported as unknown rather than as zero. + evidence = _timeout_evidence(ps, nothing) + @test evidence.seconds_since_last_message === nothing + @test evidence.seconds_since_last_output === nothing + @test evidence.watchdog_dump == false + + # The shape that says the connection died and the test did not: the socket has been + # quiet for an hour while output arrived seconds ago, and the process's own hang + # watchdog left no dump. + now = time() + ps.last_message_at = now - 3600 + ps.last_output_at = now - 5 + evidence = _timeout_evidence(ps, nothing) + @test evidence.seconds_since_last_message >= 3600 + @test evidence.seconds_since_last_output < 60 + @test evidence.watchdog_dump == false + + # A genuine hang looks the opposite way round: the watchdog dumped at the deadline. + @test _timeout_evidence(ps, "backtrace goes here").watchdog_dump == true + + # No endpoint, so the outbound backlog is unknown — never a bogus zero. + @test evidence.outbound_queued === nothing + @test evidence.outbound_blocked_seconds === nothing + + # And the whole thing has to splat into the log call the way the handler uses it. + @test_logs (:warn,) (@warn "x" _timeout_evidence(ps, nothing)...) +end