diff --git a/CLAUDE.md b/CLAUDE.md index 80a03dab1..59779b90e 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -174,7 +174,7 @@ mcpproxy upstream logs --follow # per-server logs tail -f ~/Library/Logs/mcpproxy/main.log # main log (macOS; Linux: ~/.mcpproxy/logs/main.log) ``` -**Exit codes**: 0 success · 1 general · 2 port conflict · 3 DB locked · 4 config · 5 permission. +**Exit codes**: 0 success · 1 general · 2 port conflict · 3 DB locked · 4 config · 5 permission · 6 shutdown timeout (graceful shutdown exceeded its 60s hard deadline after SIGINT/SIGTERM). ## Development Guidelines diff --git a/cmd/mcpproxy/exit_codes.go b/cmd/mcpproxy/exit_codes.go index f551f7a93..3dffea217 100644 --- a/cmd/mcpproxy/exit_codes.go +++ b/cmd/mcpproxy/exit_codes.go @@ -28,8 +28,15 @@ const ( // ExitCodePermissionError indicates insufficient permissions (file access, port binding) ExitCodePermissionError = 5 + // ExitCodeShutdownTimeout indicates graceful shutdown exceeded its hard + // deadline after a SIGINT/SIGTERM and the process killed itself so a + // supervisor (launchd/systemd, or the tray's process monitor) can restart + // it. It is deliberately NOT produced by classifyError: it is not a + // startup outcome, it is a shutdown that never finished. + ExitCodeShutdownTimeout = 6 + // Spec 098 preflight verdict codes. They are a SEPARATE band from the codes - // above on purpose: 0-5 describe whether mcpproxy could run, 10-12 describe + // above on purpose: 0-6 describe whether mcpproxy could run (or stop), 10-12 describe // what a preflight found, so a cron wrapper can branch retry-vs-page-vs-fix // on the exit code alone without parsing JSON (SC-003). Their values are the // spec's, and preflight.ExitCode is the single mapping — these constants diff --git a/cmd/mcpproxy/main.go b/cmd/mcpproxy/main.go index 7e6937295..b474d76bf 100644 --- a/cmd/mcpproxy/main.go +++ b/cmd/mcpproxy/main.go @@ -32,7 +32,6 @@ import ( "strings" "sync/atomic" "syscall" - "time" "github.com/spf13/cobra" bbolterrors "go.etcd.io/bbolt/errors" @@ -623,35 +622,26 @@ func runServer(cmd *cobra.Command, _ []string) error { var receivedSignal atomic.Value receivedSignal.Store("") - // Setup signal handling for graceful shutdown with force quit on second signal + // Setup signal handling for graceful shutdown with force quit on a further + // signal and a hard deadline so a wedged shutdown cannot make the daemon + // unkillable. See runSignalHandler in signal_handler.go. + // + // This starts BEFORE the log line below on purpose: signal.Notify is + // already registered, so from here until something reads sigChan the + // runtime is swallowing SIGINT/SIGTERM into a one-slot buffer. A log write + // can block (a full disk, a stalled pipe to the tray), and a daemon that + // cannot be killed while it is logging is the bug this handler exists to + // prevent. + go runSignalHandler(signalHandlerDeps{ + sigChan: sigChan, + cancel: cancel, + // Spec 024: Store signal for activity logging. + onSignal: func(sig os.Signal) { receivedSignal.Store(sig.String()) }, + exit: os.Exit, + logger: logger, + }) logger.Info("Signal handler goroutine starting - waiting for SIGINT or SIGTERM") _ = logger.Sync() - go func() { - logger.Info("Signal handler goroutine is running, waiting for signal on channel") - _ = logger.Sync() - sig := <-sigChan - receivedSignal.Store(sig.String()) // Spec 024: Store signal for activity logging - logger.Info("Received signal, shutting down", zap.String("signal", sig.String())) - _ = logger.Sync() // Flush logs immediately so we can see shutdown messages - logger.Info("Press Ctrl+C again within 10 seconds to force quit") - _ = logger.Sync() // Flush again - cancel() - - // Start a timer for force quit - forceQuitTimer := time.NewTimer(10 * time.Second) - defer forceQuitTimer.Stop() - - // Wait for second signal or timeout - select { - case sig2 := <-sigChan: - logger.Warn("Received second signal, forcing immediate exit", zap.String("signal", sig2.String())) - _ = logger.Sync() - os.Exit(ExitCodeGeneralError) - case <-forceQuitTimer.C: - // Normal shutdown timeout - continue with graceful shutdown - logger.Debug("Force quit timer expired, continuing with graceful shutdown") - } - }() // Start the server logger.Info("Starting mcpproxy server") diff --git a/cmd/mcpproxy/signal_handler.go b/cmd/mcpproxy/signal_handler.go new file mode 100644 index 000000000..40631c946 --- /dev/null +++ b/cmd/mcpproxy/signal_handler.go @@ -0,0 +1,146 @@ +package main + +import ( + "context" + "os" + "sync" + "time" + + "go.uber.org/zap" +) + +const ( + // shutdownGraceWindow is how long we wait before reminding the operator + // that the force-quit shortcut is still available. It does NOT bound the + // shutdown itself. + shutdownGraceWindow = 10 * time.Second + + // shutdownHardDeadline bounds graceful shutdown as a whole, measured from + // the first signal. 60s is MCPProxy's chosen bound: long enough for Docker + // container cleanup, short enough that a supervisor can restart a wedged + // daemon instead of waiting for a human with SIGKILL. It sits under + // systemd's 90s DefaultTimeoutStopSec, so systemd's own SIGKILL stays a + // backstop rather than the normal outcome. + shutdownHardDeadline = 60 * time.Second +) + +// signalHandlerDeps are the collaborators of runSignalHandler. Everything that +// touches the process or the clock is injected so the handler can be unit +// tested without real signals, real sleeps or a real os.Exit. +type signalHandlerDeps struct { + // sigChan delivers SIGINT/SIGTERM (signal.Notify in production). + sigChan <-chan os.Signal + // cancel triggers the graceful shutdown path in runServer. + cancel context.CancelFunc + // onSignal records the first signal for Spec 024 activity logging. It MUST + // run before cancel(), because the ctx.Done() branch in runServer reads the + // stored value as soon as it wakes up. + onSignal func(os.Signal) + // exit terminates the process (os.Exit in production). + exit func(int) + // logger is never nil in production; tests pass zap.NewNop(). + logger *zap.Logger + // newTimer returns a channel that fires after the given duration. It is + // called only AFTER the first signal arrives, so both windows are measured + // from that signal rather than from process start. nil means time.After. + newTimer func(time.Duration) <-chan time.Time +} + +// runSignalHandler waits for the first shutdown signal, starts the graceful +// shutdown, and then KEEPS LISTENING until the process dies. +// +// Staying alive is the whole point. signal.Notify stays registered on sigChan +// for the lifetime of the process, so the moment nobody reads that channel the +// Go runtime keeps intercepting SIGINT/SIGTERM (their default disposition is +// disabled) and dropping them into a one-slot buffer. The old handler returned +// as soon as its 10s force-quit timer expired; if shutdown then ran longer +// than that - exactly when an operator is hammering Ctrl+C - the daemon became +// unkillable by anything short of SIGKILL. +// +// The three ways out: +// - a further signal -> immediate exit, ExitCodeGeneralError +// - the hard deadline -> forced exit, ExitCodeShutdownTimeout +// - shutdown completing -> runServer returns and the process exits normally +// +// Both forced exits are decided by a small goroutine that touches nothing but +// channels. Logging is deliberately kept off that path: the failure that wedges +// shutdown (a full disk, a tray that stopped draining the core's stderr pipe) +// is the same failure that wedges the log sink, so a forced exit that had to +// get past a log write first would not be forced at all. +func runSignalHandler(d signalHandlerDeps) { + newTimer := d.newTimer + if newTimer == nil { + newTimer = time.After + } + + // Nothing may run before this receive - not even a log line. Whatever + // blocks here blocks the only reader of sigChan. + sig, open := <-d.sigChan + if !open { + return + } + started := time.Now() + + // Arm both windows FIRST. Every instant spent before this line is an + // instant the "hard" deadline is not counting. + graceWindow := newTimer(shutdownGraceWindow) + hardDeadline := newTimer(shutdownHardDeadline) + + // exiting is closed once some path has asked the process to die. In + // production d.exit never returns, so this only matters to the wait below + // (and to tests): once the decision is made there is nothing left to do. + exiting := make(chan struct{}) + var exitOnce sync.Once + forceExit := func(code int) { + exitOnce.Do(func() { + d.exit(code) + close(exiting) + }) + } + + // handlerDone lets the forcer retire if this function returns first. + handlerDone := make(chan struct{}) + defer close(handlerDone) + + // The forcer: the only goroutine that may end the process, and the only + // reader of sigChan from here on. It never logs. + go func() { + select { + case _, ok := <-d.sigChan: + if !ok { + return + } + forceExit(ExitCodeGeneralError) + case <-hardDeadline: + forceExit(ExitCodeShutdownTimeout) + case <-handlerDone: + } + }() + + d.onSignal(sig) // Spec 024: Store signal for activity logging (must precede cancel) + // Start the graceful shutdown before logging, for the same reason the + // timers are armed before logging: a blocked sink must not delay it. + d.cancel() + + // From here on this goroutine only reports. If the sink is wedged it stalls + // here, and the forcer above still ends the process on time. + d.logger.Info("Received signal, shutting down", zap.String("signal", sig.String())) + _ = d.logger.Sync() // Flush logs immediately so we can see shutdown messages + d.logger.Info("Press Ctrl+C again to force quit", + zap.Int("force_quit_exit_code", ExitCodeGeneralError), + zap.Duration("forced_exit_after", shutdownHardDeadline), + zap.Int("forced_exit_code", ExitCodeShutdownTimeout)) + _ = d.logger.Sync() // Flush again + + select { + case <-graceWindow: + // Shutdown is taking a while. Remind the operator that Ctrl+C still + // works - and, unlike before, it really does. + d.logger.Info("Graceful shutdown still in progress, press Ctrl+C again to force quit", + zap.Duration("elapsed", time.Since(started)), + zap.Duration("forced_exit_after", shutdownHardDeadline)) + _ = d.logger.Sync() + <-exiting + case <-exiting: + } +} diff --git a/cmd/mcpproxy/signal_handler_test.go b/cmd/mcpproxy/signal_handler_test.go new file mode 100644 index 000000000..7beb6d54b --- /dev/null +++ b/cmd/mcpproxy/signal_handler_test.go @@ -0,0 +1,389 @@ +package main + +import ( + "os" + "strings" + "sync" + "sync/atomic" + "syscall" + "testing" + "time" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// signalTestGuard is the deadlock guard for every blocking step in these +// tests. It is NOT the assertion mechanism: every synchronisation point below +// is a channel handshake, so a correct handler never comes anywhere near this +// bound. +const signalTestGuard = 2 * time.Second + +type signalHandlerHarness struct { + sigChan chan os.Signal + graceWindow chan time.Time + hardDeadline chan time.Time + + cancelled chan struct{} + exited chan int + returned chan struct{} + + order atomic.Int32 + onSignalOrder atomic.Int32 + cancelOrder atomic.Int32 + timersArmed atomic.Int32 + observedSignal atomic.Value +} + +func newSignalHandlerHarness(t *testing.T) *signalHandlerHarness { + t.Helper() + return newSignalHandlerHarnessWithLogger(t, zap.NewNop()) +} + +func newSignalHandlerHarnessWithLogger(t *testing.T, logger *zap.Logger) *signalHandlerHarness { + t.Helper() + + h := &signalHandlerHarness{ + // Buffered like the production channel (signal.Notify needs a buffer). + sigChan: make(chan os.Signal, 1), + // Unbuffered on purpose: a send from the test blocks until the handler + // actually receives it, which makes every step deterministic. + graceWindow: make(chan time.Time), + hardDeadline: make(chan time.Time), + cancelled: make(chan struct{}), + exited: make(chan int, 4), + returned: make(chan struct{}), + } + + deps := signalHandlerDeps{ + sigChan: h.sigChan, + cancel: func() { + h.cancelOrder.Store(h.order.Add(1)) + select { + case <-h.cancelled: + default: + close(h.cancelled) + } + }, + onSignal: func(sig os.Signal) { + h.onSignalOrder.Store(h.order.Add(1)) + h.observedSignal.Store(sig.String()) + }, + exit: func(code int) { h.exited <- code }, + logger: logger, + newTimer: func(dur time.Duration) <-chan time.Time { + h.timersArmed.Add(1) + switch dur { + case shutdownGraceWindow: + return h.graceWindow + case shutdownHardDeadline: + return h.hardDeadline + default: + t.Errorf("handler armed an unexpected timer: %s", dur) + return nil + } + }, + } + + go func() { + defer close(h.returned) + runSignalHandler(deps) + }() + + return h +} + +func (h *signalHandlerHarness) sendSignal(t *testing.T, sig os.Signal) { + t.Helper() + select { + case h.sigChan <- sig: + case <-time.After(signalTestGuard): + t.Fatalf("timed out delivering %s: nobody is reading the signal channel", sig) + } +} + +// fire simulates a timer expiring. The send blocks until the handler receives +// it, so a handler that has stopped listening fails here. +func (h *signalHandlerHarness) fire(t *testing.T, ch chan time.Time, what string) { + t.Helper() + select { + case ch <- time.Now(): + case <-time.After(signalTestGuard): + t.Fatalf("timed out firing %s: the handler is no longer listening on it", what) + } +} + +func (h *signalHandlerHarness) waitCancelled(t *testing.T) { + t.Helper() + select { + case <-h.cancelled: + case <-time.After(signalTestGuard): + t.Fatal("graceful shutdown was never started (cancel was not called)") + } +} + +func (h *signalHandlerHarness) waitExit(t *testing.T) int { + t.Helper() + select { + case code := <-h.exited: + return code + case <-time.After(signalTestGuard): + t.Fatal("the process was never asked to exit") + return -1 + } +} + +func (h *signalHandlerHarness) waitReturned(t *testing.T) { + t.Helper() + select { + case <-h.returned: + case <-time.After(signalTestGuard): + t.Fatal("runSignalHandler did not return after exiting (goroutine leak)") + } +} + +// TestRunSignalHandler_SecondSignalForcesImmediateExit pins the existing +// force-quit behaviour: the second signal kills the process right away. +func TestRunSignalHandler_SecondSignalForcesImmediateExit(t *testing.T) { + h := newSignalHandlerHarness(t) + + h.sendSignal(t, syscall.SIGINT) + h.waitCancelled(t) + h.sendSignal(t, syscall.SIGTERM) + + if code := h.waitExit(t); code != ExitCodeGeneralError { + t.Fatalf("second signal exit code = %d, want %d", code, ExitCodeGeneralError) + } + h.waitReturned(t) + + select { + case code := <-h.exited: + t.Fatalf("exit called more than once (extra code %d)", code) + default: + } +} + +// TestRunSignalHandler_SignalAfterGraceWindowStillHonored is the regression +// test for the one-shot handler. Once the grace window elapses the old handler +// returned, leaving signal.Notify registered on a channel nobody reads: the +// runtime then swallows SIGINT/SIGTERM and the daemon can only be SIGKILLed. +func TestRunSignalHandler_SignalAfterGraceWindowStillHonored(t *testing.T) { + h := newSignalHandlerHarness(t) + + h.sendSignal(t, syscall.SIGINT) + h.waitCancelled(t) + + // The 10s "press Ctrl+C again" window elapses while shutdown is still + // running (e.g. Docker container cleanup is slow). + h.fire(t, h.graceWindow, "grace window") + + // The operator hits Ctrl+C again. It must still force the exit. + h.sendSignal(t, syscall.SIGTERM) + + if code := h.waitExit(t); code != ExitCodeGeneralError { + t.Fatalf("post-grace-window signal exit code = %d, want %d", code, ExitCodeGeneralError) + } + h.waitReturned(t) +} + +// TestRunSignalHandler_HardDeadlineExits pins the new upper bound on graceful +// shutdown: when it fires the process exits with a distinct code so a +// supervisor (launchd/systemd) can tell a hung shutdown from a plain failure. +func TestRunSignalHandler_HardDeadlineExits(t *testing.T) { + if ExitCodeShutdownTimeout == ExitCodeGeneralError { + t.Fatalf("ExitCodeShutdownTimeout must be distinct from ExitCodeGeneralError (%d)", ExitCodeGeneralError) + } + + h := newSignalHandlerHarness(t) + + h.sendSignal(t, syscall.SIGINT) + h.waitCancelled(t) + h.fire(t, h.graceWindow, "grace window") + h.fire(t, h.hardDeadline, "hard deadline") + + if code := h.waitExit(t); code != ExitCodeShutdownTimeout { + t.Fatalf("hard deadline exit code = %d, want %d", code, ExitCodeShutdownTimeout) + } + h.waitReturned(t) +} + +// TestRunSignalHandler_DeadlinesStartAtFirstSignal pins where the clock +// starts. Arming the timers at process start instead would make the hard +// deadline fire ~60s into a healthy run and then kill the daemon the instant +// the first Ctrl+C arrived. +func TestRunSignalHandler_DeadlinesStartAtFirstSignal(t *testing.T) { + h := newSignalHandlerHarness(t) + + // No signal yet, so the handler is still blocked on the receive and cannot + // have armed anything. This read cannot race: arming requires the send. + if armed := h.timersArmed.Load(); armed != 0 { + t.Fatalf("handler armed %d timer(s) before the first signal", armed) + } + + h.sendSignal(t, syscall.SIGINT) + h.waitCancelled(t) + + if armed := h.timersArmed.Load(); armed != 2 { + t.Fatalf("handler armed %d timer(s) after the first signal, want 2 (grace window + hard deadline)", armed) + } + + h.sendSignal(t, syscall.SIGTERM) + h.waitExit(t) + h.waitReturned(t) +} + +// blockingSyncer is a zapcore.WriteSyncer whose Write blocks for entries +// containing blockOn, so a test can hold the handler inside a log call. +type blockingSyncer struct { + blockOn string + entered chan struct{} + release chan struct{} + once sync.Once +} + +func (b *blockingSyncer) Write(p []byte) (int, error) { + if strings.Contains(string(p), b.blockOn) { + b.once.Do(func() { close(b.entered) }) + <-b.release + } + return len(p), nil +} + +func (b *blockingSyncer) Sync() error { return nil } + +func newBlockingLogger(syncer *blockingSyncer) *zap.Logger { + return zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), + syncer, + zapcore.InfoLevel, + )) +} + +// TestRunSignalHandler_ArmsDeadlinesBeforeLogging pins the ordering that makes +// the hard deadline actually hard: a log write can block (full disk, stalled +// pipe to the tray), and any blocking done before the timers are armed is time +// the deadline is not counting. +func TestRunSignalHandler_ArmsDeadlinesBeforeLogging(t *testing.T) { + syncer := &blockingSyncer{ + blockOn: "Received signal", + entered: make(chan struct{}), + release: make(chan struct{}), + } + h := newSignalHandlerHarnessWithLogger(t, newBlockingLogger(syncer)) + h.sendSignal(t, syscall.SIGINT) + + // The handler is now wedged inside its first post-signal log call. + select { + case <-syncer.entered: + case <-time.After(signalTestGuard): + t.Fatal("handler never reached the post-signal log call") + } + + if armed := h.timersArmed.Load(); armed != 2 { + t.Fatalf("timers armed = %d while logging is blocked, want 2: the deadline clock "+ + "must start before anything that can block", armed) + } + + close(syncer.release) + h.waitCancelled(t) + h.sendSignal(t, syscall.SIGTERM) + h.waitExit(t) + h.waitReturned(t) +} + +// TestRunSignalHandler_HardDeadlineExitsWhileLoggingIsBlocked is the reason +// the deadline is enforced by its own goroutine. The failure mode that wedges +// shutdown (a full disk, a tray that stopped draining the core's stderr pipe) +// is exactly the one that wedges the log sink, so a deadline that has to get +// past a log call first is not a deadline at all. +func TestRunSignalHandler_HardDeadlineExitsWhileLoggingIsBlocked(t *testing.T) { + syncer := &blockingSyncer{ + blockOn: "Received signal", + entered: make(chan struct{}), + release: make(chan struct{}), + } + h := newSignalHandlerHarnessWithLogger(t, newBlockingLogger(syncer)) + + h.sendSignal(t, syscall.SIGINT) + + select { + case <-syncer.entered: + case <-time.After(signalTestGuard): + t.Fatal("handler never reached the post-signal log call") + } + + // Graceful shutdown must already have been started, before the blocked log + // call rather than after it. + h.waitCancelled(t) + + // The handler goroutine is stuck inside logging. The deadline must still + // kill the process. + h.fire(t, h.hardDeadline, "hard deadline") + if code := h.waitExit(t); code != ExitCodeShutdownTimeout { + t.Fatalf("hard deadline exit code = %d, want %d", code, ExitCodeShutdownTimeout) + } + + close(syncer.release) + h.waitReturned(t) +} + +// TestRunSignalHandler_SecondSignalExitsWhileLoggingIsBlocked is the operator +// half of the same guarantee: Ctrl+C twice must kill the process even when +// every log write is stalled. The sink here blocks on EVERY entry, so the +// handler goroutine cannot get past its own announcement. +func TestRunSignalHandler_SecondSignalExitsWhileLoggingIsBlocked(t *testing.T) { + syncer := &blockingSyncer{ + blockOn: "", // every entry blocks + entered: make(chan struct{}), + release: make(chan struct{}), + } + h := newSignalHandlerHarnessWithLogger(t, newBlockingLogger(syncer)) + + h.sendSignal(t, syscall.SIGINT) + + // Graceful shutdown starts before any logging, so this must be reached + // even though the sink is dead. + h.waitCancelled(t) + + select { + case <-syncer.entered: + case <-time.After(signalTestGuard): + t.Fatal("handler never reached its first log call") + } + + h.sendSignal(t, syscall.SIGTERM) + if code := h.waitExit(t); code != ExitCodeGeneralError { + t.Fatalf("second signal exit code = %d, want %d", code, ExitCodeGeneralError) + } + + close(syncer.release) + h.waitReturned(t) +} + +// TestRunSignalHandler_StoresSignalBeforeCancel guards Spec 024: runServer's +// ctx.Done() branch reads receivedSignal with an unchecked type assertion as +// soon as cancel() fires, so the store has to happen first. +func TestRunSignalHandler_StoresSignalBeforeCancel(t *testing.T) { + h := newSignalHandlerHarness(t) + + h.sendSignal(t, syscall.SIGINT) + h.waitCancelled(t) + + onSignalOrder := h.onSignalOrder.Load() + cancelOrder := h.cancelOrder.Load() + if onSignalOrder == 0 { + t.Fatal("onSignal was never called: Spec 024 activity logging would see an empty signal") + } + if onSignalOrder > cancelOrder { + t.Fatalf("onSignal ran after cancel (order %d vs %d); runServer would read a stale signal", + onSignalOrder, cancelOrder) + } + if got := h.observedSignal.Load(); got != syscall.SIGINT.String() { + t.Fatalf("recorded signal = %v, want %v", got, syscall.SIGINT.String()) + } + + // Unblock the handler so the goroutine does not outlive the test. + h.sendSignal(t, syscall.SIGTERM) + h.waitExit(t) + h.waitReturned(t) +} diff --git a/docs/architecture.md b/docs/architecture.md index 9629bd0d8..f94b9e830 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -167,6 +167,7 @@ Core process exit codes are mapped to specific state machine events: - Exit code 3 (database locked) → `EventDBLocked` - Exit code 4 (config error) → `EventConfigError` - Exit code 5 (permission error) → `EventPermissionError` +- Exit code 6 (shutdown timeout: graceful shutdown exceeded its 60s hard deadline after SIGINT/SIGTERM) → `EventGeneralError` (no dedicated event; a restart is the right response) - Other errors → `EventGeneralError` ### Automatic Retry Logic