feat(scripting): root script logger + DPS publisher wired in Host

This commit is contained in:
Joseph Doherty
2026-06-10 11:50:50 -04:00
parent 14fe88fc80
commit 73014258ef
8 changed files with 326 additions and 0 deletions
@@ -0,0 +1,25 @@
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
/// <summary>
/// DI-friendly holder for the root script <see cref="Serilog.ILogger"/> so it can be
/// injected into the Roslyn evaluators without clashing with the application's main
/// <c>Serilog.Log.Logger</c> (both are <see cref="Serilog.ILogger"/>; a wrapper type
/// gives the container an unambiguous registration to resolve).
/// </summary>
/// <remarks>
/// The wrapped logger is the composed script pipeline — a rolling <c>scripts-*.log</c>
/// file sink, the <see cref="ScriptLogCompanionSink"/> mirroring errors to the main log,
/// and the <see cref="ScriptLogTopicSink"/> fanning entries onto the cluster
/// <c>script-logs</c> topic for the live Script-log Admin UI page.
/// </remarks>
public sealed class ScriptRootLogger
{
/// <summary>Gets the composed root script logger that evaluators derive per-script loggers from.</summary>
public Serilog.ILogger Logger { get; }
/// <summary>Initializes a new instance of the <see cref="ScriptRootLogger"/> class.</summary>
/// <param name="logger">The composed root script logger. Must not be <c>null</c>.</param>
/// <exception cref="ArgumentNullException">Thrown when <paramref name="logger"/> is <c>null</c>.</exception>
public ScriptRootLogger(Serilog.ILogger logger) =>
Logger = logger ?? throw new ArgumentNullException(nameof(logger));
}
@@ -0,0 +1,38 @@
using Serilog;
using Serilog.Events;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
namespace ZB.MOM.WW.OtOpcUa.Host.Logging;
/// <summary>
/// Composes the root script <see cref="Serilog.ILogger"/> — the single pipeline every
/// per-script logger derives from. Fans each script log event out to three destinations:
/// a dedicated rolling <c>scripts-*.log</c> file, the main server log (via
/// <see cref="ScriptLogCompanionSink"/>, mirroring Error-or-higher events at Warning), and
/// the cluster <c>script-logs</c> DPS topic (via <see cref="ScriptLogTopicSink"/>) so the
/// live Script-log Admin UI page can tail script output.
/// </summary>
public static class ScriptRootLoggerFactory
{
/// <summary>
/// Builds the composed root script logger.
/// </summary>
/// <param name="publisher">
/// The publisher the topic sink forwards entries to (the DPS publisher in production).
/// </param>
/// <param name="filePath">
/// Path template for the rolling <c>scripts-*.log</c> file sink (e.g. <c>logs/scripts-.log</c>).
/// </param>
/// <param name="topicMinLevel">
/// Minimum level for events forwarded to the <c>script-logs</c> topic; lower-level events
/// still land in the file sink but are not pushed onto the cluster bus.
/// </param>
/// <returns>The composed root script logger.</returns>
public static Serilog.ILogger Build(IScriptLogPublisher publisher, string filePath, LogEventLevel topicMinLevel)
=> new LoggerConfiguration()
.MinimumLevel.Verbose()
.WriteTo.File(filePath, rollingInterval: RollingInterval.Day)
.WriteTo.Sink(new ScriptLogCompanionSink(Serilog.Log.Logger))
.WriteTo.Sink(new ScriptLogTopicSink(publisher, topicMinLevel))
.CreateLogger();
}
@@ -1,6 +1,8 @@
using Akka.Actor;
using Akka.Hosting;
using Microsoft.Extensions.DependencyInjection.Extensions;
using Serilog;
using Serilog.Events;
using ZB.MOM.WW.OtOpcUa.AdminUI;
using ZB.MOM.WW.OtOpcUa.AdminUI.Clients;
using ZB.MOM.WW.OtOpcUa.AdminUI.Components;
@@ -11,14 +13,17 @@ using ZB.MOM.WW.OtOpcUa.Configuration;
using ZB.MOM.WW.OtOpcUa.ControlPlane;
using ZB.MOM.WW.OtOpcUa.Commons.OpcUa;
using ZB.MOM.WW.OtOpcUa.Commons.Engines;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
using ZB.MOM.WW.OtOpcUa.Host;
using ZB.MOM.WW.OtOpcUa.Host.Configuration;
using ZB.MOM.WW.OtOpcUa.Host.Drivers;
using ZB.MOM.WW.OtOpcUa.Host.Engines;
using ZB.MOM.WW.OtOpcUa.Host.Health;
using ZB.MOM.WW.OtOpcUa.Host.Logging;
using ZB.MOM.WW.OtOpcUa.Host.Observability;
using ZB.MOM.WW.OtOpcUa.Host.OpcUa;
using ZB.MOM.WW.OtOpcUa.OpcUaServer;
using ZB.MOM.WW.OtOpcUa.Runtime.Scripting;
using ZB.MOM.WW.OtOpcUa.OpcUaServer.Security;
using ZB.MOM.WW.OtOpcUa.Runtime;
using ZB.MOM.WW.Auth.Abstractions.Roles;
@@ -113,6 +118,21 @@ if (hasDriver)
new RoslynScriptedAlarmEvaluator(sp.GetRequiredService<ILoggerFactory>().CreateLogger<RoslynScriptedAlarmEvaluator>()));
builder.Services.AddSingleton<IScriptedAlarmEvaluator>(sp => sp.GetRequiredService<RoslynScriptedAlarmEvaluator>());
// Script-log fan-out (Layer 0). The DPS publisher resolves the ActorSystem lazily so it never
// races Akka startup. ScriptRootLogger wraps the composed pipeline (rolling scripts-*.log +
// error mirror to the main log + script-logs DPS topic) for unambiguous DI resolution; Task 3
// injects it into the Roslyn evaluators above.
var scriptLogFilePath = builder.Configuration["Scripting:LogFilePath"] ?? "logs/scripts-.log";
var scriptLogTopicMinLevel = Enum.TryParse<LogEventLevel>(
builder.Configuration["Scripting:LogTopicMinLevel"], ignoreCase: true, out var parsedLevel)
? parsedLevel
: LogEventLevel.Information;
builder.Services.AddSingleton<IScriptLogPublisher>(sp =>
new DpsScriptLogPublisher(() => sp.GetRequiredService<ActorSystem>()));
builder.Services.AddSingleton(sp => new ScriptRootLogger(
ScriptRootLoggerFactory.Build(
sp.GetRequiredService<IScriptLogPublisher>(), scriptLogFilePath, scriptLogTopicMinLevel)));
builder.Services.AddValidatedOptions<LdapOptions, LdapOptionsValidator>(builder.Configuration, LdapOptions.SectionName);
// TryAdd so a fused admin+driver node (where AddOtOpcUaAuth also registers these) ends up
// with exactly one descriptor; on a driver-only node these are the sole registrations.
@@ -0,0 +1,60 @@
using Akka.Actor;
using Akka.Cluster.Tools.PublishSubscribe;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags;
namespace ZB.MOM.WW.OtOpcUa.Runtime.Scripting;
/// <summary>
/// Concrete <see cref="IScriptLogPublisher"/> that routes each <see cref="ScriptLogEntry"/>
/// onto the Akka DistributedPubSub <c>script-logs</c> topic
/// (<see cref="VirtualTagActor.ScriptLogsTopic"/>). <c>ScriptLogSignalRBridge</c> subscribes
/// to that topic so entries reach the live Script-log Admin UI page.
/// </summary>
/// <remarks>
/// <para>
/// The <see cref="ActorSystem"/> is resolved lazily through a <see cref="Func{ActorSystem}"/>
/// so constructing the publisher never races Akka startup — the system only needs to exist
/// by the time the first script logs, not at DI-registration time.
/// </para>
/// <para>
/// This type sits behind a Serilog sink (<see cref="ScriptLogTopicSink"/>); a sink must
/// never throw back into the logging pipeline, so every failure path here is swallowed
/// (best-effort logged at Debug to the main Serilog logger).
/// </para>
/// </remarks>
public sealed class DpsScriptLogPublisher : IScriptLogPublisher
{
private readonly Func<ActorSystem> _system;
/// <summary>Initializes a new instance of the <see cref="DpsScriptLogPublisher"/> class.</summary>
/// <param name="system">
/// Lazy accessor for the running <see cref="ActorSystem"/>. Invoked on each
/// <see cref="Publish"/> so registration does not depend on Akka having started yet.
/// </param>
/// <exception cref="ArgumentNullException">Thrown when <paramref name="system"/> is <c>null</c>.</exception>
public DpsScriptLogPublisher(Func<ActorSystem> system) =>
_system = system ?? throw new ArgumentNullException(nameof(system));
/// <summary>
/// Publishes <paramref name="entry"/> onto the DPS <c>script-logs</c> topic. Any failure
/// (system not yet ready, mediator unavailable) is swallowed so the logging pipeline is
/// never disrupted by a transient cluster condition.
/// </summary>
/// <param name="entry">The entry to publish.</param>
public void Publish(ScriptLogEntry entry)
{
try
{
var mediator = DistributedPubSub.Get(_system()).Mediator;
mediator.Tell(new Publish(VirtualTagActor.ScriptLogsTopic, entry));
}
catch (Exception ex)
{
// A logging sink must never throw into the logging pipeline. Best-effort note to
// the main log at Debug; nothing actionable for the script author here.
Serilog.Log.Debug(ex, "DpsScriptLogPublisher could not route a script log entry to the cluster bus.");
}
}
}
@@ -25,6 +25,9 @@
-->
<ProjectReference Include="..\..\Core\ZB.MOM.WW.OtOpcUa.Core.Abstractions\ZB.MOM.WW.OtOpcUa.Core.Abstractions.csproj"/>
<ProjectReference Include="..\..\Core\ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian\ZB.MOM.WW.OtOpcUa.Core.AlarmHistorian.csproj"/>
<!-- IScriptLogPublisher lives in Core.Scripting; DpsScriptLogPublisher implements it
here so the concrete Akka DPS routing stays out of the Core layer. -->
<ProjectReference Include="..\..\Core\ZB.MOM.WW.OtOpcUa.Core.Scripting\ZB.MOM.WW.OtOpcUa.Core.Scripting.csproj"/>
</ItemGroup>
<ItemGroup>
@@ -0,0 +1,101 @@
using Serilog;
using Serilog.Core;
using Serilog.Events;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests;
/// <summary>
/// Verifies the root script-logger fan-out: events flowing through the composed
/// pipeline (rolling file + companion mirror + topic sink) reach the
/// <see cref="IScriptLogPublisher"/> topic sink only when they meet the configured
/// minimum level, carrying their <c>ScriptId</c> identity property.
/// </summary>
/// <remarks>
/// Builds the identical <see cref="LoggerConfiguration"/> that the Host's
/// <c>ScriptRootLoggerFactory.Build</c> composes (file + <see cref="ScriptLogCompanionSink"/>
/// + <see cref="ScriptLogTopicSink"/>). The factory itself is a thin shell over this
/// exact wiring; testing the composition here keeps the suite a pure unit test with no
/// dependency on the Host's Web SDK executable.
/// </remarks>
[Trait("Category", "Unit")]
public sealed class ScriptRootLoggerFanoutTests : IDisposable
{
private readonly string _tempFile = Path.Combine(
Path.GetTempPath(), $"scripts-fanout-{Guid.NewGuid():N}-.log");
private sealed class FakePublisher : IScriptLogPublisher
{
/// <summary>Gets the entries that have been published to the topic.</summary>
public List<ScriptLogEntry> Published { get; } = [];
/// <inheritdoc/>
public void Publish(ScriptLogEntry entry) => Published.Add(entry);
}
/// <summary>
/// Builds the same pipeline the Host's <c>ScriptRootLoggerFactory.Build</c> composes,
/// so this test exercises the real production sink fan-out.
/// </summary>
private Logger BuildRootLogger(FakePublisher publisher, LogEventLevel topicMinLevel) =>
new LoggerConfiguration()
.MinimumLevel.Verbose()
.WriteTo.File(_tempFile, rollingInterval: RollingInterval.Day)
.WriteTo.Sink(new ScriptLogCompanionSink(Serilog.Log.Logger))
.WriteTo.Sink(new ScriptLogTopicSink(publisher, topicMinLevel))
.CreateLogger();
/// <summary>
/// An Information event flows to the topic sink as a single <see cref="ScriptLogEntry"/>
/// carrying the bound <c>ScriptId</c>.
/// </summary>
[Fact]
public void Information_event_reaches_the_topic_sink_with_its_ScriptId()
{
var publisher = new FakePublisher();
using var root = BuildRootLogger(publisher, LogEventLevel.Information);
root.ForContext(ScriptLoggerFactory.ScriptIdProperty, "S1")
.Information("virtual tag recomputed");
publisher.Published.Count.ShouldBe(1);
publisher.Published[0].ScriptId.ShouldBe("S1");
publisher.Published[0].Level.ShouldBe("Information");
publisher.Published[0].Message.ShouldBe("virtual tag recomputed");
}
/// <summary>
/// A Debug event is gated out by the topic sink's Information minimum level, so the
/// publisher receives nothing (it still lands in the file sink, which we don't assert).
/// </summary>
[Fact]
public void Debug_event_is_gated_out_by_the_topic_minimum_level()
{
var publisher = new FakePublisher();
using var root = BuildRootLogger(publisher, LogEventLevel.Information);
root.ForContext(ScriptLoggerFactory.ScriptIdProperty, "S1")
.Debug("verbose diagnostic noise");
publisher.Published.ShouldBeEmpty();
}
/// <summary>Disposes the temp log file created by the rolling file sink.</summary>
public void Dispose()
{
// Serilog appends a date stamp where the trailing '-' sits; clean any matching file.
var dir = Path.GetDirectoryName(_tempFile)!;
var prefix = Path.GetFileNameWithoutExtension(_tempFile);
try
{
foreach (var f in Directory.EnumerateFiles(dir, prefix + "*"))
File.Delete(f);
}
catch (IOException)
{
// Best-effort cleanup — a locked file on a flaky CI box must not fail the test.
}
}
}
@@ -13,6 +13,10 @@
<PackageReference Include="xunit.v3"/>
<PackageReference Include="Shouldly"/>
<PackageReference Include="Microsoft.NET.Test.Sdk"/>
<!-- The root-logger fan-out test composes the same rolling-file + sink pipeline the
Host's ScriptRootLoggerFactory builds; Core.Scripting references only Serilog core,
so the File sink must be pulled in here for WriteTo.File. -->
<PackageReference Include="Serilog.Sinks.File"/>
<PackageReference Include="xunit.runner.visualstudio">
<PrivateAssets>all</PrivateAssets>
<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
@@ -0,0 +1,75 @@
using Akka.Actor;
using Akka.Cluster.Tools.PublishSubscribe;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Runtime.Scripting;
using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness;
using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags;
namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Scripting;
/// <summary>
/// Verifies <see cref="DpsScriptLogPublisher"/> routes a <see cref="ScriptLogEntry"/>
/// onto the Akka DistributedPubSub <c>script-logs</c> topic and never throws back into
/// the calling logging pipeline.
/// </summary>
public sealed class DpsScriptLogPublisherTests : RuntimeActorTestBase
{
/// <summary>Builds a representative entry for assertions.</summary>
private static ScriptLogEntry SampleEntry() => new(
ScriptId: "S1",
Level: "Information",
Message: "hello from script",
TimestampUtc: DateTime.UtcNow,
VirtualTagId: "V1",
AlarmId: null,
EquipmentId: "EQ1");
/// <summary>
/// A published entry is delivered verbatim to a probe subscribed to the
/// <see cref="VirtualTagActor.ScriptLogsTopic"/> topic via the DPS mediator.
/// </summary>
[Fact]
public void Publish_routes_entry_to_subscribers_of_the_script_logs_topic()
{
var probe = CreateTestProbe();
var mediator = DistributedPubSub.Get(Sys).Mediator;
// Send the Subscribe FROM the probe so the SubscribeAck returns to the probe's mailbox
// (a bare mediator.Tell would route the ack to the implicit TestActor instead).
probe.Send(mediator, new Subscribe(VirtualTagActor.ScriptLogsTopic, probe.Ref));
probe.ExpectMsg<SubscribeAck>(TimeSpan.FromSeconds(10));
var publisher = new DpsScriptLogPublisher(() => Sys);
var entry = SampleEntry();
// The SubscribeAck confirms the subscribe was registered, but DPS topic membership is
// eventually-consistent — publish in a short retry loop until the probe sees the entry
// (mirrors the Host.IntegrationTests DPS round-trip pattern), then assert the payload.
AwaitAssert(() =>
{
publisher.Publish(entry);
probe.ExpectMsg<ScriptLogEntry>(TimeSpan.FromMilliseconds(200)).ShouldBe(entry);
}, duration: TimeSpan.FromSeconds(5), interval: TimeSpan.FromMilliseconds(250));
}
/// <summary>
/// A logging sink must never throw into the logging pipeline: if the system
/// accessor throws, <see cref="DpsScriptLogPublisher.Publish"/> swallows it.
/// </summary>
[Fact]
public void Publish_does_not_throw_when_the_system_accessor_throws()
{
var publisher = new DpsScriptLogPublisher(
() => throw new InvalidOperationException("system not ready"));
Should.NotThrow(() => publisher.Publish(SampleEntry()));
}
/// <summary>The constructor rejects a null system accessor.</summary>
[Fact]
public void Null_system_accessor_throws_ArgumentNullException()
{
Should.Throw<ArgumentNullException>(() => new DpsScriptLogPublisher(null!));
}
}