using Akka.Actor;
using Akka.TestKit.Xunit2;
using Microsoft.CodeAnalysis.CSharp.Scripting;
using Microsoft.CodeAnalysis.Scripting;
using Microsoft.Extensions.Logging.Abstractions;
using ZB.MOM.WW.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution;
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;
///
/// Flow Debugger step logs (design 2026-09-09 D3/D7) at the launcher boundary: the
/// ScriptRun anchor row a traced run returns inline carries the failing run's full
/// exception detail (and deliberately none for a timeout), and the run's log lines are bounded
/// by SiteRuntimeOptions.MaxLogLinesPerRun with one closing row naming the drops — all
/// of it emitted BEFORE the anchor, so the Flow Debugger reads a run's lines in order.
///
public class ScriptRunLauncherTraceTests : TestKit, IDisposable
{
/// Own pool per class, so a wedged body cannot strand the process-wide one.
private readonly ScriptExecutionScheduler _scheduler = new(4);
private readonly SharedScriptLibrary _sharedLibrary;
/// Initializes the test class with its script scheduler and shared script library.
public ScriptRunLauncherTraceTests()
=> _sharedLibrary = new SharedScriptLibrary(
new ScriptCompilationService(NullLogger.Instance),
NullLogger.Instance);
///
void IDisposable.Dispose()
{
Shutdown();
_scheduler.Dispose();
}
// ── helpers ──────────────────────────────────────────────────────────────────
private static Script CompileScript(string code)
{
var scriptOptions = 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, scriptOptions, typeof(ScriptGlobals));
script.Compile();
return script;
}
private static AuditRowProjection.AuditRowValues Row(AuditEvent evt) => evt.AsRow();
private static ScriptTraceExtra Extra(AuditEvent evt) => ScriptTraceExtra.TryParse(Row(evt).Extra)!;
/// Runs one traced script to completion and returns the reply's inline trace rows.
private ScriptCallResult RunTraced(string body, SiteRuntimeOptions options)
{
var caller = CreateTestProbe();
ScriptRunLauncher.LaunchScript(
scriptName: "Runner",
instanceName: "Inst1",
compiledScript: CompileScript(body),
parameters: null,
callDepth: 0,
instanceActor: CreateTestProbe().Ref,
sharedScriptLibrary: _sharedLibrary,
options: options,
replyTo: caller.Ref,
correlationId: "corr-1",
completionTarget: CreateTestProbe().Ref,
siteCommunicationActor: null,
logger: NullLogger.Instance,
scope: ScriptScope.Root,
runId: 1,
healthCollector: null,
serviceProvider: null,
parentExecutionId: null,
executionTimeoutSeconds: null,
scheduler: _scheduler,
trace: true,
triggerExtra: null);
return caller.ExpectMsg(TimeSpan.FromSeconds(20));
}
private static SiteRuntimeOptions Options(int timeoutSeconds = 30, int maxLogLines = 200) => new()
{
MaxScriptCallDepth = 10,
ScriptExecutionTimeoutSeconds = timeoutSeconds,
StuckScriptGraceMs = 30000,
MaxLogLinesPerRun = maxLogLines,
};
private static AuditEvent ScriptRunRow(ScriptCallResult result)
=> Assert.Single(result.TraceEvents!, e => Row(e).Kind == AuditKind.ScriptRun);
// ── ScadaBridge#56: run identity is on the Serilog LogContext while the run executes ──
/// Forwards every call to a Serilog logger so LogContext enrichment is observable at the time of the call.
private sealed class SerilogForwardingLogger(Serilog.ILogger inner) : Microsoft.Extensions.Logging.ILogger
{
public IDisposable? BeginScope(TState state) where TState : notnull => null;
public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) => true;
public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId,
TState state, Exception? exception, Func formatter)
=> inner.Write(Serilog.Events.LogEventLevel.Information, "forwarded");
}
private sealed class CaptureSink : Serilog.Core.ILogEventSink
{
public System.Collections.Concurrent.ConcurrentQueue Events { get; } = new();
public void Emit(Serilog.Events.LogEvent logEvent) => Events.Enqueue(logEvent);
}
/// Verifies a line logged during a run carries the run's ExecutionId/InstanceName/ScriptName, and the scope is popped afterwards.
[Fact]
public void RunningScript_StampsExecutionIdentityOnTheLogContext()
{
var sink = new CaptureSink();
var serilog = new Serilog.LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(sink).CreateLogger();
var caller = CreateTestProbe();
ScriptRunLauncher.LaunchScript(
scriptName: "Runner", instanceName: "Inst1",
compiledScript: CompileScript("Log.Info(\"hello\"); return null;"),
parameters: null, callDepth: 0, instanceActor: CreateTestProbe().Ref,
sharedScriptLibrary: _sharedLibrary, options: Options(), replyTo: caller.Ref,
correlationId: "corr-1", completionTarget: CreateTestProbe().Ref,
siteCommunicationActor: null, logger: new SerilogForwardingLogger(serilog),
scope: ScriptScope.Root, runId: 1, healthCollector: null, serviceProvider: null,
parentExecutionId: null, executionTimeoutSeconds: null, scheduler: _scheduler,
trace: false, triggerExtra: null);
var result = caller.ExpectMsg(TimeSpan.FromSeconds(20));
Assert.True(result.Success);
var evt = Assert.Single(sink.Events);
Assert.Equal(result.ExecutionId!.Value.ToString(), evt.Properties["ExecutionId"].ToString().Trim('"'));
Assert.Equal("Inst1", evt.Properties["InstanceName"].ToString().Trim('"'));
Assert.Equal("Runner", evt.Properties["ScriptName"].ToString().Trim('"'));
// Not leaked past the run on this thread's context.
serilog.Information("after");
Assert.False(sink.Events.Last().Properties.ContainsKey("ExecutionId"));
}
// ── (a) a throwing run carries the exception's full detail ───────────────────
/// Verifies that a traced run that throws records the full exception detail on its script-run row.
[Fact]
public void ThrowingTracedRun_ScriptRunRow_CarriesTheFullExceptionDetail()
{
var result = RunTraced("throw new InvalidOperationException(\"boom\");", Options());
Assert.False(result.Success);
var row = Row(ScriptRunRow(result));
Assert.Equal(AuditStatus.Failed, row.Status);
Assert.Contains("boom", row.ErrorMessage);
Assert.NotNull(row.ErrorDetail);
// Type name first, then the stack — the whole point of D3 over the one-line message.
Assert.StartsWith("System.InvalidOperationException", row.ErrorDetail);
Assert.Contains(" at ", row.ErrorDetail);
}
// ── (b) a timeout carries NO detail (the stack would be the launcher's) ──────
/// Verifies that a traced run that times out records no exception detail on its script-run row.
[Fact]
public void TimedOutTracedRun_ScriptRunRow_CarriesNoExceptionDetail()
{
var result = RunTraced(
"while (true) { await Task.Delay(25, CancellationToken); }",
Options(timeoutSeconds: 1));
Assert.False(result.Success);
var row = Row(ScriptRunRow(result));
Assert.Equal(AuditStatus.Failed, row.Status);
Assert.Contains("timed out", row.ErrorMessage);
Assert.Null(row.ErrorDetail);
}
// ── (c) the per-run line cap, its closing row, and emission order ────────────
/// Verifies that a traced run caps its log lines and emits the closing row before the anchor row.
[Fact]
public void TracedRun_CapsLogLines_AndEmitsTheClosingRowBeforeTheAnchor()
{
var result = RunTraced(
"Log.Info(\"a\"); Log.Info(\"b\"); Log.Info(\"c\"); Log.Info(\"d\"); Log.Info(\"e\"); return null;",
Options(maxLogLines: 2));
Assert.True(result.Success);
var rows = result.TraceEvents!;
var logs = rows.Where(e => Row(e).Kind == AuditKind.ScriptLog).ToList();
var scriptLines = logs.Where(e => Extra(e).LogSource == "script").ToList();
Assert.Equal(2, scriptLines.Count);
Assert.Equal(["a", "b"], scriptLines.Select(e => Row(e).RequestSummary));
// One closing runtime warning naming the three dropped lines.
var closing = Assert.Single(logs, e => Extra(e).LogSource == "runtime");
Assert.Equal("warn", Extra(closing).LogLevel);
Assert.Contains("3 further log line(s) were not captured", Row(closing).RequestSummary);
// Every log row — the closing one included — precedes the run's anchor row.
var anchorIndex = rows.ToList().FindIndex(e => Row(e).Kind == AuditKind.ScriptRun);
Assert.All(logs, e => Assert.True(rows.ToList().IndexOf(e) < anchorIndex));
Assert.Equal(logs.Count, anchorIndex);
}
// ── (d) the reply reports the site collector's truncation (Gitea #54) ────────
///
/// Verifies that a traced run whose inline collector dropped log-line rows says so on the
/// reply (LogsTruncated ), instead of handing the caller a silently short list.
///
[Fact]
public void TracedRun_WhoseCollectorDroppedLogRows_ReportsLogsTruncated()
{
// 600 lines is under the per-run line cap set here (1000) but over the collector's
// low-priority event share (DefaultMaxEvents - LowPriorityReserveEvents = 450).
var result = RunTraced(
"for (var i = 0; i < 600; i++) Log.Info(\"line \" + i); return null;",
Options(maxLogLines: 1000));
Assert.True(result.Success);
Assert.True(result.LogsTruncated);
Assert.False(result.Truncated);
Assert.True(result.TraceEvents!.Count < 600);
// Step rows still fit: the ScriptRun anchor is present.
ScriptRunRow(result);
}
/// Positive control: a small traced run reports neither truncation flag.
[Fact]
public void TracedRun_WithinTheCollectorCaps_ReportsNoTruncation()
{
var result = RunTraced("Log.Info(\"one\"); return null;", Options());
Assert.True(result.Success);
Assert.False(result.LogsTruncated);
Assert.False(result.Truncated);
}
}