amadan
Drain sign-in mail and close the database on a failed shutdown too
Astra on #25, round 3: when rastrillo's ten-second Server.Shutdown deadline passed with a request still running, Serve returned an error and main called os.Exit(1), skipping the deferred Runtime.Close and d.Close. An unrelated slow request cost a link already answered ?sent=1. main's body is now run(), which returns every failure instead of exiting, so its defers always run: the bounded mail drain, then the database close. main is the only os.Exit after startup, after run returns. The read-flags, resolve, open-database and build-app exits moved into run as well; build-app's had skipped d.Close. A handler still running past the HTTP deadline that reaches the queue after its close is refused, as the comment at rt.Close records. Test, failing on cf50d5c: TestSIGTERMDrainsMailWhenHTTPShutdownTimesOut. One sign-in is answered ?sent=1 and held at the relay's DATA, and a second POST never finishes its body. After SIGTERM the relay recovers past the HTTP deadline, inside the mail drain. The test requires the process to still be alive at 11.5 s, the link delivered, exit status 1 and the deadline error in the log. Before the fix it exited at 10.0 s with nothing delivered.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2 files changed,
+112
−15
cmd/calls/main.go+31 −15cmd/calls/shutdown_test.go+81 −0
CI passed — run details
CI log
=== vet === go vet ./... === fmt === === test === go test ./... ok amadan.net/oficina/calls/callscore (cached) ok amadan.net/oficina/calls/cmd/calls 13.117s ok amadan.net/oficina/calls/cmd/quality-summary (cached) ok amadan.net/oficina/calls/internal/calls 2.057s ok amadan.net/oficina/calls/internal/calls/apns (cached) ok amadan.net/oficina/calls/internal/calls/hub (cached) ? amadan.net/oficina/calls/internal/calls/icons [no test files] ? amadan.net/oficina/calls/internal/calls/keymailtest [no test files] ok amadan.net/oficina/calls/internal/calls/relay (cached) ok amadan.net/oficina/calls/internal/calls/seal (cached) ok amadan.net/oficina/calls/internal/callstest (cached) ? amadan.net/oficina/calls/protocol [no test files] ? amadan.net/oficina/calls/scripts/writeestilo [no test files] === migration-check === go run amadan.net/rastrillo/rastrillo/cmd/rastrillo migration check rastrillo migration check: models and migrations agree === race === CGO_ENABLED=1 go test -race ./internal/... ok amadan.net/oficina/calls/internal/calls 12.418s ok amadan.net/oficina/calls/internal/calls/apns (cached) ok amadan.net/oficina/calls/internal/calls/hub (cached) ? amadan.net/oficina/calls/internal/calls/icons [no test files] ? amadan.net/oficina/calls/internal/calls/keymailtest [no test files] ok amadan.net/oficina/calls/internal/calls/relay (cached) ok amadan.net/oficina/calls/internal/calls/seal (cached) ok amadan.net/oficina/calls/internal/callstest (cached)
diff --git a/cmd/calls/main.go b/cmd/calls/main.go| index 42b768c..21b2f23 100644 |
| --- a/cmd/calls/main.go |
| +++ b/cmd/calls/main.go |
| @@ -30,6 +30,20 @@ func main() { |
| // is a JSON object. |
| reportLogger := slog.New(slog.NewJSONHandler(stderr, nil)) |
| + // The only os.Exit after startup. run owns every resource and |
| + // returns its error only after its own defers have run: the sign-in |
| + // mail queue's bounded drain, then the database close. An os.Exit |
| + // inside it would skip them, and a failed HTTP shutdown (rastrillo's |
| + // ten-second deadline passing with a request still running) used to |
| + // cost a link already answered ?sent=1 (Astra on #25, round 3). |
| + if err := run(logger, reportLogger); err != nil { |
| + logger.Error("calls: exiting", "err", err) |
| + os.Exit(1) |
| + } |
| +} |
| + |
| +// run is main's body. Every failure returns, never exits; see main. |
| +func run(logger, reportLogger *slog.Logger) error { |
| // -env is stripped before Resolve sees argv, because Resolve parses |
| // os.Args itself for -socket, -addr and -db and a second flag set |
| // would refuse the platform's own activation arguments. Only the |
| @@ -37,22 +51,19 @@ func main() { |
| // misconfigured box relax every refusal (config.go). |
| envFlag, rest, err := extractEnvFlag(os.Args[1:]) |
| if err != nil { |
| - logger.Error("read flags", "err", err) |
| - os.Exit(1) |
| + return fmt.Errorf("read flags: %w", err) |
| } |
| os.Args = append(os.Args[:1], rest...) |
| env := &envFlag |
| opts, err := rastrillo.Resolve(rastrillo.Options{DBPath: "calls.db", Logger: logger}) |
| if err != nil { |
| - logger.Error("resolve activation", "err", err) |
| - os.Exit(1) |
| + return fmt.Errorf("resolve activation: %w", err) |
| } |
| d, err := db.Open(opts.DBPath, logger) |
| if err != nil { |
| - logger.Error("open database", "err", err) |
| - os.Exit(1) |
| + return fmt.Errorf("open database: %w", err) |
| } |
| defer d.Close() |
| @@ -89,14 +100,19 @@ func main() { |
| mux, rt, err := calls.App(ctx, d, cfg) |
| if err != nil { |
| - logger.Error("build app", "err", err) |
| - os.Exit(1) |
| + return fmt.Errorf("build app: %w", err) |
| } |
| - // After rastrillo.Serve returns and before d.Close() above (defers |
| - // run last-first): close the sign-in mail queue and wait for its |
| - // bounded drain. Not at SIGTERM: Serve's Shutdown is still letting |
| - // accepted requests finish then, and a link one of them queues must |
| - // reach the relay rather than be refused or die with the process. |
| + // After rastrillo.Serve returns, however it returns, and before |
| + // d.Close() above (defers run last-first): close the sign-in mail |
| + // queue and wait for its bounded drain. Not at SIGTERM: Serve's |
| + // Shutdown is still letting accepted requests finish then, and a |
| + // link one of them queues must reach the relay rather than be |
| + // refused or die with the process. |
| + // |
| + // The cutoff, when Shutdown times out: a link queued before this |
| + // close is drained; a handler still running past rastrillo's |
| + // deadline that reaches the queue afterwards is refused, and dies |
| + // with the process like the rest of its request. |
| defer rt.Close() |
| opts.Mux = mux |
| @@ -110,9 +126,9 @@ func main() { |
| // rastrillo's plain "Something went wrong." (shared chrome §3.3). |
| opts.ErrorPage = rt.ErrorPage |
| if err := rastrillo.Serve(opts); err != nil { |
| - logger.Error("serve failed", "err", err) |
| - os.Exit(1) |
| + return fmt.Errorf("serve failed: %w", err) |
| } |
| + return nil |
| } |
| // smtpSetting reads one SMTP setting, this app's own variable first and |
diff --git a/cmd/calls/shutdown_test.go b/cmd/calls/shutdown_test.go| index a368e36..3d51390 100644 |
| --- a/cmd/calls/shutdown_test.go |
| +++ b/cmd/calls/shutdown_test.go |
| @@ -3,6 +3,7 @@ package main |
| import ( |
| "bufio" |
| "context" |
| + "errors" |
| "net" |
| "net/http" |
| "net/url" |
| @@ -138,6 +139,86 @@ func TestSIGTERMDeliversAnInFlightSigninsLink(t *testing.T) { |
| } |
| } |
| +// TestSIGTERMDrainsMailWhenHTTPShutdownTimesOut: rastrillo.Serve |
| +// returns an error when its ten-second Server.Shutdown deadline passes |
| +// with a request still running, and main used to os.Exit(1) on it, |
| +// skipping the deferred drain. An unrelated slow request then cost an |
| +// already-acknowledged link (Astra on oficina/meet #25, round 3). The |
| +// drain, and the database close after it, must run on that path too. |
| +// |
| +// One sign-in is answered ?sent=1 and held at the relay's DATA; a second |
| +// POST never finishes its body, so HTTP shutdown times out. The relay |
| +// recovers after the HTTP deadline but well inside the mail drain |
| +// window. The process must still be alive then, deliver the link, and |
| +// exit 1 for the failed shutdown. |
| +func TestSIGTERMDrainsMailWhenHTTPShutdownTimesOut(t *testing.T) { |
| + if testing.Short() { |
| + t.Skip("waits out rastrillo's ten-second shutdown deadline") |
| + } |
| + relay := newHeldRelay(t) |
| + p := startCalls(t, relay.port) |
| + |
| + form := url.Values{"address": {"paul@example.test"}, "force": {"1"}} |
| + req, _ := http.NewRequest(http.MethodPost, p.origin+"/signin", strings.NewReader(form.Encode())) |
| + req.Header.Set("Content-Type", "application/x-www-form-urlencoded") |
| + req.Header.Set("Origin", p.origin) |
| + req.Header.Set("Sec-Fetch-Site", "same-origin") |
| + res, err := p.client.Do(req) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + res.Body.Close() |
| + if res.StatusCode != http.StatusSeeOther || !strings.Contains(res.Header.Get("Location"), "sent=1") { |
| + t.Fatalf("POST /signin: %d %q, want 303 ?sent=1", res.StatusCode, res.Header.Get("Location")) |
| + } |
| + select { |
| + case <-relay.atData: |
| + case <-time.After(10 * time.Second): |
| + t.Fatal("the queued link never reached the relay") |
| + } |
| + |
| + // A request that never finishes: HTTP shutdown cannot complete. |
| + stalled, err := net.Dial("tcp", p.addr) |
| + if err != nil { |
| + t.Fatal(err) |
| + } |
| + defer stalled.Close() |
| + body := url.Values{"address": {"other@example.test"}, "force": {"1"}}.Encode() |
| + if _, err := stalled.Write([]byte("POST /signin HTTP/1.1\r\nHost: " + p.addr + "\r\nOrigin: " + p.origin + |
| + "\r\nSec-Fetch-Site: same-origin\r\nContent-Type: application/x-www-form-urlencoded\r\n" + |
| + "Content-Length: " + strconv.Itoa(len(body)) + "\r\n\r\n" + body[:len(body)-1])); err != nil { |
| + t.Fatal(err) |
| + } |
| + time.Sleep(200 * time.Millisecond) |
| + |
| + if err := p.cmd.Process.Signal(syscall.SIGTERM); err != nil { |
| + t.Fatal(err) |
| + } |
| + signalled := time.Now() |
| + select { |
| + case err := <-p.exited: |
| + t.Fatalf("process exited (%v) %v after SIGTERM, with an acknowledged link still at the relay", err, time.Since(signalled).Round(time.Millisecond)) |
| + case <-time.After(11500 * time.Millisecond): |
| + } |
| + relay.release() |
| + |
| + select { |
| + case err := <-p.exited: |
| + var exit *exec.ExitError |
| + if !errors.As(err, &exit) || exit.ExitCode() != 1 { |
| + t.Fatalf("process exit: %v, want status 1 for the failed HTTP shutdown", err) |
| + } |
| + case <-time.After(20 * time.Second): |
| + t.Fatal("process did not exit after the relay accepted the message") |
| + } |
| + if !relay.accepted() { |
| + t.Fatal("process exited without the relay accepting the acknowledged sign-in link") |
| + } |
| + if !strings.Contains(p.out.String(), "context deadline exceeded") { |
| + t.Fatal("HTTP shutdown did not time out; the test did not exercise the failed-shutdown path") |
| + } |
| +} |
| + |
| // proc is a Calls process started by startCalls. |
| type proc struct { |
| addr, origin string |