dohertj2/lmxopcua
1
0
Fork 0
Code Issues 5 Pull Requests Actions Packages Projects Releases Wiki Activity

fix(opcua): #874 route the server's OPC UA SDK log output to the host logger

Browse Source 
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
This commit is contained in:
Joseph Doherty
2026-11-11 16:37:03 -05:00
parent 88698ca042
commit 2e948d3139
5 changed files with 160 additions and 9 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/OtOpcUaServerHostedService.cs
+13 -2
View File
@@ -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;
/// <summary>
/// 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 <see cref="DisposeAsync"/> after both are gone.
/// </summary>
private ITelemetryContext? _sdkTelemetry;
private OtOpcUaSdkServer? _server;
private AclRevalidationTimer? _revalidationTimer;
@@ -179,11 +186,13 @@ public sealed class OtOpcUaServerHostedService : IHostedService, IAsyncDisposabl
/// <returns>A task that represents the asynchronous operation.</returns>
public async Task StartAsync(CancellationToken cancellationToken)
{
_server = new OtOpcUaSdkServer(_loggerFactory.CreateLogger<OtOpcUaNodeManager>());
_sdkTelemetry ??= ServerSdkTelemetry.Create(_loggerFactory);
_server = new OtOpcUaSdkServer(_loggerFactory.CreateLogger<OtOpcUaNodeManager>(), _sdkTelemetry);
_appHost = new OpcUaApplicationHost(
_options,
_loggerFactory.CreateLogger<OpcUaApplicationHost>(),
_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;
}
}
src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OpcUaApplicationHost.cs
+6 -3
View File
@@ -179,7 +179,7 @@ public sealed class OpcUaApplicationHost : IAsyncDisposable
private readonly ILogger<OpcUaApplicationHost> _logger;
private ApplicationInstance? _application;
private StandardServer? _server;
private readonly ITelemetryContext _telemetry = DefaultTelemetry.Create(_ => { });
private readonly ITelemetryContext _telemetry;
private readonly List<IUserTokenAuthenticator> _identityAuthenticators = [];
private readonly FailedCredentialLockout _credentialLockout;
private readonly object _lifetimeLock = new();
@@ -190,11 +190,15 @@ public sealed class OpcUaApplicationHost : IAsyncDisposable
/// <param name="options">The host configuration options.</param>
/// <param name="logger">The logger for diagnostic output.</param>
/// <param name="userAuthenticator">An optional user authenticator for UserName tokens; uses null implementation if not provided.</param>
/// <param name="telemetry">The SDK telemetry context (<see cref="ServerSdkTelemetry.Create"/>, #874); <c>null</c>
/// discards the SDK's own log output. The caller owns and releases it.</param>
public OpcUaApplicationHost(
OpcUaApplicationHostOptions options,
ILogger<OpcUaApplicationHost> 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,
src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaSdkServer.cs
+4 -2
View File
@@ -24,8 +24,10 @@ public sealed class OtOpcUaSdkServer : StandardServer
/// <summary>Initializes a new instance of the <see cref="OtOpcUaSdkServer"/> class.</summary>
/// <param name="nodeManagerLogger">Logger handed to the created <see cref="OtOpcUaNodeManager"/>;
/// <c>null</c> leaves it on a no-op logger.</param>
public OtOpcUaSdkServer(ILogger<OtOpcUaNodeManager>? nodeManagerLogger = null)
: base(DefaultTelemetry.Create(_ => { })) => _nodeManagerLogger = nodeManagerLogger;
/// <param name="telemetry">The SDK telemetry context (<see cref="ServerSdkTelemetry.Create"/>, #874); <c>null</c>
/// discards the SDK's own log output.</param>
public OtOpcUaSdkServer(ILogger<OtOpcUaNodeManager>? nodeManagerLogger = null, ITelemetryContext? telemetry = null)
: base(telemetry ?? DefaultTelemetry.Create(_ => { })) => _nodeManagerLogger = nodeManagerLogger;
internal void ConfigureIdentityAuthenticators(IEnumerable<IUserTokenAuthenticator> authenticators) =>
AddPreStartupTask(new IdentityStartupTask(authenticators.ToArray()));
src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/ServerSdkTelemetry.cs
+92
View File
@@ -0,0 +1,92 @@
using Microsoft.Extensions.Logging;
using Opc.Ua;
namespace ZB.MOM.WW.OtOpcUa.OpcUaServer;
/// <summary>
/// The <see cref="ITelemetryContext"/> 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
/// <c>RsaEncryptedSecret</c> signing-time window, #873), certificate validation, secure-channel faults — left
/// no server log line at all (#874). <see cref="Create"/> forwards the SDK's Warning-and-above output to the
/// host's <see cref="ILoggerFactory"/> under the SDK's own categories, rate-limited per category because an
/// unauthenticated client retrying in a loop would otherwise flood the log.
/// </summary>
public static class ServerSdkTelemetry
{
/// <summary>SDK log entries forwarded per category per <see cref="Window"/> before the rest are dropped and counted.</summary>
internal const int MaxEntriesPerWindow = 20;
/// <summary>The rate-limit window.</summary>
internal static readonly TimeSpan Window = TimeSpan.FromMinutes(1);
/// <summary>Creates a context whose SDK Warning-and-above output goes to <paramref name="loggerFactory"/>.</summary>
/// <param name="loggerFactory">The host's logger factory.</param>
/// <returns>The telemetry context; release it with <see cref="Release"/>.</returns>
public static ITelemetryContext Create(ILoggerFactory loggerFactory)
{
ArgumentNullException.ThrowIfNull(loggerFactory);
return DefaultTelemetry.Create(builder => builder
.SetMinimumLevel(LogLevel.Warning)
.AddProvider(new ForwardingProvider(loggerFactory)));
}
/// <summary>Disposes the logger factory a <see cref="Create"/> context owns (not the host's factory).</summary>
/// <param name="context">The context to release.</param>
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() { }
}
/// <summary>Forwards at most <c>max</c> entries per window; the next window's first entry notes how many were dropped.</summary>
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>(TState state) where TState : notnull => target.BeginScope(state);
public bool IsEnabled(LogLevel logLevel) => target.IsEnabled(logLevel);
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> 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);
}
}
}
tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/Sdk2TrustedChannelTests.cs
+45 -2
View File
@@ -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);
}
/// <summary>
/// #874: SDK-side refusals used to leave no server log line (the host gave the SDK a provider-less telemetry
/// context). With <see cref="ServerSdkTelemetry"/> wired, rejecting an untrusted client is logged at Warning+.
/// </summary>
[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<ServiceResultException>(() => 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>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter) =>
sink.Enqueue((logLevel, category, formatter(state, exception) + (exception is null ? "" : " | " + exception.Message)));
}
}
internal static async Task<TrustedRig> 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<OpcUaApplicationHost>.Instance, this);
}, () => new OtOpcUaSdkServer(), ct);
return new OpcUaApplicationHost(_options, NullLogger<OpcUaApplicationHost>.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);
}
}