From e9bd8904cc2eef83607aea0952ad8dd6d26561f9 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Fri, 21 Aug 2026 23:26:22 +0100 Subject: [PATCH 1/8] Reapply "Name the call site in non-Gleam crash reports" This reverts commit 042d3a3e0114e224383604a5ad2fedf77491a127. --- CHANGELOG.md | 6 + README.md | 8 +- examples/playground/src/playground.gleam | 9 + examples/playground/src/playground_ffi.mjs | 6 + .../playground/test/playground_test.gleam | 10 +- src/vouch.gleam | 13 +- src/vouch/internal/config.gleam | 10 + src/vouch/internal/describe.gleam | 43 +++- src/vouch/internal/outcome.gleam | 42 +++- src/vouch/internal/report/jsonl.gleam | 38 +++- src/vouch/internal/report/junit.gleam | 8 +- src/vouch/internal/report/teamcity.gleam | 7 +- src/vouch/internal/runner.gleam | 92 ++++++-- src/vouch_ffi.erl | 166 ++++++++++++-- src/vouch_ffi.mjs | 23 +- test/helpers.gleam | 16 ++ test/vouch_e2e_test.gleam | 17 +- test/vouch_test.gleam | 203 ++++++++++++++++++ 18 files changed, 657 insertions(+), 60 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c28e7c1..9b10292 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +To keep the output of vouch clean, vouch now catches and suppresses any errors coming out of dying OTP processes. +If you need to inspect these crash reports, there is now the option `--show-crash-reports`. +These will be printed to stderr after the summary. + ## v1.2.0 Watch mode added for the JavaScript target, supporting both Node and Deno diff --git a/README.md b/README.md index c116a5e..9677563 100644 --- a/README.md +++ b/README.md @@ -52,6 +52,7 @@ gleam test -- --format=teamcity gleam test -- --junit=report.xml gleam test -- --timeout=1000 # Erlang target only gleam test -- --parallel # Erlang target only +gleam test -- --show-crash-reports # Erlang target only, see below gleam test -- --color=never # console colour: auto | always | never gleam run -m vouch -- watch # rerun the suite on file change ``` @@ -87,9 +88,14 @@ On Deno, watch mode also needs `allow_run = ["gleam"]` to spawn the inner runs ( | todo | hit `todo` in code under test | 1 — unimplemented is still not done | | skip | `todo` within test function | 0 | +## Crash reports + +To keep the output of vouch clean, vouch catches and suppresses any errors coming out of dying OTP processes. +If you need to inspect these crash reports, there is the option `--show-crash-reports`. These will be printed to stderr after the summary. + ## Target differences -Erlang target supports `--parallel` and `--timeout=n` +Erlang target supports `--parallel`, `--timeout=n` and `--show-crash-reports` Deno needs permissions in your project's `gleam.toml`. You need `allow_read` for discovery and source quoting. diff --git a/examples/playground/src/playground.gleam b/examples/playground/src/playground.gleam index bf149f3..75982bb 100644 --- a/examples/playground/src/playground.gleam +++ b/examples/playground/src/playground.gleam @@ -16,3 +16,12 @@ pub fn rate_limit(_requests: Int) -> Bool { @external(erlang, "playground_ffi", "sleep") @external(javascript, "./playground_ffi.mjs", "sleep") pub fn sleep(ms: Int) -> Nil + +/// Stands in for a dependency whose .beam has gone stale or missing: no +/// config_parser module exists, so on the BEAM the call raises undef and +/// the report names config_parser:parse/1 from the stacktrace. On +/// JavaScript the FFI throws a plain TypeError instead — a raw crash with +/// no site, which is all a JS stacktrace offers. +@external(erlang, "config_parser", "parse") +@external(javascript, "./playground_ffi.mjs", "parse") +pub fn parse_config(path: String) -> String diff --git a/examples/playground/src/playground_ffi.mjs b/examples/playground/src/playground_ffi.mjs index 4e7f967..dd3f2f3 100644 --- a/examples/playground/src/playground_ffi.mjs +++ b/examples/playground/src/playground_ffi.mjs @@ -5,3 +5,9 @@ export function sleep(ms) { // spin } } + +// The JavaScript half of parse_config: a raw runtime error, standing in for +// a broken FFI dependency. On Erlang the module itself is missing instead. +export function parse(path) { + throw new TypeError(`config_parser is not loaded (parsing ${path})`); +} diff --git a/examples/playground/test/playground_test.gleam b/examples/playground/test/playground_test.gleam index d428c5a..ba3d05c 100644 --- a/examples/playground/test/playground_test.gleam +++ b/examples/playground/test/playground_test.gleam @@ -1,6 +1,6 @@ //// One test per outcome flavour, so a plain run shows vouch's full range: //// -//// gleam test - 2 pass, 3 fail, 2 todo, 1 skip +//// gleam test - 2 pass, 4 fail, 2 todo, 1 skip //// gleam test -- --timeout=100 - slow_test also fails as a timeout //// gleam test -- --filter=slow - just the slow test //// gleam test -- --format=json - the same as a JSONL stream @@ -35,6 +35,14 @@ pub fn failing_predicate_test() { assert playground.within_budget(spend) } +/// A crash that is not a Gleam panic: the code under test calls into a +/// missing module — the stale-.beam problem. The report names what was +/// being called ("Crashed: Undef calling config_parser:parse/1") instead of +/// an information-free "Crashed: Undef". +pub fn crashing_config_test() { + playground.parse_config("gleam.toml") +} + /// A failing pattern match: renders the unmatched value. pub fn failing_let_assert_test() { let assert Ok(n) = Error("the port was closed") diff --git a/src/vouch.gleam b/src/vouch.gleam index c5941e1..1765996 100644 --- a/src/vouch.gleam +++ b/src/vouch.gleam @@ -54,6 +54,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, ) config.Console, Some(path) -> runner.run( @@ -64,15 +65,23 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, ) config.Json, None -> - runner.run(jsonl.reporter(), cfg.filter, cfg.timeout_ms, cfg.parallel) + runner.run( + jsonl.reporter(), + cfg.filter, + cfg.timeout_ms, + cfg.parallel, + cfg.show_crash_reports, + ) config.Json, Some(path) -> runner.run( reporter.pair(jsonl.reporter(), junit.reporter(path)), cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, ) config.TeamCity, None -> runner.run( @@ -80,6 +89,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, ) config.TeamCity, Some(path) -> runner.run( @@ -87,6 +97,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, ) } } diff --git a/src/vouch/internal/config.gleam b/src/vouch/internal/config.gleam index 930b124..588d1a3 100644 --- a/src/vouch/internal/config.gleam +++ b/src/vouch/internal/config.gleam @@ -34,6 +34,10 @@ pub type Config { timeout_ms: Int, color: ColorChoice, parallel: Parallelism, + /// Reprint the BEAM crash reports captured during the run (processes + /// the tests spawned dying) after the summary. Off by default: a death + /// under a test already shows in the test's outcome. + show_crash_reports: Bool, ) } @@ -49,6 +53,7 @@ pub fn from_args(args: List(String)) -> Result(Config, String) { timeout_ms: default_timeout_ms, color: Auto, parallel: Sequential, + show_crash_reports: False, ), ) } @@ -90,6 +95,8 @@ fn parse(args: List(String), config: Config) -> Result(Config, String) { "--parallel expects a worker count of at least 1, got: " <> value, )) } + ["--show-crash-reports", ..rest] -> + parse(rest, Config(..config, show_crash_reports: True)) [arg, ..] -> case string.starts_with(arg, "-") { True -> Error(usage("unknown option: " <> arg)) @@ -131,6 +138,9 @@ fn usage(problem: String) -> String { <> " --timeout=ms per-test timeout on the Erlang target (default 5000)\n" <> " --parallel[=n] run tests concurrently on the Erlang target with n\n" <> " workers (default: one per scheduler)\n" + <> " --show-crash-reports\n" + <> " print the BEAM crash reports of processes that died\n" + <> " during the run after the summary (Erlang target)\n" <> " --color=mode console colour: auto (default), always, never;\n" <> " auto respects NO_COLOR and non-TTY output\n" <> "\n" diff --git a/src/vouch/internal/describe.gleam b/src/vouch/internal/describe.gleam index a5881cd..8fa441f 100644 --- a/src/vouch/internal/describe.gleam +++ b/src/vouch/internal/describe.gleam @@ -15,12 +15,14 @@ //// Shared by every reporter, so the console, TeamCity details and JUnit //// failure bodies all say the same thing. +import gleam/dynamic.{type Dynamic} import gleam/int import gleam/list +import gleam/option.{type Option} import gleam/result import gleam/string import vouch/internal/gleam_panic.{type AssertedExpression, type GleamPanic} -import vouch/internal/outcome.{type FailureDetail} +import vouch/internal/outcome.{type CrashSite, type FailureDetail} import vouch/internal/source /// The body of a failure report: one entry per line, unindented. @@ -36,10 +38,43 @@ pub fn failure(detail: FailureDetail) -> List(String) { outcome.TimeoutDetail(ms) -> [ "Timed out after " <> int.to_string(ms) <> "ms", ] - outcome.UnknownDetail(raw) -> ["Crashed: " <> string.inspect(raw)] - outcome.ExitDetail(raw) -> [ - "Test process died: " <> string.inspect(raw), + outcome.UnknownDetail(raw, site) -> [ + "Crashed: " <> crash(raw, site), + ..at_line(site) ] + outcome.ExitDetail(raw, site) -> [ + "Test process died: " <> crash(raw, site), + ..at_line(site) + ] + } +} + +/// The reason with its call site: `Undef calling filepath:split/1`. The +/// shared summary every reporter embeds after its own prefix; without a +/// site — every JavaScript crash — it is the reason alone. +pub fn crash(raw: Dynamic, site: Option(CrashSite)) -> String { + let reason = string.inspect(raw) + case site { + option.None -> reason + option.Some(s) -> + reason + <> " calling " + <> s.module + <> ":" + <> s.function + <> "/" + <> int.to_string(s.arity) + } +} + +/// Where the crashing frame lives, when the BEAM recorded it — an undef +/// frame never does, the called function not existing anywhere. +fn at_line(site: Option(CrashSite)) -> List(String) { + case site { + option.Some(outcome.CrashSite(location: option.Some(#(file, line)), ..)) -> [ + " at " <> file <> ":" <> int.to_string(line), + ] + _ -> [] } } diff --git a/src/vouch/internal/outcome.gleam b/src/vouch/internal/outcome.gleam index adad7bd..5c4ca61 100644 --- a/src/vouch/internal/outcome.gleam +++ b/src/vouch/internal/outcome.gleam @@ -6,6 +6,7 @@ //// it fails the run, but reported distinctly from a broken test. import gleam/dynamic.{type Dynamic} +import gleam/option.{type Option} import vouch/internal/gleam_panic.{type GleamPanic} /// How a test invocation ended. On the Erlang target tests run in their own @@ -30,15 +31,40 @@ pub type TestOutcome { pub type FailureDetail { PanicDetail(GleamPanic) - /// Not a Gleam panic: a raw runtime error from FFI or similar. - UnknownDetail(raw: Dynamic) + /// Not a Gleam panic: a raw runtime error from FFI or similar. The raw + /// value is the reason alone — the stacktrace behind it is reduced to + /// `site`, so inspecting the reason never dumps frames. + UnknownDetail(raw: Dynamic, site: Option(CrashSite)) /// The test ran longer than the per-test timeout and was killed. TimeoutDetail(after_ms: Int) /// The test process died without reporting: an exit signal it did not /// cause by panicking, e.g. an explicit exit. - ExitDetail(raw: Dynamic) + ExitDetail(raw: Dynamic, site: Option(CrashSite)) } +/// The top frame of the stacktrace behind a non-Gleam crash: what was being +/// called when the test died. An undef from a stale .beam carries no Gleam +/// payload at all, so this frame is the only thing that names the failure. +pub type CrashSite { + CrashSite( + module: String, + function: String, + arity: Int, + /// The frame's file and line, when the BEAM recorded them. An undef + /// frame has neither: the called function does not exist. + location: Option(#(String, Int)), + ) +} + +/// Split a raw caught term into the error reason and the crash site from the +/// top of its stacktrace, for terms shaped {Reason, Stacktrace} — the shape +/// catch_panic captures and BEAM exit reasons already have. Terms with no +/// recognisable stacktrace pass through unchanged with no site; on +/// JavaScript the stack is an unparsed string, so there is never a site. +@external(erlang, "vouch_ffi", "split_crash") +@external(javascript, "../../vouch_ffi.mjs", "split_crash") +fn split_crash(raw: Dynamic) -> #(Dynamic, Option(CrashSite)) + /// Wrap a directly-caught result (catch_panic, or the JavaScript run loop's /// try/catch) as an invocation. pub fn from_caught(result: Result(Nil, Dynamic)) -> Invocation { @@ -58,7 +84,10 @@ pub fn classify( Panicked(raw) -> case gleam_panic.from_dynamic(raw) { Ok(p) -> classify_panic(test_module, test_function, p) - Error(Nil) -> Failed(UnknownDetail(raw)) + Error(Nil) -> { + let #(reason, site) = split_crash(raw) + Failed(UnknownDetail(reason, site)) + } } TimedOut(ms) -> Failed(TimeoutDetail(ms)) // A linked process that panicked kills the test process with the panic @@ -66,7 +95,10 @@ pub fn classify( Died(raw) -> case gleam_panic.from_dynamic(raw) { Ok(p) -> classify_panic(test_module, test_function, p) - Error(Nil) -> Failed(ExitDetail(raw)) + Error(Nil) -> { + let #(reason, site) = split_crash(raw) + Failed(ExitDetail(reason, site)) + } } } } diff --git a/src/vouch/internal/report/jsonl.gleam b/src/vouch/internal/report/jsonl.gleam index 3d93927..ac5ba1c 100644 --- a/src/vouch/internal/report/jsonl.gleam +++ b/src/vouch/internal/report/jsonl.gleam @@ -3,6 +3,7 @@ import gleam/io import gleam/list +import gleam/option.{type Option} import gleam/string import vouch/internal/event.{type Event} import vouch/internal/gleam_panic.{type GleamPanic} @@ -79,18 +80,39 @@ fn outcome_fields(out: TestOutcome) -> List(#(String, json.Value)) { #("line", Num(p.line)), ] |> list.append(kind_fields(p)) - outcome.Failed(outcome.UnknownDetail(raw)) -> [ - #("kind", Str("unknown")), - #("message", Str(string.inspect(raw))), - ] + outcome.Failed(outcome.UnknownDetail(raw, site)) -> + [#("kind", Str("unknown")), #("message", Str(string.inspect(raw)))] + |> list.append(site_fields(site)) outcome.Failed(outcome.TimeoutDetail(ms)) -> [ #("kind", Str("timeout")), #("timeout_ms", Num(ms)), ] - outcome.Failed(outcome.ExitDetail(raw)) -> [ - #("kind", Str("died")), - #("message", Str(string.inspect(raw))), - ] + outcome.Failed(outcome.ExitDetail(raw, site)) -> + [#("kind", Str("died")), #("message", Str(string.inspect(raw)))] + |> list.append(site_fields(site)) + } +} + +/// A crash site as structured fields, following the site_* naming the todo +/// outcome uses. File and line appear only when the frame carried them. +fn site_fields(site: Option(outcome.CrashSite)) -> List(#(String, json.Value)) { + case site { + option.None -> [] + option.Some(s) -> { + let named = [ + #("site_module", Str(s.module)), + #("site_function", Str(s.function)), + #("site_arity", Num(s.arity)), + ] + case s.location { + option.None -> named + option.Some(#(file, line)) -> + list.append(named, [ + #("site_file", Str(file)), + #("site_line", Num(line)), + ]) + } + } } } diff --git a/src/vouch/internal/report/junit.gleam b/src/vouch/internal/report/junit.gleam index 71b4ba8..623cbb8 100644 --- a/src/vouch/internal/report/junit.gleam +++ b/src/vouch/internal/report/junit.gleam @@ -119,20 +119,20 @@ fn test_case(r: Case) -> String { "\n", )) <> "\n \n" - outcome.Failed(outcome.UnknownDetail(raw)) -> + outcome.Failed(outcome.UnknownDetail(raw, site)) -> open <> ">\n escape(string.inspect(raw)) + <> escape(describe.crash(raw, site)) <> "\"/>\n \n" outcome.Failed(outcome.TimeoutDetail(ms)) -> open <> ">\n int.to_string(ms) <> "ms\"/>\n \n" - outcome.Failed(outcome.ExitDetail(raw)) -> + outcome.Failed(outcome.ExitDetail(raw, site)) -> open <> ">\n escape(string.inspect(raw)) + <> escape(describe.crash(raw, site)) <> "\"/>\n \n" } } diff --git a/src/vouch/internal/report/teamcity.gleam b/src/vouch/internal/report/teamcity.gleam index cf62f60..c2d15e8 100644 --- a/src/vouch/internal/report/teamcity.gleam +++ b/src/vouch/internal/report/teamcity.gleam @@ -116,11 +116,12 @@ fn test_lines( fn failure(function: String, detail: outcome.FailureDetail) -> String { case detail { outcome.PanicDetail(p) -> panic_failure(function, p) - outcome.UnknownDetail(raw) -> failed(function, string.inspect(raw), "") + outcome.UnknownDetail(raw, site) -> + failed(function, describe.crash(raw, site), "") outcome.TimeoutDetail(ms) -> failed(function, "timed out after " <> int.to_string(ms) <> "ms", "") - outcome.ExitDetail(raw) -> - failed(function, "test process died", string.inspect(raw)) + outcome.ExitDetail(raw, site) -> + failed(function, "test process died", describe.crash(raw, site)) } } diff --git a/src/vouch/internal/runner.gleam b/src/vouch/internal/runner.gleam index 1d380fd..81d428e 100644 --- a/src/vouch/internal/runner.gleam +++ b/src/vouch/internal/runner.gleam @@ -2,6 +2,8 @@ //// per-target loops live here with the narrow FFI contract at the bottom. import gleam/dynamic.{type Dynamic} +import gleam/int +import gleam/io import gleam/list import gleam/option.{type Option} import gleam/order @@ -61,12 +63,40 @@ fn finish( state: s, outcomes: List(TestOutcome), duration: Int, + show_crash_reports: Bool, ) -> Nil { let t = tally(outcomes) let _ = rep.handle(state, event.RunEnd(t, duration)) + case show_crash_reports { + True -> print_crash_reports(drain_diagnostics()) + False -> Nil + } halt(exit_code(t)) } +/// `--show-crash-reports`: the BEAM diagnostics captured during the run +/// (crash reports from processes the tests spawned, logger output), +/// reprinted as one block after the summary on stderr — visible in a +/// terminal, clear of a machine-read stdout stream (JSONL, TeamCity). +fn print_crash_reports(reports: List(String)) -> Nil { + case reports { + [] -> Nil + _ -> { + let noun = case reports { + [_] -> "crash report" + _ -> "crash reports" + } + term.warn( + int.to_string(list.length(reports)) + <> " " + <> noun + <> " captured during the run:", + ) + list.each(reports, io.print_error) + } + } +} + /// Call a function, capturing any panic as the raw target-specific value. /// On JavaScript the call is synchronous; async functions are not awaited /// here (the JavaScript run loop awaits discovered tests itself). @@ -112,10 +142,11 @@ pub fn run( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, ) -> Nil { case target() { - Erlang -> run_beam(rep, filter, timeout_ms, parallel) - JavaScript -> run_js(rep, filter, timeout_ms, parallel) + Erlang -> run_beam(rep, filter, timeout_ms, parallel, show_crash_reports) + JavaScript -> run_js(rep, filter, timeout_ms, parallel, show_crash_reports) } } @@ -127,8 +158,9 @@ fn run_beam( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, ) -> Nil { - redirect_diagnostics_to_stderr() + capture_diagnostics() let started = now_microseconds() let candidates = find_test_files() @@ -158,7 +190,13 @@ fn run_beam( 1 -> run_sequential(rep, state, tests, timeout_ms) n -> run_window(rep, tests, [], 0, state, [], timeout_ms, n) } - finish(rep, state, list.reverse(outcomes), now_microseconds() - started) + finish( + rep, + state, + list.reverse(outcomes), + now_microseconds() - started, + show_crash_reports, + ) } fn workers(parallel: config.Parallelism) -> Int { @@ -244,9 +282,23 @@ fn run_window( } } -@external(erlang, "vouch_ffi", "redirect_diagnostics_to_stderr") -@external(javascript, "../../vouch_ffi.mjs", "redirect_diagnostics_to_stderr") -fn redirect_diagnostics_to_stderr() -> Nil +@external(erlang, "vouch_ffi", "capture_diagnostics") +@external(javascript, "../../vouch_ffi.mjs", "capture_diagnostics") +fn capture_diagnostics() -> Nil + +/// Remove and return every captured BEAM diagnostic, in arrival order. +@external(erlang, "vouch_ffi", "drain_diagnostics") +@external(javascript, "../../vouch_ffi.mjs", "drain_diagnostics") +fn drain_diagnostics() -> List(String) + +/// Remove and return the captured BEAM diagnostics whose text contains +/// `marker`, leaving the rest for `--show-crash-reports`. Public so vouch's +/// own suite can prove that a deliberately-crashed process's report was +/// swallowed by the capture handler rather than reaching stderr, without +/// touching reports that belong to other tests. +@external(erlang, "vouch_ffi", "take_diagnostics_matching") +@external(javascript, "../../vouch_ffi.mjs", "take_diagnostics_matching") +pub fn take_diagnostics_matching(marker: String) -> List(String) fn path_to_module(path: String) -> String { path @@ -302,13 +354,22 @@ fn schedulers_online() -> Int // of the test in flight). /// JavaScript has no cheap process primitive: tests run in-process, so -/// `--timeout` and `--parallel` do not apply there. A documented target -/// difference — but a flag that will be ignored deserves a loud note -/// rather than silence. +/// `--timeout` and `--parallel` do not apply there, and with no BEAM there +/// are no crash reports for `--show-crash-reports` to show. A documented +/// target difference — but a flag that will be ignored deserves a loud +/// note rather than silence. pub fn warn_ineffective_js_flags( timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, ) -> Nil { + case show_crash_reports { + False -> Nil + True -> + term.warn( + "--show-crash-reports has no effect on the JavaScript target — there is no BEAM to report crashes", + ) + } case timeout_ms == config.default_timeout_ms { True -> Nil False -> @@ -330,8 +391,9 @@ fn run_js( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, ) -> Nil { - warn_ineffective_js_flags(timeout_ms, parallel) + warn_ineffective_js_flags(timeout_ms, parallel, show_crash_reports) let started = now_microseconds() js_run_tests( #(rep.init, [], 0), @@ -354,7 +416,13 @@ fn run_js( }, fn(state) { let #(st, outs, _) = state - finish(rep, st, list.reverse(outs), now_microseconds() - started) + finish( + rep, + st, + list.reverse(outs), + now_microseconds() - started, + show_crash_reports, + ) }, ) } diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index b2cc7ca..b63f7d2 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -4,11 +4,15 @@ exported_zero_arity/1, run_test/3, catch_panic/1, + split_crash/1, decode_panic/1, now_microseconds/0, is_stdout_tty/0, env/1, - redirect_diagnostics_to_stderr/0, + capture_diagnostics/0, + drain_diagnostics/0, + take_diagnostics_matching/1, + log/2, write_file/2, read_source/3, halt/1, @@ -71,14 +75,109 @@ env(Name) -> Value -> {ok, unicode:characters_to_binary(Value)} end. -%% Route BEAM diagnostics (e.g. crash reports from processes that tests -%% spawned) to stderr, so stdout stays a clean stream for reporters. They -%% remain visible in a terminal; they no longer corrupt piped output. +%% Swallow BEAM diagnostics (crash reports from processes that tests +%% spawned, anything else routed through OTP's logger) instead of letting +%% the default handler print them around the test output. A process that +%% dies under a test is already reported through the test's own outcome; +%% the BEAM's report of the same death is a duplicate. This module doubles +%% as the logger handler: log/2 renders each event with the formatter the +%% default handler would have used and stashes the text in a public ETS +%% table. The runner drains and prints that table after the summary only +%% when asked (--show-crash-reports); otherwise it is never read, except by +%% vouch's own suite proving the reports were captured. If the capture +%% handler cannot be installed, fall back to redirecting the default +%% handler to stderr: reports on stderr beat reports corrupting a +%% machine-read stdout stream. +capture_diagnostics() -> + catch case logger:get_handler_config(vouch_diagnostics) of + {ok, _} -> + %% Already capturing; installing twice would double reports. + ok; + _ -> + case logger:get_handler_config(default) of + {ok, #{filters := Filters, formatter := Formatter}} -> + ensure_diagnostics_table(), + %% Added before the default handler is removed, so no + %% window exists where an event is dropped entirely. + case logger:add_handler(vouch_diagnostics, ?MODULE, + #{filters => Filters, formatter => Formatter}) of + ok -> logger:remove_handler(default); + _ -> redirect_default_to_stderr() + end; + _ -> + %% No default handler: nothing would have printed, so + %% there is nothing to capture. + ok + end + end, + nil. + +ensure_diagnostics_table() -> + case ets:whereis(vouch_diagnostics) of + undefined -> + %% Owned by the runner process, which lives until halt. + ets:new(vouch_diagnostics, [named_table, public, ordered_set]); + _ -> + ok + end. + +%% Logger handler callback, installed by capture_diagnostics/0. Runs in the +%% logging process for logger API calls and in the logger server for +%% emulator-generated reports; either way, render now and append. Must +%% never raise: logger removes a handler whose callback crashes. +log(Event, Config) -> + catch ets:insert(vouch_diagnostics, + {erlang:unique_integer([monotonic]), render_diagnostic(Event, Config)}), + ok. + +render_diagnostic(Event, Config) -> + try + {FModule, FConfig} = maps:get(formatter, Config), + Text = unicode:characters_to_binary(FModule:format(Event, FConfig)), + true = is_binary(Text), + Text + catch + _:_ -> + unicode:characters_to_binary(io_lib:format("~0tp~n", [Event])) + end. + +%% All captured diagnostics in arrival order, removed from the table. Only +%% the returned rows are deleted, so an event arriving mid-drain is kept +%% rather than silently discarded. +drain_diagnostics() -> + take_diagnostics(fun(_Text) -> true end). + +%% Remove and return only the captured diagnostics whose text contains +%% Marker, leaving the rest alone. The suite-facing probe: a spec that +%% deliberately crashes a process can assert its report was captured +%% without touching reports that belong to other tests. +take_diagnostics_matching(Marker) -> + take_diagnostics(fun(Text) -> + binary:match(Text, Marker) =/= nomatch + end). + +%% Emulator-generated reports travel through the logger server's mailbox +%% (API-call events are handled in the logging process itself, before the +%% crash propagates), so a synchronous round-trip first makes sure +%% everything already sent is in the table before it is read. +take_diagnostics(Keep) -> + catch sys:get_state(logger, 1000), + case catch ets:tab2list(vouch_diagnostics) of + Rows when is_list(Rows) -> + [begin + catch ets:delete(vouch_diagnostics, Key), + Text + end || {Key, Text} <- Rows, Keep(Text)]; + _ -> + [] + end. + +%% Fallback when the capture handler cannot be installed: route the default +%% handler to stderr, so stdout stays a clean stream for reporters. %% logger_std_h does not honour a runtime `type` change, so the handler is -%% removed and re-added with its filters and formatter preserved. Note the -%% reports are asynchronous and can be lost entirely if the VM halts first. -redirect_diagnostics_to_stderr() -> - catch case logger:get_handler_config(default) of +%% removed and re-added with its filters and formatter preserved. +redirect_default_to_stderr() -> + case logger:get_handler_config(default) of {ok, #{module := Module, config := HConfig} = Cfg} -> NewCfg0 = Cfg#{config := HConfig#{type => standard_error}}, NewCfg = maps:remove(id, maps:remove(module, NewCfg0)), @@ -95,8 +194,7 @@ redirect_diagnostics_to_stderr() -> end; _ -> ok - end, - nil. + end. %% Paths of .gleam files under test/, relative to test/. find_test_files() -> @@ -178,18 +276,56 @@ await_test({Ref, MonRef}) -> schedulers_online() -> erlang:system_info(schedulers_online). -%% Call a function, capturing anything it throws. The raw reason is returned -%% for Gleam-side decoding; a Gleam panic's reason is a map tagged -%% gleam_error. +%% Call a function, capturing anything it throws. The reason is paired with +%% the stacktrace — for a non-Gleam crash (undef from a stale .beam, an FFI +%% error) the top frame is the only thing that names what failed, and +%% split_crash/1 reduces it to a site during classification. Gleam-side +%% decoding is unaffected: a Gleam panic's reason is a map tagged +%% gleam_error, which find_panic's recursive search still reaches inside the +%% extra tuple. The {Reason, Stacktrace} shape deliberately matches BEAM +%% exit reasons, so both feed the same split. catch_panic(F) -> try F(), {ok, nil} catch - error:Reason -> {error, Reason}; - Class:Reason -> {error, {Class, Reason}} + error:Reason:Stacktrace -> {error, {Reason, Stacktrace}}; + Class:Reason:Stacktrace -> {error, {{Class, Reason}, Stacktrace}} end. +%% Split a raw caught term into the error reason and the crash site from the +%% top of its stacktrace. Fed by catch_panic's {Reason, Stacktrace} capture +%% and by exit reasons, which the BEAM already shapes the same way. A frame +%% carries the argument list instead of an arity when the arguments are +%% known — an undef frame always does. Tuple shapes must match the +%% CrashSite constructor in src/vouch/internal/outcome.gleam. Anything +%% unrecognised passes through untouched with no site. +split_crash({Reason, [{Module, Function, ArityOrArgs, Info} | _]}) + when is_atom(Module), is_atom(Function), + is_list(ArityOrArgs) orelse is_integer(ArityOrArgs) -> + Arity = case ArityOrArgs of + Args when is_list(Args) -> length(Args); + A -> A + end, + Site = {crash_site, + atom_to_binary(Module, utf8), + atom_to_binary(Function, utf8), + Arity, + frame_location(Info)}, + {Reason, {some, Site}}; +split_crash(Raw) -> + {Raw, none}. + +frame_location(Info) when is_list(Info) -> + case {lists:keyfind(file, 1, Info), lists:keyfind(line, 1, Info)} of + {{file, File}, {line, Line}} when is_integer(Line) -> + {some, {unicode:characters_to_binary(File), Line}}; + _ -> + none + end; +frame_location(_) -> + none. + %% Decode a raw error term into vouch's GleamPanic type, or error for %% anything that is not a Gleam panic. The panic map is searched for %% recursively through nested tuples, because OTP wraps exit reasons: a todo diff --git a/src/vouch_ffi.mjs b/src/vouch_ffi.mjs index 65fa453..8fee2aa 100644 --- a/src/vouch_ffi.mjs +++ b/src/vouch_ffi.mjs @@ -8,6 +8,7 @@ import { spawnSync } from "node:child_process"; import { Worker } from "node:worker_threads"; import { isatty } from "node:tty"; import { Result$Ok, Result$Error, List$Empty, List$NonEmpty } from "./gleam.mjs"; +import { Option$None } from "../gleam_stdlib/gleam/option.mjs"; import { GleamPanic$GleamPanic, PanicKind$Todo, @@ -74,8 +75,19 @@ function erlangOnly(name) { throw new Error(`vouch: ${name} is only available on the Erlang target`); } -export function redirect_diagnostics_to_stderr() { - erlangOnly("redirect_diagnostics_to_stderr"); +export function capture_diagnostics() { + erlangOnly("capture_diagnostics"); +} + +// The run loop drains on every target when --show-crash-reports is given; +// JavaScript has no logger capture, so there is never anything to hand +// back (the flag is warned about as ineffective). +export function drain_diagnostics() { + return List$Empty(); +} + +export function take_diagnostics_matching(_marker) { + erlangOnly("take_diagnostics_matching"); } export function find_test_files() { @@ -365,6 +377,13 @@ export function catch_panic(f) { } } +// The Erlang side splits {Reason, Stacktrace} into the reason and a crash +// site taken from the top frame. A JavaScript throw only carries an unparsed +// stack string, so there is never a site here and the term passes through. +export function split_crash(raw) { + return [raw, Option$None()]; +} + // Decode a thrown value into vouch's GleamPanic type, or error for anything // that is not a Gleam panic. export function decode_panic(error) { diff --git a/test/helpers.gleam b/test/helpers.gleam index ce6d8a9..ff48616 100644 --- a/test/helpers.gleam +++ b/test/helpers.gleam @@ -66,6 +66,22 @@ pub fn crashes_linked() -> Nil { sleep(1000) } +@target(erlang) +/// Stands in for a call into a stale or missing .beam: the module does not +/// exist, so the call raises undef — no Gleam payload, only a stacktrace +/// whose top frame names the M:F/A that was called. +@external(erlang, "vouch_no_such_module", "boom") +pub fn calls_missing_function() -> Nil + +@target(erlang) +/// The same undef, but in a linked process: the test process is killed by +/// the exit signal, whose reason still carries the stacktrace. +pub fn crashes_linked_undef() -> Nil { + spawn_link(fn() { calls_missing_function() }) + // Stay alive long enough to receive the exit signal. + sleep(1000) +} + @target(erlang) @external(erlang, "timer", "sleep") fn sleep(ms: Int) -> Nil diff --git a/test/vouch_e2e_test.gleam b/test/vouch_e2e_test.gleam index 6039c7a..f7189ff 100644 --- a/test/vouch_e2e_test.gleam +++ b/test/vouch_e2e_test.gleam @@ -18,10 +18,17 @@ pub fn playground_erlang_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":3,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"outcome\":\"todo\"") assert string.contains(out, "\"site_function\":\"rate_limit\"") + // The undef crash carries its call site through the whole pipeline: + // subprocess, stream, JSON encoding. + assert string.contains(out, "\"kind\":\"unknown\"") + assert string.contains( + out, + "\"site_module\":\"config_parser\",\"site_function\":\"parse\",\"site_arity\":1", + ) // Every stdout line must be a JSON object: the stream stays machine-clean. // Asserting that no offending line was found (rather than a Bool over the // whole list) makes a failure print the first non-JSON line itself. @@ -46,8 +53,10 @@ pub fn playground_javascript_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":3,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", ) + // On JavaScript the crash is a raw TypeError with no site to extract. + assert string.contains(out, "\"kind\":\"unknown\"") } @target(erlang) @@ -63,7 +72,7 @@ pub fn playground_timeout_e2e_test() { assert string.contains(out, "\"timeout_ms\":100") assert string.contains( out, - "\"event\":\"run_end\",\"passed\":1,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":1,\"failed\":5,\"todo\":2,\"skipped\":1", ) } @@ -80,7 +89,7 @@ pub fn playground_parallel_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":3,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"site_function\":\"rate_limit\"") } diff --git a/test/vouch_test.gleam b/test/vouch_test.gleam index 2dc26b3..ace7629 100644 --- a/test/vouch_test.gleam +++ b/test/vouch_test.gleam @@ -137,8 +137,31 @@ pub fn linked_crash_is_contained_test() { let assert outcome.Failed(outcome.PanicDetail(p)) = outcome.classify("vouch_test", "linked_crash_is_contained_test", invocation) assert p.message == "crash in linked process" + // The linked process's death also reaches the emulator, which logs an + // "Error in process" report asynchronously. It must land in the capture + // buffer, never on stderr. + let assert [report, ..] = await_diagnostics("crash in linked process", 40) + assert string.contains(report, "Error in process") } +@target(erlang) +/// Captured diagnostics matching `marker`, polling while an emulator +/// report may still be in flight. Taking only the matching reports leaves +/// any other test's diagnostics alone, so this cannot race a parallel run. +fn await_diagnostics(marker: String, retries: Int) -> List(String) { + case runner.take_diagnostics_matching(marker) { + [] if retries > 0 -> { + sleep_ms(25) + await_diagnostics(marker, retries - 1) + } + reports -> reports + } +} + +@target(erlang) +@external(erlang, "timer", "sleep") +fn sleep_ms(ms: Int) -> Nil + @target(erlang) /// A todo inside an OTP process (here a real gen_server callback) reaches /// the caller wrapped in OTP exit structure. It must still classify as @@ -153,6 +176,10 @@ pub fn otp_wrapped_todo_is_todo_outcome_test() { ) assert p.module == "helpers" assert p.function == "unimplemented" + // gen_server logs its terminating report (and proc_lib its crash report) + // on the way down; both must be captured, never printed. + let reports = await_diagnostics("vouch_otp_fixture", 40) + assert reports != [] } @target(erlang) @@ -203,6 +230,108 @@ pub fn parallel_test_times_out_test() { @external(erlang, "vouch_ffi", "now_microseconds") fn monotonic_microseconds() -> Int +// --- Crash sites --- +// +// A crash that is not a Gleam panic (the motivating case: a stale .beam +// shadowing a dependency, so every call into it is undef) has no payload to +// decode. The stacktrace's top frame is the only thing that names what +// failed, so classification must carry it into the failure detail. + +@target(erlang) +pub fn undef_crash_carries_call_site_test() { + let invocation = + outcome.from_caught(runner.catch_panic(helpers.calls_missing_function)) + let assert outcome.Failed(outcome.UnknownDetail(reason, Some(site))) = + outcome.classify( + "vouch_test", + "undef_crash_carries_call_site_test", + invocation, + ) + // The reason alone: inspecting it must never dump the stacktrace. + assert string.inspect(reason) == "Undef" + // An undef frame carries the argument list (arity 0 here) and no + // file/line: the called function does not exist anywhere. + assert site + == outcome.CrashSite( + module: "vouch_no_such_module", + function: "boom", + arity: 0, + location: None, + ) +} + +@target(erlang) +/// A linked process crashing with a non-Gleam error kills the test process; +/// the exit reason still carries the stacktrace, so the death report names +/// the call site rather than dumping raw frames. +pub fn linked_undef_crash_names_call_site_test() { + let invocation = + runner.run_in_process("helpers", "crashes_linked_undef", 5000) + let assert outcome.Failed(outcome.ExitDetail(reason, Some(site))) = + outcome.classify( + "vouch_test", + "linked_undef_crash_names_call_site_test", + invocation, + ) + assert string.inspect(reason) == "Undef" + assert site.module == "vouch_no_such_module" + assert site.function == "boom" + assert site.arity == 0 + // The linked process's undef also produces an emulator report; assert it + // was captured rather than printed. + let assert [_, ..] = await_diagnostics("vouch_no_such_module", 40) +} + +@target(erlang) +/// End to end: the report line a stale .beam produces. "Crashed: Undef" +/// alone is information-free; the call site is the answer. +pub fn describe_undef_crash_test() { + let invocation = + outcome.from_caught(runner.catch_panic(helpers.calls_missing_function)) + let assert outcome.Failed(detail) = + outcome.classify("vouch_test", "describe_undef_crash_test", invocation) + assert describe.failure(detail) + == ["Crashed: Undef calling vouch_no_such_module:boom/0"] +} + +/// A frame that carries a file and line gets an `at` line, in the same +/// clickable file:line shape as panic locations. +pub fn describe_crash_site_location_test() { + let site = + outcome.CrashSite( + module: "filepath", + function: "split", + arity: 1, + location: Some(#("src/filepath.erl", 145)), + ) + assert describe.failure(outcome.UnknownDetail( + dynamic.string("boom"), + Some(site), + )) + == [ + "Crashed: \"boom\" calling filepath:split/1", + " at src/filepath.erl:145", + ] +} + +/// No recognisable stacktrace — every JavaScript crash, exotic BEAM exit +/// reasons — falls back to the reason alone, exactly as before. +pub fn describe_crash_without_site_test() { + assert describe.failure(outcome.UnknownDetail(dynamic.string("boom"), None)) + == ["Crashed: \"boom\""] + assert describe.failure(outcome.ExitDetail(dynamic.string("kill"), None)) + == ["Test process died: \"kill\""] +} + +/// A death with a known site reads like a crash: the reason, then what was +/// being called. +pub fn describe_exit_with_site_test() { + let site = + outcome.CrashSite(module: "m", function: "f", arity: 2, location: None) + assert describe.failure(outcome.ExitDetail(dynamic.string("boom"), Some(site))) + == ["Test process died: \"boom\" calling m:f/2"] +} + // --- Tally and exit codes --- fn sample_todo_panic() -> gleam_panic.GleamPanic { @@ -467,6 +596,7 @@ pub fn config_defaults_test() { timeout_ms: config.default_timeout_ms, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, )) } @@ -479,6 +609,7 @@ pub fn config_format_and_filter_test() { timeout_ms: config.default_timeout_ms, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, )) assert config.from_args([ "--filter=decode", @@ -492,6 +623,7 @@ pub fn config_format_and_filter_test() { timeout_ms: 250, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, )) } @@ -519,6 +651,13 @@ pub fn config_parallel_test() { let assert Error(_) = config.from_args(["--parallel=lots"]) } +pub fn config_show_crash_reports_test() { + let assert Ok(config.Config(show_crash_reports: True, ..)) = + config.from_args(["--show-crash-reports"]) + // A flag, not an option: a value is an error like any unknown flag. + let assert Error(_) = config.from_args(["--show-crash-reports=yes"]) +} + pub fn config_color_test() { let assert Ok(config.Config(color: config.Never, ..)) = config.from_args(["--color=never"]) @@ -793,3 +932,67 @@ pub fn jsonl_todo_result_test() { <> "\"site_module\":\"some_module\",\"site_function\":\"some_function\"," <> "\"site_line\":1}" } + +/// A crash site reaches JSON consumers as structured fields, following the +/// site_* naming the todo outcome already uses. File and line appear only +/// when the frame carried them. +pub fn jsonl_crash_site_test() { + let site = + outcome.CrashSite( + module: "filepath", + function: "split", + arity: 1, + location: Some(#("src/filepath.erl", 145)), + ) + let out = + outcome.Failed(outcome.UnknownDetail(dynamic.string("boom"), Some(site))) + assert jsonl.event_to_json(event.TestResult("m", "f", out, 10)) + == "{\"event\":\"test_result\",\"module\":\"m\",\"function\":\"f\"," + <> "\"outcome\":\"fail\",\"duration_us\":10,\"kind\":\"unknown\"," + <> "\"message\":\"\\\"boom\\\"\",\"site_module\":\"filepath\"," + <> "\"site_function\":\"split\",\"site_arity\":1," + <> "\"site_file\":\"src/filepath.erl\",\"site_line\":145}" +} + +/// The TeamCity and JUnit failure messages carry the same call site as the +/// console wording. +pub fn teamcity_crash_site_test() { + let site = + outcome.CrashSite( + module: "filepath", + function: "split", + arity: 1, + location: None, + ) + let #(_, lines) = + teamcity.step( + None, + event.TestResult( + "m_test", + "x_test", + outcome.Failed(outcome.UnknownDetail(dynamic.string("boom"), Some(site))), + 0, + ), + ) + assert string.contains(string.join(lines, "\n"), "calling filepath:split/1") +} + +pub fn junit_crash_site_test() { + let site = + outcome.CrashSite( + module: "filepath", + function: "split", + arity: 1, + location: None, + ) + let results = [ + #( + "m_test", + "x_test", + outcome.Failed(outcome.UnknownDetail(dynamic.string("boom"), Some(site))), + 0, + ), + ] + let xml = junit.render(results, 0) + assert string.contains(xml, "calling filepath:split/1") +} From 0b3d60020d1513e983418b5315fde1fc28f6e95e Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Fri, 21 Aug 2026 22:18:48 +0100 Subject: [PATCH 2/8] Playground: a passing test whose background worker crashes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit background_job_test starts an unlinked process that panics and then passes — the case lpil asked about: with crash reports swallowed, how do you know? The e2e proves the answer end to end: a default run shows nothing of the crash, and --show-crash-reports prints the BEAM report after the summary. run_command_merged folds stderr into the captured stream for that one test; the stdout-only harness keeps proving the reports never reach stdout. Co-Authored-By: Claude Fable 5 --- examples/playground/src/playground.gleam | 12 +++++ examples/playground/src/playground_ffi.erl | 7 ++- examples/playground/src/playground_ffi.mjs | 6 +++ .../playground/test/playground_test.gleam | 14 ++++- test/vouch_e2e_ffi.erl | 15 ++++-- test/vouch_e2e_test.gleam | 51 +++++++++++++++++-- 6 files changed, 96 insertions(+), 9 deletions(-) diff --git a/examples/playground/src/playground.gleam b/examples/playground/src/playground.gleam index 75982bb..8d1723f 100644 --- a/examples/playground/src/playground.gleam +++ b/examples/playground/src/playground.gleam @@ -17,6 +17,18 @@ pub fn rate_limit(_requests: Int) -> Bool { @external(javascript, "./playground_ffi.mjs", "sleep") pub fn sleep(ms: Int) -> Nil +/// A fire-and-forget worker with a bug: the caller gets Nil back and +/// carries on, while the unlinked process it started dies. The test that +/// calls this passes — the crash is only visible through the BEAM's crash +/// report, which vouch swallows unless `--show-crash-reports` is given. +pub fn start_background_job() -> Nil { + spawn(fn() { panic as "background job crashed: queue is full" }) +} + +@external(erlang, "playground_ffi", "spawn") +@external(javascript, "./playground_ffi.mjs", "spawn") +fn spawn(job: fn() -> Nil) -> Nil + /// Stands in for a dependency whose .beam has gone stale or missing: no /// config_parser module exists, so on the BEAM the call raises undef and /// the report names config_parser:parse/1 from the stacktrace. On diff --git a/examples/playground/src/playground_ffi.erl b/examples/playground/src/playground_ffi.erl index 78b1a52..4ec408e 100644 --- a/examples/playground/src/playground_ffi.erl +++ b/examples/playground/src/playground_ffi.erl @@ -1,6 +1,11 @@ -module(playground_ffi). --export([sleep/1]). +-export([sleep/1, spawn/1]). sleep(Ms) -> timer:sleep(Ms), nil. + +%% Unlinked on purpose: the crash must not take the caller down. +spawn(Job) -> + erlang:spawn(Job), + nil. diff --git a/examples/playground/src/playground_ffi.mjs b/examples/playground/src/playground_ffi.mjs index dd3f2f3..fd12831 100644 --- a/examples/playground/src/playground_ffi.mjs +++ b/examples/playground/src/playground_ffi.mjs @@ -6,6 +6,12 @@ export function sleep(ms) { } } +// JavaScript has no process to leak: a thrown error in a deferred callback +// would take the whole runtime down, not a sibling. The job is simply not +// run, so the calling test passes on both targets and only the BEAM has a +// crash report to show. +export function spawn(_job) {} + // The JavaScript half of parse_config: a raw runtime error, standing in for // a broken FFI dependency. On Erlang the module itself is missing instead. export function parse(path) { diff --git a/examples/playground/test/playground_test.gleam b/examples/playground/test/playground_test.gleam index ba3d05c..01282b6 100644 --- a/examples/playground/test/playground_test.gleam +++ b/examples/playground/test/playground_test.gleam @@ -1,10 +1,13 @@ //// One test per outcome flavour, so a plain run shows vouch's full range: //// -//// gleam test - 2 pass, 4 fail, 2 todo, 1 skip +//// gleam test - 3 pass, 4 fail, 2 todo, 1 skip //// gleam test -- --timeout=100 - slow_test also fails as a timeout //// gleam test -- --filter=slow - just the slow test //// gleam test -- --format=json - the same as a JSONL stream //// gleam test -- --junit=report.xml - plus a CI-ready XML report +//// gleam test -- --show-crash-reports +//// - plus the BEAM crash report from +//// background_job_test's worker import playground import vouch @@ -17,6 +20,15 @@ pub fn fast_pass_test() { assert playground.add(1, 2) == 3 } +/// Passes — but the unlinked worker it starts crashes behind its back. The +/// only trace is the BEAM's crash report, which vouch captures and keeps +/// out of the test output; `--show-crash-reports` prints it after the +/// summary. (On JavaScript there is no worker, so nothing crashes.) +pub fn background_job_test() { + playground.start_background_job() + assert playground.add(0, 0) == 0 +} + /// Passes with the default 5000ms timeout; fails with --timeout=100. pub fn slow_test() { playground.sleep(300) diff --git a/test/vouch_e2e_ffi.erl b/test/vouch_e2e_ffi.erl index c602967..7d7729c 100644 --- a/test/vouch_e2e_ffi.erl +++ b/test/vouch_e2e_ffi.erl @@ -1,10 +1,18 @@ %% Test-only helper: run a command in a directory, capturing stdout and the -%% exit code. stderr is deliberately not captured — the e2e tests assert -%% that stdout alone is a clean stream. +%% exit code. stderr is deliberately not captured by run_command/3 — the +%% e2e tests assert that stdout alone is a clean stream. run_command_merged/3 +%% folds stderr into the same stream, for the one case that asserts on what +%% vouch prints to stderr (captured crash reports). -module(vouch_e2e_ffi). --export([run_command/3]). +-export([run_command/3, run_command_merged/3]). run_command(Command, Args, Dir) -> + run(Command, Args, Dir, []). + +run_command_merged(Command, Args, Dir) -> + run(Command, Args, Dir, [stderr_to_stdout]). + +run(Command, Args, Dir, Extra) -> case os:find_executable(unicode:characters_to_list(Command)) of false -> {error, nil}; @@ -16,6 +24,7 @@ run_command(Command, Args, Dir) -> eof, binary, hide + | Extra ]), collect(Port, [], undefined, false) end. diff --git a/test/vouch_e2e_test.gleam b/test/vouch_e2e_test.gleam index f7189ff..9c7308e 100644 --- a/test/vouch_e2e_test.gleam +++ b/test/vouch_e2e_test.gleam @@ -18,7 +18,7 @@ pub fn playground_erlang_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"outcome\":\"todo\"") assert string.contains(out, "\"site_function\":\"rate_limit\"") @@ -53,7 +53,7 @@ pub fn playground_javascript_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", ) // On JavaScript the crash is a raw TypeError with no site to extract. assert string.contains(out, "\"kind\":\"unknown\"") @@ -72,7 +72,7 @@ pub fn playground_timeout_e2e_test() { assert string.contains(out, "\"timeout_ms\":100") assert string.contains( out, - "\"event\":\"run_end\",\"passed\":1,\"failed\":5,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", ) } @@ -89,11 +89,46 @@ pub fn playground_parallel_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"site_function\":\"rate_limit\"") } +@target(erlang) +/// background_job_test passes while the unlinked worker it starts crashes. +/// The BEAM's crash report for that death must stay out of a default run +/// entirely, and come back — after the summary — with --show-crash-reports. +/// stderr is merged into the captured stream here because that is where +/// the reports go; the stdout-only harness above proves they never reach +/// stdout. +pub fn playground_crash_reports_e2e_test() { + let assert Ok(#(_, quiet)) = + run_command_merged( + "gleam", + ["test", "--", "--color=never"], + "examples/playground", + ) + assert string.contains(quiet, "ok playground_test.background_job_test") + assert !string.contains(quiet, "background job crashed") + assert !string.contains(quiet, "Error in process") + + let assert Ok(#(_, shown)) = + run_command_merged( + "gleam", + ["test", "--", "--color=never", "--show-crash-reports"], + "examples/playground", + ) + assert string.contains( + shown, + "vouch: 1 crash report captured during the run:", + ) + assert string.contains(shown, "background job crashed: queue is full") + // After the summary, not interleaved with the results. + let assert Ok(#(_, after_summary)) = + string.split_once(shown, "3 passed, 4 failed, 2 todo, 1 skipped") + assert string.contains(after_summary, "background job crashed: queue is full") +} + @target(erlang) @external(erlang, "vouch_e2e_ffi", "run_command") fn run_command( @@ -101,3 +136,11 @@ fn run_command( args: List(String), directory: String, ) -> Result(#(Int, String), Nil) + +@target(erlang) +@external(erlang, "vouch_e2e_ffi", "run_command_merged") +fn run_command_merged( + command: String, + args: List(String), + directory: String, +) -> Result(#(Int, String), Nil) From 2b25ead6e480758a55608e3bc08d5f5c70f9f6ca Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Fri, 21 Aug 2026 23:21:14 +0100 Subject: [PATCH 3/8] Fail a test whose background process crashes A process a test starts that dies without taking the test down (an unlinked worker, a fire-and-forget job) left the test passing and the run green; the BEAM's crash report was the only trace, and the capture commits on this branch had hidden even that. gleeunit behaves the same way (pass, exit 0, report printed mid-run). Each test process now runs under its own group leader, an io-forwarding proxy that every process it starts inherits and every crash report records, so a captured report is charged to exactly the test whose process died, under --parallel too. After each test the runner claims its reports and folds them into the outcome: a passing test with a crash fails as BackgroundCrashDetail (or is a Todo when the process died of a todo); a test's own failure wins. Reports nobody claims - arrived after their test finished, or from outside any test - are printed at the end and fail the run. Only crash-shaped logger events are captured; other logger output still goes to stderr. --show-crash-reports now additionally prints the raw BEAM reports. Emulator "Error in process" events are handled in logger_proxy, not the logger server, so that is the process the pre-claim flush round-trips. The playground's background_job_test now fails on Erlang (2 pass, 5 fail) and still passes on JavaScript, where nothing is spawned. Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 41 ++- README.md | 24 +- docs/chapters/execution.typ | 21 +- docs/chapters/test-model.typ | 7 +- examples/playground/src/playground.gleam | 7 +- examples/playground/src/playground_ffi.mjs | 4 +- .../playground/test/playground_test.gleam | 22 +- src/vouch/internal/config.gleam | 11 +- src/vouch/internal/describe.gleam | 23 ++ src/vouch/internal/outcome.gleam | 65 ++++ src/vouch/internal/report/jsonl.gleam | 6 + src/vouch/internal/report/junit.gleam | 7 + src/vouch/internal/report/teamcity.gleam | 6 + src/vouch/internal/runner.gleam | 125 +++++--- src/vouch_ffi.erl | 286 ++++++++++++++---- src/vouch_ffi.mjs | 13 +- test/helpers.gleam | 40 +++ test/vouch_e2e_test.gleam | 51 +++- test/vouch_helpers_ffi.erl | 14 + test/vouch_test.gleam | 212 +++++++++++-- 20 files changed, 816 insertions(+), 169 deletions(-) create mode 100644 test/vouch_helpers_ffi.erl diff --git a/CHANGELOG.md b/CHANGELOG.md index 9b10292..8d546ab 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,9 +2,44 @@ ## Unreleased -To keep the output of vouch clean, vouch now catches and suppresses any errors coming out of dying OTP processes. -If you need to inspect these crash reports, there is now the option `--show-crash-reports`. -These will be printed to stderr after the summary. +Crash reports now name what was being called. A test that dies with a +non-Gleam error (an undef from a stale or missing .beam, an FFI crash) +previously reported only the bare reason — "Crashed: Undef" — with the +failing call discarded. The stacktrace's top frame is now carried into the +report on the Erlang target: + + Crashed: Undef calling config_parser:parse/1 + +with an `at file:line` line when the frame carries one. The same site +reaches the TeamCity and JUnit failure messages, and the JSONL stream as +structured `site_module` / `site_function` / `site_arity` (plus +`site_file` / `site_line` when known) fields. JavaScript crashes are +unchanged: a JS stacktrace is an unparsed string, so there is no site to +extract. + +A process that crashes behind a test now fails it. On the Erlang target, an +unlinked worker, a fire-and-forget job, an actor nothing is monitoring — +anything a test starts that dies without taking the test down — used to +leave the test passing and the run green, with the BEAM's crash report on +stderr as the only trace. vouch now captures those crash reports and +charges each to the test whose process died (every process a test starts +inherits the test's group leader, which the report records, so attribution +is exact under `--parallel` too). The test fails: + + playground_test.background_job_test + Background process crashed at src/playground.gleam:26 + background job crashed: queue is full + +or is a todo, when the process died of a `todo`. A test that failed on its +own keeps its own failure. A report that arrives after its test finished, +or from a process no test started, is printed at the end and fails the +run. The JSONL stream carries it as `"kind":"background_crash"` with the +cause nested under `cause`; JUnit and TeamCity get a `background_crash` +failure with the same text. Other logger output (a library's warnings) is +not a crash and still goes to stderr. A new `--show-crash-reports` flag +additionally prints the full BEAM reports as one block on stderr after the +summary. JavaScript is unaffected: there are no processes to crash behind +a test there. ## v1.2.0 diff --git a/README.md b/README.md index 9677563..9995867 100644 --- a/README.md +++ b/README.md @@ -84,14 +84,30 @@ On Deno, watch mode also needs `allow_run = ["gleam"]` to spawn the inner runs ( | Outcome | Meaning | Exit code contribution | | --- | --- | --- | | pass | ran without panic | 0 | -| fail | assert/panic/crash/timeout | 1 | -| todo | hit `todo` in code under test | 1 — unimplemented is still not done | +| fail | assert/panic/crash/timeout, or a process the test started crashed | 1 | +| todo | hit `todo` in code under test (directly or in a process it started) | 1 — unimplemented is still not done | | skip | `todo` within test function | 0 | ## Crash reports -To keep the output of vouch clean, vouch catches and suppresses any errors coming out of dying OTP processes. -If you need to inspect these crash reports, there is the option `--show-crash-reports`. These will be printed to stderr after the summary. +On the Erlang target, a process that dies *with* a test (a linked process crashing, an actor +the test is calling hitting a `todo`) is reported through the test's own outcome. A process +that dies *behind* a test — an unlinked worker, a fire-and-forget job nothing is monitoring — +would leave the test passing, with the BEAM's crash report as the only trace. vouch captures +those reports and charges each to the test whose process died (every process a test starts +inherits its group leader, which the report records), so the test fails: + +``` + playground_test.background_job_test + Background process crashed at src/playground.gleam:26 + background job crashed: queue is full +``` + +If the process died of a `todo`, the test is a todo instead. A report that arrives after its +test has finished, or from a process no test started, is printed on stderr at the end and fails +the run. Other logger output (a library's warnings) is not a crash; it goes to stderr as +before. Pass `--show-crash-reports` to also get the full BEAM reports, printed as one block on +stderr after the summary. ## Target differences diff --git a/docs/chapters/execution.typ b/docs/chapters/execution.typ index 2adc572..66c06eb 100644 --- a/docs/chapters/execution.typ +++ b/docs/chapters/execution.typ @@ -23,12 +23,21 @@ fidelity for ordinary failures. The runner waits on three possibilities: killed and reported as a timeout failure. A hung test costs its timeout, not the whole run. -BEAM diagnostics (crash reports for processes that tests spawned) are routed -to stderr at run start by re-adding the default logger handler with -`type: standard_error` — they stay visible in a terminal but can never -corrupt piped stdout. (`logger:update_handler_config` silently ignores a -runtime type change; remove-and-re-add is required. The reports are -asynchronous and are often lost to `erlang:halt` entirely.) +BEAM crash reports (a process the test started dying: the emulator's "Error +in process", proc_lib crash reports, gen_\* terminate and supervisor child +reports) are diverted at run start from the default logger handler into an +ETS table, by a capture handler whose filter admits only crash-shaped events. +Each test process runs under its own group leader — a proxy forwarding io to +the real one — which every process it starts inherits and every crash report +records, so after each test the runner claims the reports charged to it and +folds them into the outcome: a passing test whose worker crashed fails +(`BackgroundCrashDetail`), or is a todo if the worker died of a `todo`. +Reports nobody claimed (arrived after their test finished, or from outside +any test) are printed at the end and fail the run. The default handler is +re-added with `type: standard_error` for everything else routed through +logger, so it stays visible but can never corrupt piped stdout. +(`logger:update_handler_config` silently ignores a runtime type change; +remove-and-re-add is required.) Known limitation, accepted for v1: a test that spawns unlinked long-lived processes, registers global names, or mutates shared ETS tables can still diff --git a/docs/chapters/test-model.typ b/docs/chapters/test-model.typ index 8f25f74..541160b 100644 --- a/docs/chapters/test-model.typ +++ b/docs/chapters/test-model.typ @@ -82,9 +82,12 @@ pub type TestOutcome { pub type FailureDetail { PanicDetail(GleamPanic) - UnknownDetail(raw: Dynamic) + UnknownDetail(raw: Dynamic, site: Option(CrashSite)) TimeoutDetail(after_ms: Int) - ExitDetail(raw: Dynamic) + ExitDetail(raw: Dynamic, site: Option(CrashSite)) + // A process the test started died behind its back; `cause` is the + // PanicDetail or UnknownDetail that killed it (Erlang target only). + BackgroundCrashDetail(cause: FailureDetail) } ``` diff --git a/examples/playground/src/playground.gleam b/examples/playground/src/playground.gleam index 8d1723f..41152f4 100644 --- a/examples/playground/src/playground.gleam +++ b/examples/playground/src/playground.gleam @@ -18,9 +18,10 @@ pub fn rate_limit(_requests: Int) -> Bool { pub fn sleep(ms: Int) -> Nil /// A fire-and-forget worker with a bug: the caller gets Nil back and -/// carries on, while the unlinked process it started dies. The test that -/// calls this passes — the crash is only visible through the BEAM's crash -/// report, which vouch swallows unless `--show-crash-reports` is given. +/// carries on, while the unlinked process it started dies. Nothing is +/// linked to or monitoring the worker, so the calling test would pass — +/// the BEAM's crash report is the only trace of the death, and vouch +/// charges it to the test as a "Background process crashed" failure. pub fn start_background_job() -> Nil { spawn(fn() { panic as "background job crashed: queue is full" }) } diff --git a/examples/playground/src/playground_ffi.mjs b/examples/playground/src/playground_ffi.mjs index fd12831..5ebd3cf 100644 --- a/examples/playground/src/playground_ffi.mjs +++ b/examples/playground/src/playground_ffi.mjs @@ -8,8 +8,8 @@ export function sleep(ms) { // JavaScript has no process to leak: a thrown error in a deferred callback // would take the whole runtime down, not a sibling. The job is simply not -// run, so the calling test passes on both targets and only the BEAM has a -// crash report to show. +// run, so background_job_test passes on JavaScript and fails on the BEAM, +// where the worker really does crash — a documented target difference. export function spawn(_job) {} // The JavaScript half of parse_config: a raw runtime error, standing in for diff --git a/examples/playground/test/playground_test.gleam b/examples/playground/test/playground_test.gleam index 01282b6..4ce4e84 100644 --- a/examples/playground/test/playground_test.gleam +++ b/examples/playground/test/playground_test.gleam @@ -1,13 +1,16 @@ //// One test per outcome flavour, so a plain run shows vouch's full range: //// -//// gleam test - 3 pass, 4 fail, 2 todo, 1 skip +//// gleam test - 2 pass, 5 fail, 2 todo, 1 skip +//// (JavaScript: 3 pass, 4 fail — no +//// process crashes behind +//// background_job_test there) //// gleam test -- --timeout=100 - slow_test also fails as a timeout //// gleam test -- --filter=slow - just the slow test //// gleam test -- --format=json - the same as a JSONL stream //// gleam test -- --junit=report.xml - plus a CI-ready XML report //// gleam test -- --show-crash-reports -//// - plus the BEAM crash report from -//// background_job_test's worker +//// - plus the full BEAM crash report +//// from background_job_test's worker import playground import vouch @@ -20,12 +23,17 @@ pub fn fast_pass_test() { assert playground.add(1, 2) == 3 } -/// Passes — but the unlinked worker it starts crashes behind its back. The -/// only trace is the BEAM's crash report, which vouch captures and keeps -/// out of the test output; `--show-crash-reports` prints it after the -/// summary. (On JavaScript there is no worker, so nothing crashes.) +/// The test body passes — but the unlinked worker it starts crashes behind +/// its back, and nothing is linked to or monitoring it. The BEAM's crash +/// report is the only trace; vouch charges it to this test, which fails as +/// "Background process crashed". `--show-crash-reports` prints the raw +/// report too. (On JavaScript there is no worker, so this passes.) pub fn background_job_test() { playground.start_background_job() + // Give the job a moment, as a test of fire-and-forget code typically + // does; it also makes the worker's death land before the test ends, so + // the outcome is the same on a one-scheduler CI box. + playground.sleep(20) assert playground.add(0, 0) == 0 } diff --git a/src/vouch/internal/config.gleam b/src/vouch/internal/config.gleam index 588d1a3..3cb6dee 100644 --- a/src/vouch/internal/config.gleam +++ b/src/vouch/internal/config.gleam @@ -34,9 +34,10 @@ pub type Config { timeout_ms: Int, color: ColorChoice, parallel: Parallelism, - /// Reprint the BEAM crash reports captured during the run (processes - /// the tests spawned dying) after the summary. Off by default: a death - /// under a test already shows in the test's outcome. + /// Reprint, in full, the BEAM crash reports captured during the run + /// (processes the tests started dying) after the summary. Off by + /// default: a death under a test already shows in the test's outcome, + /// as its own failure or a "Background process crashed" one. show_crash_reports: Bool, ) } @@ -139,8 +140,8 @@ fn usage(problem: String) -> String { <> " --parallel[=n] run tests concurrently on the Erlang target with n\n" <> " workers (default: one per scheduler)\n" <> " --show-crash-reports\n" - <> " print the BEAM crash reports of processes that died\n" - <> " during the run after the summary (Erlang target)\n" + <> " also print the full BEAM crash reports of processes\n" + <> " that died during the run, after the summary (Erlang)\n" <> " --color=mode console colour: auto (default), always, never;\n" <> " auto respects NO_COLOR and non-TTY output\n" <> "\n" diff --git a/src/vouch/internal/describe.gleam b/src/vouch/internal/describe.gleam index 8fa441f..86759b6 100644 --- a/src/vouch/internal/describe.gleam +++ b/src/vouch/internal/describe.gleam @@ -46,9 +46,32 @@ pub fn failure(detail: FailureDetail) -> List(String) { "Test process died: " <> crash(raw, site), ..at_line(site) ] + outcome.BackgroundCrashDetail(cause) -> background_crash(cause) } } +/// A process the test started died behind its back. The cause is rendered +/// the way the same crash would be for the test itself — a panic's +/// expectation lines, a raw reason with its call site — under a first line +/// that says a background process is what died, and where. +fn background_crash(cause: FailureDetail) -> List(String) { + case cause { + outcome.PanicDetail(p) -> [ + "Background process crashed at " <> location(p), + ..list.map(failure(cause), indent) + ] + outcome.UnknownDetail(raw, site) -> [ + "Background process crashed: " <> crash(raw, site), + ..at_line(site) + ] + _ -> ["Background process crashed", ..list.map(failure(cause), indent)] + } +} + +fn indent(line: String) -> String { + " " <> line +} + /// The reason with its call site: `Undef calling filepath:split/1`. The /// shared summary every reporter embeds after its own prefix; without a /// site — every JavaScript crash — it is the reason alone. diff --git a/src/vouch/internal/outcome.gleam b/src/vouch/internal/outcome.gleam index 5c4ca61..ea27741 100644 --- a/src/vouch/internal/outcome.gleam +++ b/src/vouch/internal/outcome.gleam @@ -6,6 +6,7 @@ //// it fails the run, but reported distinctly from a broken test. import gleam/dynamic.{type Dynamic} +import gleam/list import gleam/option.{type Option} import vouch/internal/gleam_panic.{type GleamPanic} @@ -40,6 +41,21 @@ pub type FailureDetail { /// The test process died without reporting: an exit signal it did not /// cause by panicking, e.g. an explicit exit. ExitDetail(raw: Dynamic, site: Option(CrashSite)) + /// A process the test started died while the test ran, without taking + /// the test down with it — an unlinked worker, a fire-and-forget job. + /// The test itself may have passed; the BEAM's crash report for the + /// death was captured and charged to the test (Erlang target only). + /// `cause` is what killed the process: a `PanicDetail` for a Gleam + /// panic or failed assertion, an `UnknownDetail` for anything else. + BackgroundCrashDetail(cause: FailureDetail) +} + +/// The BEAM's report of a process dying while a test ran, as captured by +/// the runner's logger handler: the exit reason the report carried (a +/// Gleam panic map for a panic, assert or todo; a raw term otherwise) and +/// the report text as the default handler would have printed it. +pub type CrashReport { + CrashReport(reason: Dynamic, text: String) } /// The top frame of the stacktrace behind a non-Gleam crash: what was being @@ -117,3 +133,52 @@ pub fn classify_panic( _ -> Failed(PanicDetail(p)) } } + +/// Fold the crash reports charged to a test into its outcome. A process +/// the test started and died behind its back is a failure of the test — +/// or a Todo, when what killed the process was unimplemented code, by the +/// same rule as a todo the test reached directly. The more severe verdict +/// wins (Failed over Todo over Skipped over Pass), the test's own on a tie: +/// a test that failed on its own keeps its own failure, and the reports +/// stay available to `--show-crash-reports`. +pub fn with_crash_reports( + own: TestOutcome, + test_module: String, + test_function: String, + reports: List(CrashReport), +) -> TestOutcome { + list.fold(reports, own, fn(worst, report) { + let crash = classify_report(test_module, test_function, report) + case severity(crash) > severity(worst) { + True -> crash + False -> worst + } + }) +} + +fn classify_report( + test_module: String, + test_function: String, + report: CrashReport, +) -> TestOutcome { + case gleam_panic.from_dynamic(report.reason) { + Ok(p) -> + case classify_panic(test_module, test_function, p) { + Failed(cause) -> Failed(BackgroundCrashDetail(cause)) + todo_or_skipped -> todo_or_skipped + } + Error(Nil) -> { + let #(reason, site) = split_crash(report.reason) + Failed(BackgroundCrashDetail(UnknownDetail(reason, site))) + } + } +} + +fn severity(out: TestOutcome) -> Int { + case out { + Pass -> 0 + Skipped(_) -> 1 + Todo(_) -> 2 + Failed(_) -> 3 + } +} diff --git a/src/vouch/internal/report/jsonl.gleam b/src/vouch/internal/report/jsonl.gleam index ac5ba1c..23be4d2 100644 --- a/src/vouch/internal/report/jsonl.gleam +++ b/src/vouch/internal/report/jsonl.gleam @@ -90,6 +90,12 @@ fn outcome_fields(out: TestOutcome) -> List(#(String, json.Value)) { outcome.Failed(outcome.ExitDetail(raw, site)) -> [#("kind", Str("died")), #("message", Str(string.inspect(raw)))] |> list.append(site_fields(site)) + // The cause is nested, encoded exactly as the same crash would be for + // the test itself, so consumers reuse their failure decoding for it. + outcome.Failed(outcome.BackgroundCrashDetail(cause)) -> [ + #("kind", Str("background_crash")), + #("cause", Obj(outcome_fields(outcome.Failed(cause)))), + ] } } diff --git a/src/vouch/internal/report/junit.gleam b/src/vouch/internal/report/junit.gleam index 623cbb8..cfd47ce 100644 --- a/src/vouch/internal/report/junit.gleam +++ b/src/vouch/internal/report/junit.gleam @@ -134,6 +134,13 @@ fn test_case(r: Case) -> String { <> ">\n escape(describe.crash(raw, site)) <> "\"/>\n \n" + outcome.Failed(outcome.BackgroundCrashDetail(_) as detail) -> + open + <> ">\n escape("a process the test started crashed") + <> "\">" + <> escape(string.join(describe.failure(detail), "\n")) + <> "\n \n" } } diff --git a/src/vouch/internal/report/teamcity.gleam b/src/vouch/internal/report/teamcity.gleam index c2d15e8..1421a49 100644 --- a/src/vouch/internal/report/teamcity.gleam +++ b/src/vouch/internal/report/teamcity.gleam @@ -122,6 +122,12 @@ fn failure(function: String, detail: outcome.FailureDetail) -> String { failed(function, "timed out after " <> int.to_string(ms) <> "ms", "") outcome.ExitDetail(raw, site) -> failed(function, "test process died", describe.crash(raw, site)) + outcome.BackgroundCrashDetail(_) -> + failed( + function, + "a process the test started crashed", + string.join(describe.failure(detail), "\n"), + ) } } diff --git a/src/vouch/internal/runner.gleam b/src/vouch/internal/runner.gleam index 81d428e..314438f 100644 --- a/src/vouch/internal/runner.gleam +++ b/src/vouch/internal/runner.gleam @@ -67,36 +67,73 @@ fn finish( ) -> Nil { let t = tally(outcomes) let _ = rep.handle(state, event.RunEnd(t, duration)) + let unattributed = unattributed_crash_reports() + print_unattributed(unattributed) case show_crash_reports { - True -> print_crash_reports(drain_diagnostics()) + True -> print_crash_reports(all_crash_reports()) False -> Nil } - halt(exit_code(t)) + case unattributed { + [] -> halt(exit_code(t)) + // A crash no outcome accounts for must not hide behind a green run. + _ -> halt(1) + } } -/// `--show-crash-reports`: the BEAM diagnostics captured during the run -/// (crash reports from processes the tests spawned, logger output), -/// reprinted as one block after the summary on stderr — visible in a -/// terminal, clear of a machine-read stdout stream (JSONL, TeamCity). -fn print_crash_reports(reports: List(String)) -> Nil { +/// Crash reports no test claimed: the process died after its test had +/// finished (named here, from the group leader it inherited), or outside +/// any test. Printed on stderr — clear of a machine-read stdout stream — +/// and the run fails. +fn print_unattributed( + reports: List(#(String, Option(#(String, String)))), +) -> Nil { case reports { [] -> Nil _ -> { - let noun = case reports { - [_] -> "crash report" - _ -> "crash reports" - } term.warn( - int.to_string(list.length(reports)) - <> " " - <> noun - <> " captured during the run:", + count(reports, "crash report") + <> " not charged to any test — the run fails:", ) + list.each(reports, fn(report) { + let #(text, owner) = report + case owner { + option.Some(#(module, function)) -> + io.print_error( + "vouch: from a process started by " + <> module + <> "." + <> function + <> ", which died after the test finished:\n", + ) + option.None -> + io.print_error("vouch: from a process no test started:\n") + } + io.print_error(text) + }) + } + } +} + +/// `--show-crash-reports`: every BEAM crash report captured during the run, +/// attributed or not, reprinted in full as one block after the summary on +/// stderr — the raw report behind a "Background process crashed" failure. +fn print_crash_reports(reports: List(String)) -> Nil { + case reports { + [] -> Nil + _ -> { + term.warn(count(reports, "crash report") <> " captured during the run:") list.each(reports, io.print_error) } } } +fn count(items: List(a), noun: String) -> String { + case items { + [_] -> "1 " <> noun + _ -> int.to_string(list.length(items)) <> " " <> noun <> "s" + } +} + /// Call a function, capturing any panic as the raw target-specific value. /// On JavaScript the call is synchronous; async functions are not awaited /// here (the JavaScript run loop awaits discovered tests itself). @@ -218,9 +255,11 @@ fn run_sequential( let #(module, function) = test_case let state = rep.handle(state, event.TestStart(module, function)) let test_started = now_microseconds() - let invocation = run_in_process(module, function, timeout_ms) + let #(invocation, reports) = run_in_process(module, function, timeout_ms) let duration = now_microseconds() - test_started - let out = outcome.classify(module, function, invocation) + let out = + outcome.classify(module, function, invocation) + |> outcome.with_crash_reports(module, function, reports) let state = rep.handle(state, event.TestResult(module, function, out, duration)) #(state, [out, ..outcomes]) @@ -263,8 +302,10 @@ fn run_window( case running { [] -> #(state, outcomes) [#(module, function, handle), ..running_rest] -> { - let #(invocation, duration) = await_test(handle) - let out = outcome.classify(module, function, invocation) + let #(invocation, reports, duration) = await_test(handle) + let out = + outcome.classify(module, function, invocation) + |> outcome.with_crash_reports(module, function, reports) let state = rep.handle(state, event.TestResult(module, function, out, duration)) run_window( @@ -282,20 +323,29 @@ fn run_window( } } +/// Divert BEAM crash reports from the default logger handler into a table +/// the runner reads after each test (see vouch_ffi.erl). Installed once per +/// run, before any test starts. @external(erlang, "vouch_ffi", "capture_diagnostics") @external(javascript, "../../vouch_ffi.mjs", "capture_diagnostics") fn capture_diagnostics() -> Nil -/// Remove and return every captured BEAM diagnostic, in arrival order. -@external(erlang, "vouch_ffi", "drain_diagnostics") -@external(javascript, "../../vouch_ffi.mjs", "drain_diagnostics") -fn drain_diagnostics() -> List(String) - -/// Remove and return the captured BEAM diagnostics whose text contains -/// `marker`, leaving the rest for `--show-crash-reports`. Public so vouch's -/// own suite can prove that a deliberately-crashed process's report was -/// swallowed by the capture handler rather than reaching stderr, without -/// touching reports that belong to other tests. +/// The text of every captured crash report, in arrival order. +@external(erlang, "vouch_ffi", "all_diagnostics") +@external(javascript, "../../vouch_ffi.mjs", "all_diagnostics") +fn all_crash_reports() -> List(String) + +/// The captured crash reports no test claimed, each with the test whose +/// process tree the dying process belonged to, when it was one. +@external(erlang, "vouch_ffi", "unattributed_diagnostics") +@external(javascript, "../../vouch_ffi.mjs", "unattributed_diagnostics") +fn unattributed_crash_reports() -> List(#(String, Option(#(String, String)))) + +/// Remove and return the captured crash reports whose text contains +/// `marker`, leaving the rest alone. Public so vouch's own suite can crash a +/// process in its own process tree on purpose, consume the report (so the +/// test is not charged with it) and assert it was captured rather than +/// printed, without touching reports that belong to other tests. @external(erlang, "vouch_ffi", "take_diagnostics_matching") @external(javascript, "../../vouch_ffi.mjs", "take_diagnostics_matching") pub fn take_diagnostics_matching(marker: String) -> List(String) @@ -315,23 +365,26 @@ fn find_test_files() -> List(String) fn exported_zero_arity(module: String) -> List(String) /// Run one exported zero-arity function in its own monitored process with a -/// timeout. Public so vouch's own suite can exercise isolation directly. +/// timeout, and collect the crash reports of processes it started that died +/// while it ran. Public so vouch's own suite can exercise isolation +/// directly. @external(erlang, "vouch_ffi", "run_test") @external(javascript, "../../vouch_ffi.mjs", "run_test") pub fn run_in_process( module: String, function: String, timeout_ms: Int, -) -> outcome.Invocation +) -> #(outcome.Invocation, List(outcome.CrashReport)) /// An in-flight test started by `start_test`: created and consumed only by /// the FFI. pub type TestHandle /// Start one test without waiting for it. The spawned middleman runs the -/// same run_test as the sequential path — identical isolation and timeout -/// semantics — and `await_test` collects the invocation and its duration -/// in microseconds. Public so the suite can prove concurrency directly. +/// same run_test as the sequential path — identical isolation, timeout and +/// crash-report semantics — and `await_test` collects the invocation, the +/// crash reports charged to the test, and its duration in microseconds. +/// Public so the suite can prove concurrency directly. @external(erlang, "vouch_ffi", "start_test") @external(javascript, "../../vouch_ffi.mjs", "start_test") pub fn start_test( @@ -342,7 +395,9 @@ pub fn start_test( @external(erlang, "vouch_ffi", "await_test") @external(javascript, "../../vouch_ffi.mjs", "await_test") -pub fn await_test(handle: TestHandle) -> #(outcome.Invocation, Int) +pub fn await_test( + handle: TestHandle, +) -> #(outcome.Invocation, List(outcome.CrashReport), Int) @external(erlang, "vouch_ffi", "schedulers_online") @external(javascript, "../../vouch_ffi.mjs", "schedulers_online") diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index b63f7d2..3d831de 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -10,9 +10,12 @@ is_stdout_tty/0, env/1, capture_diagnostics/0, - drain_diagnostics/0, + all_diagnostics/0, + unattributed_diagnostics/0, take_diagnostics_matching/1, + crash_filter/2, log/2, + forward_io/1, write_file/2, read_source/3, halt/1, @@ -75,19 +78,23 @@ env(Name) -> Value -> {ok, unicode:characters_to_binary(Value)} end. -%% Swallow BEAM diagnostics (crash reports from processes that tests -%% spawned, anything else routed through OTP's logger) instead of letting -%% the default handler print them around the test output. A process that -%% dies under a test is already reported through the test's own outcome; -%% the BEAM's report of the same death is a duplicate. This module doubles -%% as the logger handler: log/2 renders each event with the formatter the -%% default handler would have used and stashes the text in a public ETS -%% table. The runner drains and prints that table after the summary only -%% when asked (--show-crash-reports); otherwise it is never read, except by -%% vouch's own suite proving the reports were captured. If the capture -%% handler cannot be installed, fall back to redirecting the default -%% handler to stderr: reports on stderr beat reports corrupting a +%% BEAM crash reports — a process dying with an uncaught error (the +%% emulator's "Error in process"), a proc_lib CRASH REPORT, a gen_* +%% "terminating" report, a supervisor's child-died report — are diverted +%% away from the default logger handler into a public ETS table. The runner +%% reads that table after each test and charges each report to the test +%% whose process died (see the per-test group leaders in run_test/3), so a +%% worker that crashes behind an otherwise passing test still turns the +%% test red; the raw report text is printed only on request +%% (--show-crash-reports). Everything else routed through logger (a +%% library's warnings, a test's own log lines) is not a crash and still +%% prints, via the default handler moved to stderr so it cannot corrupt a %% machine-read stdout stream. +%% +%% This module doubles as the capture handler: crash_filter/2 selects the +%% events and log/2 stores each one rendered with the default handler's own +%% formatter. If the capture handler cannot be installed, reports stay on +%% stderr — still better than corrupting stdout. capture_diagnostics() -> catch case logger:get_handler_config(vouch_diagnostics) of {ok, _} -> @@ -95,23 +102,37 @@ capture_diagnostics() -> ok; _ -> case logger:get_handler_config(default) of - {ok, #{filters := Filters, formatter := Formatter}} -> + {ok, #{formatter := Formatter}} -> ensure_diagnostics_table(), - %% Added before the default handler is removed, so no - %% window exists where an event is dropped entirely. - case logger:add_handler(vouch_diagnostics, ?MODULE, - #{filters => Filters, formatter => Formatter}) of - ok -> logger:remove_handler(default); - _ -> redirect_default_to_stderr() + Capture = logger:add_handler(vouch_diagnostics, ?MODULE, #{ + formatter => Formatter, + filter_default => stop, + filters => [{vouch_crashes_only, + {fun ?MODULE:crash_filter/2, only}}] + }), + redirect_default_to_stderr(), + case Capture of + ok -> + %% Only once the capture handler is live, so no + %% crash report is dropped by both sides. + logger:add_handler_filter(default, + vouch_crashes_out, + {fun ?MODULE:crash_filter/2, stop}); + _ -> + ok end; _ -> %% No default handler: nothing would have printed, so - %% there is nothing to capture. + %% there is nothing to divert. ok end end, nil. +%% Rows are {Key, GroupLeader, Text, Reason, Claimed} for captured reports +%% (Key from unique_integer([monotonic]), so arrival order is table order) +%% and {{test, GroupLeader}, Module, Function} naming the test each +%% per-test group leader belongs to. ensure_diagnostics_table() -> case ets:whereis(vouch_diagnostics) of undefined -> @@ -121,13 +142,45 @@ ensure_diagnostics_table() -> ok end. +%% Logger filter, used two ways: `only` passes crash reports and stops +%% everything else (the capture handler), `stop` stops crash reports and +%% leaves the rest to the remaining filters (the default handler). +crash_filter(Event, Mode) -> + case {is_crash_report(Event), Mode} of + {true, only} -> Event; + {true, stop} -> stop; + {false, only} -> stop; + {false, stop} -> ignore + end. + +%% The shapes the BEAM and OTP use for a dying process. Only these are +%% crashes; an error-level log line from the code under test is not. +is_crash_report(#{msg := {Format, _}, meta := #{error_logger := #{emulator := true}}}) + when is_list(Format) -> + lists:prefix("Error in process", Format); +is_crash_report(#{meta := #{error_logger := #{type := crash_report}}}) -> + true; +is_crash_report(#{msg := {report, #{label := {proc_lib, crash}}}}) -> + true; +is_crash_report(#{level := error, msg := {report, #{label := {_, terminate}}}}) -> + true; +is_crash_report(#{level := error, msg := {report, #{label := {supervisor, _}}}}) -> + true; +is_crash_report(_) -> + false. + %% Logger handler callback, installed by capture_diagnostics/0. Runs in the %% logging process for logger API calls and in the logger server for %% emulator-generated reports; either way, render now and append. Must %% never raise: logger removes a handler whose callback crashes. -log(Event, Config) -> - catch ets:insert(vouch_diagnostics, - {erlang:unique_integer([monotonic]), render_diagnostic(Event, Config)}), +log(#{meta := Meta} = Event, Config) -> + catch ets:insert(vouch_diagnostics, { + erlang:unique_integer([monotonic]), + maps:get(gl, Meta, undefined), + render_diagnostic(Event, Config), + report_reason(Event), + false + }), ok. render_diagnostic(Event, Config) -> @@ -141,41 +194,92 @@ render_diagnostic(Event, Config) -> unicode:characters_to_binary(io_lib:format("~0tp~n", [Event])) end. -%% All captured diagnostics in arrival order, removed from the table. Only -%% the returned rows are deleted, so an event arriving mid-drain is kept -%% rather than silently discarded. -drain_diagnostics() -> - take_diagnostics(fun(_Text) -> true end). +%% The exit reason a crash report carries, in the {Reason, Stacktrace} shape +%% catch_panic produces, so the Gleam side decodes a report exactly like a +%% caught panic: find_panic reaches a gleam_error map inside it and +%% split_crash names the top frame of anything else. Unknown report shapes +%% pass the whole message through. +report_reason(#{msg := {_Format, Args}, meta := #{error_logger := #{emulator := true}}}) + when is_list(Args), Args =/= [] -> + %% "Error in process ~p [on node ~p] with exit value:~n~p~n": the exit + %% value is the last argument, already {Reason, Stacktrace}. + lists:last(Args); +report_reason(#{msg := {report, #{label := {proc_lib, crash}, report := [Info | _]}}}) + when is_list(Info) -> + case lists:keyfind(error_info, 1, Info) of + {error_info, {error, Reason, Stack}} -> {Reason, Stack}; + {error_info, {Class, Reason, Stack}} -> {{Class, Reason}, Stack}; + _ -> Info + end; +report_reason(#{msg := {report, #{label := {_, terminate}, reason := Reason}}}) -> + Reason; +report_reason(#{msg := {report, #{label := {supervisor, _}, report := Report}}}) + when is_list(Report) -> + case lists:keyfind(reason, 1, Report) of + {reason, Reason} -> Reason; + false -> Report + end; +report_reason(#{msg := Msg}) -> + Msg. + +%% Every captured report's text, in arrival order, for --show-crash-reports. +all_diagnostics() -> + flush_logger(), + [Text || {Key, _GL, Text, _Reason, _Claimed} <- rows(), is_integer(Key)]. + +%% The reports no test claimed — arrived after their test had finished, or +%% from a process no test started — each with the test its group leader +%% belonged to, when there was one. The run fails on these: a crash the +%% outcomes do not account for must not hide behind a green summary. +unattributed_diagnostics() -> + flush_logger(), + [{Text, test_of(GL)} + || {Key, GL, Text, _Reason, false} <- rows(), is_integer(Key)]. + +test_of(GL) -> + case catch ets:lookup(vouch_diagnostics, {test, GL}) of + [{_, Module, Function}] -> {some, {Module, Function}}; + _ -> none + end. -%% Remove and return only the captured diagnostics whose text contains -%% Marker, leaving the rest alone. The suite-facing probe: a spec that -%% deliberately crashes a process can assert its report was captured -%% without touching reports that belong to other tests. +%% Remove and return only the captured reports whose text contains Marker, +%% leaving the rest alone. The suite-facing probe: a test that deliberately +%% crashes a process in its own process tree can consume the report (so it +%% is not charged to the test) and assert it was captured rather than +%% printed, without touching reports that belong to other tests. take_diagnostics_matching(Marker) -> - take_diagnostics(fun(Text) -> - binary:match(Text, Marker) =/= nomatch - end). - -%% Emulator-generated reports travel through the logger server's mailbox -%% (API-call events are handled in the logging process itself, before the -%% crash propagates), so a synchronous round-trip first makes sure -%% everything already sent is in the table before it is read. -take_diagnostics(Keep) -> - catch sys:get_state(logger, 1000), + flush_logger(), + [begin + catch ets:delete(vouch_diagnostics, Key), + Text + end + || {Key, _GL, Text, _Reason, _Claimed} <- rows(), + is_integer(Key), binary:match(Text, Marker) =/= nomatch]. + +rows() -> case catch ets:tab2list(vouch_diagnostics) of - Rows when is_list(Rows) -> - [begin - catch ets:delete(vouch_diagnostics, Key), - Text - end || {Key, Text} <- Rows, Keep(Text)]; - _ -> - [] + Rows when is_list(Rows) -> Rows; + _ -> [] end. -%% Fallback when the capture handler cannot be installed: route the default -%% handler to stderr, so stdout stays a clean stream for reporters. -%% logger_std_h does not honour a runtime `type` change, so the handler is -%% removed and re-added with its filters and formatter preserved. +%% Emulator-generated reports ("Error in process") are handled in the +%% logger_proxy process, whose mailbox they travel through; API-call events +%% (proc_lib, gen_server) are handled in the logging process itself, before +%% the crash propagates. A synchronous round-trip through logger_proxy makes +%% sure everything already sent is in the table before it is read. The +%% emulator sends the report before the dying process's exit signals and +%% monitors fire, so a death the test observed is always in the table by +%% the time the test's result reaches the runner. The logger server itself +%% is round-tripped too, cheaply, in case an OTP release routes through it. +flush_logger() -> + catch sys:get_state(logger_proxy, 1000), + catch sys:get_state(logger, 1000). + +%% Route the default handler to stderr, so whatever it still prints (and +%% everything, if the capture handler could not be installed) stays off the +%% stdout stream reporters own. logger_std_h does not honour a runtime +%% `type` change, so the handler is removed and re-added with its filters +%% and formatter preserved. redirect_default_to_stderr() -> case logger:get_handler_config(default) of {ok, #{module := Module, config := HConfig} = Cfg} -> @@ -217,16 +321,27 @@ exported_zero_arity(ModuleName) -> %% catches its own panic and sends the payload back, so decoding never %% depends on exit-reason fidelity; the DOWN branch only fires when the %% process died without reporting (exit signal, linked crash), and a test -%% that outlives the timeout is killed. Return values are the constructors -%% of vouch/internal/outcome.Invocation. +%% that outlives the timeout is killed. Returns {Invocation, CrashReports}: +%% a constructor of vouch/internal/outcome.Invocation, and the crash reports +%% of processes the test started that died while it ran (outcome.CrashReport +%% tuples), which the runner folds into the test's outcome. +%% +%% The test process runs under its own group leader, a proxy that forwards +%% io to the real one (start_group_leader/2). Every process the test starts +%% inherits it, and every crash report the BEAM logs names the dying +%% process's group leader, so a report is charged to exactly the test whose +%% process died — in a parallel run as much as a sequential one — and a +%% report that arrives late can still say which test it belonged to. run_test(ModuleName, FunctionName, TimeoutMs) -> Module = binary_to_atom(beam_name(ModuleName), utf8), Function = binary_to_atom(FunctionName, utf8), Self = self(), + Leader = start_group_leader(ModuleName, FunctionName), {Pid, Ref} = spawn_monitor(fun() -> + group_leader(Leader, self()), Self ! {vouch_result, self(), catch_panic(fun() -> Module:Function() end)} end), - receive + Invocation = receive {vouch_result, Pid, {ok, nil}} -> erlang:demonitor(Ref, [flush]), passed; @@ -245,32 +360,73 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> after 0 -> ok end, {timed_out, TimeoutMs} + end, + {Invocation, claim_crash_reports(Leader)}. + +%% A group leader for one test: forwards every message (io requests, whose +%% replies go straight back to the requester) to the real group leader, so +%% tests and their processes print exactly as before. It is never stopped: +%% a worker the test left running may still be printing through it after +%% the test is over, and an io request to a dead leader raises. Idle +%% leaders hibernate down to a few hundred bytes each. +start_group_leader(ModuleName, FunctionName) -> + Real = group_leader(), + Leader = spawn(?MODULE, forward_io, [Real]), + catch ets:insert(vouch_diagnostics, {{test, Leader}, ModuleName, FunctionName}), + Leader. + +forward_io(Real) -> + receive + Message -> + Real ! Message, + forward_io(Real) + after 200 -> + erlang:hibernate(?MODULE, forward_io, [Real]) + end. + +%% The captured crash reports of processes under Leader, oldest first, each +%% marked claimed so the end-of-run sweep for unattributed reports skips +%% it. Flushing first is what makes this deterministic for a death the test +%% observed (see flush_logger/0). +claim_crash_reports(Leader) -> + flush_logger(), + case catch ets:select(vouch_diagnostics, + [{{'$1', Leader, '$2', '$3', false}, + [{is_integer, '$1'}], + [{{'$1', '$2', '$3'}}]}]) of + Rows when is_list(Rows) -> + [begin + catch ets:update_element(vouch_diagnostics, Key, {5, true}), + {crash_report, Reason, Text} + end || {Key, Text, Reason} <- Rows]; + _ -> + [] end. %% Parallel execution: start one test without blocking on it. The spawned %% middleman runs the same run_test/3 as the sequential path — identical -%% isolation and timeout semantics — measures the duration, and posts the -%% result back tagged with a unique ref. The monitor covers the -%% theoretical case of the middleman dying before it reports. +%% isolation, timeout and crash-report semantics — measures the duration, +%% and posts the result back tagged with a unique ref. The monitor covers +%% the theoretical case of the middleman dying before it reports. start_test(Module, Function, TimeoutMs) -> Self = self(), Ref = make_ref(), {_Pid, MonRef} = spawn_monitor(fun() -> Started = erlang:monotonic_time(microsecond), - Result = run_test(Module, Function, TimeoutMs), + {Invocation, Reports} = run_test(Module, Function, TimeoutMs), Duration = erlang:monotonic_time(microsecond) - Started, - Self ! {vouch_parallel, Ref, Result, Duration} + Self ! {vouch_parallel, Ref, Invocation, Reports, Duration} end), {Ref, MonRef}. await_test({Ref, MonRef}) -> receive - {vouch_parallel, Ref, Result, Duration} -> + {vouch_parallel, Ref, Invocation, Reports, Duration} -> erlang:demonitor(MonRef, [flush]), - {Result, Duration}; + {Invocation, Reports, Duration}; {'DOWN', MonRef, process, _Pid, Reason} -> - {{died, Reason}, 0} + {{died, Reason}, [], 0} end. schedulers_online() -> diff --git a/src/vouch_ffi.mjs b/src/vouch_ffi.mjs index 8fee2aa..fcbaf46 100644 --- a/src/vouch_ffi.mjs +++ b/src/vouch_ffi.mjs @@ -79,10 +79,15 @@ export function capture_diagnostics() { erlangOnly("capture_diagnostics"); } -// The run loop drains on every target when --show-crash-reports is given; -// JavaScript has no logger capture, so there is never anything to hand -// back (the flag is warned about as ineffective). -export function drain_diagnostics() { +// The run loop reads the crash-report table on every target at the end of +// the run; JavaScript has no processes to crash behind a test and no +// logger capture, so there is never anything to hand back +// (--show-crash-reports is warned about as ineffective). +export function all_diagnostics() { + return List$Empty(); +} + +export function unattributed_diagnostics() { return List$Empty(); } diff --git a/test/helpers.gleam b/test/helpers.gleam index ff48616..7e38ec4 100644 --- a/test/helpers.gleam +++ b/test/helpers.gleam @@ -82,10 +82,50 @@ pub fn crashes_linked_undef() -> Nil { sleep(1000) } +@target(erlang) +/// A fire-and-forget worker that panics: unlinked, unmonitored by the +/// caller, so nothing but the BEAM's crash report records the death. The +/// caller waits for the worker to be gone before returning, so the report +/// is always in flight by the time the test's result reaches the runner. +pub fn crashes_in_background() -> Nil { + run_in_background(fn() { panic as "crash in background process" }) +} + +@target(erlang) +/// The same, but the worker hits unimplemented code: the crash report +/// carries a todo, which must classify as a Todo outcome, not a failure. +pub fn todo_in_background() -> Nil { + run_in_background(unimplemented) +} + +@target(erlang) +/// The same, but a raw non-Gleam error: an undef with no Gleam payload. +pub fn undef_in_background() -> Nil { + run_in_background(calls_missing_function) +} + +@target(erlang) +/// A worker that dies only after the caller has returned: its crash report +/// can never be claimed by the test that started it. +pub fn crashes_after_returning() -> Nil { + spawn(fn() { + sleep(50) + panic as "late crash in background process" + }) +} + @target(erlang) @external(erlang, "timer", "sleep") fn sleep(ms: Int) -> Nil +@target(erlang) +@external(erlang, "vouch_helpers_ffi", "run_in_background") +fn run_in_background(f: fn() -> Nil) -> Nil + +@target(erlang) +@external(erlang, "erlang", "spawn") +fn spawn(f: fn() -> Nil) -> Nil + // The pid is discarded, so the dishonest Nil return type is harmless here. @target(erlang) @external(erlang, "erlang", "spawn_link") diff --git a/test/vouch_e2e_test.gleam b/test/vouch_e2e_test.gleam index 9c7308e..6194d28 100644 --- a/test/vouch_e2e_test.gleam +++ b/test/vouch_e2e_test.gleam @@ -18,10 +18,20 @@ pub fn playground_erlang_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"outcome\":\"todo\"") assert string.contains(out, "\"site_function\":\"rate_limit\"") + // background_job_test's worker crash is charged to the test and streamed + // as a failure with the cause nested. + assert string.contains( + out, + "\"function\":\"background_job_test\",\"outcome\":\"fail\"", + ) + assert string.contains( + out, + "\"kind\":\"background_crash\",\"cause\":{\"message\":\"background job crashed: queue is full\"", + ) // The undef crash carries its call site through the whole pipeline: // subprocess, stream, JSON encoding. assert string.contains(out, "\"kind\":\"unknown\"") @@ -51,6 +61,8 @@ pub fn playground_javascript_e2e_test() { "examples/playground", ) assert code == 1 + // One more pass than on Erlang: JavaScript has no process to crash + // behind background_job_test. assert string.contains( out, "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", @@ -72,7 +84,7 @@ pub fn playground_timeout_e2e_test() { assert string.contains(out, "\"timeout_ms\":100") assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":1,\"failed\":6,\"todo\":2,\"skipped\":1", ) } @@ -89,18 +101,24 @@ pub fn playground_parallel_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"site_function\":\"rate_limit\"") + // Attribution holds under --parallel too: the worker's crash is charged + // to background_job_test, not to whichever test happened to be in flight. + assert string.contains( + out, + "\"function\":\"background_job_test\",\"outcome\":\"fail\"", + ) } @target(erlang) -/// background_job_test passes while the unlinked worker it starts crashes. -/// The BEAM's crash report for that death must stay out of a default run -/// entirely, and come back — after the summary — with --show-crash-reports. -/// stderr is merged into the captured stream here because that is where -/// the reports go; the stdout-only harness above proves they never reach -/// stdout. +/// background_job_test's body passes while the unlinked worker it starts +/// crashes. The crash must fail the test, named in the console report; the +/// BEAM's raw crash report must stay out of a default run and come back — +/// after the summary — with --show-crash-reports. stderr is merged into the +/// captured stream here because that is where the raw reports go; the +/// stdout-only harness above proves they never reach stdout. pub fn playground_crash_reports_e2e_test() { let assert Ok(#(_, quiet)) = run_command_merged( @@ -108,9 +126,14 @@ pub fn playground_crash_reports_e2e_test() { ["test", "--", "--color=never"], "examples/playground", ) - assert string.contains(quiet, "ok playground_test.background_job_test") - assert !string.contains(quiet, "background job crashed") + assert string.contains(quiet, "FAIL playground_test.background_job_test") + assert string.contains( + quiet, + "Background process crashed at src/playground.gleam:", + ) + assert string.contains(quiet, "background job crashed: queue is full") assert !string.contains(quiet, "Error in process") + assert !string.contains(quiet, "not charged to any test") let assert Ok(#(_, shown)) = run_command_merged( @@ -122,10 +145,10 @@ pub fn playground_crash_reports_e2e_test() { shown, "vouch: 1 crash report captured during the run:", ) - assert string.contains(shown, "background job crashed: queue is full") - // After the summary, not interleaved with the results. + // The raw report, after the summary, not interleaved with the results. let assert Ok(#(_, after_summary)) = - string.split_once(shown, "3 passed, 4 failed, 2 todo, 1 skipped") + string.split_once(shown, "2 passed, 5 failed, 2 todo, 1 skipped") + assert string.contains(after_summary, "Error in process") assert string.contains(after_summary, "background job crashed: queue is full") } diff --git a/test/vouch_helpers_ffi.erl b/test/vouch_helpers_ffi.erl new file mode 100644 index 0000000..b6c6372 --- /dev/null +++ b/test/vouch_helpers_ffi.erl @@ -0,0 +1,14 @@ +%% Test-only helper for the background-crash fixtures in helpers.gleam. +-module(vouch_helpers_ffi). +-export([run_in_background/1]). + +%% Run F in an unlinked process and wait until that process is gone. The +%% caller is not linked, so the crash does not reach it; the monitor only +%% sequences the death before the return. The BEAM logs a crash report +%% before the monitor fires, so by the time this returns the report is on +%% its way to the capture handler. +run_in_background(F) -> + {_Pid, Ref} = spawn_monitor(fun() -> F() end), + receive + {'DOWN', Ref, process, _, _} -> nil + end. diff --git a/test/vouch_test.gleam b/test/vouch_test.gleam index ace7629..dd35b0a 100644 --- a/test/vouch_test.gleam +++ b/test/vouch_test.gleam @@ -127,27 +127,112 @@ pub fn timeout_classifies_as_failure_test() { @target(erlang) pub fn hanging_test_times_out_test() { - let invocation = runner.run_in_process("helpers", "sleeps_forever", 100) + let #(invocation, reports) = + runner.run_in_process("helpers", "sleeps_forever", 100) assert invocation == outcome.TimedOut(100) + // Killed, not crashed: the BEAM logs nothing for a kill. + assert reports == [] } @target(erlang) pub fn linked_crash_is_contained_test() { - let invocation = runner.run_in_process("helpers", "crashes_linked", 5000) + let #(invocation, reports) = + runner.run_in_process("helpers", "crashes_linked", 5000) let assert outcome.Failed(outcome.PanicDetail(p)) = outcome.classify("vouch_test", "linked_crash_is_contained_test", invocation) assert p.message == "crash in linked process" // The linked process's death also reaches the emulator, which logs an - // "Error in process" report asynchronously. It must land in the capture - // buffer, never on stderr. - let assert [report, ..] = await_diagnostics("crash in linked process", 40) + // "Error in process" report. It is captured and charged to the test that + // ran the process (never printed), and the test's own failure wins. + let assert [outcome.CrashReport(text:, ..)] = reports + assert string.contains(text, "Error in process") + assert string.contains(text, "crash in linked process") + assert outcome.with_crash_reports( + outcome.classify( + "vouch_test", + "linked_crash_is_contained_test", + invocation, + ), + "vouch_test", + "linked_crash_is_contained_test", + reports, + ) + == outcome.Failed(outcome.PanicDetail(p)) +} + +// --- Background crashes (Erlang target only) --- +// +// A process the test started dies without taking the test down: nothing is +// linked to or monitoring it, so the test body passes. The BEAM's crash +// report is the only trace. It is charged to the test and folded into its +// outcome, so the crash cannot hide behind a pass. + +@target(erlang) +pub fn background_crash_fails_passing_test_test() { + let #(invocation, reports) = + runner.run_in_process("helpers", "crashes_in_background", 5000) + assert invocation == outcome.Passed + let out = + outcome.classify("vouch_test", "background_crash_test", invocation) + |> outcome.with_crash_reports( + "vouch_test", + "background_crash_test", + reports, + ) + let assert outcome.Failed(outcome.BackgroundCrashDetail(outcome.PanicDetail(p))) = + out + assert p.message == "crash in background process" + assert p.module == "helpers" + assert p.function == "crashes_in_background" +} + +@target(erlang) +/// Unimplemented code in a background process is a Todo, by the same rule +/// as a todo the test reached directly. +pub fn background_todo_is_todo_outcome_test() { + let #(invocation, reports) = + runner.run_in_process("helpers", "todo_in_background", 5000) + assert invocation == outcome.Passed + let assert outcome.Todo(p) = + outcome.classify("vouch_test", "background_todo_test", invocation) + |> outcome.with_crash_reports("vouch_test", "background_todo_test", reports) + assert p.module == "helpers" + assert p.function == "unimplemented" +} + +@target(erlang) +/// A background crash with no Gleam payload still names what was called. +pub fn background_undef_names_call_site_test() { + let #(_, reports) = + runner.run_in_process("helpers", "undef_in_background", 5000) + let assert outcome.Failed(outcome.BackgroundCrashDetail(outcome.UnknownDetail( + reason, + Some(site), + ))) = outcome.with_crash_reports(outcome.Pass, "vouch_test", "t", reports) + assert string.inspect(reason) == "Undef" + assert site.module == "vouch_no_such_module" + assert site.function == "boom" +} + +@target(erlang) +/// A worker that outlives its test: the report arrives after the test's +/// result and cannot be charged to it. The runner's end-of-run sweep picks +/// it up instead, naming the test from the group leader it inherited. +/// Consumed here so the sweep in this very run stays clean. +pub fn late_background_crash_is_unattributed_test() { + let #(invocation, reports) = + runner.run_in_process("helpers", "crashes_after_returning", 5000) + assert invocation == outcome.Passed + assert reports == [] + let assert [report] = + await_diagnostics("late crash in background process", 40) assert string.contains(report, "Error in process") } @target(erlang) -/// Captured diagnostics matching `marker`, polling while an emulator -/// report may still be in flight. Taking only the matching reports leaves -/// any other test's diagnostics alone, so this cannot race a parallel run. +/// Captured reports matching `marker`, polling while an emulator report may +/// still be in flight. Taking only the matching reports leaves any other +/// test's reports alone, so this cannot race a parallel run. fn await_diagnostics(marker: String, retries: Int) -> List(String) { case runner.take_diagnostics_matching(marker) { [] if retries > 0 -> { @@ -177,8 +262,10 @@ pub fn otp_wrapped_todo_is_todo_outcome_test() { assert p.module == "helpers" assert p.function == "unimplemented" // gen_server logs its terminating report (and proc_lib its crash report) - // on the way down; both must be captured, never printed. - let reports = await_diagnostics("vouch_otp_fixture", 40) + // on the way down, synchronously, before the call returns. Both are + // captured, never printed — and consumed here, because the server ran in + // this test's own process tree and would otherwise be charged to it. + let reports = runner.take_diagnostics_matching("vouch_otp_fixture") assert reports != [] } @@ -191,8 +278,9 @@ pub fn isolated_pass_and_panic_test() { // failing_result returns an Error value, which is still a *passing* test — // only panics fail. assert runner.run_in_process("helpers", "failing_result", 5000) - == outcome.Passed - let assert outcome.Panicked(raw) = + == #(outcome.Passed, []) + // A panic caught inside the test process is not a crash: no report. + let assert #(outcome.Panicked(raw), []) = runner.run_in_process("helpers", "panics", 5000) let assert Ok(p) = gleam_panic.from_dynamic(raw) assert p.message == "helper panicked" @@ -207,8 +295,8 @@ pub fn parallel_tests_overlap_test() { let t0 = monotonic_microseconds() let a = runner.start_test("helpers", "sleeps_briefly", 5000) let b = runner.start_test("helpers", "sleeps_briefly", 5000) - let #(invocation_a, duration_a) = runner.await_test(a) - let #(invocation_b, duration_b) = runner.await_test(b) + let assert #(invocation_a, [], duration_a) = runner.await_test(a) + let assert #(invocation_b, [], duration_b) = runner.await_test(b) let elapsed_ms = { monotonic_microseconds() - t0 } / 1000 assert invocation_a == outcome.Passed assert invocation_b == outcome.Passed @@ -222,7 +310,7 @@ pub fn parallel_tests_overlap_test() { /// that outlives its timeout comes back TimedOut from await. pub fn parallel_test_times_out_test() { let handle = runner.start_test("helpers", "sleeps_forever", 100) - let #(invocation, _) = runner.await_test(handle) + let #(invocation, _, _) = runner.await_test(handle) assert invocation == outcome.TimedOut(100) } @@ -265,7 +353,7 @@ pub fn undef_crash_carries_call_site_test() { /// the exit reason still carries the stacktrace, so the death report names /// the call site rather than dumping raw frames. pub fn linked_undef_crash_names_call_site_test() { - let invocation = + let #(invocation, reports) = runner.run_in_process("helpers", "crashes_linked_undef", 5000) let assert outcome.Failed(outcome.ExitDetail(reason, Some(site))) = outcome.classify( @@ -277,9 +365,10 @@ pub fn linked_undef_crash_names_call_site_test() { assert site.module == "vouch_no_such_module" assert site.function == "boom" assert site.arity == 0 - // The linked process's undef also produces an emulator report; assert it - // was captured rather than printed. - let assert [_, ..] = await_diagnostics("vouch_no_such_module", 40) + // The linked process's undef also produces an emulator report, captured + // and charged to the test rather than printed. + let assert [outcome.CrashReport(text:, ..)] = reports + assert string.contains(text, "vouch_no_such_module") } @target(erlang) @@ -996,3 +1085,88 @@ pub fn junit_crash_site_test() { let xml = junit.render(results, 0) assert string.contains(xml, "calling filepath:split/1") } + +// --- Background crashes: outcome folding and rendering --- + +fn background_panic() -> gleam_panic.GleamPanic { + gleam_panic.GleamPanic( + message: "queue is full", + file: "src/jobs.gleam", + module: "jobs", + function: "run", + line: 25, + kind: gleam_panic.Panic, + ) +} + +/// The more severe verdict wins, the test's own on a tie: a report never +/// downgrades a failure, and a passing test takes the report's verdict. +pub fn with_crash_reports_severity_test() { + let raw = outcome.CrashReport(reason: dynamic.string("boom"), text: "t") + let own = outcome.Failed(outcome.TimeoutDetail(100)) + assert outcome.with_crash_reports(own, "m", "t", [raw]) == own + assert outcome.with_crash_reports(outcome.Pass, "m", "t", []) == outcome.Pass + assert outcome.with_crash_reports(outcome.Pass, "m", "t", [raw]) + == outcome.Failed( + outcome.BackgroundCrashDetail(outcome.UnknownDetail( + dynamic.string("boom"), + None, + )), + ) +} + +pub fn describe_background_panic_test() { + assert describe.failure( + outcome.BackgroundCrashDetail(outcome.PanicDetail(background_panic())), + ) + == ["Background process crashed at src/jobs.gleam:25", " queue is full"] +} + +pub fn describe_background_raw_crash_test() { + let site = + outcome.CrashSite( + module: "filepath", + function: "split", + arity: 1, + location: Some(#("src/filepath.erl", 145)), + ) + assert describe.failure( + outcome.BackgroundCrashDetail(outcome.UnknownDetail( + dynamic.string("boom"), + Some(site), + )), + ) + == [ + "Background process crashed: \"boom\" calling filepath:split/1", + " at src/filepath.erl:145", + ] +} + +/// The cause is nested under its own key, encoded exactly as the same +/// crash would be for the test itself. +pub fn jsonl_background_crash_test() { + let out = + outcome.Failed( + outcome.BackgroundCrashDetail(outcome.PanicDetail(background_panic())), + ) + assert jsonl.event_to_json(event.TestResult("m", "f", out, 10)) + == "{\"event\":\"test_result\",\"module\":\"m\",\"function\":\"f\"," + <> "\"outcome\":\"fail\",\"duration_us\":10,\"kind\":\"background_crash\"," + <> "\"cause\":{\"message\":\"queue is full\",\"file\":\"src/jobs.gleam\"," + <> "\"line\":25,\"kind\":\"panic\"}}" +} + +pub fn teamcity_and_junit_background_crash_test() { + let out = + outcome.Failed( + outcome.BackgroundCrashDetail(outcome.PanicDetail(background_panic())), + ) + let #(_, lines) = + teamcity.step(None, event.TestResult("m_test", "x_test", out, 0)) + let tc = string.join(lines, "\n") + assert string.contains(tc, "a process the test started crashed") + assert string.contains(tc, "Background process crashed at src/jobs.gleam:25") + let xml = junit.render([#("m_test", "x_test", out, 0)], 0) + assert string.contains(xml, "type=\"background_crash\"") + assert string.contains(xml, "Background process crashed at src/jobs.gleam:25") +} From 584957d221a9abd094c07d494e0f221512257234 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Sat, 22 Aug 2026 00:02:03 +0100 Subject: [PATCH 4/8] Attribute background crashes by tracing, not the logger The previous commit charged a background process's death to its test by capturing the BEAM's crash report and matching the dying process's group leader. That report is asynchronous: measured against the monitor DOWN a test observes, it is only ~81% enqueued in time even after flushing logger_proxy, so a real crash could still slip through as a pass - the very bug this is meant to close. Pass/fail now comes from tracing instead. run_test traces each test's process with erlang:trace(procs, set_on_spawn), so every process it starts, transitively, reports its exit to a per-test collector. A trace exit is delivered before the test can send its result, and trace_delivered/1 flushes any still in transit before the collector is read, so attribution is exact and never a race - under --parallel as much as sequentially. The collector keeps tracing after the test is claimed, so a worker that outlives its test and crashes later is recorded as unattributed and fails the run. Nested runs (vouch's own suite runs tests that run tests) clear the trace inherited from the outer test before setting their own, since a process may have one tracer. The logger capture is kept, demoted to display only: it holds the raw BEAM reports off the output streams and hands them to --show-crash-reports, and no longer drives any outcome. CrashReport carries just the exit reason now; the report text is gone from the outcome path. Cost is ~100us per test (trace setup plus the trace_delivered barrier), doubling a 2000-empty-test run from 86ms to ~200ms - negligible for a real suite and still far faster than gleeunit, and the deterministic guarantee is worth it for a test runner. Co-Authored-By: Claude Opus 4.8 --- CHANGELOG.md | 28 +-- README.md | 16 +- docs/chapters/architecture.typ | 6 +- docs/chapters/execution.typ | 39 ++-- src/vouch/internal/outcome.gleam | 10 +- src/vouch/internal/runner.gleam | 8 + src/vouch_ffi.erl | 300 ++++++++++++++++--------------- src/vouch_ffi.mjs | 4 + test/helpers.gleam | 9 +- test/vouch_test.gleam | 67 +++---- 10 files changed, 261 insertions(+), 226 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8d546ab..ea5a94f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,26 +20,26 @@ extract. A process that crashes behind a test now fails it. On the Erlang target, an unlinked worker, a fire-and-forget job, an actor nothing is monitoring — anything a test starts that dies without taking the test down — used to -leave the test passing and the run green, with the BEAM's crash report on -stderr as the only trace. vouch now captures those crash reports and -charges each to the test whose process died (every process a test starts -inherits the test's group leader, which the report records, so attribution -is exact under `--parallel` too). The test fails: +leave the test passing and the run green (as it still does under gleeunit), +with the BEAM's crash report on stderr as the only trace. vouch now traces +each test's process tree, so a process it started that crashes is caught +and charged to that exact test — in a `--parallel` run as much as a +sequential one. The test fails: playground_test.background_job_test Background process crashed at src/playground.gleam:26 background job crashed: queue is full or is a todo, when the process died of a `todo`. A test that failed on its -own keeps its own failure. A report that arrives after its test finished, -or from a process no test started, is printed at the end and fails the -run. The JSONL stream carries it as `"kind":"background_crash"` with the -cause nested under `cause`; JUnit and TeamCity get a `background_crash` -failure with the same text. Other logger output (a library's warnings) is -not a crash and still goes to stderr. A new `--show-crash-reports` flag -additionally prints the full BEAM reports as one block on stderr after the -summary. JavaScript is unaffected: there are no processes to crash behind -a test there. +own keeps its own failure. A crash from a process that outlived its test, +or that no test started, is reported at the end and fails the run. The +JSONL stream carries it as `"kind":"background_crash"` with the cause +nested under `cause`; JUnit and TeamCity get a `background_crash` failure +with the same text. The BEAM's own crash reports are kept off the output +streams; the new `--show-crash-reports` flag prints them in full as one +block on stderr after the summary. Other logger output (a library's +warnings) is not a crash and still goes to stderr. JavaScript is +unaffected: there are no processes to crash behind a test there. ## v1.2.0 diff --git a/README.md b/README.md index 9995867..e1b6bd0 100644 --- a/README.md +++ b/README.md @@ -93,9 +93,9 @@ On Deno, watch mode also needs `allow_run = ["gleam"]` to spawn the inner runs ( On the Erlang target, a process that dies *with* a test (a linked process crashing, an actor the test is calling hitting a `todo`) is reported through the test's own outcome. A process that dies *behind* a test — an unlinked worker, a fire-and-forget job nothing is monitoring — -would leave the test passing, with the BEAM's crash report as the only trace. vouch captures -those reports and charges each to the test whose process died (every process a test starts -inherits its group leader, which the report records), so the test fails: +would leave the test passing (this is what gleeunit does), with the BEAM's crash report as the +only trace. vouch traces each test's process tree, so a process it started that crashes is +caught and charged to that test, and the test fails: ``` playground_test.background_job_test @@ -103,11 +103,11 @@ inherits its group leader, which the report records), so the test fails: background job crashed: queue is full ``` -If the process died of a `todo`, the test is a todo instead. A report that arrives after its -test has finished, or from a process no test started, is printed on stderr at the end and fails -the run. Other logger output (a library's warnings) is not a crash; it goes to stderr as -before. Pass `--show-crash-reports` to also get the full BEAM reports, printed as one block on -stderr after the summary. +If the process died of a `todo`, the test is a todo instead. A crash from a process that +outlived its test, or that no test started, is reported at the end and fails the run. The +BEAM's own crash reports are kept off the output streams (they used to interleave with it on +stderr); pass `--show-crash-reports` to print them in full as one block after the summary. +Other logger output (a library's warnings) is not a crash and still goes to stderr. ## Target differences diff --git a/docs/chapters/architecture.typ b/docs/chapters/architecture.typ index f91cc9d..d825e55 100644 --- a/docs/chapters/architecture.typ +++ b/docs/chapters/architecture.typ @@ -63,9 +63,9 @@ The FFI contract, in full: [Terminal facts (TTY, env vars)], [`io:columns/0`, `os:getenv/1`], [`isTTY` / `Deno.stdout.isTerminal`, env lookup], - [Route BEAM diagnostics to stderr], - [re-add the default logger handler], - [not needed], + [Catch a crash behind a test / keep BEAM reports off the streams], + [`erlang:trace` a per-test process tree; capture logger handler], + [not needed (no processes)], [Halt with exit code], [`erlang:halt/1`], [`process.exit` / `Deno.exit`], diff --git a/docs/chapters/execution.typ b/docs/chapters/execution.typ index 66c06eb..e953e0d 100644 --- a/docs/chapters/execution.typ +++ b/docs/chapters/execution.typ @@ -23,19 +23,32 @@ fidelity for ordinary failures. The runner waits on three possibilities: killed and reported as a timeout failure. A hung test costs its timeout, not the whole run. -BEAM crash reports (a process the test started dying: the emulator's "Error -in process", proc_lib crash reports, gen_\* terminate and supervisor child -reports) are diverted at run start from the default logger handler into an -ETS table, by a capture handler whose filter admits only crash-shaped events. -Each test process runs under its own group leader — a proxy forwarding io to -the real one — which every process it starts inherits and every crash report -records, so after each test the runner claims the reports charged to it and -folds them into the outcome: a passing test whose worker crashed fails -(`BackgroundCrashDetail`), or is a todo if the worker died of a `todo`. -Reports nobody claimed (arrived after their test finished, or from outside -any test) are printed at the end and fail the run. The default handler is -re-added with `type: standard_error` for everything else routed through -logger, so it stays visible but can never corrupt piped stdout. +A process that dies *behind* a test — an unlinked worker, a fire-and-forget +job nothing is linked to or monitoring — would leave the test passing, its +death known only to the BEAM's crash report. vouch traces each test's +process tree: `erlang:trace(TestPid, true, [procs, set_on_spawn, {tracer, +Collector}])` gives every process the test starts, transitively, a per-test +collector that receives a trace message for each abnormal exit. This is the +pass/fail signal, and it is race-free where the crash report is not: a trace +exit is delivered before the test can report its result, and +`erlang:trace_delivered/1` flushes any still in transit before the collector +is read. After each test the runner folds the collected crash reasons into +the outcome — a passing test whose worker crashed fails +(`BackgroundCrashDetail`), or is a todo if the worker died of a `todo`, the +test's own failure winning a tie. A crash a collector sees after its test +was claimed (a worker outliving its test) is recorded as unattributed; +those are reported at the end and fail the run. Nesting — vouch's own suite +runs tests that run tests — is handled by clearing the inherited trace +before setting each test's own, since a process may have only one tracer. + +The BEAM's own crash reports (the emulator's "Error in process", proc_lib +crash reports, gen_\* terminate and supervisor child reports) are separately +diverted from the default logger handler into an ETS table by a capture +handler whose filter admits only crash-shaped events, purely to keep them +off the output streams and hand their raw text to `--show-crash-reports`; +they no longer drive any outcome. The default handler is re-added with +`type: standard_error` for everything else routed through logger, so it +stays visible but can never corrupt piped stdout. (`logger:update_handler_config` silently ignores a runtime type change; remove-and-re-add is required.) diff --git a/src/vouch/internal/outcome.gleam b/src/vouch/internal/outcome.gleam index ea27741..1c2dc25 100644 --- a/src/vouch/internal/outcome.gleam +++ b/src/vouch/internal/outcome.gleam @@ -50,12 +50,12 @@ pub type FailureDetail { BackgroundCrashDetail(cause: FailureDetail) } -/// The BEAM's report of a process dying while a test ran, as captured by -/// the runner's logger handler: the exit reason the report carried (a -/// Gleam panic map for a panic, assert or todo; a raw term otherwise) and -/// the report text as the default handler would have printed it. +/// A process that crashed while a test ran, as seen by the runner's tracer: +/// the exit reason of the dead process (a Gleam panic map for a panic, +/// assert or todo; a raw `{Reason, Stacktrace}` otherwise), which decodes +/// exactly like a caught panic. pub type CrashReport { - CrashReport(reason: Dynamic, text: String) + CrashReport(reason: Dynamic) } /// The top frame of the stacktrace behind a non-Gleam crash: what was being diff --git a/src/vouch/internal/runner.gleam b/src/vouch/internal/runner.gleam index 314438f..2d33d8d 100644 --- a/src/vouch/internal/runner.gleam +++ b/src/vouch/internal/runner.gleam @@ -350,6 +350,14 @@ fn unattributed_crash_reports() -> List(#(String, Option(#(String, String)))) @external(javascript, "../../vouch_ffi.mjs", "take_diagnostics_matching") pub fn take_diagnostics_matching(marker: String) -> List(String) +/// Remove and return the rendered reasons of unattributed crashes (a worker +/// that outlived its test) whose text contains `marker`. Public so vouch's +/// own suite can prove the late-crash path reaches the unattributed table, +/// consuming its deliberately-caused entry so the suite run stays green. +@external(erlang, "vouch_ffi", "take_unattributed_matching") +@external(javascript, "../../vouch_ffi.mjs", "take_unattributed_matching") +pub fn take_unattributed_matching(marker: String) -> List(String) + fn path_to_module(path: String) -> String { path |> string.replace("\\", "/") diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index 3d831de..19c4f9e 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -13,9 +13,10 @@ all_diagnostics/0, unattributed_diagnostics/0, take_diagnostics_matching/1, + take_unattributed_matching/1, crash_filter/2, log/2, - forward_io/1, + collect_crashes/3, write_file/2, read_source/3, halt/1, @@ -78,24 +79,22 @@ env(Name) -> Value -> {ok, unicode:characters_to_binary(Value)} end. -%% BEAM crash reports — a process dying with an uncaught error (the -%% emulator's "Error in process"), a proc_lib CRASH REPORT, a gen_* -%% "terminating" report, a supervisor's child-died report — are diverted -%% away from the default logger handler into a public ETS table. The runner -%% reads that table after each test and charges each report to the test -%% whose process died (see the per-test group leaders in run_test/3), so a -%% worker that crashes behind an otherwise passing test still turns the -%% test red; the raw report text is printed only on request -%% (--show-crash-reports). Everything else routed through logger (a -%% library's warnings, a test's own log lines) is not a crash and still -%% prints, via the default handler moved to stderr so it cannot corrupt a -%% machine-read stdout stream. +%% Pass/fail for a process that dies behind a test is driven by tracing (see +%% run_test/3), not by these logger reports. The logger capture exists only +%% to keep BEAM crash reports (the emulator's "Error in process", proc_lib +%% CRASH REPORTs, gen_* terminate and supervisor child reports) off the +%% output streams and hand them to --show-crash-reports: a report is a raw +%% render of a death the trace already accounted for, wanted in full only on +%% request. Everything else routed through logger (a library's warnings, a +%% test's own log lines) is not a crash and still prints, via the default +%% handler moved to stderr so it cannot corrupt a machine-read stdout stream. %% %% This module doubles as the capture handler: crash_filter/2 selects the %% events and log/2 stores each one rendered with the default handler's own %% formatter. If the capture handler cannot be installed, reports stay on %% stderr — still better than corrupting stdout. capture_diagnostics() -> + ensure_diagnostics_tables(), catch case logger:get_handler_config(vouch_diagnostics) of {ok, _} -> %% Already capturing; installing twice would double reports. @@ -103,7 +102,6 @@ capture_diagnostics() -> _ -> case logger:get_handler_config(default) of {ok, #{formatter := Formatter}} -> - ensure_diagnostics_table(), Capture = logger:add_handler(vouch_diagnostics, ?MODULE, #{ formatter => Formatter, filter_default => stop, @@ -129,15 +127,17 @@ capture_diagnostics() -> end, nil. -%% Rows are {Key, GroupLeader, Text, Reason, Claimed} for captured reports -%% (Key from unique_integer([monotonic]), so arrival order is table order) -%% and {{test, GroupLeader}, Module, Function} naming the test each -%% per-test group leader belongs to. -ensure_diagnostics_table() -> - case ets:whereis(vouch_diagnostics) of +%% vouch_crash_texts: {Key, Text} rendered reports, Key from +%% unique_integer([monotonic]) so arrival order is table order — the raw +%% text for --show-crash-reports. vouch_unattributed: {Key, Reason, +%% TestName} for crashes a collector saw after its test was already claimed +%% (a worker outliving its test) or that no test's tree produced — these +%% fail the run. Both owned by the runner process, which lives until halt. +ensure_diagnostics_tables() -> + case ets:whereis(vouch_crash_texts) of undefined -> - %% Owned by the runner process, which lives until halt. - ets:new(vouch_diagnostics, [named_table, public, ordered_set]); + ets:new(vouch_crash_texts, [named_table, public, ordered_set]), + ets:new(vouch_unattributed, [named_table, public, ordered_set]); _ -> ok end. @@ -169,18 +169,12 @@ is_crash_report(#{level := error, msg := {report, #{label := {supervisor, _}}}}) is_crash_report(_) -> false. -%% Logger handler callback, installed by capture_diagnostics/0. Runs in the -%% logging process for logger API calls and in the logger server for -%% emulator-generated reports; either way, render now and append. Must +%% Logger handler callback, installed by capture_diagnostics/0. Renders the +%% event with the default handler's formatter and stores the text. Must %% never raise: logger removes a handler whose callback crashes. -log(#{meta := Meta} = Event, Config) -> - catch ets:insert(vouch_diagnostics, { - erlang:unique_integer([monotonic]), - maps:get(gl, Meta, undefined), - render_diagnostic(Event, Config), - report_reason(Event), - false - }), +log(Event, Config) -> + catch ets:insert(vouch_crash_texts, + {erlang:unique_integer([monotonic]), render_diagnostic(Event, Config)}), ok. render_diagnostic(Event, Config) -> @@ -194,86 +188,71 @@ render_diagnostic(Event, Config) -> unicode:characters_to_binary(io_lib:format("~0tp~n", [Event])) end. -%% The exit reason a crash report carries, in the {Reason, Stacktrace} shape -%% catch_panic produces, so the Gleam side decodes a report exactly like a -%% caught panic: find_panic reaches a gleam_error map inside it and -%% split_crash names the top frame of anything else. Unknown report shapes -%% pass the whole message through. -report_reason(#{msg := {_Format, Args}, meta := #{error_logger := #{emulator := true}}}) - when is_list(Args), Args =/= [] -> - %% "Error in process ~p [on node ~p] with exit value:~n~p~n": the exit - %% value is the last argument, already {Reason, Stacktrace}. - lists:last(Args); -report_reason(#{msg := {report, #{label := {proc_lib, crash}, report := [Info | _]}}}) - when is_list(Info) -> - case lists:keyfind(error_info, 1, Info) of - {error_info, {error, Reason, Stack}} -> {Reason, Stack}; - {error_info, {Class, Reason, Stack}} -> {{Class, Reason}, Stack}; - _ -> Info - end; -report_reason(#{msg := {report, #{label := {_, terminate}, reason := Reason}}}) -> - Reason; -report_reason(#{msg := {report, #{label := {supervisor, _}, report := Report}}}) - when is_list(Report) -> - case lists:keyfind(reason, 1, Report) of - {reason, Reason} -> Reason; - false -> Report - end; -report_reason(#{msg := Msg}) -> - Msg. - %% Every captured report's text, in arrival order, for --show-crash-reports. +%% Read once at the end of the run, by when every report has arrived. all_diagnostics() -> flush_logger(), - [Text || {Key, _GL, Text, _Reason, _Claimed} <- rows(), is_integer(Key)]. + [Text || {_Key, Text} <- table(vouch_crash_texts)]. -%% The reports no test claimed — arrived after their test had finished, or -%% from a process no test started — each with the test its group leader -%% belonged to, when there was one. The run fails on these: a crash the -%% outcomes do not account for must not hide behind a green summary. +%% The crashes no test claimed — a process that died after its test had +%% finished (named here, from its collector), or in no test's tree at all — +%% each as {ReasonText, TestName}. Trace-driven, so these are exact; the run +%% fails on them, because a crash no outcome accounts for must not hide +%% behind a green summary. unattributed_diagnostics() -> - flush_logger(), - [{Text, test_of(GL)} - || {Key, GL, Text, _Reason, false} <- rows(), is_integer(Key)]. + [{reason_text(Reason), TestName} + || {_Key, Reason, TestName} <- table(vouch_unattributed)]. -test_of(GL) -> - case catch ets:lookup(vouch_diagnostics, {test, GL}) of - [{_, Module, Function}] -> {some, {Module, Function}}; - _ -> none - end. +reason_text(Reason) -> + unicode:characters_to_binary(io_lib:format("~0tp", [Reason])). -%% Remove and return only the captured reports whose text contains Marker, -%% leaving the rest alone. The suite-facing probe: a test that deliberately -%% crashes a process in its own process tree can consume the report (so it -%% is not charged to the test) and assert it was captured rather than -%% printed, without touching reports that belong to other tests. +%% Remove and return the captured report texts containing Marker, leaving +%% the rest alone. The suite-facing probe: a test that crashes a process on +%% purpose can assert its report reached the capture table rather than +%% stderr, without disturbing other tests' reports. take_diagnostics_matching(Marker) -> flush_logger(), [begin - catch ets:delete(vouch_diagnostics, Key), + catch ets:delete(vouch_crash_texts, Key), Text end - || {Key, _GL, Text, _Reason, _Claimed} <- rows(), - is_integer(Key), binary:match(Text, Marker) =/= nomatch]. + || {Key, Text} <- table(vouch_crash_texts), + binary:match(Text, Marker) =/= nomatch]. + +%% Remove and return the rendered reasons of unattributed crashes containing +%% Marker. The suite-facing probe for the late-crash path: a test whose +%% worker outlives it can poll for its own late crash and consume it, so the +%% suite run does not fail on the unattributed entry it deliberately caused. +take_unattributed_matching(Marker) -> + [begin + catch ets:delete(vouch_unattributed, Key), + Text + end + || {Key, Reason, _TestName} <- table(vouch_unattributed), + Text <- [reason_text(Reason)], + binary:match(Text, Marker) =/= nomatch]. -rows() -> - case catch ets:tab2list(vouch_diagnostics) of +table(Name) -> + case catch ets:tab2list(Name) of Rows when is_list(Rows) -> Rows; _ -> [] end. -%% Emulator-generated reports ("Error in process") are handled in the -%% logger_proxy process, whose mailbox they travel through; API-call events -%% (proc_lib, gen_server) are handled in the logging process itself, before -%% the crash propagates. A synchronous round-trip through logger_proxy makes -%% sure everything already sent is in the table before it is read. The -%% emulator sends the report before the dying process's exit signals and -%% monitors fire, so a death the test observed is always in the table by -%% the time the test's result reaches the runner. The logger server itself -%% is round-tripped too, cheaply, in case an OTP release routes through it. +%% Emulator-generated reports ("Error in process") reach the capture handler +%% through the logger_proxy process's mailbox; API-call events (proc_lib, +%% gen_server) are handled inline. A synchronous round-trip through each +%% makes sure everything already sent is stored before the table is read. +%% This is off the per-test hot path — the reports are display-only, read +%% once at the end and by the suite's own probes. flush_logger() -> - catch sys:get_state(logger_proxy, 1000), - catch sys:get_state(logger, 1000). + flush(logger_proxy), + flush(logger). + +flush(Name) -> + case whereis(Name) of + undefined -> ok; + Pid -> catch sys:get_state(Pid, 1000) + end. %% Route the default handler to stderr, so whatever it still prints (and %% everything, if the capture handler could not be installed) stays off the @@ -322,25 +301,38 @@ exported_zero_arity(ModuleName) -> %% depends on exit-reason fidelity; the DOWN branch only fires when the %% process died without reporting (exit signal, linked crash), and a test %% that outlives the timeout is killed. Returns {Invocation, CrashReports}: -%% a constructor of vouch/internal/outcome.Invocation, and the crash reports -%% of processes the test started that died while it ran (outcome.CrashReport +%% a constructor of vouch/internal/outcome.Invocation, and the reasons of +%% processes the test started that crashed while it ran (outcome.CrashReport %% tuples), which the runner folds into the test's outcome. %% -%% The test process runs under its own group leader, a proxy that forwards -%% io to the real one (start_group_leader/2). Every process the test starts -%% inherits it, and every crash report the BEAM logs names the dying -%% process's group leader, so a report is charged to exactly the test whose -%% process died — in a parallel run as much as a sequential one — and a -%% report that arrives late can still say which test it belonged to. +%% A collector process traces the test process with `set_on_spawn`, so every +%% process the test starts — directly or transitively — is traced too, and +%% the collector receives a trace message for each abnormal exit. This is +%% the pass/fail signal: exact, and never a race, because a trace exit is +%% delivered before any result the test can send (unlike the BEAM's +%% asynchronous crash report). After the result, trace_delivered/1 flushes +%% any trace messages still in transit, then the collector is claimed. It +%% keeps tracing afterwards: a worker that outlives its test and crashes +%% later is recorded as unattributed (the runner fails the run on those). run_test(ModuleName, FunctionName, TimeoutMs) -> Module = binary_to_atom(beam_name(ModuleName), utf8), Function = binary_to_atom(FunctionName, utf8), Self = self(), - Leader = start_group_leader(ModuleName, FunctionName), + %% Spawned suspended on a `go` message so tracing is in place before the + %% test can start any worker. {Pid, Ref} = spawn_monitor(fun() -> - group_leader(Leader, self()), + receive go -> ok end, Self ! {vouch_result, self(), catch_panic(fun() -> Module:Function() end)} end), + Collector = spawn(?MODULE, collect_crashes, + [Pid, {ModuleName, FunctionName}, []]), + %% Drop any trace inherited from a traced caller — vouch's own suite runs + %% tests that themselves run tests, and a process can have only one + %% tracer — before setting this test's own. A harmless no-op for a + %% top-level test, which inherits nothing. + catch erlang:trace(Pid, false, [procs, set_on_spawn]), + catch erlang:trace(Pid, true, [procs, set_on_spawn, {tracer, Collector}]), + Pid ! go, Invocation = receive {vouch_result, Pid, {ok, nil}} -> erlang:demonitor(Ref, [flush]), @@ -361,48 +353,74 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> end, {timed_out, TimeoutMs} end, - {Invocation, claim_crash_reports(Leader)}. - -%% A group leader for one test: forwards every message (io requests, whose -%% replies go straight back to the requester) to the real group leader, so -%% tests and their processes print exactly as before. It is never stopped: -%% a worker the test left running may still be printing through it after -%% the test is over, and an io request to a dead leader raises. Idle -%% leaders hibernate down to a few hundred bytes each. -start_group_leader(ModuleName, FunctionName) -> - Real = group_leader(), - Leader = spawn(?MODULE, forward_io, [Real]), - catch ets:insert(vouch_diagnostics, {{test, Leader}, ModuleName, FunctionName}), - Leader. - -forward_io(Real) -> + {Invocation, claim_crashes(Collector)}. + +%% Tracer for one test's process tree. Accumulates the exit reason of every +%% descendant that dies abnormally — anything but a clean exit (normal, +%% shutdown), and never the test process itself, whose death is the +%% invocation. On `claim` it hands back what it has and switches to +%% forwarding: any later crash (a worker that outlived the test) goes to the +%% unattributed table, tagged with this test, for the runner's end-of-run +%% failure. Idle between events, it hibernates to a few hundred bytes. +collect_crashes(TestPid, TestName, Acc) -> receive - Message -> - Real ! Message, - forward_io(Real) + {trace, TestPid, exit, _Reason} -> + collect_crashes(TestPid, TestName, Acc); + {trace, _Pid, exit, Reason} -> + case is_clean_exit(Reason) of + true -> collect_crashes(TestPid, TestName, Acc); + false -> collect_crashes(TestPid, TestName, [Reason | Acc]) + end; + {claim, From, Ref} -> + From ! {crashes, Ref, lists:reverse(Acc)}, + forward_crashes(TestPid, TestName); + _Other -> + collect_crashes(TestPid, TestName, Acc) after 200 -> - erlang:hibernate(?MODULE, forward_io, [Real]) + erlang:hibernate(?MODULE, collect_crashes, [TestPid, TestName, Acc]) end. -%% The captured crash reports of processes under Leader, oldest first, each -%% marked claimed so the end-of-run sweep for unattributed reports skips -%% it. Flushing first is what makes this deterministic for a death the test -%% observed (see flush_logger/0). -claim_crash_reports(Leader) -> - flush_logger(), - case catch ets:select(vouch_diagnostics, - [{{'$1', Leader, '$2', '$3', false}, - [{is_integer, '$1'}], - [{{'$1', '$2', '$3'}}]}]) of - Rows when is_list(Rows) -> - [begin - catch ets:update_element(vouch_diagnostics, Key, {5, true}), - {crash_report, Reason, Text} - end || {Key, Text, Reason} <- Rows]; - _ -> - [] +forward_crashes(TestPid, TestName) -> + receive + {trace, TestPid, exit, _Reason} -> + forward_crashes(TestPid, TestName); + {trace, _Pid, exit, Reason} -> + case is_clean_exit(Reason) of + true -> ok; + false -> + catch ets:insert(vouch_unattributed, + {erlang:unique_integer([monotonic]), Reason, + {some, TestName}}) + end, + forward_crashes(TestPid, TestName); + _Other -> + forward_crashes(TestPid, TestName) + after 200 -> + erlang:hibernate(?MODULE, forward_crashes, [TestPid, TestName]) end. +is_clean_exit(normal) -> true; +is_clean_exit(shutdown) -> true; +is_clean_exit({shutdown, _}) -> true; +is_clean_exit(_) -> false. + +%% Flush trace messages still in transit to their tracers (see run_test/3), +%% then take the collector's accumulated crash reasons. +claim_crashes(Collector) -> + Delivered = erlang:trace_delivered(all), + receive {trace_delivered, all, Delivered} -> ok end, + Ref = make_ref(), + Collector ! {claim, self(), Ref}, + Reasons = receive {crashes, Ref, Rs} -> Rs after 5000 -> [] end, + reasons_to_reports(Reasons). + +%% Each crash reason as an outcome.CrashReport, whose single field the +%% Gleam side decodes exactly like a caught panic — find_panic reaches a +%% gleam_error map inside a {Reason, Stacktrace} exit, split_crash names the +%% top frame of anything else. +reasons_to_reports(Reasons) -> + [{crash_report, Reason} || Reason <- Reasons]. + %% Parallel execution: start one test without blocking on it. The spawned %% middleman runs the same run_test/3 as the sequential path — identical diff --git a/src/vouch_ffi.mjs b/src/vouch_ffi.mjs index fcbaf46..149e64e 100644 --- a/src/vouch_ffi.mjs +++ b/src/vouch_ffi.mjs @@ -95,6 +95,10 @@ export function take_diagnostics_matching(_marker) { erlangOnly("take_diagnostics_matching"); } +export function take_unattributed_matching(_marker) { + erlangOnly("take_unattributed_matching"); +} + export function find_test_files() { erlangOnly("find_test_files"); } diff --git a/test/helpers.gleam b/test/helpers.gleam index 7e38ec4..dc9e7a1 100644 --- a/test/helpers.gleam +++ b/test/helpers.gleam @@ -105,11 +105,12 @@ pub fn undef_in_background() -> Nil { } @target(erlang) -/// A worker that dies only after the caller has returned: its crash report -/// can never be claimed by the test that started it. -pub fn crashes_after_returning() -> Nil { +/// A fire-and-forget worker that is still alive when the caller returns and +/// crashes shortly after: its death can never be charged to the test that +/// started it, so the runner's tracer records it as unattributed. +pub fn returns_before_worker_crashes() -> Nil { spawn(fn() { - sleep(50) + sleep(30) panic as "late crash in background process" }) } diff --git a/test/vouch_test.gleam b/test/vouch_test.gleam index dd35b0a..08edcce 100644 --- a/test/vouch_test.gleam +++ b/test/vouch_test.gleam @@ -141,12 +141,11 @@ pub fn linked_crash_is_contained_test() { let assert outcome.Failed(outcome.PanicDetail(p)) = outcome.classify("vouch_test", "linked_crash_is_contained_test", invocation) assert p.message == "crash in linked process" - // The linked process's death also reaches the emulator, which logs an - // "Error in process" report. It is captured and charged to the test that - // ran the process (never printed), and the test's own failure wins. - let assert [outcome.CrashReport(text:, ..)] = reports - assert string.contains(text, "Error in process") - assert string.contains(text, "crash in linked process") + // The linked process is a traced descendant, so its crash is also + // collected as a background report — but the test's own death (the same + // panic, propagated by the link) is the more specific outcome, so the + // fold keeps the PanicDetail rather than a BackgroundCrashDetail. + let assert [outcome.CrashReport(_)] = reports assert outcome.with_crash_reports( outcome.classify( "vouch_test", @@ -215,29 +214,29 @@ pub fn background_undef_names_call_site_test() { } @target(erlang) -/// A worker that outlives its test: the report arrives after the test's -/// result and cannot be charged to it. The runner's end-of-run sweep picks -/// it up instead, naming the test from the group leader it inherited. -/// Consumed here so the sweep in this very run stays clean. -pub fn late_background_crash_is_unattributed_test() { +/// A worker that outlives its test: still alive when the test's result is +/// claimed (so no report is charged to the test), then crashes. The runner's +/// tracer records the late death as unattributed, which fails the run. It is +/// consumed here — after polling for it to arrive — so this suite run does +/// not itself fail on it. +pub fn late_background_crash_becomes_unattributed_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "crashes_after_returning", 5000) + runner.run_in_process("helpers", "returns_before_worker_crashes", 5000) assert invocation == outcome.Passed assert reports == [] - let assert [report] = - await_diagnostics("late crash in background process", 40) - assert string.contains(report, "Error in process") + let assert [text] = await_unattributed("late crash in background process", 80) + assert string.contains(text, "late crash in background process") } @target(erlang) -/// Captured reports matching `marker`, polling while an emulator report may -/// still be in flight. Taking only the matching reports leaves any other -/// test's reports alone, so this cannot race a parallel run. -fn await_diagnostics(marker: String, retries: Int) -> List(String) { - case runner.take_diagnostics_matching(marker) { +/// The unattributed crash reports containing `marker`, consumed, polling +/// while the late crash may still be pending. Consuming only the matching +/// rows leaves any other test's unattributed reports alone. +fn await_unattributed(marker: String, retries: Int) -> List(String) { + case runner.take_unattributed_matching(marker) { [] if retries > 0 -> { sleep_ms(25) - await_diagnostics(marker, retries - 1) + await_unattributed(marker, retries - 1) } reports -> reports } @@ -250,9 +249,11 @@ fn sleep_ms(ms: Int) -> Nil @target(erlang) /// A todo inside an OTP process (here a real gen_server callback) reaches /// the caller wrapped in OTP exit structure. It must still classify as -/// Todo, not an opaque failure. +/// Todo, not an opaque failure. Run in its own process so the gen_server's +/// death is that inner run's business, not this test's. pub fn otp_wrapped_todo_is_todo_outcome_test() { - let invocation = outcome.from_caught(runner.catch_panic(call_into_todo)) + let #(invocation, _reports) = + runner.run_in_process("vouch_otp_fixture", "call_into_todo", 5000) let assert outcome.Todo(p) = outcome.classify( "vouch_test", @@ -261,18 +262,8 @@ pub fn otp_wrapped_todo_is_todo_outcome_test() { ) assert p.module == "helpers" assert p.function == "unimplemented" - // gen_server logs its terminating report (and proc_lib its crash report) - // on the way down, synchronously, before the call returns. Both are - // captured, never printed — and consumed here, because the server ran in - // this test's own process tree and would otherwise be charged to it. - let reports = runner.take_diagnostics_matching("vouch_otp_fixture") - assert reports != [] } -@target(erlang) -@external(erlang, "vouch_otp_fixture", "call_into_todo") -fn call_into_todo() -> Nil - @target(erlang) pub fn isolated_pass_and_panic_test() { // failing_result returns an Error value, which is still a *passing* test — @@ -365,10 +356,10 @@ pub fn linked_undef_crash_names_call_site_test() { assert site.module == "vouch_no_such_module" assert site.function == "boom" assert site.arity == 0 - // The linked process's undef also produces an emulator report, captured - // and charged to the test rather than printed. - let assert [outcome.CrashReport(text:, ..)] = reports - assert string.contains(text, "vouch_no_such_module") + // The linked process is a traced descendant, so its undef is also + // collected as a background report; the decode is covered by + // background_undef_names_call_site_test. + let assert [outcome.CrashReport(_)] = reports } @target(erlang) @@ -1102,7 +1093,7 @@ fn background_panic() -> gleam_panic.GleamPanic { /// The more severe verdict wins, the test's own on a tie: a report never /// downgrades a failure, and a passing test takes the report's verdict. pub fn with_crash_reports_severity_test() { - let raw = outcome.CrashReport(reason: dynamic.string("boom"), text: "t") + let raw = outcome.CrashReport(reason: dynamic.string("boom")) let own = outcome.Failed(outcome.TimeoutDetail(100)) assert outcome.with_crash_reports(own, "m", "t", [raw]) == own assert outcome.with_crash_reports(outcome.Pass, "m", "t", []) == outcome.Pass From 1aad9ba3a7212b08a81014c40b178fd7a297e876 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Sat, 22 Aug 2026 01:39:53 +0100 Subject: [PATCH 5/8] Kill and report the processes a test leaves running MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Process-per-test isolated the test function, not the tree it spawned. Nothing in the BEAM tears that tree down when a test ends, and a `normal` exit is ignored by a non-trapping link, so a worker a test started ran on into later tests and could crash long after its own test was reported — which is what the unattributed path existed to catch after the fact. The per-test trace already had the information to prevent it: `procs` delivers `spawn` and `spawned` alongside the exits, so the collector can keep a live set as cheaply as it discards those messages today. At the claim it hands that set back; the runner kills it in spawn order, so an ancestor is gone before anything it would restart, and records each one as a leak named by what started it. A Gleam closure reaches the trace as erlang:apply over a fun, so origins go through fun_info to recover the function the closure was written in. Ordering carries the correctness. The trace flush comes first, so every death the test caused on its own is accounted for before the runner causes any. Then the collector switches to discarding, so vouch's own kills are not reported back as the test's crashes — the trap `killed` sets, since it is not a clean exit. Then the kill, then a second round only if the first killed anything. With nothing left alive the collector stops, retiring the one lingering process per test as well. Leaks do not fail the run: the process was cleaned up before it could reach another test, and the report is what stops that being silent. --keep-leaked-processes reports without killing, for a suite that shares a process across tests deliberately, or where a leaked process is linked to something outside its tree — a kill propagates along that link. Processes started through an already-running supervisor or application:start are spawned outside the test's tree and are untouched either way. Also fixes two bugs found reviewing the branch: - forward_crashes/2 was not exported. erlang:hibernate/3 resumes through an exported call, so hibernating into a local function succeeds and fails with undef on wake-up: every late crash more than one idle period after the claim was silently lost, and the collector died. The existing test passed only because its worker crashed inside the 200ms window. - A background `todo` could mark a passing test skipped. Gleam attributes a closure's panic to the enclosing named function, so a worker written inline in a test body carries the test's own module and function — the pair classify_panic reads as "this test body is pending". Skipped contributes 0 to the exit code, so the crash disappeared entirely. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 18 ++ README.md | 29 +- docs/chapters/architecture.typ | 3 +- docs/chapters/execution.typ | 28 +- examples/playground/src/playground.gleam | 8 + .../playground/test/playground_test.gleam | 16 +- src/vouch.gleam | 6 + src/vouch/internal/config.gleam | 14 + src/vouch/internal/outcome.gleam | 17 +- src/vouch/internal/runner.gleam | 112 +++++++- src/vouch_ffi.erl | 247 ++++++++++++++++-- src/vouch_ffi.mjs | 9 + test/helpers.gleam | 92 +++++++ test/vouch_e2e_test.gleam | 45 +++- test/vouch_helpers_ffi.erl | 8 +- test/vouch_test.gleam | 175 ++++++++++++- 16 files changed, 761 insertions(+), 66 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ea5a94f..3b83d21 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -41,6 +41,24 @@ block on stderr after the summary. Other logger output (a library's warnings) is not a crash and still goes to stderr. JavaScript is unaffected: there are no processes to crash behind a test there. +Processes a test leaves running are now killed and reported. Nothing in the +BEAM tears down a test's process tree when the test ends, and a `normal` +exit does not kill a linked child, so a worker a test started kept running +into later tests and could crash long after its own test had been reported. +On the Erlang target the per-test trace now also names every process the +test started that is still alive when it ends. Those are killed there — +ancestors first, so a process restarting its children is gone before they +are touched — and listed after the summary: + + vouch: 1 leaked process killed after the test that started them: + vouch: playground_test.leaky_worker_test left playground:start_long_worker/0 running + +A leak does not fail the run. `--keep-leaked-processes` leaves them running +and only reports them, for a suite that deliberately shares a process across +tests or where a leaked process is linked to something outside the test's +tree. Processes started through an already-running supervisor or +`application:start` are spawned outside the test's tree and are unaffected. + ## v1.2.0 Watch mode added for the JavaScript target, supporting both Node and Deno diff --git a/README.md b/README.md index e1b6bd0..7998ba0 100644 --- a/README.md +++ b/README.md @@ -53,6 +53,7 @@ gleam test -- --junit=report.xml gleam test -- --timeout=1000 # Erlang target only gleam test -- --parallel # Erlang target only gleam test -- --show-crash-reports # Erlang target only, see below +gleam test -- --keep-leaked-processes # Erlang target only, see below gleam test -- --color=never # console colour: auto | always | never gleam run -m vouch -- watch # rerun the suite on file change ``` @@ -109,9 +110,35 @@ BEAM's own crash reports are kept off the output streams (they used to interleav stderr); pass `--show-crash-reports` to print them in full as one block after the summary. Other logger output (a library's warnings) is not a crash and still goes to stderr. +## Leaked processes + +Process-per-test isolates the test *function*, not everything it spawns: nothing in the BEAM +tears down a test's process tree, and a `normal` exit does not kill a linked child, so a worker +a test starts keeps running until it stops on its own — during later tests, and past the point +where its own test was reported. + +On the Erlang target vouch closes that: the same trace that catches background crashes also +names every process a test started that is still alive when the test ends. Those are killed +there — ancestors first, so a process restarting its children is gone before they are touched — +and listed after the summary, named by the test that leaked them and by what started them: + +``` +vouch: 1 leaked process killed after the test that started them: +vouch: playground_test.leaky_worker_test left playground:start_long_worker/0 running +``` + +A leak does not fail the run. The process was cleaned up before it could reach another test, +and the report is what stops that being silent. Pass `--keep-leaked-processes` to leave them +running and only report them — you need it for a suite that deliberately shares a process +across tests, or where a leaked process is linked to something outside the test's tree, since +killing it would propagate along that link. What a test starts through an already-running +supervisor or `application:start` is spawned elsewhere and is never in the test's tree, so it +is neither reported nor killed. + ## Target differences -Erlang target supports `--parallel`, `--timeout=n` and `--show-crash-reports` +Erlang target supports `--parallel`, `--timeout=n`, `--show-crash-reports` and +`--keep-leaked-processes` Deno needs permissions in your project's `gleam.toml`. You need `allow_read` for discovery and source quoting. diff --git a/docs/chapters/architecture.typ b/docs/chapters/architecture.typ index d825e55..538e1ed 100644 --- a/docs/chapters/architecture.typ +++ b/docs/chapters/architecture.typ @@ -63,7 +63,8 @@ The FFI contract, in full: [Terminal facts (TTY, env vars)], [`io:columns/0`, `os:getenv/1`], [`isTTY` / `Deno.stdout.isTerminal`, env lookup], - [Catch a crash behind a test / keep BEAM reports off the streams], + [Catch a crash behind a test, kill what it leaked / keep BEAM reports off + the streams], [`erlang:trace` a per-test process tree; capture logger handler], [not needed (no processes)], [Halt with exit code], diff --git a/docs/chapters/execution.typ b/docs/chapters/execution.typ index e953e0d..222cfe7 100644 --- a/docs/chapters/execution.typ +++ b/docs/chapters/execution.typ @@ -52,10 +52,30 @@ stays visible but can never corrupt piped stdout. (`logger:update_handler_config` silently ignores a runtime type change; remove-and-re-add is required.) -Known limitation, accepted for v1: a test that spawns unlinked long-lived -processes, registers global names, or mutates shared ETS tables can still -leak state between tests. Process-per-test is the 90% solution; full -sandboxing is out of scope. +The same trace closes the process half of that leak. A test's tree is not +torn down when the test ends — nothing in the BEAM does that, and a `normal` +exit is ignored by a non-trapping link — so a worker a test started outlives +it by default. At the claim the collector already knows which descendants +are still alive, from the `spawn` and `spawned` messages `procs` delivers +alongside the exits. Those are killed in spawn order, so an ancestor dies +before anything it would restart, and recorded as leaks for the end of the +run. Order matters throughout: the flush comes first, so every death the +test caused on its own is accounted for before the runner causes any; then +the collector is switched to discarding, so vouch's own kills are not +reported back as the test's crashes (the trap `killed` sets, since it is not +a clean exit); then the kill; then a second round only if the first killed +anything, in case a survivor restarted a child. With nothing left alive the +collector stops, which also retires the one lingering process per test. +`--keep-leaked-processes` reports without killing, for a suite that shares a +process across tests deliberately or where a leaked process is linked +outside its tree, since a kill propagates along that link. + +Known limitation, accepted for v1: a test that registers global names or +mutates shared ETS tables can still leak state between tests, and a process +started through an already-running supervisor or `application:start` is +spawned outside the test's tree, so it is neither traced, reported, nor +killed. Process-per-test plus killing what a test spawned is the 90% +solution; full sandboxing is out of scope. == JavaScript target: sequential in-process diff --git a/examples/playground/src/playground.gleam b/examples/playground/src/playground.gleam index 41152f4..3689a71 100644 --- a/examples/playground/src/playground.gleam +++ b/examples/playground/src/playground.gleam @@ -26,6 +26,14 @@ pub fn start_background_job() -> Nil { spawn(fn() { panic as "background job crashed: queue is full" }) } +/// A worker with no owner: the caller returns while it is still running. +/// Nothing crashes — this is the leak, not the crash — and on the BEAM vouch +/// kills it when the test that started it ends, so it cannot run on into a +/// later test, and reports it after the summary. +pub fn start_long_worker() -> Nil { + spawn(fn() { sleep(60_000) }) +} + @external(erlang, "playground_ffi", "spawn") @external(javascript, "./playground_ffi.mjs", "spawn") fn spawn(job: fn() -> Nil) -> Nil diff --git a/examples/playground/test/playground_test.gleam b/examples/playground/test/playground_test.gleam index 4ce4e84..eb4bc83 100644 --- a/examples/playground/test/playground_test.gleam +++ b/examples/playground/test/playground_test.gleam @@ -1,7 +1,7 @@ //// One test per outcome flavour, so a plain run shows vouch's full range: //// -//// gleam test - 2 pass, 5 fail, 2 todo, 1 skip -//// (JavaScript: 3 pass, 4 fail — no +//// gleam test - 3 pass, 5 fail, 2 todo, 1 skip +//// (JavaScript: 4 pass, 4 fail — no //// process crashes behind //// background_job_test there) //// gleam test -- --timeout=100 - slow_test also fails as a timeout @@ -11,6 +11,9 @@ //// gleam test -- --show-crash-reports //// - plus the full BEAM crash report //// from background_job_test's worker +//// gleam test -- --keep-leaked-processes +//// - leave leaky_worker_test's worker +//// running instead of killing it import playground import vouch @@ -37,6 +40,15 @@ pub fn background_job_test() { assert playground.add(0, 0) == 0 } +/// Starts a worker and returns while it is still running. The test passes — +/// leaking a process is not a failure — but on the BEAM vouch kills the +/// worker at the end of this test and lists it after the summary, so it +/// cannot pollute a later test. (On JavaScript there is no worker at all.) +pub fn leaky_worker_test() { + playground.start_long_worker() + assert playground.add(2, 2) == 4 +} + /// Passes with the default 5000ms timeout; fails with --timeout=100. pub fn slow_test() { playground.sleep(300) diff --git a/src/vouch.gleam b/src/vouch.gleam index 1765996..d3f4eff 100644 --- a/src/vouch.gleam +++ b/src/vouch.gleam @@ -55,6 +55,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.Console, Some(path) -> runner.run( @@ -66,6 +67,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.Json, None -> runner.run( @@ -74,6 +76,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.Json, Some(path) -> runner.run( @@ -82,6 +85,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.TeamCity, None -> runner.run( @@ -90,6 +94,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.TeamCity, Some(path) -> runner.run( @@ -98,6 +103,7 @@ fn run_tests(args: List(String)) -> Nil { cfg.timeout_ms, cfg.parallel, cfg.show_crash_reports, + cfg.kill_leaked_processes, ) } } diff --git a/src/vouch/internal/config.gleam b/src/vouch/internal/config.gleam index 3cb6dee..54b5717 100644 --- a/src/vouch/internal/config.gleam +++ b/src/vouch/internal/config.gleam @@ -39,6 +39,13 @@ pub type Config { /// default: a death under a test already shows in the test's outcome, /// as its own failure or a "Background process crashed" one. show_crash_reports: Bool, + /// Kill the processes a test leaves running when it ends, on the Erlang + /// target. On by default: process-per-test is only a real boundary if + /// nothing survives the test that started it. Turn it off when a suite + /// deliberately shares a process across tests, or when a leaked process + /// is linked to something outside the test's tree — killing it would + /// propagate. + kill_leaked_processes: Bool, ) } @@ -55,6 +62,7 @@ pub fn from_args(args: List(String)) -> Result(Config, String) { color: Auto, parallel: Sequential, show_crash_reports: False, + kill_leaked_processes: True, ), ) } @@ -98,6 +106,8 @@ fn parse(args: List(String), config: Config) -> Result(Config, String) { } ["--show-crash-reports", ..rest] -> parse(rest, Config(..config, show_crash_reports: True)) + ["--keep-leaked-processes", ..rest] -> + parse(rest, Config(..config, kill_leaked_processes: False)) [arg, ..] -> case string.starts_with(arg, "-") { True -> Error(usage("unknown option: " <> arg)) @@ -142,6 +152,10 @@ fn usage(problem: String) -> String { <> " --show-crash-reports\n" <> " also print the full BEAM crash reports of processes\n" <> " that died during the run, after the summary (Erlang)\n" + <> " --keep-leaked-processes\n" + <> " do not kill the processes a test leaves running when\n" + <> " it ends; they are killed and reported by default\n" + <> " (Erlang)\n" <> " --color=mode console colour: auto (default), always, never;\n" <> " auto respects NO_COLOR and non-TTY output\n" <> "\n" diff --git a/src/vouch/internal/outcome.gleam b/src/vouch/internal/outcome.gleam index 1c2dc25..0b16997 100644 --- a/src/vouch/internal/outcome.gleam +++ b/src/vouch/internal/outcome.gleam @@ -58,6 +58,15 @@ pub type CrashReport { CrashReport(reason: Dynamic) } +/// A process a test started that was still alive when the test ended, named +/// by what started it: the module and function of the spawned call, or the +/// function a spawned closure was written in. Not a failure — the process is +/// killed and the leak reported, so it can neither pollute a later test nor +/// crash after its own test has been reported. +pub type ProcessLeak { + ProcessLeak(module: String, function: String, arity: Int) +} + /// The top frame of the stacktrace behind a non-Gleam crash: what was being /// called when the test died. An undef from a stale .beam carries no Gleam /// payload at all, so this frame is the only thing that names the failure. @@ -165,7 +174,13 @@ fn classify_report( Ok(p) -> case classify_panic(test_module, test_function, p) { Failed(cause) -> Failed(BackgroundCrashDetail(cause)) - todo_or_skipped -> todo_or_skipped + // A skip is the test body declaring itself pending, never a verdict + // on another process's death — but a worker written inline in a test + // body carries the enclosing test's own module and function, the + // pair classify_panic reads as a skip. Unimplemented code is a todo + // wherever it ran. + Skipped(p) -> Todo(p) + other -> other } Error(Nil) -> { let #(reason, site) = split_crash(report.reason) diff --git a/src/vouch/internal/runner.gleam b/src/vouch/internal/runner.gleam index 2d33d8d..1a75c60 100644 --- a/src/vouch/internal/runner.gleam +++ b/src/vouch/internal/runner.gleam @@ -64,11 +64,13 @@ fn finish( outcomes: List(TestOutcome), duration: Int, show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { let t = tally(outcomes) let _ = rep.handle(state, event.RunEnd(t, duration)) let unattributed = unattributed_crash_reports() print_unattributed(unattributed) + print_leaks(leaked_processes(), kill_leaked) case show_crash_reports { True -> print_crash_reports(all_crash_reports()) False -> Nil @@ -81,9 +83,9 @@ fn finish( } /// Crash reports no test claimed: the process died after its test had -/// finished (named here, from the group leader it inherited), or outside -/// any test. Printed on stderr — clear of a machine-read stdout stream — -/// and the run fails. +/// finished (named here by that test's collector, which keeps tracing its +/// tree past the claim), or outside any traced tree at all. Printed on +/// stderr — clear of a machine-read stdout stream — and the run fails. fn print_unattributed( reports: List(#(String, Option(#(String, String)))), ) -> Nil { @@ -114,6 +116,46 @@ fn print_unattributed( } } +/// Processes a test left running when it ended, killed at that point and +/// listed here — named by the test that leaked them and by what started +/// them. Printed on stderr, clear of a machine-read stdout stream. A leak +/// does not fail the run: the process was cleaned up before it could +/// pollute a later test, and this report is what keeps that from being +/// silent. `--keep-leaked-processes` turns the killing off. +fn print_leaks( + leaks: List(#(String, String, outcome.ProcessLeak)), + kill_leaked: Bool, +) -> Nil { + case leaks { + [] -> Nil + _ -> { + term.warn( + count(leaks, "leaked process") + <> case kill_leaked { + True -> " killed after the test that started them:" + False -> " left running by the test that started them:" + }, + ) + list.each(leaks, fn(leak) { + let #(module, function, origin) = leak + io.print_error( + "vouch: " + <> module + <> "." + <> function + <> " left " + <> origin.module + <> ":" + <> origin.function + <> "/" + <> int.to_string(origin.arity) + <> " running\n", + ) + }) + } + } +} + /// `--show-crash-reports`: every BEAM crash report captured during the run, /// attributed or not, reprinted in full as one block after the summary on /// stderr — the raw report behind a "Background process crashed" failure. @@ -180,10 +222,20 @@ pub fn run( timeout_ms: Int, parallel: config.Parallelism, show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { case target() { - Erlang -> run_beam(rep, filter, timeout_ms, parallel, show_crash_reports) - JavaScript -> run_js(rep, filter, timeout_ms, parallel, show_crash_reports) + Erlang -> + run_beam( + rep, + filter, + timeout_ms, + parallel, + show_crash_reports, + kill_leaked, + ) + JavaScript -> + run_js(rep, filter, timeout_ms, parallel, show_crash_reports, kill_leaked) } } @@ -196,6 +248,7 @@ fn run_beam( timeout_ms: Int, parallel: config.Parallelism, show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { capture_diagnostics() let started = now_microseconds() @@ -224,8 +277,8 @@ fn run_beam( event.RunStart(list.length(tests), list.length(candidates)), ) let #(state, outcomes) = case workers(parallel) { - 1 -> run_sequential(rep, state, tests, timeout_ms) - n -> run_window(rep, tests, [], 0, state, [], timeout_ms, n) + 1 -> run_sequential(rep, state, tests, timeout_ms, kill_leaked) + n -> run_window(rep, tests, [], 0, state, [], timeout_ms, n, kill_leaked) } finish( rep, @@ -233,6 +286,7 @@ fn run_beam( list.reverse(outcomes), now_microseconds() - started, show_crash_reports, + kill_leaked, ) } @@ -249,13 +303,15 @@ fn run_sequential( state: s, tests: List(#(String, String)), timeout_ms: Int, + kill_leaked: Bool, ) -> #(s, List(TestOutcome)) { list.fold(tests, #(state, []), fn(acc, test_case) { let #(state, outcomes) = acc let #(module, function) = test_case let state = rep.handle(state, event.TestStart(module, function)) let test_started = now_microseconds() - let #(invocation, reports) = run_in_process(module, function, timeout_ms) + let #(invocation, reports) = + run_in_process(module, function, timeout_ms, kill_leaked) let duration = now_microseconds() - test_started let out = outcome.classify(module, function, invocation) @@ -281,12 +337,13 @@ fn run_window( outcomes: List(TestOutcome), timeout_ms: Int, workers: Int, + kill_leaked: Bool, ) -> #(s, List(TestOutcome)) { case pending { [next, ..rest] if running_count < workers -> { let #(module, function) = next let state = rep.handle(state, event.TestStart(module, function)) - let handle = start_test(module, function, timeout_ms) + let handle = start_test(module, function, timeout_ms, kill_leaked) run_window( rep, rest, @@ -296,6 +353,7 @@ fn run_window( outcomes, timeout_ms, workers, + kill_leaked, ) } _ -> @@ -317,6 +375,7 @@ fn run_window( [out, ..outcomes], timeout_ms, workers, + kill_leaked, ) } } @@ -341,6 +400,22 @@ fn all_crash_reports() -> List(String) @external(javascript, "../../vouch_ffi.mjs", "unattributed_diagnostics") fn unattributed_crash_reports() -> List(#(String, Option(#(String, String)))) +/// Every process a test left running when it ended, as the test that +/// leaked it and what started it. Read once at the end of the run. +@external(erlang, "vouch_ffi", "leaked_processes") +@external(javascript, "../../vouch_ffi.mjs", "leaked_processes") +fn leaked_processes() -> List(#(String, String, outcome.ProcessLeak)) + +/// Remove and return the recorded leaks whose origin function contains +/// `marker`. Public so vouch's own suite can leak a process on purpose, +/// prove it was killed and recorded, and consume the row so the end-of-run +/// leak report does not carry the suite's own deliberate leaks. +@external(erlang, "vouch_ffi", "take_leaks_matching") +@external(javascript, "../../vouch_ffi.mjs", "take_leaks_matching") +pub fn take_leaks_matching( + marker: String, +) -> List(#(String, String, outcome.ProcessLeak)) + /// Remove and return the captured crash reports whose text contains /// `marker`, leaving the rest alone. Public so vouch's own suite can crash a /// process in its own process tree on purpose, consume the report (so the @@ -382,6 +457,7 @@ pub fn run_in_process( module: String, function: String, timeout_ms: Int, + kill_leaked: Bool, ) -> #(outcome.Invocation, List(outcome.CrashReport)) /// An in-flight test started by `start_test`: created and consumed only by @@ -399,6 +475,7 @@ pub fn start_test( module: String, function: String, timeout_ms: Int, + kill_leaked: Bool, ) -> TestHandle @external(erlang, "vouch_ffi", "await_test") @@ -425,7 +502,15 @@ pub fn warn_ineffective_js_flags( timeout_ms: Int, parallel: config.Parallelism, show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { + case kill_leaked { + True -> Nil + False -> + term.warn( + "--keep-leaked-processes has no effect on the JavaScript target — tests run in-process and start no processes to leak", + ) + } case show_crash_reports { False -> Nil True -> @@ -455,8 +540,14 @@ fn run_js( timeout_ms: Int, parallel: config.Parallelism, show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { - warn_ineffective_js_flags(timeout_ms, parallel, show_crash_reports) + warn_ineffective_js_flags( + timeout_ms, + parallel, + show_crash_reports, + kill_leaked, + ) let started = now_microseconds() js_run_tests( #(rep.init, [], 0), @@ -485,6 +576,7 @@ fn run_js( list.reverse(outs), now_microseconds() - started, show_crash_reports, + kill_leaked, ) }, ) diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index 19c4f9e..f8628e6 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -2,7 +2,7 @@ -export([ find_test_files/0, exported_zero_arity/1, - run_test/3, + run_test/4, catch_panic/1, split_crash/1, decode_panic/1, @@ -14,9 +14,17 @@ unattributed_diagnostics/0, take_diagnostics_matching/1, take_unattributed_matching/1, + leaked_processes/0, + take_leaks_matching/1, crash_filter/2, log/2, - collect_crashes/3, + %% The collector's three states. All exported because erlang:hibernate/3 + %% resumes through an exported call: hibernating into a local function + %% succeeds and then fails with undef on wake-up, silently killing the + %% collector. + collect_crashes/4, + sweep_leaks/3, + forward_crashes/2, write_file/2, read_source/3, halt/1, @@ -28,7 +36,7 @@ take_pending_key/0, keys_active/0, ensure_unicode_stdio/0, - start_test/3, + start_test/4, await_test/1, schedulers_online/0, is_erlang/0, @@ -133,11 +141,14 @@ capture_diagnostics() -> %% TestName} for crashes a collector saw after its test was already claimed %% (a worker outliving its test) or that no test's tree produced — these %% fail the run. Both owned by the runner process, which lives until halt. +%% vouch_leaks: {Key, TestName, Leak} for processes a test left running, +%% recorded as each test is claimed. ensure_diagnostics_tables() -> case ets:whereis(vouch_crash_texts) of undefined -> ets:new(vouch_crash_texts, [named_table, public, ordered_set]), - ets:new(vouch_unattributed, [named_table, public, ordered_set]); + ets:new(vouch_unattributed, [named_table, public, ordered_set]), + ets:new(vouch_leaks, [named_table, public, ordered_set]); _ -> ok end. @@ -232,6 +243,25 @@ take_unattributed_matching(Marker) -> Text <- [reason_text(Reason)], binary:match(Text, Marker) =/= nomatch]. +%% Every process a test left running, in the order they were recorded, as +%% {TestModule, TestFunction, Leak}. Read once at the end of the run. +leaked_processes() -> + [{TestModule, TestFunction, Leak} + || {_Key, {TestModule, TestFunction}, Leak} <- table(vouch_leaks)]. + +%% Remove and return the leaks whose origin function contains Marker. The +%% suite-facing probe: a test that leaks a process on purpose can assert it +%% was killed and recorded, and consume the row so the end-of-run leak +%% report does not carry the suite's own deliberate leaks. +take_leaks_matching(Marker) -> + [begin + catch ets:delete(vouch_leaks, Key), + {TestModule, TestFunction, Leak} + end + || {Key, {TestModule, TestFunction}, Leak} <- table(vouch_leaks), + {process_leak, _Module, Function, _Arity} <- [Leak], + binary:match(Function, Marker) =/= nomatch]. + table(Name) -> case catch ets:tab2list(Name) of Rows when is_list(Rows) -> Rows; @@ -314,7 +344,14 @@ exported_zero_arity(ModuleName) -> %% any trace messages still in transit, then the collector is claimed. It %% keeps tracing afterwards: a worker that outlives its test and crashes %% later is recorded as unattributed (the runner fails the run on those). -run_test(ModuleName, FunctionName, TimeoutMs) -> +%% +%% The same trace also names every process the test started that is still +%% alive when the test ends. With KillLeaked those are killed — ancestors +%% first, so a supervisor cannot restart what has already gone — and +%% recorded as leaks, which is what makes process-per-test a real boundary +%% rather than a 90% one: nothing survives to crash late. With KillLeaked +%% false the tree is left alone and late crashes take the unattributed path. +run_test(ModuleName, FunctionName, TimeoutMs, KillLeaked) -> Module = binary_to_atom(beam_name(ModuleName), utf8), Function = binary_to_atom(FunctionName, utf8), Self = self(), @@ -325,7 +362,7 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> Self ! {vouch_result, self(), catch_panic(fun() -> Module:Function() end)} end), Collector = spawn(?MODULE, collect_crashes, - [Pid, {ModuleName, FunctionName}, []]), + [Pid, {ModuleName, FunctionName}, [], #{}]), %% Drop any trace inherited from a traced caller — vouch's own suite runs %% tests that themselves run tests, and a process can have only one %% tracer — before setting this test's own. A harmless no-op for a @@ -353,7 +390,20 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> end, {timed_out, TimeoutMs} end, - {Invocation, claim_crashes(Collector)}. + {Reports, Leaks} = claim_crashes(Collector, KillLeaked), + record_leaks({ModuleName, FunctionName}, Leaks), + {Invocation, Reports}. + +%% Recorded from whichever process ran the test — the runner, or a parallel +%% middleman that dies with it — so the table is never created here: it is +%% owned by the runner (capture_diagnostics) and a middleman that created it +%% would take it to the grave. +record_leaks(_TestName, []) -> + ok; +record_leaks(TestName, Leaks) -> + [catch ets:insert(vouch_leaks, + {erlang:unique_integer([monotonic]), TestName, Leak}) || Leak <- Leaks], + ok. %% Tracer for one test's process tree. Accumulates the exit reason of every %% descendant that dies abnormally — anything but a clean exit (normal, @@ -362,24 +412,132 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> %% forwarding: any later crash (a worker that outlived the test) goes to the %% unattributed table, tagged with this test, for the runner's end-of-run %% failure. Idle between events, it hibernates to a few hundred bytes. -collect_crashes(TestPid, TestName, Acc) -> +collect_crashes(TestPid, TestName, Acc, Live) -> receive {trace, TestPid, exit, _Reason} -> - collect_crashes(TestPid, TestName, Acc); - {trace, _Pid, exit, Reason} -> + collect_crashes(TestPid, TestName, Acc, Live); + {trace, Pid, exit, Reason} -> + Rest = maps:remove(Pid, Live), case is_clean_exit(Reason) of - true -> collect_crashes(TestPid, TestName, Acc); - false -> collect_crashes(TestPid, TestName, [Reason | Acc]) + true -> collect_crashes(TestPid, TestName, Acc, Rest); + false -> collect_crashes(TestPid, TestName, [Reason | Acc], Rest) + end; + {trace, _Parent, spawn, Child, MFA} -> + collect_crashes(TestPid, TestName, Acc, + note_spawn(Child, MFA, Live)); + {trace, Child, spawned, _Parent, MFA} -> + collect_crashes(TestPid, TestName, Acc, + note_spawn(Child, MFA, Live)); + {claim, From, Ref, Kill} -> + From ! {crashes, Ref, lists:reverse(Acc), leaks_of(Live)}, + case Kill of + true -> sweep_leaks(TestPid, TestName, Live); + false -> forward_crashes(TestPid, TestName) + end; + _Other -> + collect_crashes(TestPid, TestName, Acc, Live) + after 200 -> + erlang:hibernate(?MODULE, collect_crashes, + [TestPid, TestName, Acc, Live]) + end. + +%% Between the claim and the last kill round. Crash reasons are discarded: +%% every death from here is one the runner is causing, and reporting our own +%% kills as the test's crashes is exactly the trap `killed` sets. Spawns are +%% still tracked, so a child a supervisor restarted before it was itself +%% killed shows up in the next sweep. On `finish` the collector stops if +%% nothing survived — which is the normal case, and retires the one +%% lingering process per test — or falls back to forwarding if something +%% did, so a stubborn survivor still reports a late crash. +sweep_leaks(TestPid, TestName, Live) -> + receive + {trace, TestPid, exit, _Reason} -> + sweep_leaks(TestPid, TestName, Live); + {trace, Pid, exit, _Reason} -> + sweep_leaks(TestPid, TestName, maps:remove(Pid, Live)); + {trace, _Parent, spawn, Child, MFA} -> + sweep_leaks(TestPid, TestName, note_spawn(Child, MFA, Live)); + {trace, Child, spawned, _Parent, MFA} -> + sweep_leaks(TestPid, TestName, note_spawn(Child, MFA, Live)); + {sweep, From, Ref} -> + From ! {swept, Ref, live_pids(Live)}, + sweep_leaks(TestPid, TestName, Live); + {finish, From, Ref} -> + From ! {finished, Ref}, + case live_pids(Live) of + [] -> ok; + _ -> forward_crashes(TestPid, TestName) end; - {claim, From, Ref} -> - From ! {crashes, Ref, lists:reverse(Acc)}, - forward_crashes(TestPid, TestName); _Other -> - collect_crashes(TestPid, TestName, Acc) + sweep_leaks(TestPid, TestName, Live) after 200 -> - erlang:hibernate(?MODULE, collect_crashes, [TestPid, TestName, Acc]) + erlang:hibernate(?MODULE, sweep_leaks, [TestPid, TestName, Live]) + end. + +%% One live descendant, keyed by pid. The monotonic key orders the set by +%% spawn, so killing in key order takes ancestors before their children and +%% a supervisor is gone before anything it would restart is touched. `spawn` +%% and `spawned` both arrive for the same child, so the first one wins. +note_spawn(Child, MFA, Live) -> + case maps:is_key(Child, Live) of + true -> Live; + false -> Live#{Child => {erlang:unique_integer([monotonic]), origin(MFA)}} end. +%% What started a process, for the leak report. A Gleam closure reaches the +%% trace as erlang:apply/2 over a fun, naming nothing useful; fun_info +%% recovers the module it was compiled into and the generated name +%% `-enclosing/0-fun-0-`, whose enclosing function is the half worth showing +%% — the same function a panic in that closure would report. +origin({erlang, apply, [Fun, Args]}) when is_function(Fun), is_list(Args) -> + Info = erlang:fun_info(Fun), + Module = proplists:get_value(module, Info, unknown), + Name = proplists:get_value(name, Info, unknown), + {process_leak, atom_to_binary(Module, utf8), enclosing_name(Name), + length(Args)}; +origin({Module, Function, Args}) + when is_atom(Module), is_atom(Function), is_list(Args) -> + {process_leak, atom_to_binary(Module, utf8), + atom_to_binary(Function, utf8), length(Args)}; +origin(_) -> + {process_leak, <<"unknown">>, <<"unknown">>, 0}. + +enclosing_name(Name) when is_atom(Name) -> + Bin = atom_to_binary(Name, utf8), + case Bin of + <<"-", Rest/binary>> -> + case binary:split(Rest, <<"/">>) of + [Enclosing, _] -> Enclosing; + _ -> Bin + end; + _ -> + Bin + end; +enclosing_name(_) -> + <<"unknown">>. + +%% The leaked processes still alive, oldest spawn first. Two exclusions. +%% Dead pids: a descendant whose trace was dropped (the nested case below) +%% never reports its exit, so the map can outlive it. vouch's own +%% scaffolding: the suite runs tests that run tests, and the inner test +%% process, its collector and the parallel middleman are all spawned inside +%% a traced tree — vouch's plumbing, not the user's leak, and killing our +%% own collector would be self-inflicted. +live_leaks(Live) -> + Sorted = lists:sort(fun({_, {A, _}}, {_, {B, _}}) -> A =< B end, + maps:to_list(Live)), + [{Pid, Origin} + || {Pid, {_Key, Origin}} <- Sorted, + not is_vouch_process(Origin), + is_process_alive(Pid)]. + +is_vouch_process({process_leak, <<"vouch_ffi">>, _Function, _Arity}) -> true; +is_vouch_process(_) -> false. + +leaks_of(Live) -> [Origin || {_Pid, Origin} <- live_leaks(Live)]. + +live_pids(Live) -> [Pid || {Pid, _Origin} <- live_leaks(Live)]. + forward_crashes(TestPid, TestName) -> receive {trace, TestPid, exit, _Reason} -> @@ -404,15 +562,49 @@ is_clean_exit(shutdown) -> true; is_clean_exit({shutdown, _}) -> true; is_clean_exit(_) -> false. -%% Flush trace messages still in transit to their tracers (see run_test/3), -%% then take the collector's accumulated crash reasons. -claim_crashes(Collector) -> - Delivered = erlang:trace_delivered(all), - receive {trace_delivered, all, Delivered} -> ok end, +%% Flush trace messages still in transit to their tracers (see run_test/4), +%% then take the collector's accumulated crash reasons and the processes the +%% test left running. The flush comes first so every death the test caused +%% on its own is already accounted for before the runner causes any itself. +claim_crashes(Collector, KillLeaked) -> + flush_traces(), + Ref = make_ref(), + Collector ! {claim, self(), Ref, KillLeaked}, + {Reasons, Leaks} = + receive {crashes, Ref, Rs, Ls} -> {Rs, Ls} after 5000 -> {[], []} end, + case KillLeaked of + true -> kill_leaked(Collector); + false -> ok + end, + {reasons_to_reports(Reasons), Leaks}. + +%% Take down what the test left running. A second round only if the first +%% killed anything: the one thing that can reappear is a child a supervisor +%% restarted, and the supervisor itself died in round one. +kill_leaked(Collector) -> + case kill_round(Collector) of + [] -> ok; + _ -> kill_round(Collector) + end, Ref = make_ref(), - Collector ! {claim, self(), Ref}, - Reasons = receive {crashes, Ref, Rs} -> Rs after 5000 -> [] end, - reasons_to_reports(Reasons). + Collector ! {finish, self(), Ref}, + receive {finished, Ref} -> ok after 5000 -> ok end. + +%% `kill` rather than `shutdown`, which a process trapping exits may ignore. +%% The flush afterwards puts the resulting exits in the collector's mailbox +%% before the next sweep reads its map, so a round's own kills never look +%% like survivors. +kill_round(Collector) -> + Ref = make_ref(), + Collector ! {sweep, self(), Ref}, + Pids = receive {swept, Ref, Ps} -> Ps after 5000 -> [] end, + [exit(Pid, kill) || Pid <- Pids], + flush_traces(), + Pids. + +flush_traces() -> + Delivered = erlang:trace_delivered(all), + receive {trace_delivered, all, Delivered} -> ok end. %% Each crash reason as an outcome.CrashReport, whose single field the %% Gleam side decodes exactly like a caught panic — find_panic reaches a @@ -427,12 +619,13 @@ reasons_to_reports(Reasons) -> %% isolation, timeout and crash-report semantics — measures the duration, %% and posts the result back tagged with a unique ref. The monitor covers %% the theoretical case of the middleman dying before it reports. -start_test(Module, Function, TimeoutMs) -> +start_test(Module, Function, TimeoutMs, KillLeaked) -> Self = self(), Ref = make_ref(), {_Pid, MonRef} = spawn_monitor(fun() -> Started = erlang:monotonic_time(microsecond), - {Invocation, Reports} = run_test(Module, Function, TimeoutMs), + {Invocation, Reports} = + run_test(Module, Function, TimeoutMs, KillLeaked), Duration = erlang:monotonic_time(microsecond) - Started, Self ! {vouch_parallel, Ref, Invocation, Reports, Duration} end), diff --git a/src/vouch_ffi.mjs b/src/vouch_ffi.mjs index 149e64e..a8ed2f9 100644 --- a/src/vouch_ffi.mjs +++ b/src/vouch_ffi.mjs @@ -99,6 +99,15 @@ export function take_unattributed_matching(_marker) { erlangOnly("take_unattributed_matching"); } +// Same again for leaked processes: nothing here spawns, so nothing leaks. +export function leaked_processes() { + return List$Empty(); +} + +export function take_leaks_matching(_marker) { + erlangOnly("take_leaks_matching"); +} + export function find_test_files() { erlangOnly("find_test_files"); } diff --git a/test/helpers.gleam b/test/helpers.gleam index dc9e7a1..4c7cc55 100644 --- a/test/helpers.gleam +++ b/test/helpers.gleam @@ -2,6 +2,9 @@ //// stand in for "code under test": the suite invokes them via catch_panic //// and asserts on the decoded payloads. +@target(erlang) +import vouch/internal/runner + pub fn is_even(n: Int) -> Bool { n % 2 == 0 } @@ -115,6 +118,95 @@ pub fn returns_before_worker_crashes() -> Nil { }) } +@target(erlang) +/// The same, but the worker sleeps past the collector's idle timeout before +/// crashing, so the trace message arrives at a collector that has already +/// hibernated. `returns_before_worker_crashes` never leaves the collector's +/// first receive, so it cannot cover the wake-up path. +pub fn returns_long_before_worker_crashes() -> Nil { + spawn(fn() { + sleep(400) + panic as "crash after the collector hibernated" + }) +} + +@target(erlang) +/// A worker whose `todo` is lexically inside this function, so the panic +/// names `helpers.todo_in_inline_worker` — Gleam attributes a closure's +/// panic to the enclosing named function, which is what a worker written +/// inline in a test body does too. +pub fn todo_in_inline_worker() -> Nil { + run_in_background(fn() { todo as "unimplemented worker in a test body" }) +} + +@target(erlang) +/// A worker that outlives its test and would announce it: if the kill does +/// not land, it panics with a marker no other fixture uses, so surviving is +/// observable rather than merely unproven. +pub fn leaks_a_doomed_worker() -> Nil { + spawn(fn() { + sleep(60) + panic as "doomed worker was not killed" + }) +} + +@target(erlang) +/// A leak from a named spawn rather than a closure, so the trace's MFA +/// names the worker directly and needs no fun_info to make sense of. +pub fn leaks_named_worker() -> Nil { + spawn_named("sleeps_a_long_time", 5000) +} + +@target(erlang) +pub fn sleeps_a_long_time(ms: Int) -> Nil { + sleep(ms) +} + +@target(erlang) +/// A leaked process that keeps starting children: killing a child alone +/// would just bring another one, so the parent has to die first. Bounded so +/// that a failure to kill it costs the suite half a second of spawning +/// rather than an unbounded loop, and the children crash on a timer, which +/// is what surfaces if any of them outlives the kill. +pub fn leaks_a_supervisor() -> Nil { + spawn(fn() { supervise(25) }) + // Let the first child exist before the test ends, so both are in the set. + sleep(30) +} + +@target(erlang) +fn supervise(remaining: Int) -> Nil { + case remaining { + 0 -> Nil + n -> { + spawn(fn() { + sleep(60) + panic as "restarted worker crashed" + }) + sleep(20) + supervise(n - 1) + } + } +} + +@target(erlang) +/// A test that runs a test: the shape vouch's own suite uses everywhere, +/// and the one that puts vouch's own processes inside a traced tree. +pub fn runs_a_nested_test() -> Nil { + let _ = runner.run_in_process("helpers", "is_even_wrapper", 5000, True) + Nil +} + +@target(erlang) +pub fn is_even_wrapper() -> Nil { + let _ = is_even(2) + Nil +} + +@target(erlang) +@external(erlang, "vouch_helpers_ffi", "spawn_named") +fn spawn_named(function: String, ms: Int) -> Nil + @target(erlang) @external(erlang, "timer", "sleep") fn sleep(ms: Int) -> Nil diff --git a/test/vouch_e2e_test.gleam b/test/vouch_e2e_test.gleam index 6194d28..a2a495b 100644 --- a/test/vouch_e2e_test.gleam +++ b/test/vouch_e2e_test.gleam @@ -18,7 +18,7 @@ pub fn playground_erlang_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":3,\"failed\":5,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"outcome\":\"todo\"") assert string.contains(out, "\"site_function\":\"rate_limit\"") @@ -65,7 +65,7 @@ pub fn playground_javascript_e2e_test() { // behind background_job_test. assert string.contains( out, - "\"event\":\"run_end\",\"passed\":3,\"failed\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":4,\"failed\":4,\"todo\":2,\"skipped\":1", ) // On JavaScript the crash is a raw TypeError with no site to extract. assert string.contains(out, "\"kind\":\"unknown\"") @@ -84,7 +84,7 @@ pub fn playground_timeout_e2e_test() { assert string.contains(out, "\"timeout_ms\":100") assert string.contains( out, - "\"event\":\"run_end\",\"passed\":1,\"failed\":6,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":6,\"todo\":2,\"skipped\":1", ) } @@ -101,7 +101,7 @@ pub fn playground_parallel_e2e_test() { assert code == 1 assert string.contains( out, - "\"event\":\"run_end\",\"passed\":2,\"failed\":5,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":3,\"failed\":5,\"todo\":2,\"skipped\":1", ) assert string.contains(out, "\"site_function\":\"rate_limit\"") // Attribution holds under --parallel too: the worker's crash is charged @@ -147,11 +147,46 @@ pub fn playground_crash_reports_e2e_test() { ) // The raw report, after the summary, not interleaved with the results. let assert Ok(#(_, after_summary)) = - string.split_once(shown, "2 passed, 5 failed, 2 todo, 1 skipped") + string.split_once(shown, "3 passed, 5 failed, 2 todo, 1 skipped") assert string.contains(after_summary, "Error in process") assert string.contains(after_summary, "background job crashed: queue is full") } +@target(erlang) +/// leaky_worker_test's worker is still running when the test ends. The test +/// passes — leaking is not a failure — and the worker is killed there and +/// listed after the summary, named by the test and by what started it. +/// `--keep-leaked-processes` leaves it running and says so. +pub fn playground_leaked_process_e2e_test() { + let assert Ok(#(_, killed)) = + run_command_merged( + "gleam", + ["test", "--", "--color=never"], + "examples/playground", + ) + // Leaking is not a failure: the test itself passes. + assert string.contains(killed, "ok playground_test.leaky_worker_test") + assert string.contains( + killed, + "vouch: 1 leaked process killed after the test that started them:", + ) + assert string.contains( + killed, + "vouch: playground_test.leaky_worker_test left playground:start_long_worker/0 running", + ) + + let assert Ok(#(_, kept)) = + run_command_merged( + "gleam", + ["test", "--", "--color=never", "--keep-leaked-processes"], + "examples/playground", + ) + assert string.contains( + kept, + "vouch: 1 leaked process left running by the test that started them:", + ) +} + @target(erlang) @external(erlang, "vouch_e2e_ffi", "run_command") fn run_command( diff --git a/test/vouch_helpers_ffi.erl b/test/vouch_helpers_ffi.erl index b6c6372..2e53c86 100644 --- a/test/vouch_helpers_ffi.erl +++ b/test/vouch_helpers_ffi.erl @@ -1,6 +1,6 @@ %% Test-only helper for the background-crash fixtures in helpers.gleam. -module(vouch_helpers_ffi). --export([run_in_background/1]). +-export([run_in_background/1, spawn_named/2]). %% Run F in an unlinked process and wait until that process is gone. The %% caller is not linked, so the crash does not reach it; the monitor only @@ -12,3 +12,9 @@ run_in_background(F) -> receive {'DOWN', Ref, process, _, _} -> nil end. + +%% Spawn by name rather than with a fun, so the trace's spawn message +%% carries a real MFA instead of erlang:apply over a closure. +spawn_named(Function, Ms) -> + erlang:spawn(helpers, binary_to_atom(Function, utf8), [Ms]), + nil. diff --git a/test/vouch_test.gleam b/test/vouch_test.gleam index 08edcce..35816f8 100644 --- a/test/vouch_test.gleam +++ b/test/vouch_test.gleam @@ -128,7 +128,7 @@ pub fn timeout_classifies_as_failure_test() { @target(erlang) pub fn hanging_test_times_out_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "sleeps_forever", 100) + runner.run_in_process("helpers", "sleeps_forever", 100, True) assert invocation == outcome.TimedOut(100) // Killed, not crashed: the BEAM logs nothing for a kill. assert reports == [] @@ -137,7 +137,7 @@ pub fn hanging_test_times_out_test() { @target(erlang) pub fn linked_crash_is_contained_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "crashes_linked", 5000) + runner.run_in_process("helpers", "crashes_linked", 5000, True) let assert outcome.Failed(outcome.PanicDetail(p)) = outcome.classify("vouch_test", "linked_crash_is_contained_test", invocation) assert p.message == "crash in linked process" @@ -169,7 +169,7 @@ pub fn linked_crash_is_contained_test() { @target(erlang) pub fn background_crash_fails_passing_test_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "crashes_in_background", 5000) + runner.run_in_process("helpers", "crashes_in_background", 5000, True) assert invocation == outcome.Passed let out = outcome.classify("vouch_test", "background_crash_test", invocation) @@ -190,7 +190,7 @@ pub fn background_crash_fails_passing_test_test() { /// as a todo the test reached directly. pub fn background_todo_is_todo_outcome_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "todo_in_background", 5000) + runner.run_in_process("helpers", "todo_in_background", 5000, True) assert invocation == outcome.Passed let assert outcome.Todo(p) = outcome.classify("vouch_test", "background_todo_test", invocation) @@ -203,7 +203,7 @@ pub fn background_todo_is_todo_outcome_test() { /// A background crash with no Gleam payload still names what was called. pub fn background_undef_names_call_site_test() { let #(_, reports) = - runner.run_in_process("helpers", "undef_in_background", 5000) + runner.run_in_process("helpers", "undef_in_background", 5000, True) let assert outcome.Failed(outcome.BackgroundCrashDetail(outcome.UnknownDetail( reason, Some(site), @@ -218,14 +218,149 @@ pub fn background_undef_names_call_site_test() { /// claimed (so no report is charged to the test), then crashes. The runner's /// tracer records the late death as unattributed, which fails the run. It is /// consumed here — after polling for it to arrive — so this suite run does -/// not itself fail on it. +/// not itself fail on it. Killing is off (the `False`), which is the only +/// way a worker can still be alive to crash late; the default path is +/// covered by leaked_process_is_killed_and_recorded_test. pub fn late_background_crash_becomes_unattributed_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "returns_before_worker_crashes", 5000) + runner.run_in_process( + "helpers", + "returns_before_worker_crashes", + 5000, + False, + ) assert invocation == outcome.Passed assert reports == [] let assert [text] = await_unattributed("late crash in background process", 80) assert string.contains(text, "late crash in background process") + // Recorded as a leak as well: the worker was alive when the test ended, + // and reporting a leak does not depend on killing it. + let assert [_] = runner.take_leaks_matching("returns_before_worker_crashes") +} + +@target(erlang) +/// The same, but late enough that the collector has hibernated first. A +/// collector that cannot resume — hibernating into a function the module +/// does not export fails on wake-up, not at the hibernate call — dies with +/// `undef` and silently drops every crash after the first idle period, so +/// the test above passes while the feature is broken for anything slower. +/// Killing off again, for the same reason. +pub fn crash_after_collector_hibernates_is_unattributed_test() { + let #(invocation, reports) = + runner.run_in_process( + "helpers", + "returns_long_before_worker_crashes", + 5000, + False, + ) + assert invocation == outcome.Passed + assert reports == [] + let assert [text] = + await_unattributed("crash after the collector hibernated", 120) + assert string.contains(text, "crash after the collector hibernated") + let assert [_] = + runner.take_leaks_matching("returns_long_before_worker_crashes") +} + +@target(erlang) +/// A background todo must never mark the test skipped. `Skipped` means +/// "this test body is pending", so `classify_panic` returns it for a todo +/// whose module and function are the test's own — and a worker written +/// inline in a test body carries exactly that pair. Folding that into the +/// outcome would report a test whose worker hit unimplemented code as +/// skipped, which contributes 0 to the exit code: the crash disappears. +pub fn background_todo_never_skips_the_test_test() { + let #(invocation, reports) = + runner.run_in_process("helpers", "todo_in_inline_worker", 5000, True) + assert invocation == outcome.Passed + let assert outcome.Todo(p) = + outcome.with_crash_reports( + outcome.Pass, + "helpers", + "todo_in_inline_worker", + reports, + ) + assert p.module == "helpers" + assert p.function == "todo_in_inline_worker" +} + +@target(erlang) +/// The default path for the same worker: it is still alive when the test +/// ends, so it is killed there and recorded as a leak. Nothing survives to +/// crash late, so the unattributed table — which the two tests above have +/// to disable killing to reach at all — stays empty. The leak names what +/// started the process: a Gleam closure reaches the trace as erlang:apply +/// over a fun, and only fun_info recovers the function it was written in. +pub fn leaked_process_is_killed_and_recorded_test() { + let #(invocation, reports) = + runner.run_in_process("helpers", "leaks_a_doomed_worker", 5000, True) + assert invocation == outcome.Passed + assert reports == [] + let assert [#(test_module, test_function, leak)] = + runner.take_leaks_matching("leaks_a_doomed_worker") + assert test_module == "helpers" + assert test_function == "leaks_a_doomed_worker" + assert leak + == outcome.ProcessLeak( + module: "helpers", + function: "leaks_a_doomed_worker", + arity: 0, + ) + // The worker panics 60ms in. Well past that, nothing has arrived: it was + // killed before it could get there, which is what makes this a kill and + // not merely a report. + sleep_ms(300) + assert await_unattributed("doomed worker was not killed", 0) == [] +} + +@target(erlang) +/// A named spawn — not a closure — is reported by its own module and +/// function, straight from the trace's MFA with no fun_info involved. +pub fn leak_from_named_spawn_is_recorded_test() { + let #(invocation, _) = + runner.run_in_process("helpers", "leaks_named_worker", 5000, True) + assert invocation == outcome.Passed + let assert [#(_, _, leak)] = runner.take_leaks_matching("sleeps_a_long_time") + assert leak + == outcome.ProcessLeak( + module: "helpers", + function: "sleeps_a_long_time", + arity: 1, + ) +} + +@target(erlang) +/// Ancestors die before their children: a supervisor left running is killed +/// first, so it is gone before its child is touched and cannot restart it. +/// Both are reported, the supervisor first — the set is ordered by spawn. +pub fn leaked_supervisor_and_child_are_both_killed_test() { + let #(invocation, _) = + runner.run_in_process("helpers", "leaks_a_supervisor", 5000, True) + assert invocation == outcome.Passed + // The supervising process, and whichever children were live at the claim + // (one or two, depending on how the 20ms restart tick lands). + let assert [#(_, _, parent)] = + runner.take_leaks_matching("leaks_a_supervisor") + assert parent.function == "leaks_a_supervisor" + let children = runner.take_leaks_matching("supervise") + assert list.length(children) >= 1 + // Past the children's 60ms fuse and several restart ticks: nothing was + // restarted and nothing crashed, so the parent died before its children. + sleep_ms(300) + assert await_unattributed("restarted worker crashed", 0) == [] +} + +@target(erlang) +/// The suite's own scaffolding is not a leak. A nested run — a test that +/// runs a test — spawns the inner test process, its collector and, in +/// parallel mode, a middleman inside the outer test's traced tree. Reporting +/// or killing those would be vouch charging the user for its own plumbing. +pub fn vouch_scaffolding_is_not_reported_as_a_leak_test() { + let #(invocation, _) = + runner.run_in_process("helpers", "runs_a_nested_test", 5000, True) + assert invocation == outcome.Passed + assert runner.take_leaks_matching("vouch_ffi") == [] + assert runner.take_leaks_matching("collect_crashes") == [] } @target(erlang) @@ -253,7 +388,7 @@ fn sleep_ms(ms: Int) -> Nil /// death is that inner run's business, not this test's. pub fn otp_wrapped_todo_is_todo_outcome_test() { let #(invocation, _reports) = - runner.run_in_process("vouch_otp_fixture", "call_into_todo", 5000) + runner.run_in_process("vouch_otp_fixture", "call_into_todo", 5000, True) let assert outcome.Todo(p) = outcome.classify( "vouch_test", @@ -268,11 +403,11 @@ pub fn otp_wrapped_todo_is_todo_outcome_test() { pub fn isolated_pass_and_panic_test() { // failing_result returns an Error value, which is still a *passing* test — // only panics fail. - assert runner.run_in_process("helpers", "failing_result", 5000) + assert runner.run_in_process("helpers", "failing_result", 5000, True) == #(outcome.Passed, []) // A panic caught inside the test process is not a crash: no report. let assert #(outcome.Panicked(raw), []) = - runner.run_in_process("helpers", "panics", 5000) + runner.run_in_process("helpers", "panics", 5000, True) let assert Ok(p) = gleam_panic.from_dynamic(raw) assert p.message == "helper panicked" } @@ -284,8 +419,8 @@ pub fn isolated_pass_and_panic_test() { /// while staying unambiguous. pub fn parallel_tests_overlap_test() { let t0 = monotonic_microseconds() - let a = runner.start_test("helpers", "sleeps_briefly", 5000) - let b = runner.start_test("helpers", "sleeps_briefly", 5000) + let a = runner.start_test("helpers", "sleeps_briefly", 5000, True) + let b = runner.start_test("helpers", "sleeps_briefly", 5000, True) let assert #(invocation_a, [], duration_a) = runner.await_test(a) let assert #(invocation_b, [], duration_b) = runner.await_test(b) let elapsed_ms = { monotonic_microseconds() - t0 } / 1000 @@ -300,7 +435,7 @@ pub fn parallel_tests_overlap_test() { /// The parallel path must keep per-test timeout semantics: a started test /// that outlives its timeout comes back TimedOut from await. pub fn parallel_test_times_out_test() { - let handle = runner.start_test("helpers", "sleeps_forever", 100) + let handle = runner.start_test("helpers", "sleeps_forever", 100, True) let #(invocation, _, _) = runner.await_test(handle) assert invocation == outcome.TimedOut(100) } @@ -345,7 +480,7 @@ pub fn undef_crash_carries_call_site_test() { /// the call site rather than dumping raw frames. pub fn linked_undef_crash_names_call_site_test() { let #(invocation, reports) = - runner.run_in_process("helpers", "crashes_linked_undef", 5000) + runner.run_in_process("helpers", "crashes_linked_undef", 5000, True) let assert outcome.Failed(outcome.ExitDetail(reason, Some(site))) = outcome.classify( "vouch_test", @@ -677,6 +812,7 @@ pub fn config_defaults_test() { color: config.Auto, parallel: config.Sequential, show_crash_reports: False, + kill_leaked_processes: True, )) } @@ -690,6 +826,7 @@ pub fn config_format_and_filter_test() { color: config.Auto, parallel: config.Sequential, show_crash_reports: False, + kill_leaked_processes: True, )) assert config.from_args([ "--filter=decode", @@ -704,6 +841,7 @@ pub fn config_format_and_filter_test() { color: config.Auto, parallel: config.Sequential, show_crash_reports: False, + kill_leaked_processes: True, )) } @@ -738,6 +876,15 @@ pub fn config_show_crash_reports_test() { let assert Error(_) = config.from_args(["--show-crash-reports=yes"]) } +/// Killing leaked processes is the default; the flag only turns it off. +pub fn config_keep_leaked_processes_test() { + let assert Ok(config.Config(kill_leaked_processes: True, ..)) = + config.from_args([]) + let assert Ok(config.Config(kill_leaked_processes: False, ..)) = + config.from_args(["--keep-leaked-processes"]) + let assert Error(_) = config.from_args(["--keep-leaked-processes=no"]) +} + pub fn config_color_test() { let assert Ok(config.Config(color: config.Never, ..)) = config.from_args(["--color=never"]) From fd80de9b948903cd89fa63d4d89e561b8ddf9b41 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Sat, 22 Aug 2026 01:48:05 +0100 Subject: [PATCH 6/8] Skip the leak sweep when a test leaked nothing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit kill_leaked ran on every test, so a test that cleaned up after itself still paid two collector round-trips and a second node-wide trace_delivered/1. Measured on a 2000-trivial-test suite that leaks nothing, that was 215ms -> 283ms, about 35us per test spent proving there was nothing to do. The claim already computes the live set, so both sides can gate on it: the collector stops immediately when nothing outlived the test, and claim_crashes skips the kill rounds. Nothing can appear afterwards — the test sends its result as its last act, so with no live descendant there is no one left to spawn. Both sides ask through live_pids/leaks_of, which filter alike, so they cannot disagree about emptiness. Same suite after: 184ms sequential, 196ms parallel, against 198ms and 200ms for the branch without any of the leak work — within noise. The sweep and kill only cost anything when there is something to sweep. Co-Authored-By: Claude Opus 5 --- src/vouch_ffi.erl | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index f8628e6..ea513f9 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -430,9 +430,15 @@ collect_crashes(TestPid, TestName, Acc, Live) -> note_spawn(Child, MFA, Live)); {claim, From, Ref, Kill} -> From ! {crashes, Ref, lists:reverse(Acc), leaks_of(Live)}, - case Kill of - true -> sweep_leaks(TestPid, TestName, Live); - false -> forward_crashes(TestPid, TestName) + case {Kill, live_pids(Live)} of + %% Nothing outlived the test — the overwhelming majority — + %% so there is nothing to sweep and nothing that can spawn + %% later: the collector stops here, and claim_crashes skips + %% the kill rounds. Both sides must agree on emptiness, so + %% both ask live_pids/leaks_of, which filter alike. + {true, []} -> ok; + {true, _} -> sweep_leaks(TestPid, TestName, Live); + {false, _} -> forward_crashes(TestPid, TestName) end; _Other -> collect_crashes(TestPid, TestName, Acc, Live) @@ -572,9 +578,12 @@ claim_crashes(Collector, KillLeaked) -> Collector ! {claim, self(), Ref, KillLeaked}, {Reasons, Leaks} = receive {crashes, Ref, Rs, Ls} -> {Rs, Ls} after 5000 -> {[], []} end, - case KillLeaked of - true -> kill_leaked(Collector); - false -> ok + %% No leaks means no sweep, no kill and no second trace flush: a test + %% that cleaned up after itself pays nothing for this beyond the claim + %% it was already making. The collector has already stopped itself. + case {KillLeaked, Leaks} of + {true, [_ | _]} -> kill_leaked(Collector); + _ -> ok end, {reasons_to_reports(Reasons), Leaks}. From 3fd33949614572e713c16b82811bd4090eecd0c6 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Sat, 22 Aug 2026 01:58:27 +0100 Subject: [PATCH 7/8] Update CHANGELOG.md --- CHANGELOG.md | 54 +++------------------------------------------------- 1 file changed, 3 insertions(+), 51 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3b83d21..24decb8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,62 +2,14 @@ ## Unreleased -Crash reports now name what was being called. A test that dies with a -non-Gleam error (an undef from a stale or missing .beam, an FFI crash) -previously reported only the bare reason — "Crashed: Undef" — with the -failing call discarded. The stacktrace's top frame is now carried into the -report on the Erlang target: - - Crashed: Undef calling config_parser:parse/1 - -with an `at file:line` line when the frame carries one. The same site -reaches the TeamCity and JUnit failure messages, and the JSONL stream as -structured `site_module` / `site_function` / `site_arity` (plus -`site_file` / `site_line` when known) fields. JavaScript crashes are -unchanged: a JS stacktrace is an unparsed string, so there is no site to -extract. - -A process that crashes behind a test now fails it. On the Erlang target, an -unlinked worker, a fire-and-forget job, an actor nothing is monitoring — -anything a test starts that dies without taking the test down — used to -leave the test passing and the run green (as it still does under gleeunit), -with the BEAM's crash report on stderr as the only trace. vouch now traces -each test's process tree, so a process it started that crashes is caught -and charged to that exact test — in a `--parallel` run as much as a -sequential one. The test fails: +A process that crashes now fails the test: playground_test.background_job_test Background process crashed at src/playground.gleam:26 background job crashed: queue is full -or is a todo, when the process died of a `todo`. A test that failed on its -own keeps its own failure. A crash from a process that outlived its test, -or that no test started, is reported at the end and fails the run. The -JSONL stream carries it as `"kind":"background_crash"` with the cause -nested under `cause`; JUnit and TeamCity get a `background_crash` failure -with the same text. The BEAM's own crash reports are kept off the output -streams; the new `--show-crash-reports` flag prints them in full as one -block on stderr after the summary. Other logger output (a library's -warnings) is not a crash and still goes to stderr. JavaScript is -unaffected: there are no processes to crash behind a test there. - -Processes a test leaves running are now killed and reported. Nothing in the -BEAM tears down a test's process tree when the test ends, and a `normal` -exit does not kill a linked child, so a worker a test started kept running -into later tests and could crash long after its own test had been reported. -On the Erlang target the per-test trace now also names every process the -test started that is still alive when it ends. Those are killed there — -ancestors first, so a process restarting its children is gone before they -are touched — and listed after the summary: - - vouch: 1 leaked process killed after the test that started them: - vouch: playground_test.leaky_worker_test left playground:start_long_worker/0 running - -A leak does not fail the run. `--keep-leaked-processes` leaves them running -and only reports them, for a suite that deliberately shares a process across -tests or where a leaked process is linked to something outside the test's -tree. Processes started through an already-running supervisor or -`application:start` are spawned outside the test's tree and are unaffected. +There is also a process leak detector. This doesn't fail the +run, and `--keep-leaked-processes` leaves them running instead. ## v1.2.0 From e20b46cf90778dc409533d64060270f5208a81f1 Mon Sep 17 00:00:00 2001 From: Richard Cocks <50965970+richardcocks@users.noreply.github.com> Date: Sat, 22 Aug 2026 02:00:14 +0100 Subject: [PATCH 8/8] Update README.md --- README.md | 45 +++++++-------------------------------------- 1 file changed, 7 insertions(+), 38 deletions(-) diff --git a/README.md b/README.md index 7998ba0..3af5448 100644 --- a/README.md +++ b/README.md @@ -91,49 +91,18 @@ On Deno, watch mode also needs `allow_run = ["gleam"]` to spawn the inner runs ( ## Crash reports -On the Erlang target, a process that dies *with* a test (a linked process crashing, an actor -the test is calling hitting a `todo`) is reported through the test's own outcome. A process -that dies *behind* a test — an unlinked worker, a fire-and-forget job nothing is monitoring — -would leave the test passing (this is what gleeunit does), with the BEAM's crash report as the -only trace. vouch traces each test's process tree, so a process it started that crashes is -caught and charged to that test, and the test fails: +A process that crashes fails the test: -``` - playground_test.background_job_test - Background process crashed at src/playground.gleam:26 - background job crashed: queue is full -``` + playground_test.background_job_test + Background process crashed at src/playground.gleam:26 + background job crashed: queue is full -If the process died of a `todo`, the test is a todo instead. A crash from a process that -outlived its test, or that no test started, is reported at the end and fails the run. The -BEAM's own crash reports are kept off the output streams (they used to interleave with it on -stderr); pass `--show-crash-reports` to print them in full as one block after the summary. -Other logger output (a library's warnings) is not a crash and still goes to stderr. ## Leaked processes -Process-per-test isolates the test *function*, not everything it spawns: nothing in the BEAM -tears down a test's process tree, and a `normal` exit does not kill a linked child, so a worker -a test starts keeps running until it stops on its own — during later tests, and past the point -where its own test was reported. - -On the Erlang target vouch closes that: the same trace that catches background crashes also -names every process a test started that is still alive when the test ends. Those are killed -there — ancestors first, so a process restarting its children is gone before they are touched — -and listed after the summary, named by the test that leaked them and by what started them: - -``` -vouch: 1 leaked process killed after the test that started them: -vouch: playground_test.leaky_worker_test left playground:start_long_worker/0 running -``` - -A leak does not fail the run. The process was cleaned up before it could reach another test, -and the report is what stops that being silent. Pass `--keep-leaked-processes` to leave them -running and only report them — you need it for a suite that deliberately shares a process -across tests, or where a leaked process is linked to something outside the test's tree, since -killing it would propagate along that link. What a test starts through an already-running -supervisor or `application:start` is spawned elsewhere and is never in the test's tree, so it -is neither reported nor killed. +There is a process leak detector. This does not fail the run. +You can keep leaked processes alive by passing `--keep-leaked-processes` and they will be left running. +They will still be reported in the summary. ## Target differences