Skip to content

Commit cdf55b8

Browse files
committed
fix(auditdb): align locker semantics across backends
The auditor takes short-lived locks on the enrollment IDs a request touches, through a Locker chosen from configuration: memory for a single replica, postgres for a cluster. The two were not interchangeable, so the same auditor code was correct on one deployment and broken on the other. Issue #2040 found three symptoms: - Postgres returned ErrLockNotHeld for any anchor without a session, so AssertLocksHeld conflated "lost the locks I took" with "never took any". StoreService.Append calls it on every write, so a request whose inputs and outputs yield no enrollment IDs could never be appended — and nor could an auditor that validates and appends without calling Audit, as the dvp and nft views do. - The in-memory locker kept enrollment-ID semaphores and per-anchor ID lists in one sync.Map. Both are keyed by unconstrained strings of unrelated provenance, so an anchor equal to an enrollment ID made a lookup return the other namespace's value type, and the unchecked type assertion on it panicked. - auditor.Service retried AcquireLocks up to MaxRetries times around the Postgres locker's own AcquireDeadline wait, so the two loops multiplied: worst case ten minutes of blocking for a single audit, polled at a flat, un-jittered interval that kept contending replicas in lockstep. The contract, and the fix: - The Locker interface now states the contract its implementations are held to. It had no documentation at all, which is how they drifted. AssertLocksHeld detects lost locks, not absent ones. AcquireLocks is all-or-nothing, treats an empty set as a successful acquisition of nothing, and is idempotent under a live anchor. conformance_test.go runs the shared expectations against every backend. - The in-memory locker splits the two key namespaces into separate maps, so the collision is impossible by construction rather than by convention. Reconciliation on re-acquisition runs under a per-anchor lock: it is a read-modify-write of the anchor's record, and done lock-free, two concurrent callers narrowing the set both release the same permit — which panics golang.org/x/sync/semaphore rather than being a no-op. One lock for the whole Locker would deadlock instead, since AcquireLocks blocks on permits another anchor's release must hand over. Anchor states are reference-counted and evicted, so the map does not grow by an entry per audited transaction. - The Postgres locker does all the waiting itself, with jittered exponential backoff bounded by one derived context, and auditor.Service no longer retries an error carrying ErrLockAcquireTimeout. Worst case is now about one AcquireDeadline, at a few dozen round trips rather than hundreds. AcquireMaxBackoff (default 2s) caps the growth. - Failure classification is based on whether an attempt actually lost a race for an ID, not on which context expired first. AcquireDeadline defaults to a minute, so a request-scoped caller context is nearly always the shorter of the two, and keying off it meant Postgres hardly ever reported contention in production while memory always did. The underlying error is always joined in, so a database outage is reported as itself instead of being relabelled as contention with its details discarded. Conversely, a caller's own cancellation on a free ID is no longer reported as a conflict. - releaseAnchor detaches from the caller's context, so a deferred release on an already-cancelled context still runs instead of stranding leases until their TTL, and bounds itself so a stuck DELETE cannot block past the deadline AcquireLocks promises to honour. A failed re-acquisition no longer releases an anchor that already holds a live session, which used to delete that session's leases while its heartbeat kept running and fail the caller's next legitimate Append with "locks lost before write". Fixes #2040 Signed-off-by: AkramBitar <akram@il.ibm.com>
1 parent 3552482 commit cdf55b8

12 files changed

Lines changed: 1460 additions & 132 deletions

File tree

docs/configuration.md

Lines changed: 21 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -323,9 +323,16 @@ token:
323323
postgres:
324324
# ttl is the lease duration for each EID lock row.
325325
ttl: 30s
326-
# acquireBackoff is the wait between retry attempts when a lock is contended.
326+
# acquireBackoff is the initial wait between retry attempts when a lock
327+
# is contended. Successive waits grow exponentially and are jittered,
328+
# so this is the floor rather than a fixed poll interval.
327329
acquireBackoff: 100ms
328-
# acquireDeadline is the total time allowed to acquire all EID locks.
330+
# acquireMaxBackoff caps that growth. Raised to acquireBackoff if set
331+
# below it.
332+
acquireMaxBackoff: 2s
333+
# acquireDeadline is the total time allowed to acquire all EID locks,
334+
# and the whole budget for waiting out contention: auditor.lock does
335+
# not retry an acquisition that already exhausted it.
329336
acquireDeadline: 1m
330337
# heartbeat is the interval at which held leases are renewed (~TTL/3).
331338
heartbeat: 10s
@@ -810,6 +817,14 @@ Default values:
810817
- **backoffMultiplier**: Factor by which the backoff delay increases after each retry (exponential growth)
811818
- **jitterFactor**: Randomization factor (0.0 to 1.0) added to backoff delays to prevent multiple auditors from retrying simultaneously (prevents thundering herd problem)
812819

820+
**Relationship to `auditor.locker`:** this retry covers failures that another attempt
821+
might survive, such as a transient database error. It deliberately does **not** retry
822+
an acquisition that failed with `ErrLockAcquireTimeout`, because that means the locker
823+
already spent its own `acquireDeadline` waiting out the contention — retrying would
824+
spend it again. Waiting under contention is configured once, in
825+
[`auditor.locker`](#optional-tokentmsauditorlocker), so `maxRetries` here does not
826+
multiply `acquireDeadline` there.
827+
813828
**Tuning Recommendations:**
814829

815830
1. **For High-Contention Environments:**
@@ -924,6 +939,7 @@ token:
924939
postgres:
925940
ttl: 30s
926941
acquireBackoff: 100ms
942+
acquireMaxBackoff: 2s
927943
acquireDeadline: 1m
928944
heartbeat: 10s
929945
owner:
@@ -933,8 +949,9 @@ Default values:
933949

934950
- backend: `memory` (in-process mutex, single-replica only)
935951
- postgres.ttl: 30s
936-
- postgres.acquireBackoff: 100ms
937-
- postgres.acquireDeadline: 1m
952+
- postgres.acquireBackoff: 100ms (initial wait; grows exponentially, jittered)
953+
- postgres.acquireMaxBackoff: 2s (cap on that growth; raised to `acquireBackoff` if set below it)
954+
- postgres.acquireDeadline: 1m (the whole budget for waiting out contention)
938955
- postgres.heartbeat: 10s
939956
- postgres.owner: empty, defaults to the FSC node ID (`config.Provider.ID()`). Required
940957
when `backend: postgres` — if both this value and `fsc.id` are empty or blank, the

docs/services/auditor.md

Lines changed: 30 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -83,6 +83,27 @@ When multiple auditor replicas share the same AuditDB (PostgreSQL), concurrent p
8383

8484
The locker is injected into `auditdb.StoreService` at startup. Before appending audit records, the store calls `AssertLocksHeld` to verify leases are still valid.
8585

86+
Both backends implement the same contract, defined on the `Locker` interface, because the backend is chosen from configuration — a behavioural difference between them would be a correctness difference between two deployments running the same code. The shared expectations are exercised against every backend by `locker/conformance_test.go`.
87+
88+
**`AssertLocksHeld` detects lost locks, not absent ones.** It fails only when a lease this replica held has since expired or been taken over. An anchor that holds nothing succeeds — whether because the request yielded no enrollment IDs, or because the caller never locked anything for it. The latter is a supported flow: an auditor may call `Validate` (which takes no locks) and then `Append`, as the dvp and nft sample views do.
89+
90+
**`AcquireLocks` is all-or-nothing, and never gives up ground.** A failed call holds none of the EIDs it had reached for, and leaves untouched whatever the anchor already held from an earlier successful call. Re-acquiring under a live anchor is a refresh: the EIDs it already holds are kept, new ones are added, and ones it no longer needs are released. Acquiring an *empty* set is a successful acquisition of nothing — it must not, and does not, release what the anchor is already holding.
91+
92+
**Release always runs.** `ReleaseLocks` is idempotent, safe on an anchor that never acquired anything, and safe to `defer`. Its statement is deliberately detached from the caller's context, since the usual case is a deferred release on a context that is already cancelled and a skipped release would leave the EIDs locked against every replica until the lease TTL expired. It carries its own short internal deadline so a stuck release cannot outlive the call that issued it.
93+
94+
### Error classification
95+
96+
Callers act on the outcome of a failed acquisition, so both backends classify it the same way:
97+
98+
| Outcome | Sentinels | Meaning |
99+
|---------|-----------|---------|
100+
| Another anchor holds an EID and the waiting budget ran out | `ErrLockContention` + `ErrLockAcquireTimeout` | A real conflict, already waited out in full; retrying only adds delay |
101+
| Another anchor holds an EID, but a transient failure or a cancelled caller ended the wait | `ErrLockContention` | A real conflict, not yet waited out; a later attempt may succeed |
102+
| The caller cancelled or ran out of time while nothing held the EIDs | neither (plain context error) | Not a conflict, and not counted as one |
103+
| The database failed | neither; the underlying error is preserved | An infrastructure fault, reported as itself rather than as contention |
104+
105+
The distinction is drawn from whether an attempt actually lost a race for an EID — not from which context expired first. `acquireDeadline` defaults to a minute, so a request-scoped caller context is almost always the shorter of the two, and keying off it would mean the Postgres backend hardly ever reported contention in production.
106+
86107
### Configuration
87108

88109
Configure under `token.tms.<name>.auditor.locker` (see [Configuration](../configuration.md#optional-tokentmsauditorlocker)):
@@ -96,8 +117,9 @@ token:
96117
backend: postgres # use "memory" (default) for single replica
97118
postgres:
98119
ttl: 30s
99-
acquireBackoff: 100ms
100-
acquireDeadline: 1m
120+
acquireBackoff: 100ms # initial wait; grows exponentially, jittered
121+
acquireMaxBackoff: 2s # cap on that growth
122+
acquireDeadline: 1m # whole budget for waiting out contention
101123
heartbeat: 10s
102124
owner: # required; defaults to the FSC node ID
103125
```
@@ -113,6 +135,12 @@ The Postgres backend creates an `eid_leases` table (prefixed per TMS persistence
113135

114136
**Lease ownership:** each row is keyed by EID and carries the holding replica (`owner`) plus the request it was taken for (`anchor`). An acquisition may only take over an existing row when the lease has expired, or when the row is the same replica's lease for the *same* anchor — a re-acquisition, which just refreshes the deadline. Two different anchors therefore never hold the same EID at once, including two concurrent audits on a single replica; the second one is contended and retried until `acquireDeadline`.
115137

138+
### Waiting under contention
139+
140+
`acquireDeadline` is the **entire** budget for waiting out a contended EID, and one layer does the waiting. Within it, the locker retries the atomic acquisition starting at `acquireBackoff`, doubling up to `acquireMaxBackoff`, with jitter on every sleep. The jitter matters as much as the growth: a fixed interval is identical on every replica, so contenders retry in lockstep and keep colliding, and at the defaults it also costs one round trip per interval for the whole deadline — hundreds per acquisition.
141+
142+
`auditor.Service` wraps `AcquireLocks` in its own retry (`token.tms.<name>.auditor.lock`) for transient failures, but it does **not** retry an error carrying `ErrLockAcquireTimeout`: the locker reporting one means it already spent `acquireDeadline`, so calling it again would spend that deadline afresh rather than improve the odds. Worst-case blocking for one audit is therefore about `acquireDeadline`, not `maxRetries × acquireDeadline`.
143+
116144
### Replica owner identity
117145

118146
Every lease row carries an `owner` column, and each replica scopes all of its lease

token/services/auditor/auditor.go

Lines changed: 27 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -193,6 +193,13 @@ func (a *Service) Audit(ctx context.Context, tx Transaction) (*token.InputStream
193193
// acquireLocksWithRetry attempts to acquire locks with exponential backoff and randomized jitter
194194
// to prevent livelock conditions when multiple auditors compete for the same enrollment IDs.
195195
// This implements the mitigation strategy for deadlock/livelock prevention.
196+
//
197+
// The locker owns the waiting policy and bounds it itself, so this loop must not
198+
// re-run an attempt that already spent that budget: an error carrying
199+
// ErrLockAcquireTimeout is final here. Retrying it anyway multiplied the locker's
200+
// deadline by MaxRetries — worst case, ten minutes of blocking for a single audit
201+
// against the Postgres backend, on top of the round trips each of those attempts
202+
// spent polling. Context errors are final for the same reason: the caller is gone.
196203
func (a *Service) acquireLocksWithRetry(ctx context.Context, anchor string, eids []string) error {
197204
// Create a retry runner with jitter support
198205
retryRunner := utils.NewRetryRunnerWithJitter(
@@ -204,18 +211,34 @@ func (a *Service) acquireLocksWithRetry(ctx context.Context, anchor string, eids
204211
a.lockConfig.JitterFactor,
205212
)
206213

207-
// Use the retry runner to acquire locks
208-
err := retryRunner.RunWithContext(ctx, func() error {
209-
return a.auditDB.AcquireLocks(ctx, anchor, eids...)
210-
})
214+
// Use the retry runner to acquire locks, stopping early on errors that another
215+
// attempt cannot improve on.
216+
err := retryRunner.RunWithErrorsContext(ctx, func() (bool, error) {
217+
err := a.auditDB.AcquireLocks(ctx, anchor, eids...)
218+
if err == nil {
219+
return true, nil
220+
}
211221

222+
return !isRetriableLockError(err), err
223+
})
212224
if err != nil {
213225
return errors.WithMessagef(err, "failed to acquire locks for anchor [%s]", anchor)
214226
}
215227

216228
return nil
217229
}
218230

231+
// isRetriableLockError reports whether re-running AcquireLocks stands a chance of
232+
// a different outcome. Most failures do — a contended lock may be free by now, a
233+
// database blip may have passed — but two do not: ErrLockAcquireTimeout means the
234+
// locker already spent its whole waiting budget, so an identical attempt would
235+
// just spend it again, and a context error means the caller is no longer waiting.
236+
func isRetriableLockError(err error) bool {
237+
return !errors.Is(err, auditdb.ErrLockAcquireTimeout) &&
238+
!errors.Is(err, context.Canceled) &&
239+
!errors.Is(err, context.DeadlineExceeded)
240+
}
241+
219242
// Append adds the passed transaction to the auditor database, reusing the
220243
// audit record computed by Audit, when available.
221244
// It also releases the locks acquired by Audit.

token/services/auditor/auditor_test.go

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1081,6 +1081,32 @@ func TestService_AcquireLocksWithRetry_Failure_MaxRetriesExceeded(t *testing.T)
10811081
assert.Equal(t, 10, mockLocker.GetCallCount(), "Should retry max times (default is 10)")
10821082
}
10831083

1084+
// TestService_AcquireLocksWithRetry_NoRetryAfterLockerTimeout covers issue
1085+
// #2040's third finding. A locker that reports ErrLockAcquireTimeout has already
1086+
// spent its own acquisition deadline waiting out the contention, so repeating the
1087+
// call spends that deadline again rather than giving the caller a fresh chance.
1088+
// This loop used to retry it MaxRetries times regardless: nested inside the
1089+
// Postgres locker's one-minute deadline that meant up to ten minutes of blocking
1090+
// for a single audit, and thousands of database round trips.
1091+
func TestService_AcquireLocksWithRetry_NoRetryAfterLockerTimeout(t *testing.T) {
1092+
mockLocker := newMockAuditLocker(func(ctx context.Context, anchor string, eIDs ...string) error {
1093+
return errors.Join(auditdb.ErrLockAcquireTimeout, auditdb.ErrLockContention)
1094+
})
1095+
svc := newTestServiceWithMockLocker(t, mockLocker)
1096+
1097+
_, _, err := svc.Audit(context.Background(), &auditmock.Transaction{
1098+
IDStub: func() string { return "tx-lock-timeout" },
1099+
RequestStub: func() *token.Request {
1100+
return token.NewRequest(newTestManagementService(t), token.RequestAnchor("tx-lock-timeout"))
1101+
},
1102+
})
1103+
1104+
require.Error(t, err)
1105+
require.ErrorIs(t, err, auditdb.ErrLockAcquireTimeout, "the locker's verdict must reach the caller intact")
1106+
assert.Equal(t, 1, mockLocker.GetCallCount(),
1107+
"a locker that already exhausted its acquire deadline must not be called again")
1108+
}
1109+
10841110
func TestService_AcquireLocksWithRetry_ContextCancelled_BeforeRetry(t *testing.T) {
10851111
// Mock locker that always fails
10861112
mockLocker := newMockAuditLocker(func(ctx context.Context, anchor string, eIDs ...string) error {

0 commit comments

Comments
 (0)