fix(acl): make the API-key store deadline a HARD race (R3-05 S18 live-gate failure)

BoundedApiKeyStore bounded ConfigDbApiKeyStore with a
CancellationTokenSource(TimeSpan, TimeProvider) linked into the inner call. That
bounds the call only if the callee chooses to observe the token, and
Microsoft.Data.SqlClient does not while a connect/login is in flight on a
black-holed socket. The 2026-08-20 live gate paused the SQL container and watched
a keyed activation hang 42.9 s past its 2000 ms bound — the "did not answer
within 2000 ms" Warning fired only at unpause — and because this runs inside the
SDK's synchronous SessionManager-lock-holding impersonation callback, an
unrelated already-open subscription stalled 57 s behind it. That is precisely the
hazard the bound exists to prevent, and the TTL cache cannot help a miss.

BoundAsync now races the inner call against Task.Delay on the injected clock with
Task.WhenAny. Inner wins: stop the timer, await it, faults and genuine caller
cancellation propagate unchanged. Delay wins: cancel the linked token anyway (a
cooperative inner store should still stop), hand the abandoned task to
ObserveAbandoned, meter outcome=timeout, log the now-honest Warning, and throw
OperationCanceledException — the same exception the authenticator's catch-all
already maps to the standard opaque denial. Fail-closed is unchanged: nothing
here can admit.

ObserveAbandoned disposes the CTS and TOUCHES finished.Exception (the observation
itself), so a late SqlClient fault can never become an UnobservedTaskException.
Debug, not Warning — the timeout is already reported at Warning, and an outage
must not produce two lines per activation for one event.

An abandoned answer is NEVER cached: it was taken before the deadline and would
be served after it, so a key revoked or expired in the meantime could be admitted
from a lookup nobody was still waiting for. StoreTimeoutMs <= 0 still
short-circuits to the unbounded call byte-for-byte (the documented rollback).

RED BEFORE GREEN. Every pre-existing deadline test drives GatedApiKeyStore, whose
waits take the token, so a cooperative CancelAfter unblocks them and all 15
passed against the defective build — the suite could not see the gate's failure
at all. The new UncooperativeApiKeyStore ignores ct entirely and completes only
when the test releases it. Against the unmodified store the three new tests fail
3/18 with "should throw OperationCanceledException but threw TimeoutException"
under a test-side WaitAsync(2 s), so the red is a failure and not a hang — and
that exception swap IS the finding restated as an assertion.

Host.Tests 137/137.
This commit is contained in:
Joseph Doherty
2026-08-20 13:29:21 -04:00
parent 9242630c98
commit c657b2e03d
3 changed files with 337 additions and 23 deletions
+15
View File
@@ -214,6 +214,21 @@ with two `Security:ApiKeys` knobs:
| `StoreTimeoutMs` | `2000` | Hard per-call deadline on the store. Exceeding it **denies** the activation. `≤ 0` disables the deadline (the pre-R3-05 unbounded behaviour — do not do this on an admin node). |
| `StoreCacheSeconds` | `5` | TTL of a read-through cache in front of the store, so a burst of activations costs one round trip. `0` disables it (a read per activation). |
- ⚠️ **The deadline is a HARD race, not a cooperative token — and the difference was a live-gate
failure.** It was originally a `CancellationTokenSource(TimeSpan, TimeProvider)` linked into the inner
call, which bounds the call only if the callee chooses to observe the token.
`Microsoft.Data.SqlClient` does not, while a connect or login is in flight on a black-holed socket: the
2026-08-20 R3-05 gate paused the SQL container and watched a keyed activation hang **42.9 s** past its
2000 ms bound (the Warning below fired only at unpause), stalling an unrelated already-open
subscription **57 s** behind the `SessionManager` lock. `BoundedApiKeyStore` now races the inner call
against a `Task.Delay` on the injected clock and returns control the moment the delay wins.
- **An abandoned lookup runs on, and its answer is discarded.** Nothing can cancel a SqlClient call that
is not listening, so the query may still complete (or fault) in the background long after the
activation was denied. Its result is **never** cached — it was taken before the deadline and would be
served after it, so a key revoked or expired in the meantime could be admitted from a lookup nobody
was still waiting for. The token is still cancelled, so a *cooperative* inner store does stop, and the
abandoned task's outcome is observed and logged at Debug (*"an abandoned key store lookup finished /
faulted after its deadline; discarded"*) so it can never surface as an `UnobservedTaskException`.
- **A timeout denies; it never admits.** The deadline surfaces as an `OperationCanceledException` into
`ApiKeyOpcUaUserAuthenticator`'s existing catch-all, which returns the same opaque denial as a bad
credential. There is no second denial path to get wrong, and the decorator can only ever return what
@@ -27,10 +27,12 @@ namespace ZB.MOM.WW.OtOpcUa.Host.OpcUa;
/// decorator can only return what the inner store returned, or throw.
/// </para>
/// <para>
/// ⚠️ <b>Faults and timeouts are NEVER cached.</b> Caching a deny would be fail-closed and is
/// still wrong: it would extend a ConfigDb outage past the outage, denying valid keys for a
/// further TTL after the database came back. Only a COMPLETED lookup — a hit or an authoritative
/// miss — is stored.
/// ⚠️ <b>Faults and timeouts are NEVER cached</b>, and neither is the late answer of a lookup the
/// deadline abandoned. Caching a deny would be fail-closed and is still wrong: it would extend a
/// ConfigDb outage past the outage, denying valid keys for a further TTL after the database came
/// back. Caching an abandoned answer would be worse than that — it was taken before the deadline
/// and served after it. Only a lookup that completed BEFORE its deadline — a hit or an
/// authoritative miss — is stored.
/// </para>
/// </remarks>
public sealed class BoundedApiKeyStore : IApiKeyStore
@@ -202,11 +204,33 @@ public sealed class BoundedApiKeyStore : IApiKeyStore
/// sees in production is always uncancellable.
/// </para>
/// <para>
/// ⚠️ <b>It re-throws rather than returning <see langword="null"/>.</b> <c>null</c> means
/// ⚠️ <b>The deadline is a HARD race, not a cooperative token — and that distinction was a live
/// gate failure, not a theoretical one.</b> This used to be a
/// <c>CancellationTokenSource(TimeSpan, TimeProvider)</c> linked into the inner call, which
/// bounds the call only if the callee chooses to observe the token.
/// <c>Microsoft.Data.SqlClient</c> does not, while a connect or login is in flight on a
/// black-holed socket: the 2026-08-20 R3-05 gate paused the SQL container and watched a keyed
/// activation hang <b>42.9 s</b> past its 2000 ms bound (the Warning below fired only at
/// unpause), stalling an unrelated already-open subscription for <b>57 s</b> behind the
/// <c>SessionManager</c> lock — the exact hazard the bound exists to prevent. So the inner call
/// is now raced against a <see cref="Task.Delay(TimeSpan, TimeProvider, CancellationToken)"/>
/// on the injected clock and <b>abandoned</b> when the delay wins.
/// </para>
/// <para>
/// ⚠️ <b>An abandoned lookup's answer is DISCARDED, never cached.</b> It was taken before the
/// deadline and would be served after it, so a key revoked or expired in the meantime could be
/// admitted from a lookup nobody was still waiting for. The token is still cancelled — a
/// cooperative inner store should stop — and the abandoned task's outcome is observed by
/// <see cref="ObserveAbandoned{T}"/> so it can never surface as an
/// <c>UnobservedTaskException</c>.
/// </para>
/// <para>
/// ⚠️ <b>It throws rather than returning <see langword="null"/>.</b> <c>null</c> means
/// "no such usable key", which the authenticator logs as <i>denied — no enabled, unexpired key
/// with id X</i>. A timeout is not that, and an operator reading that line during a ConfigDb
/// outage would go hunting for a key problem that does not exist. The distinct Warning below is
/// the honest signal; the denial itself is unchanged either way.
/// the honest signal; the denial itself is unchanged either way — the authenticator's catch-all
/// turns any throw into the same opaque denial.
/// </para>
/// </remarks>
private async Task<T> BoundAsync<T>(Func<CancellationToken, Task<T>> call, CancellationToken ct)
@@ -214,27 +238,78 @@ public sealed class BoundedApiKeyStore : IApiKeyStore
var timeoutMs = _options.Value.StoreTimeoutMs;
if (timeoutMs <= 0) return await call(ct).ConfigureAwait(false);
// The deadline runs on the INJECTED clock (the TimeProvider ctor overload), not on a plain
// CancelAfter, so it is the same TimeProvider the authorizer and the revalidation timer read.
// Linked with the caller's token so a genuine caller cancellation is still honoured — and so the
// catch below can tell the two apart.
using var deadline = new CancellationTokenSource(TimeSpan.FromMilliseconds(timeoutMs), _time);
using var cts = CancellationTokenSource.CreateLinkedTokenSource(ct, deadline.Token);
// winner check below can tell the two apart. NOT linked to the deadline: the deadline is the race,
// and this token is only the courtesy signal to an inner store that happens to be cooperative.
var innerCts = CancellationTokenSource.CreateLinkedTokenSource(ct);
Task<T> inner;
try
{
return await call(cts.Token).ConfigureAwait(false);
inner = call(innerCts.Token);
}
catch (OperationCanceledException) when (!ct.IsCancellationRequested)
catch
{
OtOpcUaTelemetry.ApiKeyStoreBounded.Add(
1, new KeyValuePair<string, object?>("outcome", "timeout"));
_log.LogWarning(
"ApiKeyStore: the key store did not answer within {TimeoutMs} ms — denying this activation. "
+ "Every OPC UA session activation on this server is serialized behind this call; "
+ "check ConfigDb health.",
timeoutMs);
innerCts.Dispose();
throw;
}
// The delay runs on the INJECTED clock, so it is the same TimeProvider the authorizer and the
// revalidation timer read. Its own CTS exists only to stop the timer when the inner call wins.
using var delayCts = new CancellationTokenSource();
var deadline = Task.Delay(TimeSpan.FromMilliseconds(timeoutMs), _time, delayCts.Token);
if (await Task.WhenAny(inner, deadline).ConfigureAwait(false) == inner)
{
delayCts.Cancel();
innerCts.Dispose();
return await inner.ConfigureAwait(false);
}
innerCts.Cancel();
ObserveAbandoned(inner, innerCts);
OtOpcUaTelemetry.ApiKeyStoreBounded.Add(
1, new KeyValuePair<string, object?>("outcome", "timeout"));
_log.LogWarning(
"ApiKeyStore: the key store did not answer within {TimeoutMs} ms — denying this activation. "
+ "The lookup is abandoned and its result, if it ever arrives, is discarded. Every OPC UA "
+ "session activation on this server is serialized behind this call; check ConfigDb health.",
timeoutMs);
throw new OperationCanceledException(
$"The API key store did not answer within {timeoutMs} ms; the lookup was abandoned.");
}
/// <summary>
/// Watches an abandoned inner lookup to its end so its outcome is observed and its resources are
/// released, and discards whatever it produced.
/// </summary>
/// <typeparam name="T">The abandoned call's result type.</typeparam>
/// <param name="abandoned">The lookup the deadline gave up on.</param>
/// <param name="cts">The cancellation source that call was handed; disposed once it finishes.</param>
/// <remarks>
/// Nobody awaits <paramref name="abandoned"/>, so without this its fault would be unobserved.
/// Debug rather than Warning: the timeout has already been reported at Warning, and a ConfigDb
/// outage would otherwise produce two lines per activation for one event.
/// </remarks>
private void ObserveAbandoned<T>(Task<T> abandoned, CancellationTokenSource cts) =>
_ = abandoned.ContinueWith(
finished =>
{
cts.Dispose();
var error = finished.Exception; // The observation itself — do not remove.
if (error is not null)
{
_log.LogDebug(
error,
"ApiKeyStore: an abandoned key store lookup faulted after its deadline; discarded.");
}
else
{
_log.LogDebug(
"ApiKeyStore: an abandoned key store lookup finished after its deadline; discarded.");
}
},
CancellationToken.None,
TaskContinuationOptions.ExecuteSynchronously,
TaskScheduler.Default);
}
@@ -1,4 +1,6 @@
using System.Diagnostics;
using System.Diagnostics.Metrics;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;
using Shouldly;
@@ -101,6 +103,110 @@ public sealed class BoundedApiKeyStoreTests
result.Error.ShouldBe(ApiKeyOpcUaUserAuthenticator.DenyMessage);
}
// ---------- the deadline is HARD, not cooperative (S18 live-gate follow-up, 2026-08-20) ----------
/// <summary>
/// An inner store that <b>ignores its cancellation token</b> is abandoned at the deadline anyway:
/// control returns to the activation inside the bound, not when the store eventually answers.
/// </summary>
/// <remarks>
/// <para>
/// ⚠️ <b>This is the live-gate failure, and every other deadline case in this class misses
/// it.</b> They drive <see cref="GatedApiKeyStore"/>, whose waits take the token, so a
/// cooperative <c>CancelAfter</c> is enough to unblock them. Real
/// <c>Microsoft.Data.SqlClient</c> is not cooperative while a connect or login is in flight on
/// a black-holed socket: the 2026-08-20 gate paused the SQL container and watched a keyed
/// activation hang <b>42.9 s</b> past a 2000 ms bound (the Warning fired only at unpause), with
/// an unrelated open subscription stalled 57 s behind the <c>SessionManager</c> lock.
/// </para>
/// <para>
/// The wall-clock assertion is what makes this test about the bound rather than about the
/// exception type: a cooperative implementation does not throw late here, it does not return
/// at all, so the test-side <c>WaitAsync</c> is the red.
/// </para>
/// </remarks>
[Fact]
public async Task An_uncancellable_store_is_abandoned_at_the_deadline()
{
var (_, inner) = SetUpUncooperative();
var sut = Bounded(inner, timeoutMs: 200, cacheSeconds: 5);
var started = Stopwatch.StartNew();
await Should.ThrowAsync<OperationCanceledException>(
() => sut.FindAsync(inner.KeyId, DateTime.UtcNow, default)
.WaitAsync(TimeSpan.FromSeconds(2)));
started.Stop();
started.Elapsed.ShouldBeLessThan(
TimeSpan.FromSeconds(2),
"the deadline must return control on its own, not wait for the store to answer");
// The abandoned lookup is released only now — the assertions above already hold without it.
inner.Release();
}
/// <summary>
/// A lookup abandoned at the deadline must never land in the cache when it completes later — the
/// next activation re-reads the store.
/// </summary>
/// <remarks>
/// Caching it would be worse than caching a timeout: the answer was taken before the deadline and
/// is served after it, so a key revoked or expired in the meantime would be admitted from a
/// lookup nobody was still waiting for. The call count is the assertion — a build that stored the
/// late result would serve the second call from the cache and leave <c>Calls</c> at 1.
/// </remarks>
[Fact]
public async Task An_abandoned_lookup_that_completes_later_is_not_cached()
{
var (_, inner) = SetUpUncooperative();
var sut = Bounded(inner, timeoutMs: 200, cacheSeconds: 60);
await Should.ThrowAsync<OperationCanceledException>(
() => sut.FindAsync(inner.KeyId, DateTime.UtcNow, default)
.WaitAsync(TimeSpan.FromSeconds(2)));
// The abandoned inner task now completes, with a perfectly valid key, into nobody's hands.
inner.Release();
await inner.Completed.WaitAsync(TimeSpan.FromSeconds(2));
// Well inside the 60 s TTL: a cached late answer would make this a hit.
(await sut.FindAsync(inner.KeyId, DateTime.UtcNow, default).WaitAsync(TimeSpan.FromSeconds(2)))
.ShouldNotBeNull("the store answers immediately once released");
inner.Calls.ShouldBe(2, "the abandoned lookup must not have populated the cache");
}
/// <summary>
/// An abandoned lookup that later <b>faults</b> has its exception observed and swallowed, so it
/// can never surface as an <c>UnobservedTaskException</c> on the finalizer thread.
/// </summary>
/// <remarks>
/// Nobody awaits the abandoned task, so without an explicit continuation its fault is unobserved —
/// which on some host configurations escalates. The Debug line is the observable proof the
/// continuation ran; asserting the absence of a finalizer-thread event instead would depend on GC
/// timing and prove nothing on a green run.
/// </remarks>
[Fact]
public async Task An_abandoned_lookup_that_faults_later_is_observed_and_swallowed()
{
var (_, inner) = SetUpUncooperative();
var log = new CapturingLogger();
var sut = Bounded(inner, timeoutMs: 200, cacheSeconds: 0, log: log);
await Should.ThrowAsync<OperationCanceledException>(
() => sut.FindAsync(inner.KeyId, DateTime.UtcNow, default)
.WaitAsync(TimeSpan.FromSeconds(2)));
inner.ReleaseWithFault(new InvalidOperationException("SqlClient gave up"));
await inner.Completed.WaitAsync(TimeSpan.FromSeconds(2));
// The continuation is a separate task from the one just awaited; give it a moment to run.
var deadline = Stopwatch.StartNew();
while (log.Lines.Count == 0 && deadline.Elapsed < TimeSpan.FromSeconds(2))
await Task.Delay(10);
log.Lines.ShouldContain(line => line.Contains("abandoned", StringComparison.OrdinalIgnoreCase));
}
/// <summary>
/// A non-positive <c>StoreTimeoutMs</c> disables the deadline, restoring the unbounded behaviour
/// byte-for-byte — the documented rollback.
@@ -367,7 +473,11 @@ public sealed class BoundedApiKeyStoreTests
// ---------- helpers ----------
private static BoundedApiKeyStore Bounded(
IApiKeyStore inner, int timeoutMs, int cacheSeconds, TimeProvider? clock = null) => new(
IApiKeyStore inner,
int timeoutMs,
int cacheSeconds,
TimeProvider? clock = null,
ILogger<BoundedApiKeyStore>? log = null) => new(
inner,
Options.Create(new ApiKeyOptions
{
@@ -376,7 +486,7 @@ public sealed class BoundedApiKeyStoreTests
StoreTimeoutMs = timeoutMs,
StoreCacheSeconds = cacheSeconds,
}),
NullLogger<BoundedApiKeyStore>.Instance,
log ?? NullLogger<BoundedApiKeyStore>.Instance,
clock ?? TimeProvider.System);
private static ApiKeyOpcUaUserAuthenticator Auth(IApiKeyStore store) => new(
@@ -400,6 +510,22 @@ public sealed class BoundedApiKeyStoreTests
return (presented, new GatedApiKeyStore(key));
}
/// <summary>Builds the same key in front of an inner store that does NOT honour cancellation.</summary>
/// <returns>The presented credential and the uncooperative store.</returns>
private static (string Presented, UncooperativeApiKeyStore Store) SetUpUncooperative()
{
var (presented, apiKeyId, hash) = ApiKeySecret.Generate(Pepper);
return (presented, new UncooperativeApiKeyStore(new ApiKey
{
ApiKeyId = apiKeyId,
Name = "test key",
SecretHash = hash,
Principal = Principal,
Enabled = true,
CreatedUtc = DateTime.UtcNow,
}));
}
/// <summary>
/// An inner store whose answer can be withheld — a hang the EF in-memory provider cannot
/// represent — and whose calls are counted.
@@ -456,6 +582,104 @@ public sealed class BoundedApiKeyStoreTests
}
}
/// <summary>
/// An inner store that <b>ignores its cancellation token entirely</b> — the shape real
/// <c>Microsoft.Data.SqlClient</c> takes on a black-holed connection, and the one every other fake
/// in this class cannot represent.
/// </summary>
/// <remarks>
/// <see cref="GatedApiKeyStore"/> passes the token into every wait, so a cooperative deadline
/// unblocks it and a cooperative implementation looks correct. This one only ever completes when
/// the test releases it, so the deadline has to be a real race to return at all.
/// </remarks>
private sealed class UncooperativeApiKeyStore(ApiKey key) : IApiKeyStore
{
private readonly TaskCompletionSource _gate =
new(TaskCreationOptions.RunContinuationsAsynchronously);
private readonly TaskCompletionSource _completed =
new(TaskCreationOptions.RunContinuationsAsynchronously);
private int _calls;
/// <summary>The id of the key this store holds.</summary>
public string KeyId => key.ApiKeyId;
/// <summary>How many calls reached this store (i.e. were not served from the cache).</summary>
public int Calls => _calls;
/// <summary>Completes once an in-flight inner call has run to completion or fault.</summary>
public Task Completed => _completed.Task;
/// <summary>Lets the in-flight (and every subsequent) call answer normally.</summary>
public void Release() => _gate.TrySetResult();
/// <summary>Lets the in-flight call fail, the way SqlClient eventually gives up on its own.</summary>
/// <param name="error">The fault to surface from the abandoned inner task.</param>
public void ReleaseWithFault(Exception error) => _gate.TrySetException(error);
public async Task<ApiKeyLookup?> FindAsync(string apiKeyId, DateTime utcNow, CancellationToken ct)
{
Interlocked.Increment(ref _calls);
try
{
// ⚠️ ct is deliberately NOT passed — that is the whole point of this fake.
await _gate.Task.ConfigureAwait(false);
}
finally
{
_completed.TrySetResult();
}
return string.Equals(apiKeyId, key.ApiKeyId, StringComparison.Ordinal)
? new ApiKeyLookup(key, [])
: null;
}
public async Task<IReadOnlyList<NodeAcl>> FindGrantsAsync(string principal, CancellationToken ct)
{
Interlocked.Increment(ref _calls);
try
{
await _gate.Task.ConfigureAwait(false);
}
finally
{
_completed.TrySetResult();
}
return [];
}
}
/// <summary>Collects rendered log messages so a "logged and swallowed" claim can be asserted.</summary>
private sealed class CapturingLogger : ILogger<BoundedApiKeyStore>
{
private readonly List<string> _lines = [];
private readonly Lock _gate = new();
/// <summary>Every line rendered so far.</summary>
public IReadOnlyList<string> Lines
{
get { lock (_gate) return [.. _lines]; }
}
/// <inheritdoc />
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
/// <inheritdoc />
public bool IsEnabled(LogLevel logLevel) => true;
/// <inheritdoc />
public void Log<TState>(
LogLevel logLevel,
EventId eventId,
TState state,
Exception? exception,
Func<TState, Exception?, string> formatter)
{
lock (_gate) _lines.Add(formatter(state, exception));
}
}
/// <summary>Collects <c>otopcua.opcua.apikey_store.bounded</c> measurements by their outcome tag.</summary>
/// <remarks>
/// ⚠️ Filtered by instrument name only, which is normally the metrics-test leak (a listener sees