c8b5c997b2
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.
188 lines
8.2 KiB
C#
188 lines
8.2 KiB
C#
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;
|
|
|
|
/// <summary>
|
|
/// 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
|
|
{
|
|
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<string, string?>
|
|
{
|
|
["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<string, string?> { ["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 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()
|
|
{
|
|
var config = new ConfigurationBuilder().AddInMemoryCollection(
|
|
new Dictionary<string, string?> { ["Serilog:WriteTo:0:Name"] = "File" }).Build();
|
|
|
|
Should.NotThrow(() => LogPipelineDiagnostics.CheckFileSinkGrowth(
|
|
config, () => { })).ShouldBeNull();
|
|
}
|
|
}
|