fix(configdb): InsertIfNotExistsAsync swallows duplicate-key races + add keyset tiebreaker test (#23)

Two concurrent sessions can both pass the IF NOT EXISTS check and then both attempt the INSERT against UX_AuditLog_EventId; the loser surfaced as SqlException 2601 (or 2627 for PK violations) and aborted the audit write. First-write-wins idempotency is the documented contract, so the race outcome is semantically a no-op — catch the two duplicate-key error numbers and log at Debug, let any other SqlException bubble.

Tests:

- InsertIfNotExistsAsync_ConcurrentDuplicateInserts_ProduceExactlyOneRow: 50 parallel inserters with the same EventId end with exactly one row and no escaped exceptions.

- QueryAsync_Keyset_SameOccurredAtUtc_TiebreaksOnEventId: four rows sharing the same OccurredAtUtc page deterministically through the (OccurredAtUtc, EventId) keyset cursor — exercises the e.OccurredAtUtc == after && e.EventId.CompareTo(afterId) < 0 branch and verifies EF Core 10's Guid.CompareTo translation against SQL Server uniqueidentifier order (deferred Bundle D reviewer recommendation).

AuditLogRepository now takes an optional ILogger<AuditLogRepository> (NullLogger default, mirrors InboundApiRepository); DI registration unchanged.
This commit is contained in:
Joseph Doherty
2026-05-20 12:12:50 -04:00
parent eb22d3740f
commit d745ef0715
2 changed files with 130 additions and 5 deletions

View File

@@ -1,4 +1,7 @@
using Microsoft.Data.SqlClient;
using Microsoft.EntityFrameworkCore; using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using ScadaLink.Commons.Entities.Audit; using ScadaLink.Commons.Entities.Audit;
using ScadaLink.Commons.Interfaces.Repositories; using ScadaLink.Commons.Interfaces.Repositories;
using ScadaLink.Commons.Types.Audit; using ScadaLink.Commons.Types.Audit;
@@ -12,11 +15,22 @@ namespace ScadaLink.ConfigurationDatabase.Repositories;
/// </summary> /// </summary>
public class AuditLogRepository : IAuditLogRepository public class AuditLogRepository : IAuditLogRepository
{ {
private readonly ScadaLinkDbContext _context; // SQL Server error numbers for duplicate-key violations on
// UX_AuditLog_EventId. 2601 is a unique-index violation; 2627 is a
// primary-key/unique-constraint violation. The IF NOT EXISTS … INSERT
// pattern has a check-then-act race window — two sessions can both pass
// the EXISTS check and then both attempt the INSERT — and the loser
// surfaces as one of these errors. Idempotency demands we swallow them.
private const int SqlErrorUniqueIndexViolation = 2601;
private const int SqlErrorPrimaryKeyViolation = 2627;
public AuditLogRepository(ScadaLinkDbContext context) private readonly ScadaLinkDbContext _context;
private readonly ILogger<AuditLogRepository> _logger;
public AuditLogRepository(ScadaLinkDbContext context, ILogger<AuditLogRepository>? logger = null)
{ {
_context = context ?? throw new ArgumentNullException(nameof(context)); _context = context ?? throw new ArgumentNullException(nameof(context));
_logger = logger ?? NullLogger<AuditLogRepository>.Instance;
} }
/// <summary> /// <summary>
@@ -44,8 +58,10 @@ public class AuditLogRepository : IAuditLogRepository
// FormattableString interpolation parameterises every value (no concatenation), // FormattableString interpolation parameterises every value (no concatenation),
// so this is safe against injection even for the string columns. // so this is safe against injection even for the string columns.
await _context.Database.ExecuteSqlInterpolatedAsync( try
$@"IF NOT EXISTS (SELECT 1 FROM dbo.AuditLog WHERE EventId = {evt.EventId}) {
await _context.Database.ExecuteSqlInterpolatedAsync(
$@"IF NOT EXISTS (SELECT 1 FROM dbo.AuditLog WHERE EventId = {evt.EventId})
INSERT INTO dbo.AuditLog INSERT INTO dbo.AuditLog
(EventId, OccurredAtUtc, IngestedAtUtc, Channel, Kind, CorrelationId, (EventId, OccurredAtUtc, IngestedAtUtc, Channel, Kind, CorrelationId,
SourceSiteId, SourceInstanceId, SourceScript, Actor, Target, Status, SourceSiteId, SourceInstanceId, SourceScript, Actor, Target, Status,
@@ -56,7 +72,24 @@ VALUES
{evt.SourceSiteId}, {evt.SourceInstanceId}, {evt.SourceScript}, {evt.Actor}, {evt.Target}, {status}, {evt.SourceSiteId}, {evt.SourceInstanceId}, {evt.SourceScript}, {evt.Actor}, {evt.Target}, {status},
{evt.HttpStatus}, {evt.DurationMs}, {evt.ErrorMessage}, {evt.ErrorDetail}, {evt.RequestSummary}, {evt.HttpStatus}, {evt.DurationMs}, {evt.ErrorMessage}, {evt.ErrorDetail}, {evt.RequestSummary},
{evt.ResponseSummary}, {evt.PayloadTruncated}, {evt.Extra}, {forwardState});", {evt.ResponseSummary}, {evt.PayloadTruncated}, {evt.Extra}, {forwardState});",
ct); ct);
}
catch (SqlException ex) when (
ex.Number == SqlErrorUniqueIndexViolation
|| ex.Number == SqlErrorPrimaryKeyViolation)
{
// Two concurrent sessions both passed the IF NOT EXISTS check and
// both attempted the INSERT — the loser raises 2601/2627 against
// UX_AuditLog_EventId. First-write-wins idempotency is already the
// documented contract for this method, so the race outcome is
// semantically a no-op. Swallow at Debug; other SqlExceptions
// bubble.
_logger.LogDebug(
ex,
"InsertIfNotExistsAsync swallowed duplicate-key violation (error {SqlErrorNumber}) for EventId {EventId}; treating as no-op.",
ex.Number,
evt.EventId);
}
} }
/// <summary> /// <summary>

View File

@@ -217,6 +217,98 @@ public class AuditLogRepositoryTests : IClassFixture<MsSqlMigrationFixture>
Assert.Equal(t0.AddMinutes(0), page3[0].OccurredAtUtc); Assert.Equal(t0.AddMinutes(0), page3[0].OccurredAtUtc);
} }
[SkippableFact]
public async Task InsertIfNotExistsAsync_ConcurrentDuplicateInserts_ProduceExactlyOneRow()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = NewSiteId();
// Single event used by every parallel call — same EventId, same payload.
// The repository's IF NOT EXISTS … INSERT pattern has a check-then-act
// race window between sessions; under concurrent load SQL Server can
// raise a unique-index violation (error 2601) on UX_AuditLog_EventId.
// Bundle A's hardening swallows 2601/2627 so duplicates collapse silently.
var evt = NewEvent(siteId, occurredAtUtc: new DateTime(2026, 5, 20, 12, 0, 0, DateTimeKind.Utc));
// 50 parallel inserters, each with its own DbContext (DbContext is not
// thread-safe). Parallel.ForEachAsync aggregates exceptions, so a single
// unhandled 2601 from the repository would fail this test loudly.
await Parallel.ForEachAsync(
Enumerable.Range(0, 50),
new ParallelOptions { MaxDegreeOfParallelism = 50 },
async (_, ct) =>
{
await using var context = CreateContext();
var repo = new AuditLogRepository(context);
await repo.InsertIfNotExistsAsync(evt, ct);
});
await using var readContext = CreateContext();
var count = await readContext.Set<AuditEvent>()
.Where(e => e.SourceSiteId == siteId)
.CountAsync();
Assert.Equal(1, count);
}
[SkippableFact]
public async Task QueryAsync_Keyset_SameOccurredAtUtc_TiebreaksOnEventId()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = NewSiteId();
await using var context = CreateContext();
var repo = new AuditLogRepository(context);
// Four events all sharing the exact same OccurredAtUtc — the keyset
// cursor must lean on the EventId tiebreaker (descending) to page
// deterministically. Bundle D's reviewer flagged this as a deferred
// verification because it depends on EF Core 10 translating
// Guid.CompareTo against SQL Server's uniqueidentifier sort order.
var occurredAt = new DateTime(2026, 5, 20, 13, 0, 0, DateTimeKind.Utc);
// Build four distinct Guids; we don't care about the literal ordering
// produced by Guid.CompareTo — only that paging is deterministic and
// covers every row exactly once.
var events = Enumerable.Range(0, 4)
.Select(_ => NewEvent(siteId, occurredAtUtc: occurredAt))
.ToList();
foreach (var e in events)
{
await repo.InsertIfNotExistsAsync(e);
}
var filter = new AuditLogQueryFilter(SourceSiteId: siteId);
var page1 = await repo.QueryAsync(filter, new AuditLogPaging(PageSize: 2));
Assert.Equal(2, page1.Count);
Assert.All(page1, r => Assert.Equal(occurredAt, r.OccurredAtUtc));
var cursor = page1[^1];
var page2 = await repo.QueryAsync(
filter,
new AuditLogPaging(
PageSize: 2,
AfterOccurredAtUtc: cursor.OccurredAtUtc,
AfterEventId: cursor.EventId));
Assert.Equal(2, page2.Count);
Assert.All(page2, r => Assert.Equal(occurredAt, r.OccurredAtUtc));
var page1Ids = page1.Select(r => r.EventId).ToHashSet();
var page2Ids = page2.Select(r => r.EventId).ToHashSet();
// No overlap between pages.
Assert.Empty(page1Ids.Intersect(page2Ids));
// Every inserted EventId appears in exactly one of the two pages.
var allIds = page1Ids.Union(page2Ids).ToHashSet();
Assert.Equal(4, allIds.Count);
Assert.True(events.Select(e => e.EventId).ToHashSet().SetEquals(allIds));
}
[SkippableFact] [SkippableFact]
public async Task SwitchOutPartitionAsync_ThrowsNotSupported_ForM1() public async Task SwitchOutPartitionAsync_ThrowsNotSupported_ForM1()
{ {