diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs index dacf0f82..240c9209 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs @@ -3,10 +3,19 @@ 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: +/// Diagnostics for the "healthy process, silent log" failure mode: Serilog isolates per-sink +/// failures, so a file sink that cannot open or write its file leaves an empty log, a fully +/// functional server, and no visible signal anywhere. The failure is real — a sibling repo +/// reproduced it via handle contention on one path, where RollingFileSink logs the +/// lock-out to SelfLog and quietly falls through to the next name in sequence. +/// +/// ⚠️ It is NOT, however, what Gitea #561 turned out to be. That investigation concluded from +/// Get-ChildItem that production's log was 0 bytes for six weeks; opening the file showed +/// 4.66 MB of correct output. See for the Windows metadata +/// behaviour behind the false reading — the same trap this class must not fall into, since a +/// self-check's false positive reads as confirmation of the very bug it was added to find. +/// +/// Two instruments close the genuine failure mode: /// /// — turns on Serilog's , the only /// channel that sees the exceptions sinks swallow, writing to a dedicated file plus stderr. @@ -110,9 +119,10 @@ public static class LogPipelineDiagnostics : "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."; + + " The process will run but its log stays empty. Serilog swallows per-sink write" + + $" errors; the actual reason is in SelfLog ({SelfLogPath}) and on stderr — read it" + + " before acting, and confirm by OPENING the log file rather than by listing its" + + " size, which on Windows reports the size-at-open while the sink holds the file."; } catch { @@ -135,6 +145,21 @@ public static class LogPipelineDiagnostics /// (otopcua-20260811_001.log) forms, and — because * matches zero characters — /// the un-rolled name itself. /// + /// + /// ⚠️ Length MUST be read through an opened stream, never from + /// (or Get-ChildItem/dir, which read the same place). On Windows the directory + /// entry's size and last-write time are not refreshed while the writing process holds the file + /// open, so a perfectly healthy log that the sink is actively appending to reports its + /// size-at-open — typically 0, with LastWriteTime == CreationTime — for the entire life + /// of the handle. Measuring that way makes this check declare every healthy sink silent at + /// boot: instrumentation that manufactures the exact failure it exists to detect. It also + /// produced the false 0-byte reading that made Gitea #561 look like a six-week production + /// logging outage when the file in fact held 4.66 MB of correct output. + /// + /// is required to open the file at all while the sink holds + /// its write handle; keeps this read from blocking a concurrent + /// roll or retention delete. + /// private static long MeasureFamilyBytes(string pathTemplate) { var dir = Path.GetDirectoryName(pathTemplate); @@ -147,8 +172,17 @@ public static class LogPipelineDiagnostics long total = 0; foreach (var file in Directory.EnumerateFiles(dir, pattern)) { - try { total += new FileInfo(file).Length; } - catch (IOException) { /* rolled away mid-scan */ } + try + { + using var stream = new FileStream( + file, + FileMode.Open, + FileAccess.Read, + FileShare.ReadWrite | FileShare.Delete); + total += stream.Length; + } + catch (IOException) { /* rolled away mid-scan, or momentarily unshareable */ } + catch (UnauthorizedAccessException) { /* not ours to read — treat as unmeasurable */ } } return total; 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 index a888b25f..9a0a7c0e 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.Tests/Logging/LogPipelineDiagnosticsTests.cs @@ -7,12 +7,21 @@ 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. +/// The startup log-pipeline self-check. The failure mode under test is "healthy process, empty +/// 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. +/// +/// ⚠️ These tests are platform-blind in one direction, and it mattered. The check +/// originally measured growth with FileInfo.Length, which on Windows reports the +/// directory entry — frozen at size-at-open for as long as the sink holds the file. That made +/// the check report FAILED on every healthy Windows boot. +/// would have caught it: it measures while Serilog holds +/// the file open, which is precisely the broken case. It never did, because it only ever ran on +/// macOS, where the length is honest. So a green suite here does NOT establish that the check +/// behaves on the platform it ships to — the same blindness produced the false 0-byte reading +/// that made Gitea #561 look like a six-week production outage when the log held 4.66 MB. /// public sealed class LogPipelineDiagnosticsTests : IDisposable { @@ -131,6 +140,41 @@ public sealed class LogPipelineDiagnosticsTests : IDisposable warning.ShouldBeNull(); } + [Fact] + public void Growth_is_measured_while_a_writer_holds_the_file_open() + { + // The measurement must come from an opened stream, not the directory entry. A second writer + // holding the file the way Serilog does (FileAccess.Write / FileShare.Read) must neither + // block the read nor hide the bytes it has already flushed. + var template = Path.Combine(_dir, "t-.log"); + var rolled = Path.Combine(_dir, "t-20260811.log"); + using var held = new FileStream(rolled, FileMode.Create, FileAccess.Write, FileShare.Read); + held.Write("first"u8); + held.Flush(); + + var warning = LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), + () => { held.Write("grew"u8); held.Flush(); }); + + warning.ShouldBeNull("bytes written through a still-open handle must count as growth"); + } + + [Fact] + public void A_file_locked_against_readers_does_not_break_the_check() + { + // Opening to measure can fail where a metadata read would not (FileShare.None). That must + // degrade to "unmeasurable", never to an exception escaping into startup. + var template = Path.Combine(_dir, "t-.log"); + var rolled = Path.Combine(_dir, "t-20260811.log"); + using var exclusive = new FileStream(rolled, FileMode.Create, FileAccess.Write, FileShare.None); + exclusive.Write("locked"u8); + exclusive.Flush(); + using var fileless = new LoggerConfiguration().CreateLogger(); + + Should.NotThrow(() => LogPipelineDiagnostics.CheckFileSinkGrowth( + FileSinkConfig(template), () => fileless.Information("marker"))); + } + [Fact] public void A_file_entry_with_no_path_is_tolerated() {