feat(siteruntime): ExternalSystem.Call emits Audit Log #23 event on every sync call

Wraps IExternalSystemClient.CallAsync inside ScriptRuntimeContext's
ExternalSystemHelper so every script-initiated ExternalSystem.Call
produces exactly one ApiOutbound/ApiCall AuditEvent via IAuditWriter.

- Captures duration with Stopwatch.GetTimestamp() around the call.
- Builds the audit event with full provenance (SiteId, InstanceId,
  SourceScript) and a fresh EventId; ForwardState=Pending.
- Maps Success → AuditStatus.Delivered, Failure (or thrown) → Failed;
  parses HTTP {code} out of the ExternalSystemClient's error message
  to populate HttpStatus.
- Audit emission is fully best-effort: event-build failures, sync
  WriteAsync throws, AND async WriteAsync faults are all logged at
  Warning and swallowed so the script's call path is never aborted
  by an audit-write failure (alog.md §7).
- Original ExternalCallResult or original exception flows back to the
  caller unchanged.

ScriptExecutionActor resolves IAuditWriter from DI and threads it
into ScriptRuntimeContext alongside the existing site identity.

Adds ExternalSystemCallAuditEmissionTests covering: success →
Delivered, HTTP 500 → Failed+httpStatus, HTTP 400 → Failed+httpStatus,
client-thrown network exception → Failed with original exception
re-thrown, audit-writer throw → original result returned, provenance
populated from context, DurationMs recorded.

Refs Audit Log #23 M2 Bundle F.
This commit is contained in:
Joseph Doherty
2026-05-20 13:11:19 -04:00
parent 9bf1497f03
commit 82a8bbf225
3 changed files with 429 additions and 5 deletions

View File

@@ -101,6 +101,10 @@ public class ScriptExecutionActor : ReceiveActor
// provider supplies the site id stamped on enqueued notifications. // provider supplies the site id stamped on enqueued notifications.
StoreAndForwardService? storeAndForward = null; StoreAndForwardService? storeAndForward = null;
var siteId = string.Empty; var siteId = string.Empty;
// Audit Log #23 (M2 Bundle F): the writer is a singleton (FallbackAuditWriter
// composes the SQLite hot-path + drop-oldest ring); null in tests / hosts
// that haven't called AddAuditLog, which the helper handles as a no-op.
IAuditWriter? auditWriter = null;
if (serviceProvider != null) if (serviceProvider != null)
{ {
@@ -110,6 +114,7 @@ public class ScriptExecutionActor : ReceiveActor
storeAndForward = serviceScope.ServiceProvider.GetService<StoreAndForwardService>(); storeAndForward = serviceScope.ServiceProvider.GetService<StoreAndForwardService>();
siteId = serviceScope.ServiceProvider.GetService<ISiteIdentityProvider>()?.SiteId siteId = serviceScope.ServiceProvider.GetService<ISiteIdentityProvider>()?.SiteId
?? string.Empty; ?? string.Empty;
auditWriter = serviceScope.ServiceProvider.GetService<IAuditWriter>();
} }
var context = new ScriptRuntimeContext( var context = new ScriptRuntimeContext(
@@ -128,7 +133,12 @@ public class ScriptExecutionActor : ReceiveActor
siteId, siteId,
// Notification Outbox (FU3): stamp the executing script onto outbound // Notification Outbox (FU3): stamp the executing script onto outbound
// notifications using the Site Event Logging "Source" convention. // notifications using the Site Event Logging "Source" convention.
sourceScript: $"ScriptActor:{scriptName}"); sourceScript: $"ScriptActor:{scriptName}",
// Audit Log #23 (M2 Bundle F): emit one ApiOutbound/ApiCall row per
// ExternalSystem.Call. Writer is best-effort; failures are logged
// and swallowed inside the helper so the script's call path is
// never aborted by an audit failure.
auditWriter: auditWriter);
var globals = new ScriptGlobals var globals = new ScriptGlobals
{ {

View File

@@ -1,6 +1,9 @@
using System.Diagnostics;
using System.Text.Json; using System.Text.Json;
using System.Text.RegularExpressions;
using Akka.Actor; using Akka.Actor;
using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging;
using ScadaLink.Commons.Entities.Audit;
using ScadaLink.Commons.Interfaces.Services; using ScadaLink.Commons.Interfaces.Services;
using ScadaLink.Commons.Messages.Instance; using ScadaLink.Commons.Messages.Instance;
using ScadaLink.Commons.Messages.Notification; using ScadaLink.Commons.Messages.Notification;
@@ -75,6 +78,13 @@ public class ScriptRuntimeContext
/// </summary> /// </summary>
private readonly string? _sourceScript; private readonly string? _sourceScript;
/// <summary>
/// Audit Log #23: best-effort emitter for boundary-crossing actions executed
/// by the script. Optional — when null the helpers degrade to a no-op audit
/// path so tests / contexts that do not need the audit pipeline still work.
/// </summary>
private readonly IAuditWriter? _auditWriter;
public ScriptRuntimeContext( public ScriptRuntimeContext(
IActorRef instanceActor, IActorRef instanceActor,
IActorRef self, IActorRef self,
@@ -89,7 +99,8 @@ public class ScriptRuntimeContext
StoreAndForwardService? storeAndForward = null, StoreAndForwardService? storeAndForward = null,
ICanTell? siteCommunicationActor = null, ICanTell? siteCommunicationActor = null,
string siteId = "", string siteId = "",
string? sourceScript = null) string? sourceScript = null,
IAuditWriter? auditWriter = null)
{ {
_instanceActor = instanceActor; _instanceActor = instanceActor;
_self = self; _self = self;
@@ -105,6 +116,7 @@ public class ScriptRuntimeContext
_siteCommunicationActor = siteCommunicationActor; _siteCommunicationActor = siteCommunicationActor;
_siteId = siteId; _siteId = siteId;
_sourceScript = sourceScript; _sourceScript = sourceScript;
_auditWriter = auditWriter;
} }
/// <summary> /// <summary>
@@ -204,7 +216,8 @@ public class ScriptRuntimeContext
/// ExternalSystem.Call("systemName", "methodName", params) /// ExternalSystem.Call("systemName", "methodName", params)
/// ExternalSystem.CachedCall("systemName", "methodName", params) /// ExternalSystem.CachedCall("systemName", "methodName", params)
/// </summary> /// </summary>
public ExternalSystemHelper ExternalSystem => new(_externalSystemClient, _instanceName, _logger); public ExternalSystemHelper ExternalSystem => new(
_externalSystemClient, _instanceName, _logger, _auditWriter, _siteId, _sourceScript);
/// <summary> /// <summary>
/// WP-13: Provides access to database operations. /// WP-13: Provides access to database operations.
@@ -275,17 +288,41 @@ public class ScriptRuntimeContext
/// <summary> /// <summary>
/// WP-13: Helper for ExternalSystem.Call/CachedCall syntax. /// WP-13: Helper for ExternalSystem.Call/CachedCall syntax.
/// </summary> /// </summary>
/// <remarks>
/// Audit Log #23 (M2 Bundle F): every <see cref="Call"/> invocation emits
/// one <c>ApiOutbound</c>/<c>ApiCall</c> audit row via <see cref="IAuditWriter"/>.
/// The audit emission is wrapped in a try/catch that swallows every exception
/// — the audit pipeline is best-effort and must NEVER abort the script's
/// outbound call (alog.md §7). The original <see cref="ExternalCallResult"/>
/// (or the original thrown exception) flows back to the caller unchanged.
/// </remarks>
public class ExternalSystemHelper public class ExternalSystemHelper
{ {
private static readonly Regex HttpStatusRegex = new(
@"HTTP\s+(?<code>\d{3})",
RegexOptions.Compiled | RegexOptions.CultureInvariant);
private readonly IExternalSystemClient? _client; private readonly IExternalSystemClient? _client;
private readonly string _instanceName; private readonly string _instanceName;
private readonly ILogger _logger; private readonly ILogger _logger;
private readonly IAuditWriter? _auditWriter;
private readonly string _siteId;
private readonly string? _sourceScript;
internal ExternalSystemHelper(IExternalSystemClient? client, string instanceName, ILogger logger) internal ExternalSystemHelper(
IExternalSystemClient? client,
string instanceName,
ILogger logger,
IAuditWriter? auditWriter = null,
string siteId = "",
string? sourceScript = null)
{ {
_client = client; _client = client;
_instanceName = instanceName; _instanceName = instanceName;
_logger = logger; _logger = logger;
_auditWriter = auditWriter;
_siteId = siteId;
_sourceScript = sourceScript;
} }
public async Task<ExternalCallResult> Call( public async Task<ExternalCallResult> Call(
@@ -297,7 +334,31 @@ public class ScriptRuntimeContext
if (_client == null) if (_client == null)
throw new InvalidOperationException("External system client not available"); throw new InvalidOperationException("External system client not available");
return await _client.CallAsync(systemName, methodName, parameters, cancellationToken); // Audit Log #23 (M2 Bundle F): wrap the outbound call so every
// attempt emits exactly one ApiOutbound/ApiCall row. The wrapper
// mirrors the existing call-site behaviour — the original result
// OR original exception flows back to the script untouched; the
// audit emission is best-effort.
var occurredAtUtc = DateTime.UtcNow;
var startTicks = Stopwatch.GetTimestamp();
ExternalCallResult? result = null;
Exception? thrown = null;
try
{
result = await _client.CallAsync(systemName, methodName, parameters, cancellationToken);
return result;
}
catch (Exception ex)
{
thrown = ex;
throw;
}
finally
{
var elapsedMs = (int)((Stopwatch.GetTimestamp() - startTicks)
* 1000d / Stopwatch.Frequency);
EmitCallAudit(systemName, methodName, occurredAtUtc, elapsedMs, result, thrown);
}
} }
public async Task<ExternalCallResult> CachedCall( public async Task<ExternalCallResult> CachedCall(
@@ -311,6 +372,145 @@ public class ScriptRuntimeContext
return await _client.CachedCallAsync(systemName, methodName, parameters, _instanceName, cancellationToken); return await _client.CachedCallAsync(systemName, methodName, parameters, _instanceName, cancellationToken);
} }
/// <summary>
/// Best-effort emission of one <c>ApiOutbound</c>/<c>ApiCall</c> audit
/// row. Any exception thrown by the writer is logged and swallowed —
/// audit-write failures must never abort the user-facing action.
/// </summary>
private void EmitCallAudit(
string systemName,
string methodName,
DateTime occurredAtUtc,
int durationMs,
ExternalCallResult? result,
Exception? thrown)
{
if (_auditWriter == null)
{
return;
}
AuditEvent evt;
try
{
evt = BuildCallAuditEvent(systemName, methodName, occurredAtUtc, durationMs, result, thrown);
}
catch (Exception buildEx)
{
// Building the event itself must never propagate. This is a
// defensive guard — populating a record from already-validated
// values shouldn't throw, but we honour the alog.md §7
// best-effort contract regardless.
_logger.LogWarning(buildEx,
"Failed to build Audit Log #23 event for {System}.{Method} — skipping emission",
systemName, methodName);
return;
}
try
{
// Fire-and-forget so we never block the script on the audit
// writer; the writer itself is responsible for fast, durable
// enqueue (site SQLite hot-path). We DO observe failures via
// ContinueWith so a thrown writer is logged rather than going
// to the unobserved-task firehose.
var writeTask = _auditWriter.WriteAsync(evt, CancellationToken.None);
if (!writeTask.IsCompleted)
{
writeTask.ContinueWith(
t => _logger.LogWarning(t.Exception,
"Audit Log #23 write failed for EventId {EventId} ({System}.{Method})",
evt.EventId, systemName, methodName),
CancellationToken.None,
TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously,
TaskScheduler.Default);
}
else if (writeTask.IsFaulted)
{
_logger.LogWarning(writeTask.Exception,
"Audit Log #23 write failed for EventId {EventId} ({System}.{Method})",
evt.EventId, systemName, methodName);
}
}
catch (Exception writeEx)
{
// Synchronous throw from WriteAsync (e.g. ArgumentNullException
// before the writer's own try/catch). Swallow + log per the
// alog.md §7 contract.
_logger.LogWarning(writeEx,
"Audit Log #23 write threw synchronously for EventId {EventId} ({System}.{Method})",
evt.EventId, systemName, methodName);
}
}
private AuditEvent BuildCallAuditEvent(
string systemName,
string methodName,
DateTime occurredAtUtc,
int durationMs,
ExternalCallResult? result,
Exception? thrown)
{
// Status: Delivered on a Success result; Failed otherwise (the
// ExternalSystemClient already maps HTTP non-2xx + transient
// exceptions into Success=false on the result, or surfaces a raw
// exception). M2 makes no distinction between transient + permanent
// failure here — both manifest as Status.Failed on the sync path.
var status = (thrown == null && result != null && result.Success)
? AuditStatus.Delivered
: AuditStatus.Failed;
string? errorMessage = null;
string? errorDetail = null;
int? httpStatus = null;
if (thrown != null)
{
errorMessage = thrown.Message;
errorDetail = thrown.ToString();
}
else if (result != null && !result.Success)
{
errorMessage = result.ErrorMessage;
// The ExternalSystemClient embeds the HTTP status code in the
// error message as "HTTP {code}". Parse it back out so the
// audit row carries the structured value.
if (!string.IsNullOrEmpty(result.ErrorMessage))
{
var match = HttpStatusRegex.Match(result.ErrorMessage);
if (match.Success
&& int.TryParse(match.Groups["code"].Value, out var parsed))
{
httpStatus = parsed;
}
}
}
return new AuditEvent
{
EventId = Guid.NewGuid(),
OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc),
Channel = AuditChannel.ApiOutbound,
Kind = AuditKind.ApiCall,
CorrelationId = null,
SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId,
SourceInstanceId = _instanceName,
SourceScript = _sourceScript,
Actor = null,
Target = $"{systemName}.{methodName}",
Status = status,
HttpStatus = httpStatus,
DurationMs = durationMs,
ErrorMessage = errorMessage,
ErrorDetail = errorDetail,
RequestSummary = null,
ResponseSummary = null,
PayloadTruncated = false,
Extra = null,
ForwardState = AuditForwardState.Pending,
};
}
} }
/// <summary> /// <summary>

View File

@@ -0,0 +1,214 @@
using Microsoft.Extensions.Logging.Abstractions;
using Moq;
using ScadaLink.Commons.Entities.Audit;
using ScadaLink.Commons.Interfaces.Services;
using ScadaLink.Commons.Types;
using ScadaLink.Commons.Types.Enums;
using ScadaLink.SiteRuntime.Scripts;
namespace ScadaLink.SiteRuntime.Tests.Scripts;
/// <summary>
/// Audit Log #23 — M2 Bundle F (Task F1): every script-initiated
/// <c>ExternalSystem.Call</c> emits exactly one <c>ApiOutbound</c>/<c>ApiCall</c>
/// audit event via the wrapper inside
/// <see cref="ScriptRuntimeContext.ExternalSystemHelper"/>. The audit emission
/// is best-effort: a thrown <see cref="IAuditWriter.WriteAsync"/> must never
/// abort the script's call, and the original <see cref="ExternalCallResult"/>
/// (or original exception) must surface to the caller unchanged.
/// </summary>
public class ExternalSystemCallAuditEmissionTests
{
/// <summary>
/// In-memory <see cref="IAuditWriter"/> that records every event passed to
/// <see cref="WriteAsync"/>. Optionally configurable to throw, simulating a
/// catastrophic audit-writer failure that the wrapper must swallow.
/// </summary>
private sealed class CapturingAuditWriter : IAuditWriter
{
public List<AuditEvent> Events { get; } = new();
public Exception? ThrowOnWrite { get; set; }
public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
{
if (ThrowOnWrite != null)
{
return Task.FromException(ThrowOnWrite);
}
Events.Add(evt);
return Task.CompletedTask;
}
}
private const string SiteId = "site-77";
private const string InstanceName = "Plant.Pump42";
private const string SourceScript = "ScriptActor:CheckPressure";
private static ScriptRuntimeContext.ExternalSystemHelper CreateHelper(
IExternalSystemClient client,
IAuditWriter? auditWriter)
{
return new ScriptRuntimeContext.ExternalSystemHelper(
client,
InstanceName,
NullLogger.Instance,
auditWriter,
SiteId,
SourceScript);
}
[Fact]
public async Task Call_Success_EmitsOneEvent_Channel_ApiOutbound_Kind_ApiCall_Status_Delivered()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(new ExternalCallResult(true, "{}", null));
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
var result = await helper.Call("ERP", "GetOrder");
Assert.True(result.Success);
Assert.Single(writer.Events);
var evt = writer.Events[0];
Assert.Equal(AuditChannel.ApiOutbound, evt.Channel);
Assert.Equal(AuditKind.ApiCall, evt.Kind);
Assert.Equal(AuditStatus.Delivered, evt.Status);
Assert.Equal("ERP.GetOrder", evt.Target);
Assert.Equal(AuditForwardState.Pending, evt.ForwardState);
Assert.Equal(DateTimeKind.Utc, evt.OccurredAtUtc.Kind);
Assert.NotEqual(Guid.Empty, evt.EventId);
Assert.False(evt.PayloadTruncated);
}
[Fact]
public async Task Call_HTTP500_EmitsEvent_Status_Failed_HttpStatus_500_ErrorMessage_Set()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(new ExternalCallResult(false, null, "Transient error: HTTP 500 from ERP: Internal Server Error"));
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
var result = await helper.Call("ERP", "GetOrder");
Assert.False(result.Success);
Assert.Single(writer.Events);
var evt = writer.Events[0];
Assert.Equal(AuditStatus.Failed, evt.Status);
Assert.Equal(500, evt.HttpStatus);
Assert.False(string.IsNullOrEmpty(evt.ErrorMessage));
Assert.Contains("500", evt.ErrorMessage);
}
[Fact]
public async Task Call_HTTP400_EmitsEvent_Status_Failed_HttpStatus_400()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(new ExternalCallResult(false, null, "Permanent error: HTTP 400 from ERP: Bad Request"));
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
var result = await helper.Call("ERP", "GetOrder");
Assert.False(result.Success);
Assert.Single(writer.Events);
var evt = writer.Events[0];
Assert.Equal(AuditStatus.Failed, evt.Status);
Assert.Equal(400, evt.HttpStatus);
}
[Fact]
public async Task Call_ClientThrows_NetworkException_EmitsEvent_Status_Failed_ErrorMessage_FromException()
{
var client = new Mock<IExternalSystemClient>();
var networkEx = new HttpRequestException("network down");
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ThrowsAsync(networkEx);
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
var thrown = await Assert.ThrowsAsync<HttpRequestException>(() => helper.Call("ERP", "GetOrder"));
Assert.Same(networkEx, thrown);
Assert.Single(writer.Events);
var evt = writer.Events[0];
Assert.Equal(AuditStatus.Failed, evt.Status);
Assert.Null(evt.HttpStatus);
Assert.Equal("network down", evt.ErrorMessage);
Assert.NotNull(evt.ErrorDetail);
Assert.Contains("HttpRequestException", evt.ErrorDetail);
}
[Fact]
public async Task AuditWriter_Throws_Script_Call_Returns_Original_Result_Unchanged()
{
var client = new Mock<IExternalSystemClient>();
var expected = new ExternalCallResult(true, "{\"v\":1}", null);
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(expected);
var writer = new CapturingAuditWriter
{
ThrowOnWrite = new InvalidOperationException("audit writer down")
};
var helper = CreateHelper(client.Object, writer);
var result = await helper.Call("ERP", "GetOrder");
Assert.Same(expected, result);
Assert.Empty(writer.Events);
}
[Fact]
public async Task Provenance_Populated_FromContext()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(new ExternalCallResult(true, null, null));
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
var beforeId = Guid.NewGuid();
await helper.Call("ERP", "GetOrder");
var evt = writer.Events[0];
Assert.NotEqual(beforeId, evt.EventId);
Assert.NotEqual(Guid.Empty, evt.EventId);
Assert.Equal(SiteId, evt.SourceSiteId);
Assert.Equal(InstanceName, evt.SourceInstanceId);
Assert.Equal(SourceScript, evt.SourceScript);
Assert.Null(evt.Actor);
Assert.Null(evt.CorrelationId);
}
[Fact]
public async Task DurationMs_Recorded_NonZero()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync("ERP", "Slow", It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.Returns(async () =>
{
await Task.Delay(20);
return new ExternalCallResult(true, null, null);
});
var writer = new CapturingAuditWriter();
var helper = CreateHelper(client.Object, writer);
await helper.Call("ERP", "Slow");
var evt = writer.Events[0];
Assert.NotNull(evt.DurationMs);
Assert.True(evt.DurationMs >= 0, $"DurationMs={evt.DurationMs} should be >= 0");
Assert.True(evt.DurationMs <= 5000, $"DurationMs={evt.DurationMs} should be <= 5000");
}
}