From 59574a8cdb6286ae0ebdc8ff23b04ff829186bde Mon Sep 17 00:00:00 2001 From: Raymond Nicholas Date: Thu, 17 Sep 2026 21:45:48 +0100 Subject: [PATCH 1/3] feat: drain in-flight requests and close the database on shutdown main.go ended at log.Fatal(ListenAndServe), so SIGTERM killed requests mid-flight and the os.Exit skipped every defer, including db.Close(). That left the SQLite WAL uncheckpointed: api.db stayed 4096 bytes while the -wal file held the whole schema. Co-Authored-By: Claude Code --- main.go | 163 ++++++++++++++++++++++++++++++++++++++---- shutdown.go | 53 ++++++++++++++ shutdown_test.go | 181 +++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 382 insertions(+), 15 deletions(-) create mode 100644 shutdown.go create mode 100644 shutdown_test.go diff --git a/main.go b/main.go index 3f70bf9..77892ea 100644 --- a/main.go +++ b/main.go @@ -3,9 +3,15 @@ package main import ( "context" "database/sql" + "errors" "log" + "net" "net/http" + "os" + "os/signal" "strings" + "sync" + "syscall" "time" _ "github.com/lib/pq" @@ -57,7 +63,13 @@ func main() { if err != nil { log.Fatalf("failed to open DB connection: %v", err) } - defer db.Close() + // Deliberately not `defer db.Close()`. Closing the database is the last + // step of the teardown at the end of main, for two reasons: a defer + // would close it before the background workers have stopped writing + // through it, and the log.Fatalf on the failure path calls os.Exit, + // which runs no defers at all — so a defer here would silently not + // happen in exactly the case where an unclean exit is most likely. On + // SQLite that close is also the WAL checkpoint; see the teardown. if err := db.Ping(); err != nil { log.Fatalf("failed to ping DB: %v", err) } @@ -114,6 +126,24 @@ func main() { st := openStores(cfg, db) + // The context every long-running thing in this process hangs off, and + // the reason it exists: this server is expected to be stopped by a + // signal — Ctrl-C in development, SIGTERM from systemd, Kubernetes or + // `docker stop` in a deployment — and all three mean "finish what you + // are doing and exit", not "die now". + // + // stopSignals cancels this context as well as unregistering the + // handler, which is what the teardown at the bottom of main relies on: + // on the signal path the workers have already seen the cancellation, + // and on the listener-failure path nothing else would have told them. + appCtx, stopSignals := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM) + + // The background workers, tracked so the teardown can wait for them + // before closing the database handle they write through. Without the + // Wait, "the workers have stopped" would be a hope rather than a fact, + // and a delivery landing after db.Close() logs a confusing error. + var workers sync.WaitGroup + // Hoisted into locals rather than constructed inline in the config // literal below, because the router needs these same instances: // GET /v1/admin/security/hash-migration counts what the engine wrote, @@ -309,12 +339,22 @@ func main() { // actually in force. engineCfg.LockoutThreshold = cfg.LockoutThreshold engineCfg.LockoutDuration = cfg.LockoutDuration + // Declared here rather than inside the block below because the teardown + // at the end of main closes it, and it is only non-nil when REDIS_URL + // asked for it. + var redisClient *redis.Client if cfg.RedisURL != "" { redisOpts, err := redis.ParseURL(cfg.RedisURL) if err != nil { log.Fatalf("invalid REDIS_URL: %v", err) } - limiter, err := security.NewRedisRateLimiter(redis.NewClient(redisOpts), cfg.RateLimitAttempts, cfg.RateLimitWindow) + // Hoisted out of the constructor call below so the teardown can + // close it. The client is this process's, not cryden's — the + // limiter is handed a client that is already connected and only + // ever talks to it through the Scripter interface — so closing it + // is this repo's job and nothing else would do it. + redisClient = redis.NewClient(redisOpts) + limiter, err := security.NewRedisRateLimiter(redisClient, cfg.RateLimitAttempts, cfg.RateLimitWindow) if err != nil { log.Fatalf("failed to build the Redis rate limiter: %v", err) } @@ -389,17 +429,20 @@ func main() { // The delivery worker. Started only when there is somewhere to // deliver to, so an unconfigured deployment runs no goroutine at all. // - // Run takes context.Background() because this repo has no graceful - // shutdown anywhere yet — main.go ends at log.Fatal(ListenAndServe), - // which exits the process and every goroutine with it. Introducing a - // real shutdown touches every component and is its own change; noted - // in PROGRESS.md as still owed rather than smuggled in here. + // Run takes appCtx, so a shutdown stops it at the same moment it stops + // accepting requests rather than after the drain: the two are + // independent, and holding a delivery back until the HTTP side has + // finished would only delay the exit. A delivery cut off mid-flight is + // what the stale reclaim exists for — see RunOnce's own note. if webhookStore != nil { worker := webhook.NewWorker(webhookStore, cfg.WebhookURL, cfg.WebhookSecret) worker.MaxAttempts = cfg.WebhookMaxAttempts worker.Wake = webhookWake worker.Log = log.Default() - go worker.Run(context.Background()) + // WaitGroup.Go (Go 1.25) rather than Add plus a goroutine: the + // counter and the goroutine are one statement, so the pairing that + // has to stay balanced cannot drift. + workers.Go(func() { worker.Run(appCtx) }) events := len(cfg.WebhookEvents) if events == 0 { @@ -418,10 +461,10 @@ func main() { // passed in, so the row states the exact interval the engine was asked // to count over rather than one reconstructed from the text afterwards. // - // Run takes context.Background() for the same reason the worker does: - // this repo still has no graceful shutdown, and that is noted in - // PROGRESS.md as owed rather than smuggled in behind a second - // goroutine. + // Run takes appCtx for the same reason the worker does. A digest cut + // off mid-build records nothing and is retried at the next interval, + // which is the right outcome — half a window written to the history + // would be worse than no row. if digestStore != nil { scheduler := &digest.Scheduler{ Store: digestStore, @@ -440,10 +483,16 @@ func main() { }, nil }, } - go scheduler.Run(context.Background()) + workers.Go(func() { scheduler.Run(appCtx) }) log.Printf("scheduled digests enabled: one every %s", cfg.DigestInterval) } + // Hoisted out of the Deps literal below because the teardown closes it: + // the cached provider pair holds a second database connection (the + // read-only one behind the AI query surface), and nothing else would + // release it. See Service.Close. + askAI := askai.New(settingsSecrets) + router := httpapi.NewRouter(httpapi.Deps{ Engine: engine, DB: db, @@ -471,13 +520,97 @@ func main() { // re-wire when an operator saves a change — it answers 404 // not_configured until then, like every other unconfigured // feature here. - AskAI: askai.New(settingsSecrets), + AskAI: askAI, }) limiter := httpapi.NewEdgeRateLimiter(cfg.EdgeRateLimit, cfg.EdgeRateLimitWindow) handler := httpapi.WithCORS(cfg.CORSOrigins, httpapi.WithEdgeRateLimit(limiter, router)) + // The listener is opened before the server starts serving so a port + // already in use is a startup failure that says so, rather than an + // error out of Serve after the line below has claimed the API is up. + srv := &http.Server{ + Addr: ":" + cfg.Port, + Handler: handler, + } + ln, err := net.Listen("tcp", srv.Addr) + if err != nil { + log.Fatalf("failed to listen on %s: %v", srv.Addr, err) + } + + // Serve in a goroutine, buffered so it can never block on a receiver + // that has already moved on — on the signal path nothing reads this + // channel until the drain has finished. + listenerErr := make(chan error, 1) + go func() { + err := srv.Serve(ln) + if errors.Is(err, http.ErrServerClosed) { + // Shutdown or Close was called, which is the normal way out + // of Serve rather than a failure to report. + err = nil + } + listenerErr <- err + }() + log.Printf("api listening on :%s (CORS origins: %v)", cfg.Port, cfg.CORSOrigins) - log.Fatal(http.ListenAndServe(":"+cfg.Port, handler)) + + var serveErr error + select { + case serveErr = <-listenerErr: + // The listener stopped on its own — a closed socket, a descriptor + // limit. Nothing asked it to stop, so there is nothing to drain. + log.Printf("server stopped serving: %v", serveErr) + case <-appCtx.Done(): + log.Printf("shutdown signal received: draining in-flight requests (up to %s)", shutdownDrainTimeout) + serveErr = drain(srv, shutdownDrainTimeout) + // Serve has returned by now on every path Shutdown can take, so + // this is where a listener that failed *during* the drain reports + // itself — and the buffered channel is why it could not have been + // dropped in the gap. A clean drain leaves nil here and keeps + // serveErr nil. + if err := <-listenerErr; serveErr == nil { + serveErr = err + } + } + + // ---- teardown ---- + // + // Reached on both paths above, and written once rather than deferred + // so that the order is visible and deliberate. The order is: stop the + // workers, release everything holding a connection to something else, + // then close the database last. + // + // stopSignals cancels appCtx, which is what stops the workers on the + // listener-failure path; on the signal path they saw it already. Either + // way it happens before anything they write through is closed, and the + // Wait is what makes that a fact rather than a likelihood. + stopSignals() + workers.Wait() + + // The AI query surface's own read-only connection pool. Errors are + // logged rather than fatal: by this point the process is leaving, and + // a pool that will not close is not a reason to skip the rest. + if err := askAI.Close(); err != nil { + log.Printf("closing the ask-ai providers: %v", err) + } + if redisClient != nil { + if err := redisClient.Close(); err != nil { + log.Printf("closing the Redis client: %v", err) + } + } + + // Last, and the reason this is not the deferred call it used to be: + // closing the database is what checkpoints the WAL on SQLite, and the + // os.Exit in log.Fatalf below would skip a defer. On a SQLite + // deployment this call is the difference between a schema that is in + // api.db and a schema that is only in api.db-wal. + if err := db.Close(); err != nil { + log.Printf("closing the database: %v", err) + } + + if serveErr != nil { + log.Fatalf("server: %v", serveErr) + } + log.Printf("shutdown complete") } // sqliteDSN builds the connection string for SQLITE_PATH. diff --git a/shutdown.go b/shutdown.go new file mode 100644 index 0000000..ccfc65c --- /dev/null +++ b/shutdown.go @@ -0,0 +1,53 @@ +package main + +import ( + "context" + "fmt" + "net/http" + "time" +) + +// shutdownDrainTimeout bounds how long a shutdown waits for the requests +// already in flight to finish. +// +// Thirty seconds is a number chosen rather than derived, so here is what +// it is trading. Too short and a slow request is cut off mid-write — a +// password change that has updated the hash but not yet revoked the +// session, say. Too long and a deploy sits waiting on one wedged client +// that will never read its response. Thirty seconds is past every +// handler's own work here (the slowest is the read-only-database check on +// PUT /v1/admin/settings/database-provider, which opens a connection to +// another server) and short enough that a rolling deploy is not held up. +// +// It is a constant rather than an env var because it is a property of +// this API's handlers, not of a deployment: nothing about a particular +// install makes a request here take longer. If that stops being true — +// the ask-ai widget's questions take as long as a model takes, and today +// that is bounded by the provider's own client timeout rather than by +// anything here — it becomes a knob. +const shutdownDrainTimeout = 30 * time.Second + +// drain stops the server accepting new connections and waits up to +// timeout for the ones already in flight to finish. +// +// It is the whole of what a graceful shutdown does to the HTTP side, kept +// out of main so it can be tested: the property worth pinning is that a +// request which has already started still gets its response after the +// signal arrives, and that a request which refuses to finish does not +// hold the process open forever. +func drain(srv *http.Server, timeout time.Duration) error { + ctx, cancel := context.WithTimeout(context.Background(), timeout) + defer cancel() + + if err := srv.Shutdown(ctx); err != nil { + // Shutdown has given up, which leaves the connections it was + // waiting on open. Close is what actually releases the listener + // and the sockets — without it the process can still exit, but + // nothing that was waiting on this server is told so. Its error is + // dropped deliberately: the interesting failure is the timeout, + // and Close's own error is almost always the same one. + _ = srv.Close() + return fmt.Errorf("draining in-flight requests (waited %s): %w", timeout, err) + } + return nil +} diff --git a/shutdown_test.go b/shutdown_test.go new file mode 100644 index 0000000..32adbd0 --- /dev/null +++ b/shutdown_test.go @@ -0,0 +1,181 @@ +package main + +import ( + "context" + "errors" + "net" + "net/http" + "strings" + "testing" + "time" +) + +// slowHandler is a server whose one handler blocks until the test lets it +// finish, and announces when it has started. Both halves matter: the +// announcement is what lets a test know the request is genuinely in flight +// before the drain begins, with no sleep and no race. +func slowHandler(started chan<- struct{}, release <-chan struct{}) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(started) + <-release + w.WriteHeader(http.StatusOK) + }) +} + +// startServer serves h on an ephemeral port and returns the server, the +// base URL to reach it, and a channel carrying Serve's error. +func startServer(t *testing.T, h http.Handler) (*http.Server, string, <-chan error) { + t.Helper() + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listening: %v", err) + } + srv := &http.Server{Handler: h} + serveErr := make(chan error, 1) + go func() { + err := srv.Serve(ln) + if errors.Is(err, http.ErrServerClosed) { + err = nil + } + serveErr <- err + }() + return srv, "http://" + ln.Addr().String(), serveErr +} + +// The property a graceful shutdown exists for: a request that has already +// started still gets its response, even though the signal has arrived and +// the listener has stopped accepting new ones. +// +// This is what a SIGTERM from `docker stop` or a rolling deploy does to a +// deployment, and the alternative — the process dying mid-request — is a +// password change that updated the hash but never revoked the session, or +// a client told the connection was closed with no reason. +func TestShutdownDrainsAnInFlightRequest(t *testing.T) { + started := make(chan struct{}) + release := make(chan struct{}) + srv, baseURL, serveErr := startServer(t, slowHandler(started, release)) + + response := make(chan int, 1) + go func() { + resp, err := http.Get(baseURL) + if err != nil { + // A drain that dropped the connection shows up here rather + // than as a status code, which is the failure this test is + // for. + response <- 0 + return + } + defer resp.Body.Close() + response <- resp.StatusCode + }() + + // Wait for the handler to be running before draining, so this is a + // genuine in-flight request rather than a race against the client. + <-started + + drained := make(chan error, 1) + go func() { drained <- drain(srv, 5*time.Second) }() + + // The drain must still be waiting at this point — that it is not + // finished before the handler is released is half the assertion. + select { + case err := <-drained: + t.Fatalf("drain returned %v before the in-flight request finished", err) + case <-time.After(50 * time.Millisecond): + } + + close(release) + + if err := <-drained; err != nil { + t.Fatalf("drain failed with a request that was willing to finish: %v", err) + } + if code := <-response; code != http.StatusOK { + t.Errorf("in-flight request returned %d, want 200 — a drained request must still be answered", code) + } + if err := <-serveErr; err != nil { + t.Errorf("Serve returned %v after a clean shutdown, want nil", err) + } + + // And the listener really is closed: the drain is supposed to stop + // accepting, not just stop answering. + if _, err := http.Get(baseURL); err == nil { + t.Error("the server still accepts connections after a drain") + } +} + +// The other half of the contract: a request that will not finish does not +// hold the process open forever. A drain with no bound is a deploy that +// hangs until somebody kills it, which is worse than a cut-off request +// because it needs a human. +func TestShutdownGivesUpOnARequestThatWillNotFinish(t *testing.T) { + started := make(chan struct{}) + // Never closed: this handler is the wedged client the timeout exists + // for. It is still running when the test ends, which is fine — the + // goroutine belongs to the test binary, not to a process that is + // trying to exit. + release := make(chan struct{}) + defer close(release) + + srv, baseURL, _ := startServer(t, slowHandler(started, release)) + + go func() { + resp, err := http.Get(baseURL) + if err == nil { + resp.Body.Close() + } + }() + <-started + + begin := time.Now() + err := drain(srv, 100*time.Millisecond) + elapsed := time.Since(begin) + + if err == nil { + t.Fatal("drain returned nil with a request that could not finish") + } + if !errors.Is(err, context.DeadlineExceeded) { + t.Errorf("drain error = %v, want it to wrap context.DeadlineExceeded", err) + } + // The message names the wait, because the operator reading it is + // looking at a deploy that took longer than expected and needs to know + // which bound was hit. + if want := "100ms"; !strings.Contains(err.Error(), want) { + t.Errorf("drain error = %q, want it to name the %s wait", err, want) + } + if elapsed > 2*time.Second { + t.Errorf("drain took %s to give up on a 100ms bound", elapsed) + } +} + +// drain is not the only way this server stops. A listener that fails on its +// own — a closed socket, a descriptor limit — has nothing in flight to +// drain, and Serve's error is what says so. The test pins that the error +// survives the ErrServerClosed translation rather than being swallowed +// into a nil. +func TestServeErrorIsReportedRatherThanDrained(t *testing.T) { + ln, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("listening: %v", err) + } + srv := &http.Server{Handler: http.NotFoundHandler()} + serveErr := make(chan error, 1) + go func() { + err := srv.Serve(ln) + if errors.Is(err, http.ErrServerClosed) { + err = nil + } + serveErr <- err + }() + + // Closing the listener behind Serve is the failure being simulated. + ln.Close() + + select { + case err := <-serveErr: + if err == nil { + t.Fatal("a closed listener produced a nil error; ErrServerClosed is being translated too eagerly") + } + case <-time.After(2 * time.Second): + t.Fatal("Serve did not return after its listener was closed") + } +} From e9ddfbf2fed55460f6b3c170206de36cff71a7fb Mon Sep 17 00:00:00 2001 From: Raymond Nicholas Date: Thu, 17 Sep 2026 21:45:52 +0100 Subject: [PATCH 2/3] docs: drop the comments claiming this repo has no shutdown path Four comments asserted it and are now false. shiplog's async-sink argument changed reasoning rather than wording: the missing pieces are the buffer and the flush policy, not a lifecycle to hang off. Co-Authored-By: Claude Code --- askai/askai.go | 6 +++--- digest/schedule.go | 11 ++++++----- shiplog/store.go | 15 ++++++++------- webhook/worker.go | 8 ++++---- 4 files changed, 21 insertions(+), 19 deletions(-) diff --git a/askai/askai.go b/askai/askai.go index 8134ccc..3f43f5b 100644 --- a/askai/askai.go +++ b/askai/askai.go @@ -246,9 +246,9 @@ func (s *Service) Ask(ctx context.Context, req Request) (widget.Answer, error) { // Close releases the connection pool behind the cached providers. The // cached pair is replaced and closed on every rebuild, so this is only -// about the last one — and nothing calls it yet, because this repo still -// has no graceful shutdown for it to hang off. It exists so that adding -// one does not have to start by widening this type's API. +// about the last one — main.go calls it during shutdown, after the server +// has drained and the background workers have stopped, so no question can +// be in flight against a provider this is about to close. func (s *Service) Close() error { s.mu.Lock() defer s.mu.Unlock() diff --git a/digest/schedule.go b/digest/schedule.go index 473744a..d64fe1b 100644 --- a/digest/schedule.go +++ b/digest/schedule.go @@ -56,11 +56,12 @@ type Scheduler struct { // start. A history that grows with restarts rather than with time is not // a history of anything. // -// main.go hands this context.Background(), because this repo has no -// graceful shutdown yet — the same caveat, and the same reasoning, as the -// webhook worker's goroutine. Nothing here needs stopping today: an -// interrupted run loses at most one digest, and the next interval builds -// another. +// main.go hands this the context the shutdown signal cancels, so a SIGTERM +// stops it between runs. Nothing here needed to be stoppable for +// correctness — an interrupted run records nothing and the next interval +// builds another — but a build cut off halfway is worse than one that +// never started, because half a window in the history reads as a quiet +// week rather than as a missing one. func (s *Scheduler) Run(ctx context.Context) { if s.Interval <= 0 || s.Store == nil || s.Build == nil { return diff --git a/shiplog/store.go b/shiplog/store.go index d9f6e0a..f7994cd 100644 --- a/shiplog/store.go +++ b/shiplog/store.go @@ -37,13 +37,14 @@ // path the engine logged from. That is a real cost — one insert per // record, and a login emits many — and it is not the shape a busy // deployment wants. It is the shape this one can have: making it -// asynchronous needs a buffer, a flush policy and a shutdown path, and -// this repo has no graceful shutdown anywhere yet (main.go ends at -// log.Fatal(ListenAndServe)). An asynchronous sink whose buffer is never -// flushed is a log that silently drops the last records before a crash, -// which for a log is the failure that matters most. So the honest choice -// is a bounded synchronous write now, and async logging as its own -// change alongside the shutdown path, not smuggled in behind this one. +// asynchronous needs a buffer, a flush policy, and a flush during +// shutdown. The shutdown now exists (main.go drains, stops the workers, +// then closes the database), so the missing piece is no longer a +// lifecycle to hang off — it is the buffer and the flush, and a decision +// about what happens to records still buffered when the drain times out. +// Until that is decided, the honest choice is a bounded synchronous write, +// because a log that silently drops the last records before a crash is the +// failure that matters most for a log. // // The level filter in front of the sink is what keeps the volume sane: // LOG_LEVEL defaults to info and the engine's debug records — the bulk of diff --git a/webhook/worker.go b/webhook/worker.go index 887659d..377ad3f 100644 --- a/webhook/worker.go +++ b/webhook/worker.go @@ -145,10 +145,10 @@ func Verify(secret string, body []byte, header string) bool { } // Run delivers until ctx is cancelled. It is meant to be started once, in -// its own goroutine; main.go passes context.Background() because this repo -// has no graceful shutdown anywhere yet (see PROGRESS.md — introducing one -// touches every component and is its own change, not a passenger on this -// one). +// its own goroutine; main.go hands it the context the shutdown signal +// cancels, so a SIGTERM stops it. A delivery cut off mid-flight is not +// lost — the row stays in_flight and the stale reclaim picks it up on the +// next boot, which is why stopping promptly is safe here. func (w *Worker) Run(ctx context.Context) { w.applyDefaults() if w.Secret == "" { From 40d636ae1041812f130051f240b34d43877795e0 Mon Sep 17 00:00:00 2001 From: Raymond Nicholas Date: Thu, 17 Sep 2026 21:45:56 +0100 Subject: [PATCH 3/3] docs: write up the graceful shutdown change Records the end-to-end verification (SIGTERM, then the database read read-only with no sidecar files: 7 migrations, 1 user, 2 sessions), and retires the owed items in Tiers 3, 5 and 6 and in Tier 7's spec. Co-Authored-By: Claude Code --- README.md | 4 +- docs/development/CURRENT-STATE.md | 113 +++++++++++++++++++++++++----- docs/development/NEXT.md | 34 ++++----- docs/development/PROGRESS.md | 54 ++++++++++++++ 4 files changed, 169 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index 485303d..b37c2ce 100644 --- a/README.md +++ b/README.md @@ -86,7 +86,9 @@ No migration step exists on SQLite. `main.go` calls cryden's own `sqlite.Migrate The connection is opened with three pragmas, all of them load-bearing: `foreign_keys(1)` (off by default, so the schema's `ON DELETE` clauses would silently not run), `busy_timeout(5000)` (zero by default, so a concurrent writer gets an immediate `SQLITE_BUSY` instead of waiting), and `journal_mode(WAL)`. The server verifies the first two on every boot with cryden's own `CheckPragmas` and refuses to start if the DSN and the driver have drifted apart. -**Backing up a SQLite deployment means copying `api.db`, `api.db-wal` and `api.db-shm` together**, or checkpointing first. With WAL, recent writes — including, on a fresh deployment, the entire schema — live in the `-wal` file until a checkpoint folds them into the main file, and there is no graceful shutdown here yet to force one on exit. Copying `api.db` alone can silently produce an empty database. +**Backing up a SQLite deployment means copying `api.db`, `api.db-wal` and `api.db-shm` together**, or checkpointing first. With WAL, recent writes — including, on a fresh deployment, the entire schema — live in the `-wal` file until a checkpoint folds them into the main file. Copying `api.db` alone can silently produce an empty database in that window. + +A clean stop is what closes that window: on `SIGTERM` or `SIGINT` the server stops accepting connections, waits up to 30 seconds for the requests already in flight, stops the webhook worker and digest scheduler, and closes the database — which on SQLite is the checkpoint that folds the `-wal` file back into `api.db` and removes the sidecar files. So `systemctl stop`, `docker stop` and Ctrl-C all leave a `api.db` that is complete on its own. A `kill -9`, a crash or a power loss does not, which is why the paragraph above still stands. ## Second factors diff --git a/docs/development/CURRENT-STATE.md b/docs/development/CURRENT-STATE.md index c2a7529..0caf117 100644 --- a/docs/development/CURRENT-STATE.md +++ b/docs/development/CURRENT-STATE.md @@ -391,9 +391,10 @@ deployment does on its next restart, so it is called out in `README.md`, The digest's new table (`012`) has **never been applied to a real database**, the same as `009`–`011` — there is no Postgres in this -sandbox — and the digest schedule is a goroutine on -`context.Background()`, because this repo still has no graceful -shutdown. `PROGRESS.md` says both plainly. +sandbox. The digest schedule used to be a goroutine on +`context.Background()`; it now takes the context the shutdown signal +cancels, so the paragraph that follows in the Tier 6 section applies here +too. `PROGRESS.md` says both plainly. ### Stage 2 — the providers and the widget config @@ -568,9 +569,10 @@ foreign key rather than accepting any id, so that the tested branch is the one production runs. `-race` was not run this session. **Still not built** (unchanged from Tier 4, not part of this tier): -graceful shutdown, and per-user rate limiting on anything that calls a -model. The widget's own serving endpoint was in this list when Tier 5 -landed and is not any more — see the next section. +per-user rate limiting on anything that calls a model. Graceful shutdown +was on this list and is not any more — see the last section of this file. +The widget's own serving endpoint was in this list when Tier 5 landed and +is not any more — see the next section. ## The ask-ai widget's serving endpoint — carried forward from Tier 4 @@ -653,18 +655,18 @@ single most important thing about it. see the intent that actually reached the query surface. It is also the hook a host running a different LLM backend needs, which is why it is exported rather than a test-only accessor. -- **`Service.Close()` exists and nothing calls it.** There is still no - graceful shutdown for it to hang off, so it is there so that adding - one does not have to start by widening this type's API. +- **`Service.Close()` is called by the teardown in `main.go`.** It + releases the last cached provider pool, after the server has drained + and the background workers have stopped, so no question can be in + flight against a provider that is being closed. **What is still owed, said plainly.** No per-user rate limiting on this route: it spends money per question and is bounded only by the global per-IP edge limiter. That needs policy — per-user or per-deployment, and what number — which is a deployment's call rather than something to -invent here. `Service.Close()` is never called, for the shutdown reason -above. The Anthropic provider still has never called Anthropic, so the -live path from a question to a real model is exercised only through the -`Providers` seam with doubles; the wire shape is covered by +invent here. The Anthropic provider still has never called Anthropic, so +the live path from a question to a real model is exercised only through +the `Providers` seam with doubles; the wire shape is covered by `aiprovider`'s own tests against a local fake. ## Tier 6 — SQLite backend, core auth only @@ -753,11 +755,86 @@ this repo's server was started on a real SQLite file and passed the full `internal/smoketest` run — health, signup, duplicate rejection, login, wrong password, verify, session list, missing-header rejection, refresh rotation, reuse detection, family revocation, and both OAuth refusals. -`-race` was still not run. Graceful shutdown is still unbuilt, and on -SQLite it now has a second reason to exist: with no `Close()` there is -no checkpoint on exit, so a fresh deployment's entire schema can sit in +`-race` was still not run. Graceful shutdown was not built by this tier, +and on SQLite it had a second reason to exist: with no `Close()` there is +no checkpoint on exit, so a fresh deployment's entire schema could sit in the `-wal` file — durable, but a backup that copies `api.db` alone can -silently produce an empty database. `README.md` warns about that where -an operator will see it. Per-user rate limiting on `POST /v1/ask-ai` is +silently produce an empty database. `README.md` warns about that where an +operator will see it. That gap is now closed — see the last section of +this file — but the warning stays, because a `kill -9` still leaves the +WAL uncheckpointed and the advice to copy all three files is still the +right advice. Per-user rate limiting on `POST /v1/ask-ai` is unchanged. + +## Graceful shutdown — the finding Tier 3 opened and Tier 6 sharpened + +This is not a tier. It is the one item that appeared as owed in three +separate tier write-ups (Tiers 3, 5 and 6), so it is recorded once, here, +and the three write-ups now point at it instead of restating it. + +**What it was.** `main.go` ended at +`log.Fatal(http.ListenAndServe(...))`. That single line meant three +things, and only the first was obvious: + +1. **No signal handling.** A `SIGTERM` — which is what every process + manager sends, including `docker stop` and a Kubernetes rolling + deploy — killed the process where it stood. Every request in flight + died with it. +2. **`os.Exit` runs no defers.** `log.Fatalf` calls `os.Exit(1)`, so the + `defer db.Close()` two lines above it had never run once in this + repo's life. Every clean shutdown leaked the pool. +3. **On SQLite, no close means no checkpoint.** The `-wal` file is + durable — SQLite recovers from it — but the schema and every row a + deployment had written lived only there. After two boots of the + smoke run, `api.db` was still 4096 bytes while `api.db-wal` held + 461KB. A backup that copied `api.db` alone produced an empty + database that opened without error. + +Only the third is visible from outside, and it is the one that would +have cost somebody data. + +**What it is now.** `signal.NotifyContext` on `SIGINT`/`SIGTERM` produces +one `appCtx` that everything hangs off. `net.Listen` is separated from +`srv.Serve` so a listen failure is an error to report rather than a +`Fatal` that skips teardown. The main goroutine selects on either +`Serve` returning on its own or the signal; on the signal it calls +`drain`, which is `srv.Shutdown` bounded by `shutdownDrainTimeout` +(30s, a constant in `shutdown.go` with its own reasoning) and falls back +to `srv.Close` when the bound is hit. Only then does teardown run, in +the order the components need: `stopSignals()`, `workers.Wait()` for the +webhook worker and the digest scheduler, then `askAI.Close()`, +`redisClient.Close()`, and `db.Close()` last — that last one being the +WAL checkpoint. + +**The three properties `shutdown_test.go` pins**, because they are the +whole reason `drain` is a function instead of three lines in `main`: + +- A request already in flight still gets its 200 after the signal + arrives, and the drain does not return before it finishes. The test + waits for the handler to actually be running rather than sleeping, so + it is not racing the client. +- A request that will not finish does not hold the process open. The + bound is honored and the error names the wait, because the operator + reading it is looking at a deploy that took too long. +- A listener that fails on its own reports that error rather than + having it translated into a clean shutdown by the + `http.ErrServerClosed` check. + +**Verified end to end, not just by unit test.** The binary was built, +started on a fresh `/tmp/walcheck.db`, driven through the full +`internal/smoketest` run (13/13), sent a real `SIGTERM`, and then the +database was opened **read-only with no sidecar files present**: 7 +migrations recorded, 1 user, 2 sessions, all read back out of the +single `.db` file. Before the change the same sequence left 4096 bytes +and a 461KB `-wal`. + +**What this does not do.** It does not make `shiplog`'s writes +asynchronous — the comment there has been updated from "there is no +shutdown path to hang off" to "the buffer and the flush policy are the +missing pieces, not the lifecycle", which is a different and smaller +problem. It does not add a readiness endpoint separate from `/v1/health`, +so a load balancer's behavior during the drain is unchanged. And +`shutdownDrainTimeout` is a constant rather than an env var on purpose: +if the ask-ai widget's model calls ever stop being bounded by the +provider's own client timeout, that becomes a knob. diff --git a/docs/development/NEXT.md b/docs/development/NEXT.md index 094cd45..7c0f216 100644 --- a/docs/development/NEXT.md +++ b/docs/development/NEXT.md @@ -239,9 +239,10 @@ Two details were decided rather than assumed, and are recorded in > behaviour is tested against `httptest` and an in-memory double > **rather than against Postgres `FOR UPDATE SKIP LOCKED`**, the > in-memory double cannot reproduce two workers racing (one mutex), and -> this repo still has **no graceful shutdown** — owed before the -> shipped-events sink could move off the request goroutine. `PROGRESS.md` -> has all of it. +> this repo has **no graceful shutdown** — built since, see +> `CURRENT-STATE.md`'s last section; the async-sink half of this note is +> still owed and is now only about the buffer and the flush policy. +> `PROGRESS.md` has all of it. > > Two deliberate deviations from the spec below, both argued in > `PROGRESS.md`: `webhook_deliveries` uses a `BIGSERIAL` surrogate @@ -346,8 +347,9 @@ Two details were decided rather than assumed, and are recorded in > > What is still owed from Stage 1: > -> - the digest schedule is a goroutine on `context.Background()`, because -> this repo still has no graceful shutdown. +> - ~~the digest schedule is a goroutine on `context.Background()`~~ — +> built since: it takes the context the shutdown signal cancels, see +> `CURRENT-STATE.md`'s last section. > > Three things this tier changed that were not in the spec below, all > recorded because they are behaviour rather than plumbing: @@ -669,15 +671,13 @@ avoid duplicating. run from a minimal base), published to a registry on the same tag trigger. `docker run --env-file .env -p 8080:8080 ` should be the entire setup instructions. -- **Graceful shutdown, pulled forward from Tier 3/4's owed list**: - this is the tier where it stops being a nice-to-have. A distributed - binary or container is exactly what a real orchestrator (Kubernetes, - Fly, Railway, plain systemd) sends `SIGTERM` to on every deploy, and - right now `main.go` ends at `log.Fatal(ListenAndServe(...))` with the - webhook worker and digest scheduler both running on - `context.Background()` — nothing stops them cleanly. Wire a real - shutdown context, cancel it on `SIGTERM`/`SIGINT`, and give - in-flight requests and the background workers a bounded grace period - before exiting. Don't ship distribution before this; a container - that gets killed mid-migration or mid-webhook-delivery on every - rolling deploy is a worse experience than the one being fixed. +- ~~**Graceful shutdown, pulled forward from Tier 3/4's owed list**~~ — + built ahead of this tier, on its own branch, because the original + reasoning here was that shipping distribution first would ship a + container whose every `docker stop` kills in-flight requests. + `main.go` no longer ends at `log.Fatal(ListenAndServe(...))`, and both + background workers take the context the signal cancels; see + `CURRENT-STATE.md`'s last section. **What remains for this tier is the + packaging**: the `Dockerfile`'s `ENTRYPOINT` must run the binary + directly rather than through a shell, or `docker stop` signals + `/bin/sh` and the whole thing gains nothing. diff --git a/docs/development/PROGRESS.md b/docs/development/PROGRESS.md index 811f2f5..38fc175 100644 --- a/docs/development/PROGRESS.md +++ b/docs/development/PROGRESS.md @@ -1393,3 +1393,57 @@ false. 501 is a statement about the deployment, and it is true. entries — was left as found, still a Tier 1 documentation pass. - `.env.example` documents the two backends at the top. - New `migrations/sqlite/README.md`. + +## 2026-09-17 — graceful shutdown (not a tier) + +On `feat/tier6-sqlite-backend`'s working tree, branched off as its own +change. This is the item Tiers 3, 5 and 6 each recorded as owed; it was +done now rather than inside Tier 7 because Tier 7's own spec says not to +ship distribution before it — a container whose every `docker stop` +kills in-flight requests is the bug the packaging would have shipped. + +**What was wrong, in three parts.** `main.go` ended at +`log.Fatal(http.ListenAndServe(...))`. (1) No signal handling, so +`SIGTERM` killed the process mid-request. (2) `log.Fatalf` calls +`os.Exit`, which runs no defers, so the `defer db.Close()` above it had +never once run. (3) On SQLite, no close means no WAL checkpoint — this +was the finding that started it: after two boots of the smoke run, +`api.db` was still 4096 bytes while `api.db-wal` held 461KB, so a backup +copying `api.db` alone produced a database that opened without error and +was empty. + +**What was built.** `signal.NotifyContext` on `SIGINT`/`SIGTERM` gives +one `appCtx` that the HTTP server and both background workers hang off. +`net.Listen` is separated from `srv.Serve` so a listen failure is +reported rather than being a `Fatal` that skips teardown. The main +goroutine selects on either `Serve` returning on its own or the signal; +on the signal it calls `drain` (`shutdown.go`), which is `srv.Shutdown` +bounded by a 30s constant and falls back to `srv.Close` when the bound +is hit. Teardown then runs in the order the components need: +`stopSignals()`, `workers.Wait()`, `askAI.Close()`, `redisClient.Close()`, +`db.Close()` last. Both `sync.WaitGroup.Go` (Go 1.25) and the hoisting of +`redisClient`/`askAI` exist so the teardown has something to close. + +**Verified end to end, not just by unit test.** Built the binary, +started it on a fresh `/tmp/walcheck.db`, ran the full `internal/smoketest` +(13/13), sent a real `SIGTERM` to the actual server PID, then opened the +database **read-only with no `-wal`/`-shm` present**: 7 migrations +recorded, 1 user, 2 sessions. The sidecar files were gone entirely, which +is the checkpoint. `shutdown_test.go` also pins the three properties +`drain` exists for: an in-flight request still gets its 200 and the +drain waits for it; a request that will not finish is abandoned at the +bound with an error naming the wait; a listener that fails on its own +reports that error instead of having it translated to a clean shutdown. + +**Also corrected**: four doc comments that asserted this repo has no +shutdown path and are now false (`askai.Service.Close`, +`webhook.Worker.Run`, `digest.Scheduler.Run`, and `shiplog`'s +synchronous-write argument). The `shiplog` one changed its *reasoning*, +not just its wording — the missing piece for an async sink is now the +buffer and the flush policy, not a lifecycle to hang it off — so that is +recorded rather than deleted. + +**Not done.** `-race` still has not been run. `shutdownDrainTimeout` is +a constant, not a knob, on purpose. No readiness endpoint separate from +`/v1/health`, so load-balancer behaviour during the drain is unchanged. +`go build ./... && go vet ./... && go test ./...` are all clean.