From edd0ca672ffa2b4ea39563510434c6e5b0ce95e1 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 10 Nov 2026 05:28:20 -0500 Subject: [PATCH] feat(logging): carry ExecutionId across actor hops onto other actors' log lines (ScadaBridge#56) LogContext is an AsyncLocal and does not cross an Akka message hop, so the run's id now rides the message: Commons.Observability.IExecutionCorrelated (explicit interface member, no wire change) on SetStaticAttributeCommand, AttributeValueChanged (not for an inferred writer), ScriptCallRequest and the four RouteTo*Requests, plus a new additive SourceExecutionId on GetAttributeRequest, WaitForAttributeRequest, WriteAttributeBatchRequest, WriteTagRequest and WriteTagBatchRequest. ScriptRuntimeContext stamps its id on the requests it sends, the Instance Actor hands it on to the DCL, and the Instance, Script, Alarm, Deployment Manager and both DCL actors re-push it per message in AroundReceive (ExecutionLogContext.PushFor: one type test when the message names no execution). The inbound executor pushes the request's ExecutionId for the method execution. Tests (TestKit): Instance Actor line carries the message's id, no leak from the sender's ambient context, scope ends with the message, per-write ids inside a batched SetAttributes, ids forwarded on DCL writes, ScriptRuntimeContext stamps; DCL adapter lines on single/batch writes carry the id; inbound executor lines carry the request id; Commons mapping + no serialized member. Each mutation- proved. Still open on #56: a queryable per-execution sink and a Flow Debugger section. The DCL actors' own Akka _log lines bypass Serilog (filed #120). Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- ...26-09-09-flow-debugger-step-logs-design.md | 21 +- docs/requirements/Component-SiteRuntime.md | 1 + .../DataConnection/WriteTagBatchRequest.cs | 12 +- .../DataConnection/WriteTagRequest.cs | 9 +- .../InboundApi/RouteToInstanceRequest.cs | 25 +- .../Messages/Instance/GetAttributeRequest.cs | 11 +- .../Instance/SetStaticAttributeCommand.cs | 8 +- .../Messages/Instance/WaitForAttribute.cs | 12 +- .../Messages/Instance/WriteAttributeBatch.cs | 12 +- .../ScriptExecution/ScriptCallRequest.cs | 8 +- .../Streaming/AttributeValueChanged.cs | 12 +- .../Observability/ExecutionLogContext.cs | 46 ++++ .../Observability/IExecutionCorrelated.cs | 17 ++ .../ZB.MOM.WW.ScadaBridge.Commons.csproj | 1 + .../Actors/DataConnectionActor.cs | 20 ++ .../Actors/DataConnectionManagerActor.cs | 20 ++ .../InboundScriptExecutor.cs | 5 + .../Actors/AlarmActor.cs | 16 ++ .../Actors/DeploymentManagerActor.cs | 20 +- .../Actors/InstanceActor.cs | 30 ++- .../Actors/ScriptActor.cs | 16 ++ .../Scripts/ScriptRunLogScope.cs | 13 +- .../Scripts/ScriptRuntimeContext.cs | 12 +- .../Observability/ExecutionLogContextTests.cs | 105 ++++++++ .../Actors/ExecutionLogEnrichmentTests.cs | 122 ++++++++++ .../InboundScriptExecutorLogContextTests.cs | 79 ++++++ .../Logging/ExecutionLogEnrichmentTests.cs | 228 ++++++++++++++++++ .../Logging/LogContextCapture.cs | 57 +++++ 28 files changed, 905 insertions(+), 33 deletions(-) create mode 100644 src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.Commons/Observability/IExecutionCorrelated.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionLogEnrichmentTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundScriptExecutorLogContextTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/ExecutionLogEnrichmentTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Logging/LogContextCapture.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 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)); +}