From 262de38cee3087cd5b9a8b35514d0cd0b08d69ab Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sun, 6 Sep 2026 14:28:44 -0400 Subject: [PATCH] fix(audit): trace/outbound fault continuations run on the default scheduler and central emitters log (arch-review F8) Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29 --- .../InboundDatabaseHelper.cs | 13 ++++- .../InboundScriptExecutor.cs | 3 +- .../RouteHelper.cs | 40 +++++++++++----- .../Scripts/ScriptRunLauncher.cs | 4 +- .../Scripts/ScriptRuntimeContext.cs | 4 +- .../InboundDatabaseHelperAuditTests.cs | 47 +++++++++++++++++++ 6 files changed, 93 insertions(+), 18 deletions(-) diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundDatabaseHelper.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundDatabaseHelper.cs index 806cfb33..d25f189c 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundDatabaseHelper.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundDatabaseHelper.cs @@ -2,6 +2,7 @@ using System.Data.Common; using System.Diagnostics; using System.Globalization; using System.Text; +using Microsoft.Extensions.Logging; using ZB.MOM.WW.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; @@ -70,6 +71,7 @@ public sealed class InboundDatabaseHelper private readonly Guid? _parentExecutionId; private readonly string? _actor; private readonly Action? _traceSink; + private readonly ILogger? _logger; /// /// Initializes the helper. @@ -83,6 +85,7 @@ public sealed class InboundDatabaseHelper /// The spawning execution's id, if any (an inbound request is a root, so callers normally pass null). /// The executing API method's name; the row's Actor becomes api:{methodName}. Null = NULL actor. /// Flow Debugger trace sink; receives the same event instance before the writer does. Null = none. + /// Arch-review F8: logs a Warning when the best-effort audit write faults; null = silent. // Trailing optional parameters: the original (gateway, ct, commandTimeout) shape stays // source-compatible for every existing caller and test. public InboundDatabaseHelper( @@ -94,7 +97,8 @@ public sealed class InboundDatabaseHelper Guid? executionId = null, Guid? parentExecutionId = null, string? methodName = null, - Action? traceSink = null) + Action? traceSink = null, + ILogger? logger = null) { _gateway = gateway; _ct = ct; @@ -107,6 +111,7 @@ public sealed class InboundDatabaseHelper _parentExecutionId = parentExecutionId; _actor = string.IsNullOrEmpty(methodName) ? null : "api:" + methodName; _traceSink = traceSink; + _logger = logger; } /// First column of the first row converted to (default if no rows). @@ -268,7 +273,11 @@ public sealed class InboundDatabaseHelper var t = _auditWriter.WriteAsync(evt, CancellationToken.None); if (!t.IsCompletedSuccessfully) { - _ = t.ContinueWith(static _ => { }, TaskContinuationOptions.OnlyOnFaulted); + _ = t.ContinueWith( + x => _logger?.LogWarning(x.Exception, "Flow trace DbOutbound write failed for {Connection}", connectionName), + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); } } catch (Exception) diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs index e1eaa417..c66d0fc4 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs @@ -399,7 +399,8 @@ public class InboundScriptExecutor executionId: parentExecutionId, parentExecutionId: null, methodName: method.Name, - traceSink: route.TraceSink); + traceSink: route.TraceSink, + logger: _logger); // Bind the route helper to the method deadline so a // routed Route.To(...).Call(...) inherits the method-level timeout diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/RouteHelper.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/RouteHelper.cs index 33269120..22299362 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/RouteHelper.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/RouteHelper.cs @@ -1,6 +1,7 @@ using System.Diagnostics; using System.Text.Json; using Akka.Actor; +using Microsoft.Extensions.Logging; using ZB.MOM.WW.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using ZB.MOM.WW.ScadaBridge.Commons.Messages.InboundApi; @@ -87,6 +88,7 @@ public class RouteHelper private readonly Action? _traceSink; private readonly IReadOnlySet? _permittedSiteIdentifiers; private readonly bool _captureBodies; + private readonly ILogger? _logger; /// /// Initializes a new with no deadline token and no parent execution id. @@ -97,13 +99,15 @@ public class RouteHelper /// Service to route cross-site calls to the resolved site. /// Flow Debugger (design 2026-09-05 §5.1): central-direct-write audit writer for the always-on RouteCall row; null = no row. /// Stamps SourceNode (central-a/central-b) on the RouteCall row; null = NULL. + /// Arch-review F8: logs a Warning when the best-effort RouteCall audit write faults; null = silent. public RouteHelper( IInstanceLocator instanceLocator, IInstanceRouter instanceRouter, ICentralAuditWriter? auditWriter = null, - INodeIdentityProvider? nodeIdentity = null) + INodeIdentityProvider? nodeIdentity = null, + ILogger? logger = null) : this(instanceLocator, instanceRouter, CancellationToken.None, CancellationToken.None, parentExecutionId: null, - auditWriter, nodeIdentity, trace: false, traceSink: null, permittedSiteIdentifiers: null, captureBodies: true) + auditWriter, nodeIdentity, trace: false, traceSink: null, permittedSiteIdentifiers: null, captureBodies: true, logger) { } @@ -118,7 +122,8 @@ public class RouteHelper bool trace, Action? traceSink, IReadOnlySet? permittedSiteIdentifiers, - bool captureBodies) + bool captureBodies, + ILogger? logger) { _permittedSiteIdentifiers = permittedSiteIdentifiers; _instanceLocator = instanceLocator; @@ -131,6 +136,7 @@ public class RouteHelper _trace = trace; _traceSink = traceSink; _captureBodies = captureBodies; + _logger = logger; } /// @@ -144,7 +150,7 @@ public class RouteHelper /// A new inheriting the given deadline token. public RouteHelper WithDeadline(CancellationToken deadlineToken) => new(_instanceLocator, _instanceRouter, deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); /// /// Returns a carrying the raw request-abort @@ -158,7 +164,7 @@ public class RouteHelper /// A new carrying the given request-abort token. public RouteHelper WithRequestAborted(CancellationToken requestAbortedToken) => new(_instanceLocator, _instanceRouter, _deadlineToken, requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); /// /// Audit Log (ParentExecutionId): returns a whose @@ -173,7 +179,7 @@ public class RouteHelper /// A new carrying the given parent execution id. public RouteHelper WithParentExecutionId(Guid? parentExecutionId) => new(_instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); /// /// Flow Debugger (design 2026-09-05 §5.2): returns a whose routed @@ -184,7 +190,7 @@ public class RouteHelper /// A new carrying the flag. public RouteHelper WithTrace(bool trace) => new(_instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, trace, _traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, trace, _traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); /// /// Flow Debugger (design 2026-09-05 §7.1): returns a that also @@ -196,7 +202,7 @@ public class RouteHelper /// A new carrying the sink. public RouteHelper WithTraceSink(Action? traceSink) => new(_instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); /// /// Flow Debugger outbound calls (plan 2026-09-06, D5/D7): the trace sink this helper carries, @@ -230,7 +236,7 @@ public class RouteHelper /// A new carrying the scope. public RouteHelper WithSiteScope(IReadOnlySet? permittedSiteIdentifiers) => new(_instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, permittedSiteIdentifiers, _captureBodies, _logger); /// /// Arch-review F11: returns a whose always-on RouteCall row @@ -245,7 +251,7 @@ public class RouteHelper /// A new carrying the flag. public RouteHelper WithBodyCapture(bool captureBodies) => new(_instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, captureBodies, _logger); /// /// Creates a route target for the specified instance. @@ -256,7 +262,7 @@ public class RouteHelper { return new RouteTarget( instanceCode, _instanceLocator, _instanceRouter, _deadlineToken, _requestAbortedToken, _parentExecutionId, - _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies); + _auditWriter, _nodeIdentity, _trace, _traceSink, _permittedSiteIdentifiers, _captureBodies, _logger); } } @@ -277,6 +283,7 @@ public class RouteTarget private readonly Action? _traceSink; private readonly IReadOnlySet? _permittedSiteIdentifiers; private readonly bool _captureBodies; + private readonly ILogger? _logger; /// /// Initializes a new for the specified instance. @@ -293,6 +300,7 @@ public class RouteTarget /// Receives the emitted audit events in order; null = none. /// Arch-review F2: site identifiers this call may reach; null = unscoped. /// Arch-review F11: false omits the request/response summary on the RouteCall row. + /// Arch-review F8: logs a Warning when the best-effort RouteCall audit write faults; null = silent. internal RouteTarget( string instanceCode, IInstanceLocator instanceLocator, @@ -305,7 +313,8 @@ public class RouteTarget bool trace = false, Action? traceSink = null, IReadOnlySet? permittedSiteIdentifiers = null, - bool captureBodies = true) + bool captureBodies = true, + ILogger? logger = null) { _permittedSiteIdentifiers = permittedSiteIdentifiers; _instanceCode = instanceCode; @@ -319,6 +328,7 @@ public class RouteTarget _trace = trace; _traceSink = traceSink; _captureBodies = captureBodies; + _logger = logger; } /// @@ -425,7 +435,11 @@ public class RouteTarget var t = _auditWriter.WriteAsync(evt, CancellationToken.None); if (!t.IsCompletedSuccessfully) { - _ = t.ContinueWith(static _ => { }, TaskContinuationOptions.OnlyOnFaulted); + _ = t.ContinueWith( + x => _logger?.LogWarning(x.Exception, "Flow trace RouteCall write failed for {Target}", $"{_instanceCode}.{scriptName}"), + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); } } catch (Exception) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index 111e85f8..4a86409f 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -596,7 +596,9 @@ internal static class ScriptRunLauncher { _ = t.ContinueWith( x => logger.LogWarning(x.Exception, "Flow trace ScriptRun write failed for {Script}", scriptName), - TaskContinuationOptions.OnlyOnFaulted); + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); } } catch (Exception ex) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs index 425ea5ae..ea9f4a8b 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -445,7 +445,9 @@ public class ScriptRuntimeContext { _ = t.ContinueWith( x => _logger.LogWarning(x.Exception, "Flow trace write failed for {Kind}", kind), - TaskContinuationOptions.OnlyOnFaulted); + CancellationToken.None, + TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, + TaskScheduler.Default); } } catch (Exception ex) diff --git a/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundDatabaseHelperAuditTests.cs b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundDatabaseHelperAuditTests.cs index 0ae68830..4230c963 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundDatabaseHelperAuditTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundDatabaseHelperAuditTests.cs @@ -1,6 +1,7 @@ using System.Data.Common; using Microsoft.Data.Sqlite; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using NSubstitute; using ZB.MOM.WW.Audit; @@ -58,6 +59,26 @@ public class InboundDatabaseHelperAuditTests => throw new NotImplementedException(); } + /// + /// Arch-review F8: a minimal double that records every + /// Warning-level message, mirroring the CountingLogger<T> pattern in + /// InboundScriptExecutorTests. + /// + private sealed class RecordingLogger : ILogger + { + public List<(LogLevel Level, string Message, Exception? Exception)> Entries { get; } = new(); + + 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) + { + Entries.Add((logLevel, formatter(state, exception), exception)); + } + } + private static SqliteGateway SeededGateway() => new(); private readonly List _written = new(); @@ -166,6 +187,32 @@ public class InboundDatabaseHelperAuditTests Assert.Equal(1, n2); } + [Fact] + public async Task AuditWriterFaulting_LogsWarning_AndCallStillSucceeds() + { + // Arch-review F8: the best-effort continuation used to be `static _ => { }` — a + // faulting write vanished with no trace anywhere. It now logs a Warning (and runs + // on TaskScheduler.Default rather than riding whatever context completed the + // audit-writer task), while the call itself still succeeds either way. + var faultedTask = Substitute.For(); + faultedTask.WriteAsync(Arg.Any(), Arg.Any()) + .Returns(Task.FromException(new InvalidOperationException("audit down"))); + var logger = new RecordingLogger(); + var helper = new InboundDatabaseHelper( + SeededGateway(), CancellationToken.None, TimeSpan.Zero, + auditWriter: faultedTask, nodeIdentity: _node, + executionId: _exec, parentExecutionId: _parent, methodName: "movein", + traceSink: null, logger: logger); + + var n = await helper.ExecuteAsync("MesDb", "UPDATE Machine SET Code=Code", null); + + Assert.Equal(1, n); + var entry = Assert.Single(logger.Entries); + Assert.Equal(LogLevel.Warning, entry.Level); + Assert.NotNull(entry.Exception); + Assert.Contains("MesDb", entry.Message); + } + [Fact] public async Task TraceSink_ReceivesTheSameInstance_BeforeTheWriter() {