diff --git a/CLAUDE.md b/CLAUDE.md index 789ae628..b6bed23f 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -205,7 +205,7 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - Failure detection: 2s heartbeat, 10s threshold. Total failover ~25s (drill-measured 2026-07-21 under auto-down: active-crash TAKEOVER in 28s, standby-crash removal in 27s with 0 routing blips — `docker/failover-drill.sh`). - CoordinatedShutdown for graceful singleton handover. - Automatic dual-node recovery from persistent storage. -- **Active/standby is decided by `ActiveNodeEvaluator.SelfIsOldestUp`, never by cluster leadership** — see the Architecture note above. **Central's** `/health/active` backs Traefik's active-node routing and the Inbound API uses the shared `ZB.MOM.WW.Health.IActiveNodeGate` (`AkkaActiveNodeGate`, same `ClusterActiveNode` rule; the private InboundAPI gate was removed in Gitea #80), so the proxy and the Inbound API always agree on which node is active. **Site nodes DO map `/health/*` too** — the "site nodes map no `/health/*` at all" claim that stood here was stale: `SiteServiceRegistration` registers `akka-cluster` + `localdb` (Ready) and the shared `ActiveNodeHealthCheck` (Active, constructed with the `site-{SiteId}` role so it is role-scoped; Degraded/200 during startup and publishes `activeNode`/`activeRole`/`selfAddress` data for the Overview dashboard — Gitea #97; central registers the same class unscoped), and `Program.cs`'s Site branch calls `MapZbHealth()` on the HTTP/1.1 listener so the family overview dashboard can probe every node identically. Nothing in this repo probes a site's `/health/active` (Traefik health-probes central only), and there is **no `IHealthCheckPublisher` anywhere**, so those checks run only on an inbound HTTP probe. Consequence worth knowing: the standby's correct-by-design `active-node` Unhealthy verdict is logged by `DefaultHealthCheckService` at **Error** on every probe, which `LoggerConfigurationFactory` now suppresses with one narrowly-keyed Serilog filter (register row 71 — see `Component-Host.md` → *Standby health-check log noise*; genuine failures of every other check still log at Error). Central reaches a site by dialling `GrpcNodeAAddress`/`GrpcNodeBAddress` explicitly and flipping on error; whichever node answers, the site-internal `ClusterSingletonProxy` lands the work on the active node for free, so central still never needs to track which *site* node is active. +- **Active/standby is decided by `ActiveNodeEvaluator.SelfIsOldestUp`, never by cluster leadership** — see the Architecture note above. **Central's** `/health/active` backs Traefik's active-node routing and the Inbound API uses the shared `ZB.MOM.WW.Health.IActiveNodeGate` (`AkkaActiveNodeGate`, same `ClusterActiveNode` rule; the private InboundAPI gate was removed in Gitea #80), so the proxy and the Inbound API always agree on which node is active. **Site nodes DO map `/health/*` too** — the "site nodes map no `/health/*` at all" claim that stood here was stale: `SiteServiceRegistration` registers `akka-cluster` + `localdb` (Ready) and the shared `ActiveNodeHealthCheck` (Active, constructed with the `site-{SiteId}` role so it is role-scoped; Degraded/200 during startup and publishes `activeNode`/`activeRole`/`selfAddress` data for the Overview dashboard — Gitea #97; central registers the same class unscoped), and `Program.cs`'s Site branch calls `MapZbHealth()` on the HTTP/1.1 listener so the family overview dashboard can probe every node identically. Nothing in this repo probes a site's `/health/active` (Traefik health-probes central only), and there is **no `IHealthCheckPublisher` anywhere**, so those checks run only on an inbound HTTP probe. Consequence worth knowing: the standby's correct-by-design `active-node` Unhealthy verdict is logged by `DefaultHealthCheckService` at **Error** on every probe, which `ScadaBridgeLogging` suppresses with one narrowly-keyed Serilog filter (installed through the shared `AddZbSerilog` `ConfigureLogger` hook since Gitea #94) (register row 71 — see `Component-Host.md` → *Standby health-check log noise*; genuine failures of every other check still log at Error). Central reaches a site by dialling `GrpcNodeAAddress`/`GrpcNodeBAddress` explicitly and flipping on error; whichever node answers, the site-internal `ClusterSingletonProxy` lands the work on the active node for free, so central still never needs to track which *site* node is active. - **Seed-node ordering: every node lists ITSELF first (decision 2026-07-22) — the boot-alone gap is CLOSED.** Only `seed-nodes[0]` may self-join to form a new cluster (Akka runs `FirstSeedNodeProcess` for it, `JoinSeedNodeProcess` — which can never form one — for everyone else). All 14 shipped node appsettings now lead with the node's own address, so any node can cold-start alone and become operational unattended (~5s, `seed-node-timeout`); `StartupValidator` fails the boot if the ordering is broken (compares host AND port; Akka does no DNS canonicalisation). Two nodes cold-starting together while mutually reachable converge on ONE cluster via the `InitJoin` handshake — they split only under a genuine boot-time partition, the same class auto-down accepts. **An external self-form timer (`Cluster.Join(SelfAddress)` after a window) was implemented and REJECTED:** it sits outside the join handshake, so on a routine standby restart — where the peer is alive but the join is stalled behind removal of the node's own stale incarnation — it fires mid-join and permanently splits the pair (measured: still split after 90s). Regression tests: `SelfFirstSeedBootstrapTests`. The keep-oldest active-crash total outage was separately closed by the auto-down decision. See `docs/requirements/Component-ClusterInfrastructure.md` → Seed Node Ordering. - **Simultaneous-cold-start split-brain guard (opt-in, Gitea #33) — the residual self-first cost, closed.** Self-first-on-both means a *truly simultaneous* cold start (shared power/hypervisor event) races `FirstSeedNodeProcess` on BOTH nodes → two 1-node clusters that never merge (in-process loopback tests converge and hide it; real parallel VM starts don't — OtOpcUa reproduced it live). Ported from OtOpcUa (`lmxopcua` `d1dac87f`): a **dark switch `ScadaBridge:Cluster:BootstrapGuard:Enabled` (default OFF, guard-off byte-identical)**. On: `BuildHocon` emits an EMPTY seed list (Akka does not auto-join) and `ClusterBootstrapCoordinator` (`IHostedService`, registered in BOTH the Central and Site composition roots) issues ONE reachability-gated `JoinSeedNodes` — the pure `ClusterBootstrapGuard` core makes the lower canonical `host:port` the **founder** (self-first, forms immediately), the higher node TCP-probes the founder up to `PartnerProbeSeconds` (25s) and joins **peer-first** if reachable else **self-first** (cold-start-alone preserved). Decided BEFORE a single join, **never re-forms mid-handshake** (that was the rejected self-form-timer's flaw); case-insensitive founder tie-break; probe timings validated `>0` when enabled. Residual accepted trade: founder dies in the probe→join window → higher node hangs unjoined, coordinator WARNs, a restart recovers it. Tests: `ClusterBootstrapGuardTests` (pure) + `ClusterBootstrapCoordinatorTests` (real-ActorSystem, incl. both-cold-start-together-form-one-cluster). **ENABLED on the docker rig (all 8 nodes) 2026-08-02** after `deploy.sh`'s simultaneous recreate split site pairs twice on 2026-08-01 with the guard off; live gate PASS — two consecutive simultaneous-start trials (a full redeploy + a full-topology `docker compose restart`), all four pairs converged (every lower-address node founded self-first, every higher node probed-then-joined peer-first), zero splits. Default remains OFF elsewhere (wonder-app-vd03, docker-env2, Host defaults). See `docs/requirements/Component-ClusterInfrastructure.md` → Simultaneous cold start. diff --git a/Directory.Packages.props b/Directory.Packages.props index cdc5652a..3c490192 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -106,8 +106,8 @@ - - + + diff --git a/docs/components/Host.md b/docs/components/Host.md index 47a1981b..ef85e83b 100644 --- a/docs/components/Host.md +++ b/docs/components/Host.md @@ -16,7 +16,7 @@ The component code lives in `src/ZB.MOM.WW.ScadaBridge.Host/`, split across: - `SiteServiceRegistration.cs` — extracted site-role DI registrations reused by both `Program.cs` and integration test harnesses. - `StartupValidator.cs` — pre-DI configuration preflight that fails fast before any actor system is created. - `StartupRetry.cs` — bounded exponential-backoff helper for startup preconditions (database migrations). -- `LoggerConfigurationFactory.cs` — builds the Serilog `LoggerConfiguration` with node-identity enrichment. +- `ScadaBridgeLogging.cs` — builds the process Serilog logger through the shared `AddZbSerilog` bootstrap (Telemetry.Serilog 0.2.0) with ScadaBridge's minimum-level governor and `ConfigureLogger` hook (standby active-node filter, configured node identity, LogContext, execution capture sink). ## Key Concepts diff --git a/docs/requirements/Component-Host.md b/docs/requirements/Component-Host.md index ba403f40..be8cb9ad 100644 --- a/docs/requirements/Component-Host.md +++ b/docs/requirements/Component-Host.md @@ -159,6 +159,7 @@ On site nodes, the Host must also use `WebApplication.CreateBuilder` (not `Host. The Host must configure Serilog as the logging provider with: +- **Built by the family's shared bootstrap (Gitea #94).** `ScadaBridgeLogging` builds the logger with `AddZbSerilog` (`ZB.MOM.WW.Telemetry.Serilog` 0.2.0+) and two ScadaBridge hooks: `MinimumLevelGovernor` (`ScadaBridge:Logging:MinimumLevel`, applied after `ReadFrom.Configuration` so it outranks `Serilog:MinimumLevel`; namespace `Override:*` entries still apply) and `ConfigureLogger` (the standby `active-node` filter below, the configured node identity, `Enrich.FromLogContext`, `ExecutionLogCaptureSink`). It runs `AddZbSerilog` on a small pre-host builder and `Program` installs the result as the static `Log.Logger`; both web hosts call `UseSerilog()` over it, so there is one logger and one file-sink handle per process and the static logger stays usable before the host is built and after it is disposed. - Configuration-driven sink setup (console and file sinks at minimum). - Automatic enrichment of every log entry with `SiteId`, `NodeHostname`, and `NodeRole` properties sourced from `NodeConfiguration`. - Structured (machine-parseable) output format. @@ -228,7 +229,7 @@ renders it as a *No self-heal* warning badge. See ### Standby health-check log noise -`LoggerConfigurationFactory` installs one Serilog exclusion filter, for the by-design standby +`ScadaBridgeLogging` (via the shared bootstrap's `ConfigureLogger` hook) installs one Serilog exclusion filter, for the by-design standby verdict of the `active-node` probe (register row 71). `DefaultHealthCheckService` logs one line per check per probe and picks the level from the verdict — diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs index 48454e12..58002a3c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs @@ -18,8 +18,9 @@ namespace ZB.MOM.WW.ScadaBridge.Host.Actors; /// Wiring. names this type in /// akka.loggers. It replaces Akka's DefaultLogger, which wrote to stdout only. Lines go /// to the static , which Program builds through -/// LoggerConfigurationFactory before the ActorSystem is created. ScadaBridge keeps its own -/// Serilog factory by design, so no Akka.Hosting or Akka.Logger.Serilog bridge is used. +/// ScadaBridgeLogging (the shared AddZbSerilog bootstrap) before the ActorSystem is +/// created. ScadaBridge owns that static logger by design, so no Akka.Hosting or +/// Akka.Logger.Serilog bridge is used. /// Levels. Filtering is unchanged. akka.loglevel (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 diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs b/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs deleted file mode 100644 index a53d4200..00000000 --- a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs +++ /dev/null @@ -1,220 +0,0 @@ -using Serilog; -using Serilog.Events; -using ZB.MOM.WW.Telemetry.Serilog; - -namespace ZB.MOM.WW.ScadaBridge.Host; - -/// -/// Builds the Serilog for the Host process. -/// -/// The configured minimum level comes from -/// ScadaBridge:Logging:MinimumLevel (bound to ) so an -/// operator editing that key changes the effective log level. -/// -/// The console and file sinks are read from the standard -/// Serilog configuration section via ReadFrom.Configuration — the sink -/// set, console output template, file path and rolling interval are all -/// configuration-driven (defined in appsettings.json), not hard-coded. The -/// explicit MinimumLevel.Is below pins the floor from . -/// -/// ScadaBridge:Logging:MinimumLevel is the single source of truth -/// for the floor — the explicit MinimumLevel.Is call deliberately runs -/// AFTER ReadFrom.Configuration so a Serilog:MinimumLevel entry in -/// configuration is overridden. To make that precedence visible (so an operator -/// who sets Serilog:MinimumLevel does not wonder why the change had no -/// effect), writes a one-shot warning to -/// when both keys are present. Pick one path — -/// editing Serilog:MinimumLevel alone has no effect. -/// -public static class LoggerConfigurationFactory -{ - /// Builds a enriched with node-identity properties and a configured minimum level. - /// Application configuration supplying the Serilog section and logging options. - /// Role label (e.g., central-a) added as a log enrichment property. - /// Site identifier added as a log enrichment property. - /// Hostname added as a log enrichment property. - /// The configured . - public static LoggerConfiguration Build( - IConfiguration configuration, - string nodeRole, - string siteId, - string nodeHostname) - => Build(configuration, nodeRole, siteId, nodeHostname, Console.Error); - - /// - /// Test-visible overload of - /// that routes the precedence warning through a caller-supplied - /// writer so unit tests can capture it. Production calls the four-arg - /// overload which uses . - /// - /// Application configuration supplying the Serilog section and logging options. - /// Role label added as a log enrichment property. - /// Site identifier added as a log enrichment property. - /// Hostname added as a log enrichment property. - /// Writer that receives the one-shot override-warning when both keys are present. - /// The fully configured ready to create the Serilog logger. - 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()); - } - - /// - /// Logger category that emits the per-probe "Health check {HealthCheckName} with status - /// {HealthStatus} …" line. It is DefaultHealthCheckService, not - /// HealthCheckPublisherHostedService: this host registers no - /// IHealthCheckPublisher, so the checks run only on an inbound HTTP probe of - /// /health/*. - /// - internal const string HealthCheckServiceSourceContext = - "Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService"; - - /// Name both the site and central /health/active probes register under. - internal const string ActiveNodeCheckName = "active-node"; - - /// - /// Suppresses the standby node's correct-by-design active-node Error line - /// (deferred-work register row 71). - /// - /// - /// - /// The problem. DefaultHealthCheckService logs one line per check per probe, - /// picking the level from the verdict — Debug for Healthy, Warning for Degraded, - /// Error for Unhealthy. Both active-node checks - /// (the shared ActiveNodeHealthCheck, role-scoped on a site and unscoped - /// on central) answer Unhealthy on the standby, because 503 is exactly the contract - /// /health/active 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. - /// - /// - /// Why a filter and not a level override. Serilog's MinimumLevel.Override - /// can only RAISE a per-source floor; it cannot rewrite one Error event as Information. - /// A LogEvent'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 /health/active itself, the - /// cluster view on the readiness probe, and the health dashboard. - /// - /// - /// Why this cannot hide a genuine failure. The predicate is keyed on the check - /// NAME, not on the category, so a failing localdb, akka-cluster, - /// database, or required-singletons 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. - /// - /// - /// Matching on rather than on the HealthStatus - /// property avoids depending on how the enum renders into the event; the level→verdict - /// mapping above already makes Error equivalent to Unhealthy. - /// - /// - /// The candidate log event. - /// when the event should be dropped. - 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); - } - - /// Tests one structured property for an exact scalar string value. - /// The event whose properties are inspected. - /// The structured property name. - /// The value the property must equal. - /// on an exact ordinal match. - 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); - - /// - /// Parses a Serilog name, falling back to - /// for null/blank/unrecognised values. - /// - /// When an operator sets ScadaBridge:Logging:MinimumLevel 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 - /// using ; 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. - /// - /// Configured level string, possibly null/blank/invalid. - /// The parsed , or when the value is absent or unrecognised. - internal static LogEventLevel ParseLevel(string? level) - => ParseLevel(level, Console.Error); - - /// - /// Test-visible overload of that routes the - /// one-shot warning through a caller-supplied writer ( - /// in production) so unit tests can capture the warning output. - /// - /// Configured level string, possibly null/blank/invalid. - /// Writer that receives a single warning line if the value is non-blank but unparseable. - /// The parsed , or when the value is absent or unrecognised. - internal static LogEventLevel ParseLevel(string? level, TextWriter warningWriter) - { - if (Enum.TryParse(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; - } -} diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/LoggingOptionsValidator.cs b/src/ZB.MOM.WW.ScadaBridge.Host/LoggingOptionsValidator.cs index 1adbffdd..9bb50e9a 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/LoggingOptionsValidator.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/LoggingOptionsValidator.cs @@ -6,7 +6,7 @@ namespace ZB.MOM.WW.ScadaBridge.Host; /// /// Validates at host startup (arch-review 08 round /// 2 NF4). is parsed into a Serilog -/// by LoggerConfigurationFactory.ParseLevel, +/// by ScadaBridgeLogging.ParseLevel, /// which silently falls back to Information 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/ diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/Program.cs b/src/ZB.MOM.WW.ScadaBridge.Host/Program.cs index f646b9e9..b6e85cc1 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/Program.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/Program.cs @@ -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 diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/ScadaBridgeLogging.cs b/src/ZB.MOM.WW.ScadaBridge.Host/ScadaBridgeLogging.cs new file mode 100644 index 00000000..9ee7cf7b --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Host/ScadaBridgeLogging.cs @@ -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; + +/// +/// Builds the Host process's Serilog logger through the family's shared bootstrap, +/// AddZbSerilog (ZB.MOM.WW.Telemetry.Serilog 0.2.0+, ScadaBridge#94), with two +/// ScadaBridge hooks: a minimum-level governor and a final callback. +/// +/// +/// +/// What the shared bootstrap supplies. ReadFrom.Configuration over the standard +/// Serilog section (the console and file sinks, output template, file path and rolling +/// interval all stay configuration-driven in appsettings.json), the SiteId / +/// NodeRole / NodeHostname identity enrichers, the shared TraceContextEnricher +/// and the (inert here, no ILogRedactor is registered) redaction seam. No OTLP log sink is +/// added: the telemetry options passed here never select the OTLP exporter, as before. +/// +/// +/// Minimum level (Host-011). ScadaBridge:Logging:MinimumLevel is the single source of +/// truth for the floor. is handed to +/// ZbSerilogOptions.MinimumLevelGovernor, which the library applies AFTER +/// ReadFrom.Configuration, so a Serilog:MinimumLevel entry is overridden. It always +/// returns a level (never ), 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 +/// Serilog:MinimumLevel learns why the change had no effect. Namespace +/// Serilog:MinimumLevel:Override:* entries still apply. +/// +/// +/// Final hook. ZbSerilogOptions.ConfigureLogger adds what is ScadaBridge's own: the +/// standby active-node exclusion filter (register row 71), the exact node identity this +/// process was configured with (the library stamps NodeHostname from the machine name; +/// ScadaBridge has always stamped ScadaBridge:Node:NodeHostname), Enrich.FromLogContext +/// (ScadaBridge#56 run identity) and the Flow Debugger ExecutionLogCaptureSink. +/// +/// +/// Who owns the logger. AddZbSerilog registers the logger in a container and leaves +/// alone. ScadaBridge needs the static logger before any host exists +/// (startup banner and warnings, a pre-host Fatal), for the Akka bridge +/// (SerilogAkkaLogger), and after the host is disposed (the shutdown line and the +/// unexpected-termination Fatal). So +/// runs AddZbSerilog on a small pre-host builder and resolves the logger from it once; +/// Program installs it as and the web hosts keep +/// UseSerilog() 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 +/// Log.CloseAndFlushAsync() in Program's finally does. +/// +/// +public static class ScadaBridgeLogging +{ + /// The OTel service.name ScadaBridge registers with AddZbTelemetry. + internal const string ServiceName = "scadabridge"; + + /// Creates the process logger: the shared bootstrap plus ScadaBridge's hooks. + /// Application configuration supplying the Serilog section and logging options. + /// Role label (e.g., Central) stamped as NodeRole. + /// Site identifier stamped as SiteId. + /// Configured node hostname stamped as NodeHostname. + /// The built logger; the caller owns it (Program installs it as ). + public static Logger CreateLogger( + IConfiguration configuration, + string nodeRole, + string siteId, + string nodeHostname) + => CreateLogger(configuration, nodeRole, siteId, nodeHostname, Console.Error, additionalConfiguration: null); + + /// + /// Test-visible overload of : + /// routes the operator warnings through and lets a test append + /// a capturing sink after ScadaBridge's own hook. + /// + /// Application configuration supplying the Serilog section and logging options. + /// Role label stamped as NodeRole. + /// Site identifier stamped as SiteId. + /// Configured node hostname stamped as NodeHostname. + /// Receives the one-shot operator warnings. + /// Optional extra configuration applied last (tests add a sink here). + /// The built logger. + internal static Logger CreateLogger( + IConfiguration configuration, + string nodeRole, + string siteId, + string nodeHostname, + TextWriter warningWriter, + Action? 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(); + } + + /// + /// Registers the ScadaBridge logger on through AddZbSerilog + /// with the minimum-level governor and the final ScadaBridge hook. + /// + /// The host application builder. + /// Role label stamped as NodeRole. + /// Site identifier stamped as SiteId. + /// Configured node hostname stamped as NodeHostname. + /// Receives the one-shot operator warnings. + /// Optional extra configuration applied last. + /// The same builder. + internal static IHostApplicationBuilder AddScadaBridgeSerilog( + this IHostApplicationBuilder builder, + string nodeRole, + string siteId, + string nodeHostname, + TextWriter warningWriter, + Action? 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); + }; + }); + } + + /// + /// The minimum-level governor: reads ScadaBridge:Logging:MinimumLevel (falling back to + /// Information, with a warning for an unparseable value) and warns once when a + /// Serilog:MinimumLevel entry is present, because this value overrides it. + /// + /// The application configuration. + /// Receives the one-shot operator warnings. + /// The governed floor; never . + 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; + } + + /// + /// ScadaBridge's own pipeline stages, run by ZbSerilogOptions.ConfigureLogger after the + /// shared bootstrap. + /// + /// The configuration being built. + /// Role label stamped as NodeRole. + /// Site identifier stamped as SiteId. + /// Configured node hostname stamped as NodeHostname. + 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()); + } + + /// Stamps the configured node identity, overwriting any earlier value. + 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); + } + } + + /// + /// Logger category that emits the per-probe "Health check {HealthCheckName} with status + /// {HealthStatus} …" line. It is DefaultHealthCheckService, not + /// HealthCheckPublisherHostedService: this host registers no + /// IHealthCheckPublisher, so the checks run only on an inbound HTTP probe of + /// /health/*. + /// + internal const string HealthCheckServiceSourceContext = + "Microsoft.Extensions.Diagnostics.HealthChecks.DefaultHealthCheckService"; + + /// Name both the site and central /health/active probes register under. + internal const string ActiveNodeCheckName = "active-node"; + + /// + /// Suppresses the standby node's correct-by-design active-node Error line + /// (deferred-work register row 71). + /// + /// + /// + /// The problem. DefaultHealthCheckService logs one line per check per probe, + /// picking the level from the verdict — Debug for Healthy, Warning for Degraded, + /// Error for Unhealthy. Both active-node checks + /// (the shared ActiveNodeHealthCheck, role-scoped on a site and unscoped + /// on central) answer Unhealthy on the standby, because 503 is exactly the contract + /// /health/active 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. + /// + /// + /// Why a filter and not a level override. Serilog's MinimumLevel.Override + /// can only RAISE a per-source floor; it cannot rewrite one Error event as Information. + /// A LogEvent'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 /health/active itself, the + /// cluster view on the readiness probe, and the health dashboard. + /// + /// + /// Why this cannot hide a genuine failure. The predicate is keyed on the check + /// NAME, not on the category, so a failing localdb, akka-cluster, + /// database, or required-singletons 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. + /// + /// + /// Matching on rather than on the HealthStatus + /// property avoids depending on how the enum renders into the event; the level→verdict + /// mapping above already makes Error equivalent to Unhealthy. + /// + /// + /// The candidate log event. + /// when the event should be dropped. + 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); + } + + /// Tests one structured property for an exact scalar string value. + /// The event whose properties are inspected. + /// The structured property name. + /// The value the property must equal. + /// on an exact ordinal match. + 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); + + /// + /// Parses a Serilog name, falling back to + /// for null/blank/unrecognised values. + /// + /// When an operator sets ScadaBridge:Logging:MinimumLevel 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 + /// using ; 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. + /// + /// Configured level string, possibly null/blank/invalid. + /// The parsed , or when the value is absent or unrecognised. + internal static LogEventLevel ParseLevel(string? level) + => ParseLevel(level, Console.Error); + + /// + /// Test-visible overload of that routes the + /// one-shot warning through a caller-supplied writer ( + /// in production) so unit tests can capture the warning output. + /// + /// Configured level string, possibly null/blank/invalid. + /// Writer that receives a single warning line if the value is non-blank but unparseable. + /// The parsed , or when the value is absent or unrecognised. + internal static LogEventLevel ParseLevel(string? level, TextWriter warningWriter) + { + if (Enum.TryParse(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; + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs index 7e71e02e..ab162c5c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs @@ -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 /// ExecutionId, InstanceName and ScriptName once the host enables -/// Enrich.FromLogContext() (LoggerConfigurationFactory). +/// Enrich.FromLogContext() (ScadaBridgeLogging). /// /// /// LogContext is an AsyncLocal: it follows the run's own call chain but NOT an Akka diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs index f8d4b374..b4e7afba 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs @@ -23,10 +23,8 @@ public class LoggerConfigurationTests public void MinimumLevel_Warning_SuppressesInformationLogs() { var sink = new InMemorySink(); - var logger = LoggerConfigurationFactory - .Build(BuildConfig("Warning"), "Central", "central", "node1") - .WriteTo.Sink(sink) - .CreateLogger(); + var logger = ScadaBridgeLogging.CreateLogger( + BuildConfig("Warning"), "Central", "central", "node1", new StringWriter(), lc => lc.WriteTo.Sink(sink)); logger.Information("info message"); logger.Warning("warning message"); @@ -40,10 +38,8 @@ public class LoggerConfigurationTests public void LogContextProperties_AreEnrichedOntoEvents() { var sink = new InMemorySink(); - var logger = LoggerConfigurationFactory - .Build(BuildConfig(null), "Site", "site-a", "node1") - .WriteTo.Sink(sink) - .CreateLogger(); + var logger = ScadaBridgeLogging.CreateLogger( + BuildConfig(null), "Site", "site-a", "node1", new StringWriter(), lc => lc.WriteTo.Sink(sink)); var id = Guid.NewGuid(); using (Serilog.Context.LogContext.PushProperty("ExecutionId", id)) @@ -62,10 +58,8 @@ public class LoggerConfigurationTests public void MinimumLevel_Debug_AllowsDebugLogs() { var sink = new InMemorySink(); - var logger = LoggerConfigurationFactory - .Build(BuildConfig("Debug"), "Site", "site-a", "node1") - .WriteTo.Sink(sink) - .CreateLogger(); + var logger = ScadaBridgeLogging.CreateLogger( + BuildConfig("Debug"), "Site", "site-a", "node1", new StringWriter(), lc => lc.WriteTo.Sink(sink)); logger.Debug("debug message"); @@ -78,10 +72,8 @@ public class LoggerConfigurationTests public void MinimumLevel_Absent_DefaultsToInformation() { var sink = new InMemorySink(); - var logger = LoggerConfigurationFactory - .Build(BuildConfig(null), "Central", "central", "node1") - .WriteTo.Sink(sink) - .CreateLogger(); + var logger = ScadaBridgeLogging.CreateLogger( + BuildConfig(null), "Central", "central", "node1", new StringWriter(), lc => lc.WriteTo.Sink(sink)); logger.Debug("debug message"); logger.Information("info message"); @@ -101,7 +93,7 @@ public class LoggerConfigurationTests { var writer = new StringWriter(); - var result = LoggerConfigurationFactory.ParseLevel("Informaiton", writer); + var result = ScadaBridgeLogging.ParseLevel("Informaiton", writer); Assert.Equal(LogEventLevel.Information, result); var warning = writer.ToString(); @@ -116,8 +108,8 @@ public class LoggerConfigurationTests { var writer = new StringWriter(); - var nullResult = LoggerConfigurationFactory.ParseLevel(null, writer); - var blankResult = LoggerConfigurationFactory.ParseLevel(" ", writer); + var nullResult = ScadaBridgeLogging.ParseLevel(null, writer); + var blankResult = ScadaBridgeLogging.ParseLevel(" ", writer); Assert.Equal(LogEventLevel.Information, nullResult); Assert.Equal(LogEventLevel.Information, blankResult); @@ -130,7 +122,7 @@ public class LoggerConfigurationTests { var writer = new StringWriter(); - var result = LoggerConfigurationFactory.ParseLevel("Warning", writer); + var result = ScadaBridgeLogging.ParseLevel("Warning", writer); Assert.Equal(LogEventLevel.Warning, result); Assert.Empty(writer.ToString()); @@ -141,7 +133,7 @@ public class LoggerConfigurationTests /// of truth for the Serilog floor, and the explicit MinimumLevel.Is /// call deliberately runs after ReadFrom.Configuration(...) so a /// Serilog:MinimumLevel entry is overridden. To make that precedence - /// visible — instead of silently swallowed — + /// visible — instead of silently swallowed — /// writes a one-shot warning when both keys are present. The warning must /// name both values and point the operator at the documented key. When the /// Serilog key is absent the warning is silent. @@ -158,7 +150,7 @@ public class LoggerConfigurationTests }) .Build(); - LoggerConfigurationFactory.Build(configuration, "Central", "central", "node1", writer); + using var _ = ScadaBridgeLogging.CreateLogger(configuration, "Central", "central", "node1", writer, null); var warning = writer.ToString(); Assert.Contains("warning", warning, StringComparison.OrdinalIgnoreCase); @@ -180,7 +172,7 @@ public class LoggerConfigurationTests }) .Build(); - LoggerConfigurationFactory.Build(configuration, "Central", "central", "node1", writer); + using var _ = ScadaBridgeLogging.CreateLogger(configuration, "Central", "central", "node1", writer, null); // No Serilog override -> no override-warning. (The ScadaBridge value is // a recognised level, so ParseLevel is silent too.) @@ -201,8 +193,7 @@ public class LoggerConfigurationTests public void Build_IncludesTheExecutionCaptureSink() { var configuration = new ConfigurationBuilder().AddInMemoryCollection(new Dictionary()).Build(); - using var logger = LoggerConfigurationFactory.Build(configuration, "Site", "site-a", "node1", new StringWriter()) - .CreateLogger(); + using var logger = ScadaBridgeLogging.CreateLogger(configuration, "Site", "site-a", "node1", new StringWriter(), null); var id = Guid.NewGuid(); var target = new CollectingTarget(); diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/ScadaBridgeLoggingParityTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/ScadaBridgeLoggingParityTests.cs new file mode 100644 index 00000000..75223c87 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/ScadaBridgeLoggingParityTests.cs @@ -0,0 +1,181 @@ +using System.Diagnostics; +using Microsoft.Extensions.Configuration; +using Serilog; +using Serilog.Core; +using Serilog.Events; + +namespace ZB.MOM.WW.ScadaBridge.Host.Tests; + +/// +/// ScadaBridge#94: the host logger moved from ScadaBridge's own LoggerConfigurationFactory +/// onto the shared AddZbSerilog bootstrap (Telemetry.Serilog 0.2.0) with a minimum-level +/// governor and a final ConfigureLogger hook. These tests pin the behaviour the old factory +/// had, through the real pipeline: level governance (the ScadaBridge key outranks the Serilog key, +/// namespace overrides still apply), the exact node-identity enrichers, trace correlation and the +/// property set of a plain line. The standby filter is pinned in +/// and the configured file sink in +/// , both through the same pipeline. +/// +public class ScadaBridgeLoggingParityTests +{ + private static IConfiguration Config(params (string Key, string Value)[] values) => + new ConfigurationBuilder() + .AddInMemoryCollection(values.ToDictionary(v => v.Key, v => (string?)v.Value)) + .Build(); + + private static Logger Create( + IConfiguration configuration, + InMemorySink sink, + string nodeRole = "Site", + string siteId = "site-a", + string nodeHostname = "configured-node-hostname", + TextWriter? writer = null) => + ScadaBridgeLogging.CreateLogger( + configuration, nodeRole, siteId, nodeHostname, writer ?? new StringWriter(), lc => lc.WriteTo.Sink(sink)); + + /// + /// Host-011: ScadaBridge:Logging:MinimumLevel is the floor even when + /// Serilog:MinimumLevel asks for something more verbose. Fails if the governor stops + /// running after ReadFrom.Configuration (the shared default ordering). + /// + [Fact] + public void ScadaBridgeLevel_OutranksAMoreVerboseSerilogLevel() + { + var sink = new InMemorySink(); + using var logger = Create( + Config(("ScadaBridge:Logging:MinimumLevel", "Warning"), ("Serilog:MinimumLevel", "Verbose")), + sink); + + logger.Debug("debug"); + logger.Information("info"); + logger.Warning("warning"); + + var evt = Assert.Single(sink.LogEvents); + Assert.Equal(LogEventLevel.Warning, evt.Level); + } + + /// + /// The governor never defers to the Serilog key: with the ScadaBridge key absent the floor is + /// Information (the default), not the configured Serilog Error. + /// + [Fact] + public void ScadaBridgeKeyAbsent_FloorIsInformation_NotTheSerilogKey() + { + var sink = new InMemorySink(); + using var logger = Create(Config(("Serilog:MinimumLevel:Default", "Error")), sink); + + logger.Debug("debug"); + logger.Information("info"); + + var evt = Assert.Single(sink.LogEvents); + Assert.Equal(LogEventLevel.Information, evt.Level); + } + + /// + /// Only the DEFAULT level is governed: a Serilog:MinimumLevel:Override:* namespace entry + /// still raises that namespace's floor, as it did under the old factory. + /// + [Fact] + public void NamespaceOverrides_StillApply() + { + var sink = new InMemorySink(); + using var logger = Create( + Config( + ("ScadaBridge:Logging:MinimumLevel", "Debug"), + ("Serilog:MinimumLevel:Override:Noisy.Namespace", "Error")), + sink); + + logger.ForContext(Constants.SourceContextPropertyName, "Noisy.Namespace.Thing").Warning("noisy warning"); + logger.ForContext(Constants.SourceContextPropertyName, "Quiet.Namespace.Thing").Debug("quiet debug"); + + var evt = Assert.Single(sink.LogEvents); + Assert.Equal("quiet debug", evt.RenderMessage()); + } + + /// The override warning is written once per logger build, not per line. + [Fact] + public void OverrideWarning_IsOneShot() + { + var sink = new InMemorySink(); + var writer = new StringWriter(); + using var logger = Create( + Config(("ScadaBridge:Logging:MinimumLevel", "Warning"), ("Serilog:MinimumLevel", "Debug")), + sink, + writer: writer); + + logger.Warning("one"); + logger.Warning("two"); + + var lines = writer.ToString().Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries); + Assert.Single(lines); + } + + /// + /// NodeHostname is the CONFIGURED ScadaBridge:Node:NodeHostname, not the machine + /// name the shared bootstrap stamps, and SiteId/NodeRole are the configured values. + /// + [Fact] + public void IdentityEnrichers_AreTheConfiguredValues() + { + var sink = new InMemorySink(); + const string hostname = "configured-node-hostname"; + Assert.NotEqual(hostname, Environment.MachineName); // positive control: the two differ + using var logger = Create(Config(), sink, nodeRole: "Central", siteId: "central", nodeHostname: hostname); + + logger.Information("line"); + + var evt = Assert.Single(sink.LogEvents); + Assert.Equal("central", Scalar(evt, "SiteId")); + Assert.Equal("Central", Scalar(evt, "NodeRole")); + Assert.Equal(hostname, Scalar(evt, "NodeHostname")); + } + + /// + /// The old factory stamped an empty SiteId verbatim; the shared bootstrap skips empty + /// identity values. ScadaBridge keeps stamping it. + /// + [Fact] + public void EmptySiteId_IsStillStamped() + { + var sink = new InMemorySink(); + using var logger = Create(Config(), sink, siteId: ""); + + logger.Information("line"); + + Assert.Equal("", Scalar(Assert.Single(sink.LogEvents), "SiteId")); + } + + /// + /// A plain line carries exactly the three identity properties — no enricher was added or lost + /// in the move (the trace enricher adds nothing outside an Activity, the redaction seam is inert). + /// + [Fact] + public void PlainLine_CarriesExactlyTheIdentityProperties() + { + var sink = new InMemorySink(); + using var logger = Create(Config(), sink); + + logger.Information("plain"); + + var keys = Assert.Single(sink.LogEvents).Properties.Keys.OrderBy(k => k, StringComparer.Ordinal); + Assert.Equal(new[] { "NodeHostname", "NodeRole", "SiteId" }, keys); + } + + /// Inside an Activity the shared TraceContextEnricher stamps trace_id/span_id. + [Fact] + public void InsideAnActivity_TraceContextIsStamped() + { + var sink = new InMemorySink(); + using var logger = Create(Config(), sink); + using var activity = new Activity("parity-test").SetIdFormat(ActivityIdFormat.W3C).Start(); + + logger.Information("traced"); + + var evt = Assert.Single(sink.LogEvents); + Assert.Equal(activity.TraceId.ToHexString(), Scalar(evt, "trace_id")); + Assert.Equal(activity.SpanId.ToHexString(), Scalar(evt, "span_id")); + } + + private static string? Scalar(LogEvent evt, string name) => + evt.Properties.TryGetValue(name, out var value) && value is ScalarValue { Value: var v } ? v?.ToString() : null; +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs index 06be146f..e345de9b 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs @@ -50,7 +50,7 @@ public class SerilogAkkaLoggerTests : TestKit /// /// The system keeps Akka's default logger (TestKit's); each test that needs the bridge spawns a /// over a capturing pipeline that mirrors the host's - /// LoggerConfigurationFactory (Enrich.FromLogContext plus a node property). + /// ScadaBridgeLogging (Enrich.FromLogContext plus a node property). /// public SerilogAkkaLoggerTests() : base("akka.loglevel = INFO") { diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogSinkConfigTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogSinkConfigTests.cs index de23a209..90cf9632 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogSinkConfigTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogSinkConfigTests.cs @@ -52,9 +52,9 @@ public class SerilogSinkConfigTests Assert.Contains("File", sinkNames); } - /// Verifies that the logger configuration factory applies the configured file sink. + /// Verifies that the host logger (shared AddZbSerilog bootstrap) applies the configured file sink. [Fact] - public void LoggerConfigurationFactory_AppliesConfiguredFileSink() + public void ScadaBridgeLogging_AppliesConfiguredFileSink() { // A `Serilog` section in configuration must actually reach the built logger // via ReadFrom.Configuration — proving the sink set is configuration-driven. @@ -72,9 +72,8 @@ public class SerilogSinkConfigTests }) .Build(); - var logger = LoggerConfigurationFactory - .Build(configuration, "Central", "central", "node1") - .CreateLogger(); + var logger = ScadaBridgeLogging.CreateLogger( + configuration, "Central", "central", "node1", new StringWriter(), null); logger.Information("host-014 configured-sink probe"); logger.Dispose(); diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/StandbyHealthCheckLogNoiseTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/StandbyHealthCheckLogNoiseTests.cs index c4e432b3..38aa4e59 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/StandbyHealthCheckLogNoiseTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/StandbyHealthCheckLogNoiseTests.cs @@ -38,10 +38,9 @@ public class StandbyHealthCheckLogNoiseTests }) .Build(); - return LoggerConfigurationFactory - .Build(config, "Site", "site-a", "site-a-b") - .WriteTo.Sink(sink) - .CreateLogger(); + // 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)); } /// Emits one event shaped exactly like the framework's per-check line. @@ -155,6 +154,6 @@ public class StandbyHealthCheckLogNoiseTests { // 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(LoggerConfigurationFactory.IsExpectedStandbyActiveNodeProbe(null!)); + Assert.False(ScadaBridgeLogging.IsExpectedStandbyActiveNodeProbe(null!)); } }