Log which channel failed when a test item times out

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 `<testsuite>` per source file and one `<testcase>` per (item × run profile); captured output goes to `<system-out>` with ANSI escape sequences stripped, and performance statistics become `<properties>`. It is a pure function of a `TestrunResult`, so a result file written by one process can be converted by another.

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
 

src/testitemcontroller.jl

@@ -231,7 +231,7 @@
     end
 
     # Shutdown all processes
     for (pid, ps) in c.test_processes
         if state(ps.fsm) != ProcessDead
             _shutdown_test_process!(c, ps)
         end
@@ -1528,6 +1528,46 @@
     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
+<https://github.com/JuliaControl/ModelPredictiveControl.jl/actions/runs/32420160289>, 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 @@
     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

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
 

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