diff --git a/src/ScadaLink.SiteRuntime/Actors/ScriptExecutionActor.cs b/src/ScadaLink.SiteRuntime/Actors/ScriptExecutionActor.cs index 85cea1c..a812158 100644 --- a/src/ScadaLink.SiteRuntime/Actors/ScriptExecutionActor.cs +++ b/src/ScadaLink.SiteRuntime/Actors/ScriptExecutionActor.cs @@ -101,6 +101,10 @@ public class ScriptExecutionActor : ReceiveActor // provider supplies the site id stamped on enqueued notifications. StoreAndForwardService? storeAndForward = null; 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) { @@ -110,6 +114,7 @@ public class ScriptExecutionActor : ReceiveActor storeAndForward = serviceScope.ServiceProvider.GetService(); siteId = serviceScope.ServiceProvider.GetService()?.SiteId ?? string.Empty; + auditWriter = serviceScope.ServiceProvider.GetService(); } var context = new ScriptRuntimeContext( @@ -128,7 +133,12 @@ public class ScriptExecutionActor : ReceiveActor siteId, // Notification Outbox (FU3): stamp the executing script onto outbound // 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 { diff --git a/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs index ba00063..2ac8a38 100644 --- a/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -1,6 +1,9 @@ +using System.Diagnostics; using System.Text.Json; +using System.Text.RegularExpressions; using Akka.Actor; using Microsoft.Extensions.Logging; +using ScadaLink.Commons.Entities.Audit; using ScadaLink.Commons.Interfaces.Services; using ScadaLink.Commons.Messages.Instance; using ScadaLink.Commons.Messages.Notification; @@ -75,6 +78,13 @@ public class ScriptRuntimeContext /// private readonly string? _sourceScript; + /// + /// 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. + /// + private readonly IAuditWriter? _auditWriter; + public ScriptRuntimeContext( IActorRef instanceActor, IActorRef self, @@ -89,7 +99,8 @@ public class ScriptRuntimeContext StoreAndForwardService? storeAndForward = null, ICanTell? siteCommunicationActor = null, string siteId = "", - string? sourceScript = null) + string? sourceScript = null, + IAuditWriter? auditWriter = null) { _instanceActor = instanceActor; _self = self; @@ -105,6 +116,7 @@ public class ScriptRuntimeContext _siteCommunicationActor = siteCommunicationActor; _siteId = siteId; _sourceScript = sourceScript; + _auditWriter = auditWriter; } /// @@ -204,7 +216,8 @@ public class ScriptRuntimeContext /// ExternalSystem.Call("systemName", "methodName", params) /// ExternalSystem.CachedCall("systemName", "methodName", params) /// - public ExternalSystemHelper ExternalSystem => new(_externalSystemClient, _instanceName, _logger); + public ExternalSystemHelper ExternalSystem => new( + _externalSystemClient, _instanceName, _logger, _auditWriter, _siteId, _sourceScript); /// /// WP-13: Provides access to database operations. @@ -275,17 +288,41 @@ public class ScriptRuntimeContext /// /// WP-13: Helper for ExternalSystem.Call/CachedCall syntax. /// + /// + /// Audit Log #23 (M2 Bundle F): every invocation emits + /// one ApiOutbound/ApiCall audit row via . + /// 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 + /// (or the original thrown exception) flows back to the caller unchanged. + /// public class ExternalSystemHelper { + private static readonly Regex HttpStatusRegex = new( + @"HTTP\s+(?\d{3})", + RegexOptions.Compiled | RegexOptions.CultureInvariant); + private readonly IExternalSystemClient? _client; private readonly string _instanceName; 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; _instanceName = instanceName; _logger = logger; + _auditWriter = auditWriter; + _siteId = siteId; + _sourceScript = sourceScript; } public async Task Call( @@ -297,7 +334,31 @@ public class ScriptRuntimeContext if (_client == null) 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 CachedCall( @@ -311,6 +372,145 @@ public class ScriptRuntimeContext return await _client.CachedCallAsync(systemName, methodName, parameters, _instanceName, cancellationToken); } + + /// + /// Best-effort emission of one ApiOutbound/ApiCall audit + /// row. Any exception thrown by the writer is logged and swallowed — + /// audit-write failures must never abort the user-facing action. + /// + 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, + }; + } } /// diff --git a/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCallAuditEmissionTests.cs b/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCallAuditEmissionTests.cs new file mode 100644 index 0000000..59a0e7a --- /dev/null +++ b/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCallAuditEmissionTests.cs @@ -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; + +/// +/// Audit Log #23 — M2 Bundle F (Task F1): every script-initiated +/// ExternalSystem.Call emits exactly one ApiOutbound/ApiCall +/// audit event via the wrapper inside +/// . The audit emission +/// is best-effort: a thrown must never +/// abort the script's call, and the original +/// (or original exception) must surface to the caller unchanged. +/// +public class ExternalSystemCallAuditEmissionTests +{ + /// + /// In-memory that records every event passed to + /// . Optionally configurable to throw, simulating a + /// catastrophic audit-writer failure that the wrapper must swallow. + /// + private sealed class CapturingAuditWriter : IAuditWriter + { + public List 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(); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .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(); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .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(); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .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(); + var networkEx = new HttpRequestException("network down"); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .ThrowsAsync(networkEx); + var writer = new CapturingAuditWriter(); + + var helper = CreateHelper(client.Object, writer); + var thrown = await Assert.ThrowsAsync(() => 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(); + var expected = new ExternalCallResult(true, "{\"v\":1}", null); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .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(); + client + .Setup(c => c.CallAsync("ERP", "GetOrder", It.IsAny?>(), It.IsAny())) + .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(); + client + .Setup(c => c.CallAsync("ERP", "Slow", It.IsAny?>(), It.IsAny())) + .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"); + } +}