diff --git a/cmd/api/server.go b/cmd/api/server.go index cdb0cad1..1decd059 100644 --- a/cmd/api/server.go +++ b/cmd/api/server.go @@ -149,6 +149,12 @@ func run() error { // the default handler, so a shutdown that hangs can still be interrupted. disarmStopSignals() + // Said before anything is taken apart. A configuration reload arriving in + // this window would otherwise re-run AfterResource - rebuilding the pool + // and the queue adapter, and re-registering consumers - on top of cleanup + // that has already run. + sdk.Runtime.BeginShutdown() + log.Info("Shutdown Server ... ") if err := shutdownServer(srv, shutdownTimeout); err != nil { // Not log.Fatal: that is an unconditional os.Exit(1), and Shutdown @@ -156,15 +162,28 @@ func run() error { // which is when the cleanup that follows matters most. log.Error("Server Shutdown: ", err) } + + // Runs whether or not the line above reported an error, for that reason. + if err := runShutdownHooks(cleanupTimeout); err != nil { + log.Error("Cleanup: ", err) + } log.Info("Server exiting") return nil } -// shutdownTimeout is how long Shutdown waits for in-flight requests. It plus -// whatever cleanup follows has to stay inside the orchestrator's grace period -// - `docker stop` allows 10s by default before it sends SIGKILL. -const shutdownTimeout = 5 * time.Second +// shutdownTimeout is how long Shutdown waits for in-flight requests, and +// cleanupTimeout how long the BeforeExit callbacks get after it. +// +// They are consumed one after the other, so the two together are what has to +// stay inside the orchestrator's grace period: `docker stop` allows 10s by +// default before it sends SIGKILL, and 5+3 leaves room for the process to +// finish returning. Raising either without lowering the other buys nothing - +// the budget that runs out is the orchestrator's. +const ( + shutdownTimeout = 5 * time.Second + cleanupTimeout = 3 * time.Second +) // armStopSignals registers for the stop signals and returns the channel they // arrive on together with the function that restores the default disposition. @@ -240,6 +259,19 @@ func shutdownServer(srv *http.Server, timeout time.Duration) error { return srv.Shutdown(ctx) } +// runShutdownHooks runs the BeforeExit callbacks with timeout to share. +// +// What the budget bounds is the wait, not the work. When it is gone RunShutdown +// stops waiting and returns; a callback that never looks at its context carries +// on until the process exits, and may leave a partial write behind. Go cannot +// cancel a function that does not check for cancellation, which is why the +// callbacks are handed a context at all. +func runShutdownHooks(timeout time.Duration) error { + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + return sdk.Runtime.RunShutdown(ctx) +} + // runStartupHooks runs the router registries and then the before callbacks. // // The package-level slice runs first and in its existing order, so a fork that diff --git a/cmd/api/signal_test.go b/cmd/api/signal_test.go index 3e3c5531..7d296d6f 100644 --- a/cmd/api/signal_test.go +++ b/cmd/api/signal_test.go @@ -1,6 +1,7 @@ package api import ( + "context" "fmt" "net" "net/http" @@ -10,6 +11,8 @@ import ( "syscall" "testing" "time" + + "github.com/go-admin-team/go-admin-core/v2/sdk" ) // The signal path cannot be exercised in-process: delivering a signal to the @@ -21,13 +24,15 @@ import ( // this repository's CI has no database (.github/workflows/go.yml runs neither // MySQL nor a sqlite-tagged build), and none of what is under test needs one. const ( - childEnv = "GO_ADMIN_SIGNAL_CHILD" - childStuckEnv = "GO_ADMIN_SIGNAL_CHILD_STUCK" - childHangConn = "GO_ADMIN_SIGNAL_CHILD_HANGCONN" - markerReady = "CHILD-READY" - markerSignal = "CHILD-SIGNAL" - markerShutdown = "CHILD-SHUTDOWN-OK" - markerExiting = "CHILD-EXITING" + childEnv = "GO_ADMIN_SIGNAL_CHILD" + childStuckEnv = "GO_ADMIN_SIGNAL_CHILD_STUCK" + childHangConn = "GO_ADMIN_SIGNAL_CHILD_HANGCONN" + childSlowCleanup = "GO_ADMIN_SIGNAL_CHILD_SLOWCLEANUP" + markerReady = "CHILD-READY" + markerSignal = "CHILD-SIGNAL" + markerShutdown = "CHILD-SHUTDOWN-OK" + markerCleanup = "CHILD-CLEANUP-RAN" + markerExiting = "CHILD-EXITING" ) // TestSignalChild is the child process. It is skipped in a normal run. @@ -59,6 +64,24 @@ func TestSignalChild(t *testing.T) { } go func() { _ = srv.Serve(ln) }() + // A BeforeExit callback, registered the way a module would. What the tests + // below care about is whether it runs at all - after a Shutdown that + // failed, and after its own budget has been spent. + cleanupBudget := cleanupTimeout + sdk.Runtime.SetShutdown(func(ctx context.Context) { + if os.Getenv(childSlowCleanup) == "1" { + // Outlasts the budget on purpose, and does not consult ctx - + // which is the case the contract is explicit about: what the + // context bounds is the wait, not the work. + time.Sleep(2 * time.Second) + } + fmt.Println(markerCleanup) + os.Stdout.Sync() + }) + if os.Getenv(childSlowCleanup) == "1" { + cleanupBudget = 300 * time.Millisecond + } + // Arm before announcing readiness. Doing it the other way round leaves a // window in which the parent's signal reaches the default handler and // kills the child before any of this runs - which is exactly the failure @@ -110,6 +133,8 @@ func TestSignalChild(t *testing.T) { timeout = 300 * time.Millisecond } + sdk.Runtime.BeginShutdown() + if err := shutdownServer(srv, timeout); err != nil { // Deliberately not fatal, and deliberately not a bare return: the // point is that whatever follows still runs. @@ -117,6 +142,10 @@ func TestSignalChild(t *testing.T) { } else { fmt.Println(markerShutdown) } + + if err := runShutdownHooks(cleanupBudget); err != nil { + fmt.Println("cleanup error:", err) + } fmt.Println(markerExiting) os.Stdout.Sync() } @@ -286,7 +315,55 @@ func TestShutdownTimeoutDoesNotStopWhatFollows(t *testing.T) { t.Fatalf("Shutdown did not time out, so this test proves nothing; saw:\n%s", strings.Join(seen, "\n")) } + var cleaned bool + for _, l := range seen { + if strings.Contains(l, markerCleanup) { + cleaned = true + } + } + if !cleaned { + t.Fatalf("the BeforeExit callback did not run after a failed Shutdown; saw:\n%s", + strings.Join(seen, "\n")) + } if err := cmd.Wait(); err != nil { t.Fatalf("child exited with %v after a failed Shutdown, want a clean exit", err) } } + +// A callback that outlasts its budget must not take the process with it, and +// must not be waited for: RunShutdown reports the deadline and returns, the +// callback carries on, and the process still exits cleanly. This is the half of +// the contract that is easy to get backwards - the context bounds the wait, not +// the work, because Go cannot cancel a function that does not check for it. +func TestACleanupThatOutlastsItsBudgetIsAbandonedNotAwaited(t *testing.T) { + cmd, _, lines := startChild(t, false, childSlowCleanup+"=1") + await(t, lines, markerReady, 30*time.Second) + + if err := cmd.Process.Signal(syscall.SIGTERM); err != nil { + t.Fatalf("signal: %v", err) + } + await(t, lines, markerSignal, 10*time.Second) + + // The budget is 300ms and the callback sleeps two seconds. If RunShutdown + // waited for it, this marker would not arrive for two seconds; the one + // second here is what makes "abandoned, not awaited" the thing asserted. + seen := await(t, lines, markerExiting, 1*time.Second) + + var reported bool + for _, l := range seen { + if strings.Contains(l, "cleanup error:") { + reported = true + } + if strings.Contains(l, markerCleanup) { + t.Fatalf("the slow callback finished before the process moved on, so nothing was abandoned; saw:\n%s", + strings.Join(seen, "\n")) + } + } + if !reported { + t.Fatalf("RunShutdown returned no error for a callback that outlasted the budget; saw:\n%s", + strings.Join(seen, "\n")) + } + if err := cmd.Wait(); err != nil { + t.Fatalf("child exited with %v, want a clean exit despite the abandoned callback", err) + } +}