From 7f479f3a5c3264e6588f7c8806a167e3b3347535 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 14:20:02 -0500 Subject: [PATCH] feat(logging): stamp ExecutionId/InstanceName/ScriptName on the Serilog LogContext per run (ScadaBridge#56) The site script and alarm on-trigger launchers push the run identity onto LogContext for the run's lifetime and the host now enables Enrich.FromLogContext(), so log lines written on the run's own async call chain carry the id. Bounded part only: LogContext does not cross an Akka message hop, so Instance Actor/DCL/S&F lines and a site_events execution-id column remain open (documented in the step-logs design doc section 9). Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- ...26-09-09-flow-debugger-step-logs-design.md | 8 ++- .../LoggerConfigurationFactory.cs | 4 ++ .../Scripts/ScriptRunLauncher.cs | 9 ++++ .../Scripts/ScriptRunLogScope.cs | 54 +++++++++++++++++++ .../ZB.MOM.WW.ScadaBridge.SiteRuntime.csproj | 1 + .../LoggerConfigurationTests.cs | 22 ++++++++ .../Scripts/ScriptRunLauncherTraceTests.cs | 48 +++++++++++++++++ 7 files changed, 144 insertions(+), 2 deletions(-) create mode 100644 src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs 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.