From f1240c0bd469966d1c398320c174da1a4d8e4fd2 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 1 Jun 2026 07:48:57 -0400 Subject: [PATCH] refactor(telemetry.serilog): review fixes (thread-safe redactor, bootstrap logger, minlevel ordering, test coverage) --- .../RedactionEnricher.cs | 24 +++---- .../ZB.MOM.WW.Telemetry.Serilog.csproj | 6 ++ .../ZbSerilogConfig.cs | 9 ++- .../ZbSerilogExtensions.cs | 65 +++++++++++-------- .../EnricherTests.cs | 29 +++++++++ .../RedactionTests.cs | 46 +++++++++++++ .../TraceContextEnricherTests.cs | 9 ++- 7 files changed, 140 insertions(+), 48 deletions(-) diff --git a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/RedactionEnricher.cs b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/RedactionEnricher.cs index 86f6e91..79b873d 100644 --- a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/RedactionEnricher.cs +++ b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/RedactionEnricher.cs @@ -9,22 +9,24 @@ namespace ZB.MOM.WW.Telemetry.Serilog; /// automatically by . The enricher resolves /// from DI on first use (lazy, to avoid a circular-DI problem during /// Serilog's bootstrap); if none is registered it is permanently inert — no DI call per event. +/// Resolution is thread-safe: ensures +/// exactly one DI lookup regardless of how many logging threads race to the first event. /// public sealed class RedactionEnricher : ILogEventEnricher { - private readonly IServiceProvider _serviceProvider; - private ILogRedactor? _redactor; - private bool _resolved; + private readonly Lazy _redactor; /// /// Creates the enricher bound to a service provider from which the project-supplied - /// is resolved lazily on first use. + /// is resolved lazily on first use (thread-safe). /// /// Provider used to resolve a registered . public RedactionEnricher(IServiceProvider serviceProvider) { ArgumentNullException.ThrowIfNull(serviceProvider); - _serviceProvider = serviceProvider; + _redactor = new Lazy( + () => serviceProvider.GetService(), + LazyThreadSafetyMode.ExecutionAndPublication); } /// @@ -64,17 +66,7 @@ public sealed class RedactionEnricher : ILogEventEnricher } } - private ILogRedactor? ResolveRedactor() - { - if (_resolved) - { - return _redactor; - } - - _redactor = _serviceProvider.GetService(); - _resolved = true; - return _redactor; - } + private ILogRedactor? ResolveRedactor() => _redactor.Value; private static bool HasChanged(LogEvent logEvent, string key, object? newValue) { diff --git a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZB.MOM.WW.Telemetry.Serilog.csproj b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZB.MOM.WW.Telemetry.Serilog.csproj index 730ebed..4cd6d60 100644 --- a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZB.MOM.WW.Telemetry.Serilog.csproj +++ b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZB.MOM.WW.Telemetry.Serilog.csproj @@ -24,4 +24,10 @@ + + + <_Parameter1>ZB.MOM.WW.Telemetry.Serilog.Tests + + + diff --git a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogConfig.cs b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogConfig.cs index b77a975..10b994e 100644 --- a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogConfig.cs +++ b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogConfig.cs @@ -12,8 +12,10 @@ namespace ZB.MOM.WW.Telemetry.Serilog; /// trace-context correlation, redaction, and OTel log export) to a /// . Shared by /// and unit tests so both exercise an identical enricher/sink set. +/// Internal to keep the public NuGet surface minimal; exposed to the test assembly via +/// [assembly: InternalsVisibleTo("ZB.MOM.WW.Telemetry.Serilog.Tests")]. /// -public static class ZbSerilogConfig +internal static class ZbSerilogConfig { /// /// Applies the shared identity enrichers — and @@ -113,9 +115,10 @@ public static class ZbSerilogConfig /// /// Builds the OTLP Resource-attribute map mirroring ZbResource. Null/empty optional - /// attributes are omitted, matching the shared Resource's omission rules. + /// attributes are omitted, matching the shared Resource's omission rules. Internal so it can + /// be asserted by the test assembly without being part of the public NuGet API. /// - private static IDictionary BuildResourceAttributes(ZbTelemetryOptions options) + internal static IDictionary BuildResourceAttributes(ZbTelemetryOptions options) { var attributes = new Dictionary { diff --git a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogExtensions.cs b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogExtensions.cs index b22d107..11b850a 100644 --- a/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogExtensions.cs +++ b/ZB.MOM.WW.Telemetry/src/ZB.MOM.WW.Telemetry.Serilog/ZbSerilogExtensions.cs @@ -1,5 +1,3 @@ -using Microsoft.Extensions.Configuration; -using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Serilog; using Serilog.Events; @@ -8,22 +6,46 @@ using ZB.MOM.WW.Telemetry; namespace ZB.MOM.WW.Telemetry.Serilog; /// -/// Extension point for configuring the shared Serilog bootstrap on an +/// Extension point for configuring the shared Serilog two-stage bootstrap on an /// . Wires config-driven sinks /// (ReadFrom.Configuration), an explicit minimum level (Serilog:MinimumLevel, /// default ), and the shared enricher/redaction/OTel-export /// set via . Does NOT configure OTel metrics/traces — call /// AddZbTelemetry in the core package for that. +/// +/// +/// Stage 1 (bootstrap): sets to a console-only logger before +/// Build() is called, capturing any startup exceptions that occur before the DI +/// container is ready. +/// +/// +/// Stage 2 (application): wires the full Serilog pipeline via +/// +/// once the host builds, replacing the bootstrap logger with the configuration-driven one. +/// /// public static class ZbSerilogExtensions { /// - /// Registers Serilog on the host with the shared ZB.MOM.WW configuration: sinks read from - /// (ReadFrom.Configuration), an explicit minimum level - /// (Serilog:MinimumLevel, default ), and the - /// identity enrichers (SiteId/NodeRole from , - /// NodeHostname = ). The - /// delegate receives the same + /// Registers Serilog on the host with a two-stage bootstrap: + /// + /// + /// + /// Stage 1 — immediately sets to a console-only bootstrap logger + /// so that startup exceptions before Build() are captured. + /// + /// + /// + /// + /// Stage 2 — registers the full pipeline via AddSerilog: configuration-driven sinks + /// (ReadFrom.Configuration), a code default of + /// that config can override via Serilog:MinimumLevel or namespace overrides, plus + /// the identity enrichers (SiteId/NodeRole from , + /// NodeHostname = ). + /// + /// + /// + /// The delegate receives the same /// used by AddZbTelemetry — typically share one options-population lambda across both. /// /// The host application builder. @@ -38,32 +60,21 @@ public static class ZbSerilogExtensions var options = new ZbTelemetryOptions(); configure(options); - var minimumLevel = ReadMinimumLevel(builder.Configuration); + // Stage 1: bootstrap logger captures startup exceptions before Build(). + Log.Logger = new LoggerConfiguration() + .WriteTo.Console() + .CreateBootstrapLogger(); + // Stage 2: full application logger — code default first, then config overrides. builder.Services.AddSerilog((serviceProvider, loggerConfiguration) => { loggerConfiguration - .ReadFrom.Configuration(builder.Configuration) - .MinimumLevel.Is(minimumLevel); + .MinimumLevel.Is(LogEventLevel.Information) + .ReadFrom.Configuration(builder.Configuration); ZbSerilogConfig.Apply(loggerConfiguration, options, serviceProvider); }); return builder; } - - /// - /// Reads Serilog:MinimumLevel (or the nested Serilog:MinimumLevel:Default) from - /// configuration, falling back to for missing or - /// unparseable values. - /// - private static LogEventLevel ReadMinimumLevel(IConfiguration configuration) - { - var raw = configuration["Serilog:MinimumLevel"] - ?? configuration["Serilog:MinimumLevel:Default"]; - - return Enum.TryParse(raw, ignoreCase: true, out var parsed) - ? parsed - : LogEventLevel.Information; - } } diff --git a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/EnricherTests.cs b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/EnricherTests.cs index 2fc138f..776eccb 100644 --- a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/EnricherTests.cs +++ b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/EnricherTests.cs @@ -43,4 +43,33 @@ public sealed class EnricherTests Environment.MachineName, ScalarValue(logEvent, ZbLogEnricherNames.NodeHostname)); } + + [Fact] + public void Null_SiteId_and_NodeRole_are_suppressed_but_NodeHostname_is_always_present() + { + var sink = new InMemorySink(); + var options = new ZbTelemetryOptions + { + ServiceName = "otopcua", + SiteId = null, + NodeRole = null, + }; + + var loggerConfig = new LoggerConfiguration(); + ZbSerilogConfig.Apply(loggerConfig, options); + using var logger = loggerConfig + .WriteTo.Sink(sink) + .CreateLogger(); + + logger.Information("hello"); + + var logEvent = Assert.Single(sink.LogEvents); + Assert.False(logEvent.Properties.ContainsKey(ZbLogEnricherNames.SiteId), + "SiteId should be absent when null"); + Assert.False(logEvent.Properties.ContainsKey(ZbLogEnricherNames.NodeRole), + "NodeRole should be absent when null"); + Assert.Equal( + Environment.MachineName, + ScalarValue(logEvent, ZbLogEnricherNames.NodeHostname)); + } } diff --git a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/RedactionTests.cs b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/RedactionTests.cs index 045d1f9..932fb35 100644 --- a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/RedactionTests.cs +++ b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/RedactionTests.cs @@ -84,7 +84,53 @@ public sealed class RedactionTests using var host = builder.Build(); + // Serilog.ILogger is registered by AddSerilog — not Microsoft.Extensions.Logging.ILogger. var logger = host.Services.GetRequiredService(); logger.Information("otlp wiring smoke test"); } + + [Fact] + public void BuildResourceAttributes_contains_required_keys_and_optional_keys_when_set() + { + var options = new ZbTelemetryOptions + { + ServiceName = "mxgateway", + ServiceNamespace = "ZB.MOM.WW", + SiteId = "site-a", + NodeRole = "central", + }; + + var attributes = ZbSerilogConfig.BuildResourceAttributes(options); + + // Required keys always present. + Assert.True(attributes.ContainsKey("service.name"), "service.name must be present"); + Assert.True(attributes.ContainsKey("service.namespace"), "service.namespace must be present"); + Assert.True(attributes.ContainsKey("host.name"), "host.name must be present"); + + // Optional keys present when options supply them. + Assert.True(attributes.ContainsKey("site.id"), "site.id must be present when SiteId is set"); + Assert.True(attributes.ContainsKey("node.role"), "node.role must be present when NodeRole is set"); + + Assert.Equal("mxgateway", attributes["service.name"]); + Assert.Equal("ZB.MOM.WW", attributes["service.namespace"]); + Assert.Equal(Environment.MachineName, attributes["host.name"]); + Assert.Equal("site-a", attributes["site.id"]); + Assert.Equal("central", attributes["node.role"]); + } + + [Fact] + public void BuildResourceAttributes_omits_optional_keys_when_not_set() + { + var options = new ZbTelemetryOptions + { + ServiceName = "mxgateway", + SiteId = null, + NodeRole = null, + }; + + var attributes = ZbSerilogConfig.BuildResourceAttributes(options); + + Assert.False(attributes.ContainsKey("site.id"), "site.id must be absent when SiteId is null"); + Assert.False(attributes.ContainsKey("node.role"), "node.role must be absent when NodeRole is null"); + } } diff --git a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/TraceContextEnricherTests.cs b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/TraceContextEnricherTests.cs index e6d88c5..b1ef6c2 100644 --- a/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/TraceContextEnricherTests.cs +++ b/ZB.MOM.WW.Telemetry/tests/ZB.MOM.WW.Telemetry.Serilog.Tests/TraceContextEnricherTests.cs @@ -42,11 +42,16 @@ public sealed class TraceContextEnricherTests Assert.NotNull(activity); Assert.NotNull(Activity.Current); + // Capture IDs before the log call so assertions are not sensitive to activity + // lifecycle — Activity.Current may differ after the log call returns. + var expectedTraceId = activity.TraceId.ToString(); + var expectedSpanId = activity.SpanId.ToString(); + logger.Information("traced"); var logEvent = Assert.Single(sink.LogEvents); - Assert.Equal(Activity.Current!.TraceId.ToString(), ScalarOrNull(logEvent, "trace_id")); - Assert.Equal(Activity.Current!.SpanId.ToString(), ScalarOrNull(logEvent, "span_id")); + Assert.Equal(expectedTraceId, ScalarOrNull(logEvent, "trace_id")); + Assert.Equal(expectedSpanId, ScalarOrNull(logEvent, "span_id")); } [Fact]