From 8df03c6355eca9878ac2987bb77db836c199d29b Mon Sep 17 00:00:00 2001 From: Justin Bishop Date: Fri, 16 Oct 2026 12:12:44 -0700 Subject: [PATCH] fix(sync): let the stale-issue backfill settle - The stale check orders an issue's actions by time instead of text, so backfilled rows, which carry a local UTC offset, sort with the rest. - Backfilled rows are stamped no earlier than the issue's latest action. - The check reads the status that approve nests under "issue". Before, every sync before a project's first pull backfilled the same issues again and pushed duplicate snapshots. Co-Authored-By: Claude Opus 5.5 --- internal/sync/backfill.go | 39 ++++++---- internal/sync/backfill_test.go | 136 +++++++++++++++++++++++++++++++++ 2 files changed, 161 insertions(+), 14 deletions(-) diff --git a/internal/sync/backfill.go b/internal/sync/backfill.go index 748537f0..631dea5e 100644 --- a/internal/sync/backfill.go +++ b/internal/sync/backfill.go @@ -72,6 +72,14 @@ func BackfillOrphanEntities(tx *sql.Tx, sessionID string) (int, error) { return total, nil } +// latestActionOrder orders action_log rows newest first by time. Ordering the +// text would put this function's own rows, which the driver writes as +// "2026-10-15 14:00:00-07:00", before "2026-10-15T21:00:00Z" rows from the +// same day. julianday parses both, and SQLite's CURRENT_TIMESTAMP, which are +// the formats left after migration 36 rewrote Go String() values. Ties go to +// the row logged last. +const latestActionOrder = `julianday(timestamp) DESC, rowid DESC` + // BackfillStaleIssues inserts synthetic update events for issues whose // updated_at timestamp is newer than the latest action_log entry. // This helps sync older data where status changes weren't logged. @@ -96,10 +104,10 @@ func BackfillStaleIssues(tx *sql.Tx, sessionID string) (int, error) { SELECT i.*, (SELECT timestamp FROM action_log WHERE entity_id = i.id AND entity_type IN ('issue', 'issues') - ORDER BY timestamp DESC, rowid DESC LIMIT 1) AS last_ts, + ORDER BY ` + latestActionOrder + ` LIMIT 1) AS last_ts, (SELECT new_data FROM action_log WHERE entity_id = i.id AND entity_type IN ('issue', 'issues') - ORDER BY timestamp DESC, rowid DESC LIMIT 1) AS last_data, + ORDER BY ` + latestActionOrder + ` LIMIT 1) AS last_data, (SELECT COUNT(*) FROM action_log WHERE entity_id = i.id AND entity_type IN ('issue', 'issues') AND action_type = 'delete' AND undone = 0 @@ -187,14 +195,13 @@ func BackfillStaleIssues(tx *sql.Tx, sessionID string) (int, error) { needsUpdate = true } + updatedAt, haveUpdatedAt := parseAnyTime(updatedAtVal) + lastActionAt, haveLastAction := parseAnyTime(lastActionVal) + // Check updated_at staleness when we have timestamps - if !needsUpdate && updatedAtVal != nil && lastActionVal != nil { - if updatedAt, ok := parseAnyTime(updatedAtVal); ok { - if lastActionAt, ok := parseAnyTime(lastActionVal); ok { - if updatedAt.After(lastActionAt.Add(staleThreshold)) { - needsUpdate = true - } - } + if !needsUpdate && haveUpdatedAt && haveLastAction { + if updatedAt.After(lastActionAt.Add(staleThreshold)) { + needsUpdate = true } } @@ -230,11 +237,14 @@ func BackfillStaleIssues(tx *sql.Tx, sessionID string) (int, error) { return count, fmt.Errorf("generate action id: %w", err) } + // Stamp the row no earlier than the latest action, so it becomes the + // latest action and the next run sees the status it records. ts := time.Now() - if updatedAtVal != nil { - if parsed, ok := parseAnyTime(updatedAtVal); ok { - ts = parsed - } + if haveUpdatedAt { + ts = updatedAt + } + if haveLastAction && lastActionAt.After(ts) { + ts = lastActionAt } if _, err := stmt.Exec(actionID, sessionID, entityID, string(newData), ts); err != nil { @@ -497,7 +507,8 @@ func statusMatches(lastData any, currentStatus string) bool { if err := json.Unmarshal([]byte(raw), &fields); err != nil { return false } - val, ok := fields["status"] + // Review actions such as approve nest the issue under "issue". + val, ok := unwrapIssuePayload(fields)["status"] if !ok || val == nil { return false } diff --git a/internal/sync/backfill_test.go b/internal/sync/backfill_test.go index 7c14e350..988fcbb9 100644 --- a/internal/sync/backfill_test.go +++ b/internal/sync/backfill_test.go @@ -629,3 +629,139 @@ func TestAnyEventSetsStatusFalsePositive(t *testing.T) { t.Error("anyEventSetsStatus returned true for 'open' when only 'reopened' exists") } } + +func mustExec(t *testing.T, db *sql.DB, query string, args ...any) { + t.Helper() + if _, err := db.Exec(query, args...); err != nil { + t.Fatalf("exec %q: %v", query, err) + } +} + +// runStaleBackfill runs BackfillStaleIssues in its own transaction. +func runStaleBackfill(t *testing.T, db *sql.DB) int { + t.Helper() + tx, err := db.Begin() + if err != nil { + t.Fatal(err) + } + n, err := BackfillStaleIssues(tx, "ses-test") + if err != nil { + t.Fatal(err) + } + if err := tx.Commit(); err != nil { + t.Fatal(err) + } + return n +} + +func TestBackfillStaleIssues_SettlesAfterDelete(t *testing.T) { + db := setupBackfillDB(t) + + // A delete logs no data. The backfilled row is stamped with updated_at, + // the same instant as the delete but written with a local offset, which + // sorts before the delete as text. + mustExec(t, db, `INSERT INTO issues (id, title, status, updated_at) VALUES ('td-703', 'Deleted', 'open', '2026-09-30 14:20:48.774338-07:00')`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-703a', 'ses-old', 'create', 'issue', 'td-703', '{"id":"td-703","status":"open"}', '2026-09-30T21:20:40.445832Z', 0)`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-703b', 'ses-old', 'delete', 'issue', 'td-703', '', '2026-09-30T21:20:48.774338Z', 0)`) + + if n := runStaleBackfill(t, db); n != 1 { + t.Fatalf("run 1: expected 1 stale backfill, got %d", n) + } + if n := runStaleBackfill(t, db); n != 0 { + t.Fatalf("run 2: expected 0 stale backfills, got %d", n) + } +} + +func TestBackfillStaleIssues_SettlesWhenLatestActionPostdatesUpdatedAt(t *testing.T) { + db := setupBackfillDB(t) + + mustExec(t, db, `INSERT INTO issues (id, title, status, updated_at) VALUES ('td-704', 'Closed', 'closed', '2026-10-15 14:00:00-07:00')`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-704a', 'ses-old', 'create', 'issue', 'td-704', '{"id":"td-704","status":"open"}', '2026-10-15T20:00:00Z', 0)`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-704b', 'ses-old', 'update', 'issue', 'td-704', '{"id":"td-704"}', '2026-10-15T21:00:05Z', 0)`) + + if n := runStaleBackfill(t, db); n != 1 { + t.Fatalf("run 1: expected 1 stale backfill, got %d", n) + } + if n := runStaleBackfill(t, db); n != 0 { + t.Fatalf("run 2: expected 0 stale backfills, got %d", n) + } +} + +func TestBackfillStaleIssues_OrdersActionsByTimeAcrossFormats(t *testing.T) { + db := setupBackfillDB(t) + + // "2026-10-15 15:00:00-07:00" is 22:00 UTC, an hour after the statusless + // action, although it sorts before it as text and was logged first. + mustExec(t, db, `INSERT INTO issues (id, title, status, updated_at) VALUES ('td-705', 'Closed', 'closed', '2026-10-15 15:00:00-07:00')`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, previous_data, new_data, timestamp, undone) + VALUES ('al-705a', 'ses-old', 'update', 'issue', 'td-705', '{"id":"td-705","status":"open"}', '{"id":"td-705","status":"closed"}', '2026-10-15 15:00:00-07:00', 0)`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-705b', 'ses-old', 'update', 'issue', 'td-705', '{"id":"td-705"}', '2026-10-15T21:00:00Z', 0)`) + + if n := runStaleBackfill(t, db); n != 0 { + t.Fatalf("expected 0 stale backfills, got %d", n) + } +} + +func TestBackfillStaleIssues_ReadsStatusFromApprovePayload(t *testing.T) { + db := setupBackfillDB(t) + + // Approve logs the issue nested under "issue", which the sync engine unwraps. + mustExec(t, db, `INSERT INTO issues (id, title, status, updated_at) VALUES ('td-707', 'Approved', 'closed', '2026-10-15T21:00:00Z')`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-707', 'ses-old', 'approve', 'issue', 'td-707', '{"issue":{"id":"td-707","status":"closed"},"created_review_id":"rv-1"}', '2026-10-15T21:00:00Z', 0)`) + + if n := runStaleBackfill(t, db); n != 0 { + t.Fatalf("expected 0 stale backfills, got %d", n) + } +} + +func TestBackfillStaleIssues_IgnoresOrphanCreateFromSamePass(t *testing.T) { + db := setupBackfillDB(t) + + // The issue has an update but no create, so the orphan backfill adds one, + // stamped with created_at. The update is still the latest action. + mustExec(t, db, `INSERT INTO issues (id, title, status, created_at, updated_at) VALUES ('td-708', 'Closed', 'closed', '2026-10-01T00:00:00Z', '2026-10-15T21:00:00Z')`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, previous_data, new_data, timestamp, undone) + VALUES ('al-708', 'ses-old', 'update', 'issue', 'td-708', '{"id":"td-708","status":"open"}', '{"id":"td-708","status":"closed"}', '2026-10-15T21:00:00Z', 0)`) + + tx, err := db.Begin() + if err != nil { + t.Fatal(err) + } + orphans, err := BackfillOrphanEntities(tx, "ses-test") + if err != nil { + t.Fatal(err) + } + stale, err := BackfillStaleIssues(tx, "ses-test") + if err != nil { + t.Fatal(err) + } + if err := tx.Commit(); err != nil { + t.Fatal(err) + } + if orphans != 1 || stale != 0 { + t.Fatalf("expected 1 orphan and 0 stale backfills, got %d and %d", orphans, stale) + } +} + +func TestBackfillStaleIssues_SettlesWithoutUpdatedAt(t *testing.T) { + db := setupBackfillDB(t) + + // With no updated_at, the backfilled row must still be stamped no earlier + // than the latest action, even one stamped in the future. + mustExec(t, db, `INSERT INTO issues (id, title, status, updated_at) VALUES ('td-709', 'Closed', 'closed', NULL)`) + mustExec(t, db, `INSERT INTO action_log (id, session_id, action_type, entity_type, entity_id, new_data, timestamp, undone) + VALUES ('al-709', 'ses-old', 'delete', 'issue', 'td-709', '', '2999-01-01T00:00:00Z', 0)`) + + if n := runStaleBackfill(t, db); n != 1 { + t.Fatalf("run 1: expected 1 stale backfill, got %d", n) + } + if n := runStaleBackfill(t, db); n != 0 { + t.Fatalf("run 2: expected 0 stale backfills, got %d", n) + } +}