fix(logging): #561 — SelfLog to file+stderr and a startup file-sink growth self-check
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.
This commit is contained in:
@@ -0,0 +1,156 @@
|
||||
using Serilog.Debugging;
|
||||
|
||||
namespace ZB.MOM.WW.OtOpcUa.Host.Logging;
|
||||
|
||||
/// <summary>
|
||||
/// 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:
|
||||
/// <list type="bullet">
|
||||
/// <item><see cref="EnableSelfLog"/> — turns on Serilog's <see cref="SelfLog"/>, the only
|
||||
/// channel that sees the exceptions sinks swallow, writing to a dedicated file plus stderr.</item>
|
||||
/// <item><see cref="CheckFileSinkGrowth"/> — 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.</item>
|
||||
/// </list>
|
||||
/// </summary>
|
||||
public static class LogPipelineDiagnostics
|
||||
{
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// </summary>
|
||||
internal const string SelfLogPath = "logs/serilog-selflog.txt";
|
||||
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// </summary>
|
||||
private const long SelfLogRotateBytes = 5 * 1024 * 1024;
|
||||
|
||||
/// <summary>
|
||||
/// Enables Serilog SelfLog to <see cref="SelfLogPath"/> 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.
|
||||
/// </summary>
|
||||
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 */ }
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Verifies every config-driven Serilog file sink physically grew when <paramref name="emitMarker"/>
|
||||
/// 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 (<c>logs/otopcua-.log</c> → <c>otopcua-*.log</c>, which also covers the
|
||||
/// <c>_NNN</c> 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".
|
||||
/// </summary>
|
||||
/// <param name="configuration">The host configuration carrying <c>Serilog:WriteTo</c>.</param>
|
||||
/// <param name="emitMarker">Emits one event through the live pipeline (synchronous sinks flush before returning).</param>
|
||||
public static string? CheckFileSinkGrowth(IConfiguration configuration, Action emitMarker)
|
||||
{
|
||||
try
|
||||
{
|
||||
var templates = new List<string>();
|
||||
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;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// 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.
|
||||
/// </summary>
|
||||
public static void ReportFailure(string warning) => SelfLog.WriteLine("{0}", warning);
|
||||
|
||||
/// <summary>
|
||||
/// Total bytes across the template's file family. The family glob is prefix + "*" + extension
|
||||
/// so <c>otopcua-.log</c> matches its own rolled (<c>otopcua-20260811.log</c>) and sequence
|
||||
/// (<c>otopcua-20260811_001.log</c>) forms, and — because <c>*</c> matches zero characters —
|
||||
/// the un-rolled name itself.
|
||||
/// </summary>
|
||||
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;
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user