From 2e948d3139250b3cb17cbb70528917eff888ee26 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 16:37:03 -0500 Subject: [PATCH] fix(opcua): #874 route the server's OPC UA SDK log output to the host logger MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The host handed the SDK a provider-less telemetry context, so SDK-side refusals — identity-token decryption (the SDK 2 RsaEncryptedSecret clock window, #873), certificate validation, secure-channel faults — left no server log line (found on windev during the #800 Windows validation). The hosted service now creates one ServerSdkTelemetry context from its ILoggerFactory (Warning and above, SDK categories, rate-limited 20/min per category) and shares it between OtOpcUaSdkServer and the ApplicationInstance; released on dispose. Test: an untrusted client's rejection reaches the captured log. Claude-Session: https://claude.ai/code/session_01GT67AD99zQQqpLCVm3p7xk --- .../OpcUa/OtOpcUaServerHostedService.cs | 15 ++- .../OpcUaApplicationHost.cs | 9 +- .../OtOpcUaSdkServer.cs | 6 +- .../ServerSdkTelemetry.cs | 92 +++++++++++++++++++ .../Sdk2TrustedChannelTests.cs | 47 +++++++++- 5 files changed, 160 insertions(+), 9 deletions(-) create mode 100644 src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/ServerSdkTelemetry.cs diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/OtOpcUaServerHostedService.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/OtOpcUaServerHostedService.cs index 5fefe1fa3..79590528b 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/OtOpcUaServerHostedService.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/OtOpcUaServerHostedService.cs @@ -1,3 +1,4 @@ +using Opc.Ua; using Akka.Actor; using Akka.Cluster.Tools.PublishSubscribe; using Akka.Hosting; @@ -55,6 +56,12 @@ public sealed class OtOpcUaServerHostedService : IHostedService, IAsyncDisposabl private readonly DriverWriteBounds _writeBounds; private OpcUaApplicationHost? _appHost; + + /// + /// The SDK's telemetry context: its Warning-and-above output reaches this host's logs (#874). Shared by the + /// server and the application instance, released in after both are gone. + /// + private ITelemetryContext? _sdkTelemetry; private OtOpcUaSdkServer? _server; private AclRevalidationTimer? _revalidationTimer; @@ -179,11 +186,13 @@ public sealed class OtOpcUaServerHostedService : IHostedService, IAsyncDisposabl /// A task that represents the asynchronous operation. public async Task StartAsync(CancellationToken cancellationToken) { - _server = new OtOpcUaSdkServer(_loggerFactory.CreateLogger()); + _sdkTelemetry ??= ServerSdkTelemetry.Create(_loggerFactory); + _server = new OtOpcUaSdkServer(_loggerFactory.CreateLogger(), _sdkTelemetry); _appHost = new OpcUaApplicationHost( _options, _loggerFactory.CreateLogger(), - _userAuthenticator); + _userAuthenticator, + _sdkTelemetry); try { @@ -594,5 +603,7 @@ public sealed class OtOpcUaServerHostedService : IHostedService, IAsyncDisposabl _appHost = null; _server = null; if (appHost is not null) await appHost.DisposeAsync(); + ServerSdkTelemetry.Release(_sdkTelemetry); + _sdkTelemetry = null; } } diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OpcUaApplicationHost.cs b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OpcUaApplicationHost.cs index 5d55c433b..c51761423 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OpcUaApplicationHost.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OpcUaApplicationHost.cs @@ -179,7 +179,7 @@ public sealed class OpcUaApplicationHost : IAsyncDisposable private readonly ILogger _logger; private ApplicationInstance? _application; private StandardServer? _server; - private readonly ITelemetryContext _telemetry = DefaultTelemetry.Create(_ => { }); + private readonly ITelemetryContext _telemetry; private readonly List _identityAuthenticators = []; private readonly FailedCredentialLockout _credentialLockout; private readonly object _lifetimeLock = new(); @@ -190,11 +190,15 @@ public sealed class OpcUaApplicationHost : IAsyncDisposable /// The host configuration options. /// The logger for diagnostic output. /// An optional user authenticator for UserName tokens; uses null implementation if not provided. + /// The SDK telemetry context (, #874); null + /// discards the SDK's own log output. The caller owns and releases it. public OpcUaApplicationHost( OpcUaApplicationHostOptions options, ILogger logger, - IOpcUaUserAuthenticator? userAuthenticator = null) + IOpcUaUserAuthenticator? userAuthenticator = null, + ITelemetryContext? telemetry = null) { + _telemetry = telemetry ?? DefaultTelemetry.Create(_ => { }); _options = options; _logger = logger; _userAuthenticator = userAuthenticator ?? NullOpcUaUserAuthenticator.Instance; @@ -220,7 +224,6 @@ public sealed class OpcUaApplicationHost : IAsyncDisposable sdkServer = server as OtOpcUaSdkServer ?? throw new ArgumentException("The server must support application authentication before its listeners open.", nameof(server)); _server = server; - // The empty telemetry builder keeps SDK tracing separate from the host's ILogger. _application = new ApplicationInstance(_telemetry) { ApplicationName = _options.ApplicationName, diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaSdkServer.cs b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaSdkServer.cs index 82c1c3d83..7db6cbfdd 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaSdkServer.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaSdkServer.cs @@ -24,8 +24,10 @@ public sealed class OtOpcUaSdkServer : StandardServer /// Initializes a new instance of the class. /// Logger handed to the created ; /// null leaves it on a no-op logger. - public OtOpcUaSdkServer(ILogger? nodeManagerLogger = null) - : base(DefaultTelemetry.Create(_ => { })) => _nodeManagerLogger = nodeManagerLogger; + /// The SDK telemetry context (, #874); null + /// discards the SDK's own log output. + public OtOpcUaSdkServer(ILogger? nodeManagerLogger = null, ITelemetryContext? telemetry = null) + : base(telemetry ?? DefaultTelemetry.Create(_ => { })) => _nodeManagerLogger = nodeManagerLogger; internal void ConfigureIdentityAuthenticators(IEnumerable authenticators) => AddPreStartupTask(new IdentityStartupTask(authenticators.ToArray())); diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/ServerSdkTelemetry.cs b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/ServerSdkTelemetry.cs new file mode 100644 index 000000000..101798230 --- /dev/null +++ b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/ServerSdkTelemetry.cs @@ -0,0 +1,92 @@ +using Microsoft.Extensions.Logging; +using Opc.Ua; + +namespace ZB.MOM.WW.OtOpcUa.OpcUaServer; + +/// +/// The the server hands the OPC Foundation SDK. The host used to pass a +/// provider-less context, so every SDK-side refusal — identity-token decryption (e.g. the SDK 2 +/// RsaEncryptedSecret signing-time window, #873), certificate validation, secure-channel faults — left +/// no server log line at all (#874). forwards the SDK's Warning-and-above output to the +/// host's under the SDK's own categories, rate-limited per category because an +/// unauthenticated client retrying in a loop would otherwise flood the log. +/// +public static class ServerSdkTelemetry +{ + /// SDK log entries forwarded per category per before the rest are dropped and counted. + internal const int MaxEntriesPerWindow = 20; + + /// The rate-limit window. + internal static readonly TimeSpan Window = TimeSpan.FromMinutes(1); + + /// Creates a context whose SDK Warning-and-above output goes to . + /// The host's logger factory. + /// The telemetry context; release it with . + public static ITelemetryContext Create(ILoggerFactory loggerFactory) + { + ArgumentNullException.ThrowIfNull(loggerFactory); + return DefaultTelemetry.Create(builder => builder + .SetMinimumLevel(LogLevel.Warning) + .AddProvider(new ForwardingProvider(loggerFactory))); + } + + /// Disposes the logger factory a context owns (not the host's factory). + /// The context to release. + public static void Release(ITelemetryContext? context) + { + try { (context as TelemetryContextBase)?.LoggerFactory?.Dispose(); } + catch { /* best-effort */ } + } + + private sealed class ForwardingProvider(ILoggerFactory target) : ILoggerProvider + { + public ILogger CreateLogger(string categoryName) => + new RateLimitedLogger(target.CreateLogger(categoryName), MaxEntriesPerWindow, Window); + + // The host owns the target factory; disposing the SDK's factory must not dispose it. + public void Dispose() { } + } + + /// Forwards at most max entries per window; the next window's first entry notes how many were dropped. + internal sealed class RateLimitedLogger(ILogger target, int max, TimeSpan window) : ILogger + { + private readonly object _lock = new(); + private DateTime _windowStart = DateTime.MinValue; + private int _count; + private int _suppressed; + + public IDisposable? BeginScope(TState state) where TState : notnull => target.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) => target.IsEnabled(logLevel); + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + int suppressedNote; + lock (_lock) + { + var now = DateTime.UtcNow; + if (now - _windowStart >= window) + { + suppressedNote = _suppressed; + _windowStart = now; + _count = 0; + _suppressed = 0; + } + else suppressedNote = 0; + + if (_count >= max) + { + _suppressed++; + return; + } + _count++; + } + + if (suppressedNote > 0) + target.LogWarning("OPC UA SDK: {Suppressed} further log entries were suppressed in the last {Window}.", + suppressedNote, window); + target.Log(logLevel, eventId, state, exception, formatter); + } + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/Sdk2TrustedChannelTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/Sdk2TrustedChannelTests.cs index e3851669c..47ed176eb 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/Sdk2TrustedChannelTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/Sdk2TrustedChannelTests.cs @@ -1,6 +1,7 @@ using System.Text; using System.Net; using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Opc.Ua; using Opc.Ua.Client; @@ -116,6 +117,26 @@ public sealed class Sdk2TrustedChannelTests rig.Writes.ShouldBe(0); } + /// + /// #874: SDK-side refusals used to leave no server log line (the host gave the SDK a provider-less telemetry + /// context). With wired, rejecting an untrusted client is logged at Warning+. + /// + [Fact] + public async Task An_sdk_side_refusal_reaches_the_server_log() + { + var ct = TestContext.Current.CancellationToken; + await using var rig = await TrustedRig.StartAsync(OpcUaSecurityProfile.Basic256Sha256SignAndEncrypt, ct); + rig.SdkLog.Clear(); + await Should.ThrowAsync(() => rig.ConnectAsync("contract-key", ct, untrustedClient: true)); + + var deadline = DateTime.UtcNow.AddSeconds(5); + while (rig.SdkLog.IsEmpty && DateTime.UtcNow < deadline) await Task.Delay(50, ct); + var entries = rig.SdkLog.ToArray(); + entries.ShouldNotBeEmpty("the SDK's refusal must reach the host's logger"); + entries.ShouldAllBe(e => e.Level >= LogLevel.Warning); + TestContext.Current.SendDiagnosticMessage(string.Join("\n", entries.Select(e => $"{e.Level} {e.Category}: {e.Text}"))); + } + private sealed class TrustedRig : IAsyncDisposable, IOpcUaUserAuthenticator, IOpcUaNodeWriteGateway { internal const string Principal = "trusted-contract"; @@ -137,6 +158,9 @@ public sealed class Sdk2TrustedChannelTests private readonly TaskCompletionSource _peerBarrier = new(TaskCreationOptions.RunContinuationsAsynchronously); private int _peerBarrierArrivals; internal OtOpcUaSdkServer Server { get; private set; } = null!; + internal ConcurrentQueue<(LogLevel Level, string Category, string Text)> SdkLog { get; } = new(); + private readonly ILoggerFactory _sdkLoggerFactory; + private readonly ITelemetryContext _sdkTelemetry; internal int Writes => Volatile.Read(ref _writes); internal int AuthCalls => Volatile.Read(ref _authCalls); private string ServerPki => System.IO.Path.Combine(_root, "server"); @@ -150,6 +174,23 @@ public sealed class Sdk2TrustedChannelTests PublicHostname = "localhost", PkiStoreRoot = ServerPki, AllowAnonymous = false, AutoAcceptUntrustedClientCertificates = false, EnabledSecurityProfiles = [profile], }; + _sdkLoggerFactory = LoggerFactory.Create(b => b.SetMinimumLevel(LogLevel.Trace).AddProvider(new CaptureProvider(SdkLog))); + _sdkTelemetry = ServerSdkTelemetry.Create(_sdkLoggerFactory); + } + + private sealed class CaptureProvider(ConcurrentQueue<(LogLevel, string, string)> sink) : ILoggerProvider + { + public ILogger CreateLogger(string categoryName) => new Capture(sink, categoryName); + public void Dispose() { } + + private sealed class Capture(ConcurrentQueue<(LogLevel, string, string)> sink, string category) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) => + sink.Enqueue((logLevel, category, formatter(state, exception) + (exception is null ? "" : " | " + exception.Message))); + } } internal static async Task StartAsync(OpcUaSecurityProfile profile, CancellationToken ct) @@ -186,8 +227,8 @@ public sealed class Sdk2TrustedChannelTests (_host, Server) = await OpcUaHostStart.StartAsync(port => { _port = port; _options.OpcUaPort = port; - return new OpcUaApplicationHost(_options, NullLogger.Instance, this); - }, () => new OtOpcUaSdkServer(), ct); + return new OpcUaApplicationHost(_options, NullLogger.Instance, this, _sdkTelemetry); + }, () => new OtOpcUaSdkServer(telemetry: _sdkTelemetry), ct); } private static void CopyCertificates(string from, string to) @@ -286,6 +327,8 @@ public sealed class Sdk2TrustedChannelTests if (_host is not null) await _host.DisposeAsync(); foreach (var app in _applications.Values) await app.DisposeAsync(); _applications.Clear(); + ServerSdkTelemetry.Release(_sdkTelemetry); + _sdkLoggerFactory.Dispose(); if (Directory.Exists(_root)) Directory.Delete(_root, true); } }