Files
ScadaBridge/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/StandbyHealthCheckLogNoiseTests.cs
T
Joseph Doherty 2d2e9f35c5 feat(host): build the process logger through the shared AddZbSerilog bootstrap (#94)
Switch ScadaBridge from its own LoggerConfigurationFactory to AddZbSerilog
(ZB.MOM.WW.Telemetry(.Serilog) 0.1.0 -> 0.2.0) using the two 0.2.0 hooks:

- MinimumLevelGovernor: ScadaBridge:Logging:MinimumLevel, applied after
  ReadFrom.Configuration so it outranks Serilog:MinimumLevel (never null, so the
  floor never defers to the Serilog key; Override:* namespace entries still apply;
  the one-shot conflict / unparseable-value warnings are unchanged).
- ConfigureLogger: the standby active-node exclusion filter (register row 71),
  the configured node identity (the shared bootstrap stamps NodeHostname from
  the machine name and skips empty values; an overwriting enricher keeps the
  configured ScadaBridge:Node values verbatim), Enrich.FromLogContext and the
  ExecutionLogCaptureSink.

ScadaBridgeLogging runs AddZbSerilog on a small pre-host builder and Program
installs the result as the static Log.Logger; both web hosts keep UseSerilog()
over it. One logger and one file-sink handle per process, usable before the
host is built (startup banner, warnings, pre-host Fatal), by SerilogAkkaLogger,
and after the host is disposed (shutdown line, unexpected-termination Fatal) —
AddZbSerilog's own DI registration would leave Log.Logger alone and have the
host dispose the logger.

LoggerConfigurationFactory is deleted (nothing else used it). Tests: existing
logging/standby/sink tests now run through the new pipeline, plus
ScadaBridgeLoggingParityTests (level precedence, Override:* still applies,
one-shot warning, configured identity incl. NodeHostname != MachineName and empty
SiteId, exact property set of a plain line, trace_id/span_id). Mutation-checked:
governor deferring, filter removed, identity enricher removed, FromLogContext
removed, capture sink removed each fail tests.

Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi
2026-11-12 14:43:19 -05:00

160 lines
6.3 KiB
C#

using Microsoft.Extensions.Configuration;
using Serilog;
using Serilog.Events;
namespace ZB.MOM.WW.ScadaBridge.Host.Tests;
/// <summary>
/// Deferred-work register row 71 — a standby node logged the correct-by-design
/// <c>active-node</c> health-check verdict at ERROR on every probe.
/// </summary>
/// <remarks>
/// <para>
/// <c>DefaultHealthCheckService</c> picks the log 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 <c>/health/active</c> publishes, so a healthy standby logged
/// ERR every 10 s on a site node and every 5 s on a central node behind Traefik's probe.
/// </para>
/// <para>
/// The constraint on the fix is that a GENUINE failure must still log at Error, which is why
/// the filter is keyed on the check NAME rather than on the logger category.
/// </para>
/// </remarks>
public class StandbyHealthCheckLogNoiseTests
{
private const string HealthCheckCategory =
"Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService";
private const string Template =
"Health check {HealthCheckName} with status {HealthStatus} completed after "
+ "{ElapsedMilliseconds}ms with message '{HealthCheckDescription}'";
private static ILogger BuildLogger(InMemorySink sink)
{
var config = new ConfigurationBuilder()
.AddInMemoryCollection(new Dictionary<string, string?>
{
["ScadaBridge:Logging:MinimumLevel"] = "Debug",
})
.Build();
// The real host pipeline: the shared AddZbSerilog bootstrap plus ScadaBridge's hooks.
return ScadaBridgeLogging.CreateLogger(
config, "Site", "site-a", "site-a-b", new StringWriter(), lc => lc.WriteTo.Sink(sink));
}
/// <summary>Emits one event shaped exactly like the framework's per-check line.</summary>
private static void EmitHealthCheckLine(
ILogger logger, string category, LogEventLevel level, string checkName, string status) =>
logger
.ForContext("SourceContext", category)
.Write(level, Template, checkName, status, 1.0, "some message");
/// <summary>Verifies that the standby active-node verdict is not logged.</summary>
[Fact]
public void StandbyActiveNodeVerdict_IsNotLogged()
{
// The regression: "Health check active-node with status Unhealthy … 'not the
// site pair primary (standby)'" at Error, once per probe, forever.
var sink = new InMemorySink();
var logger = BuildLogger(sink);
EmitHealthCheckLine(
logger, HealthCheckCategory, LogEventLevel.Error, "active-node", "Unhealthy");
Assert.Empty(sink.LogEvents);
}
/// <summary>Verifies that a genuine failure of a health check still logs at Error.</summary>
/// <param name="checkName">The name of the failing health check.</param>
[Theory]
[InlineData("localdb")]
[InlineData("akka-cluster")]
[InlineData("database")]
[InlineData("required-singletons")]
public void GenuineCheckFailure_StillLogsAtError(string checkName)
{
// The constraint. The filter is name-scoped, so every OTHER check on the same logger
// category keeps its Error line — a blanket category override would have silenced
// these too, which is exactly the trap this test exists to catch.
var sink = new InMemorySink();
var logger = BuildLogger(sink);
EmitHealthCheckLine(
logger, HealthCheckCategory, LogEventLevel.Error, checkName, "Unhealthy");
var evt = Assert.Single(sink.LogEvents);
Assert.Equal(LogEventLevel.Error, evt.Level);
}
/// <summary>Verifies that a healthy active-node verdict is unaffected.</summary>
[Fact]
public void ActiveNodeHealthyVerdict_IsUnaffected()
{
// The active node reports Healthy, which the framework logs at Debug. Nothing about
// the filter should touch it — it only ever matches Error.
var sink = new InMemorySink();
var logger = BuildLogger(sink);
EmitHealthCheckLine(
logger, HealthCheckCategory, LogEventLevel.Debug, "active-node", "Healthy");
Assert.Single(sink.LogEvents);
}
/// <summary>Verifies that a degraded active-node verdict is unaffected.</summary>
[Fact]
public void ActiveNodeDegradedVerdict_IsUnaffected()
{
// Degraded logs at Warning. If a future check shape ever reports Degraded for
// active-node, that should still be visible — the filter is Error-only.
var sink = new InMemorySink();
var logger = BuildLogger(sink);
EmitHealthCheckLine(
logger, HealthCheckCategory, LogEventLevel.Warning, "active-node", "Degraded");
Assert.Single(sink.LogEvents);
}
/// <summary>Verifies that an error mentioning the active node from another category is not suppressed.</summary>
[Fact]
public void AnErrorMentioningActiveNode_FromAnotherCategory_IsNotSuppressed()
{
// The predicate requires BOTH the health-check category and the check name, so
// application code logging about the active node keeps its Error.
var sink = new InMemorySink();
var logger = BuildLogger(sink);
EmitHealthCheckLine(
logger,
"ZB.MOM.WW.ScadaBridge.Host.Actors.AkkaHostedService",
LogEventLevel.Error,
"active-node",
"Unhealthy");
Assert.Single(sink.LogEvents);
}
/// <summary>Verifies that ordinary errors with no health-check properties are not suppressed.</summary>
[Fact]
public void OrdinaryErrorsWithNoHealthCheckProperties_AreNotSuppressed()
{
var sink = new InMemorySink();
var logger = BuildLogger(sink);
logger.Error("something genuinely broke");
Assert.Single(sink.LogEvents);
}
/// <summary>Verifies that the predicate rejects a null event.</summary>
[Fact]
public void Predicate_RejectsANullEvent()
{
// Defensive: Serilog never hands the filter a null, but the predicate is internal
// and reachable, and returning "suppress" for null would be the wrong default.
Assert.False(ScadaBridgeLogging.IsExpectedStandbyActiveNodeProbe(null!));
}
}