From 424db1555de2d335574f66c89f84ea82a1005c95 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 10 Nov 2026 16:46:42 -0500 Subject: [PATCH] fix: outbox KPI per-status legs, composite event-log indexes, AuditLog ingest FORCESEEK (#122, #123, #124) #122: the Notification Outbox KPI snapshots ORed every status in one aggregation, which scanned the clustered index once the table held ~1 M Parked rows (0.7-2.6 s; Health dashboard up to 5 s). Each snapshot now runs three status-equality legs that seek their own index (~0.12 s); a cold Health load on the rig is 0.12-0.52 s. #123: site_events event_type/severity indexes are now composites with timestamp, so a filtered page is read in order and stops at the limit (severity=Error over 1 GB: 2,287 -> 15 ms cold, 115 -> 1.6 ms warm). Costs 454 -> 530 B/row, ~14 % fewer rows under the same cap. The schema apply drops the old indexes in place; the cap size model samples timestamp three times and re-scores inside its band with unchanged constants. #124: the set-based AuditLog insert's NOT EXISTS probe scanned the EventId index and concurrent writers deadlocked on S/IX page locks. WITH (FORCESEEK): 4 writers 775 rows/s + 76 deadlocks in 30 s -> 5,214 rows/s + 0. New concurrent-writer regression test fails 4/4 without the hint. --- CLAUDE.md | 5 +- docs/components/SiteEventLogging.md | 8 +- ...7-site-event-log-cap-semantics-decision.md | 18 ++ .../Repositories/AuditLogRepository.cs | 13 +- .../NotificationOutboxRepository.cs | 242 +++++++++--------- .../EventLogPurgeService.cs | 14 +- .../SiteEventLogSchema.cs | 18 +- ...ationOutboxRepositoryKpiQueryShapeTests.cs | 66 ++++- .../Repositories/AuditLogRepositoryTests.cs | 59 +++++ .../SchemaIndexTests.cs | 72 +++++- .../SiteEventLogSchemaTests.cs | 2 +- .../SiteEventsSchemaCalibrationTests.cs | 27 +- 12 files changed, 386 insertions(+), 158 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 7ef69773..0cd506dc 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -182,6 +182,7 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - Audit-write failure NEVER aborts the user-facing action — audit is best-effort, the action's own success/failure path is authoritative. - 365-day central retention with monthly partition-switch purge; per-channel retention overrides (`AuditLog:PerChannelRetentionDays`) expire rows earlier than the global window via a bounded, batched row DELETE on the purge actor's maintenance path — values must be shorter than the global window (M5.5 T3); 7-day site SQLite retention with a hard `ForwardState` invariant (no row purged until forwarded or reconciled). - Append-only enforced via DB roles (writer role has INSERT only, no UPDATE/DELETE). +- **The set-based ingest probe is `WITH (FORCESEEK)` (#124).** Left alone, `InsertManyIfNotExistsAsync`'s `NOT EXISTS` anti-semi-join scanned the EventId index, and concurrent writers (ingest + reconciliation singletons, dual-write, direct writes) deadlocked on S/IX page locks — 4 writers lost ~45 % of packets to 1205. With the hint: 0 deadlocks, 8 writers 8.6 k rows/s. Reproduce with `ResidualBench audit-contention`. - **Clustered key `(OccurredAtUtc, EventId)` + aligned unique `UX_AuditLog_EventId_Occurred (EventId, OccurredAtUtc)` (migration `FlipAuditLogClusteredKey`, #111, B2 of the #78 benchmark).** The Audit Log page's newest-first page/keyset now reads an ordered range instead of the whole table (300k rows: 90,532 → 34 reads). Offline whole-table rebuild — script `docs/plans/sql/FlipAuditLogClusteredKey.sql` (+ `.rollback.sql`), both centrals stopped: the partition-switch staging table now reads the live key order, but binaries older than the flip hard-code the old one. DEV/QA not applied (sizing + window in #111). - **Parquet cold archive (T2, ScadaBridge#42) — default OFF (`AuditLog:Archive:Enabled` + absolute `Directory`, shared by both centrals).** The purge actor writes each expired partition to `{Directory}/{YYYY}/auditlog-{YYYY-MM}-{stamp}Z.parquet` (10 stored columns + `ChainSeq`/`RowHash`, tick-exact `OccurredAtUtcTicks`) plus `.tombstones.parquet` and a `.manifest.json` (written last; chain head at archive time, SHA-256 per file), read under the chain lock SHARED; then the switch runs with a guard (under the EXCLUSIVE lock: partition row count + each month's `LastSeq` must still equal the archive's, else THROW 51002/51003 and nothing is purged). Fail closed: a partition that cannot be archived is not purged. `audit archive list|verify` = `ListAuditArchives`/`VerifyAuditArchive` (verify-chain's gate): file hashes, chain recomputed from the archive, chain end vs the DB purge anchor (`Matches`/`Superseded`/`NotPurged`/`Mismatch`), CLI exit 3. `audit export --format parquet` streams the 24 export columns (was 501). No migration. **Owner decisions (#109):** destination stays a directory/UNC (no object-storage client; share + permissions named at enablement), parquet-tools-only reading (no re-import), unsigned like the chain. **Retention** `AuditLog:Archive:RetentionDays` (default 0 = never; else > `AuditLog:RetentionDays`, counted from the month's end) and **superseded stale-archive cleanup** (`DeleteSupersededStaleArchives`, default true: a retried purge's `Archived` archive is deleted only when a later `Purged`, verifying archive provably holds every row — same anchor + chain-end hash, unchained rows by EventId; else `KeptStale`) run after every purge tick; deletion touches only the archive name's own three files, manifest first; `audit archive cleanup [--dry-run]` = `CleanupAuditArchives` (Administrator). - **Hash-chain tamper evidence (T1, ScadaBridge#41) — default OFF (`AuditLog:HashChain:Enabled`).** One SHA-256 chain per UTC calendar month: `ChainSeq` + `RowHash = SHA-256(prev || canonical(row))` on `AuditLog` (migration `AddAuditLogHashChain`), linked by the central `AuditLogHashChainService` (both nodes, serialised by `sp_getapplock`) — never by the ingest path. `AuditLogChainHead` catches tail deletion and carries the partition-switch checkpoint anchor; the per-channel DELETE writes an `AuditLogChainTombstone` per chained row in the same transaction. `audit verify-chain --month` = management command `VerifyAuditChain` (OperationalAudit, unscoped callers only), first break with partition/ChainSeq/EventId, CLI exit 3. A chained row's `SourceNode` is frozen (backfill skips it). **Unsigned by owner decision (#107); external anchor = off-box head export** (`AuditLog:HashChain:HeadExport`, default off: both centrals append changed per-month heads — month, `LastSeq`/`LastHash`, purge anchor, row + tombstone counts — to append-only JSONL files `{Directory}/{yyyy}/audit-chain-heads-{date}-{node}.jsonl` or RFC 5424 syslog UDP/TCP); `audit verify-heads --path` = `VerifyAuditChainHeads` checks them against the DB (a re-hashed forgery passes verify-chain, fails verify-heads; exit 3). **Two-login hardening (#107 item 3):** `AuditLog:MaintenanceConnectionString` (`${secret:}`-capable, unset = runtime login) runs the chain job, verify/head export, partition switch-out + archive and per-channel purge on `AuditMaintenanceContext` (keyed `audit-maintenance` repository/archive); that login gets `scadabridge_audit_chainer` + `scadabridge_audit_purger`, the runtime login `scadabridge_audit_writer` (whose DENYs block chaining/purging) — pinned by `AuditMaintenanceLoginTests`. Since #113 the monthly roll-forward and `backfill-source-node` use it too (migration `AuditMaintenanceGrants`: purger gets `ALTER ANY DATASPACE` + `UPDATE (SourceNode)`). Head-export failures (#115) bump `scadabridge.audit.chain_head_export.failures` and Degrade `/health/ready` entry `audit-chain-head-export`; archive cleanup (#114) also deletes writer-named orphan temp / manifest-less files older than 24 h (`DeletedOrphan`). @@ -215,8 +216,8 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - **Flow Debugger (2026-09-05, Deployment → `/deployment/flow-debugger` + CLI `flow-debug run-method|run-script|run-value-change|replay`).** Runs one entry point (an inbound API method, or a site script) and draws every step as a Central / Site / Tags / **External** swimlane; *Live* really runs it, *Replay* rebuilds a past execution. **v1.1 (2026-09-06, `docs/plans/2026-09-06-flow-debugger-outbound-calls.md`):** every `ExternalSystem.*` / `Database.*` / `Notify.Send` a traced run makes is an `ApiCall` / `DbCall` / `Notify` node on the External lane — the site routes those already-existing `ApiOutbound` / `DbOutbound` / `Notification` rows through the same inline trace collector, the replay query widens to those channels, and `FlowGraphBuilder` folds a cached operation's rows by `(kind, CorrelationId)` into ONE node with a `Lifecycle` (sync calls in-chain, cached/notify on dashed `Async` edges, trigger cascades on `Spawn` edges, the Response linked from the inbound execution's last step). Later lifecycle rows are not inline, so after a Live run the page polls the Replay command (5 s, ≤ 2 min) while any node is `Pending`, plus a *Refresh outcomes* button. **A refresh MERGES, never replaces (2026-09-06, found live in the browser):** the page unions the re-read rows into the run's own rows by `EventId` and rebuilds the graph, because a Live run carries its site rows inline while the same rows reach central's audit store by telemetry ~5–30 s later — a Replay read taken in between lacks them, and the old wholesale swap made an already-drawn node (a resolved cached DB write) vanish until the next manual refresh. The inline rows ARE the audited rows (`FlowTraceCollector` sinks the same `AuditEvent` objects the site writer persists), so the union is exact. Central method-script `Database.*` calls (`InboundDatabaseHelper`) are now audited (`DbOutbound`/`DbWrite`) — they were not. Rig demo: `docker/seed-flow-outbound-demo.sh` + `verify-delmia-notifier.sh` step I. **Trace steps ARE audit events** — `AuditChannel.ScriptTrace` with kinds `RouteCall` (central, **always-on** per `Route.To().Call`, joins the two halves of a Replay) and `ScriptRun` / `AttributeWrite` / `AttributeWait` (site, **gated** by a `bool Trace` riding beside `ParentExecutionId` on `RouteToCallRequest` / `ScriptCallRequest` / `SetStaticAttributeCommand` / `AttributeValueChanged`; proto fields additive, `site_command.proto` imports `sitestream.proto`). A Live run gets the site rows **inline** on `RouteToCallResponse.TraceEvents` (+ `ChildExecutionId`) because the 5 s telemetry cadence is too slow; Replay reads them from `AuditLog` (`GetTraceEventsAsync`). A value-change on a data-sourced attribute is a REAL tag write; the Instance Actor's **trace arm** (`SiteRuntime:TraceArmWindowSeconds`, 30) stamps the device echo with the writer's execution id so the triggered run is parented and traced, and central polls the site's new `PullTraceEvents` RPC (point read, not reconciliation) for it. Execution path is four management commands on the **per-node `ManagementActor`** (`FlowDebug*`; the three run commands are Deployer-only, Replay is wider) — a standby refuses the three run commands with **`STANDBY_NODE`** (shown verbatim); `ApiMethod.TraceAllCalls` (migration `AddApiMethodTraceAllCalls`, CLI `--trace-all-calls`) traces every real call to a method for later Replay (7–10 rows/call). Prediction before a run is a Roslyn syntax walk (`FlowShapePredictor`, REQ-SA-7, DB-free); the graph (`FlowStep`/`FlowGraphBuilder`, Commons) is a central projection, never a wire type; the renderer is custom SVG (`FlowGraphView`). Rig: `AuditLog:PerChannelRetentionDays:ScriptTrace=30` on both centrals; `verify-delmia-notifier.sh` step H proves live + replay. **Mixed-version caveat:** an older site ignores the flag → central `RouteCall` only, page says *site not traced*. **v1.2 (2026-09-06, `docs/plans/2026-09-06-flow-debugger-followups.md`):** a `Parked` External node offers **Retry / Discard in place** (same site-scope check, confirm and relay as the report pages, via `IFlowDebugService.RetryOutboundAsync`/`DiscardOutboundAsync`, then the page re-polls Replay until the node leaves Parked) and every folded node deep-links to `/site-calls/report?correlationId=` / `/notifications/report?correlationId=` (both pages accept it through additive `TrackedOperationIdFilter` / `NotificationIdFilter` query params and auto-open the row); register row 111 closed. **Trap closed the same day:** `FlowDebugService.PredictMethodAsync` used to resolve route targets with `GetAwaiter().GetResult()` inside the synchronous predictor walk — on the Blazor renderer sync context that DEADLOCKED the whole circuit (page inert, healthy websocket, no error) whenever a method routing to a site script was chosen; now a resolve-and-rewalk loop, pinned by a single-thread-pump test. Never block on a task from a Blazor event/lifecycle path. Browser checks of the page go through Playwright (`FlowDebuggerTests`, fixture login + an ephemeral method), not the login-disabled override. **Arch-reviewed 2026-09-06** (`docs/plans/2026-09-06-flow-debugger-arch-review.md`, remediation `docs/plans/2026-09-06-flow-debugger-arch-review-remediation.md`): the inline Live trace copy is now redacted and capped by the shared `FlowTraceCollector` (500 events **and** 1 MB of `DetailsJson`, F1), a method-entry Live run enforces the operator's site scope at route time (`RouteHelper.WithSiteScope` → `SITE_SCOPE_DENIED` → `ManagementUnauthorized`, F2) — **and since Gitea #55 a site-scoped operator is refused a method Live run outright** (a method has no site, so its central-side effects can't be scoped; audited, page disables the entry; Replay + script entry unchanged), and the page/Replay opened to the `OperationalAudit` roles under the new `RequireFlowDebugger` policy while everything that executes stays Deployer-only (F3). Design `docs/plans/2026-09-05-flow-debugger-design.md`; plan `docs/plans/2026-09-05-flow-debugger.md`. **v1.3 (2026-09-08, `docs/plans/2026-09-08-flow-debugger-script-entry-design.md`):** the second entry point is site → instance → **script**; ValueChange/Conditional scripts are fired by writing the trigger's attribute (derived from the trigger config, not picked), every other kind is a direct traced `RouteToCall` with a `ParameterValueForm` from the script's `ParameterDefinitions` and one operator-attributed `RouteCall` root row (`FlowDebugRunScriptCommand`, Deployer-only, long-running); `run-value-change` stays as the attribute-level CLI escape hatch (fires Expression triggers). **Instance picker (2026-09-08, `docs/plans/2026-09-08-instance-picker-design.md`):** Flow Debugger and Debug View both replaced their flat instance `