From 29a202f5ee99e50f5859127c93cda615cc954b14 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 11 Aug 2026 05:52:54 -0400 Subject: [PATCH] =?UTF-8?q?fix(logging):=20#561=20=E2=80=94=20SelfLog=20to?= =?UTF-8?q?=20file+stderr=20and=20a=20startup=20file-sink=20growth=20self-?= =?UTF-8?q?check?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Production ran six weeks with a healthy process and a 0-byte log because Serilog isolates per-sink failures: a file sink whose every write fails is invisible from anywhere but SelfLog, which was not enabled. Two instruments: - LogPipelineDiagnostics.EnableSelfLog (before the first logger builds): SelfLog to logs/serilog-selflog.txt (rotated at 5 MB) + stderr — the only channel that carries the exception the sink swallows. - CheckFileSinkGrowth (after the startup banner): verifies each configured, unbuffered file sink's rolled-file family physically grew across a marker event; a silent sink is reported at boot via SelfLog/stderr and the console sink instead of discovered months later. Growth-across-marker, not existence — a previous run's bytes must not mask a silent sink (the false pass an existence check would have given on wonder-app-vd03). Never throws: both instruments swallow their own failures — a diagnostics channel that can fail startup is worse than the defect it watches for. The load-bearing test is the failure case (a sink that writes nothing IS reported); a check that can only pass is indistinguishable from no check. --- .../Logging/LogPipelineDiagnostics.cs | 156 ++++++++++++++++++ src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs | 18 ++ .../Logging/LogPipelineDiagnosticsTests.cs | 143 ++++++++++++++++ 3 files changed, 317 insertions(+) create mode 100644 src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs create mode 100644 tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs new file mode 100644 index 00000000..dacf0f82 --- /dev/null +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs @@ -0,0 +1,156 @@ +using Serilog.Debugging; + +namespace ZB.MOM.WW.OtOpcUa.Host.Logging; + +/// +/// Diagnostics for the "healthy process, silent log" failure mode (Gitea #561): Serilog isolates +/// per-sink failures, so a file sink whose every write fails leaves a 0-byte log, a fully +/// functional server, and no visible signal anywhere — production ran that way for six weeks. +/// Two instruments close it: +/// +/// — turns on Serilog's , the only +/// channel that sees the exceptions sinks swallow, writing to a dedicated file plus stderr. +/// — after the startup banner, verifies each +/// configured file sink actually grew when an event was emitted, so a silently-failing +/// sink is reported at boot instead of discovered months later. +/// +/// +public static class LogPipelineDiagnostics +{ + /// + /// Relative to the current directory, which Program.cs anchors to the install dir before + /// calling this. Deliberately a fixed path rather than derived from the sink config: this is + /// the channel of last resort and must not depend on the configuration it is diagnosing. + /// + internal const string SelfLogPath = "logs/serilog-selflog.txt"; + + /// + /// A broken sink can fail on every event indefinitely (two SelfLog lines per event), so cap + /// the file by deleting an oversized one at boot rather than growing it across restarts. + /// + private const long SelfLogRotateBytes = 5 * 1024 * 1024; + + /// + /// Enables Serilog SelfLog to and stderr. Failures reported here are + /// the ones sinks swallow — without this they are invisible by design. Never throws: a + /// diagnostics channel that can fail startup is worse than the defect it watches for; if the + /// file cannot be opened, stderr alone is used. + /// + public static void EnableSelfLog() + { + StreamWriter? writer = null; + try + { + var dir = Path.GetDirectoryName(SelfLogPath); + if (!string.IsNullOrEmpty(dir)) + Directory.CreateDirectory(dir); + + var info = new FileInfo(SelfLogPath); + if (info.Exists && info.Length > SelfLogRotateBytes) + info.Delete(); + + writer = new StreamWriter( + new FileStream(SelfLogPath, FileMode.Append, FileAccess.Write, FileShare.Read)) + { AutoFlush = true }; + } + catch + { + writer = null; + } + + var gate = new object(); + SelfLog.Enable(message => + { + lock (gate) + { + try { writer?.WriteLine(message); } catch { /* channel of last resort — swallow */ } + try { Console.Error.WriteLine(message); } catch { /* ditto */ } + } + }); + } + + /// + /// Verifies every config-driven Serilog file sink physically grew when + /// ran. Returns null when all sinks grew (or there is nothing checkable), else a warning + /// naming the silent template(s). The check measures total bytes across each template's + /// rolled-file family (logs/otopcua-.log → otopcua-*.log, which also covers the + /// _NNN collision-fallback names), so it is agnostic to rolling interval and to which + /// concrete file the sink is currently writing. Growth by a concurrent event counts as a pass — + /// the claim under test is "this sink's writes reach disk", not "our marker specifically landed". + /// + /// The host configuration carrying Serilog:WriteTo. + /// Emits one event through the live pipeline (synchronous sinks flush before returning). + public static string? CheckFileSinkGrowth(IConfiguration configuration, Action emitMarker) + { + try + { + var templates = new List(); + foreach (var sink in configuration.GetSection("Serilog:WriteTo").GetChildren()) + { + if (!string.Equals(sink["Name"], "File", StringComparison.Ordinal)) + continue; + // A buffered sink legitimately defers bytes past the marker, so growth proves nothing + // either way — skip rather than false-alarm. (This host's config is unbuffered.) + if (string.Equals(sink["Args:buffered"], "true", StringComparison.OrdinalIgnoreCase)) + continue; + var path = sink["Args:path"]; + if (!string.IsNullOrWhiteSpace(path)) + templates.Add(path); + } + + if (templates.Count == 0) + return null; + + var before = templates.Select(MeasureFamilyBytes).ToArray(); + emitMarker(); + var silent = templates.Where((t, i) => MeasureFamilyBytes(t) <= before[i]).ToList(); + + return silent.Count == 0 + ? null + : "Log-pipeline self-check FAILED: the Serilog file sink(s) at " + + string.Join(", ", silent.Select(t => $"'{t}'")) + + $" did not grow when a log event was emitted (cwd: {Directory.GetCurrentDirectory()})." + + " The process will run but its log stays empty — the #561 failure mode. Serilog" + + $" swallows per-sink write errors; the actual exception is in SelfLog ({SelfLogPath})" + + " and on stderr."; + } + catch + { + // Never let the self-check take down or delay the host over a diagnostics defect. + return null; + } + } + + /// + /// Routes a self-check failure to the channels that do not depend on the broken pipeline: + /// the SelfLog output (file + stderr). Also emitted through the normal logger by the caller — + /// useless when the file sink is the broken part, but it reaches the console sink and any + /// OTel export. + /// + public static void ReportFailure(string warning) => SelfLog.WriteLine("{0}", warning); + + /// + /// Total bytes across the template's file family. The family glob is prefix + "*" + extension + /// so otopcua-.log matches its own rolled (otopcua-20260811.log) and sequence + /// (otopcua-20260811_001.log) forms, and — because * matches zero characters — + /// the un-rolled name itself. + /// + private static long MeasureFamilyBytes(string pathTemplate) + { + var dir = Path.GetDirectoryName(pathTemplate); + if (string.IsNullOrEmpty(dir)) + dir = "."; + if (!Directory.Exists(dir)) + return 0; + + var pattern = Path.GetFileNameWithoutExtension(pathTemplate) + "*" + Path.GetExtension(pathTemplate); + long total = 0; + foreach (var file in Directory.EnumerateFiles(dir, pattern)) + { + try { total += new FileInfo(file).Length; } + catch (IOException) { /* rolled away mid-scan */ } + } + + return total; + } +} diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs index 1d4762e7..f7f66d82 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs @@ -122,6 +122,13 @@ await using (var secretsProvider = new ServiceCollection() // untouched. UseWindowsService already roots the content root at the base dir, so this only affects sinks. Directory.SetCurrentDirectory(AppContext.BaseDirectory); +// #561 — Serilog SelfLog to logs/serilog-selflog.txt + stderr, enabled before the first logger +// builds. Serilog isolates per-sink failures, so a file sink whose writes fail leaves a 0-byte +// log and a healthy process with no signal anywhere; SelfLog is the only channel that sees the +// swallowed exception. Placed after the CWD anchor above so the relative path lands in the +// install dir. +LogPipelineDiagnostics.EnableSelfLog(); + // Serilog — shared ZB.MOM.WW.Telemetry bootstrap. Sinks (Console + rolling daily file) // now live in appsettings.json (ReadFrom.Configuration); AddZbSerilog layers in the // shared NodeHostname / TraceContext / Redaction enrichers and trace correlation. @@ -777,6 +784,17 @@ app.MapOtOpcUaMetrics(); Log.Information("OtOpcUa.Host starting with roles=[{Roles}] (admin={HasAdmin}, driver={HasDriver})", string.Join(",", roles), hasAdmin, hasDriver); +// #561 — startup growth self-check: the banner above went through the live pipeline; verify each +// configured file sink physically grew. A sink whose writes silently fail (the wonder-app-vd03 +// 0-byte-log incident) is reported at boot — through SelfLog + stderr, which don't depend on the +// broken sink, and through the normal logger for the console sink's benefit. +if (LogPipelineDiagnostics.CheckFileSinkGrowth(app.Configuration, + () => Log.Information("Log-pipeline self-check marker")) is { } logSelfCheckWarning) +{ + LogPipelineDiagnostics.ReportFailure(logSelfCheckWarning); + Log.Warning("{LogSelfCheckWarning}", logSelfCheckWarning); +} + await app.RunAsync(); namespace ZB.MOM.WW.OtOpcUa.Host diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs new file mode 100644 index 00000000..a888b25f --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs @@ -0,0 +1,143 @@ +using Microsoft.Extensions.Configuration; +using Serilog; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Host.Logging; + +namespace ZB.MOM.WW.OtOpcUa.Host.Tests.Logging; + +/// +/// Gitea #561 — the startup log-pipeline self-check. The failure mode under test is "healthy +/// process, 0-byte log": Serilog isolates per-sink write failures, so nothing else in the +/// system can observe a file sink whose writes never reach disk. The load-bearing test here is +/// the failure case (): a check that +/// can only pass would be indistinguishable from no check at all — the same vacuity that let +/// the original defect run silent for six weeks. +/// +public sealed class LogPipelineDiagnosticsTests : IDisposable +{ + private readonly string _dir = Directory.CreateTempSubdirectory("otopcua-logcheck-").FullName; + + public void Dispose() + { + try { Directory.Delete(_dir, recursive: true); } catch { /* best effort */ } + } + + private static IConfiguration FileSinkConfig(string pathTemplate, bool? buffered = null) + { + var values = new Dictionary + { + ["Serilog:WriteTo:0:Name"] = "Console", + ["Serilog:WriteTo:1:Name"] = "File", + ["Serilog:WriteTo:1:Args:path"] = pathTemplate, + ["Serilog:WriteTo:1:Args:rollingInterval"] = "Day", + }; + if (buffered is not null) + values["Serilog:WriteTo:1:Args:buffered"] = buffered.Value ? "true" : "false"; + + return new ConfigurationBuilder().AddInMemoryCollection(values).Build(); + } + + [Fact] + public void A_working_file_sink_passes() + { + var template = Path.Combine(_dir, "t-.log"); + using var logger = new LoggerConfiguration() + .WriteTo.File(template, rollingInterval: RollingInterval.Day) + .CreateLogger(); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), () => logger.Information("marker")); + + warning.ShouldBeNull(); + } + + [Fact] + public void A_sink_that_writes_nothing_is_reported() + { + // The marker goes through a logger with NO file sink, so the configured template never + // grows — the on-disk shape of the wonder-app-vd03 incident (open handle, failed writes). + var template = Path.Combine(_dir, "t-.log"); + using var fileless = new LoggerConfiguration().CreateLogger(); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), () => fileless.Information("marker")); + + warning.ShouldNotBeNull(); + warning.ShouldContain(template); + warning.ShouldContain("did not grow"); + } + + [Fact] + public void A_preexisting_file_does_not_mask_a_silent_sink() + { + // A previous healthy run's bytes on disk must not satisfy the check: growth is measured + // across the marker, not existence. This is the exact false-pass an existence check + // would have given on wonder (the 0-byte file was created by the broken run itself, but a + // >0-byte survivor from an earlier build would fool existence just the same). + var template = Path.Combine(_dir, "t-.log"); + File.WriteAllText(Path.Combine(_dir, "t-20260811.log"), "bytes from a previous run"); + using var fileless = new LoggerConfiguration().CreateLogger(); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), () => fileless.Information("marker")); + + warning.ShouldNotBeNull(); + } + + [Fact] + public void The_rolled_and_sequenced_family_counts_as_the_template() + { + // The sink writes t-20260811.log (rolled) — the template t-.log itself never exists. + // Growth must be attributed to the template through the family glob, or every healthy + // rolling deployment would false-alarm. + var template = Path.Combine(_dir, "t-.log"); + using var logger = new LoggerConfiguration() + .WriteTo.File(template, rollingInterval: RollingInterval.Day) + .CreateLogger(); + logger.Information("creates the rolled file before the check runs"); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), () => logger.Information("marker")); + + warning.ShouldBeNull(); + File.Exists(template).ShouldBeFalse("the un-rolled template name must not exist — only the rolled form"); + } + + [Fact] + public void No_file_sink_configured_is_not_a_failure() + { + var config = new ConfigurationBuilder().AddInMemoryCollection( + new Dictionary { ["Serilog:WriteTo:0:Name"] = "Console" }).Build(); + var markerRan = false; + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth(config, () => markerRan = true); + + warning.ShouldBeNull(); + markerRan.ShouldBeFalse("with nothing checkable the marker event should not be emitted"); + } + + [Fact] + public void A_buffered_sink_is_skipped_not_reported() + { + // buffered:true legitimately defers bytes past the marker; growth proves nothing either + // way, so the check must skip rather than false-alarm. + var template = Path.Combine(_dir, "t-.log"); + using var fileless = new LoggerConfiguration().CreateLogger(); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template, buffered: true), () => fileless.Information("marker")); + + warning.ShouldBeNull(); + } + + [Fact] + public void A_file_entry_with_no_path_is_tolerated() + { + var config = new ConfigurationBuilder().AddInMemoryCollection( + new Dictionary { ["Serilog:WriteTo:0:Name"] = "File" }).Build(); + + Should.NotThrow(() => LogPipelineDiagnostics.CheckFileSinkGrowth( + config, () => { })).ShouldBeNull(); + } +}