Files
lmxopcua/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/LogPipelineDiagnostics.cs
T
Joseph Doherty 826312befe docs: fill missing XML docs and strip tracking IDs from src comments
Clears CommentChecker findings in src/ (3,280 -> 209, the remainder being false
positives like PLC-5/IEEE-754/M0.0) by adding missing summaries/params/returns,
normalising inheritdoc usage, and removing Gitea/review tracking IDs while keeping
the rationale they annotated. Comment-only: comment-stripped sources are identical
to the parent commit.
2026-10-15 06:14:58 -04:00

193 lines
9.8 KiB
C#

using Serilog.Debugging;
namespace ZB.MOM.WW.OtOpcUa.Host.Logging;
/// <summary>
/// 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 <c>RollingFileSink</c> logs the
/// lock-out to SelfLog and quietly falls through to the next name in sequence.
///
/// ⚠️ It is NOT, however, what the reported 0-byte production log turned out to be. That investigation concluded from
/// <c>Get-ChildItem</c> that production's log was 0 bytes for six weeks; opening the file showed
/// 4.66 MB of correct output. See <see cref="MeasureFamilyBytes"/> 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:
/// <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>
/// <returns>A warning describing the silent sink, or <see langword="null"/> when the check passes.</returns>
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. 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
{
// 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>
/// <param name="warning">The warning text to write.</param>
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>
/// <remarks>
/// ⚠️ Length MUST be read through an opened stream, never from <see cref="FileInfo.Length"/>
/// (or <c>Get-ChildItem</c>/<c>dir</c>, 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 <c>LastWriteTime == CreationTime</c> — 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 that report look like a six-week production
/// logging outage when the file in fact held 4.66 MB of correct output.
///
/// <see cref="FileShare.ReadWrite"/> is required to open the file at all while the sink holds
/// its write handle; <see cref="FileShare.Delete"/> keeps this read from blocking a concurrent
/// roll or retention delete.
/// </remarks>
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
{
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;
}
}