diff --git a/.gitignore b/.gitignore index 3fef3bae..c79af745 100644 --- a/.gitignore +++ b/.gitignore @@ -5,6 +5,8 @@ /debug_out /tools/bin /tools/bin-aarch64 +# source tarballs the tools build downloads and reuses as a local cache +/tools/*.tar.gz /tools-cache /dist /internal/script/resources/x86_64 diff --git a/cmd/metrics/metadata.go b/cmd/metrics/metadata.go index fd5a3cf7..1db8f130 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 --kill-after=5 30 perf list --json 2>/dev/null | awk ' BEGIN { in_hardware_event = 0 event_name = "" @@ -182,6 +182,14 @@ BEGIN { event_name = "" } ' # end of awk +# The pipeline's exit status is awk's, so a perf that timed out or failed would +# otherwise look like success with an empty event list -- a silently wrong result +# rather than a reported failure. +perf_status=${PIPESTATUS[0]} +if [[ "$perf_status" -ne 0 ]]; then + echo "perf list failed or timed out (exit $perf_status)" >&2 + exit "$perf_status" +fi `, Depends: []string{"perf"}, }, @@ -192,7 +200,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 --kill-after=5 30 perf list --json 2>/dev/null | awk ' BEGIN { event_name = "" } @@ -216,6 +224,14 @@ BEGIN { event_name = "" } ' # end of awk +# The pipeline's exit status is awk's, so a perf that timed out or failed would +# otherwise look like success with an empty event list -- a silently wrong result +# rather than a reported failure. +perf_status=${PIPESTATUS[0]} +if [[ "$perf_status" -ne 0 ]]; then + echo "perf list failed or timed out (exit $perf_status)" >&2 + exit "$perf_status" +fi `, Depends: []string{"perf"}, }, @@ -226,52 +242,61 @@ BEGIN { }, { Name: scriptPerfStatInstructions, - ScriptTemplate: "perf stat -a -e instructions sleep 1", + ScriptTemplate: "timeout --kill-after=5 30 perf stat -a -e instructions sleep 1", Depends: []string{"perf"}, }, { Name: scriptPerfStatRefCycles, - ScriptTemplate: "perf stat -a -e ref-cycles sleep 1", + ScriptTemplate: "timeout --kill-after=5 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 --kill-after=5 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 --kill-after=5 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 --kill-after=5 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 --kill-after=5 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"}, }, + // The three probes below ask for one more copy of an event than there are general + // purpose counters, so the group fits only if one copy can be placed on a fixed + // counter. That deliberate over-subscription makes the kernel's counter assignment + // search do real work, and it is scoped to a single CPU rather than system-wide + // (-a) because of it: on a virtualized guest with an emulated PMU, running the + // same over-subscribed group on every CPU at once has been observed to wedge the + // whole machine past the point where even SIGKILL reaches perf. One CPU answers + // the question just as well -- see getSupportsFixedEvent, which reads only the + // exit code, ""/" metadataScriptTimeout { + scriptDef.Timeout = metadataScriptTimeout + } metadataScripts = append(metadataScripts, scriptDef) } } diff --git a/internal/script/script.go b/internal/script/script.go index 00bd8091..913a95e9 100644 --- a/internal/script/script.go +++ b/internal/script/script.go @@ -5,6 +5,7 @@ package script import ( + "bytes" "embed" "fmt" "log/slog" @@ -25,6 +26,29 @@ var Resources embed.FS const ControllerPIDFileName = "controller.pid" +// descendantsOfShellFunc defines a shell function that prints a pid followed by +// all of its descendants. A process-group filter is not sufficient: 'timeout' +// puts itself and the command it runs into a new process group, so a probe run as +// 'timeout 30 perf stat ...' is invisible to a PGID-based search and survives a +// kill aimed at the script's group. It is shared by the controller script and by +// the cleanup we run after abandoning a controller. +const descendantsOfShellFunc = `descendants_of() { + local root="$1" snapshot frontier next depth=0 + snapshot=$(ps -eo pid,ppid 2>/dev/null || true) + frontier="$root" + # The depth cap is a safety net only; a process tree cannot be deeper than this + # in practice, and without it a malformed snapshot could loop forever. + while [[ -n "$frontier" && "$depth" -lt 32 ]]; do + echo "$frontier" + next=$(awk -v parents="$frontier" ' + BEGIN { n = split(parents, a, " "); for (i = 1; i <= n; i++) if (a[i] != "") P[a[i]] = 1 } + NR > 1 && ($2 in P) { printf "%s ", $1 } + ' <<< "$snapshot") + frontier="$next" + depth=$((depth + 1)) + done +}` + type ScriptOutput struct { ScriptDefinition Stdout string @@ -124,18 +148,46 @@ 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 // its child processes. newProcessGroup := true reuseSSHConnection := false // don't reuse ssh connection on long-running commands, makes it difficult to kill the command - stdout, stderr, exitcode, err := myTarget.RunCommandEx(cmd, timeout, newProcessGroup, reuseSSHConnection) + // Stream the controller's stderr rather than only reading it at the end. Its + // SCRIPT START/RESULT reports exist to name the script that hung, and a hung + // controller does not return, so parsing them only after it exits means they are + // missing from precisely the runs that need them. + progress := &controllerProgressLogger{} + stdout, stderr, exitcode, err := myTarget.RunCommandExLive(cmd, timeout, newProcessGroup, reuseSSHConnection, progress) + progress.flush() if err != nil { 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 } + // 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)) + // Killing our end of the connection does not stop anything on the target: the + // controller and its probes keep running there, unattached and unbounded. On a + // shared or repeatedly tested machine those leftovers accumulate and contend + // for the resource the next run's probes need, so one hang turns into a run of + // them. Reap them before returning. + CleanupAbandonedController(myTarget) + } 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 +197,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 +219,198 @@ 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 and for reporting results back. +const controllerTimeoutMargin = 60 + +// watchdogEscalationSeconds is how much longer than its own budget a hung script +// can occupy the controller: the watchdog waits WATCHDOG_KILL_AFTER seconds after +// SIGTERM, the same again after SIGKILL, plus its 1-second polling granularity. +// A deadline that omits this is guaranteed to fire during the escalation of a +// hang -- exactly when the controller is producing the diagnosis of it -- and +// killing the controller discards all of its output, because results are printed +// only once every script has finished. +const watchdogEscalationSeconds = 12 + +// 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. Each phase gets the +// watchdog escalation allowance on top, since a script that hangs holds the +// controller for its budget plus the time taken to force it out. +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 + watchdogEscalationSeconds + } else if s.Timeout > maxConcurrent { + maxConcurrent = s.Timeout + } + } + if maxConcurrent > 0 { + maxConcurrent += watchdogEscalationSeconds + } + return sequentialTotal + maxConcurrent + controllerTimeoutMargin +} + +// cleanupTemplate kills a controller left running on a target, along with every +// process below it, and reports anything that survives. Killing the local end of +// the connection has no effect on the target, so without this a probe that +// outlived its watchdog keeps running there indefinitely. +const cleanupTemplate = ` +%s +pidfile="%s" +[ -r "$pidfile" ] || exit 0 +root=$(cat "$pidfile" 2>/dev/null || true) +# Refuse anything that is not a plain pid: this string comes from a file, and it +# is about to be handed to kill. +case "$root" in ''|*[!0-9]*) exit 0 ;; esac +ps -p "$root" > /dev/null 2>&1 || { rm -f "$pidfile"; exit 0; } +# Capture the tree before signalling: the first kill orphans the descendants and +# they can no longer be traced back to the controller. +tree=$(descendants_of "$root") +echo "cleaning up abandoned controller pid=$root" +for p in $tree; do + cmd=$(tr '\0' ' ' < "/proc/$p/cmdline" 2>/dev/null || true) + [ -n "$cmd" ] && echo " killing pid=$p cmd=$cmd" +done +# shellcheck disable=SC2086 # word splitting is intended: tree is a pid list +kill -SIGKILL $tree 2>/dev/null || true +sleep 1 +for p in $tree; do + if ps -p "$p" > /dev/null 2>&1; then + echo " SURVIVED SIGKILL pid=$p state=$(ps -o stat= -p "$p" 2>/dev/null | tr -d ' ')" >&2 + fi +done +rm -f "$pidfile" +` + +// CleanupAbandonedController kills the controller script and its descendants on a +// target after we have stopped waiting for them. It is best-effort: it reports +// failures rather than returning them, because every caller is already on an error +// path and cleanup failing must not mask the original problem. +func CleanupAbandonedController(myTarget target.Target) { + pidFile := path.Join(myTarget.GetTempDirectory(), ControllerPIDFileName) + cleanupScript := fmt.Sprintf(cleanupTemplate, descendantsOfShellFunc, pidFile) + var cmd *exec.Cmd + if !myTarget.IsSuperUser() && myTarget.CanElevatePrivileges() { + // The controller runs under sudo, so its children are root-owned. + cmd = exec.Command("sudo", "bash", "-c", cleanupScript) // #nosec G204 + } else { + cmd = exec.Command("bash", "-c", cleanupScript) // #nosec G204 + } + stdout, stderr, exitcode, err := myTarget.RunCommandEx(cmd, 30, false, true) + if err != nil { + slog.Error("failed to clean up abandoned controller on target", + slog.String("target", myTarget.GetName()), slog.String("error", err.Error())) + return + } + for _, line := range strings.Split(strings.TrimSpace(stdout), "\n") { + if line != "" { + slog.Warn("abandoned controller cleanup", slog.String("target", myTarget.GetName()), slog.String("detail", strings.TrimSpace(line))) + } + } + // A process that survives SIGKILL is blocked in the kernel and cannot be reaped + // from user space at all; it needs to be reported, not retried. + for _, line := range strings.Split(strings.TrimSpace(stderr), "\n") { + if strings.Contains(line, "SURVIVED SIGKILL") { + slog.Error("process on target survived SIGKILL and could not be reaped", + slog.String("target", myTarget.GetName()), slog.String("detail", strings.TrimSpace(line))) + } + } + if exitcode != 0 { + slog.Warn("abandoned controller cleanup returned non-zero exit code", + slog.String("target", myTarget.GetName()), slog.Int("exitcode", exitcode), slog.String("stderr", stderr)) + } +} + +// logControllerDiagnosticLine surfaces one line of 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. It classifies a single line rather than a whole stderr buffer because the +// lines are consumed as they stream in, before the controller has exited. +func logControllerDiagnosticLine(line string) { + 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: "))) + } +} + +// controllerProgressLogger logs the controller's progress reports as they arrive on +// its stderr. Without it those reports are parsed only after the controller exits, +// so a run that hangs -- the case they exist to explain -- produces none of them: +// the log simply stops after "running controller script" and never names the script +// that stalled. Writing them out as they stream means a stall identifies itself +// while it is still stalled, from the local side, without needing the target to +// answer anything. +type controllerProgressLogger struct { + partial []byte +} + +// maxControllerProgressLine bounds how much unterminated output is buffered, so +// stderr without newlines cannot grow this without limit. +const maxControllerProgressLine = 64 * 1024 + +func (l *controllerProgressLogger) Write(p []byte) (int, error) { + l.partial = append(l.partial, p...) + for { + i := bytes.IndexByte(l.partial, '\n') + if i < 0 { + break + } + logControllerDiagnosticLine(string(l.partial[:i])) + l.partial = l.partial[i+1:] + } + if len(l.partial) > maxControllerProgressLine { + logControllerDiagnosticLine(string(l.partial)) + l.partial = nil + } + return len(p), nil +} + +// flush logs a final report that arrived without a trailing newline, which is what +// a controller killed mid-write leaves behind. +func (l *controllerProgressLogger) flush() { + if len(l.partial) > 0 { + logControllerDiagnosticLine(string(l.partial)) + l.partial = nil + } +} + +// 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,15 +468,18 @@ 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 { TargetTempDir string ControllerPIDFile string + DescendantsFunc string ConcurrentScripts []tplScript SequentialScripts []tplScript ContinueOnScriptError bool @@ -236,6 +487,7 @@ func formControllerScript(targetTempDirectory string, concurrentScripts []Script // populate tplData tplData.TargetTempDir = targetTempDirectory tplData.ControllerPIDFile = ControllerPIDFileName + tplData.DescendantsFunc = descendantsOfShellFunc tplData.ContinueOnScriptError = continueOnScriptError needsElevated := false for _, s := range concurrentScripts { @@ -243,7 +495,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 +503,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 +522,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 +544,215 @@ 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 + +{{.DescendantsFunc}} + +# dump_pid_states reports the kernel state of each given pid, skipping any that +# have exited. 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_pid_states() { + local label="$1" + shift + local p st wch cmd + for p in "$@"; do + ps -p "$p" > /dev/null 2>&1 || continue + # Read state via ps rather than parsing /proc//stat: the comm field there + # is parenthesized and may contain spaces, which shifts the field positions. + st=$(ps -o stat= -p "$p" 2>/dev/null | tr -d ' ') + wch=$(cat "/proc/$p/wchan" 2>/dev/null || true) + cmd=$(tr '\0' ' ' < "/proc/$p/cmdline" 2>/dev/null || true) + echo "TIMEOUT DIAG: $label pid=$p state=${st:-?} wchan=${wch:-?} cmd=${cmd:-?}" >&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 +} + +# dump_hung_process_state records why a script could not be stopped. The caller +# passes a pid list captured before any signal was sent: once the script's shell +# dies its children are reparented to init, so the tree cannot be recovered +# afterwards. +dump_hung_process_state() { + local s="$1" pid="$2" tree="$3" + echo "TIMEOUT DIAG: process tree for script '${orig_names[$s]}' (root pid $pid):" >&2 + ps -eo pid,ppid,pgid,stat,etime,wchan:24,args 2>/dev/null | awk -v pids="$tree" ' + BEGIN { n = split(pids, a, /[ \n]+/); for (i = 1; i <= n; i++) if (a[i] != "") P[a[i]] = 1 } + NR == 1 || ($1 in P) + ' >&2 || true + # shellcheck disable=SC2086 # word splitting is intended: tree is a pid list + dump_pid_states "in tree" $tree +} + +# kill_tree signals a script's process group and then every process in the +# previously captured tree individually. The group kill alone reaps the script's +# shell but leaves a 'timeout'-wrapped probe running in its own group, orphaned +# and still holding whatever it was stuck on. Descendants that lead a group get +# the signal on their group too, so a probe forked below 'timeout' is covered. +kill_tree() { + local pid="$1" sig="$2" tree="$3" p pg + kill "-$sig" -"$pid" 2>/dev/null || true + for p in $tree; do + [[ "$p" == "$pid" ]] && continue + pg=$(ps -o pgid= -p "$p" 2>/dev/null | tr -d ' ') + if [[ "$pg" == "$p" ]]; then + kill "-$sig" -"$p" 2>/dev/null || true + else + kill "-$sig" "$p" 2>/dev/null || true + 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 tree of $pid" >&2 + # Capture the tree before signalling anything: the first kill orphans the + # descendants, and an orphan cannot be traced back to this script. + local tree + tree=$(descendants_of "$pid") + dump_hung_process_state "$s" "$pid" "$tree" + kill_tree "$pid" SIGTERM "$tree" + 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 tree of $pid" >&2 + kill_tree "$pid" SIGKILL "$tree" + 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" "$tree" + touch "$script_dir/${s}.abandoned" + fi + fi + # Anything from the tree that is still alive here ignored SIGKILL, which only + # a process blocked in the kernel can do. Report it even when the script's own + # shell died: a leaked probe still holding a PMU resource is the most likely + # reason the scripts that ran after it also hung. + # shellcheck disable=SC2086 # word splitting is intended: tree is a pid list + dump_pid_states "survived SIGKILL" $tree + ) & + 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 +763,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 +792,24 @@ 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) + # Signal the process group and every descendant (see kill_tree: a + # 'timeout'-wrapped probe lives in its own group and outlives a group kill). # 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 + local tree + tree=$(descendants_of "$pid") + kill_tree "$pid" SIGTERM "$tree" + # 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)) @@ -343,10 +818,18 @@ kill_script() { # Force kill the process group if still alive 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 + kill_tree "$pid" SIGKILL "$tree" + # 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" "$tree" + 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 +838,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..2da8c601 100644 --- a/internal/script/script_test.go +++ b/internal/script/script_test.go @@ -4,13 +4,16 @@ package script import ( + "fmt" "os" "os/exec" "path" "path/filepath" "regexp" + "strconv" "strings" "testing" + "time" "perfspect/internal/target" ) @@ -337,6 +340,392 @@ 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: in tree 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 +} + +// TestFormMasterScriptReachesProcessOutsideScriptGroup covers what hid the real +// failure on m6i.16xlarge. Metadata probes run as 'timeout 30 perf stat ...', and +// timeout puts itself and the command it runs into a NEW process group. A search +// or a kill scoped to the script's own group therefore sees only the script's +// shell: the probe that actually hung is invisible, and it survives. +func TestFormMasterScriptReachesProcessOutsideScriptGroup(t *testing.T) { + tmp := t.TempDir() + // A distinctive duration makes the leak check below unambiguous; matching on + // "sleep" alone would collide with unrelated processes on the machine. + const marker = "987654" + scripts := []ScriptDefinition{ + {Name: "timeout wrapped probe", ScriptTemplate: "timeout 600 sleep " + marker, Timeout: 2}, + } + out := runController(t, tmp, scripts, 60*time.Second) + + // The probe must appear in the diagnostics by name, in a different process + // group from the script's shell. + if !strings.Contains(out, "sleep "+marker) { + t.Errorf("diagnostics did not name the process running below timeout, got:\n%s", out) + } + if matched, _ := regexp.MatchString(`TIMEOUT DIAG: in tree pid=[0-9]+ state=\S+ wchan=\S+ cmd=`, out); !matched { + t.Errorf("expected per-pid state lines for the tree, got:\n%s", out) + } + // And it must be gone. Before kill_tree, a group-scoped kill left this running + // and reparented to init. + if processCmdlineExists(t, "sleep "+marker) { + t.Errorf("process below timeout survived the watchdog kill") + } +} + +// processCmdlineExists reports whether any process has needle in its command +// line. It scans /proc rather than shelling out to pgrep, whose own command line +// would match the needle and produce a false positive. +func processCmdlineExists(t *testing.T, needle string) bool { + t.Helper() + entries, err := os.ReadDir("/proc") + if err != nil { + t.Fatalf("failed reading /proc: %v", err) + } + for _, e := range entries { + if _, err := strconv.Atoi(e.Name()); err != nil { + continue // not a pid directory + } + raw, err := os.ReadFile(filepath.Join("/proc", e.Name(), "cmdline")) + if err != nil { + continue // the process exited while we were looking + } + if strings.Contains(strings.ReplaceAll(string(raw), "\x00", " "), needle) { + return true + } + } + return false +} + +// TestCleanupScriptKillsControllerTree exercises the shell that reaps a +// controller we stopped waiting for. Killing the local end of the connection has +// no effect on the target, so this is what actually stops leaked probes from +// accumulating there across runs. +func TestCleanupScriptKillsControllerTree(t *testing.T) { + tmp := t.TempDir() + pidFile := filepath.Join(tmp, ControllerPIDFileName) + // A distinct marker from the other tests' so a stray process from one cannot + // satisfy the other's assertions. + const marker = "987655" + // Stand in for a controller: record our pid where the real one does, then run a + // probe below 'timeout', which lands in its own process group. + fake := filepath.Join(tmp, "fake_controller.sh") + body := "#!/usr/bin/env bash\necho $$ > " + pidFile + "\ntimeout 600 sleep " + marker + "\n" + if err := os.WriteFile(fake, []byte(body), 0o700); err != nil { // #nosec G306 + t.Fatalf("failed writing fake controller: %v", err) + } + controller := exec.Command("bash", fake) // #nosec G204 + if err := controller.Start(); err != nil { + t.Fatalf("failed starting fake controller: %v", err) + } + defer func() { _ = controller.Wait() }() + + // Wait for the tree to exist before trying to reap it. + deadline := time.Now().Add(10 * time.Second) + for !processCmdlineExists(t, "sleep "+marker) { + if time.Now().After(deadline) { + t.Fatal("fake controller never started its probe") + } + time.Sleep(50 * time.Millisecond) + } + + cleanup := fmt.Sprintf(cleanupTemplate, descendantsOfShellFunc, pidFile) + out, err := exec.Command("bash", "-c", cleanup).CombinedOutput() // #nosec G204 + if err != nil { + t.Fatalf("cleanup script failed: %v\noutput: %s", err, out) + } + if !strings.Contains(string(out), "cleaning up abandoned controller") { + t.Errorf("cleanup did not report what it was doing, got:\n%s", out) + } + if !strings.Contains(string(out), "sleep "+marker) { + t.Errorf("cleanup did not name the probe it killed, got:\n%s", out) + } + if processCmdlineExists(t, "sleep "+marker) { + t.Error("probe below timeout survived cleanup") + } + if _, err := os.Stat(pidFile); !os.IsNotExist(err) { + t.Errorf("cleanup left the pid file behind: %v", err) + } +} + +// TestCleanupScriptIgnoresBogusPIDFile checks that a pid file holding something +// other than a pid is refused rather than passed to kill. +func TestCleanupScriptIgnoresBogusPIDFile(t *testing.T) { + tmp := t.TempDir() + pidFile := filepath.Join(tmp, ControllerPIDFileName) + for _, contents := range []string{"", "-1", "not-a-pid", "1234; rm -rf /tmp/should-not-happen"} { + if err := os.WriteFile(pidFile, []byte(contents), 0o600); err != nil { + t.Fatalf("failed writing pid file: %v", err) + } + cleanup := fmt.Sprintf(cleanupTemplate, descendantsOfShellFunc, pidFile) + out, err := exec.Command("bash", "-c", cleanup).CombinedOutput() // #nosec G204 + if err != nil { + t.Errorf("cleanup script failed on pid file %q: %v\noutput: %s", contents, err, out) + } + if strings.Contains(string(out), "cleaning up") { + t.Errorf("cleanup acted on invalid pid file %q, output:\n%s", contents, 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 + watchdogEscalationSeconds + 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 + 2*watchdogEscalationSeconds + 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 + 2*watchdogEscalationSeconds + 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..0bd5a734 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 @@ -1533,11 +1534,30 @@ finalize() { # kill the processwatch pipeline if it is still running if [ -n "${pw_pid:-}" ] && [ "$pw_pid" -gt 0 ]; then + # pw_pid is the subshell wrapping the pipeline below, not processwatch itself, + # and signalling a shell does not signal its children -- SIGKILL least of all. + # Killing pw_pid alone therefore reaps the wrapper and orphans processwatch, + # which is root-owned, holds perf_event fds, and is given no -n count when + # duration is 0, so it never exits on its own and keeps running on the target + # after this script is long gone. + # + # Collect the tree before signalling anything: the first kill orphans everything + # below pw_pid, after which the children can no longer be traced back to it. + pw_tree="" + for p in $(pgrep -P "$pw_pid" 2>/dev/null); do + # The list is expanded once, so appending here is safe and picks up any + # grandchildren without re-entering the loop. + pw_tree="$pw_tree $p $(pgrep -P "$p" 2>/dev/null | tr '\n' ' ')" + done # Try SIGTERM first - kill -TERM "$pw_pid" 2>/dev/null || true + for p in $pw_pid $pw_tree; do + kill -TERM "$p" 2>/dev/null || true + done sleep 0.1 # Then SIGKILL if needed - kill -KILL "$pw_pid" 2>/dev/null || true + for p in $pw_pid $pw_tree; do + kill -KILL "$p" 2>/dev/null || true + done fi } trap finalize INT TERM EXIT diff --git a/internal/target/helpers.go b/internal/target/helpers.go index 461cd234..6259d79a 100644 --- a/internal/target/helpers.go +++ b/internal/target/helpers.go @@ -8,6 +8,7 @@ import ( "context" "errors" "fmt" + "io" "log/slog" "os/exec" "strings" @@ -106,6 +107,16 @@ func uninstallLkms(t Target, lkms []string) (err error) { // - exitCode: The exit code of the command. If the command fails to execute, this may be undefined. // - err: An error object if the command fails to execute or times out. func runLocalCommandWithInputWithTimeout(cmd *exec.Cmd, input string, timeout int, newProcessGroup bool) (stdout string, stderr string, exitCode int, err error) { + return runLocalCommandWithInputWithTimeoutLive(cmd, input, timeout, newProcessGroup, nil) +} + +// runLocalCommandWithInputWithTimeoutLive is runLocalCommandWithInputWithTimeout with +// an additional liveStderr writer, which receives the command's standard error as it +// is produced rather than only after the command returns. A command that hangs never +// returns, so anything it reported on stderr about its own progress is unavailable +// exactly when it is needed; a caller that passes a writer here can act on those +// reports while the command is still running. liveStderr may be nil. +func runLocalCommandWithInputWithTimeoutLive(cmd *exec.Cmd, input string, timeout int, newProcessGroup bool, liveStderr io.Writer) (stdout string, stderr string, exitCode int, err error) { logInput := "" if input != "" { logInput = "******" @@ -124,7 +135,11 @@ func runLocalCommandWithInputWithTimeout(cmd *exec.Cmd, input string, timeout in } var outbuf, errbuf strings.Builder cmd.Stdout = &outbuf - cmd.Stderr = &errbuf + if liveStderr != nil { + cmd.Stderr = io.MultiWriter(&errbuf, liveStderr) + } else { + cmd.Stderr = &errbuf + } if newProcessGroup { // isolate the command in its own process group, so that signals sent to perfspect don't affect it cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} diff --git a/internal/target/local_target.go b/internal/target/local_target.go index 232a751d..2738abac 100644 --- a/internal/target/local_target.go +++ b/internal/target/local_target.go @@ -38,6 +38,16 @@ func (t *LocalTarget) RunCommandEx(cmd *exec.Cmd, timeout int, newProcessGroup b return runLocalCommandWithInputWithTimeout(cmd, input, timeout, newProcessGroup) } +// RunCommandExLive is RunCommandEx with stderr additionally written to liveStderr as +// it arrives, so a caller can observe a command's progress reports before it exits. +func (t *LocalTarget) RunCommandExLive(cmd *exec.Cmd, timeout int, newProcessGroup bool, remoteReuseSSHConnection bool, liveStderr io.Writer) (stdout string, stderr string, exitCode int, err error) { + input := "" + if t.sudo != "" && len(cmd.Args) > 2 && cmd.Args[0] == "sudo" && strings.HasPrefix(cmd.Args[1], "-") && strings.Contains(cmd.Args[1], "S") { // 'sudo -S' gets password from stdin + input = t.sudo + "\n" + } + return runLocalCommandWithInputWithTimeoutLive(cmd, input, timeout, newProcessGroup, liveStderr) +} + // RunCommandStream runs the given command asynchronously on the target. // It sends the command to the cmdChannel and executes it with a timeout. // The output from the command is sent to the stdoutChannel and stderrChannel, diff --git a/internal/target/remote_target.go b/internal/target/remote_target.go index 2355a042..df3a83f0 100644 --- a/internal/target/remote_target.go +++ b/internal/target/remote_target.go @@ -5,6 +5,7 @@ package target import ( "fmt" + "io" "log/slog" "os" "os/exec" @@ -34,6 +35,13 @@ func (t *RemoteTarget) RunCommandEx(cmd *exec.Cmd, timeout int, newProcessGroup return runLocalCommandWithInputWithTimeout(localCommand, "", timeout, newProcessGroup) } +// RunCommandExLive is RunCommandEx with stderr additionally written to liveStderr as +// it arrives, so a caller can observe a command's progress reports before it exits. +func (t *RemoteTarget) RunCommandExLive(cmd *exec.Cmd, timeout int, newProcessGroup bool, reuseSSHConnection bool, liveStderr io.Writer) (stdout string, stderr string, exitCode int, err error) { + localCommand := t.prepareLocalCommand(cmd, reuseSSHConnection) + return runLocalCommandWithInputWithTimeoutLive(localCommand, "", timeout, newProcessGroup, liveStderr) +} + // RunCommandStream executes a command asynchronously on a remote target. // It prepares the local command based on the provided parameters and runs it // with a specified timeout. The function communicates the command's output, diff --git a/internal/target/target.go b/internal/target/target.go index 19ced087..78266c93 100644 --- a/internal/target/target.go +++ b/internal/target/target.go @@ -7,6 +7,7 @@ Package target provides a way to interact with local and remote systems. package target import ( + "io" "os" "os/exec" ) @@ -80,6 +81,13 @@ type Target interface { // It returns the standard output, standard error, exit code, and any error that occurred. RunCommandEx(cmd *exec.Cmd, timeout int, newProcessGroup bool, remoteReuseSSHConnection bool) (stdout string, stderr string, exitCode int, err error) + // RunCommandExLive is RunCommandEx with one addition: liveStderr, if non-nil, + // receives the command's standard error as it is produced instead of only after + // the command returns. Use it for commands that report their own progress on + // stderr and may hang: a hung command never returns, so its reports are + // otherwise unavailable at the one time they matter. + RunCommandExLive(cmd *exec.Cmd, timeout int, newProcessGroup bool, remoteReuseSSHConnection bool, liveStderr io.Writer) (stdout string, stderr string, exitCode int, err error) + // RunCommandStream runs the specified command on the target and streams the output to the provided channels. // Arguments: // - cmd: the command to run diff --git a/internal/workflow/signals.go b/internal/workflow/signals.go index 6f9e8824..21b2f27d 100644 --- a/internal/workflow/signals.go +++ b/internal/workflow/signals.go @@ -138,6 +138,11 @@ func configureSignalHandler(myTargets []target.Target, statusFunc progress.Multi if err != nil { slog.Error("failed to send SIGKILL signal to target controller", slog.String("target", tgt.GetName()), slog.String("error", err.Error())) } + // SIGKILL to the controller alone leaves its probes running: they are + // in their own process groups and are not its children's children by + // the time it dies. The controller is past cleaning up after itself + // here, so reap the whole tree directly. + script.CleanupAbandonedController(tgt) break } // sleep for a short time before checking again diff --git a/tools/Makefile b/tools/Makefile index 711ddaf8..98072c8c 100644 --- a/tools/Makefile +++ b/tools/Makefile @@ -93,14 +93,20 @@ endif tar -xf async-profiler-$(ASYNC_PROFILER_VERSION)-linux-arm64.tar.gz && mv async-profiler-$(ASYNC_PROFILER_VERSION)-linux-arm64 async-profiler-aarch64 endif -AVX_TURBO_VERSION := 9cfe8bf +# Must be the full 40-character SHA: the pinned commit is fetched by name below, and +# the git wire protocol will not resolve an abbreviated SHA. +AVX_TURBO_VERSION := 9cfe8bf3089636b98d9a7eaa97b9fef268004a1b avx-turbo: ifeq ("$(wildcard avx-turbo)","") - git clone $(GIT_CLONE_OPTS) https://github.com/travisdowns/avx-turbo.git -else - cd avx-turbo && git fetch && git checkout $(AVX_TURBO_VERSION) -endif - cd avx-turbo && git checkout $(AVX_TURBO_VERSION) + # Deliberately not GIT_CLONE_OPTS: a --depth 1 clone contains only the tip of the + # default branch, so checking out any other commit fails as soon as upstream pushes + # past the pin. Fetching the pinned commit itself stays shallow and stays valid. + git init -q avx-turbo + cd avx-turbo && git remote add origin https://github.com/travisdowns/avx-turbo.git +endif + cd avx-turbo && git fetch --depth 1 origin $(AVX_TURBO_VERSION) + # -f discards the patches a previous run applied, so this target is re-runnable + cd avx-turbo && git checkout -f --detach $(AVX_TURBO_VERSION) # apply our patches to avx-turbo, aperf/mperf first because it doesn't add/remove any lines cd avx-turbo && git apply ../avx-turbo-patches/0001-use-fixed-CPU-number-to-determine-if-APERF-MPERF-are.patch cd avx-turbo && git apply ../avx-turbo-patches/0001-Add-CPU-ID-pinning-option.patch