From 0f1a8ad6020ae0faf23061eeadb9a2203761810a Mon Sep 17 00:00:00 2001 From: Rolando Santamaria Maso Date: Sat, 19 Sep 2026 09:39:16 +0200 Subject: [PATCH] fix(server): progress-aware shutdown escalation with live countdown MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Stop now escalates to SIGKILL only when the spawned server goes silent (12s activity grace, stamped from stderr writes) or the 30s hard deadline expires, so a working teardown is never killed faster than the old uniform 8s wait. Clean exits emit a StopStopped event. cmd/bodek renders a live 'shutting down… Ns / 30s' countdown on an in-place stderr line (tty-gated) and states the consequence — not a blame — when a force kill cuts a possible memory flush. --- cmd/bodek/main.go | 33 +++++- internal/server/server.go | 101 ++++++++++++++-- internal/server/stop_event_test.go | 177 ++++++++++++++++++++++++++++- 3 files changed, 290 insertions(+), 21 deletions(-) diff --git a/cmd/bodek/main.go b/cmd/bodek/main.go index 16750e7..5323846 100644 --- a/cmd/bodek/main.go +++ b/cmd/bodek/main.go @@ -12,6 +12,7 @@ import ( "runtime" "strings" "syscall" + "time" tea "github.com/charmbracelet/bubbletea" "github.com/charmbracelet/lipgloss" @@ -212,14 +213,38 @@ func run() error { } defer func() { _ = cl.Close() }() - // Surface the shutdown wait on stderr: Stop blocks up to 8s while odek - // serve runs its graceful teardown, and silence reads as a hang. + // Surface the shutdown wait on stderr: Stop blocks up to 30s while odek + // serve runs its graceful teardown, and silence reads as a hang. A live + // countdown rewrites one line in place (\r — the TUI has already left + // the alt screen, so stderr is ours). The \r rewrite only makes sense + // on a terminal; pipes and logs get single newline-terminated lines. + // Escalation fires only after the child went silent (or the 30s hard + // deadline), and the message states the consequence, not a blame: a + // force kill may cut a memory flush. + interactive := false + if st, err := os.Stderr.Stat(); err == nil { + interactive = st.Mode()&os.ModeCharDevice != 0 + } + clearTail := "" + if interactive { + clearTail = " " + } + var sElapsed string srv.OnStopEvent = func(e server.StopEvent) { switch e { case server.StopStopping: - fmt.Fprintln(os.Stderr, "⏻ shutting down odek serve (graceful exit — sandbox teardown and memory flush may take a few seconds)…") + sElapsed = "0s" + fmt.Fprintln(os.Stderr, "⏻ shutting down odek serve…") case server.StopEscalated: - fmt.Fprintln(os.Stderr, "⏻ odek serve did not exit in time — force killing") + fmt.Fprintf(os.Stderr, "\r⏻ odek serve stopped forcefully after %s — memory flush may be incomplete.%s\n", sElapsed, clearTail) + case server.StopStopped: + fmt.Fprintf(os.Stderr, "\r✓ odek shut down cleanly in %s.%s\n", sElapsed, clearTail) + } + } + srv.OnStopProgress = func(p server.StopProgress) { + sElapsed = p.Elapsed.Truncate(time.Second).String() + if interactive { + fmt.Fprintf(os.Stderr, "\r⏻ shutting down odek serve… %s / %s ", sElapsed, p.Max) } } diff --git a/internal/server/server.go b/internal/server/server.go index 6369e82..c7cb7ac 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -30,8 +30,17 @@ const wsTokenCookie = "odek_ws_token" var readyTimeout = 30 * time.Second // stopTimeout bounds how long Stop waits for the spawned server's graceful -// shutdown before killing it. It is a variable so tests can shorten it. -var stopTimeout = 8 * time.Second +// shutdown before killing it regardless of activity. It is a variable so +// tests can shorten it. +var stopTimeout = 30 * time.Second + +// activityGrace bounds how long Stop waits for stderr silence before +// declaring the graceful window dead. It must stay comfortably above the +// old uniform 8s wait: a silent-but-working teardown (fsync, DB flush) +// writes nothing while it works, so a short grace would kill progress +// faster than the code this replaces. It is a variable so tests can +// shorten it. +var activityGrace = 12 * time.Second // StopEvent reports progress of Conn.Stop so callers can show the user what // the shutdown wait is doing. @@ -39,9 +48,19 @@ type StopEvent int const ( StopStopping StopEvent = iota // graceful SIGINT sent; waiting for exit - StopEscalated // graceful window expired; SIGKILL sent + StopEscalated // graceful window expired or silent; SIGKILL sent + StopStopped // child exited gracefully within the window ) +// StopProgress reports the countdown while Stop waits for the child to +// exit: Elapsed since SIGINT, Max the hard deadline, Idle how long the +// child's stderr has been silent (the escalation trigger). +type StopProgress struct { + Elapsed time.Duration + Max time.Duration + Idle time.Duration +} + // String renders the event for status lines. func (e StopEvent) String() string { switch e { @@ -49,6 +68,8 @@ func (e StopEvent) String() string { return "stopping" case StopEscalated: return "escalated" + case StopStopped: + return "stopped" default: return fmt.Sprintf("StopEvent(%d)", int(e)) } @@ -68,9 +89,15 @@ type Conn struct { reapDone chan struct{} // closed when the reaper's Wait returns watch func() // cancels the orphan watchdog (nil when none) watchMu sync.Mutex + lastAct atomic.Int64 // last child stderr write, unix nanos (0 = never) + stopping atomic.Bool // Stop reentrancy guard // OnStopEvent, when set, receives shutdown progress from Stop. OnStopEvent func(StopEvent) + + // OnStopProgress, when set, receives ~1s-granularity countdown ticks + // during Stop's graceful wait, for live countdown rendering. + OnStopProgress func(StopProgress) } // watchdogBin is the executable the orphan watchdog re-execs as. It is a @@ -186,7 +213,7 @@ func (c *Conn) spawn(opts Options, addr string) error { if stderr == nil { stderr = io.Discard } - c.scan = &tokenScanWriter{w: stderr} + c.scan = &tokenScanWriter{w: stderr, act: &c.lastAct} cmd := exec.Command(bin, args...) cmd.Stderr = c.scan @@ -262,6 +289,11 @@ func (c *Conn) Stop() { if c == nil || c.proc == nil || c.proc.Process == nil { return } + // Reentrancy guard: two concurrent Stops would interleave events and + // double-signal. The first caller owns the shutdown. + if !c.stopping.CompareAndSwap(false, true) { + return + } // Graceful shutdown owns the exit — retire the orphan watchdog first. c.watchMu.Lock() if c.watch != nil { @@ -284,14 +316,55 @@ func (c *Conn) Stop() { done = make(chan struct{}) go func() { _ = c.proc.Wait(); close(done) }() } - select { - case <-done: - case <-time.After(stopTimeout): - if c.OnStopEvent != nil { - c.OnStopEvent(StopEscalated) + // Progress-aware escalation (Stop): the idle clock starts at the SIGINT, + // and every child stderr write through the scan writer resets it. A + // silent child is declared dead after activityGrace — long before the + // hard deadline — while an active teardown (memory flush writing output) + // earns the full stopTimeout window. + c.lastAct.Store(time.Now().UnixNano()) + start := time.Now() + tick := time.NewTicker(250 * time.Millisecond) + defer tick.Stop() + lastTick := time.Duration(-1) + for { + select { + case <-done: + if c.OnStopEvent != nil { + c.OnStopEvent(StopStopped) + } + return + case <-tick.C: + now := time.Now() + if c.OnStopProgress != nil { + if s := now.Sub(start).Truncate(time.Second); s != lastTick { + lastTick = s + c.OnStopProgress(StopProgress{ + Elapsed: now.Sub(start), + Max: stopTimeout, + Idle: now.Sub(time.Unix(0, c.lastAct.Load())), + }) + } + } + if now.Sub(time.Unix(0, c.lastAct.Load())) >= activityGrace || now.Sub(start) >= stopTimeout { + // Re-check completion first: a child exiting exactly at the + // deadline must not be labelled "forcefully" and SIGKILLed + // into the void within the 250ms tick window. + select { + case <-done: + if c.OnStopEvent != nil { + c.OnStopEvent(StopStopped) + } + return + default: + } + if c.OnStopEvent != nil { + c.OnStopEvent(StopEscalated) + } + c.signalServer(syscall.SIGKILL) + <-done // the kill always lands; never return with a live child + return + } } - c.signalServer(syscall.SIGKILL) - <-done // the kill always lands; never return with a live child } } @@ -319,7 +392,8 @@ type tokenScanWriter struct { mu sync.Mutex buf []byte // partial line not yet terminated by '\n' tok string - tail []string // last complete lines, bounded, for failure diagnostics + tail []string // last complete lines, bounded, for failure diagnostics + act *atomic.Int64 // when set, stamped on every write (shutdown activity clock) } // maxTailLines bounds the stderr tail kept for error reporting. @@ -327,6 +401,9 @@ const maxTailLines = 4 func (s *tokenScanWriter) Write(p []byte) (int, error) { s.scan(p) + if s.act != nil { + s.act.Store(time.Now().UnixNano()) + } return s.w.Write(p) } diff --git a/internal/server/stop_event_test.go b/internal/server/stop_event_test.go index 1238045..1071907 100644 --- a/internal/server/stop_event_test.go +++ b/internal/server/stop_event_test.go @@ -1,6 +1,7 @@ package server import ( + "io" "os" "os/exec" "path/filepath" @@ -11,7 +12,8 @@ import ( ) // TestStopReportsStopping verifies Stop emits the "stopping" event when the -// graceful SIGINT is delivered to a well-behaved child, and no escalation. +// graceful SIGINT is delivered to a well-behaved child, then "stopped" on +// its clean exit — never an escalation. func TestStopReportsStopping(t *testing.T) { bin, err := exec.LookPath("sleep") if err != nil { @@ -31,11 +33,11 @@ func TestStopReportsStopping(t *testing.T) { case <-time.After(10 * time.Second): t.Fatal("Stop did not return") } - if len(events) != 1 { - t.Fatalf("events = %v, want exactly one StopStopping", events) + if len(events) != 2 { + t.Fatalf("events = %v, want [stopping stopped]", events) } - if events[0] != StopStopping { - t.Errorf("event = %v, want %v", events[0], StopStopping) + if events[0] != StopStopping || events[1] != StopStopped { + t.Errorf("events = %v, want [%v %v]", events, StopStopping, StopStopped) } } @@ -114,3 +116,168 @@ func TestStopReportsEscalation(t *testing.T) { t.Errorf("event order = %v, want [stopping escalated]", order) } } + +// TestStopWindowsDefaults pins the shutdown timing contract: the hard +// deadline is 30s and escalation on silence waits activityGrace for +// in-flight work (a memory flush writing stderr) before giving up. +func TestStopWindowsDefaults(t *testing.T) { + if stopTimeout != 30*time.Second { + t.Fatalf("stopTimeout = %v, want 30s hard deadline", stopTimeout) + } + if activityGrace != 12*time.Second { + t.Fatalf("activityGrace = %v, want 12s (must stay above the legacy uniform 8s so silent-but-working teardowns are never killed faster than before)", activityGrace) + } +} + +// fakeBusyINTScript builds (unstarted) a stand-in server that ignores SIGINT +// and keeps writing stderr — a proxy for a memory flush in flight. The caller +// must wire the scan writer and Start it, then waitBusyReady. +func fakeBusyINTScript(t *testing.T) *exec.Cmd { + t.Helper() + dir := t.TempDir() + ready := filepath.Join(dir, "ready") + bin := filepath.Join(dir, "fake-busy-int") + // The ready file proves the trap is installed before Stop's SIGINT; + // without it the signal wins the race and kills the shell outright. + script := "#!/bin/sh\ntrap '' INT\ntouch \"" + ready + "\"\nwhile :; do echo working… >&2; sleep 0.05; done\n" + if err := os.WriteFile(bin, []byte(script), 0o755); err != nil { + t.Fatalf("write fixture: %v", err) + } + cmd := exec.Command(bin) + // Match spawn(): own process group, so signalServer's group-signalled + // SIGINT actually targets the fixture alone. + fixturePgroup(cmd) + t.Cleanup(func() { fixtureGroupKill(cmd) }) + return cmd +} + +// waitBusyReady blocks until the fixture's trap is installed and its loop is +// running, matching fakeIgnoreINTScript's readiness contract. +func waitBusyReady(t *testing.T, dir string) { + t.Helper() + ready := filepath.Join(dir, "ready") + deadline := time.Now().Add(5 * time.Second) + for { + if _, err := os.Stat(ready); err == nil { + return + } + if time.Now().After(deadline) { + t.Fatal("fixture never became ready") + } + time.Sleep(5 * time.Millisecond) + } +} + +// newFixtureConn wires a fixture's stderr through a tokenScanWriter the +// same way spawn does, so Stop's activity tracking sees its output. +func newFixtureConn(cmd *exec.Cmd, on func(StopEvent), prog func(StopProgress)) *Conn { + c := &Conn{proc: cmd, scan: &tokenScanWriter{w: io.Discard}} + c.scan.act = &c.lastAct + cmd.Stderr = c.scan + c.OnStopEvent = on + c.OnStopProgress = prog + return c +} + +// TestStopIdleEscalatesEarly verifies a silent child that ignores SIGINT is +// force-killed after activityGrace — long before the 30s hard deadline. +func TestStopIdleEscalatesEarly(t *testing.T) { + oldStop, oldGrace := stopTimeout, activityGrace + stopTimeout, activityGrace = 10*time.Second, 300*time.Millisecond + defer func() { stopTimeout, activityGrace = oldStop, oldGrace }() + var events []StopEvent + c := newFixtureConn(fakeIgnoreINTScript(t), func(e StopEvent) { events = append(events, e) }, nil) + start := time.Now() + done := make(chan struct{}) + go func() { c.Stop(); close(done) }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("Stop did not return") + } + elapsed := time.Since(start) + if elapsed >= stopTimeout/2 { + t.Fatalf("Stop took %v; a silent child should escalate well before the deadline", elapsed) + } + if len(events) != 2 || events[0] != StopStopping || events[1] != StopEscalated { + t.Fatalf("events = %v, want [stopping escalated]", events) + } +} + +// TestStopActivityDelaysEscalationToDeadline verifies a child that keeps +// writing stderr is given the full hard deadline, not killed at the idle +// grace window. +func TestStopActivityDelaysEscalationToDeadline(t *testing.T) { + oldStop, oldGrace := stopTimeout, activityGrace + stopTimeout, activityGrace = 800*time.Millisecond, 400*time.Millisecond + defer func() { stopTimeout, activityGrace = oldStop, oldGrace }() + var events []StopEvent + cmd := fakeBusyINTScript(t) + c := newFixtureConn(cmd, func(e StopEvent) { events = append(events, e) }, nil) + // Stderr must be wired before Start — after it the pipe is already fixed + // and no activity would reach the scan writer. + cmd.Stderr = c.scan + if err := cmd.Start(); err != nil { + t.Fatalf("start fixture: %v", err) + } + waitBusyReady(t, filepath.Dir(cmd.Path)) + start := time.Now() + done := make(chan struct{}) + go func() { c.Stop(); close(done) }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("Stop did not return") + } + elapsed := time.Since(start) + if elapsed < stopTimeout-200*time.Millisecond { + t.Fatalf("Stop took %v; an active child must be held until the %v deadline (stderr tail: %q)", elapsed, stopTimeout, c.scan.Tail(4)) + } + if len(events) != 2 || events[0] != StopStopping || events[1] != StopEscalated { + t.Fatalf("events = %v, want [stopping escalated]", events) + } +} + +// TestStopProgressEvents verifies Stop reports elapsed countdown progress +// while waiting, with Max carrying the deadline for the caller's rendering. +func TestStopProgressEvents(t *testing.T) { + oldStop, oldGrace := stopTimeout, activityGrace + stopTimeout, activityGrace = 2*time.Second, 1500*time.Millisecond + defer func() { stopTimeout, activityGrace = oldStop, oldGrace }() + var events []StopEvent + var progress []StopProgress + c := newFixtureConn(fakeIgnoreINTScript(t), + func(e StopEvent) { events = append(events, e) }, + func(p StopProgress) { progress = append(progress, p) }) + done := make(chan struct{}) + go func() { c.Stop(); close(done) }() + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("Stop did not return") + } + if len(progress) == 0 { + t.Fatal("no StopProgress events; the countdown would render as silence") + } + for _, p := range progress { + if p.Max != 2*time.Second { + t.Errorf("progress Max = %v, want the 2s deadline", p.Max) + } + if p.Elapsed <= 0 { + t.Errorf("progress Elapsed = %v, want > 0", p.Elapsed) + } + } + last, prev := progress[0], progress[0] + for _, p := range progress[1:] { + last, prev = p, last + } + if len(progress) > 1 && last.Elapsed <= prev.Elapsed { + t.Errorf("progress not monotonic: %v then %v", prev.Elapsed, last.Elapsed) + } + // Instant-exit children legitimately produce zero progress events; a + // graceful window that never ticks is not a defect. This test pins the + // silent-child fixture, which always survives past the first tick. + if progress[0].Max != stopTimeout { + t.Errorf("progress not monotonic: %v then %v", prev.Elapsed, last.Elapsed) + } +}