feat(auditlog): per-script-execution correlation id on sync audit rows

This commit is contained in:
Joseph Doherty
2026-05-21 13:46:34 -04:00
parent 53508c79b2
commit 8243f61e96
11 changed files with 188 additions and 6 deletions

View File

@@ -145,6 +145,10 @@ public sealed class AuditWriteMiddleware
OccurredAtUtc = DateTime.UtcNow,
Channel = AuditChannel.ApiInbound,
Kind = kind,
// Audit Log #23: a fresh per-request correlation id so the
// inbound row carries a request identifier (closes the design
// gap that inbound rows should be correlatable).
CorrelationId = Guid.NewGuid(),
Actor = actor,
Target = methodName,
Status = status,

View File

@@ -37,6 +37,7 @@ internal sealed class AuditingDbCommand : DbCommand
private readonly string _siteId;
private readonly string _instanceName;
private readonly string? _sourceScript;
private readonly Guid _correlationId;
private readonly ILogger _logger;
private DbConnection? _wrappingConnection;
@@ -47,6 +48,7 @@ internal sealed class AuditingDbCommand : DbCommand
string siteId,
string instanceName,
string? sourceScript,
Guid correlationId,
ILogger logger)
{
_inner = inner ?? throw new ArgumentNullException(nameof(inner));
@@ -55,6 +57,7 @@ internal sealed class AuditingDbCommand : DbCommand
_siteId = siteId ?? string.Empty;
_instanceName = instanceName ?? string.Empty;
_sourceScript = sourceScript;
_correlationId = correlationId;
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
}
@@ -426,7 +429,9 @@ internal sealed class AuditingDbCommand : DbCommand
OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc),
Channel = AuditChannel.DbOutbound,
Kind = AuditKind.DbWrite,
CorrelationId = null,
// Audit Log #23: the execution-wide correlation id, so all the
// sync ApiCall/DbWrite rows from one script run share an id.
CorrelationId = _correlationId,
SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId,
SourceInstanceId = _instanceName,
SourceScript = _sourceScript,

View File

@@ -36,6 +36,7 @@ internal sealed class AuditingDbConnection : DbConnection
private readonly string _siteId;
private readonly string _instanceName;
private readonly string? _sourceScript;
private readonly Guid _correlationId;
private readonly ILogger _logger;
public AuditingDbConnection(
@@ -45,6 +46,7 @@ internal sealed class AuditingDbConnection : DbConnection
string siteId,
string instanceName,
string? sourceScript,
Guid correlationId,
ILogger logger)
{
_inner = inner ?? throw new ArgumentNullException(nameof(inner));
@@ -53,6 +55,7 @@ internal sealed class AuditingDbConnection : DbConnection
_siteId = siteId ?? string.Empty;
_instanceName = instanceName ?? string.Empty;
_sourceScript = sourceScript;
_correlationId = correlationId;
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
}
@@ -92,6 +95,7 @@ internal sealed class AuditingDbConnection : DbConnection
_siteId,
_instanceName,
_sourceScript,
_correlationId,
_logger);
}

View File

@@ -105,6 +105,21 @@ public class ScriptRuntimeContext
/// </summary>
private readonly ICachedCallTelemetryForwarder? _cachedForwarder;
/// <summary>
/// Audit Log #23: the execution-wide audit correlation id. Every sync
/// trust-boundary audit row emitted by this script execution
/// (<c>ApiCall</c>, <c>DbWrite</c>) is stamped with this id so all the
/// rows from one script run can be correlated together.
/// </summary>
private readonly Guid _correlationId;
/// <param name="correlationId">
/// Audit Log #23: the execution-wide audit correlation id. When omitted
/// (tag-change / timer-triggered executions) a fresh id is generated; an
/// inbound caller may supply one to tie the execution to an upstream
/// request. Stamped on the sync <c>ApiCall</c>/<c>DbWrite</c> audit rows
/// this execution emits.
/// </param>
public ScriptRuntimeContext(
IActorRef instanceActor,
IActorRef self,
@@ -122,7 +137,8 @@ public class ScriptRuntimeContext
string? sourceScript = null,
IAuditWriter? auditWriter = null,
IOperationTrackingStore? operationTrackingStore = null,
ICachedCallTelemetryForwarder? cachedForwarder = null)
ICachedCallTelemetryForwarder? cachedForwarder = null,
Guid? correlationId = null)
{
_instanceActor = instanceActor;
_self = self;
@@ -141,6 +157,7 @@ public class ScriptRuntimeContext
_auditWriter = auditWriter;
_operationTrackingStore = operationTrackingStore;
_cachedForwarder = cachedForwarder;
_correlationId = correlationId ?? Guid.NewGuid();
}
/// <summary>
@@ -241,7 +258,7 @@ public class ScriptRuntimeContext
/// ExternalSystem.CachedCall("systemName", "methodName", params)
/// </summary>
public ExternalSystemHelper ExternalSystem => new(
_externalSystemClient, _instanceName, _logger, _auditWriter, _siteId, _sourceScript,
_externalSystemClient, _instanceName, _logger, _correlationId, _auditWriter, _siteId, _sourceScript,
// Audit Log #23 (M3 Bundle E — Task E3): emit CachedSubmit telemetry
// on every ExternalSystem.CachedCall enqueue.
_cachedForwarder);
@@ -255,6 +272,7 @@ public class ScriptRuntimeContext
_databaseGateway,
_instanceName,
_logger,
_correlationId,
// Audit Log #23 (M4 Bundle A): wire the IAuditWriter so
// Database.Connection(name) returns an auditing decorator that
// emits one DbOutbound/DbWrite row per script-initiated
@@ -362,6 +380,7 @@ public class ScriptRuntimeContext
private readonly IExternalSystemClient? _client;
private readonly string _instanceName;
private readonly ILogger _logger;
private readonly Guid _correlationId;
private readonly IAuditWriter? _auditWriter;
private readonly string _siteId;
private readonly string? _sourceScript;
@@ -374,6 +393,7 @@ public class ScriptRuntimeContext
IExternalSystemClient? client,
string instanceName,
ILogger logger,
Guid correlationId,
IAuditWriter? auditWriter = null,
string siteId = "",
string? sourceScript = null,
@@ -382,6 +402,7 @@ public class ScriptRuntimeContext
_client = client;
_instanceName = instanceName;
_logger = logger;
_correlationId = correlationId;
_auditWriter = auditWriter;
_siteId = siteId;
_sourceScript = sourceScript;
@@ -882,7 +903,9 @@ public class ScriptRuntimeContext
OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc),
Channel = AuditChannel.ApiOutbound,
Kind = AuditKind.ApiCall,
CorrelationId = null,
// Audit Log #23: the execution-wide correlation id, so all the
// sync ApiCall/DbWrite rows from one script run share an id.
CorrelationId = _correlationId,
SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId,
SourceInstanceId = _instanceName,
SourceScript = _sourceScript,
@@ -949,6 +972,7 @@ public class ScriptRuntimeContext
private readonly IDatabaseGateway? _gateway;
private readonly string _instanceName;
private readonly ILogger _logger;
private readonly Guid _correlationId;
private readonly string _siteId;
private readonly string? _sourceScript;
private readonly ICachedCallTelemetryForwarder? _cachedForwarder;
@@ -969,6 +993,7 @@ public class ScriptRuntimeContext
IDatabaseGateway? gateway,
string instanceName,
ILogger logger,
Guid correlationId,
IAuditWriter? auditWriter = null,
string siteId = "",
string? sourceScript = null,
@@ -977,6 +1002,7 @@ public class ScriptRuntimeContext
_gateway = gateway;
_instanceName = instanceName;
_logger = logger;
_correlationId = correlationId;
_auditWriter = auditWriter;
_siteId = siteId;
_sourceScript = sourceScript;
@@ -1011,6 +1037,7 @@ public class ScriptRuntimeContext
siteId: _siteId,
instanceName: _instanceName,
sourceScript: _sourceScript,
correlationId: _correlationId,
logger: _logger);
}

View File

@@ -150,6 +150,7 @@ public class AuditWriteFailureSafetyTests : TestKit, IClassFixture<MsSqlMigratio
client,
instanceName: "Plant.Pump42",
NullLogger.Instance,
Guid.NewGuid(),
auditWriter: writer,
siteId: "site-77",
sourceScript: "ScriptActor:Sync",
@@ -193,6 +194,7 @@ public class AuditWriteFailureSafetyTests : TestKit, IClassFixture<MsSqlMigratio
client,
instanceName: "Plant.Pump42",
NullLogger.Instance,
Guid.NewGuid(),
auditWriter: writer,
siteId: "site-77",
sourceScript: "ScriptActor:Cached",
@@ -243,6 +245,7 @@ public class AuditWriteFailureSafetyTests : TestKit, IClassFixture<MsSqlMigratio
gateway,
instanceName,
NullLogger.Instance,
Guid.NewGuid(),
auditWriter: writer,
siteId: "site-77",
sourceScript: "ScriptActor:Db",

View File

@@ -157,6 +157,7 @@ public class DatabaseSyncEmissionEndToEndTests : TestKit, IClassFixture<MsSqlMig
gateway,
InstanceName,
NullLogger.Instance,
Guid.NewGuid(),
auditWriter: writer,
siteId: siteId,
sourceScript: SourceScript,

View File

@@ -350,6 +350,46 @@ public class AuditWriteMiddlewareTests
Assert.Equal(requestJson, evt.RequestSummary);
}
// ---------------------------------------------------------------------
// Correlation id — Audit Log #23: each inbound row carries a fresh
// per-request correlation id so inbound rows are correlatable.
// ---------------------------------------------------------------------
[Fact]
public async Task InboundRow_CarriesNonNull_CorrelationId()
{
var writer = new RecordingAuditWriter();
var ctx = BuildContext();
var mw = CreateMiddleware(_ =>
{
ctx.Response.StatusCode = 200;
return Task.CompletedTask;
}, writer);
await mw.InvokeAsync(ctx);
var evt = Assert.Single(writer.Events);
Assert.NotNull(evt.CorrelationId);
Assert.NotEqual(Guid.Empty, evt.CorrelationId!.Value);
}
[Fact]
public async Task SeparateRequests_GetDistinct_CorrelationIds()
{
var writer = new RecordingAuditWriter();
var mw = CreateMiddleware(hc =>
{
hc.Response.StatusCode = 200;
return Task.CompletedTask;
}, writer);
await mw.InvokeAsync(BuildContext());
await mw.InvokeAsync(BuildContext());
Assert.Equal(2, writer.Events.Count);
Assert.NotEqual(writer.Events[0].CorrelationId, writer.Events[1].CorrelationId);
}
[Fact]
public async Task DurationMs_IsRecorded()
{

View File

@@ -47,6 +47,9 @@ public class DatabaseCachedWriteEmissionTests
gateway,
InstanceName,
NullLogger.Instance,
// Audit Log #23: execution-wide correlation id. Cached rows keep
// CorrelationId = TrackedOperationId, so any value works here.
Guid.NewGuid(),
siteId: SiteId,
sourceScript: SourceScript,
cachedForwarder: forwarder);

View File

@@ -48,14 +48,28 @@ public class DatabaseSyncEmissionTests
private const string SourceScript = "ScriptActor:Sync";
private const string ConnectionName = "machineData";
/// <summary>
/// Audit Log #23: a fixed execution-wide correlation id used by the
/// default <see cref="CreateHelper(IDatabaseGateway, IAuditWriter?)"/>
/// overload so assertions can compare against a known value.
/// </summary>
private static readonly Guid TestCorrelationId = Guid.NewGuid();
private static ScriptRuntimeContext.DatabaseHelper CreateHelper(
IDatabaseGateway gateway,
IAuditWriter? auditWriter)
=> CreateHelper(gateway, auditWriter, TestCorrelationId);
private static ScriptRuntimeContext.DatabaseHelper CreateHelper(
IDatabaseGateway gateway,
IAuditWriter? auditWriter,
Guid correlationId)
{
return new ScriptRuntimeContext.DatabaseHelper(
gateway,
InstanceName,
NullLogger.Instance,
correlationId,
auditWriter: auditWriter,
siteId: SiteId,
sourceScript: SourceScript,
@@ -268,10 +282,34 @@ public class DatabaseSyncEmissionTests
Assert.Equal(SourceScript, evt.SourceScript);
// Outbound channel: Actor carries the calling script identity.
Assert.Equal(SourceScript, evt.Actor);
Assert.Null(evt.CorrelationId);
// Audit Log #23: the sync DbWrite row now carries the execution-wide
// correlation id the helper was constructed with.
Assert.Equal(TestCorrelationId, evt.CorrelationId);
Assert.NotEqual(Guid.Empty, evt.EventId);
}
[Fact]
public async Task SyncDbWrite_StampsExecutionCorrelationId()
{
using var keepAlive = new SqliteConnection("Data Source=kc;Mode=Memory;Cache=Shared");
var inner = NewInMemoryDb(out var _);
var gateway = new Mock<IDatabaseGateway>();
gateway
.Setup(g => g.GetConnectionAsync(ConnectionName, It.IsAny<CancellationToken>()))
.ReturnsAsync(inner);
var writer = new CapturingAuditWriter();
var correlationId = Guid.NewGuid();
var helper = CreateHelper(gateway.Object, writer, correlationId);
await using var conn = await helper.Connection(ConnectionName);
await using var cmd = conn.CreateCommand();
cmd.CommandText = "INSERT INTO t (id, name) VALUES (7, 'eta')";
await cmd.ExecuteNonQueryAsync();
var evt = Assert.Single(writer.Events);
Assert.Equal(correlationId, evt.CorrelationId);
}
[Fact]
public async Task DurationMs_NonZero()
{

View File

@@ -49,6 +49,9 @@ public class ExternalSystemCachedCallEmissionTests
client,
InstanceName,
NullLogger.Instance,
// Audit Log #23: execution-wide correlation id. Cached rows keep
// CorrelationId = TrackedOperationId, so any value works here.
Guid.NewGuid(),
auditWriter: null,
siteId: SiteId,
sourceScript: SourceScript,

View File

@@ -45,14 +45,28 @@ public class ExternalSystemCallAuditEmissionTests
private const string InstanceName = "Plant.Pump42";
private const string SourceScript = "ScriptActor:CheckPressure";
/// <summary>
/// Audit Log #23: a fixed execution-wide correlation id used by the
/// default <see cref="CreateHelper(IExternalSystemClient, IAuditWriter?)"/>
/// overload so assertions can compare against a known value.
/// </summary>
private static readonly Guid TestCorrelationId = Guid.NewGuid();
private static ScriptRuntimeContext.ExternalSystemHelper CreateHelper(
IExternalSystemClient client,
IAuditWriter? auditWriter)
=> CreateHelper(client, auditWriter, TestCorrelationId);
private static ScriptRuntimeContext.ExternalSystemHelper CreateHelper(
IExternalSystemClient client,
IAuditWriter? auditWriter,
Guid correlationId)
{
return new ScriptRuntimeContext.ExternalSystemHelper(
client,
InstanceName,
NullLogger.Instance,
correlationId,
auditWriter,
SiteId,
SourceScript);
@@ -211,7 +225,47 @@ public class ExternalSystemCallAuditEmissionTests
Assert.Equal(SourceScript, evt.SourceScript);
// Outbound channel: Actor carries the calling script identity.
Assert.Equal(SourceScript, evt.Actor);
Assert.Null(evt.CorrelationId);
// Audit Log #23: the sync ApiCall row now carries the execution-wide
// correlation id the helper was constructed with.
Assert.Equal(TestCorrelationId, evt.CorrelationId);
}
[Fact]
public async Task Call_SyncApiCall_StampsExecutionCorrelationId()
{
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 correlationId = Guid.NewGuid();
var helper = CreateHelper(client.Object, writer, correlationId);
await helper.Call("ERP", "GetOrder");
var evt = Assert.Single(writer.Events);
Assert.Equal(correlationId, evt.CorrelationId);
}
[Fact]
public async Task Call_TwoCallsOnSameHelper_ShareTheSameCorrelationId()
{
var client = new Mock<IExternalSystemClient>();
client
.Setup(c => c.CallAsync(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<IReadOnlyDictionary<string, object?>?>(), It.IsAny<CancellationToken>()))
.ReturnsAsync(new ExternalCallResult(true, "{}", null));
var writer = new CapturingAuditWriter();
var correlationId = Guid.NewGuid();
var helper = CreateHelper(client.Object, writer, correlationId);
await helper.Call("ERP", "GetOrder");
await helper.Call("ERP", "GetCustomer");
Assert.Equal(2, writer.Events.Count);
// Both sync ApiCall rows from one execution carry the same id.
Assert.Equal(correlationId, writer.Events[0].CorrelationId);
Assert.Equal(correlationId, writer.Events[1].CorrelationId);
Assert.Equal(writer.Events[0].CorrelationId, writer.Events[1].CorrelationId);
}
[Fact]