using Akka.Actor; using Akka.TestKit.Xunit2; using Microsoft.CodeAnalysis.CSharp.Scripting; using Microsoft.CodeAnalysis.Scripting; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using ZB.MOM.WW.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; using ZB.MOM.WW.ScadaBridge.Commons.Types.Scripts; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; /// /// ScadaBridge#56: while a run is traced, node-log lines that OTHER actors write for it (tagged with /// its ExecutionId) are copied into its ScriptLog rows as source node — under the /// run's line cap, through the same collector (and so the same redaction) as every other row — and /// an untraced run copies nothing. /// public class NodeLogCaptureTests : TestKit, IDisposable { private readonly ScriptExecutionScheduler _scheduler = new(4); private readonly SharedScriptLibrary _sharedLibrary = new( new ScriptCompilationService(NullLogger.Instance), NullLogger.Instance); /// The node's Serilog pipeline as the host builds it: LogContext enrichment plus the capture sink. private readonly Serilog.ILogger _node = new Serilog.LoggerConfiguration() .MinimumLevel.Information() .Enrich.FromLogContext() .WriteTo.Sink(new ExecutionLogCaptureSink()) .CreateLogger(); /// void IDisposable.Dispose() { Shutdown(); _scheduler.Dispose(); } /// A Microsoft logger over a Serilog logger (the host's UseSerilog shape), with a category. private sealed class SerilogMel(Serilog.ILogger inner, string category) : ILogger { private readonly Serilog.ILogger _inner = inner.ForContext("SourceContext", category); public IDisposable? BeginScope(TState state) where TState : notnull => null; public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Information; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { if (!IsEnabled(logLevel)) return; var level = logLevel switch { LogLevel.Information => Serilog.Events.LogEventLevel.Information, LogLevel.Warning => Serilog.Events.LogEventLevel.Warning, _ => Serilog.Events.LogEventLevel.Error, }; _inner.Write(level, exception, "{Message:l}", formatter(state, exception)); } } /// /// Stands in for the Instance Actor: re-pushes the message's execution id (as the real one does in /// AroundReceive), logs a line on ITS thread, and acknowledges the write. /// private sealed class LoggingInstanceActor : ReceiveActor { public LoggingInstanceActor(Serilog.ILogger node) { var log = node.ForContext("SourceContext", "ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.InstanceActor"); Receive(cmd => { using (ExecutionLogContext.PushFor(cmd)) { log.Warning("instance actor applied {Attribute} token=hunter2", cmd.AttributeName); } Sender.Tell(new SetStaticAttributeResponse( cmd.CorrelationId, cmd.InstanceUniqueName, cmd.AttributeName, true, null, DateTimeOffset.UtcNow)); }); } } private static Script Compile(string code) { var options = ScriptOptions.Default .WithReferences(typeof(object).Assembly, typeof(Enumerable).Assembly, typeof(ScriptGlobals).Assembly) .WithImports("System", "System.Collections.Generic", "System.Linq", "System.Threading.Tasks"); var script = CSharpScript.Create(code, options, typeof(ScriptGlobals)); script.Compile(); return script; } private ScriptCallResult Run(string body, bool trace, int maxLogLines = 200) { var caller = CreateTestProbe(); var instance = Sys.ActorOf(Props.Create(() => new LoggingInstanceActor(_node))); ScriptRunLauncher.LaunchScript( scriptName: "Runner", instanceName: "Inst1", compiledScript: Compile(body), parameters: null, callDepth: 0, instanceActor: instance, sharedScriptLibrary: _sharedLibrary, options: new SiteRuntimeOptions { MaxScriptCallDepth = 10, ScriptExecutionTimeoutSeconds = 30, StuckScriptGraceMs = 30000, MaxLogLinesPerRun = maxLogLines, }, replyTo: caller.Ref, correlationId: "corr-1", completionTarget: CreateTestProbe().Ref, siteCommunicationActor: null, logger: new SerilogMel(_node, "ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.ScriptActor"), scope: ScriptScope.Root, runId: 1, healthCollector: null, serviceProvider: null, parentExecutionId: null, executionTimeoutSeconds: null, scheduler: _scheduler, trace: trace, triggerExtra: null); return caller.ExpectMsg(TimeSpan.FromSeconds(20)); } private static List<(AuditEvent Event, ScriptTraceExtra Extra)> LogRows(ScriptCallResult result) => result.TraceEvents! .Where(e => e.AsRow().Kind == AuditKind.ScriptLog) .Select(e => (e, ScriptTraceExtra.TryParse(e.AsRow().Extra)!)) .ToList(); /// /// Cross-actor: the Instance Actor's line, written on its own thread while serving the traced /// run's write, comes back inline as a node row of that run, with its category and level. /// [Fact] public void TracedRun_OtherActorsLine_IsCapturedAsANodeRow() { var result = Run("await Instance.SetAttribute(\"Setpoint\", \"42\"); return null;", trace: true); Assert.True(result.Success, result.ErrorMessage); var node = Assert.Single(LogRows(result), r => r.Extra.LogSource == "node"); Assert.Equal("warn", node.Extra.LogLevel); Assert.Equal("ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.InstanceActor", node.Extra.LogCategory); Assert.Contains("instance actor applied \"Setpoint\"", node.Event.AsRow().RequestSummary); Assert.Equal(result.ExecutionId, node.Event.AsRow().ExecutionId); // The registration ends with the run: a later line for the same id is not captured. Assert.False(ExecutionLogCapture.TryGetTarget(result.ExecutionId!.Value, out _)); } /// /// An inline shared script's write is stamped with the SHARED script's own execution id; its /// node line still lands in the caller's rows (where the shared script's Log.* lines go). /// [Fact] public void SharedScriptsWrite_NodeLine_LandsInTheCallersRows() { Assert.True(_sharedLibrary.CompileAndRegister( "WriteHelper", "await Instance.SetAttribute(\"FromShared\", \"1\"); return null;")); var result = Run("await Instance.Scripts.CallShared(\"WriteHelper\"); return null;", trace: true); Assert.True(result.Success, result.ErrorMessage); var node = Assert.Single(LogRows(result), r => r.Extra.LogSource == "node"); Assert.Contains("FromShared", node.Event.AsRow().RequestSummary); Assert.Equal(result.ExecutionId, node.Event.AsRow().ExecutionId); } /// An untraced run never registers, so the same line is not captured (and the reply has no rows). [Fact] public void UntracedRun_CapturesNothing() { var result = Run("await Instance.SetAttribute(\"Setpoint\", \"42\"); return null;", trace: false); Assert.True(result.Success, result.ErrorMessage); Assert.True(result.TraceEvents is null || result.TraceEvents.Count == 0); } /// /// No double capture: the script's own Log.Info goes to the node logger (tagged with the run's /// id) and is a script row exactly once — never a second node row. The launcher's /// own failure line is the ScriptRun row, so it is not copied either. /// [Fact] public void ScriptLogLine_AndLauncherFailureLine_AreNotCopiedAsNodeRows() { var result = Run("Log.Info(\"hello\"); throw new InvalidOperationException(\"boom\");", trace: true); Assert.False(result.Success); var rows = LogRows(result); var script = Assert.Single(rows); Assert.Equal("script", script.Extra.LogSource); Assert.Equal("hello", script.Event.AsRow().RequestSummary); } /// /// Node rows share the run's line cap with the script's own lines: past it they are dropped and /// the closing runtime row names the count. /// [Fact] public void NodeRows_ShareTheRunsLineCap() { var result = Run( "Log.Info(\"one\"); for (var i = 0; i < 3; i++) await Instance.SetAttribute(\"A\" + i, \"1\"); return null;", trace: true, maxLogLines: 2); Assert.True(result.Success, result.ErrorMessage); var rows = LogRows(result); Assert.Equal(3, rows.Count); // "one" + 1 node row + the closing row Assert.Single(rows, r => r.Extra.LogSource == "node"); var closing = Assert.Single(rows, r => r.Extra.LogSource == "runtime"); Assert.Contains("2 further log line(s)", closing.Event.AsRow().RequestSummary); } /// /// Node rows ride the same inline collector as every other row, so its redactor applies: what Live /// shows is what Replay stores. /// /// A task that represents the asynchronous operation. [Fact] public async Task NodeRows_PassTheCollectorsRedactor() { var collector = new FlowTraceCollector(redactor: new TokenRedactor()); var exec = Guid.NewGuid(); var ctx = new ScriptRuntimeContext( Sys.ActorOf(Props.Create(() => new LoggingInstanceActor(_node))), _sharedLibrary, currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5), instanceName: "Inst1", logger: NullLogger.Instance, siteId: "site-a", sourceScript: "ScriptActor:Runner", executionId: exec, isTraced: true, traceCollector: collector); using (ctx.Log.CaptureNodeLines(exec)) { await ctx.SetAttribute("Setpoint", "42"); } var node = Assert.Single(collector.Complete(), e => e.AsRow().Kind == AuditKind.ScriptLog); Assert.DoesNotContain("hunter2", node.DetailsJson); Assert.Contains("token=***", node.AsRow().RequestSummary); } /// Scrubs hunter2 from the details, standing in for the host's body-regex redaction. private sealed class TokenRedactor : IAuditRedactor { public AuditEvent Apply(AuditEvent rawEvent) => rawEvent with { DetailsJson = rawEvent.DetailsJson?.Replace("hunter2", "***", StringComparison.Ordinal) }; } private (ScriptLogger Logger, List<(string Level, string Source, string Message, string? Category)> Rows) Traced(Guid id) { var rows = new List<(string, string, string, string?)>(); var logger = new ScriptLogger( new SerilogMel(_node, "ScriptActor"), (level, source, message, _, _, category, _) => { lock (rows) rows.Add((level, source, message, category)); }, maxLines: 200, "Inst1", "Runner", id); return (logger, rows); } /// An untraced logger never touches the registry. [Fact] public void UntracedLogger_CaptureNodeLines_DoesNotRegister() { var id = Guid.NewGuid(); var untraced = new ScriptLogger(NullLogger.Instance, emit: null, maxLines: 200, "Inst1", "Runner", id); using (untraced.CaptureNodeLines(id)) { Assert.False(ExecutionLogCapture.TryGetTarget(id, out _)); } } /// FlushDropped (every run-end path) closes the copy, and a capture opened after it is refused. [Fact] public void FlushDropped_ClosesTheCopy() { var id = Guid.NewGuid(); var (logger, rows) = Traced(id); var capture = logger.CaptureNodeLines(id); Assert.True(ExecutionLogCapture.TryGetTarget(id, out _)); logger.FlushDropped(); Assert.False(ExecutionLogCapture.TryGetTarget(id, out _)); using (logger.CaptureNodeLines(id)) using (ExecutionLogContext.Push(id)) { _node.Warning("after the run"); } Assert.Empty(rows); capture.Dispose(); } /// /// The runtime decorator's forward is suppressed: a runtime warning logged while traced is one /// runtime row, never a second node row — while a genuine other-actor line still is one. /// [Fact] public void RuntimeLine_IsNotCopiedAgain_ButAnotherLoggersLineIs() { var id = Guid.NewGuid(); var (logger, rows) = Traced(id); var runtime = new TraceCapturingLogger(new SerilogMel(_node, "ScriptActor"), logger); using (logger.CaptureNodeLines(id)) using (ExecutionLogContext.Push(id)) { runtime.LogWarning("runtime warning"); _node.ForContext("SourceContext", "Acme.Other").Warning("other actor"); } Assert.Equal( [("warn", "runtime", "runtime warning", (string?)null), ("warn", "node", "other actor", "Acme.Other")], rows); } }