From 5fed1c777d70f0cf9acab1f8c6c40be4e43fdc27 Mon Sep 17 00:00:00 2001 From: Dennison Date: Mon, 3 Aug 2026 22:39:39 +0200 Subject: [PATCH] test(callbacks): stabilize deadline release fixtures (#1141) --- docs/logs/INDEX.md | 4 ++ docs/logs/engineering-log.md | 4 ++ docs/logs/long-term-thinking-log.md | 5 ++ docs/logs/observational-log.md | 3 + docs/logs/system-log.md | 3 + ...41-callback-deadline-fixture-impact-map.md | 52 ++++++++++++++ ...sue-1141-callback-deadline-fixture-plan.md | 44 ++++++++++++ docs/plans/INDEX.md | 5 ++ docs/plans/active-plan.md | 2 + .../tools/delayed_callback_retry_red_test.go | 70 ++++++++++++++----- 10 files changed, 176 insertions(+), 16 deletions(-) create mode 100644 docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md create mode 100644 docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-plan.md diff --git a/docs/logs/INDEX.md b/docs/logs/INDEX.md index a32e69e4..f0aff8de 100644 --- a/docs/logs/INDEX.md +++ b/docs/logs/INDEX.md @@ -8,6 +8,10 @@ recorded in the engineering, observational, system, and long-term-thinking logs. +- 2026-08-03 — Issue #1141 callback deadline-release fixture evidence is + recorded in the engineering, observational, system, and long-term-thinking + logs. + - 2026-08-03 — Issue #1135 deterministic cron recovery fixture evidence is recorded in the engineering, observational, system, and long-term-thinking logs. diff --git a/docs/logs/engineering-log.md b/docs/logs/engineering-log.md index 684cef5b..af10fecc 100644 --- a/docs/logs/engineering-log.md +++ b/docs/logs/engineering-log.md @@ -4020,3 +4020,7 @@ Skipped creating separate issues for Op/EventMsg protocol (already covered by SS - Focused normal/race x100, complete cron normal/race, and the full repository normal/race/coverage gate pass at 85.5% total coverage with zero uncovered functions. +## 2026-08-03 (Issue #1141 callback deadline-release fixture) + +- Three callback deadline-release fixtures now use a one-second test lease and causal gates: admitted callback, heartbeat renewal entry, deadline signal, then cancellation-aware starter cancellation before unblocking renewal. +- This is test-only. The strengthened assertions retain the durable safe error, attempt/run identity, retry state, and token/lease clearing contracts. Focused normal x20 (60.593s), race x20 (62.087s), and the full normal/race/coverage gate passed at 85.5% total coverage with zero uncovered functions. diff --git a/docs/logs/long-term-thinking-log.md b/docs/logs/long-term-thinking-log.md index 01887190..1fa04ebf 100644 --- a/docs/logs/long-term-thinking-log.md +++ b/docs/logs/long-term-thinking-log.md @@ -2357,3 +2357,8 @@ Decision rule: when uncertain, default to `command intent` and `user intent` bel - Verification: focused normal/race x100, `./internal/cron` normal/race, and tmux-hosted `./scripts/test-regression.sh` pass at 85.5% coverage with zero uncovered functions. +## 2026-08-03 (Issue #1141 deterministic callback deadline fixture) + +- Command intent: remove the three hosted callback deadline-release fixture races without changing callback production behavior. +- User intent: preserve trustworthy regression gates for durable callback continuation state visible through harness APIs and clients. +- Success definition: each fixture proves actual deadline cancellation before release and retains the exact durable retry/failure contract; focused normal and race x20 plus full regression pass. Evidence: all three gates passed; this remains a test-only reliability slice. diff --git a/docs/logs/observational-log.md b/docs/logs/observational-log.md index 8ecd9902..45be4ba4 100644 --- a/docs/logs/observational-log.md +++ b/docs/logs/observational-log.md @@ -810,3 +810,6 @@ Use this file for observations about system behavior without immediately prescri completion boundary and keep the pre-return no-overlap assertion explicit. - Focused normal/race x100 and complete cron normal/race pass without a sleep, and the repository regression's normal, race, and coverage phases pass. +## 2026-08-03 (Issue #1141 callback deadline-release observation) + +- A heartbeat's absence from `ExtendLease` is not evidence that deadline cancellation failed: under CI load the independent deadline can cancel the admission first. Fixtures now observe both the deadline and starter context cancellation, so their outcome no longer depends on heartbeat scheduling. Normal and race stress x20 and the full regression passed without callback runtime changes. diff --git a/docs/logs/system-log.md b/docs/logs/system-log.md index 3e9dba6f..76ab9a1a 100644 --- a/docs/logs/system-log.md +++ b/docs/logs/system-log.md @@ -1299,3 +1299,6 @@ Use this file to document systems, interfaces, and interactions as they are buil notification for that completion boundary. This is documentation of existing scheduler behavior only; API, persistence, TUI, and native GUI contracts are unchanged. +## 2026-08-03 (Issue #1141 callback deadline fixture boundary) + +- Callback lease deadline ownership is independent of heartbeat I/O. Tests that model blocked renewal must await the manager-owned deadline and the starter's canceled context before releasing renewal; SQLite's durable state remains the observable outcome for API, TUI, and native replay. diff --git a/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md b/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md new file mode 100644 index 00000000..cd0c8f84 --- /dev/null +++ b/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md @@ -0,0 +1,52 @@ +# Cross-Surface Impact Map: Issue #1141 + +## Task + +- Task / issue: #1141 callback deadline-release fixture stabilization. +- Plan link: `2026-08-03-issue-1141-callback-deadline-fixture-plan.md`. +- Owner: callback tools test suite. +- Status: in implementation. + +## Current Ownership, Callers, and Data Flow + +- Entry points: three tests in `delayed_callback_retry_red_test.go`. +- Source of truth: `CallbackManager` owns deadline cancellation; SQLite owns token-fenced durable state. +- Callers/consumers: harness callback tests only; production callers untouched. +- Similar abstractions/search: `rg` located all deadline-release tests, `blockingLeaseStore`, `ExtendLease`, and #1121's causal-gate fixture. +- Conclusion: alter test synchronization only. + +## Config, API, CLI, and Tools + +- None: no config, endpoint, CLI, tool, wire-format, or validation change. + +## Persistence and Compatibility + +- None in runtime: tests only read existing SQLite durable fields. Compatibility remains unchanged. + +## Lifecycle, Security, and Reliability + +- Reliability: gates prove ordered heartbeat/deadline/admission cancellation. +- Security/privacy: none; safe error text remains asserted, not changed. +- Recovery: tests retain token/lease clearing and exact reserved run ID checks. + +## Product and Integration Surfaces + +- Server/runtime: existing callback state machine is characterized. +- TUI/web/macOS: no code change; safe durable state continues to be the shared source for replay/visibility. +- Provider/model/tool routing and external systems: none. + +## Deployment and Operations + +- No deployment/migration/flag/rollback; fixture-only CI reliability repair. +- Hosted fast/race checks are the operational acceptance evidence. + +## Regression Tests + +- First red: hosted #1138 fast fixture timeout with 40 ms lease. +- Acceptance: focused three-test normal/race x20; assert admitted -> renewal -> deadline -> starter cancellation -> release ordering. +- Edge/negative: attempt cap remains failed with attempt 1, unchanged RunID, zero retry/token/lease, and safe reason. +- Full command: `./scripts/test-regression.sh`. + +## Documentation and Handoff + +- No public spec change; plan, map, logs, indexes, and PR test evidence record why the fixture synchronization is causal and runtime-neutral. diff --git a/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-plan.md b/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-plan.md new file mode 100644 index 00000000..320125bc --- /dev/null +++ b/docs/plans/2026-08-03-issue-1141-callback-deadline-fixture-plan.md @@ -0,0 +1,44 @@ +# Plan: Issue #1141 callback deadline-release fixture + +## Context + +- Governing GitHub issue: #1141. +- Problem: three callback tests used a 40 ms lease and inferred deadline cancellation from a heartbeat-only channel. Under load the deadline can cancel admission before the heartbeat calls `ExtendLease`, leaving that channel unclosed despite correct runtime behavior. +- User impact: flaky baseline checks obscure durable callback guarantees needed by API, TUI, and native transcript continuation work. +- Constraints: test and documentation only; do not alter callback behavior. + +## Scope + +- In scope: deterministic gates for the three deadline-release tests and retained/stronger durable state assertions. +- Out of scope: callback policy, scheduler behavior, public API, persistence, TUI, and native GUI changes. + +## Documentation Contract + +- Feature status: implemented test-fixture repair. +- Public docs affected: none; runtime behavior is unchanged. +- Spec docs to update before code: this plan and impact map. +- Implementation notes to add after code: engineering, observational, system, and long-term-thinking logs plus their indexes. + +## Test Plan (TDD) + +- First red evidence: hosted #1138 fast CI reported the 40 ms fixture timing failure; the stronger tests replace that non-causal observation. +- New/updated tests: wait in order for admitted entry, heartbeat renewal entry, deadline gate, and cancellation-aware starter cancellation before release. +- Regression tests required: preserve same-manager retry, safe reason, and attempt-cap terminal state including exact run identity/cleared ownership. + +## Cross-Surface Impact Map + +`2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md`. + +## Implementation Checklist + +- [x] Verify the structured issue and repository owners/search evidence. +- [x] Write plan and impact map before fixture changes. +- [x] Replace timing assumptions with causal test gates. +- [x] Retain durable-state assertions and strengthen the attempt-bound state. +- [x] Run focused normal/race x20 and full regression. +- [x] Update final evidence and create the reviewable PR. + +## Risks and Mitigations + +- Risk: a longer lease hides a runtime deadline bug. +- Mitigation: each test now observes the actual deadline signal and admission cancellation before unblocking; no pass is based on elapsed sleep alone. diff --git a/docs/plans/INDEX.md b/docs/plans/INDEX.md index e587233d..b9ce2568 100644 --- a/docs/plans/INDEX.md +++ b/docs/plans/INDEX.md @@ -10,6 +10,11 @@ - `2026-08-03-issue-1140-matrix-listener-impact-map.md` — Cross-surface impact map for Issue #1140 test-harness listener injection. +- `2026-08-03-issue-1141-callback-deadline-fixture-plan.md` — Issue #1141 + test-only deterministic callback deadline-release fixture plan. +- `2026-08-03-issue-1141-callback-deadline-fixture-impact-map.md` — + Cross-surface impact map for the Issue #1141 fixture-only reliability repair. + - `2026-08-03-issue-1135-cron-fixture-plan.md` — Issue #1135 deterministic recovered-cron terminal-persistence and scope-release fixture plan. - `2026-08-03-issue-1135-cron-fixture-impact-map.md` — Cross-surface impact diff --git a/docs/plans/active-plan.md b/docs/plans/active-plan.md index 292d6b5e..0113fee8 100644 --- a/docs/plans/active-plan.md +++ b/docs/plans/active-plan.md @@ -1,5 +1,7 @@ # Active Plan +Current status: Issue #1141 isolates a callback deadline-release fixture race from #1138 hosted CI. The three tests use causal admitted, blocked-renewal, deadline, and cancellation-aware admission gates before releasing the blocked renewal; production callback/API/TUI/native behavior is explicitly out of scope. Focused normal/race x20 and the full regression remain required. + Current status: Issue #1135 isolates the hosted cron recovery fixture race. The two recovery tests now block only their terminal mock-store return, prove the persisted-but-not-returned row still denies the exact same scope, release diff --git a/internal/harness/tools/delayed_callback_retry_red_test.go b/internal/harness/tools/delayed_callback_retry_red_test.go index 086bfee2..5c57ce75 100644 --- a/internal/harness/tools/delayed_callback_retry_red_test.go +++ b/internal/harness/tools/delayed_callback_retry_red_test.go @@ -216,10 +216,12 @@ func (s *stubbornCallbackStarter) unblock() { s.releaseOnce.Do(func() { close(s. // lease-deadline context cancellation, then admits the retry using the same // reserved run identity. type deadlineThenSuccessStarter struct { - mu sync.Mutex - ids []string - entered chan struct{} - once sync.Once + mu sync.Mutex + ids []string + entered chan struct{} + canceled chan struct{} + enteredOnce sync.Once + canceledOnce sync.Once } func (*deadlineThenSuccessStarter) StartRun(string, string, string, string) error { return nil } @@ -230,8 +232,11 @@ func (s *deadlineThenSuccessStarter) StartCallback(ctx context.Context, info Cal s.ids = append(s.ids, info.RunID) s.mu.Unlock() if call == 0 { - s.once.Do(func() { close(s.entered) }) + s.enteredOnce.Do(func() { close(s.entered) }) <-ctx.Done() + if s.canceled != nil { + s.canceledOnce.Do(func() { close(s.canceled) }) + } return "", ctx.Err() } return info.RunID, nil @@ -679,22 +684,35 @@ func TestCallbackManagerDeadlineReleaseRearmsSingleOwner(t *testing.T) { if err := store.Create(context.Background(), info); err != nil { t.Fatal(err) } - starter := &deadlineThenSuccessStarter{entered: make(chan struct{})} + starter := &deadlineThenSuccessStarter{entered: make(chan struct{}), canceled: make(chan struct{})} blocking := &blockingLeaseStore{CallbackStore: store, entered: make(chan struct{}), deadlineReached: make(chan struct{}), release: make(chan struct{})} mgr := NewCallbackManager(starter, WithCallbackStore(blocking)) - mgr.leaseTime = 40 * time.Millisecond + // The explicit gates below, rather than a short lease, make this a test of + // deadline release. The one-second lease gives the heartbeat enough room to + // enter its deliberate block even under CI load. + mgr.leaseTime = time.Second mgr.retryBase = time.Millisecond - t.Cleanup(blocking.unblock) t.Cleanup(mgr.Shutdown) + t.Cleanup(blocking.unblock) if err := mgr.Recover(context.Background()); err != nil { t.Fatal(err) } waitForCallbackAdmission(t, starter.entered) select { + case <-blocking.entered: + case <-time.After(3 * time.Second): + t.Fatal("heartbeat renewal did not enter blocking lease store") + } + select { case <-blocking.deadlineReached: - case <-time.After(time.Second): + case <-time.After(3 * time.Second): t.Fatal("blocked renewal never reached its lease deadline") } + select { + case <-starter.canceled: + case <-time.After(3 * time.Second): + t.Fatal("deadline did not cancel first callback admission") + } // Let the deadline-cancelled first call return. The manager itself must // re-arm retry_wait; no second manager is constructed in this regression. blocking.unblock() @@ -718,22 +736,32 @@ func TestCallbackManagerDeadlineReleasePersistsSafeRetryReason(t *testing.T) { starter := &cancellationAwareCallbackStarter{entered: make(chan struct{}), canceled: make(chan time.Time, 1)} blocking := &blockingLeaseStore{CallbackStore: store, entered: make(chan struct{}), deadlineReached: make(chan struct{}), release: make(chan struct{})} mgr := NewCallbackManager(starter, WithCallbackStore(blocking)) - mgr.leaseTime = 40 * time.Millisecond + mgr.leaseTime = time.Second mgr.retryBase = time.Second - t.Cleanup(blocking.unblock) t.Cleanup(mgr.Shutdown) + t.Cleanup(blocking.unblock) if err := mgr.Recover(context.Background()); err != nil { t.Fatal(err) } waitForCallbackAdmission(t, starter.entered) select { + case <-blocking.entered: + case <-time.After(3 * time.Second): + t.Fatal("heartbeat renewal did not enter blocking lease store") + } + select { case <-blocking.deadlineReached: - case <-time.After(time.Second): + case <-time.After(3 * time.Second): t.Fatal("deadline was not reached") } + select { + case <-starter.canceled: + case <-time.After(3 * time.Second): + t.Fatal("deadline did not cancel callback admission") + } blocking.unblock() retrying := waitForCallbackState(t, store, info.ID, CallbackStateRetryWait) - if retrying.LastError != "callback admission unavailable" || strings.Contains(retrying.LastError, "context") { + if retrying.Attempt != 1 || retrying.RunID != info.RunID || retrying.NextAttemptAt.IsZero() || retrying.DispatchToken != "" || !retrying.DispatchLeaseUntil.IsZero() || retrying.LastError != "callback admission unavailable" || strings.Contains(retrying.LastError, "context") { t.Fatalf("unsafe or missing retry reason: %#v", retrying) } } @@ -1020,7 +1048,7 @@ func TestCallbackManagerDeadlineReleaseHonorsAttemptBound(t *testing.T) { starter := &cancellationAwareCallbackStarter{entered: make(chan struct{}), canceled: make(chan time.Time, 1)} blocking := &blockingLeaseStore{CallbackStore: store, entered: make(chan struct{}), deadlineReached: make(chan struct{}), release: make(chan struct{})} mgr := NewCallbackManager(starter, WithCallbackStore(blocking)) - mgr.leaseTime = 40 * time.Millisecond + mgr.leaseTime = time.Second mgr.maxAttempts = 1 t.Cleanup(mgr.Shutdown) t.Cleanup(blocking.unblock) @@ -1029,13 +1057,23 @@ func TestCallbackManagerDeadlineReleaseHonorsAttemptBound(t *testing.T) { } waitForCallbackAdmission(t, starter.entered) select { + case <-blocking.entered: + case <-time.After(3 * time.Second): + t.Fatal("heartbeat renewal did not enter blocking lease store") + } + select { case <-blocking.deadlineReached: - case <-time.After(time.Second): + case <-time.After(3 * time.Second): t.Fatal("deadline did not cancel bounded admission") } + select { + case <-starter.canceled: + case <-time.After(3 * time.Second): + t.Fatal("deadline did not cancel bounded callback admission") + } blocking.unblock() failed := waitForCallbackState(t, store, info.ID, CallbackStateFailed) - if !failed.NextAttemptAt.IsZero() || failed.Attempt != 1 || failed.LastError != "callback admission unavailable" { + if !failed.NextAttemptAt.IsZero() || failed.Attempt != 1 || failed.RunID != info.RunID || failed.DispatchToken != "" || !failed.DispatchLeaseUntil.IsZero() || failed.LastError != "callback admission unavailable" { t.Fatalf("bounded deadline state=%#v", failed) } }