diff --git a/CHANGELOG.md b/CHANGELOG.md index c28e7c1..24decb8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,16 @@ # Changelog +## Unreleased + +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 + +There is also a process leak detector. This doesn't fail the +run, and `--keep-leaked-processes` leaves them running instead. + ## 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..3af5448 100644 --- a/README.md +++ b/README.md @@ -52,6 +52,8 @@ 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 -- --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 ``` @@ -83,13 +85,29 @@ 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 + +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 + + +## Leaked processes + +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 -Erlang target supports `--parallel` and `--timeout=n` +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 f91cc9d..538e1ed 100644 --- a/docs/chapters/architecture.typ +++ b/docs/chapters/architecture.typ @@ -63,9 +63,10 @@ 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, 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], [`erlang:halt/1`], [`process.exit` / `Deno.exit`], diff --git a/docs/chapters/execution.typ b/docs/chapters/execution.typ index 2adc572..222cfe7 100644 --- a/docs/chapters/execution.typ +++ b/docs/chapters/execution.typ @@ -23,17 +23,59 @@ 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.) - -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. +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.) + +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/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 bf149f3..3689a71 100644 --- a/examples/playground/src/playground.gleam +++ b/examples/playground/src/playground.gleam @@ -16,3 +16,33 @@ pub fn rate_limit(_requests: Int) -> Bool { @external(erlang, "playground_ffi", "sleep") @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. 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" }) +} + +/// 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 + +/// 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.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 4e7f967..5ebd3cf 100644 --- a/examples/playground/src/playground_ffi.mjs +++ b/examples/playground/src/playground_ffi.mjs @@ -5,3 +5,15 @@ export function sleep(ms) { // spin } } + +// 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 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 +// 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..eb4bc83 100644 --- a/examples/playground/test/playground_test.gleam +++ b/examples/playground/test/playground_test.gleam @@ -1,10 +1,19 @@ //// 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 - 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 //// 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 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 @@ -17,6 +26,29 @@ pub fn fast_pass_test() { assert playground.add(1, 2) == 3 } +/// 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 +} + +/// 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) @@ -35,6 +67,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..d3f4eff 100644 --- a/src/vouch.gleam +++ b/src/vouch.gleam @@ -54,6 +54,8 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.Console, Some(path) -> runner.run( @@ -64,15 +66,26 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, + cfg.kill_leaked_processes, ) 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, + cfg.kill_leaked_processes, + ) config.Json, Some(path) -> runner.run( reporter.pair(jsonl.reporter(), junit.reporter(path)), cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.TeamCity, None -> runner.run( @@ -80,6 +93,8 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, cfg.timeout_ms, cfg.parallel, + cfg.show_crash_reports, + cfg.kill_leaked_processes, ) config.TeamCity, Some(path) -> runner.run( @@ -87,6 +102,8 @@ fn run_tests(args: List(String)) -> Nil { cfg.filter, 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 930b124..54b5717 100644 --- a/src/vouch/internal/config.gleam +++ b/src/vouch/internal/config.gleam @@ -34,6 +34,18 @@ pub type Config { timeout_ms: Int, color: ColorChoice, parallel: Parallelism, + /// 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, + /// 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, ) } @@ -49,6 +61,8 @@ pub fn from_args(args: List(String)) -> Result(Config, String) { timeout_ms: default_timeout_ms, color: Auto, parallel: Sequential, + show_crash_reports: False, + kill_leaked_processes: True, ), ) } @@ -90,6 +104,10 @@ 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)) + ["--keep-leaked-processes", ..rest] -> + parse(rest, Config(..config, kill_leaked_processes: False)) [arg, ..] -> case string.starts_with(arg, "-") { True -> Error(usage("unknown option: " <> arg)) @@ -131,6 +149,13 @@ 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" + <> " 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/describe.gleam b/src/vouch/internal/describe.gleam index a5881cd..86759b6 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,66 @@ 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) + ] + 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. +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..0b16997 100644 --- a/src/vouch/internal/outcome.gleam +++ b/src/vouch/internal/outcome.gleam @@ -6,6 +6,8 @@ //// 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} /// How a test invocation ended. On the Erlang target tests run in their own @@ -30,15 +32,64 @@ 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)) + /// 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) } +/// 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) +} + +/// 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. +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 +109,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 +120,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)) + } } } } @@ -85,3 +142,58 @@ 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)) + // 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) + 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 3d93927..23be4d2 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,21 +80,48 @@ 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)) + // 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)))), ] } } +/// 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)), + ]) + } + } + } +} + fn kind_fields(p: GleamPanic) -> List(#(String, json.Value)) { case p.kind { gleam_panic.Panic -> [#("kind", Str("panic"))] diff --git a/src/vouch/internal/report/junit.gleam b/src/vouch/internal/report/junit.gleam index 71b4ba8..cfd47ce 100644 --- a/src/vouch/internal/report/junit.gleam +++ b/src/vouch/internal/report/junit.gleam @@ -119,21 +119,28 @@ 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" + 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 cf62f60..1421a49 100644 --- a/src/vouch/internal/report/teamcity.gleam +++ b/src/vouch/internal/report/teamcity.gleam @@ -116,11 +116,18 @@ 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)) + 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 1d380fd..1a75c60 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,10 +63,117 @@ fn finish( state: s, 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)) - halt(exit_code(t)) + 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 + } + case unattributed { + [] -> halt(exit_code(t)) + // A crash no outcome accounts for must not hide behind a green run. + _ -> halt(1) + } +} + +/// Crash reports no test claimed: the process died after its test had +/// 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 { + case reports { + [] -> Nil + _ -> { + term.warn( + 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) + }) + } + } +} + +/// 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. +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. @@ -112,10 +221,21 @@ pub fn run( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, + kill_leaked: 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, + kill_leaked, + ) + JavaScript -> + run_js(rep, filter, timeout_ms, parallel, show_crash_reports, kill_leaked) } } @@ -127,8 +247,10 @@ fn run_beam( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { - redirect_diagnostics_to_stderr() + capture_diagnostics() let started = now_microseconds() let candidates = find_test_files() @@ -155,10 +277,17 @@ 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, state, list.reverse(outcomes), now_microseconds() - started) + finish( + rep, + state, + list.reverse(outcomes), + now_microseconds() - started, + show_crash_reports, + kill_leaked, + ) } fn workers(parallel: config.Parallelism) -> Int { @@ -174,15 +303,19 @@ 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 = 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) + 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]) @@ -204,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, @@ -219,14 +353,17 @@ fn run_window( outcomes, timeout_ms, workers, + kill_leaked, ) } _ -> 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( @@ -238,15 +375,63 @@ fn run_window( [out, ..outcomes], timeout_ms, workers, + kill_leaked, ) } } } } -@external(erlang, "vouch_ffi", "redirect_diagnostics_to_stderr") -@external(javascript, "../../vouch_ffi.mjs", "redirect_diagnostics_to_stderr") -fn redirect_diagnostics_to_stderr() -> Nil +/// 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 + +/// 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)))) + +/// 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 +/// 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) + +/// 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 @@ -263,34 +448,41 @@ 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 + kill_leaked: Bool, +) -> #(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( module: String, function: String, timeout_ms: Int, + kill_leaked: Bool, ) -> TestHandle @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") @@ -302,13 +494,30 @@ 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, + 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 -> + 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 +539,15 @@ fn run_js( filter: Option(String), timeout_ms: Int, parallel: config.Parallelism, + show_crash_reports: Bool, + kill_leaked: Bool, ) -> Nil { - warn_ineffective_js_flags(timeout_ms, parallel) + warn_ineffective_js_flags( + timeout_ms, + parallel, + show_crash_reports, + kill_leaked, + ) let started = now_microseconds() js_run_tests( #(rep.init, [], 0), @@ -354,7 +570,14 @@ 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, + kill_leaked, + ) }, ) } diff --git a/src/vouch_ffi.erl b/src/vouch_ffi.erl index b2cc7ca..ea513f9 100644 --- a/src/vouch_ffi.erl +++ b/src/vouch_ffi.erl @@ -2,13 +2,29 @@ -export([ find_test_files/0, exported_zero_arity/1, - run_test/3, + run_test/4, 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, + all_diagnostics/0, + unattributed_diagnostics/0, + take_diagnostics_matching/1, + take_unattributed_matching/1, + leaked_processes/0, + take_leaks_matching/1, + crash_filter/2, + log/2, + %% 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, @@ -20,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, @@ -71,14 +87,210 @@ 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. -%% 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 +%% 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. + ok; + _ -> + case logger:get_handler_config(default) of + {ok, #{formatter := Formatter}} -> + 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 divert. + ok + end + end, + nil. + +%% 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. +%% 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_leaks, [named_table, public, ordered_set]); + _ -> + 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. Renders the +%% event with the default handler's formatter and stores the text. Must +%% never raise: logger removes a handler whose callback crashes. +log(Event, Config) -> + catch ets:insert(vouch_crash_texts, + {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. + +%% 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, Text} <- table(vouch_crash_texts)]. + +%% 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() -> + [{reason_text(Reason), TestName} + || {_Key, Reason, TestName} <- table(vouch_unattributed)]. + +reason_text(Reason) -> + unicode:characters_to_binary(io_lib:format("~0tp", [Reason])). + +%% 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_crash_texts, Key), + Text + end + || {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]. + +%% 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; + _ -> [] + end. + +%% 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() -> + 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 +%% 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} -> NewCfg0 = Cfg#{config := HConfig#{type => standard_error}}, NewCfg = maps:remove(id, maps:remove(module, NewCfg0)), @@ -95,8 +307,7 @@ redirect_diagnostics_to_stderr() -> end; _ -> ok - end, - nil. + end. %% Paths of .gleam files under test/, relative to test/. find_test_files() -> @@ -119,16 +330,47 @@ 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. -run_test(ModuleName, FunctionName, TimeoutMs) -> +%% that outlives the timeout is killed. Returns {Invocation, CrashReports}: +%% 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. +%% +%% 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). +%% +%% 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(), + %% Spawned suspended on a `go` message so tracing is in place before the + %% test can start any worker. {Pid, Ref} = spawn_monitor(fun() -> + receive go -> ok end, Self ! {vouch_result, self(), catch_panic(fun() -> Module:Function() end)} end), - receive + 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]), passed; @@ -147,49 +389,319 @@ run_test(ModuleName, FunctionName, TimeoutMs) -> after 0 -> ok end, {timed_out, TimeoutMs} + end, + {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, +%% 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, Live) -> + receive + {trace, TestPid, 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, 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, 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) + 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; + _Other -> + sweep_leaks(TestPid, TestName, Live) + after 200 -> + 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} -> + 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/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, + %% 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}. + +%% 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 ! {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 +%% 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 -%% 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. -start_test(Module, Function, TimeoutMs) -> +%% 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, KillLeaked) -> 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, KillLeaked), 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() -> 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..a8ed2f9 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,37 @@ 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 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(); +} + +export function take_diagnostics_matching(_marker) { + erlangOnly("take_diagnostics_matching"); +} + +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() { @@ -365,6 +395,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..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 } @@ -66,10 +69,156 @@ 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) +/// 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 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(30) + panic as "late crash in background process" + }) +} + +@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 +@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_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 6039c7a..a2a495b 100644 --- a/test/vouch_e2e_test.gleam +++ b/test/vouch_e2e_test.gleam @@ -18,10 +18,27 @@ 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\":3,\"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\"") + 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. @@ -44,10 +61,14 @@ 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\":2,\"failed\":3,\"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\"") } @target(erlang) @@ -63,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\":4,\"todo\":2,\"skipped\":1", + "\"event\":\"run_end\",\"passed\":2,\"failed\":6,\"todo\":2,\"skipped\":1", ) } @@ -80,9 +101,90 @@ 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\":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 + // 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'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( + "gleam", + ["test", "--", "--color=never"], + "examples/playground", + ) + 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( + "gleam", + ["test", "--", "--color=never", "--show-crash-reports"], + "examples/playground", + ) + assert string.contains( + shown, + "vouch: 1 crash report captured during the run:", + ) + // The raw report, after the summary, not interleaved with the results. + let assert Ok(#(_, after_summary)) = + 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) @@ -92,3 +194,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) diff --git a/test/vouch_helpers_ffi.erl b/test/vouch_helpers_ffi.erl new file mode 100644 index 0000000..2e53c86 --- /dev/null +++ b/test/vouch_helpers_ffi.erl @@ -0,0 +1,20 @@ +%% Test-only helper for the background-crash fixtures in helpers.gleam. +-module(vouch_helpers_ffi). +-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 +%% 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. + +%% 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 2dc26b3..35816f8 100644 --- a/test/vouch_test.gleam +++ b/test/vouch_test.gleam @@ -127,24 +127,268 @@ 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, True) 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, 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" + // 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", + "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, True) + 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, True) + 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, True) + 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: 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. 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, + 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) +/// 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_unattributed(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 -/// 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, True) let assert outcome.Todo(p) = outcome.classify( "vouch_test", @@ -155,18 +399,15 @@ pub fn otp_wrapped_todo_is_todo_outcome_test() { assert p.function == "unimplemented" } -@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 — // only panics fail. - assert runner.run_in_process("helpers", "failing_result", 5000) - == outcome.Passed - let assert outcome.Panicked(raw) = - runner.run_in_process("helpers", "panics", 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, True) let assert Ok(p) = gleam_panic.from_dynamic(raw) assert p.message == "helper panicked" } @@ -178,10 +419,10 @@ 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 #(invocation_a, duration_a) = runner.await_test(a) - let #(invocation_b, duration_b) = runner.await_test(b) + 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 assert invocation_a == outcome.Passed assert invocation_b == outcome.Passed @@ -194,8 +435,8 @@ 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 #(invocation, _) = runner.await_test(handle) + let handle = runner.start_test("helpers", "sleeps_forever", 100, True) + let #(invocation, _, _) = runner.await_test(handle) assert invocation == outcome.TimedOut(100) } @@ -203,6 +444,109 @@ 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, reports) = + runner.run_in_process("helpers", "crashes_linked_undef", 5000, True) + 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 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) +/// 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 +811,8 @@ pub fn config_defaults_test() { timeout_ms: config.default_timeout_ms, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, + kill_leaked_processes: True, )) } @@ -479,6 +825,8 @@ pub fn config_format_and_filter_test() { timeout_ms: config.default_timeout_ms, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, + kill_leaked_processes: True, )) assert config.from_args([ "--filter=decode", @@ -492,6 +840,8 @@ pub fn config_format_and_filter_test() { timeout_ms: 250, color: config.Auto, parallel: config.Sequential, + show_crash_reports: False, + kill_leaked_processes: True, )) } @@ -519,6 +869,22 @@ 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"]) +} + +/// 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"]) @@ -793,3 +1159,152 @@ 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") +} + +// --- 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")) + 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") +}