feat(siteruntime): emit DbOutbound.DbWrite on sync Database.Execute*/ExecuteReader (#23 M4)
Audit Log #23 — M4 Bundle A (Tasks A1+A2): every script-initiated synchronous DB call routed through Database.Connection(name) now emits exactly one DbOutbound/DbWrite audit row. Implementation — three thin ADO.NET decorators in src/ScadaLink.SiteRuntime/Scripts/: - AuditingDbConnection: wraps the gateway-returned DbConnection so CreateDbCommand() hands the script an AuditingDbCommand. All other ADO.NET surface forwards unchanged. - AuditingDbCommand: intercepts ExecuteNonQuery / ExecuteScalar / ExecuteReader (sync + async). On terminal: Channel = DbOutbound, Kind = DbWrite, Status = Delivered|Failed, Extra = {"op":"write","rowsAffected":N} (Execute*), {"op":"read","rowsReturned":N} (ExecuteReader), RequestSummary = JSON of SQL + parameter values (default capture; redaction in M5), Target = "<connection>.<first 60 chars of SQL>", DurationMs captured via Stopwatch, Provenance from ScriptRuntimeContext (SourceSiteId, SourceInstanceId, SourceScript). - AuditingDbDataReader: counts rows on Read/ReadAsync and fires the audit emission exactly once on Close/CloseAsync/Dispose. DatabaseHelper now takes an IAuditWriter; ScriptRuntimeContext.Database threads through _auditWriter. When the writer is null (tests / minimal hosts) Connection() returns the raw inner DbConnection unchanged. Best-effort emission (alog.md §7): mirrors M2 Bundle F's 3-layer fail-safe — build, write, continuation. Audit-build, audit-write, and audit-continuation faults are logged + swallowed; the original ADO.NET result (or original exception) flows back to the script untouched. The SiteAuditWriteFailures counter increments automatically through the existing FallbackAuditWriter (Bundle G). Tests — tests/ScadaLink.SiteRuntime.Tests/Scripts/DatabaseSyncEmissionTests.cs (7 new, all passing): 1. Execute / INSERT success — one DbWrite row, op=write, rowsAffected=1. 2. ExecuteScalar success — one DbWrite row, op=write. 3. Execute throws — Status=Failed, ErrorMessage + ErrorDetail set. 4. ExecuteReader success — op=read, rowsReturned counts rows pulled. 5. AuditWriter throws — original ADO.NET rowsAffected returned, no events captured, no exception propagates. 6. Provenance populated from context. 7. DurationMs recorded non-zero. Tests use Microsoft.Data.Sqlite in-memory (already transitively available via SiteRuntime). Total SiteRuntime test suite: 251 passing (244 baseline + 7 new). Full solution test suite passes.
This commit is contained in:
Joseph Doherty
522
src/ScadaLink.SiteRuntime/Scripts/AuditingDbCommand.cs
Normal file
522
src/ScadaLink.SiteRuntime/Scripts/AuditingDbCommand.cs
Normal file
@@ -0,0 +1,522 @@
|
||||
using System.Data;
|
||||
using System.Data.Common;
|
||||
using System.Diagnostics;
|
||||
using Microsoft.Extensions.Logging;
|
||||
using ScadaLink.Commons.Entities.Audit;
|
||||
using ScadaLink.Commons.Interfaces.Services;
|
||||
using ScadaLink.Commons.Types.Enums;
|
||||
|
||||
namespace ScadaLink.SiteRuntime.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// Audit Log #23 — M4 Bundle A: <see cref="DbCommand"/> decorator that emits
|
||||
/// exactly one <c>DbOutbound</c>/<c>DbWrite</c> audit event per execution.
|
||||
/// </summary>
|
||||
/// <remarks>
|
||||
/// <para>
|
||||
/// <b>Vocabulary lock (M4 plan):</b> both writes (Execute / ExecuteScalar) and
|
||||
/// reads (ExecuteReader) emit <see cref="AuditKind.DbWrite"/> on the
|
||||
/// <see cref="AuditChannel.DbOutbound"/> channel. The <c>Extra</c> JSON column
|
||||
/// distinguishes them — <c>{"op":"write","rowsAffected":N}</c> for writes,
|
||||
/// <c>{"op":"read","rowsReturned":N}</c> for reads.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// <b>Best-effort emission (alog.md §7):</b> mirrors
|
||||
/// <see cref="ScriptRuntimeContext.ExternalSystemHelper"/>'s 3-layer fail-safe.
|
||||
/// The original ADO.NET result (or original exception) flows back to the
|
||||
/// script untouched; audit-build, audit-write, and audit-continuation faults
|
||||
/// are all logged + swallowed. A faulted <see cref="IAuditWriter"/> never
|
||||
/// aborts the SQL call.
|
||||
/// </para>
|
||||
/// </remarks>
|
||||
internal sealed class AuditingDbCommand : DbCommand
|
||||
{
|
||||
private readonly DbCommand _inner;
|
||||
private readonly IAuditWriter _auditWriter;
|
||||
private readonly string _connectionName;
|
||||
private readonly string _siteId;
|
||||
private readonly string _instanceName;
|
||||
private readonly string? _sourceScript;
|
||||
private readonly ILogger _logger;
|
||||
private DbConnection? _wrappingConnection;
|
||||
|
||||
public AuditingDbCommand(
|
||||
DbCommand inner,
|
||||
IAuditWriter auditWriter,
|
||||
string connectionName,
|
||||
string siteId,
|
||||
string instanceName,
|
||||
string? sourceScript,
|
||||
ILogger logger)
|
||||
{
|
||||
_inner = inner ?? throw new ArgumentNullException(nameof(inner));
|
||||
_auditWriter = auditWriter ?? throw new ArgumentNullException(nameof(auditWriter));
|
||||
_connectionName = connectionName ?? throw new ArgumentNullException(nameof(connectionName));
|
||||
_siteId = siteId ?? string.Empty;
|
||||
_instanceName = instanceName ?? string.Empty;
|
||||
_sourceScript = sourceScript;
|
||||
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
|
||||
}
|
||||
|
||||
// -- Forwarded surface ------------------------------------------------
|
||||
|
||||
#pragma warning disable CS8765 // ADO.NET base members carry pre-NRT signatures with permissive nullability
|
||||
public override string CommandText
|
||||
{
|
||||
get => _inner.CommandText;
|
||||
set => _inner.CommandText = value;
|
||||
}
|
||||
#pragma warning restore CS8765
|
||||
|
||||
public override int CommandTimeout
|
||||
{
|
||||
get => _inner.CommandTimeout;
|
||||
set => _inner.CommandTimeout = value;
|
||||
}
|
||||
|
||||
public override CommandType CommandType
|
||||
{
|
||||
get => _inner.CommandType;
|
||||
set => _inner.CommandType = value;
|
||||
}
|
||||
|
||||
public override bool DesignTimeVisible
|
||||
{
|
||||
get => _inner.DesignTimeVisible;
|
||||
set => _inner.DesignTimeVisible = value;
|
||||
}
|
||||
|
||||
public override UpdateRowSource UpdatedRowSource
|
||||
{
|
||||
get => _inner.UpdatedRowSource;
|
||||
set => _inner.UpdatedRowSource = value;
|
||||
}
|
||||
|
||||
protected override DbConnection? DbConnection
|
||||
{
|
||||
// When the script has wrapped the connection (the normal path through
|
||||
// ScriptRuntimeContext.DatabaseHelper.Connection) we keep returning
|
||||
// the wrapper, but writes from the user go through to the inner
|
||||
// command so the underlying provider keeps its wiring intact.
|
||||
get => _wrappingConnection ?? _inner.Connection;
|
||||
set
|
||||
{
|
||||
_wrappingConnection = value;
|
||||
_inner.Connection = value switch
|
||||
{
|
||||
AuditingDbConnection auditing => auditing.GetType()
|
||||
.GetField("_inner", System.Reflection.BindingFlags.Instance | System.Reflection.BindingFlags.NonPublic)
|
||||
!.GetValue(auditing) as DbConnection,
|
||||
_ => value
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
protected override DbParameterCollection DbParameterCollection => _inner.Parameters;
|
||||
|
||||
protected override DbTransaction? DbTransaction
|
||||
{
|
||||
get => _inner.Transaction;
|
||||
set => _inner.Transaction = value;
|
||||
}
|
||||
|
||||
public override void Cancel() => _inner.Cancel();
|
||||
|
||||
public override void Prepare() => _inner.Prepare();
|
||||
|
||||
protected override DbParameter CreateDbParameter() => _inner.CreateParameter();
|
||||
|
||||
// -- Audited execution surface ---------------------------------------
|
||||
|
||||
public override int ExecuteNonQuery()
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
int rows = 0;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
rows = _inner.ExecuteNonQuery();
|
||||
return rows;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
throw;
|
||||
}
|
||||
finally
|
||||
{
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "write",
|
||||
rowsAffected: thrown == null ? rows : (int?)null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
}
|
||||
}
|
||||
|
||||
public override object? ExecuteScalar()
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
object? scalar = null;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
scalar = _inner.ExecuteScalar();
|
||||
return scalar;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
throw;
|
||||
}
|
||||
finally
|
||||
{
|
||||
// ExecuteScalar is classified as "write" per the M4 vocabulary
|
||||
// lock — it's a single-value execution; rowsAffected mirrors the
|
||||
// inner command's value if exposed (DbCommand has no RecordsAffected
|
||||
// property, so we report -1 when the provider didn't surface it).
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "write",
|
||||
rowsAffected: thrown == null ? -1 : (int?)null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
}
|
||||
}
|
||||
|
||||
public override async Task<int> ExecuteNonQueryAsync(CancellationToken cancellationToken)
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
int rows = 0;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
rows = await _inner.ExecuteNonQueryAsync(cancellationToken).ConfigureAwait(false);
|
||||
return rows;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
throw;
|
||||
}
|
||||
finally
|
||||
{
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "write",
|
||||
rowsAffected: thrown == null ? rows : (int?)null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
}
|
||||
}
|
||||
|
||||
public override async Task<object?> ExecuteScalarAsync(CancellationToken cancellationToken)
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
object? scalar = null;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
scalar = await _inner.ExecuteScalarAsync(cancellationToken).ConfigureAwait(false);
|
||||
return scalar;
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
throw;
|
||||
}
|
||||
finally
|
||||
{
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "write",
|
||||
rowsAffected: thrown == null ? -1 : (int?)null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
}
|
||||
}
|
||||
|
||||
protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior)
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
DbDataReader? reader = null;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
reader = _inner.ExecuteReader(behavior);
|
||||
return new AuditingDbDataReader(
|
||||
reader,
|
||||
onClose: rows => EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "read",
|
||||
rowsAffected: null,
|
||||
rowsReturned: rows,
|
||||
thrown: null));
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
// Emit the failure row immediately — no reader to wait on.
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "read",
|
||||
rowsAffected: null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
throw;
|
||||
}
|
||||
}
|
||||
|
||||
protected override async Task<DbDataReader> ExecuteDbDataReaderAsync(
|
||||
CommandBehavior behavior, CancellationToken cancellationToken)
|
||||
{
|
||||
var occurredAtUtc = DateTime.UtcNow;
|
||||
var startTicks = Stopwatch.GetTimestamp();
|
||||
DbDataReader? reader = null;
|
||||
Exception? thrown = null;
|
||||
try
|
||||
{
|
||||
reader = await _inner.ExecuteReaderAsync(behavior, cancellationToken).ConfigureAwait(false);
|
||||
return new AuditingDbDataReader(
|
||||
reader,
|
||||
onClose: rows => EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "read",
|
||||
rowsAffected: null,
|
||||
rowsReturned: rows,
|
||||
thrown: null));
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
thrown = ex;
|
||||
EmitAudit(
|
||||
occurredAtUtc,
|
||||
ElapsedMs(startTicks),
|
||||
op: "read",
|
||||
rowsAffected: null,
|
||||
rowsReturned: null,
|
||||
thrown);
|
||||
throw;
|
||||
}
|
||||
}
|
||||
|
||||
protected override void Dispose(bool disposing)
|
||||
{
|
||||
if (disposing)
|
||||
{
|
||||
_inner.Dispose();
|
||||
}
|
||||
base.Dispose(disposing);
|
||||
}
|
||||
|
||||
// -- Emission ---------------------------------------------------------
|
||||
|
||||
private static int ElapsedMs(long startTicks) =>
|
||||
(int)((Stopwatch.GetTimestamp() - startTicks) * 1000d / Stopwatch.Frequency);
|
||||
|
||||
/// <summary>
|
||||
/// Best-effort emission of one <c>DbOutbound</c>/<c>DbWrite</c> audit row.
|
||||
/// Mirrors the M2 Bundle F <c>EmitCallAudit</c> 3-layer fail-safe pattern.
|
||||
/// </summary>
|
||||
private void EmitAudit(
|
||||
DateTime occurredAtUtc,
|
||||
int durationMs,
|
||||
string op,
|
||||
int? rowsAffected,
|
||||
int? rowsReturned,
|
||||
Exception? thrown)
|
||||
{
|
||||
AuditEvent evt;
|
||||
try
|
||||
{
|
||||
evt = BuildAuditEvent(occurredAtUtc, durationMs, op, rowsAffected, rowsReturned, thrown);
|
||||
}
|
||||
catch (Exception buildEx)
|
||||
{
|
||||
// Defensive: building the event from already-validated fields
|
||||
// shouldn't throw, but the alog.md §7 contract requires we never
|
||||
// propagate to the user-facing action regardless.
|
||||
_logger.LogWarning(buildEx,
|
||||
"Failed to build Audit Log #23 event for {Connection} (op={Op}) — skipping emission",
|
||||
_connectionName, op);
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
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} ({Connection} op={Op})",
|
||||
evt.EventId, _connectionName, op),
|
||||
CancellationToken.None,
|
||||
TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously,
|
||||
TaskScheduler.Default);
|
||||
}
|
||||
else if (writeTask.IsFaulted)
|
||||
{
|
||||
_logger.LogWarning(writeTask.Exception,
|
||||
"Audit Log #23 write failed for EventId {EventId} ({Connection} op={Op})",
|
||||
evt.EventId, _connectionName, op);
|
||||
}
|
||||
}
|
||||
catch (Exception writeEx)
|
||||
{
|
||||
// Synchronous throw from WriteAsync before its own try/catch.
|
||||
// Swallow + log per alog.md §7.
|
||||
_logger.LogWarning(writeEx,
|
||||
"Audit Log #23 write threw synchronously for EventId {EventId} ({Connection} op={Op})",
|
||||
evt.EventId, _connectionName, op);
|
||||
}
|
||||
}
|
||||
|
||||
private AuditEvent BuildAuditEvent(
|
||||
DateTime occurredAtUtc,
|
||||
int durationMs,
|
||||
string op,
|
||||
int? rowsAffected,
|
||||
int? rowsReturned,
|
||||
Exception? thrown)
|
||||
{
|
||||
var status = thrown == null ? AuditStatus.Delivered : AuditStatus.Failed;
|
||||
|
||||
// Target = "<connectionName>.<first 60 chars of SQL>" so the audit
|
||||
// row carries a human-recognisable handle without dragging the full
|
||||
// (potentially huge) statement into the index column. The full
|
||||
// statement + parameter values live in RequestSummary.
|
||||
string target = _connectionName;
|
||||
var sqlSnippet = _inner.CommandText ?? string.Empty;
|
||||
if (sqlSnippet.Length > 0)
|
||||
{
|
||||
var snippet = sqlSnippet.Length > 60
|
||||
? sqlSnippet[..60]
|
||||
: sqlSnippet;
|
||||
target = $"{_connectionName}.{snippet}";
|
||||
}
|
||||
|
||||
// RequestSummary captures the SQL statement + parameter values by
|
||||
// default per the alog.md M4 acceptance criteria (M5 will add
|
||||
// per-connection redaction opt-in).
|
||||
string? requestSummary = BuildRequestSummary();
|
||||
|
||||
// Extra carries the op discriminator + row count per the vocabulary
|
||||
// lock. Build as a small hand-rolled JSON object to avoid pulling
|
||||
// in System.Text.Json on the hot path.
|
||||
string extra = op == "write"
|
||||
? $"{{\"op\":\"write\",\"rowsAffected\":{(rowsAffected ?? 0)}}}"
|
||||
: $"{{\"op\":\"read\",\"rowsReturned\":{(rowsReturned ?? 0)}}}";
|
||||
|
||||
return new AuditEvent
|
||||
{
|
||||
EventId = Guid.NewGuid(),
|
||||
OccurredAtUtc = DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc),
|
||||
Channel = AuditChannel.DbOutbound,
|
||||
Kind = AuditKind.DbWrite,
|
||||
CorrelationId = null,
|
||||
SourceSiteId = string.IsNullOrEmpty(_siteId) ? null : _siteId,
|
||||
SourceInstanceId = _instanceName,
|
||||
SourceScript = _sourceScript,
|
||||
Actor = null,
|
||||
Target = target,
|
||||
Status = status,
|
||||
HttpStatus = null,
|
||||
DurationMs = durationMs,
|
||||
ErrorMessage = thrown?.Message,
|
||||
ErrorDetail = thrown?.ToString(),
|
||||
RequestSummary = requestSummary,
|
||||
ResponseSummary = null,
|
||||
PayloadTruncated = false,
|
||||
Extra = extra,
|
||||
ForwardState = AuditForwardState.Pending,
|
||||
};
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Compose a JSON request summary capturing the SQL statement and
|
||||
/// parameter values. Parameter values are captured by default per the
|
||||
/// M4 acceptance criteria — redaction is opt-in and deferred to M5.
|
||||
/// </summary>
|
||||
private string? BuildRequestSummary()
|
||||
{
|
||||
var sql = _inner.CommandText;
|
||||
if (string.IsNullOrEmpty(sql))
|
||||
{
|
||||
return null;
|
||||
}
|
||||
|
||||
// Hand-roll the JSON so we don't pull in System.Text.Json for a
|
||||
// shape this small. Values are stringified with ToString() — fully
|
||||
// structured serialisation arrives with the redaction work in M5.
|
||||
var sb = new System.Text.StringBuilder(sql.Length + 64);
|
||||
sb.Append("{\"sql\":");
|
||||
AppendJsonString(sb, sql);
|
||||
|
||||
if (_inner.Parameters.Count > 0)
|
||||
{
|
||||
sb.Append(",\"parameters\":{");
|
||||
var first = true;
|
||||
foreach (DbParameter p in _inner.Parameters)
|
||||
{
|
||||
if (!first) sb.Append(',');
|
||||
first = false;
|
||||
AppendJsonString(sb, p.ParameterName);
|
||||
sb.Append(':');
|
||||
if (p.Value is null || p.Value is DBNull)
|
||||
{
|
||||
sb.Append("null");
|
||||
}
|
||||
else
|
||||
{
|
||||
AppendJsonString(sb, p.Value.ToString() ?? string.Empty);
|
||||
}
|
||||
}
|
||||
sb.Append('}');
|
||||
}
|
||||
|
||||
sb.Append('}');
|
||||
return sb.ToString();
|
||||
}
|
||||
|
||||
private static void AppendJsonString(System.Text.StringBuilder sb, string value)
|
||||
{
|
||||
sb.Append('"');
|
||||
foreach (var ch in value)
|
||||
{
|
||||
switch (ch)
|
||||
{
|
||||
case '"': sb.Append("\\\""); break;
|
||||
case '\\': sb.Append("\\\\"); break;
|
||||
case '\b': sb.Append("\\b"); break;
|
||||
case '\f': sb.Append("\\f"); break;
|
||||
case '\n': sb.Append("\\n"); break;
|
||||
case '\r': sb.Append("\\r"); break;
|
||||
case '\t': sb.Append("\\t"); break;
|
||||
default:
|
||||
if (ch < 0x20)
|
||||
{
|
||||
sb.Append("\\u").Append(((int)ch).ToString("x4"));
|
||||
}
|
||||
else
|
||||
{
|
||||
sb.Append(ch);
|
||||
}
|
||||
break;
|
||||
}
|
||||
}
|
||||
sb.Append('"');
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user