Files
scadalink-design/tests/ScadaLink.AuditLog.Tests/Site/Telemetry/CachedCallLifecycleBridgeTests.cs
Joseph Doherty 6f5a35f222 feat(auditlog): thread ExecutionId through S&F for retry-loop cached rows
The store-and-forward retry loop emits the per-attempt and terminal cached
audit rows (ApiCallCached/DbWriteCached Attempted, CachedResolve) via
CachedCallLifecycleBridge from a CachedCallAttemptContext, not from the
script context. ExecutionId (and SourceScript) were not threaded through the
S&F buffer, so those rows had ExecutionId = null and SourceScript = null.

Thread both, additively, from the cached-call enqueue path:

- StoreAndForwardMessage gains ExecutionId (Guid?) / SourceScript (string?).
- StoreAndForwardStorage adds nullable execution_id / source_script columns
  via an idempotent PRAGMA-probed ALTER TABLE migration; rows persisted by
  an older build read back null (back-compat).
- StoreAndForwardService.EnqueueAsync gains optional executionId /
  sourceScript params, stamped onto the buffered message and surfaced on the
  CachedCallAttemptContext built in the retry loop.
- CachedCallAttemptContext gains ExecutionId / SourceScript.
- CachedCallLifecycleBridge.BuildPacket sets AuditEvent.ExecutionId and
  AuditEvent.SourceScript from the context (replacing the hard-coded
  SourceScript = null and its now-stale comment).
- IExternalSystemClient.CachedCallAsync / IDatabaseGateway.CachedWriteAsync
  gain optional executionId / sourceScript params; ScriptRuntimeContext's
  CachedCall / CachedWrite helpers pass _executionId / _sourceScript.

Script-side cached rows (CachedSubmit, immediate Attempted+Resolve) are
unchanged. All threading is additive — old buffered S&F rows still
deserialize and process with the new fields null.
2026-05-21 15:18:35 -04:00

263 lines
11 KiB
C#

using Microsoft.Extensions.Logging.Abstractions;
using NSubstitute;
using ScadaLink.AuditLog.Site.Telemetry;
using ScadaLink.Commons.Interfaces.Services;
using ScadaLink.Commons.Messages.Integration;
using ScadaLink.Commons.Types;
using ScadaLink.Commons.Types.Enums;
namespace ScadaLink.AuditLog.Tests.Site.Telemetry;
/// <summary>
/// Bundle E Tasks E4/E5 bridge tests. The bridge ingests
/// <see cref="CachedCallAttemptContext"/> notifications from the S&amp;F
/// retry loop and routes them through <see cref="ICachedCallTelemetryForwarder"/>
/// as one or two <see cref="CachedCallTelemetry"/> packets:
/// <list type="bullet">
/// <item><description>Per-attempt: one <c>ApiCallCached</c>/<c>DbWriteCached</c> Attempted row.</description></item>
/// <item><description>Terminal (Delivered/PermanentFailure/ParkedMaxRetries): adds a CachedResolve row carrying the terminal Status.</description></item>
/// </list>
/// </summary>
public class CachedCallLifecycleBridgeTests
{
private readonly ICachedCallTelemetryForwarder _forwarder = Substitute.For<ICachedCallTelemetryForwarder>();
private readonly TrackedOperationId _id = TrackedOperationId.New();
private CachedCallLifecycleBridge CreateSut() => new(
_forwarder, NullLogger<CachedCallLifecycleBridge>.Instance);
private CachedCallAttemptContext Ctx(
CachedCallAttemptOutcome outcome,
string channel = "ApiOutbound",
int retryCount = 1,
string? lastError = null,
int? httpStatus = null,
Guid? executionId = null,
string? sourceScript = null) =>
new(
TrackedOperationId: _id,
Channel: channel,
Target: "ERP.GetOrder",
SourceSite: "site-77",
Outcome: outcome,
RetryCount: retryCount,
LastError: lastError,
HttpStatus: httpStatus,
CreatedAtUtc: new DateTime(2026, 5, 20, 9, 0, 0, DateTimeKind.Utc),
OccurredAtUtc: new DateTime(2026, 5, 20, 10, 0, 0, DateTimeKind.Utc),
DurationMs: 42,
SourceInstanceId: "Plant.Pump42",
ExecutionId: executionId,
SourceScript: sourceScript);
[Fact]
public async Task TransientFailure_EmitsOneAttemptedRow_NoResolve()
{
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.TransientFailure,
retryCount: 2,
lastError: "HTTP 503",
httpStatus: 503));
var packet = Assert.Single(captured);
Assert.Equal(AuditKind.ApiCallCached, packet.Audit.Kind);
Assert.Equal(AuditStatus.Attempted, packet.Audit.Status);
Assert.Equal(503, packet.Audit.HttpStatus);
Assert.Equal("HTTP 503", packet.Audit.ErrorMessage);
Assert.Equal(_id.Value, packet.Audit.CorrelationId);
Assert.Equal("Attempted", packet.Operational.Status);
Assert.Equal(2, packet.Operational.RetryCount);
Assert.Null(packet.Operational.TerminalAtUtc);
}
[Fact]
public async Task Delivered_EmitsAttemptedRow_AndCachedResolveDelivered()
{
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(CachedCallAttemptOutcome.Delivered));
Assert.Equal(2, captured.Count);
var attempted = captured[0];
Assert.Equal(AuditKind.ApiCallCached, attempted.Audit.Kind);
Assert.Equal(AuditStatus.Attempted, attempted.Audit.Status);
Assert.Equal("Attempted", attempted.Operational.Status);
Assert.Null(attempted.Operational.TerminalAtUtc);
var resolve = captured[1];
Assert.Equal(AuditKind.CachedResolve, resolve.Audit.Kind);
Assert.Equal(AuditStatus.Delivered, resolve.Audit.Status);
Assert.Equal("Delivered", resolve.Operational.Status);
Assert.NotNull(resolve.Operational.TerminalAtUtc);
Assert.Equal(_id.Value, resolve.Audit.CorrelationId);
}
[Fact]
public async Task PermanentFailure_EmitsAttempted_AndCachedResolveParked()
{
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.PermanentFailure,
lastError: "Permanent failure (handler returned false)"));
Assert.Equal(2, captured.Count);
Assert.Equal(AuditKind.ApiCallCached, captured[0].Audit.Kind);
Assert.Equal(AuditKind.CachedResolve, captured[1].Audit.Kind);
Assert.Equal(AuditStatus.Parked, captured[1].Audit.Status);
Assert.Equal("Parked", captured[1].Operational.Status);
}
[Fact]
public async Task ParkedMaxRetries_EmitsAttempted_AndCachedResolveParked()
{
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(CachedCallAttemptOutcome.ParkedMaxRetries));
Assert.Equal(2, captured.Count);
Assert.Equal(AuditKind.CachedResolve, captured[1].Audit.Kind);
Assert.Equal(AuditStatus.Parked, captured[1].Audit.Status);
}
[Fact]
public async Task DbChannel_MapsToDbWriteCachedKind_AndDbOutboundChannel()
{
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.Delivered, channel: "DbOutbound"));
Assert.Equal(2, captured.Count);
Assert.Equal(AuditKind.DbWriteCached, captured[0].Audit.Kind);
Assert.Equal(AuditChannel.DbOutbound, captured[0].Audit.Channel);
Assert.Equal("DbOutbound", captured[0].Operational.Channel);
Assert.Equal(AuditKind.CachedResolve, captured[1].Audit.Kind);
Assert.Equal(AuditChannel.DbOutbound, captured[1].Audit.Channel);
}
[Fact]
public async Task BridgeDoesNotThrow_WhenForwarderThrows()
{
_forwarder
.ForwardAsync(Arg.Any<CachedCallTelemetry>(), Arg.Any<CancellationToken>())
.Returns(Task.FromException(new InvalidOperationException("forwarder down")));
var sut = CreateSut();
// Must not throw — best-effort emission.
await sut.OnAttemptCompletedAsync(Ctx(CachedCallAttemptOutcome.Delivered));
}
[Fact]
public async Task BridgePopulatesProvenance_FromAttemptContext()
{
CachedCallTelemetry? captured = null;
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured = t), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.TransientFailure,
retryCount: 3,
lastError: "transient",
httpStatus: 500));
Assert.NotNull(captured);
Assert.Equal("site-77", captured!.Audit.SourceSiteId);
Assert.Equal("Plant.Pump42", captured.Audit.SourceInstanceId);
Assert.Equal("ERP.GetOrder", captured.Audit.Target);
Assert.Equal(42, captured.Audit.DurationMs);
Assert.Equal(_id.Value, captured.Audit.CorrelationId);
}
// ── Audit Log #23 (ExecutionId Task 4): ExecutionId / SourceScript ──
[Fact]
public async Task RetryLoopAttemptedRow_CarriesExecutionIdAndSourceScript_FromContext()
{
// Task 4: the ExecutionId + SourceScript threaded through the S&F
// buffer arrive on the CachedCallAttemptContext; the bridge must stamp
// both onto the per-attempt ApiCallCached row (previously SourceScript
// was hard-coded null with a "not threaded through S&F" comment).
var executionId = Guid.NewGuid();
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.TransientFailure,
executionId: executionId,
sourceScript: "Plant.Pump42/OnTick"));
var packet = Assert.Single(captured);
Assert.Equal(AuditKind.ApiCallCached, packet.Audit.Kind);
Assert.Equal(executionId, packet.Audit.ExecutionId);
Assert.Equal("Plant.Pump42/OnTick", packet.Audit.SourceScript);
}
[Fact]
public async Task RetryLoopCachedResolveRow_CarriesExecutionIdAndSourceScript_FromContext()
{
// The terminal CachedResolve row must also carry the threaded
// provenance so the whole retry-loop lifecycle is correlated.
var executionId = Guid.NewGuid();
var captured = new List<CachedCallTelemetry>();
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured.Add(t)), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(
CachedCallAttemptOutcome.Delivered,
channel: "DbOutbound",
executionId: executionId,
sourceScript: "Plant.Tank/OnAlarm"));
Assert.Equal(2, captured.Count);
var resolve = Assert.Single(captured, p => p.Audit.Kind == AuditKind.CachedResolve);
Assert.Equal(executionId, resolve.Audit.ExecutionId);
Assert.Equal("Plant.Tank/OnAlarm", resolve.Audit.SourceScript);
var attempted = Assert.Single(captured, p => p.Audit.Kind == AuditKind.DbWriteCached);
Assert.Equal(executionId, attempted.Audit.ExecutionId);
Assert.Equal("Plant.Tank/OnAlarm", attempted.Audit.SourceScript);
}
[Fact]
public async Task RetryLoopRow_NullExecutionIdAndSourceScript_RemainNull()
{
// Back-compat: a pre-Task-4 buffered row has no ExecutionId /
// SourceScript; the bridge must leave the audit row's fields null
// rather than throwing.
CachedCallTelemetry? captured = null;
_forwarder.ForwardAsync(Arg.Do<CachedCallTelemetry>(t => captured = t), Arg.Any<CancellationToken>())
.Returns(Task.CompletedTask);
var sut = CreateSut();
await sut.OnAttemptCompletedAsync(Ctx(CachedCallAttemptOutcome.TransientFailure));
Assert.NotNull(captured);
Assert.Null(captured!.Audit.ExecutionId);
Assert.Null(captured.Audit.SourceScript);
}
}