From f2215e132e0407d5c6a1c50f55d0ca92cd7a0b02 Mon Sep 17 00:00:00 2001 From: zhangwenjian Date: Sat, 5 Sep 2026 15:28:15 +0800 Subject: [PATCH] =?UTF-8?q?fix=F0=9F=90=9B:=20handle=20SIGTERM,=20and=20st?= =?UTF-8?q?op=20exiting=20on=20a=20failed=20Shutdown?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three defects on one path, none of which could be seen from the code alone. **SIGTERM was never registered.** signal.Notify listened for os.Interrupt only, and Go terminates the process outright for a signal nothing handles. `docker stop`, a Kubernetes pod deletion and `systemctl stop` all send SIGTERM, so every line of the graceful shutdown below the wait was dead code outside a terminal: measured on a real binary, SIGINT printed "Shutdown Server ..." and "Server exiting" and SIGTERM printed neither. **A stuck shutdown could not be interrupted.** quit is buffered and signal.Notify stays armed after the first delivery, so further signals only refill the buffer. That was harmless while SIGTERM went to the default handler - it was the escape hatch. Registering it removes the hatch, so the disposition is now restored once the first signal is taken, and a second one kills the process the default way. Arming is split from waiting so a caller can arm before it announces readiness; a signal in between reaches the default handler, which is the very failure being fixed. **A failed Shutdown skipped everything after it.** log.Fatal is an unconditional os.Exit(1), and Shutdown reports an error precisely when connections were still in flight - the moment the cleanup that follows matters most. It is an error now, and the process carries on. That failure is closer than it looks. net/http only treats a StateNew connection as idle once it is over five seconds old, so a connection opened shortly before the signal that has sent nothing holds the whole budget: with the shipped settings.yml (readtimeout 1) the server closes it first and shutdown takes 5ms, but with settings.demo.yml (readtimeout 10000) the same connection made shutdown take 5.04s and exit 1, printing no "Server exiting". The default configuration is what has been hiding this. The wait and the shutdown are extracted so the subprocess tests can drive the real functions against an empty http.Server: CI has no database, and none of this needs one. Claude-Session: https://claude.ai/code/session_01HPTAw8b8tAdFNFn8rKdPYx --- cmd/api/server.go | 68 +++++++++-- cmd/api/signal_test.go | 266 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 323 insertions(+), 11 deletions(-) create mode 100644 cmd/api/signal_test.go diff --git a/cmd/api/server.go b/cmd/api/server.go index 83697e6b..de35e0ac 100644 --- a/cmd/api/server.go +++ b/cmd/api/server.go @@ -6,6 +6,7 @@ import ( "net/http" "os" "os/signal" + "syscall" "time" "github.com/gin-gonic/gin" @@ -85,8 +86,8 @@ func run() error { runStartupHooks() srv := &http.Server{ - Addr: fmt.Sprintf("%s:%d", config.ApplicationConfig.Host, config.ApplicationConfig.Port), - Handler: sdk.Runtime.GetEngine(), + Addr: fmt.Sprintf("%s:%d", config.ApplicationConfig.Host, config.ApplicationConfig.Port), + Handler: sdk.Runtime.GetEngine(), ReadTimeout: time.Duration(config.ApplicationConfig.ReadTimeout) * time.Second, WriteTimeout: time.Duration(config.ApplicationConfig.WriterTimeout) * time.Second, } @@ -135,23 +136,68 @@ func run() error { fmt.Printf("- Local: http://localhost:%d/swagger/admin/index.html \r\n", config.ApplicationConfig.Port) fmt.Printf("- Network: %s://%s:%d/swagger/admin/index.html \r\n", "http", pkg.GetLocalHost(), config.ApplicationConfig.Port) fmt.Printf("%s Enter Control + C Shutdown Server \r\n", pkg.GetCurrentTimeStr()) - // 等待中断信号以优雅地关闭服务器（设置 5 秒的超时时间） - quit := make(chan os.Signal, 1) - signal.Notify(quit, os.Interrupt) - <-quit - ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) - defer cancel() + waitForStopSignal() + log.Info("Shutdown Server ... ") - - if err := srv.Shutdown(ctx); err != nil { - log.Fatal("Server Shutdown:", err) + if err := shutdownServer(srv, shutdownTimeout); err != nil { + // Not log.Fatal: that is an unconditional os.Exit(1), and Shutdown + // reports an error exactly when connections were still in flight - + // which is when the cleanup that follows matters most. + log.Error("Server Shutdown: ", 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 + +// waitForStopSignal blocks until the process is asked to stop. +// +// SIGTERM is what actually arrives in production: `docker stop`, a Kubernetes +// pod deletion and `systemctl stop` all send it, and Go terminates the process +// immediately for a signal nobody listens for. Registering only os.Interrupt +// meant every graceful shutdown below this line was dead code outside a +// terminal. +// +// The disposition is restored before returning, so a second signal kills the +// process the default way. The channel keeps the notification we already took, +// so without this a stuck shutdown would swallow every further signal - once +// SIGTERM is registered there is no escape hatch left but SIGKILL. +func waitForStopSignal() os.Signal { + quit, disarm := armStopSignals() + defer disarm() + return <-quit +} + +// armStopSignals registers for the stop signals and returns the channel they +// arrive on together with the function that restores the default disposition. +// +// Registering is separate from waiting so a caller can arm before it announces +// that it is ready: a signal that arrives between the two is delivered to the +// default handler, which for both of these means the process dies without +// running any of this. +func armStopSignals() (<-chan os.Signal, func()) { + quit := make(chan os.Signal, 1) + signal.Notify(quit, os.Interrupt, syscall.SIGTERM) + return quit, func() { signal.Stop(quit) } +} + +// shutdownServer stops srv, giving in-flight requests up to timeout to finish. +// +// It returns the error instead of exiting on it. A caller that exits here skips +// its own cleanup, and Shutdown fails precisely when there was something left +// to clean up after. +func shutdownServer(srv *http.Server, timeout time.Duration) error { + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + return srv.Shutdown(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 new file mode 100644 index 00000000..604b27c3 --- /dev/null +++ b/cmd/api/signal_test.go @@ -0,0 +1,266 @@ +package api + +import ( + "fmt" + "net" + "net/http" + "os" + "os/exec" + "strings" + "syscall" + "testing" + "time" +) + +// The signal path cannot be exercised in-process: delivering a signal to the +// test binary would race with the test framework, and the disposition changes +// are global. So the test re-executes itself as a child, and the child runs the +// same waitForStopSignal / shutdownServer the server does. +// +// The child deliberately serves an empty http.Server rather than the real one: +// 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" +) + +// TestSignalChild is the child process. It is skipped in a normal run. +func TestSignalChild(t *testing.T) { + if os.Getenv(childEnv) != "1" { + t.Skip("child process entry point") + } + + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + fmt.Println("listen:", err) + os.Exit(3) + } + srv := &http.Server{Handler: http.NewServeMux()} + go func() { _ = srv.Serve(ln) }() + + if os.Getenv(childHangConn) == "1" { + c, err := net.Dial("tcp", ln.Addr().String()) + if err != nil { + fmt.Println("dial:", err) + os.Exit(5) + } + defer func() { _ = c.Close() }() + } + + // 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 + // this whole change is about, so the test must not reproduce it by + // accident. + quit, disarm := armStopSignals() + + fmt.Println(markerReady) + os.Stdout.Sync() + + sig := <-quit + disarm() + fmt.Println(markerSignal, sig) + os.Stdout.Sync() + + if os.Getenv(childStuckEnv) == "1" { + // Stand in for a cleanup hook that never finishes. The point of + // restoring the signal disposition is that a second signal still + // reaches the default handler and kills this. + time.Sleep(2 * time.Minute) + } + + timeout := shutdownTimeout + if os.Getenv(childHangConn) == "1" { + // A connection that has sent nothing keeps Shutdown busy: net/http + // only treats a StateNew connection as idle once it is more than five + // seconds old. A short budget makes the timeout deterministic without + // waiting out the real one. + timeout = 300 * time.Millisecond + } + + if err := shutdownServer(srv, timeout); err != nil { + // Deliberately not fatal, and deliberately not a bare return: the + // point is that whatever follows still runs. + fmt.Println("shutdown error:", err) + } else { + fmt.Println(markerShutdown) + } + fmt.Println(markerExiting) + os.Stdout.Sync() +} + +func startChild(t *testing.T, stuck bool, extraEnv ...string) (*exec.Cmd, *os.File, chan string) { + t.Helper() + + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("pipe: %v", err) + } + cmd := exec.Command(os.Args[0], "-test.run=TestSignalChild", "-test.v") + cmd.Env = append(os.Environ(), childEnv+"=1") + if stuck { + cmd.Env = append(cmd.Env, childStuckEnv+"=1") + } + cmd.Env = append(cmd.Env, extraEnv...) + cmd.Stdout = w + cmd.Stderr = w + if err := cmd.Start(); err != nil { + t.Fatalf("start child: %v", err) + } + _ = w.Close() + + lines := make(chan string, 64) + go func() { + defer close(lines) + buf := make([]byte, 4096) + var acc strings.Builder + for { + n, err := r.Read(buf) + if n > 0 { + acc.Write(buf[:n]) + for { + s := acc.String() + i := strings.IndexByte(s, '\n') + if i < 0 { + break + } + lines <- s[:i] + acc.Reset() + acc.WriteString(s[i+1:]) + } + } + if err != nil { + if acc.Len() > 0 { + lines <- acc.String() + } + return + } + } + }() + + t.Cleanup(func() { + _ = cmd.Process.Kill() + _, _ = cmd.Process.Wait() + _ = r.Close() + }) + return cmd, r, lines +} + +// await drains lines until one contains want, or the deadline passes. It +// returns everything it saw, so a failure says what the child actually did. +func await(t *testing.T, lines chan string, want string, d time.Duration) []string { + t.Helper() + var seen []string + deadline := time.After(d) + for { + select { + case l, ok := <-lines: + if !ok { + t.Fatalf("child output ended before %q; saw:\n%s", want, strings.Join(seen, "\n")) + } + seen = append(seen, l) + if strings.Contains(l, want) { + return seen + } + case <-deadline: + t.Fatalf("timed out waiting for %q; saw:\n%s", want, strings.Join(seen, "\n")) + } + } +} + +// Acceptance 19. Registering only os.Interrupt meant SIGTERM - the signal +// `docker stop`, Kubernetes and systemd all send - terminated the process +// before any of the shutdown path ran. Both must now reach it. +func TestBothSignalsRunTheShutdownPath(t *testing.T) { + for _, tc := range []struct { + name string + sig syscall.Signal + }{ + {"SIGINT", syscall.SIGINT}, + {"SIGTERM", syscall.SIGTERM}, + } { + t.Run(tc.name, func(t *testing.T) { + cmd, _, lines := startChild(t, false) + await(t, lines, markerReady, 30*time.Second) + + if err := cmd.Process.Signal(tc.sig); err != nil { + t.Fatalf("signal: %v", err) + } + + await(t, lines, markerSignal, 10*time.Second) + await(t, lines, markerShutdown, 10*time.Second) + await(t, lines, markerExiting, 10*time.Second) + + if err := cmd.Wait(); err != nil { + t.Fatalf("child exited with %v, want a clean exit", err) + } + }) + } +} + +// Acceptance 20. quit is a buffered channel and signal.Notify stays armed, so +// without restoring the disposition a second signal only refills the buffer: +// once SIGTERM is registered, a shutdown that hangs could not be interrupted by +// anything short of SIGKILL. +func TestASecondSignalStillKillsAStuckShutdown(t *testing.T) { + cmd, _, lines := startChild(t, true) + await(t, lines, markerReady, 30*time.Second) + + if err := cmd.Process.Signal(syscall.SIGTERM); err != nil { + t.Fatalf("first signal: %v", err) + } + await(t, lines, markerSignal, 10*time.Second) + + // The child is now inside a cleanup that will not finish on its own. + if err := cmd.Process.Signal(syscall.SIGTERM); err != nil { + t.Fatalf("second signal: %v", err) + } + + done := make(chan error, 1) + go func() { done <- cmd.Wait() }() + + select { + case err := <-done: + if err == nil { + t.Fatal("child exited cleanly; it was supposed to be killed by the second signal") + } + case <-time.After(15 * time.Second): + t.Fatal("the second signal did not kill a stuck shutdown - the escape hatch is gone") + } +} + +// Acceptance 21. srv.Shutdown reports an error exactly when connections were +// still in flight, and the old code answered that with log.Fatal - an +// unconditional os.Exit(1). Everything after it, which is where the cleanup +// hooks will hang, never ran. A failed Shutdown must not end the process. +func TestShutdownTimeoutDoesNotStopWhatFollows(t *testing.T) { + cmd, _, lines := startChild(t, false, childHangConn+"=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) + + seen := await(t, lines, markerExiting, 20*time.Second) + + var timedOut bool + for _, l := range seen { + if strings.Contains(l, "shutdown error:") { + timedOut = true + } + } + if !timedOut { + t.Fatalf("Shutdown did not time out, so this test proves nothing; 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) + } +}