diff --git a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md index 7689c090..90dbebeb 100644 --- a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md +++ b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md @@ -632,3 +632,16 @@ for the orchestrator. - The counter's `cache_hit` / `timeout` `Add` calls are deliberately NOT here — they are T4, and writing them early would have made T4's red vacuous. - 11 tests in the class, green. + +### T4 — `otopcua.opcua.apikey_store.bounded` counter + +- **RED observed (behavioural, not compile):** `A_timeout_meters_outcome_timeout` and + `A_cache_hit_meters_outcome_cache_hit` both `[FAIL]` with `should be` — the instrument existed nowhere, + so the listener saw nothing. `A_plain_read_through_meters_neither` passed vacuously at red, by design: + its job starts once the counter exists. +- **NOTE on the metrics-leak memory:** the recorder filters on **instrument name only**. That is normally + the leak (a parallel test's measurements land in it), and it is safe here for a checkable reason + recorded on the helper: `BoundedApiKeyStore` is the only writer of this instrument, only this class + constructs one, and xUnit never runs two tests of one class in parallel. Adding a second class that + exercises the decorator means adding a discriminating tag. +- 14 tests in the class, green. diff --git a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json index cf158b9e..f253cd64 100644 --- a/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json +++ b/archreview/plans/R3-05-acl-hot-path-expiry-plan.md.tasks.json @@ -27,7 +27,7 @@ { "id": "T4", "subject": "otopcua.opcua.apikey_store.bounded counter (outcome=timeout|cache_hit) + MeterListener assertions", - "status": "pending", + "status": "done", "blockedBy": [ "T3" ] diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs index 09950d24..ba3a0441 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs @@ -110,6 +110,20 @@ public static class OtOpcUaTelemetry Meter.CreateCounter("otopcua.redundancy.primary_gate_denied", unit: "{denial}", description: "Operations denied by the Primary gate (site=write|ack|alarm-emit, reason=secondary|detached|role-unknown)."); + /// + /// API-key store lookups the 03/S18 bound intervened on (outcome=timeout|cache_hit). + /// + /// + /// One counter with an outcome tag rather than two: timeout is the alarm signal that + /// the ConfigDb is not answering the OPC UA impersonation callback, and cache_hit is the + /// ratio that says whether the TTL is doing anything. A missing cache_hit stream on a busy + /// fused central is how you notice Security:ApiKeys:StoreCacheSeconds was set to 0 by + /// accident. A plain read-through meters neither — the counter names interventions, not traffic. + /// + public static readonly Counter ApiKeyStoreBounded = + Meter.CreateCounter("otopcua.opcua.apikey_store.bounded", unit: "{lookup}", + description: "API-key store lookups the bound intervened on (outcome=timeout|cache_hit)."); + // ---------------- Convenience helpers ---------------- /// 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 63c03710..21e112d5 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/BoundedApiKeyStore.cs @@ -1,6 +1,7 @@ using System.Collections.Concurrent; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; +using ZB.MOM.WW.OtOpcUa.Commons.Observability; using ZB.MOM.WW.OtOpcUa.Configuration.Entities; using ZB.MOM.WW.OtOpcUa.Core.Authorization; @@ -139,6 +140,8 @@ public sealed class BoundedApiKeyStore : IApiKeyStore { if (cache.TryGetValue(key, out var entry) && _time.GetUtcNow() - entry.StampedUtc < ttl) { + OtOpcUaTelemetry.ApiKeyStoreBounded.Add( + 1, new KeyValuePair("outcome", "cache_hit")); value = entry.Value; return true; } @@ -202,6 +205,8 @@ public sealed class BoundedApiKeyStore : IApiKeyStore } catch (OperationCanceledException) when (!ct.IsCancellationRequested) { + 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; " 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 80a7fa4c..74210583 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,7 +1,9 @@ +using System.Diagnostics.Metrics; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; using Shouldly; using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Observability; using ZB.MOM.WW.OtOpcUa.Configuration.Entities; using ZB.MOM.WW.OtOpcUa.Core.Authorization; using ZB.MOM.WW.OtOpcUa.Host.OpcUa; @@ -270,6 +272,61 @@ public sealed class BoundedApiKeyStoreTests inner.Calls.ShouldBe(callsAfterFlood + 1); } + // ---------- metering ---------- + + /// A deadline that fires meters outcome=timeout — the alarm signal for a sick ConfigDb. + [Fact] + public async Task A_timeout_meters_outcome_timeout() + { + var (_, inner) = SetUp(); + inner.BlockForever = true; + using var meter = new MeterRecorder(); + var sut = Bounded(inner, timeoutMs: 100, cacheSeconds: 0); + + await Should.ThrowAsync( + () => sut.FindAsync(inner.KeyId, DateTime.UtcNow, default).WaitAsync(TimeSpan.FromSeconds(5))); + + meter.WithOutcome("timeout").ShouldBe(1); + meter.WithOutcome("cache_hit").ShouldBe(0); + } + + /// + /// A cache hit meters outcome=cache_hit — the ratio that tells an operator the TTL is + /// doing something. A missing stream on a busy fused central is how you notice + /// StoreCacheSeconds was set to 0 by accident. + /// + [Fact] + public async Task A_cache_hit_meters_outcome_cache_hit() + { + var (_, inner) = SetUp(); + var clock = new FakeClock(new DateTimeOffset(2026, 8, 20, 12, 0, 0, TimeSpan.Zero)); + using var meter = new MeterRecorder(); + var sut = Bounded(inner, timeoutMs: 0, cacheSeconds: 5, clock); + + await sut.FindAsync(inner.KeyId, clock.GetUtcNow().UtcDateTime, default); + meter.WithOutcome("cache_hit").ShouldBe(0, "the first call is a miss"); + + await sut.FindAsync(inner.KeyId, clock.GetUtcNow().UtcDateTime, default); + meter.WithOutcome("cache_hit").ShouldBe(1); + } + + /// A plain read-through — no deadline hit, no cache hit — meters nothing at all. + /// + /// The counter names lookups the bound INTERVENED on. Metering every lookup would bury the two + /// outcomes that matter under the ordinary traffic they have to be spotted in. + /// + [Fact] + public async Task A_plain_read_through_meters_neither() + { + var (_, inner) = SetUp(); + using var meter = new MeterRecorder(); + var sut = Bounded(inner, timeoutMs: 2000, cacheSeconds: 0); + + await sut.FindAsync(inner.KeyId, DateTime.UtcNow, default); + + meter.Total.ShouldBe(0); + } + // ---------- helpers ---------- private static BoundedApiKeyStore Bounded( @@ -361,6 +418,65 @@ public sealed class BoundedApiKeyStoreTests } } + /// 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 + /// a PARALLEL test's measurements too). It is safe HERE for a checkable reason: + /// is the only thing in the product that writes this instrument, + /// and this class is the only one in the assembly that constructs one — and xUnit never runs two + /// tests of the same class in parallel. Adding a class that exercises the decorator means adding + /// a discriminating tag here. + /// + private sealed class MeterRecorder : IDisposable + { + private readonly MeterListener _listener; + private readonly List[]> _tagSets = []; + private readonly Lock _gate = new(); + private long _total; + + public MeterRecorder() + { + _listener = new MeterListener + { + InstrumentPublished = (instrument, listener) => + { + if (instrument.Meter.Name == OtOpcUaTelemetry.MeterName + && instrument.Name == "otopcua.opcua.apikey_store.bounded") + { + listener.EnableMeasurementEvents(instrument); + } + }, + }; + _listener.SetMeasurementEventCallback((_, value, tags, _) => + { + lock (_gate) + { + _total += value; + _tagSets.Add(tags.ToArray()); + } + }); + _listener.Start(); + } + + /// Every measurement seen, regardless of tags. + public long Total + { + get { lock (_gate) return _total; } + } + + /// How many measurements carried outcome=. + /// The outcome tag value to count. + /// The measurement count. + public int WithOutcome(string outcome) + { + lock (_gate) + return _tagSets.Count(set => set.Any(t => t.Key == "outcome" && Equals(t.Value, outcome))); + } + + /// + public void Dispose() => _listener.Dispose(); + } + /// /// A hand-advanced clock. Overrides GetUtcNow() only — see the class remarks for why that /// confines it to the TTL cases.