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: