diff --git a/README.md b/README.md index 6c940f9..13cf2ba 100644 --- a/README.md +++ b/README.md @@ -1064,6 +1064,8 @@ webhooker/ │ │ └── webhook.go # Webhook receiver handler │ ├── healthcheck/ │ │ └── healthcheck.go # Health check service (uptime, version) +│ ├── lifecycle/ +│ │ └── lifecycle.go # Shared stop-hook waiter, bounded by the stop context │ ├── logger/ │ │ └── logger.go # slog setup with TTY detection │ ├── middleware/ @@ -1189,6 +1191,64 @@ downstream at form-parse time. - Container runs as non-root user (UID 1000) - GORM soft deletes on all entities (data preserved for audit) +### Shutdown + +On SIGINT or SIGTERM, fx runs the registered stop hooks in reverse +dependency order under a **5 second budget** (`fx.StopTimeout` in +`cmd/webhooker/main.go`). That budget covers the whole sequence, not +each hook. The order, read off the fx stop-hook log: + +1. `ArchiveSweeper` +2. `RetentionReaper` +3. `server` — the HTTP drain, bounded separately by + `server.ShutdownTimeout` (**3 seconds**) +4. `delivery.Engine` +5. `healthcheck` +6. `WebhookDBManager` +7. the database close + +The two components that can realistically hold the budget run +first: a retention sweep or an archive prune caught mid-tick each +waits on its `WaitGroup` bounded by the stop context, so a wedge +there consumes the 5 seconds before the HTTP server hook is ever +entered. The hooks after the server are microsecond-scale in normal +operation. + +The HTTP drain budget is deliberately **shorter** than the sequence +budget. Were the two equal, a drain that used its whole budget would +exhaust the sequence budget at the instant it finished, and every +later hook — the delivery engine, the healthcheck, the webhook DB +manager and the database close — would be skipped in exactly the +case where the drain mattered. 3 seconds leaves 2 seconds for the +tail, which is far more than it needs. This does not make the +database close unconditional: a wedged `ArchiveSweeper` or +`RetentionReaper` still runs first and can consume the whole budget +on its own. + +The value is chosen to sit inside the container stop grace period. +Docker's default `docker stop` grace is 10 seconds and the Dockerfile +sets no `STOPSIGNAL` or grace override, so the process must be gone +before that. fx's own default is 15 seconds, which is past the grace: +the container would be SIGKILLed (exit 137) before the bound could +fire, and nothing that depends on it — including the +`shutdown timed out, goroutines still running` error log that tells +an operator a component is wedged — would ever be reached. + +Two operational consequences follow from bounding the sequence: + +- **A wedged component aborts the rest of the shutdown.** fx checks + the stop context before each remaining hook and returns outright + once it has expired, skipping the hooks it has not reached. If the + first-stopped component consumes the whole budget, the later hooks + never run — **the database close among them**. SQLite is crash-safe, + so this is not corruption, but it is not a clean close either. +- **Lowering the grace below 5 seconds reintroduces the silent + truncation.** `docker stop --time`, Compose's `stop_grace_period`, + or Kubernetes' `terminationGracePeriodSeconds` set under 5 seconds + put SIGKILL back in front of the bound, and the process dies with + no shutdown diagnostics at all. Keep the deployment's grace above + the stop timeout. + ### Docker The Dockerfile uses a multi-stage build: diff --git a/cmd/webhooker/main.go b/cmd/webhooker/main.go index 793f44c..7e64bd9 100644 --- a/cmd/webhooker/main.go +++ b/cmd/webhooker/main.go @@ -2,6 +2,8 @@ package main import ( + "time" + "go.uber.org/fx" "sneak.berlin/go/webhooker/internal/config" "sneak.berlin/go/webhooker/internal/database" @@ -15,6 +17,29 @@ import ( "sneak.berlin/go/webhooker/internal/session" ) +// stopTimeout bounds the whole fx stop sequence, not each hook. +// +// fx defaults to 15s, which is longer than Docker's 10s default +// stop grace: the container would be SIGKILLed before the bound +// could fire, so nothing bounded by it would ever be observed. +// 5s leaves headroom inside that grace for signal delivery and +// process exit; the observed wedge case already exits at ~5.3s, +// so a larger bound would trade a rare skipped database close for +// a more common hard kill. +// +// It must stay strictly above server.ShutdownTimeout: an HTTP +// drain that uses its whole budget would otherwise exhaust the +// sequence budget at that instant, and fx would skip every hook +// after the server — the delivery engine, the healthcheck, the +// webhook DB manager and the database close. Those tail hooks are +// microsecond-scale in normal operation, so the 2s difference is +// ample. TestStopTimeout_LeavesHeadroomForTailHooks pins it. +// +// This does not make the database close unconditional: the +// ArchiveSweeper and RetentionReaper hooks run before the server +// and can still consume the whole budget on their own. +const stopTimeout = 5 * time.Second + // Build-time variables set via -ldflags. // //nolint:gochecknoglobals // Build-time variables injected by the linker. @@ -27,7 +52,14 @@ func main() { globals.Appname = appname globals.Version = version - fx.New( + newApp().Run() +} + +// newApp builds the application graph. It is separate from main so +// a test can assert the options it carries. +func newApp() *fx.App { + return fx.New( + fx.StopTimeout(stopTimeout), fx.Provide( globals.New, logger.New, @@ -60,5 +92,5 @@ func main() { ) { }, ), - ).Run() + ) } diff --git a/cmd/webhooker/main_test.go b/cmd/webhooker/main_test.go new file mode 100644 index 0000000..942e816 --- /dev/null +++ b/cmd/webhooker/main_test.go @@ -0,0 +1,61 @@ +package main + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/server" +) + +// dockerStopGrace is Docker's default `docker stop` grace period. +// The Dockerfile sets no STOPSIGNAL or grace override, so this is +// the deadline the container is actually held to, and the fx stop +// timeout has to fit inside it with room for signal delivery and +// process exit. +const dockerStopGrace = 10 * time.Second + +// TestNewApp_StopTimeout pins the fx stop timeout. Without the +// explicit fx.StopTimeout option the app reads fx's 15s +// DefaultTimeout, which exceeds dockerStopGrace: the container is +// SIGKILLed before the bound fires and every shutdown hook bounded +// by it — including the operator-facing timeout log — becomes +// unreachable in the image this repo produces. +// +// fx.New applies options before it executes invokes, so the timeout +// is set whether or not the graph itself can be constructed here. +func TestNewApp_StopTimeout(t *testing.T) { + t.Setenv("DATA_DIR", t.TempDir()) + + got := newApp().StopTimeout() + + require.Equal(t, stopTimeout, got) + require.Less(t, got, dockerStopGrace) +} + +// tailHeadroom is the slack the fx stop budget must keep beyond the +// HTTP drain. The hooks that run after the server — the delivery +// engine, the healthcheck, the webhook DB manager and the database +// close — are microsecond-scale in normal operation, so this is +// generous for them. +const tailHeadroom = 2 * time.Second + +// TestStopTimeout_LeavesHeadroomForTailHooks pins the relationship +// between the HTTP drain budget and the fx stop budget. fx bounds +// the whole stop sequence, and returns without running its +// remaining hooks once the stop context has expired. If the two +// values were equal, an HTTP drain that used its full budget would +// exhaust the sequence budget at the instant it finished and every +// later hook, the database close included, would be skipped in +// exactly the case where the drain mattered. +// +// Lowering either constant to erase the gap must fail here rather +// than silently recreating that. +func TestStopTimeout_LeavesHeadroomForTailHooks(t *testing.T) { + t.Parallel() + + require.Less(t, server.ShutdownTimeout, stopTimeout) + require.GreaterOrEqual( + t, stopTimeout-server.ShutdownTimeout, tailHeadroom, + ) +} diff --git a/internal/lifecycle/export_test.go b/internal/lifecycle/export_test.go new file mode 100644 index 0000000..08fd13b --- /dev/null +++ b/internal/lifecycle/export_test.go @@ -0,0 +1,21 @@ +package lifecycle + +import ( + "context" + "log/slog" +) + +// WaitDone exposes waitDone to the external test package. Only the +// unexported waiter can be handed a channel that is already closed +// before the call, which is the state the preamble exists for; +// through WaitForShutdown the waiter goroutine may or may not have +// closed the channel yet, so the case is not reachable +// deterministically from outside. +func WaitDone( + ctx context.Context, + log *slog.Logger, + component string, + done <-chan struct{}, +) error { + return waitDone(ctx, log, component, done) +} diff --git a/internal/lifecycle/lifecycle.go b/internal/lifecycle/lifecycle.go index b538fd6..614305f 100644 --- a/internal/lifecycle/lifecycle.go +++ b/internal/lifecycle/lifecycle.go @@ -38,6 +38,29 @@ func WaitForShutdown( wg.Wait() }() + return waitDone(ctx, log, component, done) +} + +// waitDone waits for done to close, bounded by ctx. +// +// The non-blocking preamble is load-bearing. When the component has +// already drained and ctx has already expired, both cases of the +// bounded select are ready and Go picks between them uniformly at +// random, so a clean shutdown would be reported as a timeout about +// half the time. Draining wins: the goroutines are gone, and there +// is nothing left for the operator to act on. +func waitDone( + ctx context.Context, + log *slog.Logger, + component string, + done <-chan struct{}, +) error { + select { + case <-done: + return nil + default: + } + select { case <-done: return nil diff --git a/internal/lifecycle/lifecycle_test.go b/internal/lifecycle/lifecycle_test.go index ca327e3..db5a7cf 100644 --- a/internal/lifecycle/lifecycle_test.go +++ b/internal/lifecycle/lifecycle_test.go @@ -37,6 +37,57 @@ func TestWaitForShutdown_DrainedGroup(t *testing.T) { ) } +// racePasses is how many times the both-cases-ready race is run. +// Without the preamble each pass is an independent coin flip, so +// the probability of the whole loop passing by luck is 2^-N: at +// this N the test is deterministic in practice, and it involves no +// wall-clock waiting at all. +const racePasses = 1000 + +// TestWaitDone_DrainedBeforeExpiredContext covers the case where a +// component drained cleanly but the stop context had already +// expired. Both select cases are ready, and Go chooses among ready +// cases uniformly at random, so the drained case must be settled by +// the preamble before the bounded select ever runs. +func TestWaitDone_DrainedBeforeExpiredContext(t *testing.T) { + t.Parallel() + + done := make(chan struct{}) + close(done) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + for pass := range racePasses { + require.NoErrorf( + t, + lifecycle.WaitDone( + ctx, discardLogger(), "test component", done, + ), + "pass %d reported a timeout for a drained component", + pass, + ) + } +} + +// TestWaitDone_ExpiredContext pins the other side of the preamble: +// an expired context with a component that has not drained is still +// a timeout. +func TestWaitDone_ExpiredContext(t *testing.T) { + t.Parallel() + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + + err := lifecycle.WaitDone( + ctx, discardLogger(), "test component", + make(chan struct{}), + ) + + require.ErrorIs(t, err, context.Canceled) + require.ErrorContains(t, err, "test component") +} + func TestWaitForShutdown_ContextExpires(t *testing.T) { t.Parallel() diff --git a/internal/server/server.go b/internal/server/server.go index 1d67f31..a483794 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -24,9 +24,15 @@ import ( ) const ( - // shutdownTimeout is the maximum time to wait for the HTTP + // ShutdownTimeout is the maximum time to wait for the HTTP // server to finish in-flight requests during shutdown. - shutdownTimeout = 5 * time.Second + // + // It must stay strictly below the fx stop timeout in + // cmd/webhooker, which bounds the whole stop sequence: a drain + // that used the entire sequence budget would leave nothing for + // the hooks that run after the server, including the database + // close. It is exported so that relationship can be tested. + ShutdownTimeout = 3 * time.Second // sentryFlushTimeout is the maximum time to wait for Sentry // to flush pending events during shutdown. @@ -164,7 +170,7 @@ func (s *Server) cleanShutdown(ctx context.Context) { s.exitCode = 0 ctxShutdown, shutdownCancel := context.WithTimeout( - ctx, shutdownTimeout, + ctx, ShutdownTimeout, ) defer shutdownCancel()