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