feat(observability): meter bounded API-key store lookups

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.

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"
       ]

src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs

@@ -110,6 +110,20 @@ public static class OtOpcUaTelemetry
         Meter.CreateCounter<long>("otopcua.redundancy.primary_gate_denied", unit: "{denial}",
             description: "Operations denied by the Primary gate (site=write|ack|alarm-emit, reason=secondary|detached|role-unknown).");
 
+    /// <summary>
+    ///     API-key store lookups the 03/S18 bound intervened on (outcome=timeout|cache_hit).
+    /// </summary>
+    /// <remarks>
+    ///     One counter with an <c>outcome</c> tag rather than two: <c>timeout</c> is the alarm signal that
+    ///     the ConfigDb is not answering the OPC UA impersonation callback, and <c>cache_hit</c> is the
+    ///     ratio that says whether the TTL is doing anything. A missing <c>cache_hit</c> stream on a busy
+    ///     fused central is how you notice <c>Security:ApiKeys:StoreCacheSeconds</c> was set to 0 by
+    ///     accident. A plain read-through meters neither — the counter names interventions, not traffic.
+    /// </remarks>
+    public static readonly Counter<long> ApiKeyStoreBounded =
+        Meter.CreateCounter<long>("otopcua.opcua.apikey_store.bounded", unit: "{lookup}",
+            description: "API-key store lookups the bound intervened on (outcome=timeout|cache_hit).");
+
     // ---------------- Convenience helpers ----------------
 
     /// <summary>

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<string, object?>("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<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; "

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 ----------
+
+    /// <summary>A deadline that fires meters <c>outcome=timeout</c> — the alarm signal for a sick ConfigDb.</summary>
+    [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<OperationCanceledException>(
+            () => sut.FindAsync(inner.KeyId, DateTime.UtcNow, default).WaitAsync(TimeSpan.FromSeconds(5)));
+
+        meter.WithOutcome("timeout").ShouldBe(1);
+        meter.WithOutcome("cache_hit").ShouldBe(0);
+    }
+
+    /// <summary>
+    ///     A cache hit meters <c>outcome=cache_hit</c> — the ratio that tells an operator the TTL is
+    ///     doing something. A missing stream on a busy fused central is how you notice
+    ///     <c>StoreCacheSeconds</c> was set to 0 by accident.
+    /// </summary>
+    [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);
+    }
+
+    /// <summary>A plain read-through — no deadline hit, no cache hit — meters nothing at all.</summary>
+    /// <remarks>
+    ///     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.
+    /// </remarks>
+    [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
         }
     }
 
+    /// <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
+    ///     a PARALLEL test's measurements too). It is safe HERE for a checkable reason:
+    ///     <see cref="BoundedApiKeyStore"/> 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.
+    /// </remarks>
+    private sealed class MeterRecorder : IDisposable
+    {
+        private readonly MeterListener _listener;
+        private readonly List<KeyValuePair<string, object?>[]> _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<long>((_, value, tags, _) =>
+            {
+                lock (_gate)
+                {
+                    _total += value;
+                    _tagSets.Add(tags.ToArray());
+                }
+            });
+            _listener.Start();
+        }
+
+        /// <summary>Every measurement seen, regardless of tags.</summary>
+        public long Total
+        {
+            get { lock (_gate) return _total; }
+        }
+
+        /// <summary>How many measurements carried <c>outcome=<paramref name="outcome"/></c>.</summary>
+        /// <param name="outcome">The outcome tag value to count.</param>
+        /// <returns>The measurement count.</returns>
+        public int WithOutcome(string outcome)
+        {
+            lock (_gate)
+                return _tagSets.Count(set => set.Any(t => t.Key == "outcome" && Equals(t.Value, outcome)));
+        }
+
+        /// <inheritdoc />
+        public void Dispose() => _listener.Dispose();
+    }
+
     /// <summary>
     ///     A hand-advanced clock. Overrides <c>GetUtcNow()</c> only — see the class remarks for why that
     ///     confines it to the TTL cases.