Skip to content

Commit 7450621

Browse files
committed
fix(auditdb): correct locker reconciliation, classification and cleanup
Review follow-up on the #2040 fix. Seven defects, each with a regression test verified to fail without the corresponding change. In-memory locker: - The idempotent-re-acquire reconciliation was a read-modify-write over two lock-free sync.Maps. Concurrent callers narrowing an anchor's ID set all read the same stale record, all concluded the same ID was stale, and all released its permit; x/sync/semaphore panics on over-release, so the previous change traded the type-assertion panic it fixed for a new one ("semaphore: released more than held"). Reconciliation now runs under a per-anchor lock. A single lock for the whole Locker would deadlock, 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 one entry per audited transaction. - An empty re-acquire recorded the empty set, releasing the locks the anchor already held while returning nil: the caller kept believing it held them and another anchor could take them immediately. Acquiring nothing now leaves the anchor untouched, as the distributed locker already did. - ErrLockContention was attached to every failed acquisition, so cancelling a request on a completely free ID was reported and counted as a lock conflict. The permit is now tried before blocking on it, so the sentinels are attached only when the ID was genuinely held. Postgres locker: - The outcome was classified by which context expired first. acquireDeadline defaults to a minute, so a request-scoped caller context is nearly always shorter, and a caller-driven timeout returned a bare context.DeadlineExceeded with no sentinel — this backend hardly ever reported contention in production while the in-memory one always did. Classification is now based on whether an attempt actually lost a race. - A query killed by the acquire deadline carries context.DeadlineExceeded, so a database outage was relabelled as contention with the original error discarded, and isRetriableLockError then refused to retry it. The underlying error is always joined in, and ErrLockAcquireTimeout is attached only when the waiting budget is genuinely spent. - The cleanup DELETE ran on a context that could neither be cancelled nor time out, so it could block indefinitely on a saturated connection pool or a conflicting row lock — leaving AcquireLocks hanging past the deadline it promises to honour and leaking the goroutine on shutdown. releaseAnchor now detaches and bounds, which also stops ReleaseLocks silently skipping the delete on an already-cancelled context and stranding leases until TTL. - A failed re-acquire released the anchor unconditionally, deleting the lease rows of the live session it was re-acquiring for while leaving that session's record and heartbeat running; the next renewal reported the leases lost and the caller's next legitimate Append failed its pre-write assertion. Cleanup runs only when the anchor has no live session. The conformance suite gave the Postgres locker a 300ms acquire deadline, shorter than its own wait contexts, which masked the misclassification above; it now uses a production-shaped deadline. Signed-off-by: AkramBitar <akram@il.ibm.com>
1 parent bf27a8f commit 7450621

8 files changed

Lines changed: 648 additions & 79 deletions

File tree

docs/services/auditor.md

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,23 @@ Both backends implement the same contract, defined on the `Locker` interface, be
7070

7171
**`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.
7272

73+
**`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.
74+
75+
**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.
76+
77+
### Error classification
78+
79+
Callers act on the outcome of a failed acquisition, so both backends classify it the same way:
80+
81+
| Outcome | Sentinels | Meaning |
82+
|---------|-----------|---------|
83+
| 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 |
84+
| 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 |
85+
| 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 |
86+
| The database failed | neither; the underlying error is preserved | An infrastructure fault, reported as itself rather than as contention |
87+
88+
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.
89+
7390
### Configuration
7491

7592
Configure under `token.tms.<name>.auditor.locker` (see [Configuration](../configuration.md#optional-tokentmsauditorlocker)):

plan.md

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,54 @@ Fix the three findings in issue #2040 in `token/services/storage/auditdb/locker`
4545
`auditor.lock` and `auditor.locker`).
4646
8. [x] **Done**`make unit-tests`, `make unit-tests-race` on the touched packages,
4747
`make lint-auto-fix`, `make checks`.
48+
9. [x] **Done** — Review round: fixed seven defects found in steps 3–5, each with a test that
49+
fails without the fix (see "Review findings" below).
50+
51+
## Review findings addressed
52+
53+
The first pass fixed the three findings in #2040 but introduced or left seven defects of its
54+
own. All seven are fixed, and every one has a regression test verified to fail on the
55+
pre-review code.
56+
57+
1. **New panic in the in-memory locker (critical).** The idempotent-re-acquire reconciliation
58+
was a read-modify-write over two lock-free `sync.Map`s: concurrent callers narrowing an
59+
anchor's ID set all read the same stale record, all concluded the same ID was stale, and
60+
all released its permit. `golang.org/x/sync/semaphore` panics on over-release, so this
61+
traded the type-assertion panic being fixed for a new one. Reproduced as
62+
`panic: semaphore: released more than held`. Fixed with per-anchor locking (`anchorState`),
63+
which makes the reconciliation atomic; a single lock for the whole `Locker` would deadlock,
64+
since `AcquireLocks` blocks on permits that another anchor's release must hand over.
65+
Anchor states are reference-counted and evicted so the map does not grow per transaction.
66+
2. **Empty re-acquire released the anchor's locks (high).** No early return for an empty set,
67+
so `AcquireLocks(ctx, "a")` after `AcquireLocks(ctx, "a", "alice")` recorded the empty set,
68+
released alice and returned `nil`. Exclusivity was gone with no error anywhere, and it was a
69+
fresh divergence — the Postgres locker returns early.
70+
3. **Postgres almost never reported contention (high).** The outcome was classified by which
71+
context expired first. `acquireDeadline` defaults to 1 minute, so a request-scoped caller
72+
context is nearly always shorter, and a caller-driven timeout returned a bare
73+
`context.DeadlineExceeded` with no sentinel. Now classified by whether an attempt actually
74+
lost a race. `conformance_test.go` had masked this by giving the Postgres locker a 300 ms
75+
deadline — shorter than the test's own wait — so the conformance locker now uses a
76+
production-shaped 30 s deadline instead.
77+
4. **Unbounded cleanup context (medium).** `context.WithoutCancel(ctx)` has no deadline, so the
78+
cleanup `DELETE` could block indefinitely on a saturated pool or a conflicting row lock —
79+
leaving `AcquireLocks` hanging past the deadline it promises and leaking the goroutine on
80+
shutdown. `releaseAnchor` now detaches *and* bounds (`releaseTimeout`), which also fixes
81+
`ReleaseLocks` silently skipping the delete on an already-cancelled context.
82+
5. **Database failures relabelled as contention (medium).** A query killed by `acquireCtx` has
83+
`context.DeadlineExceeded` in its chain, so an outage was reported as `ErrLockContention`
84+
with the original error discarded — and `isRetriableLockError` then refused to retry it. The
85+
underlying error is now always joined in, and `ErrLockAcquireTimeout` is attached only when
86+
the waiting budget is genuinely spent.
87+
6. **Cancellation reported as contention (low).** `acquireError` attached `ErrLockContention`
88+
unconditionally, so a shutdown cancellation on a completely free ID came back as a lock
89+
conflict — the mirror image of finding 3's divergence. The sentinels are now attached only
90+
when the ID was actually held, established by trying the permit before blocking on it.
91+
7. **Failed re-acquire tore down a live session (low).** The failure path released the anchor
92+
unconditionally, deleting the lease rows of the live session it was re-acquiring for while
93+
leaving that session's record and heartbeat running; the next renewal reported the leases
94+
lost and the caller's next legitimate `Append` failed its pre-write assertion. Cleanup now
95+
runs only when the anchor has no live session.
4896

4997
## Notes & Decisions
5098

token/services/storage/auditdb/locker/conformance_test.go

Lines changed: 74 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -68,11 +68,18 @@ func newPostgresLocker(t *testing.T) locker.Locker {
6868
_, _ = db.Exec("DROP TABLE IF EXISTS " + table)
6969
t.Cleanup(func() { _, _ = db.Exec("DROP TABLE IF EXISTS " + table) })
7070

71+
// AcquireDeadline is deliberately far longer than any context the cases below
72+
// pass in, because that is the production shape: it defaults to a minute, so a
73+
// request-scoped caller context is nearly always the shorter of the two. A
74+
// deadline shorter than the caller's would let this backend pass the contention
75+
// case for the wrong reason — the failure would be attributed to a budget this
76+
// locker had spent itself, hiding that a caller-driven timeout reported no
77+
// sentinel at all.
7178
l, err := lockerpostgres.New(db, table, lockerpostgres.Config{
7279
TTL: 30 * time.Second,
7380
Heartbeat: 10 * time.Second,
7481
AcquireBackoff: 10 * time.Millisecond,
75-
AcquireDeadline: 300 * time.Millisecond,
82+
AcquireDeadline: 30 * time.Second,
7683
Owner: "conformance-owner",
7784
}, stubReplicaID{id: "conformance-owner"})
7885
require.NoError(t, err)
@@ -200,6 +207,13 @@ func TestConformance_ReacquireSameAnchorIsIdempotent(t *testing.T) {
200207
// in a way callers can classify. auditor.Service inspects these sentinels to
201208
// decide whether retrying can help, so a backend that reports contention as a
202209
// bare context error is not interchangeable with one that does not.
210+
//
211+
// The caller's context here is much shorter than the Postgres backend's
212+
// AcquireDeadline, which is the production shape and the case that used to be
213+
// misclassified: that backend decided what to report from whichever context
214+
// expired first, so a caller-driven timeout returned a bare
215+
// context.DeadlineExceeded with no sentinel while the in-memory locker reported
216+
// contention for the identical situation.
203217
func TestConformance_ContentionIsReported(t *testing.T) {
204218
for _, b := range backends() {
205219
t.Run(b.name, func(t *testing.T) {
@@ -208,14 +222,72 @@ func TestConformance_ContentionIsReported(t *testing.T) {
208222
require.NoError(t, l.AcquireLocks(ctx, "holder", "alice"))
209223
t.Cleanup(func() { l.ReleaseLocks(ctx, "holder") })
210224

211-
waitCtx, cancel := context.WithTimeout(ctx, time.Second)
225+
waitCtx, cancel := context.WithTimeout(ctx, 400*time.Millisecond)
212226
defer cancel()
213227
err := l.AcquireLocks(waitCtx, "waiter", "alice")
214228

215229
require.Error(t, err, "a lock held by another anchor must not be acquirable")
216230
require.ErrorIs(t, err, errs.ErrLockContention)
217231
require.ErrorIs(t, err, errs.ErrLockAcquireTimeout,
218232
"having spent the whole waiting budget must be distinguishable from plain contention")
233+
234+
// The holder keeps its lock: a failed acquisition takes nothing away.
235+
require.NoError(t, l.AssertLocksHeld(ctx, "holder"))
236+
})
237+
}
238+
}
239+
240+
// TestConformance_EmptyReacquireKeepsHeldLocks pairs with EmptyEnrollmentIDs:
241+
// acquiring nothing succeeds, and must also leave alone whatever the anchor
242+
// already holds. The in-memory locker used to record the empty set instead, which
243+
// released those locks while returning nil — the caller kept believing it held
244+
// them and another anchor could take them immediately, with no error anywhere.
245+
// The Postgres locker returns early, so this was a divergence too.
246+
func TestConformance_EmptyReacquireKeepsHeldLocks(t *testing.T) {
247+
for _, b := range backends() {
248+
t.Run(b.name, func(t *testing.T) {
249+
l := b.new(t)
250+
ctx := context.Background()
251+
252+
require.NoError(t, l.AcquireLocks(ctx, "anchor1", "alice"))
253+
require.NoError(t, l.AcquireLocks(ctx, "anchor1"), "acquiring nothing must succeed")
254+
require.NoError(t, l.AssertLocksHeld(ctx, "anchor1"), "the anchor still holds alice")
255+
256+
waitCtx, cancel := context.WithTimeout(ctx, 300*time.Millisecond)
257+
defer cancel()
258+
require.Error(t, l.AcquireLocks(waitCtx, "anchor2", "alice"),
259+
"an empty re-acquisition must not hand alice to another anchor")
260+
261+
l.ReleaseLocks(ctx, "anchor1")
262+
require.NoError(t, l.AcquireLocks(ctx, "anchor2", "alice"),
263+
"releasing the anchor must still release alice")
264+
l.ReleaseLocks(ctx, "anchor2")
265+
})
266+
}
267+
}
268+
269+
// TestConformance_CancelledCallerIsNotContention is the mirror image of
270+
// ContentionIsReported: a failure with no other holder involved must not be
271+
// dressed up as a lock conflict. The in-memory locker attached ErrLockContention
272+
// to every failed acquisition, so graceful-shutdown cancellations were reported
273+
// and counted as conflicts, while Postgres returned a plain context error.
274+
func TestConformance_CancelledCallerIsNotContention(t *testing.T) {
275+
for _, b := range backends() {
276+
t.Run(b.name, func(t *testing.T) {
277+
l := b.new(t)
278+
cancelled, cancel := context.WithCancel(context.Background())
279+
cancel()
280+
281+
err := l.AcquireLocks(cancelled, "anchor1", "alice")
282+
require.Error(t, err, "a caller that has given up must not be granted locks")
283+
require.ErrorIs(t, err, context.Canceled)
284+
require.NotErrorIs(t, err, errs.ErrLockContention,
285+
"nothing held alice, so the failure is the caller's own cancellation")
286+
287+
// The failed call retained nothing, so alice is still free.
288+
ctx := context.Background()
289+
require.NoError(t, l.AcquireLocks(ctx, "anchor2", "alice"))
290+
l.ReleaseLocks(ctx, "anchor2")
219291
})
220292
}
221293
}

0 commit comments

Comments
 (0)