diff --git a/cmd/metrics/metadata.go b/cmd/metrics/metadata.go index fd5a3cf7..06cb2c69 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 = "" } @@ -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"}, }, { @@ -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..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,7 +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) + // 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 @@ -163,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) @@ -220,10 +310,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 +335,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 +343,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,8 +362,13 @@ 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="" +# 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}} @@ -287,16 +384,165 @@ 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 + +# 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 + ( + # 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 + 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 + 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 + 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]:-}" + [[ -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 +} + +# 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 } @@ -307,11 +553,22 @@ 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 - if wait "$current_seq_pid"; then - exitcodes[$s]=0 + start_times[$s]=$(date +%s) + announce_script "$s" "$current_seq_pid" + start_watchdog "$s" "$current_seq_pid" + if wait_for_script "$s" "$current_seq_pid"; then + stop_watchdog "$s" + 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 + 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 +582,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)) @@ -344,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 @@ -355,12 +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" + 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 3a271c03..f6bb6bea 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,267 @@ 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) + } +} + +// 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) { + 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