Akka ILoggingAdapter output bypasses Serilog (DefaultLogger → stdout only) #120

New Issue

2026-11-10T05:27:39-05:00

dohertj2 commented

2026-11-10 05:27:39 -05:00

Found while implementing #56 (ExecutionId log enrichment).

What: actors that log through Akka's ILoggingAdapter (Context.GetLogger()) — e.g. DataConnectionActor, DataConnectionManagerActor, CertStoreActor, CentralCommunicationActor — never reach the Serilog pipeline. The host builds its ActorSystem from hand-assembled HOCON (AkkaHostedService.BuildHocon → ActorSystem.Create("scadabridge", config)) with no akka.loggers setting and no Akka.Logger.Serilog / Akka.Hosting LoggerFactory bridge, so those lines go to Akka's DefaultLogger (stdout) only:

they are not in the rolling file sinks LoggerConfigurationFactory configures,
they carry none of the node/site/trace enrichers, and
they cannot carry ExecutionId (#56): Akka logs asynchronously through its logger actor, so even a bridged adapter would not see the handler's Serilog LogContext.

The arch review recorded the dual logging stacks as LOG-01 (docs/plans/2026-09-09-arch-review.md:806).

Options:

(recommended) Route Akka logging through Microsoft.Extensions.Logging (Akka.Hosting's LoggerFactoryLogger, or Akka.Logger.Serilog) so the lines at least land in the file sinks with the node enrichers. Fits the family baseline (one Serilog pipeline). Does not by itself give ExecutionId.
Migrate the DCL actors (the ones on an execution's write path) from ILoggingAdapter to an injected ILogger, as InstanceActor/ScriptActor already do — then #56's per-message AroundReceive push tags them too. More churn; only worth it for actors that serve executions.

Note: the protocol adapters the DCL calls (RealOpcUaClient, the MxGateway adapter) already log through ILogger, and since #56 their lines on a script's write path DO carry the ExecutionId. Only the DCL actors' own _log lines (mostly Debug on the write path) are affected.

Found while implementing #56 (ExecutionId log enrichment). **What:** actors that log through Akka's `ILoggingAdapter` (`Context.GetLogger()`) — e.g. `DataConnectionActor`, `DataConnectionManagerActor`, `CertStoreActor`, `CentralCommunicationActor` — never reach the Serilog pipeline. The host builds its `ActorSystem` from hand-assembled HOCON (`AkkaHostedService.BuildHocon` → `ActorSystem.Create("scadabridge", config)`) with no `akka.loggers` setting and no `Akka.Logger.Serilog` / Akka.Hosting `LoggerFactory` bridge, so those lines go to Akka's `DefaultLogger` (stdout) only: - they are not in the rolling file sinks `LoggerConfigurationFactory` configures, - they carry none of the node/site/trace enrichers, and - they cannot carry `ExecutionId` (#56): Akka logs asynchronously through its logger actor, so even a bridged adapter would not see the handler's Serilog `LogContext`. The arch review recorded the dual logging stacks as LOG-01 (`docs/plans/2026-09-09-arch-review.md:806`). **Options:** 1. *(recommended)* Route Akka logging through `Microsoft.Extensions.Logging` (Akka.Hosting's `LoggerFactoryLogger`, or `Akka.Logger.Serilog`) so the lines at least land in the file sinks with the node enrichers. Fits the family baseline (one Serilog pipeline). Does not by itself give `ExecutionId`. 2. Migrate the DCL actors (the ones on an execution's write path) from `ILoggingAdapter` to an injected `ILogger`, as `InstanceActor`/`ScriptActor` already do — then #56's per-message `AroundReceive` push tags them too. More churn; only worth it for actors that serve executions. Note: the protocol adapters the DCL calls (`RealOpcUaClient`, the MxGateway adapter) already log through `ILogger`, and since #56 their lines on a script's write path DO carry the `ExecutionId`. Only the DCL actors' own `_log` lines (mostly Debug on the write path) are affected.

dohertj2 added the type:debt priority:p3 labels 2026-11-10 05:27:39 -05:00

dohertj2 referenced this issue from a commit

2026-11-10 05:28:26 -05:00

feat(logging): carry ExecutionId across actor hops onto other actors' log lines (ScadaBridge#56)

dohertj2 referenced this issue

2026-11-10 05:28:44 -05:00

Capture other actors' log lines per execution (ExecutionId log enrichment) #56

dohertj2 referenced this issue from a commit

2026-11-10 06:12:46 -05:00

feat(logging): bridge Akka logging to Serilog and copy traced runs' node-log lines into the Flow Debugger (ScadaBridge#120, #56)

dohertj2 commented

2026-11-10 06:13:18 -05:00

Fixed on main in c810bd0f (pushed together with the #56 remainder).

What changed

AkkaHostedService.BuildHocon now sets akka.loggers = [ZB.MOM.WW.ScadaBridge.Host.Actors.SerilogAkkaLogger]. This replaces Akka's stdout-only DefaultLogger.
The logger is in-repo and small, with no Akka.Hosting or Akka.Logger.Serilog dependency, because ScadaBridge keeps its own Serilog factory. It writes every ILoggingAdapter line to the static Serilog logger that Program builds through LoggerConfigurationFactory, so the lines now reach the file sinks and carry the SiteId/NodeHostname/NodeRole/trace enrichers.
SourceContext is the logging class's full name, so namespace MinimumLevel.Overrides apply to Akka lines too. AkkaSource is the actor path. Akka's own timestamp is kept, and the format arguments become structured properties.
No volume change: akka.loglevel stays INFO, so Akka's Debug lifecycle chatter is still filtered at the adapter. The INFO+ lines that used to go to stdout now go through Serilog instead. Nothing new is produced.
ExecutionId across the logger-actor hop:
- ExecutionLogContext gained Current, an AsyncLocal mirror of the pushed id. ScriptRunLogScope now pushes through it.
- DataConnectionActor and DataConnectionManagerActor log through the new DataConnectionLayer.Logging.ExecutionAwareLogging.GetLogger(Context). Akka's BusLogging is sealed, so this is a LoggingAdapterBase with the same publishing behaviour.
- That adapter wraps the message in ExecutionTaggedLogMessage while an id is current. ToString() is unchanged, so the stdout logger and TestKit filters see the same text.
- The Serilog logger actor pushes the id again while it writes the line, so the AroundReceive push is visible on those lines.

Evidence

dotnet build ZB.MOM.WW.ScadaBridge.slnx: 0 warnings, 0 errors.
Full suites: Host 687/687, DCL 501 passed / 4 skipped, Commons 951/951, SiteRuntime 1037/1037.
New tests:
- Host.Tests/SerilogAkkaLoggerTests: the line reaches Serilog with SourceContext, AkkaSource, node enricher and structured args; the ExecutionId crosses the logger hop; the timestamp is kept and every level maps; the Serilog minimum level applies; HOCON names the logger with loglevel INFO; an ActorSystem boots with the logger configured.
- DCL.Tests/Actors/ExecutionAwareLoggingTests: a line inside a push is tagged and its text is unchanged; a line outside a push is published unwrapped; a disabled level publishes nothing; DataConnectionActor's own write-path Debug line Writing to tag is tagged with the request's id, with an uncorrelated write as the control.
- Commons.Tests ExecutionLogContext.Current tracks pushes and nesting and is restored on dispose.
Mutation checks, each of which made the matching test fail:
- logger actor pushes null instead of the id
- akka.loggers removed from the HOCON
- adapter does not wrap
- DataConnectionActor reverted to Context.GetLogger()

Docs: Component-Host REQ-HOST-8, Component-SiteRuntime, step-logs design §12, CLAUDE.md.

Fixed on main in **`c810bd0f`** (pushed together with the #56 remainder). **What changed** - `AkkaHostedService.BuildHocon` now sets `akka.loggers = [ZB.MOM.WW.ScadaBridge.Host.Actors.SerilogAkkaLogger]`. This replaces Akka's stdout-only `DefaultLogger`. - The logger is in-repo and small, with no Akka.Hosting or `Akka.Logger.Serilog` dependency, because ScadaBridge keeps its own Serilog factory. It writes every `ILoggingAdapter` line to the static Serilog logger that `Program` builds through `LoggerConfigurationFactory`, so the lines now reach the file sinks and carry the `SiteId`/`NodeHostname`/`NodeRole`/trace enrichers. - `SourceContext` is the logging class's full name, so namespace `MinimumLevel.Override`s apply to Akka lines too. `AkkaSource` is the actor path. Akka's own timestamp is kept, and the format arguments become structured properties. - **No volume change:** `akka.loglevel` stays `INFO`, so Akka's Debug lifecycle chatter is still filtered at the adapter. The INFO+ lines that used to go to stdout now go through Serilog instead. Nothing new is produced. - **ExecutionId across the logger-actor hop:** - `ExecutionLogContext` gained `Current`, an `AsyncLocal` mirror of the pushed id. `ScriptRunLogScope` now pushes through it. - `DataConnectionActor` and `DataConnectionManagerActor` log through the new `DataConnectionLayer.Logging.ExecutionAwareLogging.GetLogger(Context)`. Akka's `BusLogging` is sealed, so this is a `LoggingAdapterBase` with the same publishing behaviour. - That adapter wraps the message in `ExecutionTaggedLogMessage` while an id is current. `ToString()` is unchanged, so the stdout logger and TestKit filters see the same text. - The Serilog logger actor pushes the id again while it writes the line, so the `AroundReceive` push is visible on those lines. **Evidence** - `dotnet build ZB.MOM.WW.ScadaBridge.slnx`: 0 warnings, 0 errors. - Full suites: Host 687/687, DCL 501 passed / 4 skipped, Commons 951/951, SiteRuntime 1037/1037. - New tests: - `Host.Tests/SerilogAkkaLoggerTests`: the line reaches Serilog with SourceContext, AkkaSource, node enricher and structured args; the ExecutionId crosses the logger hop; the timestamp is kept and every level maps; the Serilog minimum level applies; HOCON names the logger with loglevel INFO; an ActorSystem boots with the logger configured. - `DCL.Tests/Actors/ExecutionAwareLoggingTests`: a line inside a push is tagged and its text is unchanged; a line outside a push is published unwrapped; a disabled level publishes nothing; `DataConnectionActor`'s own write-path Debug line `Writing to tag` is tagged with the request's id, with an uncorrelated write as the control. - `Commons.Tests` `ExecutionLogContext.Current` tracks pushes and nesting and is restored on dispose. - Mutation checks, each of which made the matching test fail: - logger actor pushes null instead of the id - `akka.loggers` removed from the HOCON - adapter does not wrap - `DataConnectionActor` reverted to `Context.GetLogger()` Docs: Component-Host REQ-HOST-8, Component-SiteRuntime, step-logs design §12, CLAUDE.md.

dohertj2 closed this issue

2026-11-10 06:13:18 -05:00

dohertj2 referenced this issue

2026-11-10 06:13:18 -05:00

Capture other actors' log lines per execution (ExecutionId log enrichment) #56

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: dohertj2/ScadaBridge#120