diff --git a/README.md b/README.md index b1b0e44..e73b6b2 100644 --- a/README.md +++ b/README.md @@ -1145,8 +1145,6 @@ webhooker/ │ │ ├── archive_sweeper.go # Periodic pruning of idle archives │ │ ├── url_mask.go # Strips credentials from *url.Error │ │ └── ssrf.go # SSRF prevention (IP validation, safe HTTP transport) -│ ├── lifecycle/ -│ │ └── lifecycle.go # Shared fx start/stop hook helpers │ ├── handlers/ │ │ ├── handlers.go # Base handler struct, JSON helpers, template rendering │ │ ├── auth.go # Login, logout handlers @@ -1158,6 +1156,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/ @@ -1316,6 +1316,78 @@ rather than global: **LoginRateLimit** on `/pages/login`, - GORM soft deletes on every entity that carries `BaseModel`, which is all of them but `Setting` (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**), then a Sentry flush if + `SENTRY_DSN` is set +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 +(`server.TailHookReserve`) for the tail, which is far more than the +microseconds it needs. + +That reserve belongs to the tail hooks, not to the server hook, and +the Sentry flush is what could take it: it runs after the drain +**inside the same hook**, and `sentry.Flush` takes a bare duration +and honours no context, so an unreachable Sentry endpoint would add +its own timeout on top of a full-length drain and consume the whole +sequence budget by itself. It is therefore clamped to whatever is +left on the stop context minus the reserve, and skipped when that +leaves too little to be worth attempting — so a full-length drain +means Sentry events are dropped rather than the database close being +skipped. + +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 three-stage build. Each stage is pinned by diff --git a/cmd/webhooker/main.go b/cmd/webhooker/main.go index 793f44c..114d154 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,33 @@ 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. +// +// The server's stop hook must fit inside it with room to spare: a +// hook that used the whole budget would exhaust it 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. That hook is the 3s HTTP drain plus the Sentry flush that +// follows it in the same hook, so the flush is clamped to the stop +// context's remaining time less server.TailHookReserve rather than +// running for its own fixed 2s; the reserve is what the tail hooks +// live on, and they are microsecond-scale in normal operation. +// TestStopTimeout_LeavesHeadroomForTailHooks pins the arithmetic +// across every drain length. +// +// 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 +56,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 +96,5 @@ func main() { ) { }, ), - ).Run() + ) } diff --git a/cmd/webhooker/main_test.go b/cmd/webhooker/main_test.go new file mode 100644 index 0000000..fb22c18 --- /dev/null +++ b/cmd/webhooker/main_test.go @@ -0,0 +1,75 @@ +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 +// server stop hook. 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 server's stop hook 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 hook +// could use the entire budget, every later hook — the database close +// included — would be skipped in exactly the case where the drain +// mattered. +// +// The hook is not just the HTTP drain: a Sentry flush follows it in +// the same hook, and sentry.Flush honours no context, so both halves +// have to be counted. The sweep walks every drain length the hook +// can produce, since a shorter drain leaves the flush more room and +// the worst case is not necessarily at either extreme. +// +// Shrinking either budget, or unbounding the flush again, must fail +// here rather than silently recreating a hook that swallows the +// whole sequence. +func TestStopTimeout_LeavesHeadroomForTailHooks(t *testing.T) { + t.Parallel() + + require.Less(t, server.ShutdownTimeout, stopTimeout) + + const step = 10 * time.Millisecond + + for drain := time.Duration(0); drain <= server.ShutdownTimeout; drain += step { + hook := drain + server.SentryFlushBudget(stopTimeout-drain) + + require.LessOrEqual( + t, hook+tailHeadroom, stopTimeout, + "a %s drain leaves the tail hooks short", drain, + ) + } +} 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..5246198 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -24,15 +24,48 @@ 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. + // TailHookReserve is the share of the fx stop budget this hook + // refuses to spend, leaving it for the hooks that run after the + // server: the delivery engine, the healthcheck, the webhook DB + // manager and the database close. + TailHookReserve = 2 * time.Second + + // sentryFlushTimeout is the longest wait for Sentry to flush + // pending events during shutdown, before the remaining stop + // budget is taken into account. sentryFlushTimeout = 2 * time.Second + + // minSentryFlush is the shortest flush worth attempting. Below + // it the remaining budget goes to the tail hooks instead. + minSentryFlush = 250 * time.Millisecond ) +// SentryFlushBudget reports how long the Sentry flush may run when +// remaining is the time left on the fx stop context after the HTTP +// drain. sentry.Flush takes a bare duration and honours no context, +// so this clamp is the only thing keeping a stalled flush from +// spending the tail hooks' share of the budget on top of a +// full-length drain. TailHookReserve is held back, and anything +// under minSentryFlush is skipped rather than attempted uselessly. +func SentryFlushBudget(remaining time.Duration) time.Duration { + budget := min(remaining-TailHookReserve, sentryFlushTimeout) + if budget < minSentryFlush { + return 0 + } + + return budget +} + //nolint:revive // ServerParams is a standard fx naming convention. type ServerParams struct { fx.In @@ -164,7 +197,7 @@ func (s *Server) cleanShutdown(ctx context.Context) { s.exitCode = 0 ctxShutdown, shutdownCancel := context.WithTimeout( - ctx, shutdownTimeout, + ctx, ShutdownTimeout, ) defer shutdownCancel() @@ -178,10 +211,31 @@ func (s *Server) cleanShutdown(ctx context.Context) { s.cleanupForExit() if s.sentryEnabled { - sentry.Flush(sentryFlushTimeout) + s.flushSentry(ctx) } } +// flushSentry drains Sentry's queue inside what is left of the fx +// stop budget. A context carrying no deadline — a caller outside the +// fx lifecycle — gets the full timeout. +func (s *Server) flushSentry(ctx context.Context) { + flush := sentryFlushTimeout + + if deadline, ok := ctx.Deadline(); ok { + flush = SentryFlushBudget(time.Until(deadline)) + } + + if flush <= 0 { + s.log.Warn( + "skipping sentry flush, stop budget exhausted", + ) + + return + } + + sentry.Flush(flush) +} + func (s *Server) configure() { // identify ourselves in the logs s.params.Logger.Identify() diff --git a/internal/server/shutdown_test.go b/internal/server/shutdown_test.go new file mode 100644 index 0000000..5f58637 --- /dev/null +++ b/internal/server/shutdown_test.go @@ -0,0 +1,59 @@ +package server_test + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" + "sneak.berlin/go/webhooker/internal/server" +) + +// TestSentryFlushBudget covers the clamp that keeps the Sentry flush +// from spending the tail hooks' share of the fx stop budget. +// sentry.Flush ignores the stop context, so without the clamp a +// stalled flush adds its whole timeout on top of the HTTP drain. +func TestSentryFlushBudget(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + remaining time.Duration + want time.Duration + }{ + { + name: "full drain leaves only the reserve", + remaining: server.TailHookReserve, + want: 0, + }, + { + name: "expired budget", + remaining: -time.Second, + want: 0, + }, + { + name: "sliver above the reserve is not worth it", + remaining: server.TailHookReserve + 10*time.Millisecond, + want: 0, + }, + { + name: "partial flush when some room is left", + remaining: server.TailHookReserve + time.Second, + want: time.Second, + }, + { + name: "capped at the nominal timeout", + remaining: time.Hour, + want: 2 * time.Second, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + require.Equal( + t, tt.want, server.SentryFlushBudget(tt.remaining), + ) + }) + } +}