Skip to content

Commit 731e71d

Browse files
midagedevclaude
andauthored
fix(server): a background sync with no owner outlives the server that started it (GDK-270) (#26)
`handlePutSettings` ends by kicking a full sync when the mirrored scope changes, and `startSyncJob` started it as `go s.runSyncJob(context.Background(), …)`: no cancel, no WaitGroup, no handle. The comment above that line correctly explained why the job cannot hang off the request context, and then handed its lifetime to nobody. The symptom CI reported was a test failing on a PR that changed one markdown file: `TempDir RemoveAll cleanup: directory not empty`. The mirror is WAL, so a connection that opens or closes there recreates -wal/-shm — and the detached goroutine was still writing into a directory the test had already torn down. It never reproduced on macOS by repetition, which is why it survived. It is deterministic when you ask the right question. A goroutine that still holds the pool is `database/sql` reporting `InUse > 0` after `Close`, and that needs no race detector, no Linux and no repetition: the four scope-changing settings PUTs fail in under a second. The four that fail are exactly the four where `scopeChanged` is true; the siblings that do not change scope pass. Structural: the server owns the lifetime. `newServer` builds a cancelable `jobsCtx`, `startSyncJob` registers on a WaitGroup and refuses once the context is cancelled, and `Handler.Shutdown`/`Close` cancel and wait within the same 3s bound `cmd/gadak/serve.go` already uses for `http.Server`. Waiting for the goroutine is not sufficient — `database/sql` rolls a cancelled Tx back from `Tx.awaitDone`, which can still hold the connection — so the wait ends on the pool going idle, which is the writer this bug is actually about. Wired into every production path that closes a mirror, because a shutdown method nobody calls is decoration: `cmd/gadak/serve.go`, `desktop/main.go`, and `workspace.Registry.Close`, each ordered so the sync stops before the database it writes to closes. `Entry.Handler` narrows from `http.Handler` to `*server.Handler`: the entry owns that lifetime, and the old type hid it. Recurrence: `quiesceFixtureDir` now asserts no connection is checked out once a test is done, so this class fails in one second on any machine instead of rarely on Linux; the existing "files came back" check stays, since it catches an external writer a pool check cannot see. CI repeats `internal/server` and `internal/workspace` under `-race`, not path-scoped. FAIL-first, both halves lead-run. The fixture assertion on the unfixed tree: four PUTs, `1 connection(s) still checked out after Close`, 0.66s. The production wiring, with `Registry.Close` unwired: `1 connection(s) still checked out after Registry.Close — the workspace's sync outlived its mirror`. Debuggability: `store.PoolStats()` is what makes the assertion expressible, and `Handler.SnapshotSync()` answers "what background work is running right now" in-process, mirroring the existing GET /sync/progress/ rather than adding a route. Known and unchanged: the suite still attempts an outbound request to the fixture's `x.atlassian.net`; the job is cancelled at teardown so it no longer outlives the test, but removing the attempt is a separate change. Co-authored-by: midagedev <midagedev@users.noreply.github.com> Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
1 parent 498ca4c commit 731e71d

9 files changed

Lines changed: 273 additions & 6 deletions

File tree

.github/workflows/ci.yml

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,18 @@ jobs:
5656
- name: Go tests
5757
run: go test ./...
5858

59+
# GDK-270: a startSyncJob goroutine that outlives the test only shows
60+
# up when this package is repeated under the race detector. Not
61+
# path-scoped — the writer can be introduced from any import of
62+
# internal/server. internal/workspace is here too: it owns the same
63+
# lifetime one layer up (Registry.Close stops each workspace's sync
64+
# before its mirror). count=2 (not 4): the job already ran count=1
65+
# above; locally count=4 -race is ~180s, and doubling the package
66+
# under race is enough to catch "passes once" while staying modest
67+
# in a 20-minute job.
68+
- name: Server tests under race (GDK-270)
69+
run: go test ./internal/server/ ./internal/workspace/ -count=2 -race
70+
5971
- name: Frontend typecheck
6072
run: npm run typecheck
6173

cmd/gadak/serve.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -265,6 +265,10 @@ func cmdServe(args []string) error {
265265
}
266266

267267
api := newServeAPI(db, cfg)
268+
// Registered after db.Close and before reg.Close, so the LIFO order is
269+
// workspaces, then this handler, then the mirror: a background sync must
270+
// stop before the database it writes to closes (GDK-270).
271+
defer api.Close()
268272
spa := serveSPAHandler(opts.static)
269273

270274
// Workspace mounts share this process's listener; each profile opens lazily.

desktop/main.go

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,8 @@ func run() error {
8686
} else {
8787
api = server.NewWithCache(db, cfg, cache)
8888
}
89+
// After db.Close above, so LIFO stops the background sync first (GDK-270).
90+
defer api.Close()
8991

9092
ui, ok := gadak.WebUI()
9193
if !ok {

internal/server/onboarding.go

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -268,15 +268,28 @@ func (s *server) startSyncJob(cfg *config.Config, full bool) bool {
268268
return s.syncKick(cfg, full)
269269
}
270270
s.syncMu.Lock()
271+
if s.jobsCtx != nil && s.jobsCtx.Err() != nil {
272+
s.syncMu.Unlock()
273+
return false
274+
}
271275
if s.syncJob.Running {
272276
s.syncMu.Unlock()
273277
return false
274278
}
275279
s.syncJob = progressDoc{Running: true, Phase: "syncing", StartedAt: store.Now()}
280+
s.jobsWG.Add(1)
276281
s.syncMu.Unlock()
277282

278283
// The request is answered immediately, so the run cannot hang off r.Context().
279-
go s.runSyncJob(context.Background(), cfg, full)
284+
// Lifetime is the server's jobsCtx: Shutdown cancels it and waits (GDK-270).
285+
ctx := s.jobsCtx
286+
if ctx == nil {
287+
ctx = context.Background()
288+
}
289+
go func() {
290+
defer s.jobsWG.Done()
291+
s.runSyncJob(ctx, cfg, full)
292+
}()
280293
return true
281294
}
282295

internal/server/server.go

Lines changed: 98 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -89,6 +89,15 @@ type server struct {
8989
syncMu sync.Mutex
9090
syncJob progressDoc
9191
activity mirrorActivity
92+
93+
// jobsCtx is cancelled by Shutdown so a startSyncJob goroutine cannot
94+
// outlive the server. jobsWG counts those goroutines; Close waits on it.
95+
// Nothing else owned this lifetime, so a settings PUT in a test (or a
96+
// serve process exiting) left the writer holding a WAL connection
97+
// (GDK-270).
98+
jobsCtx context.Context
99+
jobsCancel context.CancelFunc
100+
jobsWG sync.WaitGroup
92101
}
93102

94103
// Handler is the HTTP API plus optional update-check control. It implements
@@ -133,6 +142,7 @@ func newServer(db *store.DB, cfg *config.Config, cache *attachcache.Cache, profi
133142
}
134143
s := &server{db: db, cache: cache, profile: profile}
135144
s.cfg.Store(cfg)
145+
s.jobsCtx, s.jobsCancel = context.WithCancel(context.Background())
136146

137147
// Every pattern is anchored with {$}: a trailing slash alone would make each
138148
// literal endpoint a subtree that overlaps `{key}/detail/`, which ServeMux
@@ -252,9 +262,86 @@ func newServer(db *store.DB, cfg *config.Config, cache *attachcache.Cache, profi
252262
mux.HandleFunc("/", handleNotFound)
253263
h := &Handler{mux: mux, s: s}
254264
h.guarded = GuardBrowser(mux)
265+
if testRegisterHandler != nil {
266+
testRegisterHandler(h)
267+
}
255268
return h
256269
}
257270

271+
// testRegisterHandler is set from tests so fixture cleanup can Shutdown every
272+
// Handler that opened a given DB before closing it. Production is nil.
273+
var testRegisterHandler func(*Handler)
274+
275+
// closeWait is how long Close waits for in-flight startSyncJob goroutines.
276+
// Same bound as the HTTP server's shutdown window in cmd/gadak/serve.go
277+
// (the 3-second context.WithTimeout around srv.Shutdown). Past this, Close
278+
// returns and the caller may close the database anyway; a still-running job
279+
// then fails the pool assertion (tests) or races WAL files (production).
280+
const closeWait = 3 * time.Second
281+
282+
// Shutdown cancels background startSyncJob work and waits for those
283+
// goroutines to return, or until ctx is done. A timed-out wait returns
284+
// ctx.Err(); the job may still be running and still hold a database
285+
// connection. Idempotent.
286+
//
287+
// Returning from the job goroutine is not enough: database/sql rolls a
288+
// cancelled Tx back from a helper goroutine (Tx.awaitDone), and that
289+
// helper can still hold the pool connection after runSyncJob has
290+
// returned. Waiting for InUse==0 is waiting for that writer, which is
291+
// the WAL leak GDK-270 actually is.
292+
func (h *Handler) Shutdown(ctx context.Context) error {
293+
if h == nil || h.s == nil {
294+
return nil
295+
}
296+
if h.s.jobsCancel != nil {
297+
h.s.jobsCancel()
298+
}
299+
done := make(chan struct{})
300+
go func() {
301+
h.s.jobsWG.Wait()
302+
close(done)
303+
}()
304+
if ctx == nil {
305+
ctx = context.Background()
306+
}
307+
select {
308+
case <-done:
309+
case <-ctx.Done():
310+
return fmt.Errorf("background sync still running after shutdown bound: %w", ctx.Err())
311+
}
312+
return waitPoolIdle(ctx, h.s.db)
313+
}
314+
315+
// waitPoolIdle waits until no connection is checked out, or ctx is done.
316+
func waitPoolIdle(ctx context.Context, db *store.DB) error {
317+
if db == nil {
318+
return nil
319+
}
320+
if db.PoolStats().InUse == 0 {
321+
return nil
322+
}
323+
t := time.NewTicker(5 * time.Millisecond)
324+
defer t.Stop()
325+
for {
326+
select {
327+
case <-ctx.Done():
328+
return fmt.Errorf("background sync returned but %d connection(s) still checked out: %w", db.PoolStats().InUse, ctx.Err())
329+
case <-t.C:
330+
if db.PoolStats().InUse == 0 {
331+
return nil
332+
}
333+
}
334+
}
335+
}
336+
337+
// Close is Shutdown with a 3s bound — the same window cmd/gadak/serve.go
338+
// uses for http.Server.Shutdown.
339+
func (h *Handler) Close() error {
340+
ctx, cancel := context.WithTimeout(context.Background(), closeWait)
341+
defer cancel()
342+
return h.Shutdown(ctx)
343+
}
344+
258345
// StartUpdateCheck runs a GitHub release lookup immediately and every 24h.
259346
// Results feed latest_version / release_url on bootstrap and delta when the
260347
// running build is older. Records cacheDir even when disabled so a later
@@ -307,6 +394,17 @@ func (h *Handler) SnapshotUpdate() UpdateStatus {
307394
return h.s.snapshotUpdate()
308395
}
309396

397+
// SnapshotSync is the debug document for "what background work is running
398+
// right now": the same one-shot job + activity picture that
399+
// GET /api/v1/issues/sync/progress/ already returns. No new endpoint — that
400+
// GET already carries it; this is the in-process form, matching SnapshotUpdate.
401+
func (h *Handler) SnapshotSync() progressResponse {
402+
if h == nil || h.s == nil {
403+
return progressResponse{}
404+
}
405+
return h.s.syncProgressResponse()
406+
}
407+
310408
// setUpdateInfo stores a release snapshot (tests and the background loop).
311409
func (s *server) setUpdateInfo(info selfupdate.Info, ok bool) {
312410
s.updateMu.Lock()

internal/server/server_test.go

Lines changed: 78 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ import (
1111
"os"
1212
"path/filepath"
1313
"strings"
14+
"sync"
1415
"sync/atomic"
1516
"testing"
1617
"time"
@@ -22,6 +23,42 @@ import (
2223
"github.com/midagedev/gadak/internal/store"
2324
)
2425

26+
// liveHandlers lets fixtureAt stop every Handler created against a DB before
27+
// that DB is closed. Production never sets testRegisterHandler.
28+
var (
29+
liveMu sync.Mutex
30+
liveHandlers = map[*store.DB][]*Handler{}
31+
)
32+
33+
func init() {
34+
testRegisterHandler = registerLive
35+
}
36+
37+
func registerLive(h *Handler) {
38+
if h == nil || h.s == nil || h.s.db == nil {
39+
return
40+
}
41+
liveMu.Lock()
42+
liveHandlers[h.s.db] = append(liveHandlers[h.s.db], h)
43+
liveMu.Unlock()
44+
}
45+
46+
func shutdownLive(t *testing.T, db *store.DB) {
47+
t.Helper()
48+
if db == nil {
49+
return
50+
}
51+
liveMu.Lock()
52+
hs := liveHandlers[db]
53+
delete(liveHandlers, db)
54+
liveMu.Unlock()
55+
for _, h := range hs {
56+
if err := h.Close(); err != nil {
57+
t.Errorf("Handler.Close: %v — a startSyncJob goroutine did not return within the shutdown bound (GDK-270)", err)
58+
}
59+
}
60+
}
61+
2562
// testRequest is httptest.NewRequest with Host set for the loopback API guard.
2663
// httptest defaults Host to "example.com", which browserGuard correctly
2764
// rejects as a DNS-rebinding name; real clients send localhost or an IP.
@@ -49,8 +86,17 @@ func testRequest(method, target string, body io.Reader) *http.Request {
4986
// nothing to race on, and it turns "some file was in the way" into "this named
5087
// file appeared after teardown began", reported by the fixture that owns the
5188
// path instead of anonymously by the framework.
52-
func quiesceFixtureDir(t *testing.T, dir string) {
89+
func quiesceFixtureDir(t *testing.T, dir string, db *store.DB) {
5390
t.Helper()
91+
if db != nil {
92+
stats := db.PoolStats()
93+
if stats.InUse > 0 {
94+
// A connection still checked out means something the test started
95+
// is still running. Close cannot reclaim it, and under WAL that
96+
// writer recreates journal files in this TempDir (GDK-270).
97+
t.Errorf("%d connection(s) still checked out after Close — something the test started is still running (GDK-270); stats=%+v", stats.InUse, stats)
98+
}
99+
}
54100
entries, err := os.ReadDir(dir)
55101
if err != nil {
56102
// Already gone, or unreadable: not this helper's business.
@@ -89,8 +135,11 @@ func fixtureAt(t *testing.T) (*store.DB, *config.Config, string) {
89135
t.Fatalf("open: %v", err)
90136
}
91137
t.Cleanup(func() {
138+
// Stop writers first: a startSyncJob goroutine that outlives Close
139+
// holds a pool connection and recreates WAL files in dir (GDK-270).
140+
shutdownLive(t, db)
92141
db.Close()
93-
quiesceFixtureDir(t, dir)
142+
quiesceFixtureDir(t, dir, db)
94143
})
95144
if err := db.UpsertSource(context.Background(), store.Source{ID: "jira", Kind: "jira", BaseURL: "https://x.atlassian.net"}); err != nil {
96145
t.Fatalf("source: %v", err)
@@ -1241,3 +1290,30 @@ func TestBootstrapSurvivesABrokenGroupQuery(t *testing.T) {
12411290
t.Fatal("issues went missing with the broken query")
12421291
}
12431292
}
1293+
1294+
func TestHandlerShutdownCancelsSyncJob(t *testing.T) {
1295+
db, cfg := fixture(t)
1296+
h := New(db, cfg)
1297+
if !h.s.startSyncJob(cfg, true) {
1298+
t.Fatal("startSyncJob refused")
1299+
}
1300+
if err := h.Close(); err != nil {
1301+
t.Fatalf("Close: %v", err)
1302+
}
1303+
if n := db.PoolStats().InUse; n != 0 {
1304+
t.Fatalf("%d connection(s) still checked out after Handler.Close — background sync did not return (GDK-270)", n)
1305+
}
1306+
if err := h.Close(); err != nil {
1307+
t.Fatalf("second Close: %v", err)
1308+
}
1309+
}
1310+
1311+
func TestSnapshotSyncMatchesProgressEndpoint(t *testing.T) {
1312+
db, cfg := fixture(t)
1313+
h := New(db, cfg)
1314+
httpDoc := decode[progressResponse](t, get(t, h, apiBase+"sync/progress/", nil))
1315+
snap := h.SnapshotSync()
1316+
if snap != httpDoc {
1317+
t.Fatalf("SnapshotSync %+v != GET sync/progress/ %+v", snap, httpDoc)
1318+
}
1319+
}

internal/store/stats.go

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
package store
2+
3+
import "database/sql"
4+
5+
// PoolStats reports the connection pool's state. A caller that has finished
6+
// with a mirror can assert nothing is still checked out: a connection that
7+
// outlives Close belongs to something still running, and under WAL it writes
8+
// journal files back into a directory the caller may already have removed
9+
// (GDK-270).
10+
func (db *DB) PoolStats() sql.DBStats { return db.sql.Stats() }

internal/workspace/workspace.go

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,10 @@ var workspaceNameRe = regexp.MustCompile(`^[A-Za-z0-9_-]{1,64}$`)
3131

3232
// Entry is one opened workspace mirror (handler + DB + config).
3333
type Entry struct {
34-
Handler http.Handler
34+
// Handler is the concrete server handler, not http.Handler: this entry
35+
// owns its lifetime, and Close has to be able to stop the background sync
36+
// before the mirror it writes to is closed (GDK-270).
37+
Handler *server.Handler
3538
DB *store.DB
3639
Cfg *config.Config
3740
}
@@ -65,8 +68,16 @@ func (r *Registry) Close() {
6568
r.mu.Lock()
6669
defer r.mu.Unlock()
6770
for name, e := range r.entries {
68-
if e != nil && e.DB != nil {
69-
_ = e.DB.Close()
71+
if e != nil {
72+
// Stop this workspace's background sync before closing the mirror
73+
// it writes to; a job that outlives the DB holds a WAL connection
74+
// (GDK-270).
75+
if e.Handler != nil {
76+
_ = e.Handler.Close()
77+
}
78+
if e.DB != nil {
79+
_ = e.DB.Close()
80+
}
7081
}
7182
delete(r.entries, name)
7283
}

internal/workspace/workspace_test.go

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -442,3 +442,44 @@ func TestWorkspaceConnectStartsWatch(t *testing.T) {
442442
t.Fatalf("workspace connect did not start Watch: watching %v", reg.Watching())
443443
}
444444
}
445+
446+
// TestCloseStopsWorkspaceSyncBeforeTheMirror is the production half of
447+
// GDK-270. The server learned to own its background sync, but a Registry that
448+
// closed only e.DB would still leave a workspace's job writing into a mirror
449+
// that had just been closed — the same leak, one layer up. Driving a real
450+
// scope-changing settings PUT is what starts that job; the profile's Site is a
451+
// dead loopback port, so the sync fails fast without leaving this machine.
452+
func TestCloseStopsWorkspaceSyncBeforeTheMirror(t *testing.T) {
453+
setupHome(t)
454+
seedProfile(t, "", &config.Config{
455+
Site: "http://127.0.0.1:1", Email: "a@example.invalid", Token: "test-token", Projects: []string{"AAA"},
456+
})
457+
seedProfile(t, "work", &config.Config{
458+
Site: "http://127.0.0.1:1", Email: "b@example.invalid", Token: "test-token", Projects: []string{"BBB"},
459+
})
460+
461+
reg := New()
462+
e, err := reg.Get("work")
463+
if err != nil {
464+
t.Fatalf("Get: %v", err)
465+
}
466+
db := e.DB
467+
468+
spa := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })
469+
h := reg.Handler(spa, "test-ver")
470+
rec := httptest.NewRecorder()
471+
body := strings.NewReader(`{"projects":["BBB","CCC"],"staleThresholdHours":72}`)
472+
req := httptest.NewRequest(http.MethodPut, "/w/work/api/v1/issues/settings/", body)
473+
req.Host = "127.0.0.1:7777"
474+
req.Header.Set("Content-Type", "application/json")
475+
h.ServeHTTP(rec, req)
476+
if rec.Code != http.StatusOK {
477+
t.Fatalf("PUT settings → %d %s", rec.Code, rec.Body.String())
478+
}
479+
480+
reg.Close()
481+
482+
if n := db.PoolStats().InUse; n != 0 {
483+
t.Fatalf("%d connection(s) still checked out after Registry.Close — the workspace's sync outlived its mirror (GDK-270)", n)
484+
}
485+
}

0 commit comments

Comments
 (0)