feat(secrets): 0.6.3 — hub sweep outcome logging (in-sync debug + hourly heartbeat + recovered) and ISecretsHubSyncStatus

GrpcSecretSyncService's background sweep now records outcomes on a new
SecretsHubSyncStatus (registered singleton, exposed as public
ISecretsHubSyncStatus) and logs three new events on the outcome-recording
path: EventId 4 (Debug, every in-sync sweep), EventId 5 (Information, the
same outcome throttled to at most once per the new
SecretsGrpcHubClientOptions.InSyncLogInterval, default 1h), and EventId 6
(Information, the first sweep to succeed after one or more failures).
EventIds 1-3 are unchanged; the raw internal SweepAsync still throws on
failure exactly as before. Not yet published to the Gitea feed and
ScadaBridge is not re-pinned — that is a separate, later step.
This commit is contained in:
Joseph Doherty
2026-09-28 17:26:25 -04:00
parent 5c73be486d
commit b392b84f21
8 changed files with 475 additions and 10 deletions
@@ -150,6 +150,15 @@ public static class SecretsGrpcHubClientExtensions
});
}
// Singleton, and registered for BOTH the concrete type and the public interface: the
// service needs the concrete type (it calls the internal RecordSuccess/RecordFailure), and
// an application observing hub-sync health (a readiness check, a status page) needs only
// the read-only ISecretsHubSyncStatus. TryAddSingleton for the concrete type means the
// interface registration below resolves the SAME instance rather than constructing a second
// one, which would silently split "what the service records" from "what a consumer reads".
services.TryAddSingleton<SecretsHubSyncStatus>();
services.TryAddSingleton<ISecretsHubSyncStatus>(sp => sp.GetRequiredService<SecretsHubSyncStatus>());
services.AddHostedService<GrpcSecretSyncService>();
return services;
@@ -36,6 +36,13 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
private readonly SecretsGrpcHubClientOptions _options;
private readonly ILogger<GrpcSecretSyncService> _logger;
private readonly TimeProvider _timeProvider;
private readonly SecretsHubSyncStatus _status;
// Last time a row actually moved, and last time the in-sync heartbeat was logged — both
// instance state because they describe THIS service's observed history, not anything the hub
// or the local store can answer on demand.
private DateTimeOffset? _lastPullUtc;
private DateTimeOffset? _lastInSyncHeartbeatUtc;
/// <summary>Creates the sync service.</summary>
/// <param name="local">The node's local store — the only thing this service writes to.</param>
@@ -44,13 +51,20 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
/// <param name="options">Hub-client options.</param>
/// <param name="logger">Logger for sweep outcomes and failures.</param>
/// <param name="timeProvider">Clock, injectable so tests need not wait a real interval.</param>
/// <param name="status">
/// The sweep-outcome tracker this service updates. Optional so existing callers that construct
/// this type directly (tests, mainly) keep compiling; a real host resolves the same singleton
/// <c>AddZbSecretsGrpcHubClient</c> registers for <see cref="ISecretsHubSyncStatus"/>, so the two
/// stay the same instance.
/// </param>
public GrpcSecretSyncService(
ISecretStore local,
ISecretsHubReader hub,
ISecretCacheInvalidator? cacheInvalidator,
IOptions<SecretsGrpcHubClientOptions> options,
ILogger<GrpcSecretSyncService> logger,
TimeProvider? timeProvider = null)
TimeProvider? timeProvider = null,
SecretsHubSyncStatus? status = null)
{
ArgumentNullException.ThrowIfNull(options);
ArgumentNullException.ThrowIfNull(local);
@@ -59,6 +73,7 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
_options = options.Value;
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_timeProvider = timeProvider ?? TimeProvider.System;
_status = status ?? new SecretsHubSyncStatus();
_reconciler = new SecretReplicationReconciler(
local,
cacheInvalidator,
@@ -82,11 +97,22 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
}
/// <summary>
/// Runs one pull-only reconcile against the hub.
/// Runs one pull-only reconcile against the hub. Throws on any failure — an unreachable hub, a
/// rejected credential, a deadline — so a direct caller sees the raw outcome. The background
/// loop never calls this directly; it goes through <see cref="SweepAndRecordAsync"/>, which
/// shares this method's reconcile core but also records the outcome and logs it.
/// </summary>
/// <param name="ct">A token to cancel the sweep.</param>
/// <returns>How many rows were pulled from the hub.</returns>
internal async Task<int> SweepAsync(CancellationToken ct)
internal async Task<int> SweepAsync(CancellationToken ct) =>
(await SweepCoreAsync(ct).ConfigureAwait(false)).Pulled;
/// <summary>
/// The reconcile core shared by <see cref="SweepAsync"/> and <see cref="SweepAndRecordAsync"/>:
/// fetches the hub manifest and reconciles the local store against it. Throws on failure —
/// callers that want failures recorded/logged instead do that around this call, not inside it.
/// </summary>
private async Task<(int Pulled, int ManifestCount)> SweepCoreAsync(CancellationToken ct)
{
IReadOnlyList<SecretManifestEntry> hubManifest =
await _hub.GetManifestAsync(ct).ConfigureAwait(false);
@@ -97,20 +123,54 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
// it rather than re-deriving the diff here also keeps the batching: a cold-starting node's
// pull set is central's ENTIRE inventory, and an unchunked GetSecrets would exceed gRPC's
// 4 MB default message cap and then fail identically on every interval forever.
return await _reconciler
int pulled = await _reconciler
.ReconcileAsync(hubManifest, (names, token) => _hub.GetManyAsync(names, token), ct)
.ConfigureAwait(false);
return (pulled, hubManifest.Count);
}
private async Task SweepSafelyAsync(CancellationToken ct)
private Task SweepSafelyAsync(CancellationToken ct) => SweepAndRecordAsync(ct);
/// <summary>
/// Test-only entry point for the same outcome-recording sweep the background loop runs — never
/// throws, always updates <see cref="ISecretsHubSyncStatus"/>, and logs exactly as a real tick
/// would. Exists so a test can drive one sweep at a time without standing up the
/// <see cref="BackgroundService"/> host lifecycle.
/// </summary>
/// <param name="ct">A token to cancel the sweep.</param>
internal Task SweepForTestAsync(CancellationToken ct) => SweepAndRecordAsync(ct);
private async Task SweepAndRecordAsync(CancellationToken ct)
{
DateTimeOffset now = _timeProvider.GetUtcNow();
try
{
int pulled = await SweepAsync(ct).ConfigureAwait(false);
(int pulled, int manifestCount) = await SweepCoreAsync(ct).ConfigureAwait(false);
int priorFailures = _status.RecordSuccess(now);
if (priorFailures > 0)
{
LogSweepRecovered(priorFailures);
}
if (pulled > 0)
{
LogSweepConverged(pulled);
_lastPullUtc = now;
}
else
{
LogSweepInSync(manifestCount);
if (_lastInSyncHeartbeatUtc is null ||
now - _lastInSyncHeartbeatUtc.Value >= _options.InSyncLogInterval)
{
LogSweepInSyncHeartbeat(manifestCount, _lastPullUtc);
_lastInSyncHeartbeatUtc = now;
}
}
}
catch (OperationCanceledException) when (ct.IsCancellationRequested)
@@ -124,6 +184,7 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
// has the same correct response: keep serving the local store and try again. Letting any
// of it escape would fault the BackgroundService and take the host down over a transient
// central outage, which is precisely the availability the pull-only topology exists for.
_status.RecordFailure(now, ex);
LogSweepFailed(ex);
}
}
@@ -145,4 +206,36 @@ internal sealed partial class GrpcSecretSyncService : BackgroundService
Level = LogLevel.Warning,
Message = "Discarding replicated secret row {SecretName} that could not be applied locally; the rest of the batch continues.")]
private partial void LogRowDiscarded(Exception exception, string secretName);
/// <summary>
/// Logged at Debug on every sweep that found nothing to pull — the full-cadence signal, for a
/// verbose log level, that the loop is alive and agrees with the hub even between the rare
/// Information-level heartbeats.
/// </summary>
[LoggerMessage(
EventId = 4,
Level = LogLevel.Debug,
Message = "Secrets hub sweep found nothing new; {Count} secret(s) already in sync.")]
private partial void LogSweepInSync(int count);
/// <summary>
/// Logged at Information at most once per <see cref="SecretsGrpcHubClientOptions.InSyncLogInterval"/>
/// — an in-sync sweep is otherwise Debug-only, so this is the periodic proof at the default log
/// level that the follower is still converged rather than silently stuck.
/// </summary>
[LoggerMessage(
EventId = 5,
Level = LogLevel.Information,
Message = "Secrets hub in sync ({Count} secret(s)); last change pulled {LastPullUtc}")]
private partial void LogSweepInSyncHeartbeat(int count, DateTimeOffset? lastPullUtc);
/// <summary>
/// Logged at Information the first time a sweep succeeds after one or more failures — the
/// recovery line that closes out whatever run of <see cref="LogSweepFailed"/> Warnings preceded it.
/// </summary>
[LoggerMessage(
EventId = 6,
Level = LogLevel.Information,
Message = "Secrets hub sync recovered after {Failures} failed sweep(s)")]
private partial void LogSweepRecovered(int failures);
}
@@ -0,0 +1,87 @@
namespace ZB.MOM.WW.Secrets.Replicator.Grpc;
/// <summary>Point-in-time outcome of the hub follower's sweeps. Never carries secret material.</summary>
/// <remarks>
/// Registered as a singleton by <c>AddZbSecretsGrpcHubClient</c> alongside the background sweep
/// service, so a host can surface hub-sync health (a readiness check, a status page) without
/// scraping logs. Every field reflects the outcome of the most recently completed sweep only —
/// there is deliberately no history here, just "what happened last time".
/// </remarks>
public interface ISecretsHubSyncStatus
{
/// <summary>
/// When the most recent sweep finished, whether it succeeded or failed. <see langword="null"/>
/// before the first sweep has completed.
/// </summary>
DateTimeOffset? LastSweepUtc { get; }
/// <summary>
/// When the most recent <em>successful</em> sweep finished. <see langword="null"/> if no sweep
/// has ever succeeded.
/// </summary>
DateTimeOffset? LastSuccessUtc { get; }
/// <summary>
/// The number of sweeps that have failed in a row, ending at the most recent sweep. Reset to
/// zero the moment a sweep succeeds.
/// </summary>
int ConsecutiveFailures { get; }
/// <summary>
/// The message from the most recent sweep failure, or <see langword="null"/> if the most recent
/// sweep succeeded (or none has run yet). This is the exception's type and message only — never
/// a stack trace, and never secret material, since the sweep never has plaintext in scope.
/// </summary>
string? LastError { get; }
}
/// <summary>The mutable implementation the sync service writes to; consumers see only the interface.</summary>
internal sealed class SecretsHubSyncStatus : ISecretsHubSyncStatus
{
private readonly object _gate = new();
/// <inheritdoc/>
public DateTimeOffset? LastSweepUtc { get; private set; }
/// <inheritdoc/>
public DateTimeOffset? LastSuccessUtc { get; private set; }
/// <inheritdoc/>
public int ConsecutiveFailures { get; private set; }
/// <inheritdoc/>
public string? LastError { get; private set; }
/// <summary>
/// Records a successful sweep, resetting the failure streak.
/// </summary>
/// <param name="now">The instant the sweep completed.</param>
/// <returns>
/// The consecutive-failure count <em>before</em> this success — the caller uses a non-zero
/// result to decide whether the sweep is a recovery worth logging.
/// </returns>
internal int RecordSuccess(DateTimeOffset now)
{
lock (_gate)
{
int prior = ConsecutiveFailures;
LastSweepUtc = LastSuccessUtc = now;
ConsecutiveFailures = 0;
LastError = null;
return prior;
}
}
/// <summary>Records a failed sweep, extending the failure streak.</summary>
/// <param name="now">The instant the sweep failed.</param>
/// <param name="ex">The exception the sweep failed with.</param>
internal void RecordFailure(DateTimeOffset now, Exception ex)
{
lock (_gate)
{
LastSweepUtc = now;
ConsecutiveFailures++;
LastError = ex.GetType().Name + ": " + ex.Message;
}
}
}
@@ -77,6 +77,20 @@ public sealed class SecretsGrpcHubClientOptions
/// </summary>
public TimeSpan CallDeadline { get; set; } = TimeSpan.FromSeconds(30);
/// <summary>
/// How often an in-sync sweep (nothing to pull) is allowed to log an Information-level
/// heartbeat. Defaults to one hour. Must be positive.
/// </summary>
/// <remarks>
/// A converged follower sweeps every <see cref="SyncInterval"/> — 30 seconds by default — and
/// finds nothing new almost every time. Logging that outcome at Information on every sweep
/// would drown the log; staying silent forever would make "the sweep loop is alive and the hub
/// still agrees with this node" unobservable between the rare sweeps that actually pull
/// something. Every sweep still logs at Debug regardless of this interval, so a verbose log
/// level shows the true cadence when it is needed.
/// </remarks>
public TimeSpan InSyncLogInterval { get; set; } = TimeSpan.FromHours(1);
/// <summary>
/// Throws if the options are unusable. Called by the DI extension at registration time so a
/// misconfigured node fails at startup rather than on the first silent sweep failure.
@@ -161,6 +175,13 @@ public sealed class SecretsGrpcHubClientOptions
$"gRPC secrets hub client CallDeadline must be positive " +
$"({sectionPath}:CallDeadline, was {CallDeadline}).");
}
if (InSyncLogInterval <= TimeSpan.Zero)
{
throw new InvalidOperationException(
$"gRPC secrets hub client InSyncLogInterval must be positive " +
$"({sectionPath}:InSyncLogInterval, was {InSyncLogInterval}).");
}
}
/// <summary>The configuration section these options are bound from unless a caller overrides it.</summary>