diff --git a/README.md b/README.md index 1f845f4..b250fde 100644 --- a/README.md +++ b/README.md @@ -3245,9 +3245,9 @@ 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 +3. `server` — the HTTP drain, bounded by `server.ShutdownTimeout` + (**3 seconds**) and by what the hooks before it left, then a Sentry + flush if `SENTRY_DSN` is set 4. `delivery.Engine` — waits for its workers, then closes the archive databases 5. `healthcheck` @@ -3267,23 +3267,30 @@ 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. +(`server.TailHookReserve`) for the tail. The reserve is that +remainder, not a figure sized to the tail, which takes about a +millisecond. 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. +the server hook could take it in two ways. The hooks before it may +already have spent part of the budget, so a full 3-second drain +would come out of the reserve; the drain is therefore also bounded +by whatever is left on the stop context minus the reserve. And the +Sentry flush 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 clamped the same way, 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. +This does not make the database close unconditional. A slow +`ArchiveSweeper` or `RetentionReaper` is enough to cut the shutdown +short, not only one that consumes the whole budget: what they spend +comes out of the drain first, so after 2 seconds of theirs a request +still in flight gets 1 second to finish, and after 3 it gets none. +Past 3 seconds they spend the reserve itself, and one that takes the +whole budget skips every hook after it, the database close included. The value is chosen to sit inside the container stop grace period. Docker's default `docker stop` grace is 10 seconds and the Dockerfile diff --git a/cmd/webhooker/main.go b/cmd/webhooker/main.go index 1d88d3c..966df32 100644 --- a/cmd/webhooker/main.go +++ b/cmd/webhooker/main.go @@ -38,17 +38,19 @@ import ( // 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 +// close. That hook is the HTTP drain plus the Sentry flush that +// follows it in the same hook, and each 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. +// running for its own fixed 3s and 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. +// across every drain length and every amount of budget the hooks +// before the server may already have spent. // // 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. +// ArchiveSweeper and RetentionReaper hooks run before the server. +// What they spend comes out of the drain first, but past 3s it comes +// out of the reserve, and they can consume the whole budget. const stopTimeout = 5 * time.Second // exitUsage is the status for a command line this binary cannot make diff --git a/cmd/webhooker/main_test.go b/cmd/webhooker/main_test.go index ad1d5cf..b225db6 100644 --- a/cmd/webhooker/main_test.go +++ b/cmd/webhooker/main_test.go @@ -252,22 +252,40 @@ const tailHeadroom = 2 * time.Second // 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. +// Nor does the hook start on a full budget: the ArchiveSweeper and +// RetentionReaper hooks run before it, and whatever they spent is +// gone. The outer sweep walks every amount they can spend. Once they +// have eaten into the headroom themselves, the hook must spend +// nothing of what is left. A drain that starts on the full budget +// must still get all of ShutdownTimeout, so a smaller stopTimeout +// cannot silently shorten every drain. +// +// Shrinking either budget, or unbounding the drain or 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) + require.Equal( + t, server.ShutdownTimeout, server.DrainBudget(stopTimeout), + "a drain that starts on the full stop budget is cut short", + ) const step = 10 * time.Millisecond - for drain := time.Duration(0); drain <= server.ShutdownTimeout; drain += step { - hook := drain + server.SentryFlushBudget(stopTimeout-drain) + for spent := time.Duration(0); spent <= stopTimeout; spent += step { + remaining := stopTimeout - spent + longest := max(server.DrainBudget(remaining), 0) - require.LessOrEqual( - t, hook+tailHeadroom, stopTimeout, - "a %s drain leaves the tail hooks short", drain, - ) + for drain := time.Duration(0); drain <= longest; drain += step { + hook := drain + server.SentryFlushBudget(remaining-drain) + + require.GreaterOrEqual( + t, remaining-hook, min(remaining, tailHeadroom), + "a %s drain after %s of earlier hooks leaves "+ + "the tail hooks short", drain, spent, + ) + } } } diff --git a/internal/server/export_test.go b/internal/server/export_test.go index 36ce86a..957f4dd 100644 --- a/internal/server/export_test.go +++ b/internal/server/export_test.go @@ -1,6 +1,8 @@ package server import ( + "context" + "log/slog" "net/http" "testing" @@ -37,6 +39,14 @@ func SentryClientOptionsForTest( return sentryClientOptions(dsn, release) } +// CleanShutdownForTest runs the server's stop hook, cleanShutdown, +// against hs: a server the test started itself, so it can hold a +// request open across the drain. Sentry is off. +func CleanShutdownForTest(ctx context.Context, hs *http.Server) { + s := &Server{log: slog.New(slog.DiscardHandler), httpServer: hs} + s.cleanShutdown(ctx) +} + // newServerForTest builds a Server through New, as the application // does, on a lifecycle that is never started: the hooks New adds to // it never run, so nothing listens. diff --git a/internal/server/server.go b/internal/server/server.go index 12521c1..804b991 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -39,6 +39,12 @@ const ( // 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. + // + // Its value is not tuned to those hooks, which take about a + // millisecond between them. It is what the 5s fx stop timeout in + // cmd/webhooker leaves after a full ShutdownTimeout drain, so a + // drain that starts on a full budget still gets all of + // ShutdownTimeout. TailHookReserve = 2 * time.Second // sentryFlushTimeout is the longest wait for Sentry to flush @@ -59,6 +65,16 @@ const ( // key off it, and a zero exit would read as a deliberate stop. const StartupFailureExitCode = 1 +// DrainBudget reports how long the HTTP drain may wait for in-flight +// requests when remaining is the time left on the fx stop context as +// the server's stop hook starts. The hooks before the server can +// already have spent part of the budget, so the drain takes its time +// out of what they left, never out of TailHookReserve. Zero or less +// means no wait at all. +func DrainBudget(remaining time.Duration) time.Duration { + return min(ShutdownTimeout, remaining-TailHookReserve) +} + // 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, @@ -261,10 +277,17 @@ func (s *Server) cleanupForExit() { s.log.Info("cleaning up") } +// cleanShutdown drains the HTTP server and flushes Sentry inside what +// is left of the fx stop budget. A context carrying no deadline — a +// caller outside the fx lifecycle — gets the full ShutdownTimeout. func (s *Server) cleanShutdown(ctx context.Context) { - ctxShutdown, shutdownCancel := context.WithTimeout( - ctx, ShutdownTimeout, - ) + drain := ShutdownTimeout + + if deadline, ok := ctx.Deadline(); ok { + drain = DrainBudget(time.Until(deadline)) + } + + ctxShutdown, shutdownCancel := context.WithTimeout(ctx, drain) defer shutdownCancel() err := s.httpServer.Shutdown(ctxShutdown) diff --git a/internal/server/shutdown_test.go b/internal/server/shutdown_test.go index 5f58637..2a2e644 100644 --- a/internal/server/shutdown_test.go +++ b/internal/server/shutdown_test.go @@ -1,13 +1,148 @@ package server_test import ( + "context" + "net" + "net/http" "testing" + "testing/synctest" "time" "github.com/stretchr/testify/require" "sneak.berlin/go/webhooker/internal/server" ) +// TestDrainBudget covers the clamp that keeps the HTTP drain from +// spending the tail hooks' share of the fx stop budget when the hooks +// before the server have already used part of it. +func TestDrainBudget(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + remaining time.Duration + want time.Duration + }{ + { + name: "only the reserve is left", + remaining: server.TailHookReserve, + want: 0, + }, + { + name: "earlier hooks spent part of the budget", + remaining: server.TailHookReserve + time.Second, + want: time.Second, + }, + { + name: "capped at the nominal timeout", + remaining: time.Hour, + want: server.ShutdownTimeout, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + require.Equal(t, tt.want, server.DrainBudget(tt.remaining)) + }) + } +} + +// TestCleanShutdown_LeavesTailHookReserve stops the server with a +// request still in flight, after the hooks before it have spent all +// of the stop budget but TailHookReserve. The drain must give up at +// once rather than wait for the request: what is left belongs to the +// hooks after the server, the database close among them. A drain +// bounded only by ShutdownTimeout waits until the stop context +// expires, and fx then skips those hooks. +// +// The test runs in a synctest bubble, whose clock moves only while +// every goroutine in it is blocked, so a drain that gives up at once +// leaves the stop context unexpired however slow the host is. The +// request travels over net.Pipe because a goroutine waiting on a +// real socket would stop that clock from moving at all. +func TestCleanShutdown_LeavesTailHookReserve(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + entered := make(chan struct{}) + release := make(chan struct{}) + + hs := &http.Server{ + Handler: http.HandlerFunc( + func(http.ResponseWriter, *http.Request) { + close(entered) + <-release + }, + ), + ReadHeaderTimeout: time.Second, + } + + srvConn, cliConn := net.Pipe() + + listener := pipeListener{ + conns: make(chan net.Conn, 1), + closed: make(chan struct{}), + } + listener.conns <- srvConn + + go func() { _ = hs.Serve(listener) }() + + // Cleanups run last first: the handler returns, then closing + // the client end ends the server's write of the response. + t.Cleanup(func() { _ = cliConn.Close() }) + t.Cleanup(func() { close(release) }) + + _, err := cliConn.Write( + []byte("GET / HTTP/1.1\r\nHost: webhooker.test\r\n\r\n"), + ) + require.NoError(t, err) + + <-entered + + stopCtx, cancel := context.WithTimeout( + t.Context(), server.TailHookReserve, + ) + defer cancel() + + server.CleanShutdownForTest(stopCtx, hs) + + require.NoError( + t, stopCtx.Err(), "the drain spent the tail hooks' reserve", + ) + }) +} + +// pipeListener is the net.Listener http.Server.Serve needs to serve +// the server end of a net.Pipe: Accept returns that one connection, +// then waits until Close, as a real listener with no more clients +// does. +type pipeListener struct { + conns chan net.Conn + closed chan struct{} +} + +func (l pipeListener) Accept() (net.Conn, error) { + select { + case conn := <-l.conns: + return conn, nil + case <-l.closed: + return nil, net.ErrClosed + } +} + +func (l pipeListener) Close() error { + close(l.closed) + + return nil +} + +// Addr is never called by http.Server.Serve. +func (pipeListener) Addr() net.Addr { + return nil +} + // 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