fix(secrets): rate-limited denial warning on the Grpc hub (live-gate finding) — 0.4.1
The ScadaBridge live gate (check 4) found SecretsHubAuthInterceptor denying correctly but logging nothing: the only trace of a refusal was a framework Grpc.AspNetCore.Server Information line. A follower whose bearer token was mis-rotated therefore stopped converging silently, with the hub showing it only at INF. Every denial is now counted and summarised in a Warning emitted on the first denial after startup or after a 60-second quiet window, carrying the denials since the previous summary plus a breakdown by cause. A single probe is visible immediately; a sustained flood is bounded to one line per window, which is what makes warning safe at all — the endpoint is unauthenticated by construction, so a per-denial warning would be an unbounded log write driven by an unauthenticated caller. Counters are Interlocked and the emit is decided by a compare-exchange on the last-emit timestamp, so exactly one thread emits per window and a denial counted after the drain carries into the next summary rather than being lost. The cause breakdown is server-side diagnostics only. Denied() is untouched: every rejection still returns the identical uniform Unauthenticated status, the comparison is still constant-time, and no token material appears in any log line. The existing warn-once-on-unconfigured-token signal is unchanged and still emitted exactly once; denials in that state count toward the new summary's "unconfigured" category. TimeProvider is an optional default-valued parameter rather than a second overload — the type must keep exactly one public constructor or the gRPC interceptor activator silently stops invoking the auth gate. Two existing tests scoped their assertions to the configuration warning, since both kinds now share a category: the new line is deliberate behavior, not drift. Claude-Session: https://claude.ai/code/session_014WNM4vjoVksyyBraTXSZE1
This commit is contained in:
Joseph Doherty
+200
-3
@@ -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<string> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<string> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> 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<SecretsHubAuthInterceptor> logger)
|
||||
private static SecretsHubAuthInterceptor Build(string token, out HubCapturingLogger<SecretsHubAuthInterceptor> logger) =>
|
||||
Build(token, out logger, out _);
|
||||
|
||||
private static SecretsHubAuthInterceptor Build(
|
||||
string token,
|
||||
out HubCapturingLogger<SecretsHubAuthInterceptor> logger,
|
||||
out HubFakeTimeProvider clock)
|
||||
{
|
||||
logger = new HubCapturingLogger<SecretsHubAuthInterceptor>();
|
||||
clock = new HubFakeTimeProvider();
|
||||
var options = new SecretsGrpcHubServerOptions { BearerToken = token };
|
||||
return new SecretsHubAuthInterceptor(Options.Create(options), logger);
|
||||
return new SecretsHubAuthInterceptor(Options.Create(options), logger, clock);
|
||||
}
|
||||
|
||||
/// <summary>The rate-limited denial summaries only — not the unset-token configuration warning.</summary>
|
||||
private static List<string> DenialWarnings(HubCapturingLogger<SecretsHubAuthInterceptor> 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<RpcException> AssertDeniedAsync(
|
||||
SecretsHubAuthInterceptor interceptor, string? header)
|
||||
{
|
||||
@@ -396,6 +572,27 @@ internal sealed class HubAsyncStreamReaderStub<T> : IAsyncStreamReader<T>
|
||||
public Task<bool> MoveNext(CancellationToken cancellationToken) => Task.FromResult(false);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A manually advanced clock, so the denial-warning rate limit is exercised by moving time rather
|
||||
/// than by sleeping through a 60-second window.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// Hand-rolled rather than taken from <c>Microsoft.Extensions.TimeProvider.Testing</c>, which this
|
||||
/// project deliberately does not reference — only <see cref="TimeProvider.GetUtcNow"/> is needed.
|
||||
/// Reads are volatile because the concurrency test drives it from many threads at once.
|
||||
/// </remarks>
|
||||
internal sealed class HubFakeTimeProvider : TimeProvider
|
||||
{
|
||||
private long _utcTicks = new DateTime(2026, 8, 7, 12, 0, 0, DateTimeKind.Utc).Ticks;
|
||||
|
||||
/// <inheritdoc/>
|
||||
public override DateTimeOffset GetUtcNow() =>
|
||||
new(Volatile.Read(ref _utcTicks), TimeSpan.Zero);
|
||||
|
||||
/// <summary>Moves the clock forward by <paramref name="delta"/>.</summary>
|
||||
public void Advance(TimeSpan delta) => Interlocked.Add(ref _utcTicks, delta.Ticks);
|
||||
}
|
||||
|
||||
/// <summary>Captures formatted log messages so tests can assert on what was — and was not — logged.</summary>
|
||||
internal sealed class HubCapturingLogger<TCategory> : ILogger<TCategory>
|
||||
{
|
||||
|
||||
Reference in New Issue
Block a user