From c8b5c997b21cc1526d917d1a9c1806a775c54dfe Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 12 Aug 2026 02:09:23 -0400 Subject: [PATCH] =?UTF-8?q?fix(logging):=20#561=20was=20a=20measurement=20?= =?UTF-8?q?artifact=20=E2=80=94=20measure=20sink=20growth=20through=20an?= =?UTF-8?q?=20open=20handle?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Gitea #561 ("production writes a 0-byte log") is closed as not-a-defect. The production log on wonder-app-vd03 listed as 0 bytes with LastWriteTime == CreationTime; opening it showed 4,658,893 bytes of correct output, written continuously since service start. On Windows the directory entry's size and last-write time are not refreshed while the writing process holds the file open, so Get-ChildItem, dir and FileInfo.Length all report size-at-open for the life of the handle. A live, healthy log is indistinguishable from a dead sink by metadata alone — which is what made the false reading survive six weeks of investigation. That same trap was in the 29a202f5 instrumentation: CheckFileSinkGrowth measured with FileInfo.Length, so it would have reported "self-check FAILED: the sink did not grow" at every boot on a perfectly healthy Windows service — and a self-check's false positive reads as confirmation of the very bug it was added to find. MeasureFamilyBytes now reads Length through an opened FileStream: FileShare.ReadWrite to open it at all while the sink holds its write handle, and FileShare.Delete so the probe never blocks a roll or retention delete. Both instruments are kept. A sink that cannot write its file is still a real and otherwise-invisible failure — a sibling repo reproduced it via handle contention, where RollingFileSink logs the lock-out to SelfLog and falls through to _001. Only the two doc claims that are now false are corrected: the class summary's "production ran that way for six weeks" and the warning text's "#561 failure mode". Tests: A_working_file_sink_passes already measured while Serilog held the file open — precisely the broken case — and passed throughout, because it only ever ran on macOS, where the length is honest. That platform blindness is now recorded in the class summary, alongside two tests pinning the sharing contract the fix depends on. --- .../Logging/LogPipelineDiagnostics.cs | 52 ++++++++++++++--- .../Logging/LogPipelineDiagnosticsTests.cs | 56 +++++++++++++++++-- 2 files changed, 93 insertions(+), 15 deletions(-) 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() {