diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRootLogger.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRootLogger.cs new file mode 100644 index 00000000..07f000c0 --- /dev/null +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRootLogger.cs @@ -0,0 +1,25 @@ +namespace ZB.MOM.WW.OtOpcUa.Core.Scripting; + +/// +/// DI-friendly holder for the root script so it can be +/// injected into the Roslyn evaluators without clashing with the application's main +/// Serilog.Log.Logger (both are ; a wrapper type +/// gives the container an unambiguous registration to resolve). +/// +/// +/// The wrapped logger is the composed script pipeline — a rolling scripts-*.log +/// file sink, the mirroring errors to the main log, +/// and the fanning entries onto the cluster +/// script-logs topic for the live Script-log Admin UI page. +/// +public sealed class ScriptRootLogger +{ + /// Gets the composed root script logger that evaluators derive per-script loggers from. + public Serilog.ILogger Logger { get; } + + /// Initializes a new instance of the class. + /// The composed root script logger. Must not be null. + /// Thrown when is null. + public ScriptRootLogger(Serilog.ILogger logger) => + Logger = logger ?? throw new ArgumentNullException(nameof(logger)); +} diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/ScriptRootLoggerFactory.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/ScriptRootLoggerFactory.cs new file mode 100644 index 00000000..1796417a --- /dev/null +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Logging/ScriptRootLoggerFactory.cs @@ -0,0 +1,38 @@ +using Serilog; +using Serilog.Events; +using ZB.MOM.WW.OtOpcUa.Core.Scripting; + +namespace ZB.MOM.WW.OtOpcUa.Host.Logging; + +/// +/// Composes the root script — the single pipeline every +/// per-script logger derives from. Fans each script log event out to three destinations: +/// a dedicated rolling scripts-*.log file, the main server log (via +/// , mirroring Error-or-higher events at Warning), and +/// the cluster script-logs DPS topic (via ) so the +/// live Script-log Admin UI page can tail script output. +/// +public static class ScriptRootLoggerFactory +{ + /// + /// Builds the composed root script logger. + /// + /// + /// The publisher the topic sink forwards entries to (the DPS publisher in production). + /// + /// + /// Path template for the rolling scripts-*.log file sink (e.g. logs/scripts-.log). + /// + /// + /// Minimum level for events forwarded to the script-logs topic; lower-level events + /// still land in the file sink but are not pushed onto the cluster bus. + /// + /// The composed root script logger. + 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(); +} diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs index 8f14a66c..fb7cf8b5 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Program.cs @@ -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().CreateLogger())); builder.Services.AddSingleton(sp => sp.GetRequiredService()); + // 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( + builder.Configuration["Scripting:LogTopicMinLevel"], ignoreCase: true, out var parsedLevel) + ? parsedLevel + : LogEventLevel.Information; + builder.Services.AddSingleton(sp => + new DpsScriptLogPublisher(() => sp.GetRequiredService())); + builder.Services.AddSingleton(sp => new ScriptRootLogger( + ScriptRootLoggerFactory.Build( + sp.GetRequiredService(), scriptLogFilePath, scriptLogTopicMinLevel))); + builder.Services.AddValidatedOptions(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. diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Scripting/DpsScriptLogPublisher.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Scripting/DpsScriptLogPublisher.cs new file mode 100644 index 00000000..248d69ad --- /dev/null +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Scripting/DpsScriptLogPublisher.cs @@ -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; + +/// +/// Concrete that routes each +/// onto the Akka DistributedPubSub script-logs topic +/// (). ScriptLogSignalRBridge subscribes +/// to that topic so entries reach the live Script-log Admin UI page. +/// +/// +/// +/// The is resolved lazily through a +/// 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. +/// +/// +/// This type sits behind a Serilog sink (); 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). +/// +/// +public sealed class DpsScriptLogPublisher : IScriptLogPublisher +{ + private readonly Func _system; + + /// Initializes a new instance of the class. + /// + /// Lazy accessor for the running . Invoked on each + /// so registration does not depend on Akka having started yet. + /// + /// Thrown when is null. + public DpsScriptLogPublisher(Func system) => + _system = system ?? throw new ArgumentNullException(nameof(system)); + + /// + /// Publishes onto the DPS script-logs topic. Any failure + /// (system not yet ready, mediator unavailable) is swallowed so the logging pipeline is + /// never disrupted by a transient cluster condition. + /// + /// The entry to publish. + 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."); + } + } +} diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ZB.MOM.WW.OtOpcUa.Runtime.csproj b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ZB.MOM.WW.OtOpcUa.Runtime.csproj index c051c39b..42a358d8 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ZB.MOM.WW.OtOpcUa.Runtime.csproj +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/ZB.MOM.WW.OtOpcUa.Runtime.csproj @@ -25,6 +25,9 @@ --> + + diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRootLoggerFanoutTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRootLoggerFanoutTests.cs new file mode 100644 index 00000000..ecd53a04 --- /dev/null +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRootLoggerFanoutTests.cs @@ -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; + +/// +/// Verifies the root script-logger fan-out: events flowing through the composed +/// pipeline (rolling file + companion mirror + topic sink) reach the +/// topic sink only when they meet the configured +/// minimum level, carrying their ScriptId identity property. +/// +/// +/// Builds the identical that the Host's +/// ScriptRootLoggerFactory.Build composes (file + +/// + ). 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. +/// +[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 + { + /// Gets the entries that have been published to the topic. + public List Published { get; } = []; + + /// + public void Publish(ScriptLogEntry entry) => Published.Add(entry); + } + + /// + /// Builds the same pipeline the Host's ScriptRootLoggerFactory.Build composes, + /// so this test exercises the real production sink fan-out. + /// + 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(); + + /// + /// An Information event flows to the topic sink as a single + /// carrying the bound ScriptId. + /// + [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"); + } + + /// + /// 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). + /// + [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(); + } + + /// Disposes the temp log file created by the rolling file sink. + 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. + } + } +} diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests.csproj b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests.csproj index be47f51a..34393c12 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests.csproj +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests.csproj @@ -13,6 +13,10 @@ + + all runtime; build; native; contentfiles; analyzers; buildtransitive diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Scripting/DpsScriptLogPublisherTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Scripting/DpsScriptLogPublisherTests.cs new file mode 100644 index 00000000..6354eb50 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Scripting/DpsScriptLogPublisherTests.cs @@ -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; + +/// +/// Verifies routes a +/// onto the Akka DistributedPubSub script-logs topic and never throws back into +/// the calling logging pipeline. +/// +public sealed class DpsScriptLogPublisherTests : RuntimeActorTestBase +{ + /// Builds a representative entry for assertions. + private static ScriptLogEntry SampleEntry() => new( + ScriptId: "S1", + Level: "Information", + Message: "hello from script", + TimestampUtc: DateTime.UtcNow, + VirtualTagId: "V1", + AlarmId: null, + EquipmentId: "EQ1"); + + /// + /// A published entry is delivered verbatim to a probe subscribed to the + /// topic via the DPS mediator. + /// + [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(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(TimeSpan.FromMilliseconds(200)).ShouldBe(entry); + }, duration: TimeSpan.FromSeconds(5), interval: TimeSpan.FromMilliseconds(250)); + } + + /// + /// A logging sink must never throw into the logging pipeline: if the system + /// accessor throws, swallows it. + /// + [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())); + } + + /// The constructor rejects a null system accessor. + [Fact] + public void Null_system_accessor_throws_ArgumentNullException() + { + Should.Throw(() => new DpsScriptLogPublisher(null!)); + } +}