fix(logging): row 71 — stop logging the standby's by-design active-node verdict at ERROR
A healthy standby logged "Health check active-node with status Unhealthy … 'not the site pair primary (standby)'" at Error on every probe — every 10s on a site node, and (discovered while fixing this) every 5s on a central standby, which Traefik health-probes at that cadence. Correct-by-design state at an alarming severity: it floods the log and trains operators to ignore ERR. Mechanism: DefaultHealthCheckService logs one line per check per probe and picks the level from the verdict — Debug/Warning/Error for Healthy/Degraded/Unhealthy. Both active-node checks answer Unhealthy on the standby because 503 IS the contract /health/active publishes. There is no IHealthCheckPublisher in this repo, so each line is one inbound HTTP probe. Fix: one Serilog exclusion filter in LoggerConfigurationFactory. A level override could not work — Serilog's MinimumLevel.Override only RAISES a per-source floor, and a LogEvent's Level is immutable, so neither an override nor an enricher can rewrite Error as Information. Changing the check to report Degraded was rejected: it would alter the HTTP status that /health/active publishes, which is load-bearing for Traefik and the family dashboard. The constraint (genuine failures must still log at Error) is preserved by keying the predicate on the check NAME rather than the logger category: localdb, akka-cluster, database and required-singletons keep their Error lines, and the active-node check has no error path of its own — the active node always answers Healthy — so the only event this can ever suppress is a standby reporting that it is a standby. The verdict stays fully observable via /health/active's own HTTP status, the readiness probe's cluster view, and the health dashboard. Also corrects a stale CLAUDE.md claim found while verifying what consumes this check: "/health/active is central-only (site nodes map no /health/* at all)" is wrong — SiteServiceRegistration registers akka-cluster + localdb + the role-scoped SitePairActiveNodeHealthCheck, and Program.cs's Site branch calls MapZbHealth() on the HTTP/1.1 listener. Fail-before evidence: with the filter behaviourally disabled, StandbyActiveNodeVerdict_IsNotLogged fails "Collection was not empty" while the other 9 tests in the file — the must-still-log constraints — pass either way, which is what proves the filter is narrow rather than a blanket suppression. Tests: Host 518 green (10 new).
This commit is contained in:
@@ -85,12 +85,91 @@ public static class LoggerConfigurationFactory
|
||||
return new LoggerConfiguration()
|
||||
.ReadFrom.Configuration(configuration)
|
||||
.MinimumLevel.Is(minimumLevel)
|
||||
// Register row 71. Drop ONLY the framework's Error line for the by-design
|
||||
// standby verdict of the active-node probe. See IsExpectedStandbyActiveNodeProbe
|
||||
// for why this cannot hide a genuine failure.
|
||||
.Filter.ByExcluding(IsExpectedStandbyActiveNodeProbe)
|
||||
.Enrich.WithProperty("SiteId", siteId)
|
||||
.Enrich.WithProperty("NodeHostname", nodeHostname)
|
||||
.Enrich.WithProperty("NodeRole", nodeRole)
|
||||
.Enrich.With(new TraceContextEnricher());
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Logger category that emits the per-probe "Health check {HealthCheckName} with status
|
||||
/// {HealthStatus} …" line. It is <c>DefaultHealthCheckService</c>, not
|
||||
/// <c>HealthCheckPublisherHostedService</c>: this host registers no
|
||||
/// <c>IHealthCheckPublisher</c>, so the checks run only on an inbound HTTP probe of
|
||||
/// <c>/health/*</c>.
|
||||
/// </summary>
|
||||
internal const string HealthCheckServiceSourceContext =
|
||||
"Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService";
|
||||
|
||||
/// <summary>Name both the site and central <c>/health/active</c> probes register under.</summary>
|
||||
internal const string ActiveNodeCheckName = "active-node";
|
||||
|
||||
/// <summary>
|
||||
/// Suppresses the standby node's correct-by-design <c>active-node</c> Error line
|
||||
/// (deferred-work register row 71).
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <para>
|
||||
/// <b>The problem.</b> <c>DefaultHealthCheckService</c> logs one line per check per probe,
|
||||
/// picking the level from the verdict — Debug for Healthy, Warning for Degraded,
|
||||
/// <b>Error for Unhealthy</b>. Both active-node checks
|
||||
/// (<c>SitePairActiveNodeHealthCheck</c> on a site, the shared <c>ActiveNodeHealthCheck</c>
|
||||
/// on central) answer Unhealthy on the standby, because 503 is exactly the contract
|
||||
/// <c>/health/active</c> publishes to Traefik and the family dashboard. So a perfectly
|
||||
/// healthy standby logged ERR on every probe — every 10 s on a site node, every 5 s on a
|
||||
/// central node behind Traefik's 5 s active-node probe. That floods the standby's log and
|
||||
/// trains operators to ignore ERR.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Why a filter and not a level override.</b> Serilog's <c>MinimumLevel.Override</c>
|
||||
/// can only RAISE a per-source floor; it cannot rewrite one Error event as Information.
|
||||
/// A <c>LogEvent</c>'s level is immutable, so an enricher cannot do it either. Excluding
|
||||
/// the single by-design event is the surgical option, and it leaves the verdict fully
|
||||
/// observable where it belongs: the HTTP status of <c>/health/active</c> itself, the
|
||||
/// cluster view on the readiness probe, and the health dashboard.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Why this cannot hide a genuine failure.</b> The predicate is keyed on the check
|
||||
/// NAME, not on the category, so a failing <c>localdb</c>, <c>akka-cluster</c>,
|
||||
/// <c>database</c>, or <c>required-singletons</c> check still logs at Error untouched.
|
||||
/// And the active-node check is a pure "am I the oldest Up member" verdict with no error
|
||||
/// path of its own — the ACTIVE node always answers Healthy, so the only event this can
|
||||
/// ever match is a standby reporting that it is a standby. Genuine loss of the pair
|
||||
/// surfaces on the readiness checks, which are deliberately out of scope here.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// Matching on <see cref="LogEventLevel.Error"/> rather than on the <c>HealthStatus</c>
|
||||
/// property avoids depending on how the enum renders into the event; the level→verdict
|
||||
/// mapping above already makes Error equivalent to Unhealthy.
|
||||
/// </para>
|
||||
/// </remarks>
|
||||
/// <param name="logEvent">The candidate log event.</param>
|
||||
/// <returns><see langword="true"/> when the event should be dropped.</returns>
|
||||
internal static bool IsExpectedStandbyActiveNodeProbe(LogEvent logEvent)
|
||||
{
|
||||
if (logEvent is null || logEvent.Level != LogEventLevel.Error)
|
||||
{
|
||||
return false;
|
||||
}
|
||||
|
||||
return MatchesScalar(logEvent, "SourceContext", HealthCheckServiceSourceContext)
|
||||
&& MatchesScalar(logEvent, "HealthCheckName", ActiveNodeCheckName);
|
||||
}
|
||||
|
||||
/// <summary>Tests one structured property for an exact scalar string value.</summary>
|
||||
/// <param name="logEvent">The event whose properties are inspected.</param>
|
||||
/// <param name="propertyName">The structured property name.</param>
|
||||
/// <param name="expected">The value the property must equal.</param>
|
||||
/// <returns><see langword="true"/> on an exact ordinal match.</returns>
|
||||
private static bool MatchesScalar(LogEvent logEvent, string propertyName, string expected) =>
|
||||
logEvent.Properties.TryGetValue(propertyName, out var value)
|
||||
&& value is ScalarValue { Value: string actual }
|
||||
&& string.Equals(actual, expected, StringComparison.Ordinal);
|
||||
|
||||
/// <summary>
|
||||
/// Parses a Serilog <see cref="LogEventLevel"/> name, falling back to
|
||||
/// <see cref="LogEventLevel.Information"/> for null/blank/unrecognised values.
|
||||
|
||||
Reference in New Issue
Block a user