diff --git a/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs index f8c6b3b..b5eceaa 100644 --- a/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ScadaLink.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -446,13 +446,20 @@ public class ScriptRuntimeContext // Hand off to the existing cached-call path. The TrackedOperationId // becomes the S&F message id so the retry loop (Bundle E Tasks - // E4/E5) can read it back via StoreAndForwardMessage.Id. The - // underlying ExternalCallResult is intentionally discarded — the - // script's contract is now "return the tracking id, observe outcome - // via Tracking.Status". + // E4/E5) can read it back via StoreAndForwardMessage.Id. + // + // M3 Bundle F (F2): the result is now retained because the + // immediate-success path (WasBuffered=false) bypasses S&F entirely + // — no retry loop, no ICachedCallLifecycleObserver fire. The + // helper must emit the Attempted + CachedResolve terminal rows + // itself, otherwise Tracking.Status(id) would stay in Submitted + // forever and the audit log would be missing the M3 lifecycle. + // The WasBuffered=true path is unaffected — the S&F retry loop + // owns the Attempted + Resolve emissions in that case. + ExternalCallResult? result; try { - await _client.CachedCallAsync( + result = await _client.CachedCallAsync( systemName, methodName, parameters, @@ -473,6 +480,16 @@ public class ScriptRuntimeContext throw; } + // M3 Bundle F (F2): immediate-completion lifecycle — emit the + // missing Attempted + CachedResolve rows when the underlying call + // resolved without engaging the store-and-forward retry loop. + if (result is { WasBuffered: false }) + { + await EmitImmediateTerminalTelemetryAsync( + systemName, methodName, target, trackedId, result, cancellationToken) + .ConfigureAwait(false); + } + return trackedId; } @@ -546,6 +563,177 @@ public class ScriptRuntimeContext } } + /// + /// M3 Bundle F (F2): emit the Attempted + CachedResolve lifecycle + /// rows for an immediate-completion CachedCall (WasBuffered=false). + /// The S&F retry loop never engaged, so the + /// ICachedCallLifecycleObserver never fires — the helper must + /// produce both rows itself to keep the M3 audit contract whole + /// (Submit → Attempted → Resolve under one TrackedOperationId). + /// + /// + /// Best-effort emission: a throwing forwarder is logged and swallowed + /// per alog.md §7. The two rows are emitted INDEPENDENTLY so a single + /// forwarder fault doesn't drop both halves of the terminal pair. + /// + private async Task EmitImmediateTerminalTelemetryAsync( + string systemName, + string methodName, + string target, + TrackedOperationId trackedId, + ExternalCallResult result, + CancellationToken cancellationToken) + { + if (_cachedForwarder == null) + { + return; + } + + var occurredAtUtc = DateTime.UtcNow; + // Extract an HTTP status from the error message when present + // (mirrors EmitCallAudit's existing HttpStatusRegex behaviour so + // the immediate-failure row carries the same HttpStatus value the + // synchronous Call() audit row would have stamped). + int? httpStatus = null; + if (!result.Success && !string.IsNullOrEmpty(result.ErrorMessage)) + { + var match = HttpStatusRegex.Match(result.ErrorMessage); + if (match.Success && int.TryParse(match.Groups["code"].Value, out var code)) + { + httpStatus = code; + } + } + + // Status mapping for immediate completion: + // Success=true -> Delivered (audit) / "Delivered" (operational) + // Success=false -> Failed (audit) / "Failed" (operational) + // Permanent vs transient is not relevant here: a permanent failure + // returns Success=false WasBuffered=false (parked-equivalent); a + // transient failure with NO S&F engine wired likewise lands here + // with Success=false. Either way the terminal state is "the + // immediate attempt failed and the operation is done". + var auditTerminalStatus = result.Success + ? AuditStatus.Delivered + : AuditStatus.Failed; + var operationalTerminalStatus = result.Success ? "Delivered" : "Failed"; + + // --- Attempted row ------------------------------------------------- + CachedCallTelemetry attempted; + try + { + attempted = new CachedCallTelemetry( + Audit: new AuditEvent + { + EventId = Guid.NewGuid(), + OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc), + Channel = AuditChannel.ApiOutbound, + Kind = AuditKind.ApiCallCached, + CorrelationId = trackedId.Value, + SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId, + SourceInstanceId = _instanceName, + SourceScript = _sourceScript, + Target = target, + Status = AuditStatus.Attempted, + HttpStatus = httpStatus, + ErrorMessage = result.Success ? null : result.ErrorMessage, + ForwardState = AuditForwardState.Pending, + }, + Operational: new SiteCallOperational( + TrackedOperationId: trackedId, + Channel: "ApiOutbound", + Target: target, + SourceSite: _siteId, + Status: "Attempted", + // RetryCount stays 0 — the operation never reached the + // S&F retry sweep, so no retries were performed. + RetryCount: 0, + LastError: result.Success ? null : result.ErrorMessage, + HttpStatus: httpStatus, + CreatedAtUtc: occurredAtUtc, + UpdatedAtUtc: occurredAtUtc, + TerminalAtUtc: null)); + } + catch (Exception buildEx) + { + _logger.LogWarning(buildEx, + "Failed to build immediate-Attempted telemetry for {System}.{Method} (TrackedOperationId {Id}) — skipping emission", + systemName, methodName, trackedId); + attempted = null!; + } + + if (attempted is not null) + { + try + { + await _cachedForwarder.ForwardAsync(attempted, cancellationToken) + .ConfigureAwait(false); + } + catch (Exception ex) + { + _logger.LogWarning(ex, + "Immediate-Attempted telemetry forward failed for {System}.{Method} (TrackedOperationId {Id})", + systemName, methodName, trackedId); + } + } + + // --- CachedResolve row -------------------------------------------- + CachedCallTelemetry resolve; + try + { + resolve = new CachedCallTelemetry( + Audit: new AuditEvent + { + EventId = Guid.NewGuid(), + OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc), + Channel = AuditChannel.ApiOutbound, + Kind = AuditKind.CachedResolve, + CorrelationId = trackedId.Value, + SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId, + SourceInstanceId = _instanceName, + SourceScript = _sourceScript, + Target = target, + Status = auditTerminalStatus, + HttpStatus = httpStatus, + ErrorMessage = result.Success ? null : result.ErrorMessage, + ForwardState = AuditForwardState.Pending, + }, + Operational: new SiteCallOperational( + TrackedOperationId: trackedId, + Channel: "ApiOutbound", + Target: target, + SourceSite: _siteId, + Status: operationalTerminalStatus, + RetryCount: 0, + LastError: result.Success ? null : result.ErrorMessage, + HttpStatus: httpStatus, + CreatedAtUtc: occurredAtUtc, + UpdatedAtUtc: occurredAtUtc, + // Immediate-completion terminal — mark TerminalAtUtc so + // SiteCallAudit can move the row to its purge eligible + // set. + TerminalAtUtc: occurredAtUtc)); + } + catch (Exception buildEx) + { + _logger.LogWarning(buildEx, + "Failed to build immediate-CachedResolve telemetry for {System}.{Method} (TrackedOperationId {Id}) — skipping emission", + systemName, methodName, trackedId); + return; + } + + try + { + await _cachedForwarder.ForwardAsync(resolve, cancellationToken) + .ConfigureAwait(false); + } + catch (Exception ex) + { + _logger.LogWarning(ex, + "Immediate-CachedResolve telemetry forward failed for {System}.{Method} (TrackedOperationId {Id})", + systemName, methodName, trackedId); + } + } + /// /// Best-effort emission of one ApiOutbound/ApiCall audit /// row. Any exception thrown by the writer is logged and swallowed — diff --git a/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCachedCallEmissionTests.cs b/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCachedCallEmissionTests.cs index 294f2a8..3d56ffe 100644 --- a/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCachedCallEmissionTests.cs +++ b/tests/ScadaLink.SiteRuntime.Tests/Scripts/ExternalSystemCachedCallEmissionTests.cs @@ -218,4 +218,141 @@ public class ExternalSystemCachedCallEmissionTests trackedId), Times.Once); } + + /// + /// Audit Log #23 — M3 Bundle F (F2): when the underlying client call + /// completes immediately (no S&F buffering, WasBuffered=false), + /// the S&F retry loop never engages and the + /// ICachedCallLifecycleObserver hook never fires. The cached-call + /// helper itself must therefore emit the terminal lifecycle rows — + /// otherwise Tracking.Status(id) would return Submitted + /// forever and the audit log would be missing the Attempted / + /// CachedResolve pair the M3 contract requires. + /// + /// Expected emissions on immediate success: + /// 1. CachedSubmit / Submitted (already covered) + /// 2. ApiCallCached / Attempted + /// 3. CachedResolve / Delivered (TerminalAtUtc set) + /// + [Fact] + public async Task CachedCall_ImmediateSuccess_EmitsAttemptedAndCachedResolve() + { + var client = new Mock(); + client + .Setup(c => c.CachedCallAsync( + "ERP", "GetOrder", + It.IsAny?>(), + InstanceName, + It.IsAny(), + It.IsAny())) + // WasBuffered=false — the immediate HTTP attempt succeeded; S&F + // is bypassed entirely. + .ReturnsAsync(new ExternalCallResult(true, "{\"ok\":true}", null, WasBuffered: false)); + var forwarder = new CapturingForwarder(); + + var helper = CreateHelper(client.Object, forwarder); + var trackedId = await helper.CachedCall("ERP", "GetOrder"); + + // Three telemetry packets emitted: Submit, Attempted, Resolve. + Assert.Equal(3, forwarder.Telemetry.Count); + + var submit = forwarder.Telemetry[0]; + Assert.Equal(AuditKind.CachedSubmit, submit.Audit.Kind); + Assert.Equal(AuditStatus.Submitted, submit.Audit.Status); + Assert.Equal(trackedId, submit.Operational.TrackedOperationId); + Assert.Null(submit.Operational.TerminalAtUtc); + + var attempted = forwarder.Telemetry[1]; + Assert.Equal(AuditChannel.ApiOutbound, attempted.Audit.Channel); + Assert.Equal(AuditKind.ApiCallCached, attempted.Audit.Kind); + Assert.Equal(AuditStatus.Attempted, attempted.Audit.Status); + Assert.Equal(trackedId.Value, attempted.Audit.CorrelationId); + Assert.Equal("ERP.GetOrder", attempted.Audit.Target); + Assert.Equal(trackedId, attempted.Operational.TrackedOperationId); + Assert.Equal("Attempted", attempted.Operational.Status); + Assert.Null(attempted.Operational.TerminalAtUtc); + + var resolve = forwarder.Telemetry[2]; + Assert.Equal(AuditChannel.ApiOutbound, resolve.Audit.Channel); + Assert.Equal(AuditKind.CachedResolve, resolve.Audit.Kind); + Assert.Equal(AuditStatus.Delivered, resolve.Audit.Status); + Assert.Equal(trackedId.Value, resolve.Audit.CorrelationId); + Assert.Equal(trackedId, resolve.Operational.TrackedOperationId); + Assert.Equal("Delivered", resolve.Operational.Status); + // Terminal row carries TerminalAtUtc. + Assert.NotNull(resolve.Operational.TerminalAtUtc); + } + + /// + /// Audit Log #23 — M3 Bundle F (F2): the immediate-failure terminal + /// path. When the client returns Success=false with + /// WasBuffered=false (a permanent failure or a transient failure + /// without an S&F engine to buffer it), the cached-call helper must + /// still emit Attempted + CachedResolve with the failed status. + /// + [Fact] + public async Task CachedCall_ImmediateFailure_EmitsAttemptedAndCachedResolveFailed() + { + var client = new Mock(); + client + .Setup(c => c.CachedCallAsync( + "ERP", "GetOrder", + It.IsAny?>(), + InstanceName, + It.IsAny(), + It.IsAny())) + .ReturnsAsync(new ExternalCallResult( + false, null, "Permanent error: HTTP 422 bad payload", WasBuffered: false)); + var forwarder = new CapturingForwarder(); + + var helper = CreateHelper(client.Object, forwarder); + var trackedId = await helper.CachedCall("ERP", "GetOrder"); + + Assert.Equal(3, forwarder.Telemetry.Count); + + var attempted = forwarder.Telemetry[1]; + Assert.Equal(AuditKind.ApiCallCached, attempted.Audit.Kind); + Assert.Equal(AuditStatus.Attempted, attempted.Audit.Status); + // The per-attempt row carries the error message. + Assert.NotNull(attempted.Audit.ErrorMessage); + + var resolve = forwarder.Telemetry[2]; + Assert.Equal(AuditKind.CachedResolve, resolve.Audit.Kind); + // Immediate permanent failure -> Failed audit status / operational Failed. + Assert.Equal(AuditStatus.Failed, resolve.Audit.Status); + Assert.Equal("Failed", resolve.Operational.Status); + Assert.NotNull(resolve.Operational.TerminalAtUtc); + Assert.NotNull(resolve.Operational.LastError); + } + + /// + /// Audit Log #23 — M3 Bundle F (F2): when the client reports + /// WasBuffered=true, the helper hands the operation to S&F and + /// the retry-loop observer owns the Attempted + Resolve emissions. The + /// helper must NOT emit those rows itself (otherwise we'd get duplicate + /// Attempted + Resolve audit rows under the same tracking id). + /// + [Fact] + public async Task CachedCall_BufferedPath_DoesNotEmitTerminalTelemetryFromHelper() + { + var client = new Mock(); + client + .Setup(c => c.CachedCallAsync( + "ERP", "GetOrder", + It.IsAny?>(), + InstanceName, + It.IsAny(), + It.IsAny())) + // S&F took ownership — Attempted + Resolve come from the + // CachedCallLifecycleBridge driven by the retry loop, not the helper. + .ReturnsAsync(new ExternalCallResult(true, null, null, WasBuffered: true)); + var forwarder = new CapturingForwarder(); + + var helper = CreateHelper(client.Object, forwarder); + await helper.CachedCall("ERP", "GetOrder"); + + // Only the CachedSubmit row — no Attempted / Resolve from the helper. + var only = Assert.Single(forwarder.Telemetry); + Assert.Equal(AuditKind.CachedSubmit, only.Audit.Kind); + } }