Skip to content

Commit bdb8f71

Browse files
committed
fix(telemetry): drain remaining BBolt writers before shutdown-marker resolve (Spec 080, review round 4)
Two writers could still hit BBolt after Close() resolved the clean-shutdown marker (FR-010: the marker resolve must be the final DB write of a graceful shutdown) or even after the DB handle closed: 1. Error-code notifier (runtime.go SetTelemetry wiring): review round 1 made the notifier synchronous for FR-012 but kept the 24h diagnostics counter write in an untracked goroutine — no better tracked than the pre-branch `go notifier(code)` in the supervisor, and now able to race the marker resolve. The counter write is now synchronous too: it completes inside the supervisor's call stack, so Supervisor.Stop() (which joins its goroutines before Close touches storage) is a hard barrier. Safe: sub-ms BBolt Update, the callback never re-enters the supervisor (documented at notifyErrorCode), and RecordLastErrorCode already writes synchronously under identical locking. SetErrorCodeNotifier's contract now forbids callback goroutines that outlive the call. The untracked-goroutine exposure itself pre-dates the branch; the marker invariant it violates is new here, and the specific goroutine was introduced in round 1 (1ec8109). 2. ActivityService (activity records, retention pruning, usage-snapshot flushes, async sensitive-data detection — all BBolt writes): Close() only context-cancelled it and never awaited it, so the flush-on-shutdown (persistUsage) and any in-flight worker could land after the marker resolve or be lost at DB close. Pre-existing on main (Stop() existed but was never called from Close); the Spec 080 marker invariant makes it observable, so it is fixed on this branch. ActivityService.Stop() is now idempotent, returns immediately if Start never ran, and waits for the event loop's final flush plus a WaitGroup over the retention loop, the usage-flush loop, and per-event detection goroutines. Close() calls it after appCancel (so the final flush is captured) and BEFORE StopAsync/ResolveCleanShutdown/storage Close. Tests: TestRuntimeCloseWaitsForActivityWritersBeforeMarkerResolve proves the shutdown flush lands before the DB closes AND the marker still resolves to clean; TestActivityServiceStopSafeWhenNeverStartedAndIdempotent covers the never-started and repeated-Stop paths (every existing prechurn test now exercises the never-started branch through Close).
1 parent 6a334d2 commit bdb8f71

4 files changed

Lines changed: 200 additions & 15 deletions

File tree

internal/runtime/activity_service.go

Lines changed: 66 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package runtime
33
import (
44
"context"
55
"encoding/json"
6+
"sync"
67
"sync/atomic"
78
"time"
89

@@ -39,8 +40,18 @@ type ActivityService struct {
3940

4041
// Channel for receiving events
4142
eventCh chan Event
42-
// Done channel for graceful shutdown
43-
done chan struct{}
43+
44+
// Shutdown coordination (Spec 080 FR-010): Runtime.Close must be able to
45+
// await every BBolt writer this service owns BEFORE the clean-shutdown
46+
// marker resolves and the DB closes. done signals the main event loop's
47+
// exit (the final flush-on-shutdown included); workersWG tracks the
48+
// background loops (retention, usage flush) and the per-event async
49+
// detection goroutines, all of which write to BBolt. startMu/started make
50+
// Stop return immediately when Start never ran (done would never close).
51+
done chan struct{}
52+
workersWG sync.WaitGroup
53+
startMu sync.Mutex
54+
started bool
4455

4556
// Retention configuration
4657
maxAge time.Duration
@@ -116,17 +127,37 @@ func (s *ActivityService) SetRetentionConfig(maxAge time.Duration, maxRecords in
116127
// Start begins listening for activity events and persisting them.
117128
// It should be called as a goroutine: go svc.Start(ctx, runtime)
118129
func (s *ActivityService) Start(ctx context.Context, rt *Runtime) {
130+
// Mark started so Stop knows the done channel WILL close; refuse a second
131+
// Start (the done/WaitGroup bookkeeping is single-shot).
132+
s.startMu.Lock()
133+
if s.started {
134+
s.startMu.Unlock()
135+
s.logger.Warn("Activity service Start called twice; ignoring")
136+
return
137+
}
138+
s.started = true
139+
s.startMu.Unlock()
140+
119141
// Subscribe to runtime events
120142
eventCh := rt.SubscribeEvents()
121143
defer rt.UnsubscribeEvents(eventCh)
122144

123-
// Start retention loop in a separate goroutine
124-
go s.runRetentionLoop(ctx)
145+
// Start retention loop in a separate goroutine. Tracked in workersWG: it
146+
// prunes activity records (BBolt writes), so Stop must await it.
147+
s.workersWG.Add(1)
148+
go func() {
149+
defer s.workersWG.Done()
150+
s.runRetentionLoop(ctx)
151+
}()
125152

126153
// Spec 069 A2: load/rebuild the usage aggregate before processing events,
127-
// then start the periodic snapshot flush loop.
154+
// then start the periodic snapshot flush loop (tracked: it writes BBolt).
128155
s.initUsageFromStorage()
129-
go s.runUsageFlushLoop(ctx)
156+
s.workersWG.Add(1)
157+
go func() {
158+
defer s.workersWG.Done()
159+
s.runUsageFlushLoop(ctx)
160+
}()
130161

131162
s.logger.Info("Activity service started")
132163

@@ -213,9 +244,30 @@ func (s *ActivityService) runRetentionCleanup() {
213244
}
214245
}
215246

216-
// Stop gracefully shuts down the activity service.
247+
// Stop gracefully shuts down the activity service, waiting for every BBolt
248+
// writer it owns to finish: the main event loop (including its final
249+
// flush-on-shutdown of the usage snapshot), the retention and usage-flush
250+
// loops, and any in-flight async detection goroutines (Spec 080 FR-010: no
251+
// activity write may land after Runtime.Close resolves the clean-shutdown
252+
// marker or closes the DB).
253+
//
254+
// Callers must cancel the context passed to Start FIRST — the final usage
255+
// flush runs on ctx.Done inside the event loop, and Stop waits for it, so the
256+
// flush is captured before the marker resolves. Idempotent, and returns
257+
// immediately when Start never ran.
217258
func (s *ActivityService) Stop() {
259+
s.startMu.Lock()
260+
started := s.started
261+
s.startMu.Unlock()
262+
if !started {
263+
return
264+
}
265+
// Main loop exit (closes done AFTER the shutdown flush). All workersWG.Add
266+
// calls happen before done closes — the loop goroutines are registered at
267+
// the top of Start and detection goroutines are only spawned from the event
268+
// loop — so Wait below cannot race an Add.
218269
<-s.done
270+
s.workersWG.Wait()
219271
}
220272

221273
// handleEvent processes an activity event and persists it to storage.
@@ -355,9 +407,14 @@ func (s *ActivityService) handleToolCallCompleted(evt Event) {
355407
s.usage.Apply(record)
356408
}
357409

358-
// Run async sensitive data detection (Spec 026)
410+
// Run async sensitive data detection (Spec 026). Tracked in workersWG:
411+
// it updates the record's metadata in BBolt, so Stop must await it.
359412
if s.detector != nil {
360-
go s.runAsyncDetection(record.ID, arguments, response)
413+
s.workersWG.Add(1)
414+
go func() {
415+
defer s.workersWG.Done()
416+
s.runAsyncDetection(record.ID, arguments, response)
417+
}()
361418
}
362419
}
363420
}

internal/runtime/prechurn_lifecycle_test.go

Lines changed: 102 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import (
55
"errors"
66
"path/filepath"
77
"testing"
8+
"time"
89

910
"go.etcd.io/bbolt"
1011
berrors "go.etcd.io/bbolt/errors"
@@ -139,6 +140,107 @@ func TestRuntimeCloseCleanupBranchStillResolvesAndClosesStorage(t *testing.T) {
139140
}
140141
}
141142

143+
// TestRuntimeCloseWaitsForActivityWritersBeforeMarkerResolve guards the Close
144+
// ordering added in review round 4 (Spec 080 FR-010): the ActivityService owns
145+
// BBolt writers (activity records, usage-snapshot flushes, retention pruning,
146+
// async detection), and before this fix Close only context-cancelled it —
147+
// its final flush-on-shutdown (persistUsage) raced the shutdown-marker resolve
148+
// and the DB close, so the flush could be lost or land AFTER the marker
149+
// claimed "no writes remain". Now Close awaits ActivityService.Stop() before
150+
// StopAsync/ResolveCleanShutdown/db.Close, so the flush must both survive and
151+
// precede the clean marker.
152+
func TestRuntimeCloseWaitsForActivityWritersBeforeMarkerResolve(t *testing.T) {
153+
t.Setenv("MCPPROXY_LAUNCHED_BY", "")
154+
dataDir := t.TempDir()
155+
156+
rt, _ := previousShutdownVia(t, dataDir)
157+
158+
// Start the activity service exactly as StartBackgroundInitialization does.
159+
rt.ActivityService().SetEventEmitter(rt)
160+
go rt.ActivityService().Start(rt.AppContext(), rt)
161+
162+
// Emit a completed tool call and wait until the event loop has persisted it
163+
// and folded it into the in-memory usage aggregate (Apply runs only after a
164+
// successful SaveActivity). Re-emit each attempt: an event published before
165+
// Start's SubscribeEvents registers is silently dropped, so a single early
166+
// emit could race the service's startup.
167+
deadline := time.Now().Add(5 * time.Second)
168+
for {
169+
rt.EmitActivityToolCallCompleted(
170+
"prechurn-srv", "prechurn-tool", "sess-1", "req-1", "mcp",
171+
"success", "", 7, nil, "ok", false, "", nil, "", "", 0, 0)
172+
if snap := rt.ActivityService().UsageSnapshot(); snap != nil && len(snap.Tools) > 0 {
173+
break
174+
}
175+
if time.Now().After(deadline) {
176+
t.Fatal("timed out waiting for the activity event to reach the usage aggregate")
177+
}
178+
time.Sleep(10 * time.Millisecond)
179+
}
180+
181+
// The default flush cadence (30s) cannot fire within this test, so the ONLY
182+
// path that persists the aggregate is the flush-on-shutdown — which Close
183+
// must wait for before resolving the marker and closing the DB.
184+
if err := rt.Close(); err != nil {
185+
t.Fatalf("close: %v", err)
186+
}
187+
188+
// Reopen: the flush landed AND the marker resolved to clean afterwards.
189+
rt2, prev := previousShutdownVia(t, dataDir)
190+
defer func() { _ = rt2.Close() }()
191+
if prev != "clean" {
192+
t.Fatalf("after graceful close: expected clean, got %q", prev)
193+
}
194+
data, err := rt2.StorageManager().LoadUsageSnapshot()
195+
if err != nil {
196+
t.Fatalf("load usage snapshot: %v", err)
197+
}
198+
if len(data) == 0 {
199+
t.Fatal("usage snapshot missing: shutdown flush did not land before the DB closed")
200+
}
201+
agg, err := decodeUsageAggregate(data)
202+
if err != nil {
203+
t.Fatalf("decode usage snapshot: %v", err)
204+
}
205+
if _, ok := agg.Tools[toolKey("prechurn-srv", "prechurn-tool")]; !ok {
206+
t.Fatalf("persisted usage snapshot lacks the recorded tool call; tools = %d", len(agg.Tools))
207+
}
208+
}
209+
210+
// TestActivityServiceStopSafeWhenNeverStartedAndIdempotent: Close() now calls
211+
// ActivityService.Stop() unconditionally, including on runtimes whose
212+
// background initialization never ran (every other test in this file) and on
213+
// double Close. Stop must return immediately when Start never ran, and be
214+
// idempotent after a normal shutdown.
215+
func TestActivityServiceStopSafeWhenNeverStartedAndIdempotent(t *testing.T) {
216+
t.Setenv("MCPPROXY_LAUNCHED_BY", "")
217+
dataDir := t.TempDir()
218+
219+
rt, _ := previousShutdownVia(t, dataDir)
220+
221+
// Never started: must not block.
222+
doneCh := make(chan struct{})
223+
go func() {
224+
rt.ActivityService().Stop()
225+
close(doneCh)
226+
}()
227+
select {
228+
case <-doneCh:
229+
case <-time.After(2 * time.Second):
230+
t.Fatal("ActivityService.Stop blocked although Start never ran")
231+
}
232+
233+
// Started, then Close (which stops it), then Stop again: idempotent.
234+
// (Runtime.Close itself is not re-runnable — cache.Manager.Close panics on
235+
// a second call, a pre-existing constraint — so only Stop is re-invoked.)
236+
go rt.ActivityService().Start(rt.AppContext(), rt)
237+
if err := rt.Close(); err != nil {
238+
t.Fatalf("close: %v", err)
239+
}
240+
rt.ActivityService().Stop() // second stop must not hang or panic
241+
rt.ActivityService().Stop() // and a third
242+
}
243+
142244
// TestRuntimeCloseAfterExternalStopAsyncStillResolvesClean guards the split
143245
// Close sequence (Spec 080 FR-010, review round 3): Close now runs
144246
// storage.StopAsync (stop + drain queued async DB ops) BEFORE resolving the

internal/runtime/runtime.go

Lines changed: 26 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -653,6 +653,20 @@ func (r *Runtime) Close() error {
653653
}
654654
}
655655

656+
// Spec 080 (FR-010, review round 4): the ActivityService owns BBolt
657+
// writers — activity records, retention pruning, usage-snapshot flushes,
658+
// async sensitive-data detection. The appCancel at the top of Close
659+
// triggered its flush-on-shutdown; await that flush AND all its worker
660+
// goroutines here, BEFORE the async-op drain and the shutdown-marker
661+
// resolve below, so no activity write can land after the marker claims
662+
// the shutdown was clean (or after the DB closes). This writer-vs-close
663+
// race pre-dates Spec 080 (Stop existed but was never called); the marker
664+
// invariant makes it observable, so it is closed here. Stop returns
665+
// immediately when Start never ran and is itself idempotent.
666+
if r.activityService != nil {
667+
r.activityService.Stop()
668+
}
669+
656670
// Spec 080 (US3, FR-010): resolve the shutdown marker to "clean" at the
657671
// LAST point the DB is still open — i.e. after the async storage manager
658672
// has stopped AND drained its queue (those queued operations perform BBolt
@@ -2524,9 +2538,18 @@ func (r *Runtime) SetTelemetry(version, edition string) {
25242538
if prechurnStore != nil {
25252539
_ = prechurnStore.RecordLastErrorCode(db, code)
25262540
}
2527-
// The 24h aggregate counter keeps its pre-existing async
2528-
// posture: loss-tolerant, off the supervisor's path.
2529-
go func() { _ = diagStore.RecordErrorCode(db, code) }()
2541+
// The 24h aggregate counter write is synchronous too
2542+
// (review round 4): an untracked goroutine here could run
2543+
// after Close resolves the shutdown marker (FR-010) or
2544+
// after the DB handle closes. Synchronous means the write
2545+
// completes inside the supervisor's call stack, so
2546+
// supervisor.Stop() — which joins its goroutines before
2547+
// Close touches storage — is a hard barrier: after it
2548+
// returns, no notifier-driven DB write remains. Same
2549+
// safety argument as above: sub-ms BBolt Update, no
2550+
// supervisor re-entry, so no lock cycle even when the
2551+
// caller holds stateMu.
2552+
_ = diagStore.RecordErrorCode(db, code)
25302553
})
25312554
}
25322555

internal/runtime/supervisor/supervisor.go

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -810,9 +810,12 @@ func (s *Supervisor) SetOnServerConnectedCallback(callback func(serverName strin
810810
// callback receives the stable MCPX_* code string and is invoked
811811
// SYNCHRONOUSLY at the classification site (Spec 080 FR-012: the pre-churn
812812
// last_error_code must be durable before a crash can follow the
813-
// classification). The callback must be fast (sub-ms) and must not call back
814-
// into the Supervisor; anything slow or loss-tolerant (e.g. aggregate
815-
// counters) should offload to a goroutine inside the callback itself.
813+
// classification). The callback must be fast (sub-ms), must not call back
814+
// into the Supervisor, and must NOT spawn goroutines that outlive the call:
815+
// Runtime.Close relies on Supervisor.Stop() as a barrier — once Stop returns,
816+
// no callback-driven DB write may remain in flight, or it could land after
817+
// the clean-shutdown marker resolves or after the DB closes (Spec 080
818+
// FR-010).
816819
func (s *Supervisor) SetErrorCodeNotifier(fn func(code string)) {
817820
s.callbackMu.Lock()
818821
defer s.callbackMu.Unlock()

0 commit comments

Comments
 (0)