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
This commit is contained in:
Joseph Doherty
@@ -18,8 +18,9 @@ namespace ZB.MOM.WW.ScadaBridge.Host.Actors;
|
||||
/// <para><b>Wiring.</b> <see cref="AkkaHostedService.BuildHocon"/> names this type in
|
||||
/// <c>akka.loggers</c>. It replaces Akka's <c>DefaultLogger</c>, which wrote to stdout only. Lines go
|
||||
/// to the static <see cref="SerilogLog.Logger"/>, which <c>Program</c> builds through
|
||||
/// <c>LoggerConfigurationFactory</c> before the ActorSystem is created. ScadaBridge keeps its own
|
||||
/// Serilog factory by design, so no Akka.Hosting or <c>Akka.Logger.Serilog</c> bridge is used.</para>
|
||||
/// <c>ScadaBridgeLogging</c> (the shared <c>AddZbSerilog</c> bootstrap) before the ActorSystem is
|
||||
/// created. ScadaBridge owns that static logger by design, so no Akka.Hosting or
|
||||
/// <c>Akka.Logger.Serilog</c> bridge is used.</para>
|
||||
/// <para><b>Levels.</b> Filtering is unchanged. <c>akka.loglevel</c> (INFO) still decides which lines
|
||||
/// an adapter publishes, so Akka's Debug lifecycle chatter is never built. The Serilog minimum level
|
||||
/// then applies as it does to every other line. Akka Debug, Info, Warning and Error map to Serilog
|
||||
|
||||
@@ -1,220 +0,0 @@
|
||||
using Serilog;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.Telemetry.Serilog;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.Host;
|
||||
|
||||
/// <summary>
|
||||
/// Builds the Serilog <see cref="LoggerConfiguration"/> for the Host process.
|
||||
///
|
||||
/// The configured minimum level comes from
|
||||
/// <c>ScadaBridge:Logging:MinimumLevel</c> (bound to <see cref="LoggingOptions"/>) so an
|
||||
/// operator editing that key changes the effective log level.
|
||||
///
|
||||
/// The console and file sinks are read from the standard
|
||||
/// <c>Serilog</c> configuration section via <c>ReadFrom.Configuration</c> — the sink
|
||||
/// set, console output template, file path and rolling interval are all
|
||||
/// configuration-driven (defined in <c>appsettings.json</c>), not hard-coded. The
|
||||
/// explicit <c>MinimumLevel.Is</c> below pins the floor from <see cref="LoggingOptions"/>.
|
||||
///
|
||||
/// <c>ScadaBridge:Logging:MinimumLevel</c> is the single source of truth
|
||||
/// for the floor — the explicit <c>MinimumLevel.Is</c> call deliberately runs
|
||||
/// AFTER <c>ReadFrom.Configuration</c> so a <c>Serilog:MinimumLevel</c> entry in
|
||||
/// configuration is overridden. To make that precedence visible (so an operator
|
||||
/// who sets <c>Serilog:MinimumLevel</c> does not wonder why the change had no
|
||||
/// effect), <see cref="Build"/> writes a one-shot warning to
|
||||
/// <see cref="Console.Error"/> when both keys are present. Pick one path —
|
||||
/// editing <c>Serilog:MinimumLevel</c> alone has no effect.
|
||||
/// </summary>
|
||||
public static class LoggerConfigurationFactory
|
||||
{
|
||||
/// <summary>Builds a <see cref="LoggerConfiguration"/> enriched with node-identity properties and a configured minimum level.</summary>
|
||||
/// <param name="configuration">Application configuration supplying the Serilog section and logging options.</param>
|
||||
/// <param name="nodeRole">Role label (e.g., <c>central-a</c>) added as a log enrichment property.</param>
|
||||
/// <param name="siteId">Site identifier added as a log enrichment property.</param>
|
||||
/// <param name="nodeHostname">Hostname added as a log enrichment property.</param>
|
||||
/// <returns>The configured <see cref="LoggerConfiguration"/>.</returns>
|
||||
public static LoggerConfiguration Build(
|
||||
IConfiguration configuration,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname)
|
||||
=> Build(configuration, nodeRole, siteId, nodeHostname, Console.Error);
|
||||
|
||||
/// <summary>
|
||||
/// Test-visible overload of <see cref="Build(IConfiguration, string, string, string)"/>
|
||||
/// that routes the precedence warning through a caller-supplied
|
||||
/// writer so unit tests can capture it. Production calls the four-arg
|
||||
/// overload which uses <see cref="Console.Error"/>.
|
||||
/// </summary>
|
||||
/// <param name="configuration">Application configuration supplying the Serilog section and logging options.</param>
|
||||
/// <param name="nodeRole">Role label added as a log enrichment property.</param>
|
||||
/// <param name="siteId">Site identifier added as a log enrichment property.</param>
|
||||
/// <param name="nodeHostname">Hostname added as a log enrichment property.</param>
|
||||
/// <param name="warningWriter">Writer that receives the one-shot override-warning when both keys are present.</param>
|
||||
/// <returns>The fully configured <see cref="LoggerConfiguration"/> ready to create the Serilog logger.</returns>
|
||||
internal static LoggerConfiguration Build(
|
||||
IConfiguration configuration,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname,
|
||||
TextWriter warningWriter)
|
||||
{
|
||||
var loggingOptions = new LoggingOptions();
|
||||
configuration.GetSection("ScadaBridge:Logging").Bind(loggingOptions);
|
||||
|
||||
var minimumLevel = ParseLevel(loggingOptions.MinimumLevel, warningWriter);
|
||||
|
||||
// Warn once if the operator also set a Serilog:MinimumLevel —
|
||||
// they almost certainly expected it to take effect, but the explicit
|
||||
// MinimumLevel.Is call below silently overrides it. The warning is
|
||||
// emitted only when the conflicting key is actually present (a bare
|
||||
// "Default" value is what ReadFrom.Configuration reads); a missing /
|
||||
// empty Serilog:MinimumLevel section is silent.
|
||||
var serilogMinimumLevel = configuration["Serilog:MinimumLevel"]
|
||||
?? configuration["Serilog:MinimumLevel:Default"];
|
||||
if (!string.IsNullOrWhiteSpace(serilogMinimumLevel))
|
||||
{
|
||||
warningWriter.WriteLine(
|
||||
$"warning: Serilog:MinimumLevel ('{serilogMinimumLevel}') is being overridden by " +
|
||||
$"ScadaBridge:Logging:MinimumLevel ('{loggingOptions.MinimumLevel ?? "Information (default)"}'). " +
|
||||
"ScadaBridge:Logging:MinimumLevel is the documented source of truth for the floor (Host-011); " +
|
||||
"remove the Serilog:MinimumLevel entry to silence this warning.");
|
||||
}
|
||||
|
||||
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)
|
||||
// ScadaBridge#56: surface the ExecutionId/InstanceName/ScriptName the site script
|
||||
// launcher pushes onto LogContext, so lines written on a run's own call chain carry
|
||||
// the run's identity. See SiteRuntime ScriptRunLogScope for the (bounded) scope.
|
||||
.Enrich.FromLogContext()
|
||||
.Enrich.With(new TraceContextEnricher())
|
||||
// ScadaBridge#56: copies each line tagged with a TRACED execution's ExecutionId into that
|
||||
// run's Flow Debugger step log (ScriptLog rows, source "node"). One volatile read and out
|
||||
// when nothing is traced. Attached directly (never behind an async wrapper): its
|
||||
// de-duplication guard is per thread.
|
||||
.WriteTo.Sink(new ZB.MOM.WW.ScadaBridge.Commons.Observability.ExecutionLogCaptureSink());
|
||||
}
|
||||
|
||||
/// <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
|
||||
/// (the shared <c>ActiveNodeHealthCheck</c>, role-scoped on a site and unscoped
|
||||
/// 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.
|
||||
///
|
||||
/// When an operator sets <c>ScadaBridge:Logging:MinimumLevel</c> to a
|
||||
/// value that doesn't parse (e.g. the typo "Informaiton"), the helper must NOT
|
||||
/// throw — startup has to succeed so the rest of the system can come up — but
|
||||
/// it MUST make the silent fallback visible. The logger is not yet built at
|
||||
/// this point, so the warning is written directly to <see cref="Console.Error"/>
|
||||
/// using <see cref="WriteParseWarning"/>; non-null/non-blank values that fail
|
||||
/// to parse are reported once, naming the offending value and the fallback.
|
||||
/// Null/blank values are treated as "unset" and silently default — only
|
||||
/// explicit-but-invalid values trigger the warning.
|
||||
/// </summary>
|
||||
/// <param name="level">Configured level string, possibly null/blank/invalid.</param>
|
||||
/// <returns>The parsed <see cref="LogEventLevel"/>, or <see cref="LogEventLevel.Information"/> when the value is absent or unrecognised.</returns>
|
||||
internal static LogEventLevel ParseLevel(string? level)
|
||||
=> ParseLevel(level, Console.Error);
|
||||
|
||||
/// <summary>
|
||||
/// Test-visible overload of <see cref="ParseLevel(string?)"/> that routes the
|
||||
/// one-shot warning through a caller-supplied writer (<see cref="Console.Error"/>
|
||||
/// in production) so unit tests can capture the warning output.
|
||||
/// </summary>
|
||||
/// <param name="level">Configured level string, possibly null/blank/invalid.</param>
|
||||
/// <param name="warningWriter">Writer that receives a single warning line if the value is non-blank but unparseable.</param>
|
||||
/// <returns>The parsed <see cref="LogEventLevel"/>, or <see cref="LogEventLevel.Information"/> when the value is absent or unrecognised.</returns>
|
||||
internal static LogEventLevel ParseLevel(string? level, TextWriter warningWriter)
|
||||
{
|
||||
if (Enum.TryParse<LogEventLevel>(level, ignoreCase: true, out var parsed))
|
||||
return parsed;
|
||||
|
||||
if (!string.IsNullOrWhiteSpace(level))
|
||||
warningWriter.WriteLine(
|
||||
$"warning: ScadaBridge:Logging:MinimumLevel value '{level}' is not a recognised Serilog LogEventLevel; falling back to Information.");
|
||||
|
||||
return LogEventLevel.Information;
|
||||
}
|
||||
}
|
||||
@@ -6,7 +6,7 @@ namespace ZB.MOM.WW.ScadaBridge.Host;
|
||||
/// <summary>
|
||||
/// Validates <see cref="LoggingOptions"/> at host startup (arch-review 08 round
|
||||
/// 2 NF4). <see cref="LoggingOptions.MinimumLevel"/> is parsed into a Serilog
|
||||
/// <see cref="LogEventLevel"/> by <c>LoggerConfigurationFactory.ParseLevel</c>,
|
||||
/// <see cref="LogEventLevel"/> by <c>ScadaBridgeLogging.ParseLevel</c>,
|
||||
/// which silently falls back to <c>Information</c> for an unrecognised value.
|
||||
/// This validator surfaces that misconfiguration at boot instead: a present,
|
||||
/// non-blank value must name a real level (Verbose/Debug/Information/Warning/
|
||||
|
||||
@@ -141,15 +141,15 @@ var nodeRole = configuration["ScadaBridge:Node:Role"]!;
|
||||
var nodeHostname = configuration["ScadaBridge:Node:NodeHostname"] ?? "unknown";
|
||||
var siteId = configuration["ScadaBridge:Node:SiteId"] ?? "central";
|
||||
|
||||
// Serilog structured logging.
|
||||
// Minimum level is driven by ScadaBridge:Logging:MinimumLevel (LoggingOptions).
|
||||
// Console and file sinks are defined in the `Serilog` configuration
|
||||
// section (appsettings.json) and applied via ReadFrom.Configuration inside the
|
||||
// factory — the sink set, output template, file path and rolling interval are all
|
||||
// configuration-driven, not hard-coded here.
|
||||
Log.Logger = ZB.MOM.WW.ScadaBridge.Host.LoggerConfigurationFactory
|
||||
.Build(configuration, nodeRole, siteId, nodeHostname)
|
||||
.CreateLogger();
|
||||
// Serilog structured logging, built by the family's shared AddZbSerilog bootstrap
|
||||
// (ZB.MOM.WW.Telemetry.Serilog, ScadaBridge#94) with ScadaBridge's hooks: minimum level driven by
|
||||
// ScadaBridge:Logging:MinimumLevel (LoggingOptions) and the standby active-node filter.
|
||||
// Console and file sinks are defined in the `Serilog` configuration section (appsettings.json)
|
||||
// and applied via ReadFrom.Configuration — the sink set, output template, file path and rolling
|
||||
// interval are all configuration-driven, not hard-coded here. The static logger stays the single
|
||||
// process logger (both web hosts call UseSerilog() over it); see ScadaBridgeLogging for why.
|
||||
Log.Logger = ZB.MOM.WW.ScadaBridge.Host.ScadaBridgeLogging
|
||||
.CreateLogger(configuration, nodeRole, siteId, nodeHostname);
|
||||
|
||||
// The host's ApplicationStopping token, captured once the host is built. A normal Windows service
|
||||
// stop (or SIGTERM) cancels it BEFORE RunAsync unwinds, and WindowsServiceLifetime.StopAsync can
|
||||
|
||||
@@ -0,0 +1,349 @@
|
||||
using Microsoft.Extensions.DependencyInjection;
|
||||
using Microsoft.Extensions.Hosting;
|
||||
using Serilog;
|
||||
using Serilog.Core;
|
||||
using Serilog.Events;
|
||||
using ZB.MOM.WW.Telemetry.Serilog;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.Host;
|
||||
|
||||
/// <summary>
|
||||
/// Builds the Host process's Serilog logger through the family's shared bootstrap,
|
||||
/// <c>AddZbSerilog</c> (<c>ZB.MOM.WW.Telemetry.Serilog</c> 0.2.0+, ScadaBridge#94), with two
|
||||
/// ScadaBridge hooks: a minimum-level governor and a final <see cref="LoggerConfiguration"/> callback.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <para>
|
||||
/// <b>What the shared bootstrap supplies.</b> <c>ReadFrom.Configuration</c> over the standard
|
||||
/// <c>Serilog</c> section (the console and file sinks, output template, file path and rolling
|
||||
/// interval all stay configuration-driven in <c>appsettings.json</c>), the <c>SiteId</c> /
|
||||
/// <c>NodeRole</c> / <c>NodeHostname</c> identity enrichers, the shared <c>TraceContextEnricher</c>
|
||||
/// and the (inert here, no <c>ILogRedactor</c> is registered) redaction seam. No OTLP log sink is
|
||||
/// added: the telemetry options passed here never select the OTLP exporter, as before.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Minimum level (Host-011).</b> <c>ScadaBridge:Logging:MinimumLevel</c> is the single source of
|
||||
/// truth for the floor. <see cref="GovernMinimumLevel(IConfiguration, TextWriter)"/> is handed to
|
||||
/// <c>ZbSerilogOptions.MinimumLevelGovernor</c>, which the library applies AFTER
|
||||
/// <c>ReadFrom.Configuration</c>, so a <c>Serilog:MinimumLevel</c> entry is overridden. It always
|
||||
/// returns a level (never <see langword="null"/>), so the floor never defers to the Serilog key.
|
||||
/// When both keys are present it writes a one-shot warning so an operator who edits
|
||||
/// <c>Serilog:MinimumLevel</c> learns why the change had no effect. Namespace
|
||||
/// <c>Serilog:MinimumLevel:Override:*</c> entries still apply.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Final hook.</b> <c>ZbSerilogOptions.ConfigureLogger</c> adds what is ScadaBridge's own: the
|
||||
/// standby <c>active-node</c> exclusion filter (register row 71), the exact node identity this
|
||||
/// process was configured with (the library stamps <c>NodeHostname</c> from the machine name;
|
||||
/// ScadaBridge has always stamped <c>ScadaBridge:Node:NodeHostname</c>), <c>Enrich.FromLogContext</c>
|
||||
/// (ScadaBridge#56 run identity) and the Flow Debugger <c>ExecutionLogCaptureSink</c>.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Who owns the logger.</b> <c>AddZbSerilog</c> registers the logger in a container and leaves
|
||||
/// <see cref="Log.Logger"/> alone. ScadaBridge needs the static logger before any host exists
|
||||
/// (startup banner and warnings, a pre-host <c>Fatal</c>), for the Akka bridge
|
||||
/// (<c>SerilogAkkaLogger</c>), and after the host is disposed (the shutdown line and the
|
||||
/// unexpected-termination <c>Fatal</c>). So <see cref="CreateLogger(IConfiguration, string, string, string)"/>
|
||||
/// runs <c>AddZbSerilog</c> on a small pre-host builder and resolves the logger from it once;
|
||||
/// <c>Program</c> installs it as <see cref="Log.Logger"/> and the web hosts keep
|
||||
/// <c>UseSerilog()</c> over the static logger, exactly as before. There is therefore one logger
|
||||
/// (one file-sink handle) per process, and the host's container never disposes it — the
|
||||
/// <c>Log.CloseAndFlushAsync()</c> in <c>Program</c>'s <c>finally</c> does.
|
||||
/// </para>
|
||||
/// </remarks>
|
||||
public static class ScadaBridgeLogging
|
||||
{
|
||||
/// <summary>The OTel <c>service.name</c> ScadaBridge registers with <c>AddZbTelemetry</c>.</summary>
|
||||
internal const string ServiceName = "scadabridge";
|
||||
|
||||
/// <summary>Creates the process logger: the shared bootstrap plus ScadaBridge's hooks.</summary>
|
||||
/// <param name="configuration">Application configuration supplying the Serilog section and logging options.</param>
|
||||
/// <param name="nodeRole">Role label (e.g., <c>Central</c>) stamped as <c>NodeRole</c>.</param>
|
||||
/// <param name="siteId">Site identifier stamped as <c>SiteId</c>.</param>
|
||||
/// <param name="nodeHostname">Configured node hostname stamped as <c>NodeHostname</c>.</param>
|
||||
/// <returns>The built logger; the caller owns it (Program installs it as <see cref="Log.Logger"/>).</returns>
|
||||
public static Logger CreateLogger(
|
||||
IConfiguration configuration,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname)
|
||||
=> CreateLogger(configuration, nodeRole, siteId, nodeHostname, Console.Error, additionalConfiguration: null);
|
||||
|
||||
/// <summary>
|
||||
/// Test-visible overload of <see cref="CreateLogger(IConfiguration, string, string, string)"/>:
|
||||
/// routes the operator warnings through <paramref name="warningWriter"/> and lets a test append
|
||||
/// a capturing sink after ScadaBridge's own hook.
|
||||
/// </summary>
|
||||
/// <param name="configuration">Application configuration supplying the Serilog section and logging options.</param>
|
||||
/// <param name="nodeRole">Role label stamped as <c>NodeRole</c>.</param>
|
||||
/// <param name="siteId">Site identifier stamped as <c>SiteId</c>.</param>
|
||||
/// <param name="nodeHostname">Configured node hostname stamped as <c>NodeHostname</c>.</param>
|
||||
/// <param name="warningWriter">Receives the one-shot operator warnings.</param>
|
||||
/// <param name="additionalConfiguration">Optional extra configuration applied last (tests add a sink here).</param>
|
||||
/// <returns>The built logger.</returns>
|
||||
internal static Logger CreateLogger(
|
||||
IConfiguration configuration,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname,
|
||||
TextWriter warningWriter,
|
||||
Action<LoggerConfiguration>? additionalConfiguration)
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(configuration);
|
||||
|
||||
// A pre-host builder whose only job is to run AddZbSerilog: no default sources, so its
|
||||
// configuration is exactly the caller's (already secret-expanded) configuration.
|
||||
var builder = Microsoft.Extensions.Hosting.Host.CreateEmptyApplicationBuilder(new HostApplicationBuilderSettings());
|
||||
builder.Configuration.AddConfiguration(configuration);
|
||||
builder.AddScadaBridgeSerilog(nodeRole, siteId, nodeHostname, warningWriter, additionalConfiguration);
|
||||
|
||||
// The provider is deliberately never disposed: disposing it would dispose the logger, whose
|
||||
// lifetime belongs to Program (Log.CloseAndFlushAsync). It holds nothing else.
|
||||
#pragma warning disable ASP0000 // deliberate pre-host container
|
||||
var provider = builder.Services.BuildServiceProvider();
|
||||
#pragma warning restore ASP0000
|
||||
return (Logger)provider.GetRequiredService<Serilog.ILogger>();
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Registers the ScadaBridge logger on <paramref name="builder"/> through <c>AddZbSerilog</c>
|
||||
/// with the minimum-level governor and the final ScadaBridge hook.
|
||||
/// </summary>
|
||||
/// <param name="builder">The host application builder.</param>
|
||||
/// <param name="nodeRole">Role label stamped as <c>NodeRole</c>.</param>
|
||||
/// <param name="siteId">Site identifier stamped as <c>SiteId</c>.</param>
|
||||
/// <param name="nodeHostname">Configured node hostname stamped as <c>NodeHostname</c>.</param>
|
||||
/// <param name="warningWriter">Receives the one-shot operator warnings.</param>
|
||||
/// <param name="additionalConfiguration">Optional extra configuration applied last.</param>
|
||||
/// <returns>The same builder.</returns>
|
||||
internal static IHostApplicationBuilder AddScadaBridgeSerilog(
|
||||
this IHostApplicationBuilder builder,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname,
|
||||
TextWriter warningWriter,
|
||||
Action<LoggerConfiguration>? additionalConfiguration = null)
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(warningWriter);
|
||||
|
||||
return builder.AddZbSerilog(
|
||||
telemetry =>
|
||||
{
|
||||
telemetry.ServiceName = ServiceName;
|
||||
telemetry.SiteId = siteId;
|
||||
telemetry.NodeRole = nodeRole;
|
||||
},
|
||||
serilog =>
|
||||
{
|
||||
serilog.MinimumLevelGovernor = configuration => GovernMinimumLevel(configuration, warningWriter);
|
||||
serilog.ConfigureLogger = (loggerConfiguration, _) =>
|
||||
{
|
||||
ConfigureScadaBridgePipeline(loggerConfiguration, nodeRole, siteId, nodeHostname);
|
||||
additionalConfiguration?.Invoke(loggerConfiguration);
|
||||
};
|
||||
});
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The minimum-level governor: reads <c>ScadaBridge:Logging:MinimumLevel</c> (falling back to
|
||||
/// Information, with a warning for an unparseable value) and warns once when a
|
||||
/// <c>Serilog:MinimumLevel</c> entry is present, because this value overrides it.
|
||||
/// </summary>
|
||||
/// <param name="configuration">The application configuration.</param>
|
||||
/// <param name="warningWriter">Receives the one-shot operator warnings.</param>
|
||||
/// <returns>The governed floor; never <see langword="null"/>.</returns>
|
||||
internal static LogEventLevel GovernMinimumLevel(IConfiguration configuration, TextWriter warningWriter)
|
||||
{
|
||||
var loggingOptions = new LoggingOptions();
|
||||
configuration.GetSection("ScadaBridge:Logging").Bind(loggingOptions);
|
||||
|
||||
var minimumLevel = ParseLevel(loggingOptions.MinimumLevel, warningWriter);
|
||||
|
||||
// Warn once if the operator also set a Serilog:MinimumLevel — they almost certainly
|
||||
// expected it to take effect, but the governed level silently overrides it. Emitted only
|
||||
// when the conflicting key is actually present (a bare "Default" value is what
|
||||
// ReadFrom.Configuration reads); a missing / empty Serilog:MinimumLevel section is silent.
|
||||
var serilogMinimumLevel = configuration["Serilog:MinimumLevel"]
|
||||
?? configuration["Serilog:MinimumLevel:Default"];
|
||||
if (!string.IsNullOrWhiteSpace(serilogMinimumLevel))
|
||||
{
|
||||
warningWriter.WriteLine(
|
||||
$"warning: Serilog:MinimumLevel ('{serilogMinimumLevel}') is being overridden by " +
|
||||
$"ScadaBridge:Logging:MinimumLevel ('{loggingOptions.MinimumLevel ?? "Information (default)"}'). " +
|
||||
"ScadaBridge:Logging:MinimumLevel is the documented source of truth for the floor (Host-011); " +
|
||||
"remove the Serilog:MinimumLevel entry to silence this warning.");
|
||||
}
|
||||
|
||||
return minimumLevel;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// ScadaBridge's own pipeline stages, run by <c>ZbSerilogOptions.ConfigureLogger</c> after the
|
||||
/// shared bootstrap.
|
||||
/// </summary>
|
||||
/// <param name="loggerConfiguration">The configuration being built.</param>
|
||||
/// <param name="nodeRole">Role label stamped as <c>NodeRole</c>.</param>
|
||||
/// <param name="siteId">Site identifier stamped as <c>SiteId</c>.</param>
|
||||
/// <param name="nodeHostname">Configured node hostname stamped as <c>NodeHostname</c>.</param>
|
||||
internal static void ConfigureScadaBridgePipeline(
|
||||
LoggerConfiguration loggerConfiguration,
|
||||
string nodeRole,
|
||||
string siteId,
|
||||
string nodeHostname)
|
||||
{
|
||||
loggerConfiguration
|
||||
// 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)
|
||||
// The shared bootstrap stamps NodeHostname from the machine name and skips an empty
|
||||
// SiteId/NodeRole; ScadaBridge has always stamped the configured values verbatim.
|
||||
// Enrich.WithProperty only adds an ABSENT property, so this enricher overwrites.
|
||||
.Enrich.With(new NodeIdentityEnricher(siteId, nodeHostname, nodeRole))
|
||||
// ScadaBridge#56: surface the ExecutionId/InstanceName/ScriptName the site script
|
||||
// launcher pushes onto LogContext, so lines written on a run's own call chain carry
|
||||
// the run's identity. See SiteRuntime ScriptRunLogScope for the (bounded) scope.
|
||||
.Enrich.FromLogContext()
|
||||
// ScadaBridge#56: copies each line tagged with a TRACED execution's ExecutionId into that
|
||||
// run's Flow Debugger step log (ScriptLog rows, source "node"). One volatile read and out
|
||||
// when nothing is traced. Attached directly (never behind an async wrapper): its
|
||||
// de-duplication guard is per thread.
|
||||
.WriteTo.Sink(new ZB.MOM.WW.ScadaBridge.Commons.Observability.ExecutionLogCaptureSink());
|
||||
}
|
||||
|
||||
/// <summary>Stamps the configured node identity, overwriting any earlier value.</summary>
|
||||
private sealed class NodeIdentityEnricher : ILogEventEnricher
|
||||
{
|
||||
private readonly LogEventProperty _siteId;
|
||||
private readonly LogEventProperty _nodeHostname;
|
||||
private readonly LogEventProperty _nodeRole;
|
||||
|
||||
public NodeIdentityEnricher(string siteId, string nodeHostname, string nodeRole)
|
||||
{
|
||||
_siteId = new LogEventProperty(ZbLogEnricherNames.SiteId, new ScalarValue(siteId));
|
||||
_nodeHostname = new LogEventProperty(ZbLogEnricherNames.NodeHostname, new ScalarValue(nodeHostname));
|
||||
_nodeRole = new LogEventProperty(ZbLogEnricherNames.NodeRole, new ScalarValue(nodeRole));
|
||||
}
|
||||
|
||||
public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
|
||||
{
|
||||
logEvent.AddOrUpdateProperty(_siteId);
|
||||
logEvent.AddOrUpdateProperty(_nodeHostname);
|
||||
logEvent.AddOrUpdateProperty(_nodeRole);
|
||||
}
|
||||
}
|
||||
|
||||
/// <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
|
||||
/// (the shared <c>ActiveNodeHealthCheck</c>, role-scoped on a site and unscoped
|
||||
/// 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.
|
||||
///
|
||||
/// When an operator sets <c>ScadaBridge:Logging:MinimumLevel</c> to a
|
||||
/// value that doesn't parse (e.g. the typo "Informaiton"), the helper must NOT
|
||||
/// throw — startup has to succeed so the rest of the system can come up — but
|
||||
/// it MUST make the silent fallback visible. The logger is not yet built at
|
||||
/// this point, so the warning is written directly to <see cref="Console.Error"/>
|
||||
/// using <see cref="WriteParseWarning"/>; non-null/non-blank values that fail
|
||||
/// to parse are reported once, naming the offending value and the fallback.
|
||||
/// Null/blank values are treated as "unset" and silently default — only
|
||||
/// explicit-but-invalid values trigger the warning.
|
||||
/// </summary>
|
||||
/// <param name="level">Configured level string, possibly null/blank/invalid.</param>
|
||||
/// <returns>The parsed <see cref="LogEventLevel"/>, or <see cref="LogEventLevel.Information"/> when the value is absent or unrecognised.</returns>
|
||||
internal static LogEventLevel ParseLevel(string? level)
|
||||
=> ParseLevel(level, Console.Error);
|
||||
|
||||
/// <summary>
|
||||
/// Test-visible overload of <see cref="ParseLevel(string?)"/> that routes the
|
||||
/// one-shot warning through a caller-supplied writer (<see cref="Console.Error"/>
|
||||
/// in production) so unit tests can capture the warning output.
|
||||
/// </summary>
|
||||
/// <param name="level">Configured level string, possibly null/blank/invalid.</param>
|
||||
/// <param name="warningWriter">Writer that receives a single warning line if the value is non-blank but unparseable.</param>
|
||||
/// <returns>The parsed <see cref="LogEventLevel"/>, or <see cref="LogEventLevel.Information"/> when the value is absent or unrecognised.</returns>
|
||||
internal static LogEventLevel ParseLevel(string? level, TextWriter warningWriter)
|
||||
{
|
||||
if (Enum.TryParse<LogEventLevel>(level, ignoreCase: true, out var parsed))
|
||||
return parsed;
|
||||
|
||||
if (!string.IsNullOrWhiteSpace(level))
|
||||
warningWriter.WriteLine(
|
||||
$"warning: ScadaBridge:Logging:MinimumLevel value '{level}' is not a recognised Serilog LogEventLevel; falling back to Information.");
|
||||
|
||||
return LogEventLevel.Information;
|
||||
}
|
||||
}
|
||||
@@ -8,7 +8,7 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
/// run (ScadaBridge#56), so every log line written on the run's async flow - the script body's own
|
||||
/// callees (external-system client, database gateway, store-and-forward enqueue, ...) - carries
|
||||
/// <c>ExecutionId</c>, <c>InstanceName</c> and <c>ScriptName</c> once the host enables
|
||||
/// <c>Enrich.FromLogContext()</c> (<c>LoggerConfigurationFactory</c>).
|
||||
/// <c>Enrich.FromLogContext()</c> (<c>ScadaBridgeLogging</c>).
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <c>LogContext</c> is an <c>AsyncLocal</c>: it follows the run's own call chain but NOT an Akka
|
||||
|
||||
Reference in New Issue
Block a user