using System.Diagnostics.Metrics; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Types.Transport; using ZB.MOM.WW.ScadaBridge.Transport.Import; namespace ZB.MOM.WW.ScadaBridge.Transport.Tests.Import; /// /// Register row 53: MaxConcurrentImportSessions had no observability — nothing /// counted open sessions and nothing logged a rejection at the cap, so the earlier /// session leak could only be inferred from rotating test failures. These tests pin the /// two signals that close that gap: the /// scadabridge.central.transport.import_sessions.open gauge and the Warning-level /// log emitted when rejects at the cap. /// public sealed class BundleSessionObservabilityTests { private const string OpenSessionsGauge = "scadabridge.central.transport.import_sessions.open"; private const string RejectedSessionsCounter = "scadabridge.central.transport.import_sessions.rejected"; // ------------------------------------------------------------------ // Warning log on cap rejection // ------------------------------------------------------------------ /// Verifies that opening a session at the cap logs a warning with the session count and the cap. [Fact] public void Open_AtCap_LogsWarningWithCountAndCap() { // The rejection used to be visible only as the exception the caller saw. The // operator-facing signal must name BOTH the current count and the cap — that // pair is what distinguishes genuine concurrency from a leak. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 3 }); var logger = new CapturingLogger(); var sut = new BundleSessionStore(opts, clock, logger); var future = clock.GetUtcNow().AddMinutes(30); for (var i = 0; i < 3; i++) { sut.Open(SessionExpiringAt(future)); } Assert.Throws(() => sut.Open(SessionExpiringAt(future))); var warning = Assert.Single(logger.Entries, e => e.Level == LogLevel.Warning); Assert.Contains("Bundle import session rejected", warning.Message, StringComparison.Ordinal); Assert.Contains("3 of 3", warning.Message, StringComparison.Ordinal); Assert.Contains("MaxConcurrentImportSessions", warning.Message, StringComparison.Ordinal); } /// Verifies that opening a session under the cap logs nothing. [Fact] public void Open_UnderCap_LogsNothing() { // Negative control: the Warning must be a cap signal, not per-open noise. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 3 }); var logger = new CapturingLogger(); var sut = new BundleSessionStore(opts, clock, logger); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30))); Assert.Empty(logger.Entries); } /// Verifies that opening at a cap filled by expired sessions reclaims them and logs nothing. [Fact] public void Open_AtCapOfExpiredSessions_ReclaimsAndLogsNothing() { // A store that is full only of stale entries reclaims and admits the caller — // that is not a cap hit and must not produce a Warning, or the signal would fire // routinely on any node whose sweep has not yet run. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 2 }); var logger = new CapturingLogger(); var sut = new BundleSessionStore(opts, clock, logger); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(5))); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(5))); clock.Advance(TimeSpan.FromMinutes(10)); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30))); Assert.Empty(logger.Entries); } // ------------------------------------------------------------------ // Rejection counter (register row 66) // ------------------------------------------------------------------ /// Verifies that opening a session at the cap increments the rejection counter. [Fact] public void Open_AtCap_IncrementsTheRejectionCounter() { // Row 53 shipped the gauge + Warning; a log line is not alertable. This counter is // the series an operator can page on, so it must move on a genuine cap hit. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 3 }); var sut = new BundleSessionStore(opts, clock, NullLogger.Instance); var future = clock.GetUtcNow().AddMinutes(30); for (var i = 0; i < 3; i++) { sut.Open(SessionExpiringAt(future)); } var delta = ReadRejectionCounter(() => Assert.Throws(() => sut.Open(SessionExpiringAt(future)))); Assert.Equal(1, delta); } /// Verifies that repeated cap hits accumulate on the rejection counter. [Fact] public void Open_RepeatedCapHits_AccumulateOnTheRejectionCounter() { // A counter that saturated at 1 would hide exactly the case it exists for: a // sustained rejection rate is what distinguishes real contention from a one-off. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 1 }); var sut = new BundleSessionStore(opts, clock, NullLogger.Instance); var future = clock.GetUtcNow().AddMinutes(30); sut.Open(SessionExpiringAt(future)); var delta = ReadRejectionCounter(() => { for (var i = 0; i < 3; i++) { Assert.Throws(() => sut.Open(SessionExpiringAt(future))); } }); Assert.Equal(3, delta); } /// Verifies that opening a session under the cap does not increment the rejection counter. [Fact] public void Open_UnderCap_DoesNotIncrementTheRejectionCounter() { // Negative control: the counter is a rejection signal, not an open-session signal. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 3 }); var sut = new BundleSessionStore(opts, clock, NullLogger.Instance); var delta = ReadRejectionCounter(() => sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(0, delta); } /// Verifies that reclaiming expired sessions at the cap does not increment the rejection counter. [Fact] public void Open_AtCapOfExpiredSessions_ReclaimsWithoutIncrementingTheRejectionCounter() { // The load-bearing negative control. The cap check runs TWICE — once before // EvictExpired and once after — and only the post-eviction check is a rejection. // Counting the first would make the series fire routinely on any node whose sweep // has not yet run, turning a page-worthy signal into background noise. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 2 }); var sut = new BundleSessionStore(opts, clock, NullLogger.Instance); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(5))); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(5))); clock.Advance(TimeSpan.FromMinutes(10)); var delta = ReadRejectionCounter(() => sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(0, delta); } /// Verifies that reopening an existing session id at the cap does not increment the rejection counter. [Fact] public void Open_ReopeningAnExistingSessionIdAtCap_DoesNotIncrementTheRejectionCounter() { // Re-Opening an id already in the store skips the cap block entirely and overwrites // in place. It consumes no new slot and turns nobody away, so it must not count. var clock = new TestClock(DateTimeOffset.UtcNow); var opts = Options.Create(new TransportOptions { MaxConcurrentImportSessions = 2 }); var sut = new BundleSessionStore(opts, clock, NullLogger.Instance); var future = clock.GetUtcNow().AddMinutes(30); var first = SessionExpiringAt(future); sut.Open(first); sut.Open(SessionExpiringAt(future)); // Store is now exactly at the cap of 2. var delta = ReadRejectionCounter(() => sut.Open(first)); Assert.Equal(0, delta); } // ------------------------------------------------------------------ // OpenSessionCount / gauge // ------------------------------------------------------------------ /// Verifies that the open session count excludes sessions that expired but have not been swept. [Fact] public void OpenSessionCount_ExcludesExpiredButUnsweptSessions() { // The eviction sweep runs once a minute, so a raw dictionary count would report // the store as pinned at the cap for up to a sweep interval after a burst had // actually drained — exactly the false signal this instrument exists to rule out. var clock = new TestClock(DateTimeOffset.UtcNow); var sut = new BundleSessionStore(Options.Create(new TransportOptions()), clock, NullLogger.Instance); sut.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(5))); var live = SessionExpiringAt(clock.GetUtcNow().AddMinutes(60)); sut.Open(live); Assert.Equal(2, sut.OpenSessionCount); clock.Advance(TimeSpan.FromMinutes(10)); // The short session has expired but nothing has swept it yet. Assert.Equal(1, sut.OpenSessionCount); } /// Verifies that the eviction service registers the gauge provider and clears it on stop. /// A task that represents the asynchronous operation. [Fact] public async Task EvictionService_RegistersTheGaugeProvider_AndClearsItOnStop() { // The eviction service is Transport's only lifecycle seam, so it owns the // process-global gauge slot. Every assertion here is a DELTA over a scoped action // against this test's own store (register row 74) — see ReadGaugeDelta. var clock = new TestClock(DateTimeOffset.UtcNow); var store = new BundleSessionStore(Options.Create(new TransportOptions()), clock, NullLogger.Instance); var service = new BundleSessionEvictionService(store, InertUnlockWindow.Instance, NullLogger.Instance); await service.StartAsync(CancellationToken.None); try { // While registered, this store's opens are what the gauge reports. var whileRegistered = ReadGaugeDelta(() => { store.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30))); store.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30))); }); Assert.Equal(2, whileRegistered); } finally { await service.StopAsync(CancellationToken.None); } // After the clear the gauge no longer reads through this store: opening more // sessions on it moves the instrument by nothing. Stated as a delta this is a // STRONGER claim than the old `Assert.Equal(0, ReadGauge())` — that one merely // said "the instrument reports zero", which any unregistered slot satisfies, // and which a foreign registrant would have failed for reasons unrelated to // the clear. var afterClear = ReadGaugeDelta(() => store.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(0, afterClear); } /// Verifies that stopping an eviction service does not clobber a newer instance's gauge provider. /// A task that represents the asynchronous operation. [Fact] public async Task EvictionService_StopDoesNotClobberANewerInstancesProvider() { // Identity-checked compare-and-clear: a late stop of a superseded instance must // leave a newer registrant's provider in place (mirrors the StoreAndForward // queue-depth gauge's contract). var clock = new TestClock(DateTimeOffset.UtcNow); var oldStore = new BundleSessionStore(Options.Create(new TransportOptions()), clock, NullLogger.Instance); var newStore = new BundleSessionStore(Options.Create(new TransportOptions()), clock, NullLogger.Instance); var oldService = new BundleSessionEvictionService(oldStore, InertUnlockWindow.Instance, NullLogger.Instance); var newService = new BundleSessionEvictionService(newStore, InertUnlockWindow.Instance, NullLogger.Instance); await oldService.StartAsync(CancellationToken.None); await newService.StartAsync(CancellationToken.None); try { // Late stop of the superseded instance, then prove the NEWER store is still // the one driving the gauge — by moving it and measuring the movement. await oldService.StopAsync(CancellationToken.None); var newStoreStillDrivesIt = ReadGaugeDelta(() => newStore.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(1, newStoreStillDrivesIt); // Negative control on the same window: the superseded store is detached, so // its opens must not reach the instrument. Without this, a provider slot left // pointing at oldStore would still satisfy the assertion above by coincidence // whenever both stores happened to hold equal counts. var oldStoreIsDetached = ReadGaugeDelta(() => oldStore.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(0, oldStoreIsDetached); } finally { await newService.StopAsync(CancellationToken.None); } var afterClear = ReadGaugeDelta(() => newStore.Open(SessionExpiringAt(clock.GetUtcNow().AddMinutes(30)))); Assert.Equal(0, afterClear); } // ------------------------------------------------------------------ // Helpers // ------------------------------------------------------------------ /// /// Runs between two observations of the open-import-sessions /// gauge and returns how far the instrument MOVED across it. /// /// /// /// Register row 74. These tests used to assert absolute gauge values — /// Assert.Equal(0, baseline), Assert.Equal(2, ReadGauge()) — against /// what is a single process-global provider slot /// (SetImportSessionCountProvider / ClearImportSessionCountProvider). /// That is the same shape as the register row 32 flake in /// QueueDepthGaugeTests: correct only for as long as this file is the slot's /// sole registrant, and silently wrong the day a sibling suite writes it. A delta /// carries no assumption about what the slot held on entry, so a non-zero inherited /// baseline cancels out. /// /// /// Honest residual, and the reason this is a delta rather than a full fix: unlike /// — where every measurement in the window is /// driven synchronously by this test's own Open call, making it genuinely /// immune — a gauge has ONE slot and last-writer-wins. If a concurrent registrant /// overwrote the slot BETWEEN the two reads, no read-side technique could recover; /// that case needs mutual exclusion on the slot (row 32's serialized collection). /// It cannot arise today: this is the only file in the assembly that constructs a /// BundleSessionEvictionService, and test assemblies run in separate /// processes. A second such file should bring the collection treatment with it. /// /// /// The action to measure across. /// The gauge's movement while ran. private static long ReadGaugeDelta(Action act) { var before = ReadGauge(); act(); return ReadGauge() - before; } /// /// Forces one synchronous observation of the open-import-sessions gauge and returns /// the measured value. Mirrors the MeterListener helper used by the Communication /// and StoreAndForward telemetry suites. Private to by /// convention — see its remarks for why no test reads this absolutely. /// /// The gauge's current value, or 0 if it never reported. private static long ReadGauge() { long observed = 0; using var listener = new MeterListener(); listener.InstrumentPublished = (instrument, l) => { if (instrument.Meter.Name == ScadaBridgeTelemetry.MeterName && instrument.Name == OpenSessionsGauge) { l.EnableMeasurementEvents(instrument); } }; listener.SetMeasurementEventCallback((_, measurement, _, _) => observed = measurement); listener.Start(); listener.RecordObservableInstruments(); return observed; } /// /// Runs with a listener attached to the import-session rejection /// counter and returns the number of rejections recorded DURING that action. /// /// /// Deliberately a delta over a scoped action rather than an absolute read. The counter /// is a process-global static, so an absolute assertion would inherit the register /// row 32 flake that makes QueueDepthGaugeTests fail only under the full /// concurrent suite. A counter measured this way is immune: the listener exists only /// for the duration of , and every increment is driven /// synchronously by this test's own Open call on its own store instance, so a /// concurrently-running test class cannot contribute a measurement to this window. /// /// The action to measure. /// Rejections counted while ran. private static long ReadRejectionCounter(Action act) { long delta = 0; using var listener = new MeterListener(); listener.InstrumentPublished = (instrument, l) => { if (instrument.Meter.Name == ScadaBridgeTelemetry.MeterName && instrument.Name == RejectedSessionsCounter) { l.EnableMeasurementEvents(instrument); } }; listener.SetMeasurementEventCallback((_, measurement, _, _) => delta += measurement); listener.Start(); act(); return delta; } private static BundleSession SessionExpiringAt(DateTimeOffset expiresAt) => new() { SessionId = Guid.NewGuid(), Manifest = StubManifest(), DecryptedContent = Array.Empty(), ExpiresAt = expiresAt, }; private static BundleManifest StubManifest() => new( BundleFormatVersion: 1, SchemaVersion: "1.0", CreatedAtUtc: DateTimeOffset.UnixEpoch, SourceEnvironment: "test", ExportedBy: "t", ScadaBridgeVersion: "1", ContentHash: "0", Encryption: null, Summary: new BundleSummary(0, 0, 0, 0, 0, 0, 0, 0), Contents: Array.Empty()); /// Minimal mutable-clock for deterministic expiry. private sealed class TestClock : TimeProvider { private DateTimeOffset _now; /// Initializes the clock at the given start time. /// The initial time. public TestClock(DateTimeOffset start) { _now = start; } /// public override DateTimeOffset GetUtcNow() => _now; /// Moves the clock forward. /// The amount of time to advance. public void Advance(TimeSpan by) => _now = _now.Add(by); } /// /// Do-nothing for the eviction-service tests. /// The service also ticks the unlock-attempt retention prune (register row 65), but /// these tests exercise only its gauge lifecycle — never ExecuteAsync — so the /// window is present purely to satisfy the constructor. The prune tick itself is /// covered by FleetWideUnlockThrottleTests against the real SQL-backed window. /// private sealed class InertUnlockWindow : IBundleUnlockAttemptWindow { public static readonly InertUnlockWindow Instance = new(); /// public Task TryRegisterAttemptAsync( string clientKey, int maxAttemptsPerWindow, TimeSpan window, CancellationToken ct = default) => Task.FromResult(true); /// public Task PruneAsync(TimeSpan window, CancellationToken ct = default) => Task.CompletedTask; } /// Captures formatted log entries so the cap-rejection Warning can be asserted. private sealed class CapturingLogger : ILogger { /// Gets the captured log entries in emission order. public List<(LogLevel Level, string Message)> Entries { get; } = []; /// Starts no scope; the fake does not track scopes. /// The type of the scope state. /// The scope state, ignored. /// No scope token; the fake does not track scopes. public IDisposable? BeginScope(TState state) where TState : notnull => null; /// Reports every log level as enabled. /// The log level being queried. /// Always . public bool IsEnabled(LogLevel logLevel) => true; /// Records the log entry for later assertions. /// The type of the log state. /// The severity of the entry. /// The event id of the entry. /// The state object being logged. /// The exception associated with the entry, if any. /// Formats the state and exception into the message text. public void Log( LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { Entries.Add((logLevel, formatter(state, exception))); } } }