diff --git a/docs/plans/2026-09-09-flow-debugger-step-logs-design.md b/docs/plans/2026-09-09-flow-debugger-step-logs-design.md index 2045e177..04b8566c 100644 --- a/docs/plans/2026-09-09-flow-debugger-step-logs-design.md +++ b/docs/plans/2026-09-09-flow-debugger-step-logs-design.md @@ -129,8 +129,12 @@ bounds it. Nothing new crosses the PSK boundary: `ScriptLog` rows ride the exist Live streaming of lines during a long run (rows still arrive with the reply — D4 of the base design); a run-wide chronological log list (belongs to the Direction B list, register row 110); capturing what -**other actors** log for a run (instance actor, DCL) — needs `LogContext` enrichment with `ExecutionId` plus -`Enrich.FromLogContext()` and an execution-id column on `site_events`; a `Log` sink to the site event log; capturing `Console.Out` on a site run — `System` is imported so +**other actors** log for a run (instance actor, DCL) — **partly done (Gitea #56):** the site script/alarm launcher now pushes +`ExecutionId`/`InstanceName`/`ScriptName` onto the Serilog `LogContext` for the run and the host enables `Enrich.FromLogContext()`, +so lines written on the run's own async call chain (script callees) carry the id in the node log. **Still open:** `LogContext` is +an `AsyncLocal` and does not cross an Akka message hop, so Instance Actor / DCL / alarm / S&F lines handled for a run are untagged +(needs the id on the message envelope + a per-message push in each actor), and there is no execution-id column on `site_events` +(replicated table, both-nodes-together schema change) or Flow Debugger query by it; a `Log` sink to the site event log; capturing `Console.Out` on a site run — `System` is imported so `Console.WriteLine` compiles today, and the Test Run sandbox captures it (`SandboxConsoleCapture`), but on a site node `Console.Out` is process-global and shared by every concurrent run, so per-run capture is unsound; `Log.*` is the leveled, per-run replacement and the sandbox mirror writes to the same console pane. diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs b/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs index a3fbf728..6b9d537f 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs @@ -92,6 +92,10 @@ public static class LoggerConfigurationFactory .Enrich.WithProperty("SiteId", siteId) .Enrich.WithProperty("NodeHostname", nodeHostname) .Enrich.WithProperty("NodeRole", nodeRole) + // ScadaBridge#56: surface the ExecutionId/InstanceName/ScriptName the site script + // launcher pushes onto LogContext, so lines written on a run's own call chain carry + // the run's identity. See SiteRuntime ScriptRunLogScope for the (bounded) scope. + .Enrich.FromLogContext() .Enrich.With(new TraceContextEnricher()); } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index fdbbf36a..fc01151f 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -288,6 +288,7 @@ internal static class ScriptRunLauncher var workerSlot = ScriptExecutionScheduler.CurrentWorkerSlot; var workerRunStamp = workerSlot is { } slot ? executionScheduler.CurrentRunStamp(slot) : 0L; + IDisposable? logScope = null; var completed = 0; ArmStuckScriptWatchdog( cts, options, logger, siteEventLogger, executionScheduler, @@ -412,6 +413,9 @@ internal static class ScriptRunLauncher // Script file access (design 2026-09-28): the Files global's host reader. fileReader: fileReader); + // ScadaBridge#56: stamp the run identity on the LogContext for the rest of the run. + logScope = ScriptRunLogScope.Push(context.ExecutionId, instanceName, scriptName); + var globals = new ScriptGlobals { Instance = context, @@ -533,6 +537,7 @@ internal static class ScriptRunLauncher // Mark the body finished so the stuck-script watchdog (registered on // cts.Token above) treats a timely cancellation as NOT stuck. Interlocked.Exchange(ref completed, 1); + logScope?.Dispose(); // Dispose the DI scope (and scoped services) after script execution completes serviceScope?.Dispose(); cts.Dispose(); @@ -709,6 +714,7 @@ internal static class ScriptRunLauncher var workerSlot = ScriptExecutionScheduler.CurrentWorkerSlot; var workerRunStamp = workerSlot is { } slot ? executionScheduler.CurrentRunStamp(slot) : 0L; + IDisposable? logScope = null; var completed = 0; ArmStuckScriptWatchdog( cts, options, logger, siteEventLogger, executionScheduler, @@ -766,6 +772,8 @@ internal static class ScriptRunLauncher // Script file access (design 2026-09-28): the Files global's host reader. fileReader: services?.GetService()); + logScope = ScriptRunLogScope.Push(context.ExecutionId, instanceName, scriptName); + var globals = new ScriptGlobals { Instance = context, @@ -811,6 +819,7 @@ internal static class ScriptRunLauncher // Mark the body finished so the stuck-script watchdog (registered on // cts.Token above) treats a timely cancellation as NOT stuck. Interlocked.Exchange(ref completed, 1); + logScope?.Dispose(); cts.Dispose(); } } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs new file mode 100644 index 00000000..76d6947b --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs @@ -0,0 +1,54 @@ +using Serilog.Context; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// Stamps a script/alarm run's identity onto the Serilog LogContext for the lifetime of the +/// run (ScadaBridge#56), so every log line written on the run's async flow - the script body's own +/// callees (external-system client, database gateway, store-and-forward enqueue, ...) - carries +/// ExecutionId, InstanceName and ScriptName once the host enables +/// Enrich.FromLogContext() (LoggerConfigurationFactory). +/// +/// +/// Bounded by design. LogContext is an AsyncLocal: it follows the run's own +/// call chain but NOT an Akka message hop. A line logged by the Instance Actor, DCL or alarm +/// actors while handling a message sent BY the run runs on that actor's own context and does not +/// carry the id. Closing that needs the id on the message envelope plus a per-message push in each +/// actor, and a queryable sink (an execution-id column on the replicated site_events table); +/// both are recorded as the remaining work on the issue. +/// +internal static class ScriptRunLogScope +{ + /// Property name carrying the run's ExecutionId. + internal const string ExecutionIdProperty = "ExecutionId"; + + /// Property name carrying the instance's unique name. + internal const string InstanceNameProperty = "InstanceName"; + + /// Property name carrying the script (or alarm source) name. + internal const string ScriptNameProperty = "ScriptName"; + + /// Pushes the run identity onto the LogContext; dispose to pop it. + /// The run's execution id. + /// The owning instance's unique name. + /// The script (or alarm source) name. + /// A disposable that removes the three properties again. + internal static IDisposable Push(Guid executionId, string instanceName, string scriptName) + { + var a = LogContext.PushProperty(ExecutionIdProperty, executionId); + var b = LogContext.PushProperty(InstanceNameProperty, instanceName); + var c = LogContext.PushProperty(ScriptNameProperty, scriptName); + return new Scope(a, b, c); + } + + private sealed class Scope(IDisposable a, IDisposable b, IDisposable c) : IDisposable + { + public void Dispose() + { + // Reverse order: LogContext is a stack. + c.Dispose(); + b.Dispose(); + a.Dispose(); + } + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ZB.MOM.WW.ScadaBridge.SiteRuntime.csproj b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ZB.MOM.WW.ScadaBridge.SiteRuntime.csproj index b90ec920..f7d913da 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ZB.MOM.WW.ScadaBridge.SiteRuntime.csproj +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ZB.MOM.WW.ScadaBridge.SiteRuntime.csproj @@ -21,6 +21,7 @@ + diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs index 97cf2ccb..7bca937e 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs @@ -35,6 +35,28 @@ public class LoggerConfigurationTests Assert.Equal(LogEventLevel.Warning, sink.LogEvents[0].Level); } + /// Verifies the logger enriches events from the Serilog LogContext, so a run's pushed ExecutionId reaches the sink (ScadaBridge#56). + [Fact] + public void LogContextProperties_AreEnrichedOntoEvents() + { + var sink = new InMemorySink(); + var logger = LoggerConfigurationFactory + .Build(BuildConfig(null), "Site", "site-a", "node1") + .WriteTo.Sink(sink) + .CreateLogger(); + + var id = Guid.NewGuid(); + using (Serilog.Context.LogContext.PushProperty("ExecutionId", id)) + { + logger.Information("inside"); + } + logger.Information("outside"); + + Assert.Equal(2, sink.LogEvents.Count); + Assert.Equal(id.ToString(), sink.LogEvents[0].Properties["ExecutionId"].ToString().Trim('"')); + Assert.False(sink.LogEvents[1].Properties.ContainsKey("ExecutionId")); + } + /// Verifies that a Debug minimum level allows Debug logs. [Fact] public void MinimumLevel_Debug_AllowsDebugLogs() diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs index b6049843..3aa93b7c 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunLauncherTraceTests.cs @@ -98,6 +98,54 @@ public class ScriptRunLauncherTraceTests : TestKit, IDisposable 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.