Skip to content

Commit 44290ee

Browse files
committed
fix(recovery): guard claim fan-out send on context cancellation to unblock Stop
The recovery manager fanned claims out to its worker pool with an unguarded `work <- claim` send. On shutdown the workers return from their own select on `ctx.Done()` without draining `work`, so that send blocked forever: `close(work)` was never reached, the recovery loop's deferred `wg.Done()` never ran, and `Stop()`'s `wg.Wait()` hung while holding `m.mu`, wedging every later `Start()`/`Stop()` call. Extract the fan-out into `Manager.fanOut` and guard the send on `ctx.Done()`, keeping `close(work)` and `workerWG.Wait()` on the cancellation path so no worker goroutine leaks, and surface the cancellation instead of swallowing it. Undispatched claims stay `Pending`, so the next sweep re-claims them once their lease expires and no work is lost. `fanOut` also returns the number of claims it dispatched. The sweep summary counted successes as `len(records)-failures`, which was only correct while the fan-out either completed or hung; a cancelled fan-out leaves a tail that never reaches `errCh`, so a partial sweep reported never-attempted claims as succeeded. Successes are now counted against the dispatched total and a short dispatch warns on its own. A sweep aborted by `Stop()` is an ordinary shutdown, so `recoveryLoop` logs a cancelled sweep at debug level via `logSweepError` and keeps the warning for genuine failures. Signed-off-by: AkramBitar <akram@il.ibm.com>
1 parent 04845db commit 44290ee

3 files changed

Lines changed: 172 additions & 15 deletions

File tree

docs/services/storage/recovery.md

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -170,4 +170,8 @@ All three terminal statuses (`Confirmed`, `Deleted`, `Orphan`) are excluded from
170170

171171
## Thread Safety
172172

173-
The Manager is thread-safe and can be safely started/stopped from multiple goroutines. The Handler implementation must also be thread-safe as it will be called concurrently by multiple workers.
173+
The Manager is thread-safe and can be safely started/stopped from multiple goroutines. The Handler implementation must also be thread-safe as it will be called concurrently by multiple workers.
174+
175+
## Shutdown Behaviour
176+
177+
`Stop()` cancels the manager context and waits for the recovery loop to return. If a sweep is mid-batch, the fan-out to the worker pool aborts on cancellation: workers stop after their in-flight `Handler.Recover()` call and any claims not yet dispatched are simply left undispatched. Those rows keep their `Pending` status, so they become eligible again once their lease (`leaseDuration`) expires and are picked up by the next sweep — on this or another replica. The aborted sweep reports a `recovery fan-out cancelled` error. Because this is an ordinary shutdown rather than a failure, the loop logs it at debug level and only warns for genuine sweep errors. The sweep summary counts successes against the claims actually dispatched, so a partial sweep logs `claimed=N, dispatched=M, ...` at warn level instead of crediting the undispatched tail as succeeded.

token/services/storage/services/recovery/manager.go

Lines changed: 65 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -162,7 +162,7 @@ func (m *Manager) recoveryLoop() {
162162
}
163163

164164
if err := m.runSweep(m.ctx); err != nil {
165-
m.logger.Warnf("initial transaction recovery sweep failed: %v", err)
165+
m.logSweepError("initial transaction recovery sweep", err)
166166
}
167167

168168
for {
@@ -173,12 +173,28 @@ func (m *Manager) recoveryLoop() {
173173
return
174174
case <-ticker.C:
175175
if err := m.runSweep(m.ctx); err != nil {
176-
m.logger.Warnf("transaction recovery sweep failed: %v", err)
176+
m.logSweepError("transaction recovery sweep", err)
177177
}
178178
}
179179
}
180180
}
181181

182+
// logSweepError reports a sweep that returned an error.
183+
//
184+
// A sweep aborted because Stop cancelled the manager context is an ordinary
185+
// shutdown rather than a failure, so it is logged at debug level: the fan-out
186+
// surfaces the cancellation as an error to keep the undispatched claims visible
187+
// to the caller, and warning about it would flag a healthy node shutdown.
188+
func (m *Manager) logSweepError(what string, err error) {
189+
if errors.Is(err, context.Canceled) {
190+
m.logger.Debugf("%s stopped: %v", what, err)
191+
192+
return
193+
}
194+
195+
m.logger.Warnf("%s failed: %v", what, err)
196+
}
197+
182198
func (m *Manager) validateConfig() error {
183199
switch {
184200
case m.config.TTL <= 0:
@@ -248,16 +264,7 @@ func (m *Manager) recoverTransactions(ctx context.Context) error {
248264
go m.worker(ctx, &workerWG, work, errCh)
249265
}
250266

251-
// ClaimPendingTransactions reads directly from the requests table where
252-
// tx_id is the primary key, so each claim is already unique. Fan out
253-
// straight to the workers; nil entries are defensive but should never
254-
// occur in practice.
255-
for _, claim := range records {
256-
if claim == nil {
257-
continue
258-
}
259-
work <- claim
260-
}
267+
dispatched, fanOutErr := m.fanOut(ctx, records, work)
261268
close(work)
262269

263270
workerWG.Wait()
@@ -277,15 +284,59 @@ func (m *Manager) recoverTransactions(ctx context.Context) error {
277284
}
278285
}
279286

280-
if failures > 0 {
281-
m.logger.Warnf("completed recovery sweep: claimed=%d, succeeded=%d, failed=%d", len(records), len(records)-failures, failures)
287+
// Successes are counted against what the fan-out actually dispatched, not
288+
// against len(records): a cancelled fan-out leaves the tail undispatched,
289+
// and those claims never reach errCh. Attributing them to len(records)-failures
290+
// would report never-attempted work as succeeded.
291+
if failures > 0 || dispatched < len(records) {
292+
m.logger.Warnf("completed recovery sweep: claimed=%d, dispatched=%d, succeeded=%d, failed=%d",
293+
len(records), dispatched, dispatched-failures, failures)
282294
} else {
283295
m.logger.Debugf("completed recovery sweep: claimed=%d, all succeeded", len(records))
284296
}
285297

298+
if fanOutErr != nil {
299+
return errors.Join(fanOutErr, firstErr)
300+
}
301+
286302
return firstErr
287303
}
288304

305+
// fanOut dispatches the claimed records to the worker pool.
306+
//
307+
// ClaimPendingTransactions reads directly from the requests table where tx_id
308+
// is the primary key, so each claim is already unique. Fan out straight to the
309+
// workers; nil entries are defensive but should never occur in practice.
310+
//
311+
// The send is guarded on ctx.Done() because the workers return from their own
312+
// select as soon as the context is cancelled, without draining what is left in
313+
// work. An unguarded send would then block forever with no receiver, so
314+
// close(work) and the deferred wg.Done() of the recovery loop would never run
315+
// and Stop's wg.Wait() would hang while holding m.mu, wedging every later
316+
// Start/Stop call.
317+
//
318+
// It returns the number of claims actually handed to a worker. Callers need
319+
// this to report the sweep outcome: claims left undispatched by a cancellation
320+
// never reach errCh, so they cannot be inferred from the failure count.
321+
func (m *Manager) fanOut(ctx context.Context, records []*ttxdb.RecoveryClaim, work chan<- *ttxdb.RecoveryClaim) (int, error) {
322+
dispatched := 0
323+
for i, claim := range records {
324+
if claim == nil {
325+
continue
326+
}
327+
select {
328+
case work <- claim:
329+
dispatched++
330+
case <-ctx.Done():
331+
m.logger.Debugf("recovery fan-out cancelled: %d of %d claim(s) not dispatched", len(records)-i, len(records))
332+
333+
return dispatched, errors.Wrapf(ctx.Err(), "recovery fan-out cancelled")
334+
}
335+
}
336+
337+
return dispatched, nil
338+
}
339+
289340
func (m *Manager) worker(ctx context.Context, wg *sync.WaitGroup, work <-chan *ttxdb.RecoveryClaim, errCh chan<- error) {
290341
defer wg.Done()
291342

token/services/storage/services/recovery/manager_test.go

Lines changed: 102 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,10 @@ SPDX-License-Identifier: Apache-2.0
77
package recovery_test
88

99
import (
10+
"context"
1011
"errors"
12+
"strconv"
13+
"sync"
1114
"testing"
1215
"time"
1316

@@ -306,6 +309,105 @@ func TestManager_NoPromotionWhenGracePeriodDisabled(t *testing.T) {
306309
assert.Equal(t, 0, mockDB.SetStatusCallCount(), "grace period disabled should never call SetStatus")
307310
}
308311

312+
// TestManager_StopDuringFanOutDoesNotDeadlock walks the exact failure scenario
313+
// reported in issue #2038, step by step:
314+
//
315+
// 1. recoveryLoop's goroutine is mid-fan-out, with claims still queued to send
316+
// to work — forced here by returning 64 claims to a single worker that is
317+
// parked inside Recover, so the unbuffered send has no receiver.
318+
// 2. Stop() cancels m.ctx — called from a goroutine so the test can observe it
319+
// hanging instead of hanging with it.
320+
// 3. All WorkerCount workers observe ctx.Done() in their select and exit before
321+
// draining the remaining items from work — the worker is released after the
322+
// cancellation, so both its select arms are ready and it takes ctx.Done().
323+
// 4. The fan-out loop's next `work <- claim` send now has no receiver and, when
324+
// unguarded, blocks forever.
325+
// 5. That send sits in the goroutine wg.Done() is deferred on, so the deferred
326+
// call never runs.
327+
// 6. Stop()'s m.wg.Wait() — held under m.mu — hangs indefinitely, and every
328+
// later Start()/Stop() deadlocks on m.mu; asserted by the final restart.
329+
//
330+
// Verified to fail (10s timeout at step 6) against the unguarded send and to
331+
// pass with the ctx.Done()-guarded fan-out.
332+
func TestManager_StopDuringFanOutDoesNotDeadlock(t *testing.T) {
333+
logger := logging.MustGetLogger()
334+
mockDB := &mock2.Storage{}
335+
mockHandler := &mock2.Handler{}
336+
config := recovery2.Config{
337+
Enabled: true,
338+
TTL: 10 * time.Millisecond,
339+
ScanInterval: 10 * time.Millisecond,
340+
BatchSize: 100,
341+
WorkerCount: 1,
342+
LeaseDuration: time.Second,
343+
AdvisoryLockID: 1,
344+
InstanceID: "test-instance",
345+
}
346+
347+
// Step 1: many more claims than workers, so the fan-out loop is guaranteed to
348+
// still have undispatched claims when the context is cancelled. 64 also makes
349+
// it statistically certain (1 - 2^-63) that the worker's select picks
350+
// ctx.Done() before draining the batch on its own.
351+
const claimCount = 64
352+
records := make([]*ttxdb.RecoveryClaim, claimCount)
353+
for i := range records {
354+
records[i] = &ttxdb.RecoveryClaim{TxID: "tx" + strconv.Itoa(i)}
355+
}
356+
357+
leadership := &mock2.Leadership{}
358+
leadership.CloseReturns(nil)
359+
mockDB.AcquireRecoveryLeadershipReturns(leadership, true, nil)
360+
mockDB.ClaimPendingTransactionsReturns(records, nil)
361+
mockDB.ReleaseRecoveryClaimReturns(nil)
362+
363+
var once sync.Once
364+
inWorker := make(chan struct{})
365+
release := make(chan struct{})
366+
mockHandler.RecoverStub = func(_ context.Context, _ string) error {
367+
// Hold the single worker inside Recover so the fan-out loop is parked
368+
// on its send, then let it go only after Stop() cancelled the context.
369+
once.Do(func() {
370+
close(inWorker)
371+
<-release
372+
})
373+
374+
return nil
375+
}
376+
377+
manager := recovery2.NewManager(logger, mockDB, mockHandler, config)
378+
require.NoError(t, manager.Start())
379+
380+
select {
381+
case <-inWorker:
382+
case <-time.After(10 * time.Second):
383+
t.Fatal("timed out waiting for the recovery sweep to reach a worker")
384+
}
385+
386+
// Step 2: cancel m.ctx via Stop() while the fan-out is parked on its send.
387+
stopped := make(chan error, 1)
388+
go func() {
389+
stopped <- manager.Stop()
390+
}()
391+
392+
// Step 3: let Stop() cancel the context first, then unblock the worker so it
393+
// returns to its select with both ctx.Done() and the fan-out send ready.
394+
time.Sleep(50 * time.Millisecond)
395+
close(release)
396+
397+
// Steps 4-5-6: with the unguarded send this never returns.
398+
select {
399+
case err := <-stopped:
400+
require.NoError(t, err)
401+
case <-time.After(10 * time.Second):
402+
t.Fatal("Stop() deadlocked while the sweep was fanning out claims")
403+
}
404+
405+
// Step 6, second half: the manager must not be wedged — m.mu was released, so
406+
// a subsequent Start()/Stop() pair still works.
407+
require.NoError(t, manager.Start())
408+
require.NoError(t, manager.Stop())
409+
}
410+
309411
func TestDefaultConfig(t *testing.T) {
310412
config := recovery2.DefaultConfig()
311413

0 commit comments

Comments
 (0)