From 751defaeaffa361d83c9e21451fb916456bdd62a Mon Sep 17 00:00:00 2001 From: Dennison Date: Tue, 8 Sep 2026 07:18:57 -0400 Subject: [PATCH] fix(cli): cleanup no longer killed by its own status message MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `go-code runs | head` left harnessd running. The orphan holds the workspace lock, so the next go-code in that project died ~11s later with "callback workspace is already owned" — and the wrapper's error hint suggested a port conflict, which cannot be the cause, because the lock is workspace-scoped rather than port-scoped. The script runs under `set -euo pipefail`, and stop_server's first statement was an info line. With stdout closed that write fails, `set -e` aborts the function, and the kill on the next line never runs. Cleanup was killed by its own status message. `|| true` on the printf is not sufficient on its own: a SIGPIPE taken while the EXIT trap is running terminates the shell instead of returning control to the trap. So stop_server now ignores PIPE outright, making cleanup immune to writing rather than merely tolerant of it. The EXIT trap is also armed the moment the daemon is spawned rather than at mode dispatch, which closes the window in between and collapses three per-mode arms into one owner of the contract. Closes #1416 Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01WJGxhoFhA8JjkwZFcLGdS5 --- cmd/harnesscli/go_code_script_test.go | 201 ++++++++++++++++++++++++++ docs/logs/engineering-log.md | 62 ++++++++ scripts/go-code.sh | 43 +++--- website/docs/cli/go-code-wrapper.md | 6 + 4 files changed, 295 insertions(+), 17 deletions(-) diff --git a/cmd/harnesscli/go_code_script_test.go b/cmd/harnesscli/go_code_script_test.go index 6d11a934..9ce9fbd5 100644 --- a/cmd/harnesscli/go_code_script_test.go +++ b/cmd/harnesscli/go_code_script_test.go @@ -7,8 +7,11 @@ import ( "os" "os/exec" "path/filepath" + "strconv" "strings" + "syscall" "testing" + "time" ) func TestGoCodeScriptRoutesDailyCommands(t *testing.T) { @@ -285,3 +288,201 @@ func TestGoCodeScriptSurfacesHarnessdLogOnStartupFailure(t *testing.T) { t.Fatalf("startup failure did not report the harnessd log path:\n%s", out) } } + +// TestGoCodeScriptStopsHarnessdOnInterrupt pins the cleanup contract of issue +// #1416: a harnessd the wrapper started must not outlive the wrapper, however +// the wrapper exits — including Ctrl+C, which is the way users actually abort. +// +// An orphan holds the workspace lock (internal/harness/tools/delayed_callback_store.go), +// so the next go-code in that project dies with "callback workspace is already +// owned" — a message that names neither the cause nor the remedy. This test +// reproduces the orphan itself rather than that downstream symptom. +func TestGoCodeScriptStopsHarnessdOnInterrupt(t *testing.T) { + scriptPath, err := filepath.Abs(filepath.Join("..", "..", "scripts", "go-code.sh")) + if err != nil { + t.Fatalf("resolve go-code script path: %v", err) + } + + for _, tc := range []struct { + name string + // startedByWrapper false simulates a daemon the user already had + // running: the health check succeeds immediately, so the wrapper + // never starts one and must never kill it. + startedByWrapper bool + }{ + {name: "wrapper-started daemon is stopped", startedByWrapper: true}, + {name: "pre-existing daemon is left alone", startedByWrapper: false}, + } { + t.Run(tc.name, func(t *testing.T) { + tmp := t.TempDir() + binDir := t.TempDir() + pidFile := filepath.Join(tmp, "harnessd.pid") + countFile := filepath.Join(tmp, "curl.count") + + failFirst := "0" + if tc.startedByWrapper { + failFirst = "1" + } + writeExecutable(t, filepath.Join(binDir, "curl"), "#!/usr/bin/env bash\nf=\"$CURL_COUNT_FILE\"\nn=0\nif [ -f \"$f\" ]; then n=$(cat \"$f\"); fi\nn=$((n+1))\necho \"$n\" > \"$f\"\nif [ \"${CURL_FAIL_FIRST:-0}\" = \"1\" ] && [ \"$n\" -eq 1 ]; then exit 1; fi\nexit 0\n") + // harnessd: record own PID, then outlive the wrapper unless stopped. + // Ignores SIGINT, so it survives the process-group signal a real + // Ctrl+C delivers. Only an explicit stop from the wrapper ends it — + // which is exactly the orphan this test is about. + writeExecutable(t, filepath.Join(binDir, "harnessd"), "#!/usr/bin/env bash\ntrap '' INT\necho $$ > \"$DAEMON_PID_FILE\"\nsleep 300\n") + // harnesscli: keep the wrapper alive so it is still running when signalled. + writeExecutable(t, filepath.Join(binDir, "harnesscli"), "#!/usr/bin/env bash\nsleep 300\n") + + cmd := exec.Command("bash", scriptPath, "runs") + cmd.Env = append(os.Environ(), + "PATH="+binDir+string(os.PathListSeparator)+os.Getenv("PATH"), + "HARNESS_ADDR=:19620", + "DAEMON_PID_FILE="+pidFile, + "CURL_COUNT_FILE="+countFile, + "CURL_FAIL_FIRST="+failFirst, + ) + // Own process group so the signal goes to the wrapper alone, not to + // the whole test process group. + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + if err := cmd.Start(); err != nil { + t.Fatalf("start go-code: %v", err) + } + defer func() { + _ = cmd.Process.Kill() + _, _ = cmd.Process.Wait() + }() + + var daemonPID int + if tc.startedByWrapper { + daemonPID = waitForPIDFile(t, pidFile) + // Control: the daemon must be alive before the signal, or a + // passing test would prove nothing. + if !processAlive(daemonPID) { + t.Fatalf("stub harnessd (pid %d) was not running before the interrupt", daemonPID) + } + } else { + // Give the wrapper time to reach harnesscli; it must not have + // started a daemon at all. + time.Sleep(2 * time.Second) + if _, err := os.Stat(pidFile); err == nil { + t.Fatal("wrapper started a daemon even though one was already healthy") + } + // Stand up an unrelated daemon-like process to prove it survives. + sleeper := exec.Command("sleep", "300") + if err := sleeper.Start(); err != nil { + t.Fatalf("start stand-in daemon: %v", err) + } + defer func() { _ = sleeper.Process.Kill(); _, _ = sleeper.Process.Wait() }() + daemonPID = sleeper.Process.Pid + } + + // A real Ctrl+C goes to the foreground process group, not to bash + // alone. Signalling only the wrapper would deadlock: bash defers a + // trap until the foreground child exits, and that child sleeps. + if err := syscall.Kill(-cmd.Process.Pid, syscall.SIGINT); err != nil { + t.Fatalf("signal wrapper process group: %v", err) + } + waitDone := make(chan struct{}) + go func() { _, _ = cmd.Process.Wait(); close(waitDone) }() + select { + case <-waitDone: + case <-time.After(10 * time.Second): + t.Fatal("wrapper did not exit within 10s of SIGINT") + } + + deadline := time.Now().Add(8 * time.Second) + for time.Now().Before(deadline) { + if tc.startedByWrapper && !processAlive(daemonPID) { + return // cleaned up as required + } + time.Sleep(100 * time.Millisecond) + } + + if tc.startedByWrapper { + t.Fatalf("harnessd (pid %d) still running after the wrapper was interrupted; "+ + "it will hold the workspace lock and break the next go-code", daemonPID) + } + if !processAlive(daemonPID) { + t.Fatal("wrapper killed a daemon it did not start") + } + }) + } +} + +// waitForPIDFile blocks until the stub daemon has recorded its PID. +func waitForPIDFile(t *testing.T, path string) int { + t.Helper() + deadline := time.Now().Add(10 * time.Second) + for time.Now().Before(deadline) { + raw, err := os.ReadFile(path) + if err == nil { + if pid, convErr := strconv.Atoi(strings.TrimSpace(string(raw))); convErr == nil && pid > 0 { + return pid + } + } + time.Sleep(50 * time.Millisecond) + } + t.Fatalf("stub harnessd never recorded a pid at %s", path) + return 0 +} + +// processAlive reports whether pid is still running. Signal 0 performs the +// permission and existence check without delivering anything. +func processAlive(pid int) bool { + proc, err := os.FindProcess(pid) + if err != nil { + return false + } + return proc.Signal(syscall.Signal(0)) == nil +} + +// TestGoCodeScriptStopsHarnessdWhenOutputPipeCloses pins the other half of the +// cleanup contract in issue #1416, and the half that actually orphans daemons +// in practice: `go-code runs | head -5`, or piping into a pager the user quits. +// +// When the reader closes early the wrapper dies of SIGPIPE, and bash does not +// run an EXIT trap for a shell killed by a signal it has no handler for. The +// daemon is left holding the workspace lock, so the next go-code in that +// project fails with "callback workspace is already owned". +// +// Ctrl+C, by contrast, is already handled correctly — see +// TestGoCodeScriptStopsHarnessdOnInterrupt. +func TestGoCodeScriptStopsHarnessdWhenOutputPipeCloses(t *testing.T) { + scriptPath, err := filepath.Abs(filepath.Join("..", "..", "scripts", "go-code.sh")) + if err != nil { + t.Fatalf("resolve go-code script path: %v", err) + } + + tmp := t.TempDir() + binDir := t.TempDir() + pidFile := filepath.Join(tmp, "harnessd.pid") + countFile := filepath.Join(tmp, "curl.count") + + writeExecutable(t, filepath.Join(binDir, "curl"), "#!/usr/bin/env bash\nf=\"$CURL_COUNT_FILE\"\nn=0\nif [ -f \"$f\" ]; then n=$(cat \"$f\"); fi\nn=$((n+1))\necho \"$n\" > \"$f\"\nif [ \"$n\" -eq 1 ]; then exit 1; fi\nexit 0\n") + writeExecutable(t, filepath.Join(binDir, "harnessd"), "#!/usr/bin/env bash\necho $$ > \"$DAEMON_PID_FILE\"\nsleep 300\n") + // Emit far more than the reader will consume, so the write lands on a + // closed pipe — exactly what a real `runs` listing into `head` does. + writeExecutable(t, filepath.Join(binDir, "harnesscli"), "#!/usr/bin/env bash\nfor i in $(seq 1 500); do echo \"run_$i completed\"; done\n") + + cmd := exec.Command("bash", "-c", scriptPath+" runs 2>&1 | head -5 >/dev/null") + cmd.Env = append(os.Environ(), + "PATH="+binDir+string(os.PathListSeparator)+os.Getenv("PATH"), + "HARNESS_ADDR=:19640", + "DAEMON_PID_FILE="+pidFile, + "CURL_COUNT_FILE="+countFile, + ) + if err := cmd.Run(); err != nil { + t.Fatalf("pipeline failed: %v", err) + } + + daemonPID := waitForPIDFile(t, pidFile) + + deadline := time.Now().Add(8 * time.Second) + for time.Now().Before(deadline) { + if !processAlive(daemonPID) { + return // cleaned up as required + } + time.Sleep(100 * time.Millisecond) + } + t.Fatalf("harnessd (pid %d) still running after the wrapper's output pipe closed; "+ + "it will hold the workspace lock and break the next go-code in this project", daemonPID) +} diff --git a/docs/logs/engineering-log.md b/docs/logs/engineering-log.md index 02f528cd..e493a76b 100644 --- a/docs/logs/engineering-log.md +++ b/docs/logs/engineering-log.md @@ -1,5 +1,67 @@ # Engineering Log +## 2026-09-08 — Issue #1416 closed output pipe orphaned harnessd + +- Symptom: `go-code runs | head -5` (or piping into a pager the user quits + early) left `harnessd` running after the wrapper exited. The orphaned + daemon holds the workspace's callback-recovery lock + (`internal/harness/tools/delayed_callback_store.go:156`), so the next + `go-code` invocation in that project died about 11 seconds later with + `fatal: recover callbacks: acquire callback recovery authority: callback + workspace is already owned: resource temporarily unavailable`. The + wrapper's own error hint made it worse by suggesting a port conflict — + advice that cannot work, since the lock is workspace-scoped, not + port-scoped. +- Cause, confirmed with a `bash -x` trace rather than inferred: the script + runs under `set -euo pipefail` (`scripts/go-code.sh:2`). `stop_server()`'s + first statement after its guards was an `info "stopping harnessd (pid + ...)"` call, which writes to stdout. With stdout already closed, that + write fails, `set -e` aborts the function right there, and the `kill + "$pid"` on the next line never runs. Cleanup was killed by its own status + message. The trace ended exactly at: + ``` + + info 'stopping harnessd (pid 42794)' + + printf '%s %s\n' '[go-code]' 'stopping harnessd (pid 42794)' + scripts/go-code.sh: line 99: printf: write error: Broken pipe + ``` +- Fix: `trap '' PIPE` at the top of `stop_server()` (`scripts/go-code.sh:178`) + so cleanup can no longer be killed by a failed write — necessary on its + own, because `|| true` alone did **not** fix the leak: a `SIGPIPE` taken + while the `EXIT` trap is already running terminates the shell outright + instead of returning control to the trap, which was verified by + re-running the trace with only the `|| true` guard in place and still + seeing the daemon leak. `|| true` was then added to the `printf` calls in + `info`, `warn`, `die` (`scripts/go-code.sh:99-101`), and in + `show_harnessd_log`, so a status line can never abort its caller under + `set -e`. The `EXIT` trap is now armed in `start_server()` + (`scripts/go-code.sh:281`) immediately after the daemon is spawned, + replacing three separate per-mode `trap stop_server EXIT` arms in `main()` + (tui/prompt/cli), so there is one owner of the cleanup contract and no + window between spawning the daemon and arming its cleanup. +- The durable lesson: under `set -e`, a status message inside a cleanup path + is load-bearing, and a `SIGPIPE` taken during an `EXIT` trap kills the + shell rather than returning to it — so cleanup must be immune to write + failures, not merely tolerant of them. +- The corrected diagnosis: issue #1416 was originally filed claiming Ctrl+C + (`SIGINT`) caused the leak. That was wrong. The evidence was an artifact + of how the reproduction was run: the wrapper was signalled alone rather + than as a process group, so bash deferred its trap while a foreground + child was running, and the liveness check happened while the wrapper was + still alive — making it look like Ctrl+C failed to clean up when it + actually just hadn't run yet. Ctrl+C is handled correctly; the real + trigger is a closed output pipe, not a signal, and the fix was found by + `bash -x` tracing the pipe case, not by reasoning about signals. An + earlier draft of the fix added `INT`/`TERM`/`HUP`/`PIPE` signal traps and + an `on_signal` helper; those were removed — they were written against the + wrong mechanism and were not needed. +- Tests: `TestGoCodeScriptStopsHarnessdWhenOutputPipeCloses` + (`cmd/harnesscli/go_code_script_test.go`) is the real bug, red first with + `harnessd (pid 41667) still running after the wrapper's output pipe + closed`. `TestGoCodeScriptStopsHarnessdOnInterrupt` covers two cases + (wrapper-started daemon stopped; pre-existing daemon left alone), + signalling the whole process group as a real Ctrl+C does; it passes today + and is a guard against regression, not a red-first test. + ## 2026-09-08 — Issue #1413 readable go-code startup output - Symptom: `go-code` printed 13 lines of undifferentiated output on a normal diff --git a/scripts/go-code.sh b/scripts/go-code.sh index 23db07ff..3c196f3f 100755 --- a/scripts/go-code.sh +++ b/scripts/go-code.sh @@ -91,9 +91,14 @@ style() { fi } -info() { printf '%s %s\n' "$(style 1 '36' '[go-code]')" "$*"; } -warn() { printf '%s %s %s\n' "$(style 2 '33' '[go-code]')" "$(style 2 '1;33' 'WARN:')" "$*" >&2; } -die() { printf '%s %s %s\n' "$(style 2 '31' '[go-code]')" "$(style 2 '1;31' 'ERROR:')" "$*" >&2; show_harnessd_log; exit 1; } +# The `|| true` on each printf is load-bearing, not defensive noise: this script +# runs under `set -e`, and a write to a closed stdout (`go-code runs | head`) +# fails with EPIPE. Without the guard, a status line aborts its caller — which +# orphaned the daemon, because stop_server's first statement is an info line and +# the kill never ran. Issue #1416. +info() { printf '%s %s\n' "$(style 1 '36' '[go-code]')" "$*" || true; } +warn() { printf '%s %s %s\n' "$(style 2 '33' '[go-code]')" "$(style 2 '1;33' 'WARN:')" "$*" >&2 || true; } +die() { printf '%s %s %s\n' "$(style 2 '31' '[go-code]')" "$(style 2 '1;31' 'ERROR:')" "$*" >&2 || true; show_harnessd_log; exit 1; } # show_harnessd_log prints the captured daemon log when a wrapper-started # harnessd failed. The daemon's stdout is redirected to a file so a healthy @@ -103,17 +108,17 @@ die() { printf '%s %s %s\n' "$(style 2 '31' '[go-code]')" "$(style 2 '1;31' 'E # a long fatal message stays emphasized across the terminal's soft wrap. show_harnessd_log() { [[ -n "${HARNESSD_LOG:-}" && -s "${HARNESSD_LOG:-}" ]] || return 0 - printf '\n %s\n' "$(style 2 '1' 'harnessd said:')" >&2 + printf '\n %s\n' "$(style 2 '1' 'harnessd said:')" >&2 || true local line while IFS= read -r line; do case "$line" in *fatal:*|*panic:*|*"refusing to start"*) - printf ' %s\n' "$(style 2 '1;31' "$line")" >&2 ;; + printf ' %s\n' "$(style 2 '1;31' "$line")" >&2 || true ;; *) - printf ' %s\n' "$(style 2 '2' "$line")" >&2 ;; + printf ' %s\n' "$(style 2 '2' "$line")" >&2 || true ;; esac done < <(tail -n 20 "$HARNESSD_LOG") - printf '\n %s %s\n\n' "$(style 2 '2' 'full log:')" "$HARNESSD_LOG" >&2 + printf '\n %s %s\n\n' "$(style 2 '2' 'full log:')" "$HARNESSD_LOG" >&2 || true } require_command() { @@ -164,6 +169,14 @@ PID_FILE="" STARTED_BY_US=0 stop_server() { + # Cleanup must not depend on being able to write. This runs from the EXIT + # trap, often with stdout already closed (`go-code runs | head`), and a + # SIGPIPE taken here kills the shell mid-trap — the daemon then survives and + # holds the workspace lock, breaking the next go-code in the project. + # Ignoring PIPE turns that fatal signal into an EPIPE the `|| true` in info() + # absorbs, so the kill below always runs. Issue #1416. + trap '' PIPE + if [[ "$STARTED_BY_US" -ne 1 ]]; then return 0 fi @@ -261,6 +274,12 @@ start_server() { echo "$pid" > "$PID_FILE" STARTED_BY_US=1 + # Arm cleanup the moment the daemon exists, rather than at mode dispatch + # further below: anything that exits in between would orphan it. stop_server + # checks STARTED_BY_US itself, so this can never touch a daemon we did not + # start. Issue #1416. + trap stop_server EXIT + # Wait up to 10 s for /healthz to return 200. info "waiting for server to become healthy (pid ${pid})..." local waited=0 @@ -439,10 +458,6 @@ main() { echo "${base_url}" ;; tui) - # Only stop what we started. - if [[ "$STARTED_BY_US" -eq 1 ]]; then - trap stop_server EXIT - fi if [[ -n "$resume_id" ]]; then harnesscli -base-url "$base_url" -workspace "$project_root" --tui -resume "$resume_id" else @@ -450,15 +465,9 @@ main() { fi ;; prompt) - if [[ "$STARTED_BY_US" -eq 1 ]]; then - trap stop_server EXIT - fi harnesscli -base-url "$base_url" -workspace "$project_root" -prompt "$prompt" ;; cli) - if [[ "$STARTED_BY_US" -eq 1 ]]; then - trap stop_server EXIT - fi harnesscli "$cli_command" -base-url "$base_url" ${cli_args[@]+"${cli_args[@]}"} ;; esac diff --git a/website/docs/cli/go-code-wrapper.md b/website/docs/cli/go-code-wrapper.md index eddbc29c..e195f72d 100644 --- a/website/docs/cli/go-code-wrapper.md +++ b/website/docs/cli/go-code-wrapper.md @@ -191,6 +191,12 @@ If `harnessd` fails to become healthy, `go-code` prints the last 20 lines of tha The wrapper colors its own `[go-code]` prefix and the `WARN:`/`ERROR:` markers (cyan, yellow, red) when writing to a terminal. Color is never the only signal — the words `WARN:` and `ERROR:` always stay in the text. Color is disabled, and output is plain text, whenever `NO_COLOR` is set, `TERM=dumb`, or the given output stream (stdout or stderr) isn't a terminal — for example when you pipe `go-code` into another command. stdout and stderr are checked independently, since one can be redirected without the other. +Piping `go-code` into a command that exits early — `go-code runs | head -5`, or any pager you quit before it reaches the end of the output — still stops a daemon the wrapper started. Closing the read end of the pipe makes the wrapper's own status writes fail (`SIGPIPE`/`EPIPE`), but that failure can no longer stop the shutdown itself: `stop_server` ignores `PIPE` before doing anything else, and every status line is written with `|| true`, so a write failure never skips the `kill` that stops `harnessd`. + +### Troubleshooting: a stale `harnessd` left behind + +If a `harnessd` the wrapper started is ever left running after `go-code` exits — for example after a crash rather than a normal exit — the symptom on your next `go-code` invocation in that project is a failure like `callback workspace is already owned: resource temporarily unavailable`, because the leftover daemon still holds the workspace's callback-recovery lock. Changing `HARNESS_ADDR` or the port does not help: the lock is scoped to the workspace, not the port. The remedy is to stop the stray process directly, for example `pkill -f harnessd`, then run `go-code` again. + ### Project root detection `go-code` automatically resolves the workspace root before launching TUI or prompt mode. It walks parent directories from `$PWD`, looking for: