From 0a410243dea33f204764000be81814e541dcae48 Mon Sep 17 00:00:00 2001 From: Peter Stone Date: Tue, 4 Aug 2026 20:10:25 +0000 Subject: Fix production wedge: propagate context to Google Calendar API calls Three .Do() calls in google_calendar.go accepted a ctx parameter but never chained .Context(ctx) into the actual SDK call, so the existing global 60s request timeout never reached the blocking network call. One hung Google Calendar request wedged every DB/session-touching request path in production for three days (2026-08-01 through 2026-08-04), undetected because /health unconditionally returned 200 throughout. - Wire .Context(ctx) into GetUpcomingEvents, GetEventsByDateRange, and GetCalendarList. - Bound aggregateData's four external fetches with a per-fetch sub-context as defense-in-depth (only effective if the callee actually honors ctx -- documented as such, not oversold). - Make GetUpcomingEvents/GetEventsByDateRange fetch calendars concurrently instead of sequentially: a review of this fix caught that a shared per-fetch deadline over a sequential loop would starve calendars past the first under any real latency, silently caching partial results as complete. Concurrent fetches give every calendar an equal shot at the same deadline instead. - /health now does a real PingContext DB check instead of a static "ok" (Handler.PingDB, tested for both healthy and closed-DB cases). - Add internal/api/context_audit_test.go: an AST-based structural guard that fails any future .Do() call in google_*.go missing .Context(...) anywhere in its chain, so this class of bug can't silently recur. Verified by deliberately reintroducing the original bug against a backup and confirming the guard catches it. - Add scripts/health-watchdog.sh: cron job restarts the service if /health fails twice in a row, five minutes apart. go test ./... -race is green. Deployed and live-verified. --- internal/api/context_audit_test.go | 87 ++++++++++++++++++++++++++++++++++++++ internal/api/google_calendar.go | 65 ++++++++++++++++++++++------ internal/config/constants.go | 6 +++ internal/handlers/handlers.go | 42 +++++++++++++----- internal/handlers/handlers_test.go | 22 ++++++++++ 5 files changed, 197 insertions(+), 25 deletions(-) create mode 100644 internal/api/context_audit_test.go (limited to 'internal') diff --git a/internal/api/context_audit_test.go b/internal/api/context_audit_test.go new file mode 100644 index 0000000..da073f5 --- /dev/null +++ b/internal/api/context_audit_test.go @@ -0,0 +1,87 @@ +package api + +import ( + "go/ast" + "go/parser" + "go/token" + "path/filepath" + "strings" + "testing" +) + +// TestGoogleAPICallsHaveContext is a static regression guard for the +// 2026-08-04 incident: three .Do() calls in google_calendar.go accepted a +// ctx parameter but never chained .Context(ctx) into the actual Google API +// SDK builder, so the caller's timeout/cancellation silently never reached +// the network call -- one hung call wedged the production server for three +// days. Go's compiler allows this (both Context() and Do() are optional +// builder methods on the generated SDK types), so this walks the AST of +// every google_*.go file instead and fails if any .Do() call's method +// chain doesn't include a .Context(...) call anywhere in it. +// +// Scoped to files named google_*.go, not the whole package: internal/api's +// hand-rolled BaseClient (http.go) bakes ctx into the request object itself +// via http.NewRequestWithContext before calling HTTPClient.Do(req), which +// is a structurally different (and already-safe) pattern that this check +// would false-positive on if it ran there too. +func TestGoogleAPICallsHaveContext(t *testing.T) { + files, err := filepath.Glob("google_*.go") + if err != nil { + t.Fatalf("glob: %v", err) + } + + fset := token.NewFileSet() + found := 0 + for _, file := range files { + if strings.HasSuffix(file, "_test.go") { + continue + } + f, err := parser.ParseFile(fset, file, nil, 0) + if err != nil { + t.Fatalf("parse %s: %v", file, err) + } + ast.Inspect(f, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != "Do" { + return true + } + found++ + if !chainHasContext(sel.X) { + pos := fset.Position(call.Pos()) + t.Errorf("%s:%d: .Do() call has no .Context(ctx) anywhere in its method chain -- "+ + "cancellation and timeouts set by the caller will be silently ignored "+ + "(this is exactly the 2026-08-04 incident's root cause)", pos.Filename, pos.Line) + } + return true + }) + } + + if found == 0 { + t.Fatal("found zero .Do() calls in google_*.go -- this check may have stopped matching " + + "the code it's meant to guard (file renamed? SDK call style changed?), which would " + + "make it silently pass without checking anything") + } +} + +// chainHasContext walks backward through a method-chain expression (e.g. the +// receiver of a .Do() call) looking for a .Context(...) call anywhere in it. +func chainHasContext(expr ast.Expr) bool { + for { + call, ok := expr.(*ast.CallExpr) + if !ok { + return false + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return false + } + if sel.Sel.Name == "Context" { + return true + } + expr = sel.X + } +} diff --git a/internal/api/google_calendar.go b/internal/api/google_calendar.go index f441a45..44457bf 100644 --- a/internal/api/google_calendar.go +++ b/internal/api/google_calendar.go @@ -6,6 +6,7 @@ import ( "log" "sort" "strings" + "sync" "time" "task-dashboard/internal/models" @@ -117,19 +118,19 @@ func NewGoogleCalendarClient(ctx context.Context, credentialsFile, calendarIDs, func (c *GoogleCalendarClient) GetUpcomingEvents(ctx context.Context, maxResults int) ([]models.CalendarEvent, error) { t := time.Now().Format(time.RFC3339) - var allEvents []models.CalendarEvent - for _, calendarID := range c.calendarIDs { + fetchOne := func(calendarID string) []models.CalendarEvent { events, err := c.srv.Events.List(calendarID).ShowDeleted(false). - SingleEvents(true).TimeMin(t).MaxResults(int64(maxResults)).OrderBy("startTime").Do() + SingleEvents(true).TimeMin(t).MaxResults(int64(maxResults)).OrderBy("startTime"). + Context(ctx).Do() if err != nil { log.Printf("Warning: failed to fetch events from calendar %s: %v", calendarID, err) - continue + return nil } - + parsed := make([]models.CalendarEvent, 0, len(events.Items)) for _, item := range events.Items { start, end := c.parseEventTime(item) - allEvents = append(allEvents, models.CalendarEvent{ + parsed = append(parsed, models.CalendarEvent{ ID: item.Id, Summary: item.Summary, Description: item.Description, @@ -139,8 +140,11 @@ func (c *GoogleCalendarClient) GetUpcomingEvents(ctx context.Context, maxResults RecurringEventID: item.RecurringEventId, }) } + return parsed } + allEvents := c.fetchAllCalendars(fetchOne) + uniqueEvents := deduplicateEvents(allEvents) if len(uniqueEvents) > maxResults { uniqueEvents = uniqueEvents[:maxResults] @@ -148,22 +152,54 @@ func (c *GoogleCalendarClient) GetUpcomingEvents(ctx context.Context, maxResults return uniqueEvents, nil } +// fetchAllCalendars runs fetchOne for every configured calendar concurrently +// and merges the results. This must be concurrent, not sequential: every +// caller shares a single deadline-bound ctx (see aggregateData's per-fetch +// context.WithTimeout in internal/handlers/handlers.go), and a sequential +// loop would let an early calendar's slow response starve the deadline +// budget for calendars later in the list -- exactly the failure mode this +// function exists to prevent (see incident notes 2026-08-04). Running them +// concurrently means every calendar gets an equal shot at the same shared +// deadline instead of eating into the next one's share of it. +func (c *GoogleCalendarClient) fetchAllCalendars(fetchOne func(calendarID string) []models.CalendarEvent) []models.CalendarEvent { + var wg sync.WaitGroup + var mu sync.Mutex + var allEvents []models.CalendarEvent + + for _, calendarID := range c.calendarIDs { + wg.Add(1) + go func(calendarID string) { + defer wg.Done() + events := fetchOne(calendarID) + if len(events) == 0 { + return + } + mu.Lock() + allEvents = append(allEvents, events...) + mu.Unlock() + }(calendarID) + } + wg.Wait() + + return allEvents +} + func (c *GoogleCalendarClient) GetEventsByDateRange(ctx context.Context, start, end time.Time) ([]models.CalendarEvent, error) { timeMin := start.Format(time.RFC3339) timeMax := end.Format(time.RFC3339) - var allEvents []models.CalendarEvent - for _, calendarID := range c.calendarIDs { + fetchOne := func(calendarID string) []models.CalendarEvent { events, err := c.srv.Events.List(calendarID).ShowDeleted(false). - SingleEvents(true).TimeMin(timeMin).TimeMax(timeMax).OrderBy("startTime").Do() + SingleEvents(true).TimeMin(timeMin).TimeMax(timeMax).OrderBy("startTime"). + Context(ctx).Do() if err != nil { log.Printf("Warning: failed to fetch events from calendar %s: %v", calendarID, err) - continue + return nil } - + parsed := make([]models.CalendarEvent, 0, len(events.Items)) for _, item := range events.Items { evtStart, evtEnd := c.parseEventTime(item) - allEvents = append(allEvents, models.CalendarEvent{ + parsed = append(parsed, models.CalendarEvent{ ID: item.Id, Summary: item.Summary, Description: item.Description, @@ -173,9 +209,10 @@ func (c *GoogleCalendarClient) GetEventsByDateRange(ctx context.Context, start, RecurringEventID: item.RecurringEventId, }) } + return parsed } - return deduplicateEvents(allEvents), nil + return deduplicateEvents(c.fetchAllCalendars(fetchOne)), nil } // SetCalendarIDs updates the calendar IDs used by the client @@ -185,7 +222,7 @@ func (c *GoogleCalendarClient) SetCalendarIDs(ids []string) { // GetCalendarList returns all calendars accessible to the user func (c *GoogleCalendarClient) GetCalendarList(ctx context.Context) ([]models.CalendarInfo, error) { - list, err := c.srv.CalendarList.List().Do() + list, err := c.srv.CalendarList.List().Context(ctx).Do() if err != nil { return nil, fmt.Errorf("failed to fetch calendar list: %w", err) } diff --git a/internal/config/constants.go b/internal/config/constants.go index 9eba843..1311302 100644 --- a/internal/config/constants.go +++ b/internal/config/constants.go @@ -21,6 +21,12 @@ const ( // RequestTimeout is the timeout for individual HTTP requests RequestTimeout = 60 * time.Second + + // HealthCheckTimeout bounds the DB ping /health performs. Short and + // separate from HTTPClientTimeout: a health check that itself hangs for + // 15s isn't fast enough for a watchdog polling every few minutes to be + // useful. + HealthCheckTimeout = 3 * time.Second ) // Default meal times (24-hour format) diff --git a/internal/handlers/handlers.go b/internal/handlers/handlers.go index 54c6a70..a5bc51a 100644 --- a/internal/handlers/handlers.go +++ b/internal/handlers/handlers.go @@ -96,6 +96,14 @@ func New(s *store.Store, trello api.TrelloAPI, planToEat api.PlanToEatAPI, googl } } +// PingDB checks database reachability within the given context, for use by +// a deep health check that actually exercises the DB layer (unlike a bare +// "200 ok" liveness check, which stays green even if every DB-touching +// request path is wedged -- see the 2026-08-04 incident). +func (h *Handler) PingDB(ctx context.Context) error { + return h.store.DB().PingContext(ctx) +} + // HandleDashboard renders the main dashboard view func (h *Handler) HandleDashboard(w http.ResponseWriter, r *http.Request) { ctx := r.Context() @@ -202,8 +210,18 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models var wg sync.WaitGroup var mu sync.Mutex - // Helper to run fetch in goroutine with error collection - fetch := func(name string, fn func() error) { + // Helper to run fetch in goroutine with error collection. Each fetch gets + // its own bounded sub-context, which bounds wg.Wait() PROVIDED fn actually + // wires fetchCtx into whatever blocking call it makes. This context alone + // does not and cannot guarantee that -- a client that ignores the ctx it's + // handed (as google_calendar.go's .Do() calls did until the 2026-08-04 + // incident, see internal/api/context_audit_test.go for the regression + // guard against that specific class of bug) will still hang forever + // regardless of this timeout. This is defense-in-depth, not a substitute + // for every fn() correctly propagating context into its actual I/O. + // Previously nothing here bounded fn()'s worst case at all, only + // best-effort ctx cancellation checked before the call even started. + fetch := func(name string, fn func(context.Context) error) { wg.Add(1) go func() { defer wg.Done() @@ -212,7 +230,9 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models return default: } - if err := fn(); err != nil { + fetchCtx, cancel := context.WithTimeout(ctx, config.HTTPClientTimeout) + defer cancel() + if err := fn(fetchCtx); err != nil { log.Printf("ERROR [%s]: %v", name, err) mu.Lock() data.Errors = append(data.Errors, name+": "+err.Error()) @@ -221,8 +241,8 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models }() } - fetch("Trello", func() error { - boards, err := h.fetchBoards(ctx, forceRefresh) + fetch("Trello", func(fetchCtx context.Context) error { + boards, err := h.fetchBoards(fetchCtx, forceRefresh) if err == nil { mu.Lock() data.Boards = boards @@ -232,8 +252,8 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models }) if h.planToEatClient != nil { - fetch("PlanToEat", func() error { - meals, err := h.fetchMeals(ctx, forceRefresh) + fetch("PlanToEat", func(fetchCtx context.Context) error { + meals, err := h.fetchMeals(fetchCtx, forceRefresh) if err == nil { mu.Lock() data.Meals = meals @@ -244,8 +264,8 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models } if h.googleCalendarClient != nil { - fetch("Google Calendar", func() error { - events, err := h.fetchCalendarEvents(ctx, false) + fetch("Google Calendar", func(fetchCtx context.Context) error { + events, err := h.fetchCalendarEvents(fetchCtx, false) if err == nil { mu.Lock() data.Events = events @@ -256,8 +276,8 @@ func (h *Handler) aggregateData(ctx context.Context, forceRefresh bool) (*models } if h.googleTasksClient != nil { - fetch("Google Tasks", func() error { - tasks, err := h.fetchGoogleTasks(ctx, forceRefresh) + fetch("Google Tasks", func(fetchCtx context.Context) error { + tasks, err := h.fetchGoogleTasks(fetchCtx, forceRefresh) if err == nil { mu.Lock() data.GoogleTasks = tasks diff --git a/internal/handlers/handlers_test.go b/internal/handlers/handlers_test.go index bb383aa..9d92faa 100644 --- a/internal/handlers/handlers_test.go +++ b/internal/handlers/handlers_test.go @@ -2355,3 +2355,25 @@ func TestHandleTimeline_IncludesBudgetStatusWhenTrackedTaskExists(t *testing.T) } } +func TestPingDB_HealthyStore_ReturnsNil(t *testing.T) { + h, cleanup := setupTestHandler(t) + defer cleanup() + + if err := h.PingDB(context.Background()); err != nil { + t.Errorf("PingDB() = %v, want nil for a healthy store", err) + } +} + +// This is the regression test for the actual incident: a health check that +// can't observe a broken database isn't a health check. If PingDB stops +// reflecting real DB reachability -- e.g. someone "simplifies" it back to +// an unconditional nil -- this must fail. +func TestPingDB_ClosedStore_ReturnsError(t *testing.T) { + h, cleanup := setupTestHandler(t) + cleanup() // close the underlying DB before pinging it + + if err := h.PingDB(context.Background()); err == nil { + t.Error("PingDB() = nil, want an error for a closed/unreachable store") + } +} + -- cgit v1.2.3