From 431fad7d9b0d0e7c35bfd02784cfd562e20b8f24 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 31 Aug 2026 19:25:07 +0000 Subject: [PATCH 1/5] Initial plan From b0a764d843fab2cf3f433af7cd8d12cbef52afea Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 31 Aug 2026 19:25:54 +0000 Subject: [PATCH 2/5] Add timeout 30 to perf stat capability probe scripts in metadata.go Co-authored-by: romirdes <86635949+romirdes@users.noreply.github.com> --- cmd/metrics/metadata.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/cmd/metrics/metadata.go b/cmd/metrics/metadata.go index fd5a3cf7..d47a6ce1 100644 --- a/cmd/metrics/metadata.go +++ b/cmd/metrics/metadata.go @@ -226,52 +226,52 @@ BEGIN { }, { Name: scriptPerfStatInstructions, - ScriptTemplate: "perf stat -a -e instructions sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e instructions sleep 1", Depends: []string{"perf"}, }, { Name: scriptPerfStatRefCycles, - ScriptTemplate: "perf stat -a -e ref-cycles sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e ref-cycles sleep 1", Depends: []string{"perf"}, }, { Name: scriptPerfStatPEBS, - ScriptTemplate: "perf stat -a -e INT_MISC.UNKNOWN_BRANCH_CYCLES sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e INT_MISC.UNKNOWN_BRANCH_CYCLES sleep 1", Architectures: []string{cpus.X86Architecture}, Depends: []string{"perf"}, }, { Name: scriptPerfStatOCR, - ScriptTemplate: "perf stat -a -e OCR.READS_TO_CORE.LOCAL_DRAM sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e OCR.READS_TO_CORE.LOCAL_DRAM sleep 1", Architectures: []string{cpus.X86Architecture}, Depends: []string{"perf"}, }, { Name: scriptPerfStatTMA, - ScriptTemplate: "perf stat -a -e '{topdown.slots, topdown-bad-spec}' sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e '{topdown.slots, topdown-bad-spec}' sleep 1", Architectures: []string{cpus.X86Architecture}, Depends: []string{"perf"}, }, { Name: scriptPerfStatAMDUncoreProbe, - ScriptTemplate: `perf stat -a -e "l3/event=0x4,umask=0xff,enallcores=0x1,enallslices=0x1,threadmask=0x3,name='l3_lookup_state.all_coherent_accesses_to_l3'/" sleep 1`, + ScriptTemplate: `timeout 30 perf stat -a -e "l3/event=0x4,umask=0xff,enallcores=0x1,enallslices=0x1,threadmask=0x3,name='l3_lookup_state.all_coherent_accesses_to_l3'/" sleep 1`, Architectures: []string{cpus.X86Architecture}, Vendors: []string{cpus.AMDVendor}, Depends: []string{"perf"}, }, { Name: scriptPerfStatFixedInstr, - ScriptTemplate: "perf stat -a -e '{{{.InstructionsList}}}' sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e '{{{.InstructionsList}}}' sleep 1", Depends: []string{"perf"}, }, { Name: scriptPerfStatFixedCycles, - ScriptTemplate: "perf stat -a -e '{{{.CpuCyclesList}}}' sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e '{{{.CpuCyclesList}}}' sleep 1", Depends: []string{"perf"}, }, { Name: scriptPerfStatFixedRefCycles, - ScriptTemplate: "perf stat -a -e '{{{.RefCyclesList}}}' sleep 1", + ScriptTemplate: "timeout 30 perf stat -a -e '{{{.RefCyclesList}}}' sleep 1", Depends: []string{"perf"}, }, { From 5b85a8dc40a198b5066019fe4009b4f9b479166b Mon Sep 17 00:00:00 2001 From: romirdes Date: Mon, 31 Aug 2026 13:46:20 -0700 Subject: [PATCH 3/5] Add timeout 30 to perf list --json probe scripts to prevent hang on large virtualized instances perf list --json can also stall indefinitely on some hypervisors (e.g. m6i.16xlarge), just like perf stat. The stderr.txt from the failing test showed PerfSpect was stuck at "collecting metadata", and perf list is the remaining unguarded perf command in that stage. Wrap both scriptPerfSupportedEvents and scriptPerfAllSupportedEvents with timeout 30 to bound them consistently with the perf stat probes. --- cmd/metrics/metadata.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cmd/metrics/metadata.go b/cmd/metrics/metadata.go index d47a6ce1..1a5deb7f 100644 --- a/cmd/metrics/metadata.go +++ b/cmd/metrics/metadata.go @@ -147,7 +147,7 @@ var baseMetadataScripts = []script.ScriptDefinition{ { Name: scriptPerfSupportedEvents, ScriptTemplate: `# Parse perf list JSON output to extract Hardware events and cstate/power events -perf list --json 2>/dev/null | awk ' +timeout 30 perf list --json 2>/dev/null | awk ' BEGIN { in_hardware_event = 0 event_name = "" @@ -192,7 +192,7 @@ BEGIN { { Name: scriptPerfAllSupportedEvents, ScriptTemplate: `# Parse perf list JSON output to extract Hardware events and cstate/power events -perf list --json 2>/dev/null | awk ' +timeout 30 perf list --json 2>/dev/null | awk ' BEGIN { event_name = "" } From 2e4d66fdbd91ce2e2e3ddda613c3f8d637fb1892 Mon Sep 17 00:00:00 2001 From: romirdes Date: Wed, 2 Sep 2026 15:26:09 -0700 Subject: [PATCH 4/5] fix: bound metadata script execution with a per-script watchdog Metrics collection could stall indefinitely during the "collecting metadata" phase. Nothing in the chain bounded it: RunScripts launches the controller script with no timeout, and the controller's `wait` blocks forever on a script that never exits. A single wedged probe therefore hung the whole run. Wrapping the inner command in `timeout` does not fix this. Each script runs under setsid and may fork; `timeout` signals only its direct child, so a wedged grandchild -- e.g. a perf stuck on a PMU access, as seen on some virtualized instance types -- survives and the controller keeps waiting on it. Add a Timeout field to ScriptDefinition and have the controller start a per-script watchdog that signals the script's entire process group (SIGTERM, then SIGKILL after a grace period), which reaps wedged descendants. Apply a 60s budget to the metadata probes, which are all short by construction. Scripts with no timeout keep running unbounded, so indefinite-duration collection is unchanged. Also: - Report each script's exit code and elapsed time, plus a stderr tail on failure, so a hanging probe is identifiable from the log instead of presenting as a silent stall. Timeouts are logged even when continuing on script error, where the controller still exits 0. - Reduce kill_script's post-SIGTERM grace from 60s to 5s. Cleanup is serial and perfspect's signal handler only allows ~20s for the whole controller to exit, so the old budget let one hung script drag shutdown far past that deadline. Co-Authored-By: Claude Opus 5 --- cmd/metrics/metadata.go | 16 ++++- internal/script/script.go | 117 +++++++++++++++++++++++++++++++-- internal/script/script_test.go | 101 ++++++++++++++++++++++++++++ internal/script/scripts.go | 1 + 4 files changed, 229 insertions(+), 6 deletions(-) diff --git a/cmd/metrics/metadata.go b/cmd/metrics/metadata.go index 1a5deb7f..06cb2c69 100644 --- a/cmd/metrics/metadata.go +++ b/cmd/metrics/metadata.go @@ -300,8 +300,17 @@ BEGIN { }, } +// metadataScriptTimeout bounds how long any single metadata script may run. +// Metadata collection is a bounded probing phase -- every script here reads a +// sysfs/procfs value, runs a tool, or runs 'perf stat ... sleep 1' -- so none has +// a legitimate reason to run for long. Without a bound, a probe that wedges (e.g. +// a perf event that hangs the PMU on some virtualized instance types) stalls +// collection indefinitely, because the controller waits on it forever. +const metadataScriptTimeout = 60 + // getMetadataScripts returns the list of scripts to run for metadata collection. -// It copies the base definitions and applies template replacements and privilege settings. +// It copies the base definitions and applies template replacements, privilege +// settings, and the metadata script timeout. func getMetadataScripts(noRoot bool, noSystemSummary bool, numGPCounters int) ([]script.ScriptDefinition, error) { metadataScripts := make([]script.ScriptDefinition, 0, len(baseMetadataScripts)) @@ -309,6 +318,7 @@ func getMetadataScripts(noRoot bool, noSystemSummary bool, numGPCounters int) ([ for _, baseDef := range baseMetadataScripts { scriptDef := baseDef scriptDef.Superuser = !noRoot + scriptDef.Timeout = metadataScriptTimeout // Apply template replacements for fixed counter scripts switch scriptDef.Name { @@ -339,6 +349,10 @@ func getMetadataScripts(noRoot bool, noSystemSummary bool, numGPCounters int) ([ if !noSystemSummary { for _, scriptName := range app.TableDefinitions[app.SystemSummaryTableName].ScriptNames { scriptDef := script.GetScriptByName(scriptName) + // Only tighten the budget; never loosen one a script set for itself. + if scriptDef.Timeout == 0 || scriptDef.Timeout > metadataScriptTimeout { + scriptDef.Timeout = metadataScriptTimeout + } metadataScripts = append(metadataScripts, scriptDef) } } diff --git a/internal/script/script.go b/internal/script/script.go index 00bd8091..85f7b8ed 100644 --- a/internal/script/script.go +++ b/internal/script/script.go @@ -148,6 +148,23 @@ func RunScripts(myTarget target.Target, scripts []ScriptDefinition, continueOnSc return nil, fmt.Errorf("controller script returned exit code %d", exitcode) } } + // Surface watchdog timeouts. The controller reports these on stderr and, when + // continuing on script error, still exits 0 -- so without this the fact that a + // script was killed for hanging would not be logged anywhere. + if strings.Contains(stderr, "TIMEOUT:") { + for line := range strings.SplitSeq(stderr, "\n") { + if strings.HasPrefix(line, "TIMEOUT:") { + slog.Warn("script exceeded its timeout and was killed", slog.String("detail", strings.TrimPrefix(line, "TIMEOUT: "))) + } + } + } + // Log per-script exit codes and elapsed times to make a slow or failing script + // identifiable without re-running with extra instrumentation. + for line := range strings.SplitSeq(stderr, "\n") { + if strings.HasPrefix(line, "SCRIPT RESULT:") { + slog.Debug("script result", slog.String("detail", strings.TrimPrefix(line, "SCRIPT RESULT: "))) + } + } // parse output of controller script allScriptOutputs := parseControllerScriptOutput(stdout) for _, scriptOutput := range allScriptOutputs { @@ -220,10 +237,12 @@ func formControllerScript(targetTempDirectory string, concurrentScripts []Script // template that renders the shell controller script. // Primarily carries the sanitized script name used for filenames and // template keys (e.g., ${s}.sh, ${s}.stdout, pids[$s]), while the original - // Name is kept for readable summary output. + // Name is kept for readable summary output. Timeout is the script's + // watchdog budget in seconds; 0 means the script may run indefinitely. type tplScript struct { Name string Sanitized string + Timeout int } // tplData holds all data passed into the controller script template. tplData := struct { @@ -243,7 +262,7 @@ func formControllerScript(targetTempDirectory string, concurrentScripts []Script needsElevated = true } tplData.ConcurrentScripts = append(tplData.ConcurrentScripts, tplScript{ - Name: s.Name, Sanitized: sanitizeScriptName(s.Name), + Name: s.Name, Sanitized: sanitizeScriptName(s.Name), Timeout: s.Timeout, }) } for _, s := range sequentialScripts { @@ -251,7 +270,7 @@ func formControllerScript(targetTempDirectory string, concurrentScripts []Script needsElevated = true } tplData.SequentialScripts = append(tplData.SequentialScripts, tplScript{ - Name: s.Name, Sanitized: sanitizeScriptName(s.Name), + Name: s.Name, Sanitized: sanitizeScriptName(s.Name), Timeout: s.Timeout, }) } // define controller script template @@ -270,6 +289,9 @@ declare -a sequential_scripts=() declare -A pids=() declare -A exitcodes=() declare -A orig_names=() +declare -A timeouts=() +declare -A watchdog_pids=() +declare -A start_times=() current_seq_pid="" current_seq_script="" @@ -287,16 +309,88 @@ ensure_trailing_newline() { {{- range .ConcurrentScripts}} concurrent_scripts+=({{ .Sanitized }}) orig_names[{{ .Sanitized }}]="{{ .Name }}" +timeouts[{{ .Sanitized }}]={{ .Timeout }} {{ end }} {{- range .SequentialScripts}} sequential_scripts+=({{ .Sanitized }}) orig_names[{{ .Sanitized }}]="{{ .Name }}" +timeouts[{{ .Sanitized }}]={{ .Timeout }} {{ end }} +# Grace period between the watchdog's SIGTERM and its follow-up SIGKILL. +readonly WATCHDOG_KILL_AFTER=5 + +# Grace period kill_script allows a script to exit after SIGTERM before it +# escalates to SIGKILL, during signal-triggered cleanup. +readonly KILL_GRACE_SECONDS=5 + +# start_watchdog starts a background timer for a script. Each script runs via +# setsid, so it leads its own process group; the watchdog signals the whole +# group (negative PID). This is what makes the timeout forceful: signalling only +# the script's direct child would leave a wedged grandchild (e.g. a perf stuck in +# the kernel) running, and the controller's 'wait' would block on it forever. +start_watchdog() { + local s="$1" pid="$2" budget="${timeouts[$1]:-0}" + [[ "$budget" -le 0 ]] && return 0 + ( + # Poll rather than 'sleep $budget' so the watchdog exits promptly once the + # script finishes, instead of lingering for the full budget. + local waited=0 + while [[ "$waited" -lt "$budget" ]]; do + ps -p "$pid" > /dev/null 2>&1 || exit 0 + sleep 1 + waited=$((waited + 1)) + done + ps -p "$pid" > /dev/null 2>&1 || exit 0 + echo "TIMEOUT: script '${orig_names[$s]}' exceeded ${budget}s; sending SIGTERM to process group $pid" >&2 + kill -SIGTERM -"$pid" 2>/dev/null || true + local killwait=0 + while ps -p "$pid" > /dev/null 2>&1 && [[ "$killwait" -lt "$WATCHDOG_KILL_AFTER" ]]; do + sleep 1 + killwait=$((killwait + 1)) + done + if ps -p "$pid" > /dev/null 2>&1; then + echo "TIMEOUT: script '${orig_names[$s]}' ignored SIGTERM after ${WATCHDOG_KILL_AFTER}s; sending SIGKILL to process group $pid" >&2 + kill -SIGKILL -"$pid" 2>/dev/null || true + fi + ) & + watchdog_pids[$s]=$! +} + +# stop_watchdog cancels a script's watchdog once the script has exited. +stop_watchdog() { + local s="$1" wpid="${watchdog_pids[$1]:-}" + [[ -z "$wpid" ]] && return 0 + kill -SIGKILL "$wpid" 2>/dev/null || true + wait "$wpid" 2>/dev/null || true + unset 'watchdog_pids[$s]' +} + +# report_script_result logs a script's exit code and elapsed time, and on a +# timeout kill (SIGTERM=143, SIGKILL=137) or generic failure also emits a tail of +# its stderr. This identifies exactly which probe hung, rather than leaving a +# silent stall. +report_script_result() { + local s="$1" ec="$2" + local elapsed=$(( $(date +%s) - ${start_times[$s]:-0} )) + echo "SCRIPT RESULT: '${orig_names[$s]}' exit=$ec elapsed=${elapsed}s" >&2 + if [[ "$ec" -ne 0 ]]; then + if [[ "$ec" -eq 143 || "$ec" -eq 137 ]]; then + echo "SCRIPT RESULT: '${orig_names[$s]}' was killed by the watchdog (likely hung)" >&2 + fi + if [[ -s "$script_dir/${s}.stderr" ]]; then + echo "SCRIPT RESULT: '${orig_names[$s]}' stderr tail:" >&2 + tail -n 20 "$script_dir/${s}.stderr" >&2 || true + fi + fi +} + start_concurrent_scripts() { for s in "${concurrent_scripts[@]}"; do setsid bash "$script_dir/${s}.sh" > "$script_dir/${s}.stdout" 2> "$script_dir/${s}.stderr" & pids[$s]=$! + start_times[$s]=$(date +%s) + start_watchdog "$s" "${pids[$s]}" done } @@ -307,11 +401,17 @@ run_sequential_scripts() { setsid bash "$script_dir/${s}.sh" > "$script_dir/${s}.stdout" 2> "$script_dir/${s}.stderr" & current_seq_pid=$! pids[$s]=$current_seq_pid + start_times[$s]=$(date +%s) + start_watchdog "$s" "$current_seq_pid" if wait "$current_seq_pid"; then exitcodes[$s]=0 + stop_watchdog "$s" + report_script_result "$s" 0 else ec=$? exitcodes[$s]=$ec + stop_watchdog "$s" + report_script_result "$s" "$ec" if [ "$continue_on_script_error" -eq 0 ]; then echo "Script '${orig_names[$s]}' failed with exit code $ec; stopping further sequential scripts." >&2 exit $ec @@ -325,16 +425,21 @@ run_sequential_scripts() { kill_script() { local s="$1" local pid="${pids[$s]:-}" + stop_watchdog "$s" [[ -z "$pid" ]] && return 0 if ! ps -p "$pid" > /dev/null 2>&1; then return 0; fi # Signal the process group (negative PID) # Bash background jobs ignore SIGINT by default, but they do not ignore SIGTERM. echo "Sending SIGTERM to script '${orig_names[$s]}' with PID $pid" >&2 kill -SIGTERM -"$pid" 2>/dev/null || true - # Wait up to 1 minute in 1s intervals + # Wait for the script to exit gracefully, in 1s intervals. + # This budget is per-script and cleanup is serial, so it must stay small: the + # signal handler in perfspect only allows ~20s for the whole controller to exit + # before it escalates to SIGKILL. A long budget here (it was 60s) makes a single + # hung script stall shutdown well past that deadline. local waited=0 echo "Waiting for script '${orig_names[$s]}' with PID $pid to exit gracefully" >&2 - while ps -p "$pid" > /dev/null 2>&1 && [ "$waited" -lt 60 ]; do + while ps -p "$pid" > /dev/null 2>&1 && [ "$waited" -lt "$KILL_GRACE_SECONDS" ]; do echo -n "." >&2 sleep 1 waited=$((waited + 1)) @@ -361,6 +466,8 @@ wait_for_concurrent_scripts() { ec=$? exitcodes[$s]=$ec fi + stop_watchdog "$s" + report_script_result "$s" "${exitcodes[$s]}" done } diff --git a/internal/script/script_test.go b/internal/script/script_test.go index 3a271c03..3329de19 100644 --- a/internal/script/script_test.go +++ b/internal/script/script_test.go @@ -11,6 +11,7 @@ import ( "regexp" "strings" "testing" + "time" "perfspect/internal/target" ) @@ -337,6 +338,106 @@ func TestFormMasterScriptExecutionIntegration(t *testing.T) { } } +// TestFormMasterScriptNoTimeoutRunsToCompletion confirms that a script with +// Timeout unset (0) is left to run without a watchdog, so indefinite-duration +// collection is unaffected. +func TestFormMasterScriptNoTimeoutRunsToCompletion(t *testing.T) { + tmp := t.TempDir() + scripts := []ScriptDefinition{{Name: "untimed", ScriptTemplate: "sleep 2\necho done\n"}} + writeChildScripts(t, tmp, scripts) + master, _, err := formControllerScript(tmp, scripts, nil, true) + if err != nil { + t.Fatalf("error forming master script: %v", err) + } + masterPath := filepath.Join(tmp, "controller.sh") + if err := os.WriteFile(masterPath, []byte(master), 0o700); err != nil { + t.Fatalf("failed writing master script: %v", err) + } + out, err := runLocalBash(masterPath) + if err != nil { + t.Fatalf("error executing master script: %v\noutput: %s", err, out) + } + if strings.Contains(out, "TIMEOUT:") { + t.Errorf("script with no timeout should not be killed by a watchdog:\n%s", out) + } + parsed := parseControllerScriptOutput(out) + if len(parsed) != 1 || parsed[0].Exitcode != 0 { + t.Fatalf("expected one successful script output, got %+v", parsed) + } + if !strings.Contains(parsed[0].Stdout, "done") { + t.Errorf("expected script to run to completion, stdout: %q", parsed[0].Stdout) + } +} + +// TestFormMasterScriptWatchdogKillsHungScript confirms that a script exceeding +// its Timeout has its whole process group killed, and that the controller keeps +// going instead of blocking on it forever. +// +// The hung script leaves a grandchild sleeping and waits on it. That is the shape +// of a wedged probe (e.g. a perf that hangs the PMU), and the case a plain +// 'timeout' wrapped around the inner command does not cover, because signalling +// only the direct child leaves the grandchild -- and therefore the wait -- alive. +func TestFormMasterScriptWatchdogKillsHungScript(t *testing.T) { + tmp := t.TempDir() + scripts := []ScriptDefinition{ + {Name: "hung probe", ScriptTemplate: "sleep 600 &\nwait\n", Timeout: 3}, + {Name: "fast probe", ScriptTemplate: "echo alive\n", Timeout: 3}, + } + writeChildScripts(t, tmp, scripts) + master, _, err := formControllerScript(tmp, scripts, nil, true) + if err != nil { + t.Fatalf("error forming master script: %v", err) + } + masterPath := filepath.Join(tmp, "controller.sh") + if err := os.WriteFile(masterPath, []byte(master), 0o700); err != nil { + t.Fatalf("failed writing master script: %v", err) + } + + start := time.Now() + out, err := runLocalBash(masterPath) + if err != nil { + t.Fatalf("error executing master script: %v\noutput: %s", err, out) + } + elapsed := time.Since(start) + // Without the watchdog the controller waits on the hung script indefinitely. + if elapsed > 30*time.Second { + t.Fatalf("controller did not recover from hung script: took %v", elapsed) + } + + // The timeout must be reported clearly enough to identify which probe hung. + for _, want := range []string{"TIMEOUT:", "exceeded 3s", "killed by the watchdog", "SCRIPT RESULT: 'hung probe'"} { + if !strings.Contains(out, want) { + t.Errorf("missing timeout diagnostic %q in output:\n%s", want, out) + } + } + + byName := make(map[string]ScriptOutput) + for _, p := range parseControllerScriptOutput(out) { + byName[p.Name] = p + } + // The hung script is reported as signal-killed, not as a success. + if ec := byName["hung probe"].Exitcode; ec != 143 && ec != 137 { + t.Errorf("expected hung script to exit via signal (143/137), got %d", ec) + } + // A hung script must not prevent the other scripts' results from being collected. + if got := byName["fast probe"]; got.Exitcode != 0 || !strings.Contains(got.Stdout, "alive") { + t.Errorf("expected fast probe to succeed, got exit=%d stdout=%q", got.Exitcode, got.Stdout) + } +} + +// writeChildScripts writes each script definition's template to the directory +// the controller script expects to find it in. +func writeChildScripts(t *testing.T, dir string, scripts []ScriptDefinition) { + t.Helper() + for _, s := range scripts { + p := filepath.Join(dir, scriptNameToFilename(s.Name)) + content := "#!/usr/bin/env bash\n" + s.ScriptTemplate + if err := os.WriteFile(p, []byte(content), 0o700); err != nil { + t.Fatalf("failed writing child script %s: %v", p, err) + } + } +} + // runLocalBash executes a bash script locally and returns combined stdout. func runLocalBash(scriptPath string) (string, error) { outBytes, err := exec.Command("bash", scriptPath).CombinedOutput() // #nosec G204 diff --git a/internal/script/scripts.go b/internal/script/scripts.go index 036819f7..7be0369d 100644 --- a/internal/script/scripts.go +++ b/internal/script/scripts.go @@ -21,6 +21,7 @@ type ScriptDefinition struct { Depends []string // binary dependencies that must be available for the script to run Superuser bool // requires sudo or root Sequential bool // run script sequentially (not at the same time as others) + Timeout int // maximum seconds the script may run before its process group is killed. 0 means no timeout. } // script names, these must be unique From 6f6d34bc5abb7024124d86cbb5d0e08d1c204f96 Mon Sep 17 00:00:00 2001 From: romirdes Date: Fri, 4 Sep 2026 11:10:23 -0700 Subject: [PATCH 5/5] fix: make a hung metadata script diagnosable instead of silent A probe that hangs during metadata collection produced no information at all: the controller waited on it forever, and RunScripts only reads the controller's output once it exits, so nothing was ever reported. The run appeared to stall in "collecting metadata" until ssh gave up 300 seconds later (ServerAliveInterval 30 x ServerAliveCountMax 10) and returned exit code 255 with empty output, which was then reported without the stderr that would have explained it. Signalling harder does not fix this. A process in uninterruptible sleep (state D) -- the expected shape of a wedged PMU access on a virtualized instance -- does not act on any signal, SIGKILL included, until the kernel call it is blocked in returns. So the controller must stop waiting rather than try harder to kill: - Abandon a script that survives SIGKILL: the watchdog leaves a marker, wait_for_script stops waiting on it, and the run completes with that script reported as ABANDONED. Other scripts' results are still returned. - Capture why it could not be stopped: per-process state and wchan for the whole process group, plus the kernel stack of any process in state D, which names the call it is stuck in. Readable because metadata scripts run elevated. - Announce each script as it starts, so a controller that dies before producing results still identifies which scripts were in flight. - Remove the blocking wait from kill_script for the same reason; it would stall shutdown past the ~20s the perfspect signal handler allows. On the Go side: - Bound the controller run when every script is bounded, deriving the deadline from the script budgets (sequential budgets add, concurrent overlap). This guarantees we regain control even if the target wedges or the connection stops delivering. A single unbounded script, such as indefinite-duration collection, leaves the controller unbounded as before. - Include stderr in the returned error. An ssh transport failure and a script failure both surface as a non-zero exit code, and the distinction is not recoverable from the code alone. - Log the controller's own reporting before deciding whether its exit code is fatal, so a diagnosis survives the failure paths. Co-Authored-By: Claude Opus 5 --- internal/script/script.go | 228 +++++++++++++++++++++++++++++---- internal/script/script_test.go | 161 +++++++++++++++++++++++ 2 files changed, 362 insertions(+), 27 deletions(-) diff --git a/internal/script/script.go b/internal/script/script.go index 85f7b8ed..03151026 100644 --- a/internal/script/script.go +++ b/internal/script/script.go @@ -124,7 +124,15 @@ func RunScripts(myTarget target.Target, scripts []ScriptDefinition, continueOnSc } else { cmd = exec.Command("bash", path.Join(myTarget.GetTempDirectory(), controllerScriptName)) // #nosec G204 } - timeout := 0 // no timeout + // Bound the controller itself when every script is bounded. The per-script + // watchdogs normally end a hang, but they run on the target: if the target + // wedges hard enough, or the connection carrying the controller stops + // delivering, nothing comes back at all. A deadline here guarantees we regain + // control and can report the partial output and diagnostics collected so far. + // Scripts with no timeout (e.g. indefinite-duration collection) keep the + // controller unbounded, as before. + timeout := controllerTimeout(append(concurrentScripts, sequentialScripts...)) + slog.Debug("running controller script", slog.String("target", myTarget.GetName()), slog.Int("timeout", timeout), slog.Int("scripts", len(concurrentScripts)+len(sequentialScripts))) // We run controller in a new process group so that tty/terminal signals, e.g., Ctrl-C, are not sent to the command. This is // necessary to allow the controller script to handle signals itself and propagate them to all child scripts as needed. The // signal handler in perfspect will send the signal to the controller.sh script on each target so that it can clean up @@ -136,6 +144,17 @@ func RunScripts(myTarget target.Target, scripts []ScriptDefinition, continueOnSc slog.Error("failed to execute controller script on target", slog.String("stdout", stdout), slog.String("stderr", stderr), slog.Int("exitcode", exitcode), slog.String("error", err.Error())) return nil, err } + // Report what the controller told us before deciding whether its exit code is + // fatal, so a diagnosis is available even on the failure paths below. + logControllerDiagnostics(stderr) + // A negative exit code means the process was signalled rather than exiting on + // its own, which for a bounded run means our deadline killed it. Say so + // explicitly: the alternative is an unexplained failure that looks identical to + // a crash. The SCRIPT START lines above name the scripts that never finished. + if exitcode < 0 && timeout > 0 { + slog.Error("controller script did not finish within its deadline and was terminated", + slog.String("target", myTarget.GetName()), slog.Int("deadlineSeconds", timeout)) + } if exitcode != 0 { // If the controller was interrupted (e.g., by SIGINT) but still produced output, // parse the output rather than discarding it. This handles the case where the @@ -145,24 +164,11 @@ func RunScripts(myTarget target.Target, scripts []ScriptDefinition, continueOnSc slog.Warn("controller script returned non-zero exit code, but output is available and will be processed", slog.Int("exitcode", exitcode), slog.String("stderr", stderr)) } else { slog.Error("controller script returned non-zero exit code", slog.String("stdout", stdout), slog.String("stderr", stderr), slog.Int("exitcode", exitcode)) - return nil, fmt.Errorf("controller script returned exit code %d", exitcode) - } - } - // Surface watchdog timeouts. The controller reports these on stderr and, when - // continuing on script error, still exits 0 -- so without this the fact that a - // script was killed for hanging would not be logged anywhere. - if strings.Contains(stderr, "TIMEOUT:") { - for line := range strings.SplitSeq(stderr, "\n") { - if strings.HasPrefix(line, "TIMEOUT:") { - slog.Warn("script exceeded its timeout and was killed", slog.String("detail", strings.TrimPrefix(line, "TIMEOUT: "))) - } - } - } - // Log per-script exit codes and elapsed times to make a slow or failing script - // identifiable without re-running with extra instrumentation. - for line := range strings.SplitSeq(stderr, "\n") { - if strings.HasPrefix(line, "SCRIPT RESULT:") { - slog.Debug("script result", slog.String("detail", strings.TrimPrefix(line, "SCRIPT RESULT: "))) + // Include stderr in the error itself. It carries the reason -- an ssh + // transport failure (exit 255) is otherwise indistinguishable from a + // failure in the scripts, and the distinction is not recoverable from + // the exit code alone. + return nil, fmt.Errorf("controller script returned exit code %d: %s", exitcode, lastLines(stderr, 5)) } } // parse output of controller script @@ -180,6 +186,73 @@ func RunScripts(myTarget target.Target, scripts []ScriptDefinition, continueOnSc return scriptOutputs, nil } +// controllerTimeoutMargin is added to the sum of the script timeouts to allow for +// the controller's own setup, the watchdogs' SIGTERM-then-SIGKILL escalation, and +// reporting results back. +const controllerTimeoutMargin = 60 + +// controllerTimeout returns a deadline in seconds for the whole controller run, +// or 0 for no deadline. A deadline is only imposed when every script is itself +// bounded: a single unbounded script (indefinite-duration collection) means the +// controller legitimately has no upper bound. +// +// Sequential scripts run one after another, so their budgets add up, whereas +// concurrent scripts overlap and only the largest matters. +func controllerTimeout(scripts []ScriptDefinition) int { + sequentialTotal := 0 + maxConcurrent := 0 + for _, s := range scripts { + if s.Timeout <= 0 { + return 0 + } + if s.Sequential { + sequentialTotal += s.Timeout + } else if s.Timeout > maxConcurrent { + maxConcurrent = s.Timeout + } + } + return sequentialTotal + maxConcurrent + controllerTimeoutMargin +} + +// logControllerDiagnostics surfaces the controller's own reporting. The controller +// writes these to stderr, and when continuing on script error it still exits 0, so +// without this a script that hung or was abandoned would not be logged anywhere. +func logControllerDiagnostics(stderr string) { + for line := range strings.SplitSeq(stderr, "\n") { + switch { + case strings.HasPrefix(line, "TIMEOUT DIAG:"): + // Process state and kernel stack of a script that would not die. + slog.Warn("hung script diagnostics", slog.String("detail", strings.TrimPrefix(line, "TIMEOUT DIAG: "))) + case strings.HasPrefix(line, "TIMEOUT:"): + slog.Warn("script exceeded its timeout", slog.String("detail", strings.TrimPrefix(line, "TIMEOUT: "))) + case strings.Contains(line, "ABANDONED"): + slog.Warn("script could not be stopped and was abandoned", slog.String("detail", strings.TrimPrefix(line, "SCRIPT RESULT: "))) + case strings.HasPrefix(line, "SCRIPT RESULT:"): + slog.Debug("script result", slog.String("detail", strings.TrimPrefix(line, "SCRIPT RESULT: "))) + case strings.HasPrefix(line, "SCRIPT START:"): + slog.Debug("script started", slog.String("detail", strings.TrimPrefix(line, "SCRIPT START: "))) + } + } +} + +// lastLines returns up to n trailing non-empty lines of s, joined by "; ", for +// embedding in an error message. +func lastLines(s string, n int) string { + var lines []string + for line := range strings.SplitSeq(s, "\n") { + if strings.TrimSpace(line) != "" { + lines = append(lines, strings.TrimSpace(line)) + } + } + if len(lines) == 0 { + return "(no stderr)" + } + if len(lines) > n { + lines = lines[len(lines)-n:] + } + return strings.Join(lines, "; ") +} + // RunScriptStream runs a script on the specified target and streams the output to the specified channels. func RunScriptStream(myTarget target.Target, script ScriptDefinition, localTempDir string, stdoutChannel chan []byte, stderrChannel chan []byte, exitcodeChannel chan int, errorChannel chan error, cmdChannel chan *exec.Cmd) { installedLkms, err := prepareTargetToRunScripts(myTarget, []ScriptDefinition{script}, localTempDir, true) @@ -294,6 +367,8 @@ declare -A watchdog_pids=() declare -A start_times=() current_seq_pid="" current_seq_script="" +# set by wait_for_script: 1 when we stopped waiting on an unkillable script +last_wait_abandoned=0 continue_on_script_error={{if .ContinueOnScriptError}}1{{else}}0{{end}} @@ -324,11 +399,38 @@ readonly WATCHDOG_KILL_AFTER=5 # escalates to SIGKILL, during signal-triggered cleanup. readonly KILL_GRACE_SECONDS=5 +# dump_hung_process_state records why a script could not be stopped. Process +# state D is uninterruptible sleep: the process is blocked inside a kernel call +# and will not act on any signal -- not even SIGKILL -- until that call returns. +# That is what distinguishes a probe wedged on a PMU access from a merely slow +# command, and it is why signalling alone cannot always reap it. The kernel stack +# names the exact call it is stuck in, and is readable because metadata scripts +# run with elevated privileges. +dump_hung_process_state() { + local s="$1" pid="$2" p st wch + echo "TIMEOUT DIAG: process group $pid for script '${orig_names[$s]}':" >&2 + ps -eo pid,ppid,pgid,stat,etime,wchan:24,args 2>/dev/null | awk -v pg="$pid" 'NR==1 || $3==pg' >&2 || true + for p in $(ps -eo pid,pgid 2>/dev/null | awk -v pg="$pid" '$2==pg {print $1}'); do + st=$(awk '{print $3}' "/proc/$p/stat" 2>/dev/null || true) + wch=$(cat "/proc/$p/wchan" 2>/dev/null || true) + echo "TIMEOUT DIAG: pid=$p state=${st:-?} wchan=${wch:-?}" >&2 + if [[ "$st" == "D" ]]; then + echo "TIMEOUT DIAG: pid=$p is in uninterruptible sleep and cannot be signalled; kernel stack:" >&2 + cat "/proc/$p/stack" 2>/dev/null >&2 || echo "TIMEOUT DIAG: (kernel stack unavailable)" >&2 + fi + done +} + # start_watchdog starts a background timer for a script. Each script runs via # setsid, so it leads its own process group; the watchdog signals the whole # group (negative PID). This is what makes the timeout forceful: signalling only # the script's direct child would leave a wedged grandchild (e.g. a perf stuck in # the kernel) running, and the controller's 'wait' would block on it forever. +# +# If the group survives even SIGKILL it is abandoned: a marker file tells the +# waiter to stop waiting on it. Otherwise an unkillable probe would block the +# controller forever, and none of the diagnostics below would ever be reported, +# because the caller only reads our output once we exit. start_watchdog() { local s="$1" pid="$2" budget="${timeouts[$1]:-0}" [[ "$budget" -le 0 ]] && return 0 @@ -343,6 +445,7 @@ start_watchdog() { done ps -p "$pid" > /dev/null 2>&1 || exit 0 echo "TIMEOUT: script '${orig_names[$s]}' exceeded ${budget}s; sending SIGTERM to process group $pid" >&2 + dump_hung_process_state "$s" "$pid" kill -SIGTERM -"$pid" 2>/dev/null || true local killwait=0 while ps -p "$pid" > /dev/null 2>&1 && [[ "$killwait" -lt "$WATCHDOG_KILL_AFTER" ]]; do @@ -352,11 +455,39 @@ start_watchdog() { if ps -p "$pid" > /dev/null 2>&1; then echo "TIMEOUT: script '${orig_names[$s]}' ignored SIGTERM after ${WATCHDOG_KILL_AFTER}s; sending SIGKILL to process group $pid" >&2 kill -SIGKILL -"$pid" 2>/dev/null || true + killwait=0 + while ps -p "$pid" > /dev/null 2>&1 && [[ "$killwait" -lt "$WATCHDOG_KILL_AFTER" ]]; do + sleep 1 + killwait=$((killwait + 1)) + done + if ps -p "$pid" > /dev/null 2>&1; then + echo "TIMEOUT: script '${orig_names[$s]}' survived SIGKILL; abandoning it so collection can continue" >&2 + dump_hung_process_state "$s" "$pid" + touch "$script_dir/${s}.abandoned" + fi fi ) & watchdog_pids[$s]=$! } +# wait_for_script waits for a script to exit, but gives up if its watchdog has +# abandoned it as unkillable. Sets last_wait_abandoned=1 in that case, and +# otherwise returns the script's real exit status. A plain 'wait' cannot be used +# here: it blocks forever on a process stuck in uninterruptible sleep. +wait_for_script() { + local s="$1" pid="$2" + last_wait_abandoned=0 + while ps -p "$pid" > /dev/null 2>&1; do + if [[ -f "$script_dir/${s}.abandoned" ]]; then + last_wait_abandoned=1 + return 0 + fi + sleep 1 + done + # The process has exited, so this returns immediately with its real status. + wait "$pid" +} + # stop_watchdog cancels a script's watchdog once the script has exited. stop_watchdog() { local s="$1" wpid="${watchdog_pids[$1]:-}" @@ -385,11 +516,32 @@ report_script_result() { fi } +# report_abandoned_script records a script we gave up waiting for. The exit code +# is synthetic: the process is still alive, so there is no real status to report. +report_abandoned_script() { + local s="$1" + local elapsed=$(( $(date +%s) - ${start_times[$s]:-0} )) + echo "SCRIPT RESULT: '${orig_names[$s]}' ABANDONED after ${elapsed}s (unkillable, still running)" >&2 + if [[ -s "$script_dir/${s}.stderr" ]]; then + echo "SCRIPT RESULT: '${orig_names[$s]}' stderr tail:" >&2 + tail -n 20 "$script_dir/${s}.stderr" >&2 || true + fi + exitcodes[$s]=137 +} + +# announce_script names a script as it starts. Without this, a controller that +# dies or is killed before producing results gives no indication of which script +# it had reached. +announce_script() { + echo "SCRIPT START: '${orig_names[$1]}' pid=$2 budget=${timeouts[$1]:-0}s" >&2 +} + start_concurrent_scripts() { for s in "${concurrent_scripts[@]}"; do setsid bash "$script_dir/${s}.sh" > "$script_dir/${s}.stdout" 2> "$script_dir/${s}.stderr" & pids[$s]=$! start_times[$s]=$(date +%s) + announce_script "$s" "${pids[$s]}" start_watchdog "$s" "${pids[$s]}" done } @@ -402,11 +554,16 @@ run_sequential_scripts() { current_seq_pid=$! pids[$s]=$current_seq_pid start_times[$s]=$(date +%s) + announce_script "$s" "$current_seq_pid" start_watchdog "$s" "$current_seq_pid" - if wait "$current_seq_pid"; then - exitcodes[$s]=0 + if wait_for_script "$s" "$current_seq_pid"; then stop_watchdog "$s" - report_script_result "$s" 0 + if [[ "$last_wait_abandoned" -eq 1 ]]; then + report_abandoned_script "$s" + else + exitcodes[$s]=0 + report_script_result "$s" 0 + fi else ec=$? exitcodes[$s]=$ec @@ -449,9 +606,17 @@ kill_script() { if ps -p "$pid" > /dev/null 2>&1; then echo "Force killing script '${orig_names[$s]}' with PID $pid" >&2 kill -SIGKILL -"$pid" 2>/dev/null || true + # Give SIGKILL a moment to land, then report if it did not. Do not 'wait' + # here: a process in uninterruptible sleep survives SIGKILL until its kernel + # call returns, and waiting on it would stall shutdown indefinitely -- past + # the ~20s the perfspect signal handler allows before it escalates. + sleep 1 + if ps -p "$pid" > /dev/null 2>&1; then + echo "Script '${orig_names[$s]}' with PID $pid survived SIGKILL; abandoning it" >&2 + dump_hung_process_state "$s" "$pid" + fi fi - wait "$pid" 2>/dev/null || true - echo "Script '${orig_names[$s]}' with PID $pid has been killed" >&2 + echo "Done killing script '${orig_names[$s]}' with PID $pid" >&2 if [[ -z "${exitcodes[$s]:-}" ]]; then echo "Setting exit code for script '${orig_names[$s]}' to 143 (terminated by SIGTERM)" >&2 exitcodes[$s]=143 @@ -460,14 +625,23 @@ kill_script() { wait_for_concurrent_scripts() { for s in "${concurrent_scripts[@]}"; do - if wait "${pids[$s]}"; then - exitcodes[$s]=0 + local abandoned=0 + if wait_for_script "$s" "${pids[$s]}"; then + if [[ "$last_wait_abandoned" -eq 1 ]]; then + abandoned=1 + else + exitcodes[$s]=0 + fi else ec=$? exitcodes[$s]=$ec fi stop_watchdog "$s" - report_script_result "$s" "${exitcodes[$s]}" + if [[ "$abandoned" -eq 1 ]]; then + report_abandoned_script "$s" + else + report_script_result "$s" "${exitcodes[$s]}" + fi done } diff --git a/internal/script/script_test.go b/internal/script/script_test.go index 3329de19..f6bb6bea 100644 --- a/internal/script/script_test.go +++ b/internal/script/script_test.go @@ -425,6 +425,167 @@ func TestFormMasterScriptWatchdogKillsHungScript(t *testing.T) { } } +// TestFormMasterScriptReportsHungScriptDiagnostics confirms that when the +// watchdog fires, the controller names the script and records the process state of +// its whole group -- the evidence needed to tell a probe wedged in the kernel +// (state D) from one that is merely slow. +// +// The script ignores SIGTERM so it outlives the grace period and forces the +// escalation path. SIGKILL cannot be trapped, so it does get reaped here; the +// case where even SIGKILL fails is covered by +// TestFormMasterScriptAbandonsUnkillableScript. +func TestFormMasterScriptReportsHungScriptDiagnostics(t *testing.T) { + tmp := t.TempDir() + scripts := []ScriptDefinition{ + {Name: "stubborn probe", ScriptTemplate: "trap '' TERM\nsleep 600 &\nwait\n", Timeout: 2}, + {Name: "good probe", ScriptTemplate: "echo alive\n", Timeout: 2}, + } + out := runController(t, tmp, scripts, 60*time.Second) + + // The good probe's result must survive the other script's misbehaviour. + byName := make(map[string]ScriptOutput) + for _, p := range parseControllerScriptOutput(out) { + byName[p.Name] = p + } + if got := byName["good probe"]; got.Exitcode != 0 || !strings.Contains(got.Stdout, "alive") { + t.Errorf("expected good probe to succeed, got exit=%d stdout=%q", got.Exitcode, got.Stdout) + } + for _, want := range []string{ + "SCRIPT START: 'stubborn probe'", // names the script even if we never finish + "exceeded 2s", + "ignored SIGTERM", + "TIMEOUT DIAG:", // process state of the group + } { + if !strings.Contains(out, want) { + t.Errorf("missing diagnostic %q in output:\n%s", want, out) + } + } + // The per-process state line is the point of the diagnostics: without it there + // is no way to distinguish uninterruptible sleep from a slow command. + if !regexp.MustCompile(`TIMEOUT DIAG: pid=[0-9]+ state=\S+ wchan=\S+`).MatchString(out) { + t.Errorf("expected per-pid state/wchan lines in output:\n%s", out) + } +} + +// TestFormMasterScriptAbandonsUnkillableScript confirms the controller stops +// waiting on a script that cannot be killed, reports it, and still returns the +// other scripts' results. +// +// A process wedged in uninterruptible sleep cannot be created on demand, so the +// watchdog's "gave up" marker is pre-seeded to drive the same code path. This is +// the case that previously produced total silence: the controller blocked on +// 'wait' forever, so no diagnostics were ever reported, because the caller only +// reads the controller's output once it exits. +func TestFormMasterScriptAbandonsUnkillableScript(t *testing.T) { + tmp := t.TempDir() + scripts := []ScriptDefinition{ + // No watchdog on this one (Timeout 0); the marker alone drives the path. + {Name: "wedged probe", ScriptTemplate: "sleep 600\n"}, + {Name: "good probe", ScriptTemplate: "echo alive\n"}, + } + marker := filepath.Join(tmp, sanitizeScriptName("wedged probe")+".abandoned") + if err := os.WriteFile(marker, nil, 0o600); err != nil { + t.Fatalf("failed seeding abandoned marker: %v", err) + } + // Without the bypass this blocks for the full 600s sleep. + out := runController(t, tmp, scripts, 60*time.Second) + + if !strings.Contains(out, "ABANDONED") { + t.Errorf("expected the abandoned script to be reported:\n%s", out) + } + byName := make(map[string]ScriptOutput) + for _, p := range parseControllerScriptOutput(out) { + byName[p.Name] = p + } + // A synthetic kill code, since the process is still running and has no status. + if got := byName["wedged probe"].Exitcode; got != 137 { + t.Errorf("expected abandoned script to report exit 137, got %d", got) + } + if got := byName["good probe"]; got.Exitcode != 0 || !strings.Contains(got.Stdout, "alive") { + t.Errorf("expected good probe to succeed, got exit=%d stdout=%q", got.Exitcode, got.Stdout) + } +} + +// runController writes the child scripts and controller for the given definitions, +// runs it, and fails if it does not finish within limit. +func runController(t *testing.T, dir string, scripts []ScriptDefinition, limit time.Duration) string { + t.Helper() + writeChildScripts(t, dir, scripts) + master, _, err := formControllerScript(dir, scripts, nil, true) + if err != nil { + t.Fatalf("error forming controller script: %v", err) + } + masterPath := filepath.Join(dir, "controller.sh") + if err := os.WriteFile(masterPath, []byte(master), 0o700); err != nil { + t.Fatalf("failed writing controller script: %v", err) + } + start := time.Now() + out, err := runLocalBash(masterPath) + if err != nil { + t.Fatalf("error executing controller script: %v\noutput: %s", err, out) + } + if elapsed := time.Since(start); elapsed > limit { + t.Fatalf("controller did not return promptly: took %v (limit %v)\noutput: %s", elapsed, limit, out) + } + return out +} + +func TestControllerTimeout(t *testing.T) { + cases := []struct { + name string + scripts []ScriptDefinition + want int + }{ + { + // An unbounded script means the run has no legitimate upper bound. + name: "any unbounded script disables the deadline", + scripts: []ScriptDefinition{{Name: "a", Timeout: 30}, {Name: "b", Timeout: 0}}, + want: 0, + }, + { + // Concurrent scripts overlap, so only the largest budget matters. + name: "concurrent scripts take the maximum", + scripts: []ScriptDefinition{{Name: "a", Timeout: 30}, {Name: "b", Timeout: 60}}, + want: 60 + controllerTimeoutMargin, + }, + { + // Sequential scripts run one after another, so their budgets add up. + name: "sequential scripts accumulate", + scripts: []ScriptDefinition{{Name: "a", Timeout: 30, Sequential: true}, {Name: "b", Timeout: 45, Sequential: true}}, + want: 75 + controllerTimeoutMargin, + }, + { + name: "mixed adds sequential total to concurrent maximum", + scripts: []ScriptDefinition{{Name: "a", Timeout: 30, Sequential: true}, {Name: "b", Timeout: 60}, {Name: "c", Timeout: 20}}, + want: 30 + 60 + controllerTimeoutMargin, + }, + { + name: "no scripts means no deadline", + scripts: nil, + want: controllerTimeoutMargin, + }, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if got := controllerTimeout(tc.scripts); got != tc.want { + t.Errorf("controllerTimeout() = %d, want %d", got, tc.want) + } + }) + } +} + +func TestLastLines(t *testing.T) { + if got := lastLines("", 5); got != "(no stderr)" { + t.Errorf("expected placeholder for empty input, got %q", got) + } + if got := lastLines("a\n\nb\nc\n", 2); got != "b; c" { + t.Errorf("expected trailing non-empty lines, got %q", got) + } + if got := lastLines("only\n", 5); got != "only" { + t.Errorf("expected the single line, got %q", got) + } +} + // writeChildScripts writes each script definition's template to the directory // the controller script expects to find it in. func writeChildScripts(t *testing.T, dir string, scripts []ScriptDefinition) {