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 04b8566c..58730765 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 @@ -29,7 +29,7 @@ copy); run-wide `n errors · n warnings · n info` in the status strip. Live and DB helpers already fill it with `ex.ToString()`. `FlowStepProjector.Project` drops `AuditDetails.ErrorDetail`. Centrally, `InboundScriptExecutor.ExecuteAsync` swallows the exception into `"Internal script error"` / `SCRIPT_ERROR` (`InboundScriptExecutor.cs:548-552`) and the runner's inbound row gets that text. -- **No execution-id enrichment on node loggers.** Zero `LogContext.PushProperty` calls; `Enrich.FromLogContext` +- **No execution-id enrichment on node loggers** *(as of 2026-09-09; since closed in part by Gitea #56, see §9)*. Zero `LogContext.PushProperty` calls; `Enrich.FromLogContext` is not configured; the `TraceContextEnricher` stamps W3C ids only. `site_events` has no execution-id column. Capturing what *other* actors log for a run is therefore out of reach without a separate enrichment initiative (§9). @@ -129,12 +129,19 @@ 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) — **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 +**other actors** log for a run (instance actor, DCL) — **enrichment done, capture open (Gitea #56):** the site script/alarm launcher pushes +`ExecutionId`/`InstanceName`/`ScriptName` onto the Serilog `LogContext` for the run, the inbound executor pushes the request's +`ExecutionId` for the method execution, and the host enables `Enrich.FromLogContext()`. Because `LogContext` is an `AsyncLocal` +that does not cross an Akka message hop, the id rides the message instead: `Commons.Observability.IExecutionCorrelated` +(explicit interface member, no wire change) is implemented by `SetStaticAttributeCommand`, `AttributeValueChanged` (not when the +writer is *inferred* by the trace arm), `ScriptCallRequest`, the four `RouteTo*Request`s, and — via a new additive +`SourceExecutionId` — `GetAttributeRequest`, `WaitForAttributeRequest`, `WriteAttributeBatchRequest`, `WriteTagRequest`, +`WriteTagBatchRequest`; the Instance, Script, Alarm, Deployment Manager and both DCL actors re-push it per message in +`AroundReceive` (`ExecutionLogContext.PushFor`; one type test for an uncorrelated message). So a node-log line the Instance +Actor or a protocol adapter writes while serving a run's write carries the run's id. **Still open:** a queryable per-execution +sink — the `site_events` execution-id column (replicated table, both-nodes-together schema change) or a sink that copies tagged +lines of a *traced* execution into `ScriptLog` rows — and a Flow Debugger section that shows them; and the DCL actors' own Akka +`ILoggingAdapter` lines, which bypass Serilog entirely (Gitea #120); 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/docs/requirements/Component-SiteRuntime.md b/docs/requirements/Component-SiteRuntime.md index a82d83d7..f533189b 100644 --- a/docs/requirements/Component-SiteRuntime.md +++ b/docs/requirements/Component-SiteRuntime.md @@ -584,6 +584,7 @@ Available to all script runs and alarm on-trigger runs: - **Runtime lines land on the step that produced them.** While a run is traced, `ScriptRuntimeContext` wraps its own `ILogger` in a `TraceCapturingLogger`, which forwards everything to the inner logger unchanged and additionally copies **Information and above** into `ScriptLog` rows with `logSource = "runtime"` (Debug/Trace are deliberately not captured — internal chatter). `IsEnabled` returns true for Information and above regardless of the node's minimum level, because those entries are trace data rather than node log output. Attribution rides an ambient `TraceStepScope` (`AsyncLocal`): `SetAttribute`, `WriteBatchAndWait`, `WaitInternal` and the synchronous `ExternalSystem.Call` pre-mint their step row's `EventId`, open the scope around their body and pass the id to `EmitTrace`, so a warning the runtime logs inside a write shows on that write's node. Everything else falls back to the run's anchor `ScriptRun` row. **Build `ScriptLogger` over the UNDECORATED logger** — `TraceCapturingLogger`'s constructor rejects an inner `TraceCapturingLogger`, since double wrapping would emit two rows per line. - **Bounded (D7).** `ScadaBridge:SiteRuntime:MaxLogLinesPerRun` (default 200, validated `> 0`) caps the rows one run may emit; messages are clipped at 2 000 characters. Lines past the cap are counted and dropped, and a single closing `warn` / `runtime` row naming the dropped count is flushed at run end (it bypasses the counter — it is the one row that must always land). - **Exception detail.** A failed run's `ScriptRun` row now carries `errorDetail = ex.ToString()` alongside the existing one-line `errorMessage`, so the Flow Debugger can show type, message, stack and inner exception. A timeout emits no detail — an `OperationCanceledException` stack is noise. +- **`ExecutionId` on node-log lines across actor hops (Gitea #56).** The launcher pushes the run's `ExecutionId` / `InstanceName` / `ScriptName` onto the Serilog `LogContext` for the run, and the host enables `Enrich.FromLogContext()`. `LogContext` does not cross an Akka message hop, so every request a run sends carries its id (`SourceExecutionId` / `ParentExecutionId`, exposed as `Commons.Observability.IExecutionCorrelated`) and the Instance, Script, Alarm, Deployment Manager and DCL actors re-push it for that one message in `AroundReceive` — a node-log line the Instance Actor, or a protocol adapter on the write path, writes while serving the run carries the run's id; a message naming no execution costs one type test and carries nothing (the sender's ambient context never leaks in). An `AttributeValueChanged` whose writer was *inferred* by the trace arm is not stamped. Only the id rides — never a value. The DCL actors' own Akka `_log` lines bypass Serilog and are untagged (Gitea #120). This is node-log enrichment only; the Flow Debugger does not yet show these lines (#56 remains open for the per-execution sink). - **`Console.WriteLine` is not the logging surface on a site.** `System` is imported, so it compiles, and the Central UI Test Run sandbox does capture it; but on a site node `Console.Out` is process-global and shared by every concurrent script run, so per-run capture is unsound. `Log.*` is the leveled, per-run replacement, and the sandbox's mirror writes to the same console pane. ### Parameter Access diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagBatchRequest.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagBatchRequest.cs index 8c55f4d2..23148052 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagBatchRequest.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagBatchRequest.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; /// @@ -16,13 +18,21 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; /// Optional device tag path of a flag written AFTER the batch succeeds; null to skip. /// Value to write to (ignored when it is null/empty). /// When the request was issued (UTC). +/// ScadaBridge#56: the execution issuing this request (a site script run), so the +/// actors that serve it stamp the id onto their log lines. Additive and nullable; never serialized as anything +/// but an id. public record WriteTagBatchRequest( string CorrelationId, string ConnectionName, IReadOnlyDictionary Values, // device tagPath -> value string? TriggerTagPath, // optional flag written AFTER the batch object? TriggerValue, - DateTimeOffset Timestamp); + DateTimeOffset Timestamp, + Guid? SourceExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Response for a . is true only diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagRequest.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagRequest.cs index 1d020f11..2053c7e3 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagRequest.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/DataConnection/WriteTagRequest.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; /// @@ -9,7 +11,12 @@ public record WriteTagRequest( string ConnectionName, string TagPath, object? Value, - DateTimeOffset Timestamp); + DateTimeOffset Timestamp, + Guid? SourceExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Response for a device tag write operation. diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/InboundApi/RouteToInstanceRequest.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/InboundApi/RouteToInstanceRequest.cs index 359fc4d6..889c0f19 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/InboundApi/RouteToInstanceRequest.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/InboundApi/RouteToInstanceRequest.cs @@ -1,4 +1,5 @@ using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.InboundApi; @@ -22,7 +23,11 @@ public record RouteToCallRequest( IReadOnlyDictionary? Parameters, DateTimeOffset Timestamp, Guid? ParentExecutionId = null, - bool Trace = false); + bool Trace = false) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment (the inbound request). + Guid? IExecutionCorrelated.CorrelatedExecutionId => ParentExecutionId; +} /// /// Response from a Route.To() call. @@ -57,7 +62,11 @@ public record RouteToGetAttributesRequest( string InstanceUniqueName, IReadOnlyList AttributeNames, DateTimeOffset Timestamp, - Guid? ParentExecutionId = null); + Guid? ParentExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment (the inbound request). + Guid? IExecutionCorrelated.CorrelatedExecutionId => ParentExecutionId; +} /// /// Response containing attribute values from a remote instance. @@ -87,7 +96,11 @@ public record RouteToSetAttributesRequest( IReadOnlyDictionary AttributeValues, DateTimeOffset Timestamp, Guid? ParentExecutionId = null, - bool Trace = false); + bool Trace = false) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment (the inbound request). + Guid? IExecutionCorrelated.CorrelatedExecutionId => ParentExecutionId; +} /// /// Response confirming attribute writes on a remote instance. @@ -128,7 +141,11 @@ public record RouteToWaitForAttributeRequest( TimeSpan Timeout, DateTimeOffset Timestamp, Guid? ParentExecutionId = null, - bool RequireGoodQuality = false); + bool RequireGoodQuality = false) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment (the inbound request). + Guid? IExecutionCorrelated.CorrelatedExecutionId => ParentExecutionId; +} /// /// Response from a remote attribute wait. / diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/GetAttributeRequest.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/GetAttributeRequest.cs index aba0deb8..d7ad83c5 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/GetAttributeRequest.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/GetAttributeRequest.cs @@ -1,14 +1,23 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// /// Request to get the current value of an attribute from an Instance Actor. /// Uses the Ask pattern for system boundaries; Tell pattern is preferred for hot-path. /// +/// SourceExecutionId (ScadaBridge#56): the site script run issuing the read, so the Instance Actor +/// stamps it onto any line it logs while serving it. Additive and nullable. public record GetAttributeRequest( string CorrelationId, string InstanceUniqueName, string AttributeName, - DateTimeOffset Timestamp); + DateTimeOffset Timestamp, + Guid? SourceExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Response containing the current value and quality of an attribute. diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/SetStaticAttributeCommand.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/SetStaticAttributeCommand.cs index c464f3be..1b694d73 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/SetStaticAttributeCommand.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/SetStaticAttributeCommand.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// @@ -27,7 +29,11 @@ public record SetStaticAttributeCommand( string Value, DateTimeOffset Timestamp, Guid? SourceExecutionId = null, - bool Trace = false); + bool Trace = false) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Response confirming that a static attribute was set. diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WaitForAttribute.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WaitForAttribute.cs index 99b29fe9..3412a645 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WaitForAttribute.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WaitForAttribute.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// @@ -37,6 +39,9 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// the match tests the value only). Trailing/defaulted so existing positional /// constructions compile unchanged. /// +/// ScadaBridge#56: the execution issuing this request (a site script run), so the +/// actors that serve it stamp the id onto their log lines. Additive and nullable; never serialized as anything +/// but an id. public record WaitForAttributeRequest( string CorrelationId, string InstanceName, @@ -45,7 +50,12 @@ public record WaitForAttributeRequest( Func? Predicate, TimeSpan Timeout, DateTimeOffset OccurredAtUtc, - bool RequireGoodQuality = false); + bool RequireGoodQuality = false, + Guid? SourceExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Reply to a . Exactly one of diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WriteAttributeBatch.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WriteAttributeBatch.cs index b836246b..ffcd3816 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WriteAttributeBatch.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Instance/WriteAttributeBatch.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// @@ -22,13 +24,21 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; /// Optional canonical attribute name of a flag written AFTER the batch; null to skip. /// Codec-encoded value for . /// When the request was issued (UTC). +/// ScadaBridge#56: the execution issuing this request (a site script run), so the +/// actors that serve it stamp the id onto their log lines. Additive and nullable; never serialized as anything +/// but an id. public record WriteAttributeBatchRequest( string CorrelationId, string InstanceName, IReadOnlyDictionary AttributeEncodedValues, // canonical attr name -> codec-encoded value string? TriggerAttribute, string? TriggerEncodedValue, - DateTimeOffset OccurredAtUtc); + DateTimeOffset OccurredAtUtc, + Guid? SourceExecutionId = null) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment. + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionId; +} /// /// Reply to a . is true only diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/ScriptExecution/ScriptCallRequest.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/ScriptExecution/ScriptCallRequest.cs index 217f1dc3..dc927dda 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/ScriptExecution/ScriptCallRequest.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/ScriptExecution/ScriptCallRequest.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; /// @@ -16,4 +18,8 @@ public record ScriptCallRequest( int CurrentCallDepth, string CorrelationId, Guid? ParentExecutionId = null, - bool Trace = false); + bool Trace = false) : IExecutionCorrelated +{ + /// ScadaBridge#56: the execution this message serves, for log enrichment (the calling run). + Guid? IExecutionCorrelated.CorrelatedExecutionId => ParentExecutionId; +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Streaming/AttributeValueChanged.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Streaming/AttributeValueChanged.cs index 5431f96d..cb4766c8 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Streaming/AttributeValueChanged.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Messages/Streaming/AttributeValueChanged.cs @@ -1,3 +1,5 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + namespace ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming; /// @@ -41,4 +43,12 @@ public record AttributeValueChanged( DateTimeOffset Timestamp, Guid? SourceExecutionId = null, bool Trace = false, - bool SourceExecutionInferred = false) : ISiteStreamEvent; + bool SourceExecutionInferred = false) : ISiteStreamEvent, IExecutionCorrelated +{ + /// + /// ScadaBridge#56: the writing execution, for log enrichment of the actors that handle the change. + /// An INFERRED writer (a device echo matched to a traced write by the trace arm) is a heuristic + /// linkage, so it is not stamped onto log lines. + /// + Guid? IExecutionCorrelated.CorrelatedExecutionId => SourceExecutionInferred ? null : SourceExecutionId; +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs new file mode 100644 index 00000000..7ccbf1e6 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs @@ -0,0 +1,46 @@ +using Serilog.Context; + +namespace ZB.MOM.WW.ScadaBridge.Commons.Observability; + +/// +/// Stamps an execution id onto the Serilog LogContext (ScadaBridge#56), so every line +/// logged inside the scope - through Serilog directly or through a Microsoft +/// ILogger backed by Serilog (UseSerilog) - carries an ExecutionId +/// property once the host enables Enrich.FromLogContext(). +/// +/// +/// Why per message. LogContext is an AsyncLocal: it follows one +/// async call chain but does not cross an Akka message hop (the dispatcher does not flow the +/// sender's execution context into the receiver). An actor that serves an execution therefore +/// re-establishes the id from the message itself, for the duration of that one message: +/// +/// protected override bool AroundReceive(Receive receive, object message) +/// { +/// using (ExecutionLogContext.PushFor(message)) +/// return base.AroundReceive(receive, message); +/// } +/// +/// Continuations the handler starts (ContinueWith, PipeTo, an adapter call) +/// capture the context at creation, so their lines carry the id too. +/// Cost. A message that is not , or names no +/// execution, costs one type test and allocates nothing. +/// Nesting. A later push of the same property wins, so a child run started while +/// serving its parent's message logs under its OWN id (the launcher pushes it). +/// +public static class ExecutionLogContext +{ + /// The log-event property carrying the execution id. + public const string ExecutionIdProperty = "ExecutionId"; + + /// Pushes as . + /// The execution id; null pushes nothing. + /// A disposable that pops the property, or null when nothing was pushed. + public static IDisposable? Push(Guid? executionId) + => executionId is { } id ? LogContext.PushProperty(ExecutionIdProperty, id) : null; + + /// Pushes the execution a message serves, when it names one. + /// Any actor message. + /// A disposable that pops the property, or null when the message names no execution. + public static IDisposable? PushFor(object? message) + => message is IExecutionCorrelated correlated ? Push(correlated.CorrelatedExecutionId) : null; +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/IExecutionCorrelated.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/IExecutionCorrelated.cs new file mode 100644 index 00000000..dcdc3942 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/IExecutionCorrelated.cs @@ -0,0 +1,17 @@ +namespace ZB.MOM.WW.ScadaBridge.Commons.Observability; + +/// +/// A message sent on behalf of one execution (a site script/alarm run, or an inbound API +/// method request) that names that execution, so the actor handling it can stamp the id onto +/// its log lines (ScadaBridge#56). See . +/// +/// +/// Implemented explicitly on the message records, mapped onto the field the record already +/// carries (SourceExecutionId / ParentExecutionId), so it adds no serialized +/// member and no wire change. Only an identifier ever rides here — never a value or a secret. +/// +public interface IExecutionCorrelated +{ + /// The execution this message serves, or null when it serves none. + Guid? CorrelatedExecutionId { get; } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/ZB.MOM.WW.ScadaBridge.Commons.csproj b/src/ZB.MOM.WW.ScadaBridge.Commons/ZB.MOM.WW.ScadaBridge.Commons.csproj index 55b3ee87..21ccb36a 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/ZB.MOM.WW.ScadaBridge.Commons.csproj +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/ZB.MOM.WW.ScadaBridge.Commons.csproj @@ -8,6 +8,7 @@ + diff --git a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs index 215f96ef..eee411a7 100644 --- a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs @@ -328,6 +328,26 @@ public class DataConnectionActor : UntypedActor, IWithTimers _tagResolutionInterval = _options.TagResolutionRetryInterval; } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// + /// Enrichment reaches lines written through a Serilog-backed ILogger - here, the protocol + /// adapter's own logging on the write path, whose WriteAsync starts inside this scope. This + /// actor's own Akka _log lines go through Akka's logger, not Serilog, and are not enriched. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + /// protected override void PreStart() { diff --git a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs index db8008bf..f8b34de9 100644 --- a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs @@ -233,6 +233,26 @@ public class DataConnectionManagerActor : ReceiveActor _log.Warning("No connection actor for {0} during alarm unsubscribe", request.ConnectionName); } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// + /// Enrichment reaches lines written through a Serilog-backed ILogger - here, the protocol + /// adapter's own logging on the write path, whose WriteAsync starts inside this scope. This + /// actor's own Akka _log lines go through Akka's logger, not Serilog, and are not enriched. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + private void HandleRouteWrite(WriteTagRequest request) { if (_connectionActors.TryGetValue(request.ConnectionName, out var actor)) diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs index d5f500ee..a294f53e 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs @@ -442,6 +442,11 @@ public class InboundScriptExecutor using var cts = CancellationTokenSource.CreateLinkedTokenSource( cancellationToken, timeoutCts.Token); + // ScadaBridge#56: every line logged on this request's async flow (the executor, the + // Database helper, route/communication callees) carries the request's ExecutionId; the + // site actors that serve a routed call re-stamp it from RouteTo*Request.ParentExecutionId. + using var executionLogScope = ExecutionLogContext.Push(parentExecutionId); + // IpsenMES MoveIn: expose the scoped, parameterized Database helper to the script // (reads + writes). Resolve the gateway from a fresh DI scope // (declared outside the try so it lives until after the script handler runs and is diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs index 9a5f8303..360e4125 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Microsoft.CodeAnalysis.Scripting; @@ -262,6 +263,21 @@ public class AlarmActor : ReceiveActor Receive(HandleExpressionEvalFailed); } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + /// protected override void PreStart() { diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/DeploymentManagerActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/DeploymentManagerActor.cs index ba87d8a8..ca1fe5ed 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/DeploymentManagerActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/DeploymentManagerActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Akka.Cluster; @@ -571,6 +572,21 @@ public class DeploymentManagerActor : ReceiveActor, IWithTimers }); } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + /// protected override void PreStart() { @@ -3509,7 +3525,9 @@ public class DeploymentManagerActor : ReceiveActor, IWithTimers var inner = new WaitForAttributeRequest( request.CorrelationId, request.InstanceUniqueName, request.AttributeName, request.TargetValueEncoded, null, request.Timeout, DateTimeOffset.UtcNow, - request.RequireGoodQuality); + request.RequireGoodQuality, + // ScadaBridge#56: the Instance Actor logs under the inbound request's id. + SourceExecutionId: request.ParentExecutionId); // Ask bounded by the WAIT timeout + slack — NOT a fixed 30s (the wait legitimately blocks up to request.Timeout). instanceActor.Ask(inner, request.Timeout + TimeSpan.FromSeconds(5)) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/InstanceActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/InstanceActor.cs index 21de043f..9b554c6e 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/InstanceActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/InstanceActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Microsoft.CodeAnalysis.Scripting; @@ -450,6 +451,21 @@ public class InstanceActor : ReceiveActor Receive(_ => FlushDirtyStaticOverrides()); } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + /// protected override void PreStart() { @@ -608,7 +624,11 @@ public class InstanceActor : ReceiveActor var caller = Sender; var outcomes = new Task[request.Writes.Count]; for (var i = 0; i < outcomes.Length; i++) - outcomes[i] = ApplySetAttribute(request.Writes[i]); + { + // ScadaBridge#56: the batch envelope names no execution; each write names its own. + using (ExecutionLogContext.PushFor(request.Writes[i])) + outcomes[i] = ApplySetAttribute(request.Writes[i]); + } if (outcomes.All(t => t.IsCompleted)) { @@ -897,7 +917,9 @@ public class InstanceActor : ReceiveActor resolved.Attribute.BoundDataConnectionName!, resolved.Attribute.DataSourceReference!, writeValue, - DateTimeOffset.UtcNow); + DateTimeOffset.UtcNow, + // ScadaBridge#56: the DCL (and its adapter) log under the writing execution's id. + SourceExecutionId: command.SourceExecutionId); // Flow Debugger trace arm (design §5.3): only a TRACED write with a known writer arms; // the next device update is marked as inferred in HandleTagValueUpdate. Untraced writes @@ -1036,7 +1058,9 @@ public class InstanceActor : ReceiveActor } var dclReq = new WriteTagBatchRequest( - cid, connName!, values, triggerPath, triggerVal, DateTimeOffset.UtcNow); + cid, connName!, values, triggerPath, triggerVal, DateTimeOffset.UtcNow, + // ScadaBridge#56: the DCL (and its adapter) log under the writing execution's id. + SourceExecutionId: request.SourceExecutionId); // Ask the DCL and pipe the batch outcome back to the original caller. The DCL // bounds its own write with WriteTimeout; this Ask is bounded a bit longer so a diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs index c46b271d..86c5b664 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Microsoft.CodeAnalysis.Scripting; @@ -228,6 +229,21 @@ public class ScriptActor : ReceiveActor, IWithTimers Receive(HandleExpressionEvalFailed); } + /// + /// ScadaBridge#56: while handling a message sent on behalf of an execution + /// (), every line this actor logs - and every line logged by + /// a continuation it starts - carries that execution's ExecutionId. A message that names + /// no execution costs one type test. + /// + /// The behaviour that handles the message. + /// The message. + /// Whether the message was handled. + protected override bool AroundReceive(Receive receive, object message) + { + using (ExecutionLogContext.PushFor(message)) + return base.AroundReceive(receive, message); + } + /// protected override void PreStart() { diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs index 76d6947b..9dff54e4 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.Commons.Observability; using Serilog.Context; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; @@ -10,17 +11,15 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; /// 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. +/// LogContext is an AsyncLocal: it follows the run's own call chain but NOT an Akka +/// message hop. The messages the run sends carry its id instead () +/// and the Instance, Script, Alarm, Deployment Manager and DCL actors re-push it per message +/// (). /// internal static class ScriptRunLogScope { /// Property name carrying the run's ExecutionId. - internal const string ExecutionIdProperty = "ExecutionId"; + internal const string ExecutionIdProperty = ExecutionLogContext.ExecutionIdProperty; /// Property name carrying the instance's unique name. internal const string InstanceNameProperty = "InstanceName"; diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs index d49ac577..b72412bc 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -719,7 +719,9 @@ public class ScriptRuntimeContext { var correlationId = Guid.NewGuid().ToString(); var request = new GetAttributeRequest( - correlationId, _instanceName, attributeName, DateTimeOffset.UtcNow); + correlationId, _instanceName, attributeName, DateTimeOffset.UtcNow, + // ScadaBridge#56: the Instance Actor logs under this run's id while serving it. + SourceExecutionId: _executionId); var response = await _instanceActor.Ask(request, _askTimeout).ConfigureAwait(false); @@ -823,7 +825,9 @@ public class ScriptRuntimeContext var cid = Guid.NewGuid().ToString(); var req = new WaitForAttributeRequest( cid, _instanceName, name, targetValueEncoded, predicate, timeout, DateTimeOffset.UtcNow, - requireGoodQuality); + requireGoodQuality, + // ScadaBridge#56: the Instance Actor logs under this run's id while serving it. + SourceExecutionId: _executionId); var startedUtc = DateTime.UtcNow; var sw = _isTraced ? Stopwatch.StartNew() : null; @@ -1126,7 +1130,9 @@ public class ScriptRuntimeContext { var cid = Guid.NewGuid().ToString(); var batchReq = new WriteAttributeBatchRequest( - cid, _instanceName, encodedValues, triggerAttr, triggerEncoded, DateTimeOffset.UtcNow); + cid, _instanceName, encodedValues, triggerAttr, triggerEncoded, DateTimeOffset.UtcNow, + // ScadaBridge#56: rides on to the DCL batch write so both actors log under this run's id. + SourceExecutionId: _executionId); // 35s: the InstanceActor's DCL Ask is internally bounded at 30s, so allow a small // margin so the DCL's own typed failure/timeout reply is the one we observe rather diff --git a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs new file mode 100644 index 00000000..b04e37c9 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs @@ -0,0 +1,105 @@ +using System.Collections.Concurrent; +using Newtonsoft.Json; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.InboundApi; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + +namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Observability; + +/// +/// ScadaBridge#56: which messages name the execution they serve, and what pushing one does to a +/// LogContext-enriched logger. +/// +public class ExecutionLogContextTests +{ + private static readonly DateTimeOffset Now = DateTimeOffset.UtcNow; + private static readonly Guid Id = Guid.NewGuid(); + + private sealed class CaptureSink : ILogEventSink + { + public ConcurrentQueue Events { get; } = new(); + public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent); + } + + /// Every correlated message, built with on its execution field. + /// The messages. + public static TheoryData CorrelatedMessages() => new() + { + new SetStaticAttributeCommand("c", "i", "a", "v", Now, SourceExecutionId: Id), + new AttributeValueChanged("i", "p", "a", 1, "Good", Now, SourceExecutionId: Id), + new ScriptCallRequest("s", null, 0, "c", ParentExecutionId: Id), + new RouteToCallRequest("c", "i", "s", null, Now, ParentExecutionId: Id), + new RouteToGetAttributesRequest("c", "i", ["a"], Now, ParentExecutionId: Id), + new RouteToSetAttributesRequest("c", "i", new Dictionary(), Now, ParentExecutionId: Id), + new RouteToWaitForAttributeRequest("c", "i", "a", null, TimeSpan.FromSeconds(1), Now, ParentExecutionId: Id), + new GetAttributeRequest("c", "i", "a", Now, SourceExecutionId: Id), + new WaitForAttributeRequest("c", "i", "a", null, null, TimeSpan.FromSeconds(1), Now, SourceExecutionId: Id), + new WriteAttributeBatchRequest("c", "i", new Dictionary(), null, null, Now, SourceExecutionId: Id), + new WriteTagRequest("c", "conn", "tag", 1, Now, SourceExecutionId: Id), + new WriteTagBatchRequest("c", "conn", new Dictionary(), null, null, Now, SourceExecutionId: Id), + }; + + /// Each correlated message reports the execution id it was built with. + /// The message. + [Theory] + [MemberData(nameof(CorrelatedMessages))] + public void CorrelatedMessage_ReportsItsExecutionId(object message) + => Assert.Equal(Id, Assert.IsAssignableFrom(message).CorrelatedExecutionId); + + /// + /// The correlation member is an explicit interface implementation: it adds nothing to the + /// serialized shape, so the wire is unchanged. + /// + /// The message. + [Theory] + [MemberData(nameof(CorrelatedMessages))] + public void CorrelatedMessage_SerializesNoExtraMember(object message) + => Assert.DoesNotContain(nameof(IExecutionCorrelated.CorrelatedExecutionId), JsonConvert.SerializeObject(message)); + + /// An inferred writer (the trace arm's device-echo heuristic) is not stamped onto log lines. + [Fact] + public void InferredValueChange_NamesNoExecution() + { + IExecutionCorrelated inferred = new AttributeValueChanged( + "i", "p", "a", 1, "Good", Now, SourceExecutionId: Id, Trace: true, SourceExecutionInferred: true); + Assert.Null(inferred.CorrelatedExecutionId); + } + + /// A message that names no execution - or is not correlated at all - pushes nothing. + [Fact] + public void PushFor_NothingToStamp_ReturnsNull() + { + Assert.Null(ExecutionLogContext.PushFor(new WriteTagRequest("c", "conn", "tag", 1, Now))); + Assert.Null(ExecutionLogContext.PushFor("not a message")); + Assert.Null(ExecutionLogContext.PushFor(null)); + Assert.Null(ExecutionLogContext.Push(null)); + } + + /// Lines inside the scope carry the id, lines after it do not, and a nested push wins. + [Fact] + public void PushFor_StampsLinesInsideTheScope_AndTheInnermostWins() + { + var sink = new CaptureSink(); + var log = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(sink).CreateLogger(); + var child = Guid.NewGuid(); + + using (ExecutionLogContext.PushFor(new ScriptCallRequest("s", null, 0, "c", ParentExecutionId: Id))) + { + log.Information("parent"); + using (ExecutionLogContext.Push(child)) + log.Information("child"); + } + log.Information("outside"); + + var events = sink.Events.ToList(); + Assert.Equal(Id.ToString(), events[0].Properties[ExecutionLogContext.ExecutionIdProperty].ToString().Trim('"')); + Assert.Equal(child.ToString(), events[1].Properties[ExecutionLogContext.ExecutionIdProperty].ToString().Trim('"')); + Assert.False(events[2].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty)); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionLogEnrichmentTests.cs b/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionLogEnrichmentTests.cs new file mode 100644 index 00000000..bb266eb7 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionLogEnrichmentTests.cs @@ -0,0 +1,122 @@ +using System.Collections.Concurrent; +using Akka.Actor; +using Akka.TestKit.Xunit2; +using NSubstitute; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Protocol; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors; +using ZB.MOM.WW.ScadaBridge.HealthMonitoring; + +namespace ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests.Actors; + +/// +/// ScadaBridge#56: a device write the DCL performs for an execution runs the protocol adapter +/// inside that execution's log scope, so whatever the adapter logs while writing carries the +/// execution's id - though the write crossed two actor hops (script, Instance Actor, DCL). +/// +public class ExecutionLogEnrichmentTests : TestKit +{ + private sealed class CaptureSink : ILogEventSink + { + public ConcurrentQueue Events { get; } = new(); + public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent); + } + + private readonly CaptureSink _sink = new(); + private readonly Serilog.ILogger _adapterLog; + private readonly IDataConnection _adapter = Substitute.For(); + + /// Creates the adapter double; its writes log through a LogContext-enriched Serilog logger. + public ExecutionLogEnrichmentTests() + { + _adapterLog = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(_sink).CreateLogger(); + _adapter.ConnectAsync(Arg.Any>(), Arg.Any()) + .Returns(Task.CompletedTask); + _adapter.WriteAsync(Arg.Any(), Arg.Any(), Arg.Any()) + .Returns(ci => + { + _adapterLog.Information("adapter wrote {Tag}", ci.ArgAt(0)); + return Task.FromResult(new WriteResult(true, null)); + }); + _adapter.WriteBatchAsync(Arg.Any>(), Arg.Any()) + .Returns(ci => + { + _adapterLog.Information("adapter batch-wrote"); + return Task.FromResult>( + ci.ArgAt>(0).ToDictionary(kv => kv.Key, _ => new WriteResult(true, null))); + }); + } + + private async Task ConnectedActor(string name) + { + var options = new DataConnectionOptions + { + ReconnectInterval = TimeSpan.FromMilliseconds(100), + WriteTimeout = TimeSpan.FromSeconds(5), + SeedReadMaxAttempts = 1, + SeedReadRetryDelay = TimeSpan.FromMilliseconds(10), + }; + var actor = Sys.ActorOf(Props.Create(() => new DataConnectionActor( + name, _adapter, options, Substitute.For(), + Substitute.For(), "OpcUa")), name); + AwaitCondition(() => _adapter.ReceivedCalls().Any(c => c.GetMethodInfo().Name == "ConnectAsync"), + TimeSpan.FromSeconds(3)); + await Task.Delay(200); + return actor; + } + + private Guid? ExecutionIdOf(string fragment) + { + var evt = _sink.Events.First(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal)); + return evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var v) + ? Guid.Parse(v.ToString().Trim('"')) + : null; + } + + /// The adapter's line for a single write carries the execution id the request names. + /// A task that represents the asynchronous operation. + [Fact] + public async Task SingleWrite_AdapterLinesCarryTheExecutionId() + { + var actor = await ConnectedActor("enrich-single"); + var executionId = Guid.NewGuid(); + + actor.Tell(new WriteTagRequest("c1", "enrich-single", "tagA", 1, DateTimeOffset.UtcNow, executionId)); + Assert.True(ExpectMsg(TimeSpan.FromSeconds(5)).Success); + + Assert.Equal(executionId, ExecutionIdOf("tagA")); + } + + /// The adapter's line for a batch write carries the execution id the request names. + /// A task that represents the asynchronous operation. + [Fact] + public async Task BatchWrite_AdapterLinesCarryTheExecutionId() + { + var actor = await ConnectedActor("enrich-batch"); + var executionId = Guid.NewGuid(); + + actor.Tell(new WriteTagBatchRequest("c1", "enrich-batch", + new Dictionary { ["tagB"] = 2 }, null, null, DateTimeOffset.UtcNow, executionId)); + Assert.True(ExpectMsg(TimeSpan.FromSeconds(5)).Success); + + Assert.Equal(executionId, ExecutionIdOf("batch-wrote")); + } + + /// A write that names no execution logs untagged (control for the two tests above). + /// A task that represents the asynchronous operation. + [Fact] + public async Task UncorrelatedWrite_AdapterLinesAreUntagged() + { + var actor = await ConnectedActor("enrich-none"); + + actor.Tell(new WriteTagRequest("c1", "enrich-none", "tagC", 1, DateTimeOffset.UtcNow)); + Assert.True(ExpectMsg(TimeSpan.FromSeconds(5)).Success); + + Assert.Null(ExecutionIdOf("tagC")); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundScriptExecutorLogContextTests.cs b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundScriptExecutorLogContextTests.cs new file mode 100644 index 00000000..e79dd563 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundScriptExecutorLogContextTests.cs @@ -0,0 +1,79 @@ +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging.Abstractions; +using NSubstitute; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.Commons.Entities.InboundApi; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + +namespace ZB.MOM.WW.ScadaBridge.InboundAPI.Tests; + +/// +/// ScadaBridge#56: an inbound API method request stamps its ExecutionId on the Serilog +/// LogContext for the whole execution, so a line logged anywhere on the request's async flow +/// (the method script's callees - route, database, communication) carries it. +/// +public class InboundScriptExecutorLogContextTests +{ + private sealed class CaptureSink : ILogEventSink + { + public ConcurrentQueue Events { get; } = new(); + public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent); + } + + private readonly CaptureSink _sink = new(); + private readonly Serilog.ILogger _log; + private readonly InboundScriptExecutor _executor = + new(NullLogger.Instance, Substitute.For()); + private readonly RouteHelper _route = new(Substitute.For(), Substitute.For()); + private readonly ApiMethod _method = new("logs", "x") { Id = 1, TimeoutSeconds = 10 }; + + /// Registers a handler that logs one line from inside the method execution. + public InboundScriptExecutorLogContextTests() + { + _log = new LoggerConfiguration().Enrich.FromLogContext().WriteTo.Sink(_sink).CreateLogger(); + _executor.RegisterHandler("logs", async _ => + { + await Task.Yield(); // the line is written after an await, on a continuation + _log.Information("inside the method"); + return null; + }); + } + + private static Guid? ExecutionIdOf(LogEvent evt) + => evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var v) + ? Guid.Parse(v.ToString().Trim('"')) + : null; + + /// A line written during the execution carries the request's id; one written after does not. + /// A task that represents the asynchronous operation. + [Fact] + public async Task LinesDuringTheExecution_CarryTheRequestsExecutionId() + { + var executionId = Guid.NewGuid(); + + var result = await _executor.ExecuteAsync(_method, new Dictionary(), _route, + TimeSpan.FromSeconds(10), parentExecutionId: executionId); + _log.Information("after the method"); + + Assert.True(result.Success, result.ErrorMessage); + var events = _sink.Events.ToList(); + Assert.Equal(2, events.Count); + Assert.Equal(executionId, ExecutionIdOf(events[0])); + Assert.Null(ExecutionIdOf(events[1])); + } + + /// A request with no execution id (outside the inbound flow) logs untagged. + /// A task that represents the asynchronous operation. + [Fact] + public async Task NoExecutionId_LinesAreUntagged() + { + var result = await _executor.ExecuteAsync(_method, new Dictionary(), _route, + TimeSpan.FromSeconds(10)); + + Assert.True(result.Success, result.ErrorMessage); + Assert.Null(ExecutionIdOf(Assert.Single(_sink.Events))); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/ExecutionLogEnrichmentTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/ExecutionLogEnrichmentTests.cs new file mode 100644 index 00000000..8dfaa4b3 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/ExecutionLogEnrichmentTests.cs @@ -0,0 +1,228 @@ +using System.Reflection; +using System.Text.Json; +using Akka.Actor; +using Akka.TestKit.Xunit2; +using Microsoft.Extensions.Logging.Abstractions; +using Serilog.Context; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Flattening; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Messages; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Persistence; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; +using ZB.MOM.WW.ScadaBridge.TestSupport; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Logging; + +/// +/// ScadaBridge#56: a log line the Instance Actor (or any other actor serving an execution) writes +/// while handling a message sent on behalf of that execution carries the execution's id, although +/// LogContext itself never crosses the message hop - the id rides the message and the actor +/// re-pushes it per message. +/// +public class ExecutionLogEnrichmentTests : TestKit, IDisposable +{ + private const string InstanceName = "Enrich1"; + private const string NoDclLine = "cannot be routed"; + + private readonly SiteStorageService _storage; + private readonly ScriptCompilationService _compilationService; + private readonly SharedScriptLibrary _sharedScriptLibrary; + private readonly TestLocalDb _localDb; + + /// Creates a temporary LocalDb-backed site store per test. + public ExecutionLogEnrichmentTests() + { + _localDb = TestLocalDb.CreateTemp("execution-log-enrichment"); + _storage = new SiteStorageService(_localDb.Db, NullLogger.Instance); + _storage.InitializeAsync().GetAwaiter().GetResult(); + _compilationService = new ScriptCompilationService(NullLogger.Instance); + _sharedScriptLibrary = new SharedScriptLibrary( + _compilationService, NullLogger.Instance); + } + + /// + void IDisposable.Dispose() + { + Shutdown(); + var path = _localDb.Path; + _localDb.Dispose(); + TestLocalDb.DeleteFiles(path); + } + + private IActorRef StartInstance(Microsoft.Extensions.Logging.ILogger logger, IActorRef? dcl = null) + { + var config = new FlattenedConfiguration + { + InstanceUniqueName = InstanceName, + Attributes = + [ + new ResolvedAttribute + { + CanonicalName = "Speed", Value = "0", DataType = "Int32", + DataSourceReference = "ns=2;s=Speed", BoundDataConnectionName = "conn-1" + }, + new ResolvedAttribute + { + CanonicalName = "Trigger", Value = "0", DataType = "Int32", + DataSourceReference = "ns=2;s=Trigger", BoundDataConnectionName = "conn-1" + } + ] + }; + var json = JsonSerializer.Serialize(config); + return ActorOf(Props.Create(() => new InstanceActor( + InstanceName, json, _storage, _compilationService, _sharedScriptLibrary, null, + new SiteRuntimeOptions(), logger, dcl))); + } + + /// + /// A data-sourced write with no DCL logs a warning while the Instance Actor serves it; that + /// line carries the writing execution's id. + /// + [Fact] + public void InstanceActor_LineLoggedWhileServingAnExecution_CarriesItsExecutionId() + { + var capture = new LogContextCapture(); + var instance = StartInstance(capture); + var executionId = Guid.NewGuid(); + + instance.Tell(new SetStaticAttributeCommand( + "c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: executionId)); + Assert.False(ExpectMsg(TimeSpan.FromSeconds(10)).Success); + + Assert.Equal(executionId, capture.ExecutionIdOf(NoDclLine)); + } + + /// + /// The id comes from the MESSAGE, never from the sender's ambient context: a message that names + /// no execution produces an untagged line even when the sending thread had one pushed. (The + /// positive control is the test above - same command, same line, id on the message.) + /// + [Fact] + public void InstanceActor_UncorrelatedMessage_DoesNotInheritTheSendersLogContext() + { + var capture = new LogContextCapture(); + var instance = StartInstance(capture); + + using (LogContext.PushProperty(ExecutionLogContext.ExecutionIdProperty, Guid.NewGuid())) + { + instance.Tell(new SetStaticAttributeCommand("c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow)); + } + ExpectMsg(TimeSpan.FromSeconds(10)); + + Assert.True(capture.Has(NoDclLine)); + Assert.Null(capture.ExecutionIdOf(NoDclLine)); + } + + /// The scope is popped after the message: the next uncorrelated message logs untagged. + [Fact] + public void InstanceActor_ExecutionScopeEndsWithTheMessage() + { + var capture = new LogContextCapture(); + var instance = StartInstance(capture); + + instance.Tell(new SetStaticAttributeCommand( + "first", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: Guid.NewGuid())); + ExpectMsg(TimeSpan.FromSeconds(10)); + instance.Tell(new SetStaticAttributeCommand("second", InstanceName, "Trigger", "1", DateTimeOffset.UtcNow)); + ExpectMsg(TimeSpan.FromSeconds(10)); + + var lines = capture.Events.Where(e => e.RenderMessage().Contains(NoDclLine, StringComparison.Ordinal)).ToList(); + Assert.Equal(2, lines.Count); + Assert.True(lines[0].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty)); + Assert.False(lines[1].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty)); + } + + /// + /// A routed SetAttributes arrives as one that names no + /// execution; each write inside it does, and its line carries that write's id. + /// + [Fact] + public void InstanceActor_BatchedWrites_LogUnderEachWritesExecution() + { + var capture = new LogContextCapture(); + var instance = StartInstance(capture); + var executionId = Guid.NewGuid(); + + instance.Tell(new InstanceSetAttributesRequest("c1", + [ + new SetStaticAttributeCommand("w1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, + SourceExecutionId: executionId), + ])); + ExpectMsg(TimeSpan.FromSeconds(10)); + + Assert.Equal(executionId, capture.ExecutionIdOf(NoDclLine)); + } + + /// A script run stamps its own id on every request it sends the Instance Actor. + /// A task that represents the asynchronous operation. + [Fact] + public async Task ScriptRuntimeContext_StampsItsExecutionIdOnInstanceRequests() + { + var probe = CreateTestProbe(); + var executionId = Guid.NewGuid(); + var ctx = new ScriptRuntimeContext( + probe.Ref, _sharedScriptLibrary, + currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5), + instanceName: InstanceName, logger: NullLogger.Instance, + executionId: executionId); + + var read = ctx.GetAttribute("Speed"); + var get = probe.ExpectMsg(TimeSpan.FromSeconds(5)); + Assert.Equal(executionId, get.SourceExecutionId); + probe.Reply(new GetAttributeResponse(get.CorrelationId, InstanceName, "Speed", 1, true, "Good", DateTimeOffset.UtcNow)); + await read; + + var call = ctx.WriteBatchAndWait( + new Dictionary { ["Speed"] = "7" }, "Trigger", "1", "Ack", "1", TimeSpan.FromSeconds(3)); + var batch = probe.ExpectMsg(TimeSpan.FromSeconds(5)); + Assert.Equal(executionId, batch.SourceExecutionId); + probe.Reply(new WriteAttributeBatchResponse(batch.CorrelationId, true, null)); + var wait = probe.ExpectMsg(TimeSpan.FromSeconds(5)); + Assert.Equal(executionId, wait.SourceExecutionId); + probe.Reply(new WaitForAttributeResponse(wait.CorrelationId, Matched: true, "1", "Good", TimedOut: false)); + Assert.True(await call); + } + + /// The Instance Actor hands the writing execution's id on to the DCL, single and batch writes alike. + [Fact] + public void InstanceActor_ForwardsTheExecutionIdOnDclWrites() + { + var dcl = CreateTestProbe(); + var instance = StartInstance(NullLogger.Instance, dcl.Ref); + dcl.ExpectMsg(TimeSpan.FromSeconds(10)); + var single = Guid.NewGuid(); + var batch = Guid.NewGuid(); + + instance.Tell(new SetStaticAttributeCommand( + "c1", InstanceName, "Speed", "5", DateTimeOffset.UtcNow, SourceExecutionId: single)); + Assert.Equal(single, dcl.ExpectMsg(TimeSpan.FromSeconds(10)).SourceExecutionId); + + instance.Tell(new WriteAttributeBatchRequest( + "c2", InstanceName, new Dictionary { ["Speed"] = "7" }, "Trigger", "1", + DateTimeOffset.UtcNow, SourceExecutionId: batch)); + Assert.Equal(batch, dcl.ExpectMsg(TimeSpan.FromSeconds(10)).SourceExecutionId); + } + + /// + /// Every site actor that serves executions re-pushes the id per message. A behavioural test + /// covers the Instance Actor (above) and the DCL connection actor (DCL tests); this pins the + /// hook on the rest so a refactor that drops it is caught. + /// + /// The actor type. + [Theory] + [InlineData(typeof(InstanceActor))] + [InlineData(typeof(ScriptActor))] + [InlineData(typeof(AlarmActor))] + [InlineData(typeof(DeploymentManagerActor))] + [InlineData(typeof(ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionManagerActor))] + [InlineData(typeof(ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionActor))] + public void ExecutionServingActors_OverrideAroundReceive(Type actorType) + { + var method = actorType.GetMethod( + "AroundReceive", BindingFlags.Instance | BindingFlags.NonPublic | BindingFlags.DeclaredOnly); + Assert.NotNull(method); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/LogContextCapture.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/LogContextCapture.cs new file mode 100644 index 00000000..5c4492d6 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/LogContextCapture.cs @@ -0,0 +1,57 @@ +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ILogger = Microsoft.Extensions.Logging.ILogger; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Logging; + +/// +/// A Microsoft that writes each call straight to a Serilog logger enriched +/// from LogContext - the shape the host gets from UseSerilog - and keeps the events, +/// so a test can read the ExecutionId a line carried at the moment it was logged. +/// +internal sealed class LogContextCapture : ILogger, ILogEventSink +{ + private readonly Serilog.ILogger _serilog; + + /// Creates the capture with its own Serilog pipeline. + public LogContextCapture() + => _serilog = new LoggerConfiguration().MinimumLevel.Verbose() + .Enrich.FromLogContext().WriteTo.Sink(this).CreateLogger(); + + /// Every event logged so far. + public ConcurrentQueue Events { get; } = new(); + + /// The ExecutionId the first line containing carried (null when none). + /// Text the rendered message contains. + /// The id, or null when the line carried none. + public Guid? ExecutionIdOf(string fragment) + { + var evt = Events.First(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal)); + return evt.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var value) + ? Guid.Parse(value.ToString().Trim('"')) + : null; + } + + /// Whether a line containing was logged. + /// Text the rendered message contains. + /// True once such a line exists. + public bool Has(string fragment) => Events.Any(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal)); + + /// + public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent); + + /// + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + /// + public bool IsEnabled(LogLevel logLevel) => true; + + /// + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + => _serilog.Write(LogEventLevel.Information, exception, "{Line}", formatter(state, exception)); +}