Merge branch 'fix/r3-05-s18-hard-deadline' — R3-05 S18 live-gate failure: the API-key store deadline is a hard Task.WhenAny race (SqlClient ignores cooperative cancellation on a black-holed socket: 42.9 s activation hang, 57 s stall of open subscriptions); compose wires OTOPCUA_ACL_ENABLED to the centrals
This commit is contained in:
@@ -910,3 +910,91 @@ Gate rows deleted (`NodeAcl` row, the `expiry-probe` key, nothing else had been
|
||||
recreated **without** the override (`Security__Acl__Enabled` absent from both env lists, i.e. default `false`),
|
||||
parity `b344565cad3d` ×6 re-asserted, readiness back, final deploy `1c666be3…` Sealed, anonymous read of `HR100`
|
||||
answers a value again. Rig left UP on the master image with `DisableLogin=true`.
|
||||
|
||||
## S18 hard-deadline follow-up (2026-08-20)
|
||||
|
||||
The gate's S18 finding is **fixed on `fix/r3-05-s18-hard-deadline`** (branched off master `9242630c`), plus the
|
||||
compose recipe defect the same leg exposed. Not yet live re-gated — the paused-SQL leg has to be re-run.
|
||||
|
||||
### What was wrong
|
||||
|
||||
`BoundedApiKeyStore.BoundAsync` bounded the inner store with a
|
||||
`CancellationTokenSource(TimeSpan, TimeProvider)` linked into the call. **That bounds the call only if the
|
||||
callee chooses to observe the token**, and `Microsoft.Data.SqlClient` does not while a connect or login is
|
||||
in flight on a black-holed socket. So the deadline never returned control: the gate's keyed activation ran
|
||||
**42.9 s** against a 2000 ms bound, the *"did not answer within 2000 ms"* Warning was emitted only at
|
||||
unpause, and because the whole thing sits inside the SDK's synchronous `SessionManager`-lock-holding
|
||||
impersonation callback, an unrelated already-open subscription stalled **57 s** behind it. The T3 TTL cache
|
||||
cannot help: a miss is exactly what the outage produces.
|
||||
|
||||
### Red before green — the observation, not just the claim
|
||||
|
||||
Every pre-existing deadline test drives `GatedApiKeyStore`, whose waits take the token
|
||||
(`Task.Delay(Timeout.Infinite, ct)`, `gate.WaitAsync(ct)`). A cooperative `CancelAfter` unblocks those, so
|
||||
**all 15 of them passed against the defective build** — the suite could not see the gate's failure at all.
|
||||
The new fake, `UncooperativeApiKeyStore`, ignores `ct` entirely and completes only when the test releases
|
||||
it, modelling SqlClient. Against the unmodified `BoundedApiKeyStore` the three new tests fail — with a
|
||||
test-side `WaitAsync(2 s)`, so the red is a **failure, not a hang**:
|
||||
|
||||
```
|
||||
Failed! - Failed: 3, Passed: 15, Skipped: 0, Total: 18
|
||||
An_uncancellable_store_is_abandoned_at_the_deadline [FAIL]
|
||||
An_abandoned_lookup_that_completes_later_is_not_cached [FAIL]
|
||||
An_abandoned_lookup_that_faults_later_is_observed_and_swallowed [FAIL]
|
||||
Shouldly.ShouldAssertException : … should throw System.OperationCanceledException but threw System.TimeoutException
|
||||
```
|
||||
|
||||
`TimeoutException` rather than `OperationCanceledException` **is** the finding, restated as an assertion:
|
||||
with a 200 ms bound the decorator had still not returned 2 s later.
|
||||
|
||||
### The fix
|
||||
|
||||
`BoundAsync` now races the inner call against `Task.Delay(timeout, _time, …)` — the injected clock, so the
|
||||
deadline stays on the same `TimeProvider` as the authorizer and the revalidation timer — with
|
||||
`Task.WhenAny`:
|
||||
|
||||
- **Inner wins** ⇒ stop the delay timer, dispose, `await inner` (faults and a genuine *caller* cancellation
|
||||
propagate exactly as before).
|
||||
- **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, unchanged: nothing here can admit.**
|
||||
- `ObserveAbandoned` attaches a continuation that disposes the CTS, **touches `finished.Exception`** (the
|
||||
observation itself, so a late SqlClient fault can never become an `UnobservedTaskException`), and logs at
|
||||
Debug. Debug rather than Warning because the timeout is already reported at Warning — a ConfigDb outage
|
||||
should 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.
|
||||
`Store(...)` is simply unreachable on the timeout path; the test asserts it by call count (a cached late
|
||||
answer would make the next lookup a hit and leave `Calls` at 1).
|
||||
- `StoreTimeoutMs ≤ 0` still short-circuits to the unbounded call, byte-for-byte — the documented rollback.
|
||||
|
||||
Files: `src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs`,
|
||||
`tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/OpcUa/BoundedApiKeyStoreTests.cs`, `docs/security.md`
|
||||
§"Bounding the key store". Host.Tests **137/137 green** (was 134; +3).
|
||||
|
||||
### Recipe defect fixed: `OTOPCUA_ACL_ENABLED` never reached the centrals
|
||||
|
||||
The gate's own correction note, actioned. `Security__Acl__Enabled: "${OTOPCUA_ACL_ENABLED:-false}"` was
|
||||
wired to **site-a-1 / site-a-2 only**, so
|
||||
`OTOPCUA_ACL_ENABLED=true docker compose up -d central-1 central-2` was a silent no-op — on the one node
|
||||
kind that carries `BoundedApiKeyStore` at all (only a fused admin+driver node wraps `ConfigDbApiKeyStore`).
|
||||
The key is now on **central-1 and central-2** too, same env var, **same default-`false`**, so today's rig
|
||||
behaviour is unchanged and the plan's step 1 does what it says. site-b stays hardcoded OFF as the A/B
|
||||
control.
|
||||
|
||||
### Live re-gate — still owed
|
||||
|
||||
Re-run **step 8's paused-SQL leg only** (setup steps 2-4 unchanged, and step 1 now needs no scratch
|
||||
override). Expected, versus what the gate saw:
|
||||
|
||||
| Observation | Gate (defective) | Expected now |
|
||||
|---|---|---|
|
||||
| Keyed `read` connect with SQL paused | 42.9 s, client `BadRequestTimeout` | denies in ≈ `StoreTimeoutMs` (2 s) |
|
||||
| *"did not answer within 2000 ms"* Warning | at unpause, ~40 s late | at the deadline, while SQL is still paused |
|
||||
| Already-open subscription on the same node | 57 s gap | no gap beyond the ~2 s of the activation |
|
||||
| `apikey_store_bounded{outcome="timeout"}` | 1, ~40 s late | 1, promptly |
|
||||
| Falsification control (pause with **no** activation) | streamed clean | must still stream clean |
|
||||
|
||||
⚠️ The Debug abandonment line is not visible at the rig's default log level — it is not part of the gate's
|
||||
pass criteria; the Warning and the restored subscription are.
|
||||
|
||||
@@ -403,6 +403,13 @@ services:
|
||||
Security__Ldap__ServiceAccountPassword: "serviceaccount123"
|
||||
Security__DeployApiKey: "docker-dev-deploy-key"
|
||||
Security__Auth__DisableLogin: "${OTOPCUA_DISABLE_LOGIN:-true}"
|
||||
# #520 stage 6 — node ACL enforcement, the dark switch. Default OFF, exactly as in production.
|
||||
# The centrals read the SAME env override as the site-a pair, so an ACL live gate can enable it
|
||||
# where BoundedApiKeyStore actually lives (only a fused admin+driver node wraps ConfigDbApiKeyStore):
|
||||
# OTOPCUA_ACL_ENABLED=true docker compose -f docker-dev/docker-compose.yml up -d central-1 central-2
|
||||
# Added 2026-08-20: the R3-05 gate found this key wired only to site-a-1/2, so that command was a
|
||||
# silent no-op on the centrals and the gate needed a scratch compose override to proceed.
|
||||
Security__Acl__Enabled: "${OTOPCUA_ACL_ENABLED:-false}"
|
||||
# Map the shared-GLAuth data-plane groups (ReadOnly/WriteOperate/...) to data-plane role
|
||||
# strings the OPC UA session ACL gates read. The DB LdapGroupRoleMapping is AdminRole-typed
|
||||
# (AdminUI roles); this free-form GroupToRole baseline is the path for data-plane roles.
|
||||
@@ -529,6 +536,10 @@ services:
|
||||
Security__Ldap__ServiceAccountPassword: "serviceaccount123"
|
||||
Security__DeployApiKey: "docker-dev-deploy-key"
|
||||
Security__Auth__DisableLogin: "${OTOPCUA_DISABLE_LOGIN:-true}"
|
||||
# Node ACL enforcement, the dark switch — same env override and same default-OFF as central-1.
|
||||
# Both centrals must carry it: `up -d central-1 central-2` recreates both, and a pair split across
|
||||
# two enforcement postures is not a rig anyone can reason about.
|
||||
Security__Acl__Enabled: "${OTOPCUA_ACL_ENABLED:-false}"
|
||||
# Data-plane group→role baseline (see central-1).
|
||||
Security__Ldap__GroupToRole__ReadOnly: "ReadOnly"
|
||||
Security__Ldap__GroupToRole__WriteOperate: "WriteOperate"
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user