fix(auditlog): truncate over-width SiteCalls.LastError on the cached-telemetry dual-write and the reconciliation pull (review 2026-10-21 follow-up)

This commit is contained in:
Joseph Doherty
2026-10-22 09:52:17 -04:00
parent 89d8568fdf
commit 7be22d2ac2
6 changed files with 121 additions and 4 deletions
+5 -1
View File
@@ -353,7 +353,11 @@ collapse first-write-wins before the statement is built, duplicates *across*
packets are eliminated by the anti-semi-join, and any failure falls back to the packets are eliminated by the anti-semi-join, and any failure falls back to the
per-row / per-entry path — so the documented invariant that one bad row cannot per-row / per-entry path — so the documented invariant that one bad row cannot
sink the rest of the batch still holds, it is simply no longer paid for on the sink the rest of the batch still holds, it is simply no longer paid for on the
healthy path. healthy path. A site `LastError` longer than the central `SiteCalls.LastError` column (1024
characters) is truncated to the column width on both the dual-write and the
reconciliation pull (`SiteCallColumnBounds`) — an over-width message used to fail the
whole dual-write with SQL 8152, so the audit row came back Rejected and the
`SiteCalls` row was never written by either path (review 2026-10-21 follow-up).
The set-based path binds its string parameters at the VALUE's own length, never The set-based path binds its string parameters at the VALUE's own length, never
at the column width. Declaring the width makes the client TRUNCATE an over-long at the column width. Declaring the width makes the client TRUNCATE an over-long
@@ -435,7 +435,7 @@ public class AuditLogIngestActor : ReceiveActor
var safeRedactor = redactor ?? SafeDefaultAuditRedactor.Instance; var safeRedactor = redactor ?? SafeDefaultAuditRedactor.Instance;
var filteredAudit = safeRedactor.Apply(entry.Audit); var filteredAudit = safeRedactor.Apply(entry.Audit);
var auditStamped = AuditRowProjection.WithIngestedAtUtc(filteredAudit, ingestedAt); var auditStamped = AuditRowProjection.WithIngestedAtUtc(filteredAudit, ingestedAt);
var siteCallStamped = entry.SiteCall with { IngestedAtUtc = ingestedAt }; var siteCallStamped = SiteCallColumnBounds.Clamp(entry.SiteCall) with { IngestedAtUtc = ingestedAt };
await auditRepo.InsertIfNotExistsAsync(auditStamped, fallbackBudget.Token) await auditRepo.InsertIfNotExistsAsync(auditStamped, fallbackBudget.Token)
.ConfigureAwait(false); .ConfigureAwait(false);
@@ -539,7 +539,7 @@ public class AuditLogIngestActor : ReceiveActor
foreach (var entry in cmd.Entries) foreach (var entry in cmd.Entries)
{ {
await siteCallRepo await siteCallRepo
.UpsertAsync(entry.SiteCall with { IngestedAtUtc = ingestedAt }, ct) .UpsertAsync(SiteCallColumnBounds.Clamp(entry.SiteCall) with { IngestedAtUtc = ingestedAt }, ct)
.ConfigureAwait(false); .ConfigureAwait(false);
} }
@@ -141,7 +141,9 @@ public sealed class GrpcPullSiteCallsClient : IPullSiteCallsClient
{ {
try try
{ {
var sc = SiteCallDtoMapper.FromDto(dto) with { SourceSite = siteId }; // Fit LastError to the central column so the reconciliation upsert cannot fail
// with SQL 8152 (review 2026-10-21 follow-up — see SiteCallColumnBounds).
var sc = SiteCallColumnBounds.Clamp(SiteCallDtoMapper.FromDto(dto)) with { SourceSite = siteId };
siteCalls.Add(sc); siteCalls.Add(sc);
} }
catch (Exception ex) catch (Exception ex)
@@ -0,0 +1,41 @@
using ZB.MOM.WW.ScadaBridge.Commons.Entities.Audit;
namespace ZB.MOM.WW.ScadaBridge.AuditLog.Central;
/// <summary>
/// Fits a site-supplied <see cref="SiteCall"/> to the central <c>SiteCalls</c> column widths before
/// it is written (review 2026-10-21 follow-up). The site's tracking store does not bound
/// <see cref="SiteCall.LastError"/>, while the central column is <c>nvarchar(1024)</c>
/// (<c>SiteCallEntityTypeConfiguration</c>): an over-width error used to fail the
/// cached-telemetry dual-write with SQL 8152 — the audit row was reported Rejected to the site
/// and the reconciliation pull's upsert failed the same way, so the <c>SiteCalls</c> row was never
/// written at all. Truncating a diagnostic message is the right trade; dropping the row is not.
/// </summary>
internal static class SiteCallColumnBounds
{
/// <summary>Width of <c>SiteCalls.LastError</c>; must match <c>SiteCallEntityTypeConfiguration</c>.</summary>
public const int LastErrorMaxLength = 1024;
/// <summary>
/// Returns <paramref name="siteCall"/> unchanged when it already fits, otherwise a copy whose
/// <see cref="SiteCall.LastError"/> is truncated to <see cref="LastErrorMaxLength"/> characters
/// (never splitting a UTF-16 surrogate pair).
/// </summary>
/// <param name="siteCall">The row about to be written centrally.</param>
/// <returns>A row that fits the central columns.</returns>
public static SiteCall Clamp(SiteCall siteCall)
{
if (siteCall.LastError is not { Length: > LastErrorMaxLength } error)
{
return siteCall;
}
var cut = LastErrorMaxLength;
if (char.IsHighSurrogate(error[cut - 1]))
{
cut--;
}
return siteCall with { LastError = error[..cut] };
}
}
@@ -160,6 +160,37 @@ public class AuditLogIngestActorCombinedTelemetryTests : TestKit, IClassFixture<
Assert.Equal(siteCall.Status, siteCallRow!.Status); Assert.Equal(siteCall.Status, siteCallRow!.Status);
} }
/// <summary>
/// Review 2026-10-21 follow-up: a site LastError longer than the central
/// <c>SiteCalls.LastError</c> column (nvarchar(1024)) used to fail the dual-write with SQL
/// 8152 — the audit row was reported Rejected and the SiteCalls row was never upserted. The
/// ingest now truncates it to the column width, so both rows land.
/// </summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[SkippableFact]
public async Task Receive_OverWidthLastError_IsTruncated_BothRowsLand()
{
Skip.IfNot(_fixture.Available, _fixture.SkipReason);
var siteId = NewSiteId();
var (audit, siteCall) = NewEntry(siteId);
siteCall = siteCall with { LastError = new string('x', 5000) };
var actor = CreateActor(BuildServiceProvider());
actor.Tell(
new IngestCachedTelemetryCommand(new[] { new CachedTelemetryEntry(audit, siteCall) }),
TestActor);
var reply = ExpectMsg<IngestCachedTelemetryReply>(TimeSpan.FromSeconds(15));
Assert.Equal(new[] { audit.EventId }, reply.AcceptedEventIds);
Assert.Empty(reply.RejectedEventIds);
await using var read = CreateReadContext();
var siteCallRow = await read.Set<SiteCall>()
.SingleAsync(s => s.TrackedOperationId == siteCall.TrackedOperationId);
Assert.Equal(SiteCallColumnBounds.LastErrorMaxLength, siteCallRow.LastError!.Length);
}
/// <summary>Verifies that a duplicate event id with an unchanged status is a no-op that leaves the row counts unchanged and still acknowledges the id.</summary> /// <summary>Verifies that a duplicate event id with an unchanged status is a no-op that leaves the row counts unchanged and still acknowledges the id.</summary>
/// <returns>A task that represents the asynchronous operation.</returns> /// <returns>A task that represents the asynchronous operation.</returns>
[SkippableFact] [SkippableFact]
@@ -274,6 +274,45 @@ public class GrpcPullSiteCallsClientTests
Assert.False(result.MoreAvailable); Assert.False(result.MoreAvailable);
} }
/// <summary>
/// Review 2026-10-21 follow-up: a pulled LastError longer than the central SiteCalls column
/// is truncated to the column width, so the reconciliation upsert cannot fail with SQL 8152.
/// </summary>
/// <returns>A task that represents the asynchronous operation.</returns>
[Fact]
public async Task PullAsync_truncates_over_width_last_error_to_the_column_width()
{
var proto = new ProtoPullResponse();
var dto = Dto(Guid.NewGuid(), BaseTime);
dto.LastError = new string('e', 5000);
proto.Operationals.Add(dto);
var sut = new GrpcPullSiteCallsClient(
new StaticEnumerator(new SiteEntry("site-a", "http://site-a:8083")),
FakeInvoker.Returning(proto),
NullLogger<GrpcPullSiteCallsClient>.Instance);
var result = await sut.PullAsync("site-a", BaseTime, afterId: null, batchSize: 256, CancellationToken.None);
Assert.Equal(SiteCallColumnBounds.LastErrorMaxLength, Assert.Single(result.SiteCalls).LastError!.Length);
}
/// <summary>A surrogate pair straddling the cut is never split; short values pass through untouched.</summary>
[Fact]
public void SiteCallColumnBounds_Clamp_KeepsSurrogatePairsWhole_AndLeavesShortValuesAlone()
{
static ZB.MOM.WW.ScadaBridge.Commons.Entities.Audit.SiteCall Call(string lastError) =>
SiteCallDtoMapper.FromDto(Dto(Guid.NewGuid(), BaseTime)) with { LastError = lastError };
var shortCall = Call("boom");
Assert.Same(shortCall, SiteCallColumnBounds.Clamp(shortCall));
var straddle = new string('a', SiteCallColumnBounds.LastErrorMaxLength - 2) + "\U0001F600" + "tail";
var clamped = SiteCallColumnBounds.Clamp(Call(straddle)).LastError!;
Assert.True(clamped.Length <= SiteCallColumnBounds.LastErrorMaxLength);
Assert.False(char.IsHighSurrogate(clamped[^1]));
}
/// <summary>Verifies that PullAsync with a MinValue unspecified-kind cursor does not throw and still dials the site.</summary> /// <summary>Verifies that PullAsync with a MinValue unspecified-kind cursor does not throw and still dials the site.</summary>
/// <returns>A task that represents the asynchronous operation.</returns> /// <returns>A task that represents the asynchronous operation.</returns>
[Fact] [Fact]