fix(logging): #561 was a measurement artifact — measure sink growth through an open handle
v2-ci / build (push) Successful in 4m34s
v2-ci / unit-tests (push) Failing after 16m39s

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.
This commit is contained in:
Joseph Doherty
2026-08-12 02:09:23 -04:00
parent b037cc7ac4
commit c8b5c997b2
2 changed files with 93 additions and 15 deletions
@@ -7,12 +7,21 @@ using ZB.MOM.WW.OtOpcUa.Host.Logging;
namespace ZB.MOM.WW.OtOpcUa.Host.Tests.Logging;
/// <summary>
/// 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 <b>failure</b> case (<see cref="A_sink_that_writes_nothing_is_reported"/>): 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 <b>failure</b>
/// case (<see cref="A_sink_that_writes_nothing_is_reported"/>): a check that can only pass would
/// be indistinguishable from no check at all.
///
/// ⚠️ <b>These tests are platform-blind in one direction, and it mattered.</b> The check
/// originally measured growth with <c>FileInfo.Length</c>, 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.
/// <see cref="A_working_file_sink_passes"/> 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.
/// </summary>
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()
{