diff --git a/ZB.MOM.WW.Secrets/CHANGELOG.md b/ZB.MOM.WW.Secrets/CHANGELOG.md index e9c7571..2544c74 100644 --- a/ZB.MOM.WW.Secrets/CHANGELOG.md +++ b/ZB.MOM.WW.Secrets/CHANGELOG.md @@ -5,6 +5,32 @@ follows [Keep a Changelog](https://keepachangelog.com/); versions are shared acr package in the family (see `Directory.Build.props`) even when a given release only touches one of them. +## 0.4.1 — 2026-08-07 + +### Fixed + +- **`ZB.MOM.WW.Secrets.Replicator.Grpc` — the hub now logs its denials.** A ScadaBridge live + gate found that `SecretsHubAuthInterceptor` refused calls correctly but wrote nothing about + it: the only trace of a refusal was a framework `Grpc.AspNetCore.Server` Information line, so + a follower whose bearer token had been mis-rotated silently stopped converging and the hub + showed it only at INF. Every denial is now counted, and a `Warning` summarising the window is + emitted on the first denial after startup or after 60 quiet seconds — carrying the number of + denials since the previous summary plus a breakdown by cause (missing/malformed credential, + wrong credential, hub token unconfigured). A single probe is therefore visible immediately, + while a sustained attack is bounded to one log line per minute — the endpoint is + unauthenticated by construction, so a per-denial warning would be an unbounded log write + driven by an unauthenticated caller. + +### Unchanged + +- **Wire behavior is byte-identical.** The cause breakdown is server-side diagnostics only; every + rejection still returns the same uniform `Unauthenticated` status with the same detail, and the + credential comparison is still constant-time. No token material, presented or configured, + appears in any log line at any level. +- The existing warn-once-on-unconfigured-token line is unchanged and still emitted exactly once; + denials in that state also count toward the new summary's `unconfigured` category. +- Every other package in the family is behaviorally unchanged in this release. + ## 0.4.0 — 2026-08-07 ### Added diff --git a/ZB.MOM.WW.Secrets/Directory.Build.props b/ZB.MOM.WW.Secrets/Directory.Build.props index 45c6ded..cc3f0a8 100644 --- a/ZB.MOM.WW.Secrets/Directory.Build.props +++ b/ZB.MOM.WW.Secrets/Directory.Build.props @@ -5,7 +5,7 @@ enable enable latest - 0.4.0 + 0.4.1 true README.md diff --git a/ZB.MOM.WW.Secrets/src/ZB.MOM.WW.Secrets.Replicator.Grpc/SecretsHubAuthInterceptor.cs b/ZB.MOM.WW.Secrets/src/ZB.MOM.WW.Secrets.Replicator.Grpc/SecretsHubAuthInterceptor.cs index 5f92cfd..e8a11cd 100644 --- a/ZB.MOM.WW.Secrets/src/ZB.MOM.WW.Secrets.Replicator.Grpc/SecretsHubAuthInterceptor.cs +++ b/ZB.MOM.WW.Secrets/src/ZB.MOM.WW.Secrets.Replicator.Grpc/SecretsHubAuthInterceptor.cs @@ -24,6 +24,18 @@ namespace ZB.MOM.WW.Secrets.Replicator.Grpc; /// "wrong token" would hand an attacker a free oracle. /// /// +/// Every denial is counted, and a summary is warned at most once per +/// seconds. A refusal that logs nothing is a follower +/// that silently stops converging — a mis-rotated token showed up on the hub only as a framework +/// Information line. The rate limit is what makes warning at all safe: this endpoint is +/// unauthenticated by definition, so a per-denial warning would be an unbounded log write driven +/// by an unauthenticated caller. +/// +/// +/// The summary's category breakdown is server-side diagnostics only. It never reaches the +/// wire — the response stays the one uniform status regardless of category. +/// +/// /// No token material is ever logged, presented or configured, at any level. /// /// @@ -42,12 +54,33 @@ public sealed class SecretsHubAuthInterceptor : Interceptor /// The one detail every denial carries. It says nothing about why. private const string DenialDetail = "Unauthenticated."; + /// + /// How long one denial summary covers. Deliberately a constant and not a configuration key: + /// there is no deployment for which a different value is right, and an operator-tunable log + /// rate on an unauthenticated endpoint is a knob whose only interesting setting is a dangerous + /// one. + /// + private const int DenialWarningWindowSeconds = 60; + + private static readonly long DenialWarningWindowTicks = + TimeSpan.FromSeconds(DenialWarningWindowSeconds).Ticks; + private readonly byte[] _expectedTokenUtf8; private readonly string _bearerTokenConfigurationKey; private readonly ILogger _logger; + private readonly TimeProvider _timeProvider; private int _unconfiguredWarningEmitted; + // Denials arrive concurrently from any number of callers, so every counter is touched through + // Interlocked and the emit is decided by a single compare-exchange on the last-emit timestamp. + // Zero means "never emitted", which is why the very first denial always wins the window. + private long _lastDenialWarningUtcTicks; + private long _denialsSinceLastWarning; + private long _missingOrMalformedDenials; + private long _wrongCredentialDenials; + private long _unconfiguredDenials; + /// /// Creates the interceptor over the hub's configured token. /// @@ -59,11 +92,20 @@ public sealed class SecretsHubAuthInterceptor : Interceptor /// /// The hub options carrying the shared bearer token. /// Diagnostics sink. Never receives token material. + /// + /// Clock behind the denial-warning rate limit. Optional — a default-valued parameter rather than + /// a second overload, because the single-public-constructor rule above admits no overload; both + /// the container's activator and ActivatorUtilities honour the default when nothing is + /// registered, so a host that registers a gets its own and one that + /// does not gets . + /// public SecretsHubAuthInterceptor( IOptions options, - ILogger logger) + ILogger logger, + TimeProvider? timeProvider = null) { ArgumentNullException.ThrowIfNull(options); + _timeProvider = timeProvider ?? TimeProvider.System; SecretsGrpcHubServerOptions value = options.Value; _logger = logger ?? throw new ArgumentNullException(nameof(logger)); @@ -135,7 +177,7 @@ public sealed class SecretsHubAuthInterceptor : Interceptor if (_expectedTokenUtf8.Length == 0) { WarnUnconfiguredOnce(); - throw Denied(); + throw DeniedAs(DenialCategory.Unconfigured); } Metadata headers = context.RequestHeaders; @@ -157,12 +199,12 @@ public sealed class SecretsHubAuthInterceptor : Interceptor if (authorizationHeaderCount != 1 || presented is null) { - throw Denied(); + throw DeniedAs(DenialCategory.MissingOrMalformed); } if (!presented.StartsWith(BearerScheme, StringComparison.Ordinal)) { - throw Denied(); + throw DeniedAs(DenialCategory.MissingOrMalformed); } // FixedTimeEquals compares in time independent of the contents, and returns false for a @@ -171,7 +213,7 @@ public sealed class SecretsHubAuthInterceptor : Interceptor byte[] presentedTokenUtf8 = Encoding.UTF8.GetBytes(presented[BearerScheme.Length..]); if (!CryptographicOperations.FixedTimeEquals(presentedTokenUtf8, _expectedTokenUtf8)) { - throw Denied(); + throw DeniedAs(DenialCategory.WrongCredential); } } @@ -181,6 +223,99 @@ public sealed class SecretsHubAuthInterceptor : Interceptor /// private static RpcException Denied() => new(new Status(StatusCode.Unauthenticated, DenialDetail)); + /// + /// Records a denial in , emits the window's summary if this call is + /// the one that opened a new window, and returns the same uniform denial every path throws. + /// + /// + /// The category only ever reaches the local log. is called unchanged, so + /// the status a caller receives is byte-identical whatever brought it here — bookkeeping runs + /// strictly after the decision and cannot alter it. + /// + private RpcException DeniedAs(DenialCategory category) + { + switch (category) + { + case DenialCategory.MissingOrMalformed: + Interlocked.Increment(ref _missingOrMalformedDenials); + break; + case DenialCategory.WrongCredential: + Interlocked.Increment(ref _wrongCredentialDenials); + break; + default: + Interlocked.Increment(ref _unconfiguredDenials); + break; + } + + Interlocked.Increment(ref _denialsSinceLastWarning); + WarnDeniedIfWindowElapsed(); + + return Denied(); + } + + /// + /// Emits one summary per window, drained of everything counted since the previous one. + /// + /// + /// + /// The first denial after startup — and the first after any quiet period longer than the window + /// — warns immediately, so a single probe is visible rather than being averaged away. + /// + /// + /// Exactly one thread emits per window: the compare-exchange publishes the new window start + /// only for the caller that observed the old one, and every loser returns without logging. The + /// counters are then drained with , so a + /// denial counted a moment after the drain is carried into the NEXT summary rather than lost. + /// + /// + private void WarnDeniedIfWindowElapsed() + { + long now = _timeProvider.GetUtcNow().UtcTicks; + long lastEmitted = Volatile.Read(ref _lastDenialWarningUtcTicks); + + if (now - lastEmitted < DenialWarningWindowTicks) + { + return; + } + + if (Interlocked.CompareExchange(ref _lastDenialWarningUtcTicks, now, lastEmitted) != lastEmitted) + { + return; + } + + long total = Interlocked.Exchange(ref _denialsSinceLastWarning, 0); + long missingOrMalformed = Interlocked.Exchange(ref _missingOrMalformedDenials, 0); + long wrongCredential = Interlocked.Exchange(ref _wrongCredentialDenials, 0); + long unconfigured = Interlocked.Exchange(ref _unconfiguredDenials, 0); + + _logger.LogWarning( + "The gRPC secrets hub denied {DeniedCount} call(s) since the previous such warning " + + "(missing or malformed credential: {MissingOrMalformedCount}; wrong credential: " + + "{WrongCredentialCount}; hub token unconfigured: {UnconfiguredCount}). Denials are " + + "summarised at most once every {DenialWarningWindowSeconds}s.", + total, + missingOrMalformed, + wrongCredential, + unconfigured, + DenialWarningWindowSeconds); + } + + /// + /// Why a denial happened, for the local summary only. This never reaches a caller — telling one + /// apart from another on the wire is exactly the oracle the uniform denial exists to withhold. + /// + private enum DenialCategory + { + /// No Authorization header, more than one, or one that is not a bearer. + MissingOrMalformed, + + /// A well-formed bearer credential that is not the configured one. + WrongCredential, + + /// The hub has no token configured, so nothing could have been accepted. + Unconfigured, + } + /// /// Warns once — not once per call — that the hub cannot serve, naming the exact key to set. A /// per-call warning would bury the one line that matters under the flood it describes. diff --git a/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubAuthInterceptorTests.cs b/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubAuthInterceptorTests.cs index aea1cd1..a722deb 100644 --- a/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubAuthInterceptorTests.cs +++ b/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubAuthInterceptorTests.cs @@ -83,13 +83,20 @@ public sealed class SecretsHubAuthInterceptorTests await AssertDeniedAsync(interceptor, $"Bearer {ConfiguredToken}"); } + // Scoped to the CONFIGURATION warning. The denial summary is a second, deliberately + // separate warning on this same path (one says "set a key", the other says "callers are + // being turned away"), so counting every Warning would no longer measure what this pins. List warnings = logger.Entries - .Where(e => e.Level == LogLevel.Warning) + .Where(e => e.Level == LogLevel.Warning + && e.Message.Contains("no bearer token configured", StringComparison.Ordinal)) .Select(e => e.Message) .ToList(); string warning = Assert.Single(warnings); Assert.Contains("Secrets:GrpcHub:BearerToken", warning, StringComparison.Ordinal); + + // …and the denial summary is still rate-limited to one line across the same three calls. + Assert.Single(DenialWarnings(logger)); } [Fact] @@ -279,6 +286,160 @@ public sealed class SecretsHubAuthInterceptorTests } } + // ---- the rate-limited denial warning (live-gate finding: denials were logged nowhere) ---- + + [Fact] + public async Task The_first_denial_warns_immediately() + { + // A single probe has to be visible. The rate limit bounds a flood; it must not swallow the + // one denial an operator is most likely to be looking for. + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out _); + + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); + + string warning = Assert.Single(DenialWarnings(logger)); + Assert.Contains("denied 1", warning, StringComparison.Ordinal); + } + + [Fact] + public async Task A_second_denial_inside_the_window_does_not_warn_again() + { + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out HubFakeTimeProvider clock); + + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); + clock.Advance(TimeSpan.FromSeconds(59)); + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); + + Assert.Single(DenialWarnings(logger)); + } + + [Fact] + public async Task A_denial_after_the_window_warns_and_reports_what_was_suppressed() + { + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out HubFakeTimeProvider clock); + + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); // warns: 1 + for (int i = 0; i < 4; i++) + { + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); // suppressed: 4 + } + + clock.Advance(TimeSpan.FromSeconds(61)); + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); // warns: 4 + 1 + + List warnings = DenialWarnings(logger); + Assert.Equal(2, warnings.Count); + Assert.Contains("denied 1", warnings[0], StringComparison.Ordinal); + Assert.Contains("denied 5", warnings[1], StringComparison.Ordinal); + } + + [Fact] + public async Task The_warning_breaks_the_denials_down_by_category() + { + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out HubFakeTimeProvider clock); + + // The first denial opens the window and is drained on its own, so the counts asserted below + // are those of the SECOND window: everything from the "Basic abc" through the closing one. + await AssertDeniedAsync(interceptor, header: null); // missing — emits (1) + await AssertDeniedAsync(interceptor, "Basic abc"); // malformed + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); // wrong + await AssertDeniedAsync(interceptor, "Bearer also-wrong"); // wrong + await AssertDeniedAsync(interceptor, "Bearer still-wrong"); // wrong + + clock.Advance(TimeSpan.FromSeconds(61)); + await AssertDeniedAsync(interceptor, header: null); // missing — emits (5) + + string summary = DenialWarnings(logger)[1]; + Assert.Contains("denied 5", summary, StringComparison.Ordinal); + Assert.Contains("missing or malformed credential: 2", summary, StringComparison.Ordinal); + Assert.Contains("wrong credential: 3", summary, StringComparison.Ordinal); + Assert.Contains("hub token unconfigured: 0", summary, StringComparison.Ordinal); + } + + [Fact] + public async Task A_denial_on_an_unconfigured_hub_counts_as_unconfigured() + { + // The warn-once config signal and the denial summary are different signals: the first says + // "an operator has to set a key", the second says "callers are being turned away right now". + SecretsHubAuthInterceptor interceptor = Build( + string.Empty, out HubCapturingLogger logger, out HubFakeTimeProvider clock); + + await AssertDeniedAsync(interceptor, $"Bearer {ConfiguredToken}"); + await AssertDeniedAsync(interceptor, $"Bearer {ConfiguredToken}"); + clock.Advance(TimeSpan.FromSeconds(61)); + await AssertDeniedAsync(interceptor, $"Bearer {ConfiguredToken}"); + + string summary = DenialWarnings(logger)[1]; + Assert.Contains("denied 2", summary, StringComparison.Ordinal); + Assert.Contains("hub token unconfigured: 2", summary, StringComparison.Ordinal); + Assert.Contains("missing or malformed credential: 0", summary, StringComparison.Ordinal); + + // …and the unset-token warning is still emitted exactly once, unaffected. + Assert.Single( + logger.Entries, + e => e.Level == LogLevel.Warning + && e.Message.Contains("no bearer token configured", StringComparison.Ordinal)); + } + + [Fact] + public async Task A_concurrent_burst_emits_exactly_one_warning() + { + // The endpoint is unauthenticated, so the denial path is reachable by anyone at any rate; + // a per-denial warning would be an unbounded log write driven by an unauthenticated caller. + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out _); + + const int callers = 64; + using var gate = new Barrier(callers); + await Task.WhenAll(Enumerable.Range(0, callers).Select(_ => Task.Run(async () => + { + gate.SignalAndWait(); + await AssertDeniedAsync(interceptor, "Bearer wrong-token-value"); + }))); + + // Exactly one line, whatever the interleaving. The COUNT it reports is deliberately not + // asserted: a denial that increments after the winning thread drained the counter is carried + // into the next window rather than lost, so any value in 1..callers is correct here. + Assert.Single(DenialWarnings(logger)); + } + + [Fact] + public async Task The_denial_warning_never_carries_token_material() + { + const string presented = "presented-token-that-must-not-be-logged"; + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out HubFakeTimeProvider clock); + + await AssertDeniedAsync(interceptor, $"Bearer {presented}"); + clock.Advance(TimeSpan.FromSeconds(61)); + await AssertDeniedAsync(interceptor, $"Bearer {presented}"); + + Assert.Equal(2, DenialWarnings(logger).Count); + foreach (string message in logger.Entries.Select(e => e.Message)) + { + Assert.DoesNotContain(ConfiguredToken, message, StringComparison.OrdinalIgnoreCase); + Assert.DoesNotContain(presented, message, StringComparison.OrdinalIgnoreCase); + } + } + + [Fact] + public async Task An_accepted_call_never_warns() + { + SecretsHubAuthInterceptor interceptor = Build( + ConfiguredToken, out HubCapturingLogger logger, out _); + + await interceptor.UnaryServerHandler( + new GetManifestRequest(), + HubServerCallContextStub.WithAuthorization($"Bearer {ConfiguredToken}"), + (_, _) => Task.FromResult(new GetManifestResponse())); + + Assert.DoesNotContain(logger.Entries, e => e.Level == LogLevel.Warning); + } + [Fact] public void Interceptor_has_exactly_one_public_constructor() { @@ -291,13 +452,28 @@ public sealed class SecretsHubAuthInterceptorTests Assert.Single(ctors); } - private static SecretsHubAuthInterceptor Build(string token, out HubCapturingLogger logger) + private static SecretsHubAuthInterceptor Build(string token, out HubCapturingLogger logger) => + Build(token, out logger, out _); + + private static SecretsHubAuthInterceptor Build( + string token, + out HubCapturingLogger logger, + out HubFakeTimeProvider clock) { logger = new HubCapturingLogger(); + clock = new HubFakeTimeProvider(); var options = new SecretsGrpcHubServerOptions { BearerToken = token }; - return new SecretsHubAuthInterceptor(Options.Create(options), logger); + return new SecretsHubAuthInterceptor(Options.Create(options), logger, clock); } + /// The rate-limited denial summaries only — not the unset-token configuration warning. + private static List DenialWarnings(HubCapturingLogger logger) => + logger.Entries + .Where(e => e.Level == LogLevel.Warning + && e.Message.Contains("The gRPC secrets hub denied", StringComparison.Ordinal)) + .Select(e => e.Message) + .ToList(); + private static async Task AssertDeniedAsync( SecretsHubAuthInterceptor interceptor, string? header) { @@ -396,6 +572,27 @@ internal sealed class HubAsyncStreamReaderStub : IAsyncStreamReader public Task MoveNext(CancellationToken cancellationToken) => Task.FromResult(false); } +/// +/// A manually advanced clock, so the denial-warning rate limit is exercised by moving time rather +/// than by sleeping through a 60-second window. +/// +/// +/// Hand-rolled rather than taken from Microsoft.Extensions.TimeProvider.Testing, which this +/// project deliberately does not reference — only is needed. +/// Reads are volatile because the concurrency test drives it from many threads at once. +/// +internal sealed class HubFakeTimeProvider : TimeProvider +{ + private long _utcTicks = new DateTime(2026, 8, 7, 12, 0, 0, DateTimeKind.Utc).Ticks; + + /// + public override DateTimeOffset GetUtcNow() => + new(Volatile.Read(ref _utcTicks), TimeSpan.Zero); + + /// Moves the clock forward by . + public void Advance(TimeSpan delta) => Interlocked.Add(ref _utcTicks, delta.Ticks); +} + /// Captures formatted log messages so tests can assert on what was — and was not — logged. internal sealed class HubCapturingLogger : ILogger { diff --git a/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubIntegrationTests.cs b/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubIntegrationTests.cs index ecf2c77..13e0924 100644 --- a/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubIntegrationTests.cs +++ b/ZB.MOM.WW.Secrets/tests/ZB.MOM.WW.Secrets.Replicator.Grpc.Tests/SecretsHubIntegrationTests.cs @@ -317,8 +317,18 @@ public sealed class SecretsHubIntegrationTests : IAsyncLifetime () => client.Hub.GetManifestAsync(CancellationToken.None)); } - CapturedLog warning = Assert.Single(server.Logs.WarningsFrom()); + // Scoped to the CONFIGURATION warning, because the interceptor deliberately emits a second + // kind on this path: a rate-limited summary of the denials themselves. Both are warnings + // from the same category, so an unfiltered Single would now be counting two signals as one. + IReadOnlyList warnings = server.Logs.WarningsFrom(); + CapturedLog warning = Assert.Single( + warnings, w => w.Message.Contains("no bearer token configured", StringComparison.Ordinal)); Assert.Contains("Secrets:GrpcHub:BearerToken", warning.Message, StringComparison.Ordinal); + + // And the denial summary is likewise once, not once per refused caller — the point of the + // rate limit, checked here through the real registration rather than a hand-built instance. + Assert.Single( + warnings, w => w.Message.Contains("The gRPC secrets hub denied", StringComparison.Ordinal)); } [Fact]