diff --git a/CHANGELOG.md b/CHANGELOG.md index 046b4ae..24b5e7d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,10 +9,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- A test run now completes when the controller cannot spawn a test process, for example because the program in `juliaCmd` does not exist or `juliaCmd` holds a command with arguments such as `julia +1.12`. The controller now errors the queued test items with the cause ("Could not start the test process for test item '…': `…`: no such file or directory (ENOENT)") and removes the process. The spawn error only went to the log, so the process stayed in the starting state, its test items stayed pending, and a shutdown waited the full grace period for it. It was also logged as an error, which under VS Code's crash-reporting logger ended the test item controller and filed a crash report for what is a configuration mistake; it is now a warning, and the controller runs later test runs normally. - The controller now calls `on_process_terminated` (JSON-RPC: `testProcessTerminated`) for a test process that it replaces with a new one. A test run replaces a pooled process when the environment content hash changed. It also replaces a process that has no endpoint, for example when the run starts after `terminate_test_process` but before the process exits. A restart that Revise asks for also replaces the process. The controller removed the old process without a report. The termination message of the old process then found no entry, so a consumer with a list of test processes kept the old entry. - - On Julia 1.12 and later, a garbage collection in a test process no longer has to wait for the hang watchdog to wake up. The watchdog paces itself with a plain OS sleep, and that `ccall` kept its thread GC-unsafe for the full 50 ms poll interval, so every stop-the-world collection stalled until the sleep ended: 25–50 ms of extra time-to-safepoint per GC on Windows and 50–190 ms on GitHub's macOS runners, none of it counted in the GC time reported for a test item. The sleep now runs in a GC-safe region (`@ccall gc_safe=true`), which brings that delay to zero. On Windows it goes through libuv's `uv_sleep` rather than Win32 `Sleep`, because `@ccall` cannot express the `stdcall` convention `Sleep` needs on 32-bit Windows. Older Julia versions keep the previous sleep. - - A test item that uses a `@testmodule` now runs with its own file path, so `@__DIR__` and `@__FILE__` inside it resolve against its own directory and its top-level frames are attributed to its own file. The test process evaluated the `@testmodule` into the same local that holds the test item's path, so the item's body was then handed the *setup's* path — an item in `test/sub/` declaring a setup defined in `test/` loaded `joinpath(@__DIR__, "data", …)` relative to `test/`, and a failure in it was reported at the setup's file. Only the first item to evaluate a given `@testmodule` on a process was affected, because later items reuse the already-evaluated module and never take that branch, which is why this presented as order- and scheduling-dependent. The working directory was always correct, so a bare relative path was unaffected. `TestItemRunner.jl`'s in-process runner never had this bug. - Test processes running with a portable `JULIA_CPU_TARGET` (a multi-versioned target such as `generic;sandybridge,...;haswell,...`, which CI sets so a cached depot survives moving between runner CPUs) now precompile their test environment from a child Julia started on that target's base variant. The variable never changes the process it is set in — Julia reads it only when spawning precompilation workers — so a test process accepted whatever native images the depot already held, compiled only the stale packages, and handed them to workers that rejected those native images: slow nested recompilation on Julia ≤ 1.12, and on Julia 1.13, whose workers run with `--compiled-modules=strict`, a failure of every `using` in the run (`Precompiled image ... not available with flags ...`). The child rejects the same images the workers would and rebuilds them under the portable target once; activation without the variable is unchanged. - A package whose `test/` folder is a `[workspace]` member (Julia 1.12+) can now run its test items. Such a test project has no manifest of its own — it resolves against the workspace's shared one — so mirroring it into a scratch environment left `TestEnv` trying to resolve a manifest from scratch, which fails as soon as the workspace contains an unregistered path-tracked package. The test process now does what `Pkg.test` does for exactly this shape and nothing else: it activates the member project in place, instantiates it and precompiles it, refusing to run rather than resolving into the user's tree when the workspace manifest is missing. Any other `test/Project.toml`, including one with a manifest of its own that `dev`s the package, is still sandboxed as `Pkg.test` would. ([#103](https://github.com/julia-testitems/TestItemControllers.jl/pull/103)) diff --git a/src/messages.jl b/src/messages.jl index 1b7ed44..a8e0cb6 100644 --- a/src/messages.jl +++ b/src/messages.jl @@ -185,8 +185,11 @@ struct TestProcessIOErrorMsg <: ReactorMessage error_type::Symbol # :restart or :fatal exit_code::Union{Nothing,Int} term_signal::Union{Nothing,Int} + # Set when the process could not be started at all; see `TestProcessState.launch_failure`. + reason::Union{Nothing,String} end -TestProcessIOErrorMsg(id::String, error_type::Symbol) = TestProcessIOErrorMsg(id, error_type, nothing, nothing) +TestProcessIOErrorMsg(id::String, error_type::Symbol) = TestProcessIOErrorMsg(id, error_type, nothing, nothing, nothing) +TestProcessIOErrorMsg(id::String, error_type::Symbol, exit_code, term_signal) = TestProcessIOErrorMsg(id, error_type, exit_code, term_signal, nothing) struct ActivationFailedMsg <: ReactorMessage testprocess_id::String diff --git a/src/state.jl b/src/state.jl index 8b2fdf2..0714f22 100644 --- a/src/state.jl +++ b/src/state.jl @@ -42,6 +42,10 @@ 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} + # Why the controller could not start this process at all (e.g. `juliaCmd` does not + # exist), worded for the user. Set from `TestProcessIOErrorMsg`; when present, the + # queued test items are errored with it instead of being told the process crashed. + launch_failure::Union{Nothing,String} # 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 @@ -84,6 +88,7 @@ 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, # launch_failure nothing, # last_message_at nothing, # last_output_at ) diff --git a/src/testitemcontroller.jl b/src/testitemcontroller.jl index 9de2750..69949d3 100644 --- a/src/testitemcontroller.jl +++ b/src/testitemcontroller.jl @@ -1651,7 +1651,12 @@ function _handle_termination_during_run!(c::TestItemController, msg::TestProcess process_was_running = ps !== nothing && state(ps.fsm) in (ProcessRunning, ProcessIdle) if !process_was_running # True startup crash — process never ran any item. Error all queued items. - @info "Test process '$(terminated_proc_id)' crashed during startup, erroring $(length(items_to_redistribute)) queued item(s)" + launch_failure = ps === nothing ? nothing : ps.launch_failure + if launch_failure !== nothing + @info "Test process '$(terminated_proc_id)' could not be started ($(launch_failure)), erroring $(length(items_to_redistribute)) queued item(s)" + else + @info "Test process '$(terminated_proc_id)' crashed during startup, erroring $(length(items_to_redistribute)) queued item(s)" + end for testitem_id in items_to_redistribute item = _item_for_env(tr, test_env_id, testitem_id) work_key = (testitem_id, test_env_id) @@ -1665,6 +1670,8 @@ function _handle_termination_during_run!(c::TestItemController, msg::TestProcess test_env_id, TestMessage[ TestMessage( + launch_failure !== nothing ? + "Could not start the test process for test item '$(item.label)': $(launch_failure)" : "Test process crashed before running test item '$(item.label)'", nothing, nothing, @@ -2230,6 +2237,7 @@ function handle!(c::TestItemController, msg::TestProcessIOErrorMsg) # Store exit info on the process state so downstream handlers can access it. ps.last_exit_code = msg.exit_code ps.last_term_signal = msg.term_signal + msg.reason !== nothing && (ps.launch_failure = msg.reason) _kill_julia_process!(ps) @@ -2622,6 +2630,12 @@ function _launch_julia_process!(c::TestItemController, ps::TestProcessState) c.error_handler_file, c.crash_reporting_pipename, julia_version, launch_token) catch err + # `start` sends no message to the reactor for an error that occurs before its own + # error handler (a failed spawn is reported there; this is anything else, e.g. + # `Sockets.listen`). Without this message, the process stays in ProcessStarting and + # its test run does not complete. Posted before the `@error`, which under the + # crash-reporting logger ends the controller. + try put!(c.reactor_channel, TestProcessIOErrorMsg(ps.id, :fatal)) catch end @error "Error in test process IO" testprocess_id=ps.id exception=(err, catch_backtrace()) end push!(ps.process_tasks, t) diff --git a/src/testprocess.jl b/src/testprocess.jl index f89b3dc..25ec903 100644 --- a/src/testprocess.jl +++ b/src/testprocess.jl @@ -414,13 +414,29 @@ function start(testprocess_id, reactor_channel, ps::TestProcessState, env::Proce cmd_args = `$(env.juliaCmd) $(jlArgs) --startup-file=no --history-file=no --depwarn=no $coverage_arg $testserver_script $pipe_name $(debug_pipe_name) $(error_handler_file...) $(crash_reporting_pipename...)` @info "Launching Julia test server process" testprocess_id pipe_name @debug "Full launch command" testprocess_id cmd=string(cmd_args) testserver_script mode=env.mode - jl_process = open( - pipeline( - Cmd(cmd_args, detach=false, env=jlEnv), - stdout = pipe_out, - stderr = pipe_out + jl_process = try + open( + pipeline( + Cmd(cmd_args, detach=false, env=jlEnv), + stdout = pipe_out, + stderr = pipe_out + ) ) - ) + catch err + err isa Base.IOError || rethrow() + # A `juliaCmd` that cannot be run is the user's configuration, not a fault in + # the controller: say why on the test items and stay up. An `@error` here + # would take the whole controller down under the crash-reporting logger. The + # reason is built from the error code because `err.msg` embeds the entire + # environment of the command. + reason = "`$(env.juliaCmd)`: $(Base.struverror(err.code)) ($(Base.uverrorname(err.code)))" + if occursin(' ', env.juliaCmd) && !isfile(env.juliaCmd) + reason *= ". `juliaCmd` is run as a single program; pass arguments such as `+1.12` in `juliaArgs`" + end + @warn "Could not start Julia test process" testprocess_id reason + put!(reactor_channel, TestProcessIOErrorMsg(testprocess_id, :fatal, nothing, nothing, reason)) + return + end proc_kill_registration = CancellationTokens.register(token) do @info "Killing test process due to cancellation" testprocess_id diff --git a/test/test_process_crash.jl b/test/test_process_crash.jl index 8d68b64..035af6b 100644 --- a/test/test_process_crash.jl +++ b/test/test_process_crash.jl @@ -188,6 +188,127 @@ end @test length(terminated) == 1 end +@testitem "A Julia command that cannot be spawned errors all test items" setup=[TestHelpers] begin + using Logging: with_logger, Warn, Error + using Test: TestLogger + + pkg_path = joinpath(TestHelpers.TESTDATA_DIR, "BasicPackage") + discovered = TestHelpers.discover_test_items(pkg_path) + items = filter(i -> i.label in ("add works", "greet works"), discovered.items) + @test length(items) == 2 + + julia_cmd = joinpath(pkg_path, "nonexistent", "julia") + + # At shutdown, the controller waits up to 30 s for a test process that it did not + # remove. A `shutdown_timeout` below that makes such a process fail the test. + logger = TestLogger(min_level=Warn) + result = with_logger(logger) do + TestHelpers.run_testrun(items, discovered.setups, discovered; julia_cmd, max_procs=2, timeout=60, shutdown_timeout=10) + end + + errored = filter(e -> e.event == :errored, result.events) + @test sort([e.testitem_id for e in errored]) == sort([i.id for i in items]) + + # The user is told why, not that the process crashed. + @test all(errored) do e + any(m -> occursin("Could not start the test process", m.message) && occursin("ENOENT", m.message), e.messages) + end + + # A misconfigured `juliaCmd` is a user error. Under the crash-reporting logger VS Code + # installs, anything logged at `Error` ends the controller and files a crash report. + @test !any(r -> r.level >= Error, logger.logs) + + created = [e.id for e in result.process_events if e.event == :process_created] + terminated = [e.id for e in result.process_events if e.event == :process_terminated] + @test sort(terminated) == sort(created) +end + +@testitem "A Julia command with arguments in it points the user at juliaArgs" setup=[TestHelpers] begin + pkg_path = joinpath(TestHelpers.TESTDATA_DIR, "BasicPackage") + discovered = TestHelpers.discover_test_items(pkg_path) + items = filter(i -> i.label == "add works", discovered.items) + @test length(items) == 1 + + # The controller runs the whole string as one program, so a juliaup channel written into + # `juliaCmd` cannot be spawned. + result = TestHelpers.run_testrun(items, discovered.setups, discovered; julia_cmd="julia +1.12", timeout=60, shutdown_timeout=10) + + errored = filter(e -> e.event == :errored, result.events) + @test length(errored) == 1 + @test !isempty(errored) && any(errored[1].messages) do m + occursin("Could not start the test process", m.message) && occursin("`juliaArgs`", m.message) + end +end + +@testitem "A Julia process that exits during startup errors its test items as crashed" setup=[TestHelpers] begin + pkg_path = joinpath(TestHelpers.TESTDATA_DIR, "BasicPackage") + discovered = TestHelpers.discover_test_items(pkg_path) + items = filter(i -> i.label == "add works", discovered.items) + @test length(items) == 1 + + # Julia rejects the unknown option and exits before it connects to the controller. The + # process was spawned, so this is a crash and not a failure to start it. + result = TestHelpers.run_testrun(items, discovered.setups, discovered; julia_args=["--no-such-option"], timeout=120, shutdown_timeout=10) + + errored = filter(e -> e.event == :errored, result.events) + @test length(errored) == 1 + @test !isempty(errored) && any(m -> occursin("Test process crashed before running test item", m.message), errored[1].messages) + @test !isempty(errored) && !any(m -> occursin("Could not start the test process", m.message), errored[1].messages) + + created = [e.id for e in result.process_events if e.event == :process_created] + terminated = [e.id for e in result.process_events if e.event == :process_terminated] + @test sort(terminated) == sort(created) +end + +@testitem "The controller runs test items again after a Julia command could not be spawned" setup=[TestHelpers] begin + using TestItemControllers: TestItemController, TestRunItem, execute_testrun, shutdown, ControllerCallbacks + import UUIDs + + pkg_path = joinpath(TestHelpers.TESTDATA_DIR, "BasicPackage") + discovered = TestHelpers.discover_test_items(pkg_path) + items = filter(i -> i.label == "add works", discovered.items) + @test length(items) == 1 + + events = NamedTuple[] + events_lock = ReentrantLock() + push_event!(e) = lock(() -> push!(events, e), events_lock) + + callbacks = ControllerCallbacks( + on_testitem_started = (run_id, item_id, test_env_id) -> nothing, + on_testitem_passed = (run_id, item_id, test_env_id, duration) -> push_event!((event=:passed, testrun_id=run_id)), + on_testitem_failed = (run_id, item_id, test_env_id, messages, duration) -> push_event!((event=:failed, testrun_id=run_id)), + on_testitem_errored = (run_id, item_id, test_env_id, messages, duration) -> push_event!((event=:errored, testrun_id=run_id)), + on_testitem_skipped = (run_id, item_id, test_env_id) -> nothing, + on_append_output = (run_id, item_id, test_env_id, output) -> nothing, + on_attach_debugger = (run_id, pipe_name) -> nothing, + ) + + controller = TestItemController(callbacks; log_level=:Debug) + controller_task = @async try + run(controller) + catch err + @error "Controller error" exception=(err, catch_backtrace()) + end + + env_kwargs = TestHelpers._env_kwargs(discovered) + function run_once(test_env) + testrun_id = string(UUIDs.uuid4()) + work_units = [TestRunItem(item.id, test_env.id, nothing, :Debug) for item in items] + run_task = @async execute_testrun(controller, testrun_id, [test_env], items, work_units, discovered.setups, 1, nothing) + TestHelpers.timed_wait(run_task, 600; label="test run") + return lock(() -> [e.event for e in events if e.testrun_id == testrun_id], events_lock) + end + + bad_env = TestHelpers.make_test_environment(; env_kwargs..., julia_cmd=joinpath(pkg_path, "nonexistent", "julia")) + @test run_once(bad_env) == [:errored] + + good_env = TestHelpers.make_test_environment(; env_kwargs...) + @test run_once(good_env) == [:passed] + + shutdown(controller) + TestHelpers.timed_wait(controller_task, 60; label="controller shutdown") +end + @testitem "The startup-crash warning only reads fields the exception has" begin using TestItemControllers: TestProcessCrashException