A cached-telemetry audit row whose OperationTracking snapshot could not be
resolved was skipped and left Pending. Nothing ever removed it, so the next
drain re-read it, failed identically, and logged again — forever.
The severity was worse than the original write-up said. The queue is read
oldest-first with a fixed BatchSize (default 256), so once a batch's worth of
permanently-unresolvable rows collected at the head, every drain re-read
exactly those rows and NEVER REACHED the newer rows behind them. That is a
permanent stall of the cached-telemetry path, not the "log flood, no data loss"
the issue was first filed as. Measured on the rig at ~2,800 warnings/minute,
surviving both a process restart and a container restart.
Fix: after a grace period (CachedTrackingGraceSeconds, default 300 s) the
operational half is abandoned and the row marked Forwarded. A row with no
CorrelationId is abandoned immediately — it can never resolve.
Marking Forwarded does not drop audit data. That state means "no longer owed by
the drain, still eligible for reconciliation", which is exactly this situation:
ReadPendingSinceAsync covers Forwarded as well as Pending and central dedups on
EventId, so the reconciliation pull still delivers the audit half. What is lost
is the operational (SiteCalls) half, which is unrecoverable anyway once the
tracking row is gone.
Three deliberate boundaries:
- Inside the grace window the row is still retried — a missing snapshot is
normally a brief write race, and abandoning on the first failed lookup would
discard the operational half of every cached call that lost that race.
- A tracking-store THROW never abandons, however old the row: a throw is a
store fault (locked, corrupt, mid-restore), not a verdict about the row.
- Logging is per drain pass, not per row. Deferred rows dropped to Debug —
being inside the grace window is normal operation, not a warning.
CachedDrain_OrphanRow_NoTrackingSnapshot_IsSkipped_DoesNotCrash was RETARGETED
rather than deleted: it pinned the defect ("skipped and stays Pending"), so its
orphan assertion is inverted and the half that still holds is kept verbatim.
Three tests added, including the starvation regression. Both "must NOT abandon"
tests carry a positive control on the read count, so they cannot pass by virtue
of a drain that never ran.
Verified non-vacuous: with abandonment disabled the two abandonment tests go
red and the two guards stay green. Build 0 warnings; AuditLog 358, Host 330,
SiteRuntime 512, StoreAndForward 130, Communication 312, Commons 684,
Integration 94 — all pass.
Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
The Phase 2 soak's "LocalDb fails under load" blocker is NOT a product defect.
Root cause: host-side (macOS) sqlite3 reads of the live, bind-mounted WAL
databases. POSIX advisory locks do not propagate across the virtiofs boundary,
so the host reader believes it is the only connection, checkpoints on close and
resets the WAL to 0 bytes under the container. The container's still-mapped
WAL index then references frames that no longer exist and every subsequent
statement fails SQLITE_IOERR_SHORT_READ (522) -> primary code 10, permanently
until the process reopens the database.
Reproduced on demand both on the rig (one sqlite3 SELECT reset a 4.6 MiB WAL and
produced the first error one second later) and in a minimal python:3.12-alpine
repro with no LocalDb or .NET involved. Refuted the converse: a freshly-reopened
node sustained the full soak load 10+ minutes with zero errors.
The original brief's isolation was confounded - both nodes had been poisoned by
the same sampling pass, and a poisoned standby looks healthy only because it
issues almost no statements. Corrections annotated in place.
Hardening shipped alongside:
- SqliteErrorCodes.Describe: log SQLite primary AND extended codes at the
LocalDb-adjacent catch sites (the missing extended code is what made the
original diagnosis so slow).
- SiteAuditTelemetryActor: stop touching ActorContext across an await
(NotSupportedException), with regression coverage.
- infra/reseed.sh: apply the MSSQL init scripts explicitly. The official
mssql/server image does not implement /docker-entrypoint-initdb.d, so a fresh
volume hung the reseed forever; compose mounts annotated as informational.
Deliberately NOT done: detect-and-reopen self-heal in SqliteLocalDb. It defends
only against external interference, which is now prevented at the source, and
same-kernel production readers see the locks correctly.
Build 0 warnings; SiteAuditTelemetryActorTests 9/9, SiteEventLogging 70/70.
Claude-Session: https://claude.ai/code/session_01BL2Vu1ESDQ9SCN4gVKkdts
The host does not guarantee IHostedService.StopAsync is driven before the DI
container is disposed — WebApplicationFactory's teardown reaches Dispose first
— so cancelling the internal CTS from StopAsync threw ObjectDisposedException
and aborted the host's whole shutdown sequence. Four services shared the same
copy-pasted lifecycle and the same two races: StopAsync cancelling an already-
disposed CTS, and StartAsync reading _cts.Token lazily inside the Task.Run
lambda, which faults the loop task the host awaits when Dispose wins that race.
Each service now captures the token on the caller's thread, tolerates a
disposed CTS, and cancels-before-disposing so the loop is always signalled and
its pending Task.Delay sees a cancelled token rather than a dead source.
SiteAuditBacklogReporter also gains the outer OperationCanceledException guard
its sibling SiteAuditRetentionService already carried (arch-review 04 R2, R7),
without which a shutdown landing mid-probe threw TaskCanceledException out of
Host.StopAsync.
Surfaced while verifying the Gitea #15 test-harness fix: in Host.Tests the
aborted teardown skipped the fixture's env-var restore, contaminating every
later test in the run.
Refs: Gitea #15
Consolidates the reporter's poll cadence onto SqliteAuditWriterOptions instead of
the hard-coded 30 s constant, closing deferred-work register item #21 (the config-
shape cleanup its own XML doc flagged as a follow-up).
- SqliteAuditWriterOptions.BacklogPollIntervalSeconds (default 30).
- Reporter reads it via IOptions; precedence explicit-override (tests) > configured
> 30 s default; a non-positive value falls back to the default. Corrected the
stale "hard-code / tunable in a follow-up" class-doc.
- Cadence tests + register updated (row 21 -> Resolved).
Claude-Session: https://claude.ai/code/session_01MtdgwpEeCUn6cUA5f1LMPj
SiteAuditRetentionService (site-only IHostedService) ticks PurgeExpiredAsync on
InitialDelay(5m)/PurgeInterval(24h, clamped >=1m), cutoff = UtcNow - RetentionDays.
Registered site-only in AddAuditLogHealthMetricsBridge; options bound from
AuditLog:SiteRetention. Per-tick failures swallowed. Added a test-only
PurgeIntervalOverride (mirrors SiteCallAuditOptions) so the ms-cadence tick test
can bypass the 1-min production clamp. Doc updated. (PLAN-04 Task 3, S1/U2)
RetentionDays clamped [1,90]; PurgeInterval clamped to >= 1 min (Timer spin
footgun); 5-min InitialDelay so a daily-recycled node still purges. (PLAN-04 Task 2)
Retention purge deletes Forwarded/Reconciled rows older than the cutoff and
reclaims pages via incremental_vacuum; Pending rows are never purged on age
alone (would lose audit data that never reached central). Temp-table purge set
avoids the SQLite 999-param limit; runs under _writeLock. (PLAN-04 Task 1, S1/U2)
Perf re-baseline (HotPathLatencyTests): empirical p95 on Apple M-series Release
build: 4KB DetailsJson slow path ≈14 µs, small-DetailsJson no-redactors ≈2 µs,
true no-op fast path ≈0 µs. Thresholds updated: 200 µs / 30 µs / 5 µs (≈15×
headroom for contested CI runners). Old thresholds (50 µs / 10 µs) were set for
the pre-C3 typed-field path; canonical JSON parse+rewrite is empirically faster.
Adds a third test (Filter_Apply_NoDetailsJson_FastPath) that asserts same-instance
return on the DetailsJson-null + within-cap fast path. Env-var overrides retained.
CollapseAuditLogToCanonicalMigrationTests (new): three MSSQL-gated [SkippableFact]
tests verifying Action/Category/Outcome projection, NULL Actor, DetailsJson codec
round-trip, and all six persisted computed columns (Kind/Status/SourceSiteId/
ExecutionId/ParentExecutionId) for ApiOutbound, InboundAuthFailure, and Failed-
status rows.
AddAuditLogTableMigrationTests: rename CreatesFiveNamedIndexes →
CreatesNineNamedIndexes; expand coverage from 5 original indexes to all 9 named
non-clustered indexes present after CollapseAuditLogToCanonical (adds
IX_AuditLog_Execution, IX_AuditLog_ParentExecution, IX_AuditLog_Node_Occurred,
UX_AuditLog_EventId).
Dead-cref cleanup: zero references to the deleted IAuditPayloadFilter /
DefaultAuditPayloadFilter / SafeDefaultAuditPayloadFilter types remain in any
.cs file (source or test). 26 occurrences across 13 files replaced with correct
references to IAuditRedactor / ScadaBridgeAuditRedactor / SafeDefaultAuditRedactor
or reworded as plain prose.
Residual sweep: no unused transitional code found beyond the acknowledged
"C3 transitional shim" comments on IngestedAtUtc stamping (active code, not dead).
Joseph Doherty