diff options
| -rw-r--r-- | .agent/worklog.md | 1 | ||||
| -rw-r--r-- | cmd/dashboard/main.go | 18 | ||||
| -rw-r--r-- | internal/api/context_audit_test.go | 87 | ||||
| -rw-r--r-- | internal/api/google_calendar.go | 65 | ||||
| -rw-r--r-- | internal/config/constants.go | 6 | ||||
| -rw-r--r-- | internal/handlers/handlers.go | 42 | ||||
| -rw-r--r-- | internal/handlers/handlers_test.go | 22 | ||||
| -rwxr-xr-x | scripts/health-watchdog.sh | 33 |
8 files changed, 248 insertions, 26 deletions
diff --git a/.agent/worklog.md b/.agent/worklog.md index d41438c..66aeab8 100644 --- a/.agent/worklog.md +++ b/.agent/worklog.md @@ -4,6 +4,7 @@ Cleaned Backlog ## Recently Completed +- **Production incident: server wedged 3 days, root cause + structural fix** — three `.Do()` calls in `google_calendar.go` (`GetUpcomingEvents`, `GetEventsByDateRange`, `GetCalendarList`) accepted a `ctx` param but never chained `.Context(ctx)` into the actual Google API SDK call, so the pre-existing global 60s `middleware.Timeout` never reached the blocking network call — one hung Google Calendar request wedged every DB/session-touching request path for 3 days starting 2026-08-01, undetected because `/health` unconditionally returned 200 the whole time. Fixed: wired `.Context(ctx)` into all three call sites; `aggregateData`'s 4 external fetches (Trello/PlanToEat/Calendar/Tasks) each now get a bounded per-fetch sub-context (`config.HTTPClientTimeout`) as defense-in-depth (documented as exactly that in the comment — it only helps if the callee honors ctx, doesn't independently guarantee anything); `/health` now does a real `PingContext` DB check instead of a static "ok" (`Handler.PingDB`, tested for both healthy and closed-DB cases); a new `scripts/health-watchdog.sh` cron job (every 5 min) restarts the service if `/health` fails twice in a row. Caught by a from-scratch multi-angle code review before commit: the per-fetch timeout, applied to `GetUpcomingEvents`'s sequential per-calendar loop, would have starved calendars past the first under any real latency (and the swallowed per-calendar error meant that got silently cached as "zero events" — a live regression against this account's 3 configured calendars, never shipped). Fixed by making the per-calendar loop concurrent (`fetchAllCalendars`, shared `sync.WaitGroup`) instead of sequential, so every calendar gets an equal shot at the same deadline instead of eating into the next one's share of it — without touching the pre-existing, deliberately-tested "per-calendar errors are logged and skipped, not propagated" contract. Added `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 — verified by deliberately reintroducing the original bug against a real backup and confirming the guard catches it, then restoring. `go test ./... -race` green. Deployed server; Android quick-add fix (was silently no-op-ing on failure, plus its 5 post-`addTask` follow-up calls were still unchecked) deployed separately as `doot-widget.apk`. - **Bucket CRUD + read-only Projects/Labels on the Settings page** — new "Maintenance Buckets" section: create a bucket (name/cycle_days/pick_n), add a pool item by title (creates the task and assigns it in one step via a new form), remove an item, delete a bucket (unbuckets its tasks rather than deleting them). New store methods `GetBucketItems`/`DeleteBucket`. New read-only "Projects" and "Labels" sections (name + color swatch) -- simple enough that read-only was the right call, per user direction, rather than duplicating the Android popup's editing UX on web. Fully covered by store+handler tests (`go test ./...` green). Not yet deployed. - **Tasks tab rework: Chains section, chain checklist modal, chain-completion lock guard, project-name visibility** — the flat Tasks-tab atom list was silently dumping every chain step (locked and unlocked) and dormant bucket-pool items into the grid as ordinary undated cards, with no chain/project context and, worse, a raw Complete checkbox that `CompleteNativeTask` didn't actually guard against for locked steps (would have corrupted the WIP-1 invariant if clicked). Fixed: `CompleteNativeTask` now returns `ErrChainTaskLocked` for a locked chain task (mapped to 400 in both the widget and web complete-atom handlers); chain tasks (locked or unlocked) and dormant bucket items are excluded from the flat atom list entirely; a new "Chains" section on the Tasks tab shows one card per active/paused chain (`GetChains`, `BuildChainSummaries`) with the current step, N/M progress, and a click-through to a new modal (`GET /chains/{id}`, `chain-detail.html`) listing every position in order (locked/unlocked/completed) with pause/resume/abandon buttons -- the web checklist view originally deferred as Android-only. Along the way, found and fixed a real bug this surfaced: resuming a paused chain only flipped the status flag, never actually unlocking the deferred successor, so a chain paused right after a completion would stay stuck forever -- `SetChainStatus` now catches up the deferred advancement on resume, idempotently (no due-date reset if nothing was actually stuck). Regular atom cards also gained a project-name chip for general visibility. Fully covered by store+handler tests (`go test ./...` green). Not yet deployed. - **Linear task chains + recurring maintenance buckets** — implemented the last two items from `[[doot-future-task-scheduling-ideas]]` (items 1 and 2, budgets/availability and labels/projects, turned out to already be shipped -- their spec status headers and the budgets plan's checkboxes had just never been updated to say so; corrected both). Chains: `task_chains` table + `chain_id`/`chain_position`/`chain_unlocked` on `native_tasks` (migration 026), WIP-limit-1 sequencing wired into `CompleteNativeTask`'s existing recurrence-hook pattern, locked tasks excluded from all date-based queries, 5 new `/api/widget/chains*` endpoints, a position badge ("N/M") on web timeline rows and the Android widget row. Buckets: `maintenance_buckets` table + `bucket_id`/`bucket_state`/`bucket_last_active_at` on `native_tasks` (migration 027), staleness-then-priority selection scoring, a new `RunBucketCycleCheck` scheduler loop mirroring `RunRecurrenceCheck`, 5 new endpoints including the distinct Defer action (returns to pool without crediting completion, unlike Complete), a Defer button on both web timeline rows and the Android widget row. Both fully covered by store+handler tests (`go test ./...` green). Deferred (backend/API exists, UI doesn't): a dedicated Android chain-checklist screen, and bucket-management create/add-item screens on web or Android -- both explicitly out of scope in their specs' own interviews. Not yet deployed or built into the Android APK. diff --git a/cmd/dashboard/main.go b/cmd/dashboard/main.go index cb2b757..89d12d1 100644 --- a/cmd/dashboard/main.go +++ b/cmd/dashboard/main.go @@ -209,9 +209,25 @@ func main() { // Rate limiter for agent auth (stricter - 10 requests/minute per IP) agentAuthRateLimiter := appmiddleware.NewRateLimiter(10, time.Minute) - // Health check (no auth) + // Health check (no auth). Actually pings the database rather than + // unconditionally returning 200 -- a health check that can't fail isn't + // a health check, it's a liveness stub. That distinction is exactly what + // let the 2026-08-04 incident (DB/session-touching requests wedged for + // three days) go undetected: this endpoint said "ok" the entire time. + // Note the scope: this proves the DB is reachable, not that every request + // path is healthy -- a hung external API call that doesn't touch the DB + // (the actual incident's mechanism) wouldn't be caught by this alone. + // That class of bug is addressed structurally instead, by requiring every + // Google API call to propagate context (see internal/api/context_audit_test.go). r.Get("/health", func(w http.ResponseWriter, r *http.Request) { + ctx, cancel := context.WithTimeout(r.Context(), config.HealthCheckTimeout) + defer cancel() w.Header().Set("Content-Type", "text/plain") + if err := h.PingDB(ctx); err != nil { + w.WriteHeader(http.StatusServiceUnavailable) + _, _ = w.Write([]byte("db unreachable: " + err.Error())) + return + } w.WriteHeader(http.StatusOK) _, _ = w.Write([]byte("ok")) }) 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") + } +} + diff --git a/scripts/health-watchdog.sh b/scripts/health-watchdog.sh new file mode 100755 index 0000000..9fde6a5 --- /dev/null +++ b/scripts/health-watchdog.sh @@ -0,0 +1,33 @@ +#!/bin/bash +# Health watchdog for the doot server. +# +# /health pings the database (see cmd/dashboard/main.go) rather than +# unconditionally returning 200 -- it used to be a liveness stub that +# stayed green for three days during the 2026-08-04 incident while every +# DB-touching request path was wedged. This polls it and restarts the +# service if it's stuck. Meant to run from cron every few minutes. +# +# Usage: ./scripts/health-watchdog.sh + +APP_URL="http://127.0.0.1:38080/health" +SERVICE="task-dashboard@doot.terst.org.service" +LOG="/var/log/doot-health-watchdog.log" +TIMEOUT=5 + +check() { + curl -s -o /dev/null -w "%{http_code}" --max-time "$TIMEOUT" "$APP_URL" 2>/dev/null +} + +# Two attempts, 5s apart -- don't restart on a single transient blip. +code=$(check) +if [ "$code" != "200" ]; then + sleep 5 + code=$(check) +fi +if [ "$code" = "200" ]; then + exit 0 +fi + +echo "$(date -u '+%Y-%m-%dT%H:%M:%SZ') UNHEALTHY (http_code=${code:-timeout}) -- restarting ${SERVICE}" >> "$LOG" +systemctl restart "$SERVICE" +echo "$(date -u '+%Y-%m-%dT%H:%M:%SZ') restart issued" >> "$LOG" |