diff --git a/docs/security.md b/docs/security.md index aef95689..cb9f8147 100644 --- a/docs/security.md +++ b/docs/security.md @@ -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 diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs index bc63006e..4da11850 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs @@ -27,10 +27,12 @@ namespace ZB.MOM.WW.OtOpcUa.Host.OpcUa; /// decorator can only return what the inner store returned, or throw. /// /// -/// ⚠️ Faults and timeouts are NEVER cached. 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. +/// ⚠️ Faults and timeouts are NEVER cached, 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. /// /// public sealed class BoundedApiKeyStore : IApiKeyStore @@ -202,11 +204,33 @@ public sealed class BoundedApiKeyStore : IApiKeyStore /// sees in production is always uncancellable. /// /// - /// ⚠️ It re-throws rather than returning . null means + /// ⚠️ The deadline is a HARD race, not a cooperative token — and that distinction was a live + /// gate failure, not a theoretical one. This used to be 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 for 57 s behind the + /// SessionManager lock — the exact hazard the bound exists to prevent. So the inner call + /// is now raced against a + /// on the injected clock and abandoned when the delay wins. + /// + /// + /// ⚠️ An abandoned lookup's answer is DISCARDED, 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 — a + /// cooperative inner store should stop — and the abandoned task's outcome is observed by + /// so it can never surface as an + /// UnobservedTaskException. + /// + /// + /// ⚠️ It throws rather than returning . null means /// "no such usable key", which the authenticator logs as denied — no enabled, unexpired key /// with id X. 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. /// /// private async Task BoundAsync(Func> 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 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("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("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."); } + + /// + /// Watches an abandoned inner lookup to its end so its outcome is observed and its resources are + /// released, and discards whatever it produced. + /// + /// The abandoned call's result type. + /// The lookup the deadline gave up on. + /// The cancellation source that call was handed; disposed once it finishes. + /// + /// Nobody awaits , 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. + /// + private void ObserveAbandoned(Task 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); } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/OpcUa/BoundedApiKeyStoreTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/OpcUa/BoundedApiKeyStoreTests.cs index 9a4357dc..e8081db1 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/OpcUa/BoundedApiKeyStoreTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/OpcUa/BoundedApiKeyStoreTests.cs @@ -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) ---------- + + /// + /// An inner store that ignores its cancellation token is abandoned at the deadline anyway: + /// control returns to the activation inside the bound, not when the store eventually answers. + /// + /// + /// + /// ⚠️ This is the live-gate failure, and every other deadline case in this class misses + /// it. They drive , whose waits take the token, so a + /// cooperative CancelAfter is enough to unblock them. Real + /// Microsoft.Data.SqlClient 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 42.9 s past a 2000 ms bound (the Warning fired only at unpause), with + /// an unrelated open subscription stalled 57 s behind the SessionManager lock. + /// + /// + /// 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 WaitAsync is the red. + /// + /// + [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( + () => 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(); + } + + /// + /// A lookup abandoned at the deadline must never land in the cache when it completes later — the + /// next activation re-reads the store. + /// + /// + /// 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 Calls at 1. + /// + [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( + () => 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"); + } + + /// + /// An abandoned lookup that later faults has its exception observed and swallowed, so it + /// can never surface as an UnobservedTaskException on the finalizer thread. + /// + /// + /// 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. + /// + [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( + () => 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)); + } + /// /// A non-positive StoreTimeoutMs 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? log = null) => new( inner, Options.Create(new ApiKeyOptions { @@ -376,7 +486,7 @@ public sealed class BoundedApiKeyStoreTests StoreTimeoutMs = timeoutMs, StoreCacheSeconds = cacheSeconds, }), - NullLogger.Instance, + log ?? NullLogger.Instance, clock ?? TimeProvider.System); private static ApiKeyOpcUaUserAuthenticator Auth(IApiKeyStore store) => new( @@ -400,6 +510,22 @@ public sealed class BoundedApiKeyStoreTests return (presented, new GatedApiKeyStore(key)); } + /// Builds the same key in front of an inner store that does NOT honour cancellation. + /// The presented credential and the uncooperative store. + 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, + })); + } + /// /// 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 } } + /// + /// An inner store that ignores its cancellation token entirely — the shape real + /// Microsoft.Data.SqlClient takes on a black-holed connection, and the one every other fake + /// in this class cannot represent. + /// + /// + /// 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. + /// + private sealed class UncooperativeApiKeyStore(ApiKey key) : IApiKeyStore + { + private readonly TaskCompletionSource _gate = + new(TaskCreationOptions.RunContinuationsAsynchronously); + private readonly TaskCompletionSource _completed = + new(TaskCreationOptions.RunContinuationsAsynchronously); + private int _calls; + + /// The id of the key this store holds. + public string KeyId => key.ApiKeyId; + + /// How many calls reached this store (i.e. were not served from the cache). + public int Calls => _calls; + + /// Completes once an in-flight inner call has run to completion or fault. + public Task Completed => _completed.Task; + + /// Lets the in-flight (and every subsequent) call answer normally. + public void Release() => _gate.TrySetResult(); + + /// Lets the in-flight call fail, the way SqlClient eventually gives up on its own. + /// The fault to surface from the abandoned inner task. + public void ReleaseWithFault(Exception error) => _gate.TrySetException(error); + + public async Task 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> FindGrantsAsync(string principal, CancellationToken ct) + { + Interlocked.Increment(ref _calls); + try + { + await _gate.Task.ConfigureAwait(false); + } + finally + { + _completed.TrySetResult(); + } + + return []; + } + } + + /// Collects rendered log messages so a "logged and swallowed" claim can be asserted. + private sealed class CapturingLogger : ILogger + { + private readonly List _lines = []; + private readonly Lock _gate = new(); + + /// Every line rendered so far. + public IReadOnlyList Lines + { + get { lock (_gate) return [.. _lines]; } + } + + /// + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + /// + public bool IsEnabled(LogLevel logLevel) => true; + + /// + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + lock (_gate) _lines.Add(formatter(state, exception)); + } + } + /// Collects otopcua.opcua.apikey_store.bounded measurements by their outcome tag. /// /// ⚠️ Filtered by instrument name only, which is normally the metrics-test leak (a listener sees