diff --git a/docker-dev/README.md b/docker-dev/README.md index fa55c9b8..c728f431 100644 --- a/docker-dev/README.md +++ b/docker-dev/README.md @@ -86,10 +86,33 @@ Central nodes authenticate against the shared GLAuth at `10.100.0.35:3893` (base ## Headless deploy ```bash -POST http://localhost:9200/api/deployments -X-Api-Key: docker-dev-deploy-key +./docker-dev/deploy.sh # trigger a deploy (no request body) +./docker-dev/deploy.sh artifact.json # …sending that JSON file as the request body ``` +`deploy.sh` polls `http://localhost:9200/health/ready` (every 2 s, up to 120 s) and only then +issues the single, un-retried `POST http://localhost:9200/api/deployments` with +`X-Api-Key: docker-dev-deploy-key`. Override the URL / key / timeout via `OTOPCUA_ADMIN_URL`, +`OTOPCUA_DEPLOY_API_KEY`, `OTOPCUA_READY_TIMEOUT_SECONDS`. + +### First-POST 404 + +The first headless POST after `up -d` was seen answering **404** ~40 s into boot (2026-08-17 live +gate), clearing on retry. Neither end can produce it: the AdminUI maps every route synchronously +before `RunAsync` (`Program.cs:740` maps the deploy API, `:803` runs) and that endpoint's only +failure modes are 503 / 401 / 422 / 409 / 500 — it has no 404 path; and Traefik answers a *matched* +router whose servers are all down with **503 "no available server"** (the checked-in +`traefik-dynamic.yml` router is `PathPrefix(/)` → `otopcua-admin` with a `/health/active` +healthCheck). Traefik's `api@internal` router (`PathPrefix(/api)`) is bound to the `:8080` +entrypoint (host 8089), not `web`/`:9200`, so it does not shadow `/api/deployments` either. So a +404 from `:9200` is Go's default "404 page not found" — **no router matched at that instant**; +the mechanism is unconfirmed. The `--accesslog=true --accesslog.fields.defaultmode=keep` flags on +the `traefik` service exist to diagnose the next occurrence: `docker compose -f +docker-dev/docker-compose.yml logs traefik` and look for the request with an empty `RouterName`. +The readiness gate in `deploy.sh` avoids the race (a 200 through `:9200` proves both a matched +router and a live backend), so a 404 *after* the gate is new evidence and the script fails loudly +saying so. + ## Tear down ```bash diff --git a/docker-dev/deploy.sh b/docker-dev/deploy.sh new file mode 100755 index 00000000..d3202c80 --- /dev/null +++ b/docker-dev/deploy.sh @@ -0,0 +1,100 @@ +#!/usr/bin/env bash +# +# Readiness-gated headless deploy trigger for the docker-dev rig. +# +# Why the gate exists: the 2026-08-17 live gate saw the first +# `POST http://localhost:9200/api/deployments` after `up -d` answer a transient 404 +# (~40 s into boot), which then cleared on a retry. That 404 can come from neither +# end of the request: the AdminUI maps every route synchronously before RunAsync and +# the deploy endpoint has no 404 path (503/401/422/409/500 only), and Traefik answers +# a matched-router-with-all-servers-down as 503 "no available server". So the 404 means +# no Traefik router matched at that instant. Polling /health/ready through :9200 until +# it answers 200 proves both halves are in place — the router table carries the +# otopcua-admin router AND a backend is up — before the single, un-retried POST. +# +# A 404 AFTER the gate is therefore new evidence, not the known boot race: it should be +# investigated against the Traefik access log (`--accesslog=true` on the traefik service; +# `docker compose -f docker-dev/docker-compose.yml logs traefik`), which records the +# RouterName (empty on an unmatched request) for the failing call. +# +# Usage: +# ./deploy.sh # no body (matches the bare README snippet) +# ./deploy.sh artifact.json # send that file as the JSON request body +# cat artifact.json | ./deploy.sh +# +# NOTE (unverified against a live rig): the no-body invocation sends +# `Content-Type: application/json` with an empty body. Whether the minimal-API +# `DeployRequest?` parameter binds that as null or answers 400 has not been confirmed. +# +set -euo pipefail + +BASE_URL="${OTOPCUA_ADMIN_URL:-http://localhost:9200}" +DEPLOY_URL="$BASE_URL/api/deployments" +READY_URL="$BASE_URL/health/ready" +API_KEY="${OTOPCUA_DEPLOY_API_KEY:-docker-dev-deploy-key}" +READY_TIMEOUT_SECONDS="${OTOPCUA_READY_TIMEOUT_SECONDS:-120}" +READY_POLL_SECONDS=2 + +# --- 1. readiness gate ------------------------------------------------------- +echo "Waiting for $READY_URL (up to ${READY_TIMEOUT_SECONDS}s)..." +deadline=$(( $(date +%s) + READY_TIMEOUT_SECONDS )) +ready=0 +while [ "$(date +%s)" -lt "$deadline" ]; do + # --max-time bounds a connected-but-hung backend, so one poll can never eat the budget. + code="$(curl -s --max-time 10 -o /dev/null -w "%{http_code}" "$READY_URL" || true)" + if [ "$code" = "200" ]; then + ready=1 + break + fi + echo " not ready yet (HTTP ${code:-000}); retrying in ${READY_POLL_SECONDS}s" + sleep "$READY_POLL_SECONDS" +done + +if [ "$ready" -ne 1 ]; then + echo "ERROR: $READY_URL did not return 200 within ${READY_TIMEOUT_SECONDS}s — not posting." >&2 + echo " Check the stack is up: docker compose -f docker-dev/docker-compose.yml ps" >&2 + exit 1 +fi +echo "Ready. Posting deployment..." + +# --- 2. the single, un-retried POST ------------------------------------------ +curl_args=(-s --max-time 60 -w '\n%{http_code}' -X POST "$DEPLOY_URL" + -H "X-Api-Key: $API_KEY" + -H "Content-Type: application/json") + +if [ "$#" -ge 1 ]; then + [ -f "$1" ] || { echo "ERROR: body file not found: $1" >&2; exit 2; } + curl_args+=(--data-binary "@$1") +elif [ ! -t 0 ]; then + curl_args+=(--data-binary @-) +fi + +# Guarded: a transport-level curl failure (connection refused/reset, timeout) must not trip +# `set -e` before the status/body reporting below — that reporting is the whole point here. +if ! response="$(curl "${curl_args[@]}")"; then + echo "ERROR: POST $DEPLOY_URL failed (curl could not complete the request)." >&2 + exit 1 +fi +status="$(printf '%s' "$response" | tail -n1)" +body="$(printf '%s' "$response" | sed '$d')" + +echo "HTTP $status" +if [ -n "$body" ]; then printf '%s\n' "$body"; fi + +case "$status" in + 2*) + exit 0 + ;; + 404) + echo "ERROR: POST $DEPLOY_URL returned 404 AFTER the readiness gate passed." >&2 + echo " This is NEW evidence — the AdminUI deploy endpoint has no 404 path and a" >&2 + echo " down backend answers 503, so no Traefik router matched this request." >&2 + echo " Inspect the Traefik access log (RouterName is empty on an unmatched request):" >&2 + echo " docker compose -f docker-dev/docker-compose.yml logs traefik" >&2 + exit 1 + ;; + *) + echo "ERROR: POST $DEPLOY_URL failed with HTTP $status." >&2 + exit 1 + ;; +esac diff --git a/docker-dev/docker-compose.yml b/docker-dev/docker-compose.yml index 3ab758c0..97abc07c 100644 --- a/docker-dev/docker-compose.yml +++ b/docker-dev/docker-compose.yml @@ -914,6 +914,14 @@ services: - --providers.file.filename=/etc/traefik/dynamic.yml - --providers.file.watch=true - --api.insecure=true + # Access log, on deliberately: the 2026-08-17 live gate saw a transient 404 on the + # first POST /api/deployments (~40 s after boot) that can only mean "no router + # matched" — the AdminUI has no 404 path on that endpoint and a matched router with + # every server down answers 503. `defaultmode=keep` keeps RouterName/ServiceName in + # each line, which is empty on an unmatched request — that is how the next + # occurrence gets diagnosed. See docker-dev/README.md §"First-POST 404". + - --accesslog=true + - --accesslog.fields.defaultmode=keep ports: - "9200:80" # host port 9200 → traefik :80 entrypoint (80 conflicts with scadabridge-traefik) - "8089:8080" # 8080 conflicts with the sister scadalink dev stack diff --git a/docs/plans/2026-08-17-perf-followups-r2.md b/docs/plans/2026-08-17-perf-followups-r2.md new file mode 100644 index 00000000..3ad01266 --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r2.md @@ -0,0 +1,589 @@ +# Perf Follow-ups Round 2 Implementation Plan + +> **For Claude:** REQUIRED SUB-SKILL: Use superpowers-extended-cc:subagent-driven-development to +> implement this plan task-by-task. Opus implementers; classification-driven review chains. + +**Goal:** Close the follow-up register opened by the 2026-08-17 perf follow-ups round +(`docs/plans/2026-08-17-perf-followups.md` §"Follow-up register") — the ACL +generation-rollover window, the S7 coverage gaps (cancellation branches, one-bad-decode, +Timer/Counter live pin), the historian test hope-waits, the orphaned-test-DB reaper, the +MTConnect ownership comment, and the docker-dev deploy readiness gate. + +**Architecture:** No new subsystems. One production concurrency fix (generation stamp on the +ACL cache's `Shard`), one production doc comment (MTConnect), one rig hardening +(`docker-dev/deploy.sh` + Traefik access log); everything else is test/fixture work. Branch +`perf/followups-r2` off master (`7bb888be`). + +**Tech Stack:** .NET 10, xUnit + Shouldly, Akka.NET TestKit, python-snap7 fixture on +`10.100.0.35`, SQL Server at `10.100.0.35,14330`, Traefik v3.1 on the local OrbStack rig. + +**Out of scope (say so once, here):** the cross-repo HistorianGateway batch `WriteLiveValues` +RPC (sister repo); the VPN-gated historian E2E; the FetchAndCache / ACL-enabled / alarm-ratchet +/ load-scale live exercises (separate live-gate effort, on request). + +--- + +## SHARED-CHECKOUT RULES (every implementer, verbatim from round 1) + +All implementers share ONE checkout on branch `perf/followups-r2`. Therefore: + +- Stage and commit with **explicit pathspecs only**: `git add -- ` then + `git commit -m "" -- `. NEVER bare `git commit`, `git add .`, `git add -A`. +- NEVER run `git checkout`, `git switch`, `git reset`, `git stash`, `git clean`, or touch + files outside your task's `Files:` contract. +- On `index.lock` contention or transient build races (CS2012, MSB3030): wait 5–15 s and retry. +- Falsification mutations (temporarily reverting a fix to prove a test bites) are made with + Edit and reverted with Edit — never with git. +- TDD red-first where the plan says so; when a test pins existing behaviour instead, label it + honestly ("pin, not red-first") in your report. +- Build/test only your own projects (`dotnet build ` / `dotnet test + [--filter ...]`), not the whole solution. + +--- + +### Task 1: Close the ACL generation-rollover window; capacity hint on eviction + +**Classification:** high-risk +**Estimated implement time:** ~5 min +**Parallelizable with:** Task 2, Task 3, Task 4, Task 5, Task 6, Task 7 + +**Files:** +- Modify: `src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs` +- Test: `tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs` + +**The defect (pre-existing, recorded by round 1).** `InvalidateIfStale` (lines 342–350) +publishes the new `_generation` in the CAS at line 349 *before* the winner's `ClearAll()` +(365–370) has purged the shards. A racer entering `TryGet` (167–183) in that window reads +`seen == generation`, skips clearing, and serves an entry written under the previous +generation from a shard the winner has not removed yet. Key revocation/expiry are unaffected +(re-checked above the cache), so this is a stale grant walk only — but it is real, and the fix +shape was already chosen in round 1's register: **stamp the generation on `Shard` itself**. + +**Spec:** + +1. `Shard` (lines 378–391) gains a constructor taking `long generation` (stored in a + `public readonly long Generation` field) and an optional initial-capacity hint for + `Entries` (see step 6). All four construction sites in `Set` (lines 208, 221, 232, 236) + pass the current query generation. +2. `TryGet` serves a hit **only when `shard.Generation == generation`**. A + generation-mismatched shard is a miss (do not evict from the read path — `TryGet` must stay + allocation-free and non-mutating; the winner's `ClearAll` or the next `Set` reclaims it). +3. `Set`: after acquiring the shard, if `shard.Generation != generation`, evict-swap exactly + like the existing per-shard bound path (`TryUpdate(sessionKey, new Shard(generation), shard)` + + `Interlocked.Add(ref _globalCount, -Seal(shard))`, then re-acquire) before inserting. + `_globalCount` accounting must stay exact — the seal/booking protocol from `d8849345` is + load-bearing; do not weaken `TryBookInsert`/`Seal`. +4. **Deterministic pin of the window** (this is the red-first test): add an internal + test-only seam `internal void AdvanceGenerationForTest(long generation)` that CAS-moves + `_generation` WITHOUT calling `ClearAll` — exactly the racer's view of the window. Test: + `Set` under gen 1, `AdvanceGenerationForTest(2)`, then `TryGet(gen 2, …)` for the same key + **must miss**. Run it before the fix: it goes red (the stale entry is served). After the + fix: green. Falsification after fixing: temporarily remove the `shard.Generation` check via + Edit, confirm red, restore. +5. Extend the existing stress test (lines 186–264) or add a sibling: interleave generation + bumps with readers/writers and assert **no hit ever returns a value stored under an older + generation** (encode the generation in the stored bool — e.g. store `gen % 2 == 0` — and + assert every hit equals the current generation's encoding). Also keep asserting + `TrackedCount`/`LiveShardCount` exactness at quiescence. +6. **Capacity hint (second register item, same ctor):** only the eviction-swap site (line 232 + path) passes a capacity hint — the evicted shard's sealed count, clamped to a sane bound + (e.g. `Math.Clamp(captured, 0, MaxEntriesPerShard)` or the existing per-key ceiling const) — + because a shard evicted at the ceiling *is* the crawler signal. Plain `GetOrAdd` shards + stay default-capacity. One test: after an eviction swap, inserts proceed correctly (a + behaviour pin; capacity itself is not observable — say so in the test comment). +7. Update the class-level comments where they describe the invalidation story; do not restate + history, state the invariant ("a shard can only serve the generation it was built under"). + +**Steps:** red test (4) → fix (1–3) → green → falsification → stress (5) → capacity (6) → +`dotnet test tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests --filter "FullyQualifiedName~SessionAclDecisionCache"` +→ commit with pathspecs: `git commit -m "fix(acl): stamp the generation on Shard so a rollover racer cannot serve a stale-generation verdict; eviction-swap capacity hint" -- `. + +--- + +### Task 2: S7 read-path coverage — cancellation branches + one bad decode in a chunk + +**Classification:** standard +**Estimated implement time:** ~5 min +**Parallelizable with:** Task 1, Task 3, Task 4, Task 5, Task 6, Task 7 + +**Files:** +- Test (only): `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs` + +**Context.** Three read paths carry the STAB-15a cancellation contract (`_plcDead = true` + +rethrow): per-tag (`S7Driver.cs:649-660`, covered by +`S7DriverReconnectTests.Cancelled_read_marks_handle_dead_and_next_read_reopens`), span block +read (`S7Driver.cs:920-926`, **uncovered**), multi-var leftovers (`S7Driver.cs:803-809`, +**uncovered**). The per-chunk fallback (`:810-817`) has one whole-request-fault test; the +per-ITEM decode guard (`:819-836`, null value → `InvalidDataException` → that tag Bad) and the +shape-mismatch arm (`:796-801`) have none. `ImageS7PlcFactory` +(`S7SpanReadParityTests.cs:453`, `ImageS7Plc` at `:480`) exposes only `ReadFault` and +`MultiVarFault` knobs today. + +**Spec — all tests are pins of existing behaviour unless marked red-first:** + +1. Extend `ImageS7PlcFactory`/`ImageS7Plc` with three knobs, mirroring the existing fault + knobs' style: + - `HangReadBytes` (a `TaskCompletionSource` gate): `ReadBytesAsync` awaits + `Task.Delay(Timeout.Infinite, ct)` so cancellation is the only exit — the + `S7DriverReconnectTests` fake at `:557-560` is the pattern. + - `HangMultiVar`: same for `ReadMultipleVarsAsync`. + - `NullItemIndex` (int?): `ReadMultipleVarsAsync` returns the normal answered list but with + item N's `Value` left null — the decode guard's trigger at `:824-826`. + Track a `CreatedPlcCount` on the factory if not already present (reopen observable). +2. **Cancelled span block read:** plan spans on, hang `ReadBytesAsync`, cancel the read's CTS, + assert `OperationCanceledException` propagates out of `ReadAsync`, and the NEXT read + constructs a fresh plc (`CreatedPlcCount` increments — the `_plcDead` reopen contract), + using the same assertion shape as the reconnect test at `S7DriverReconnectTests.cs:338-355`. +3. **Cancelled multi-var read:** spans on with a leftover batch (reuse the existing + multi-var-eligible tag set from `:257/:281`), hang `ReadMultipleVarsAsync`, cancel, same + two assertions. +4. **One bad decode inside an otherwise-good chunk:** `NullItemIndex = 1` on a 3-item + multi-var chunk → exactly that tag lands Bad (`RecordReadFailure` status), its chunk-mates + Good with correct values, `MultiVarCalls == 1`, and **no per-tag fallback reads occur** for + the good items (per-item failure is not chunk failure). Assert driver health reflects the + partial failure the same way the existing fallback test does. +5. **Shape mismatch:** a knob (or reuse `NullItemIndex`-style) making `ReadMultipleVarsAsync` + return `chunk.Count - 1` items → the whole chunk falls back per-tag (`:796-801` → + `InvalidDataException` → `:810-817`), all values still served Good via fallback. +6. Falsification for (2) and (3): via Edit, temporarily change the production OCE arm to swallow + (mimic the pre-#527-style bug) and confirm the reopen assertion goes red; restore. Note in + the report which line was mutated. + +**Steps:** knobs → tests (each run individually) → falsification → full file run +(`dotnet test tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests --filter "FullyQualifiedName~S7SpanReadParityTests"`) +→ commit `test(s7): pin the span/multi-var cancellation reopen contract, one-bad-decode-in-chunk, and multi-var shape mismatch -- tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs`. + +--- + +### Task 3: Timer/Counter live pin — TM/CT area in the s7_1500 fixture + +**Classification:** standard (live-gated) +**Estimated implement time:** ~5 min authoring + fixture redeploy wall-time +**Parallelizable with:** Task 1, Task 2, Task 4, Task 5, Task 6, Task 7 (disjoint files; the +live leg runs against the shared fixture host, not the checkout) + +**Files:** +- Modify: `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/profiles/s7_1500.json` +- Modify: `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/S7_1500/S7_1500SpanReadTests.cs` +- Modify (if needed for seeding TM/CT): `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/server.py` +- Modify: `tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/README.md` + +**Context.** The round-1 gate could not live-pin the Timer/Counter multi-var exclusion because +the fixture profile declares only DB1 + MK (`s7_1500.json`), though `server.py:34-41`'s +`AREA_MAP` already supports `TM`/`CT` (`snap7.type.SrvArea`). The exclusion itself: +`S7ReadSpanPlanner.cs:94-103` (planner → leftovers) and `S7Driver.cs:1129-1132` +(`IsBufferType` → never multi-var). Timer/Counter entries are 2-byte device-number-indexed +cells; a "device number N" seed lands at byte offset `2*N` big-endian in the area buffer. + +**Spec:** + +1. Add `TM` index 0 and `CT` index 0 areas (size 64 bytes each = 32 devices) to + `s7_1500.json` with 2–3 distinct non-zero seeds each (the #536 rule: a zero-valued source + proves nothing) at known device numbers, `_desc`'d. Keep every existing seed byte-identical + — the round-1 tests depend on them. +2. New `[SkippableFact]`-style test (follow the file's existing gating convention) in + `S7_1500SpanReadTests.cs`: author a tag set mixing multi-var-eligible scalars with one + Timer and one Counter tag; spans on. Assert: + - the Timer/Counter values read back as the seeded non-zero constants (correct decode on a + real wire), and + - via `CountingPlc`, **no multi-var request ever contains a Timer/Counter item** and the + TM/CT reads arrive as their own block/per-tag requests — the live pin of the exclusion. +3. **Accepted alternate outcome, stated in advance:** S7.Net's TM/CT read is a distinct wire + shape the python-snap7 server has never served. If it genuinely cannot (live evidence: + error/exception captured, not a guess), do NOT force it: env-gate the test with a skip + reason naming the fixture limitation, record the evidence in the Outcomes, and the + exclusion stays unit-pinned. A red herring here must not burn the task. +4. Fixture redeploy recipe (round-1 ops notes, both bit last time): + `rsync -av --rsync-path="sudo rsync" tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/ dohertj2@10.100.0.35:/opt/otopcua-s7/` + then `ssh dohertj2@10.100.0.35 'cd /opt/otopcua-s7 && docker compose build && docker compose up -d --force-recreate'` + — `--build` is mandatory (profile is baked into the image) and confirm + `seeded DB1 … seeds=` (and the new TM/CT lines) in `docker logs`. +5. Run: `dotnet test tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests --filter "FullyQualifiedName~S7_1500SpanReadTests"` with the fixture live. All pre-existing + tests must stay green (the seed-compat rule in step 1). + +**Commit:** `test(s7): live-pin the Timer/Counter multi-var exclusion against a TM/CT-seeded s7_1500 fixture` with pathspecs. + +--- + +### Task 4: Historian recorder tests — bounded watches instead of hope-waits + +**Classification:** standard +**Estimated implement time:** ~4 min +**Parallelizable with:** Task 1, Task 2, Task 3, Task 5, Task 6, Task 7 + +**Files:** +- Test (only): `tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs` + +**Context.** Three fixed sleeps synchronize negative assertions ("X did not happen"): +line 602 (`FromMilliseconds(500)` before asserting no truncation after a shutdown-cancelled +write), line 452 (300 ms before asserting an abandoned tag stopped being rewritten), line 857 +(300 ms before asserting sequential-drain concurrency). A negative can't be polled for +directly; each needs a **positive completion observable**, then the assert. The Task-9 +treatment (`FasterLogHistorizationOutboxTests.cs:203-231`) is the pattern for the poll shape +(Stopwatch + 25 ms + cap, return last observation). `InMemoryOutbox` has +`AppendCallCount`/`AppendBatchCallCount`/`PeekBatchCallCount`/`DroppedCount` but **no +`RemoveCallCount`**. + +**Spec:** + +1. Add `RemoveCallCount` to `InMemoryOutbox` (increment in `RemoveAsync`), same style as the + existing counters. +2. **Line 602 test:** replace the sleep with a bounded watch: after `writer.Cancelled`, poll + (25 ms / 2 s cap) for the *bug's* positive signal — `RemoveCallCount > 0` or + `CountAsync != 2` — failing fast red if either fires, green after the full window if + neither does. Comment: "bounded negative watch — red is immediate when the fold truncates, + green costs the window once". Keep the existing preconditions (594–595) untouched. +3. **Line 452 test:** replace wall-clock with the drain's own clock: snapshot + `PeekBatchCallCount`, poll until it has advanced by ≥ 3 (more passes have demonstrably + run), then assert the `Good.Tag` write count is unchanged. Cap 5 s; on cap-out without 3 + passes, fail with a message naming the observed pass count. +4. **Line 857 test:** same pass-count clock (≥ 2 further passes) before the concurrency + asserts; keep the existing `AwaitAssertAsync` precondition. +5. Do NOT touch the deliberate mechanics delays (1476, 1640, 1656, 1673 — documented + pool-thread forcing; leave them and their comments alone). +6. Each reworked test: run 5× locally (`--filter`) to check stability; note the timings in + the report. + +**Commit:** `test(historian): replace the recorder tests' fixed sleeps with bounded watches on drain-pass and truncation observables` with pathspecs. + +--- + +### Task 5: Orphaned test-database reaper (AdminUI + Configuration fixtures) + +**Classification:** standard +**Estimated implement time:** ~4 min +**Parallelizable with:** Task 1, Task 2, Task 3, Task 4, Task 6, Task 7 + +**Files:** +- Modify: `tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/AdminUiSqlServerFixture.cs` +- Modify: `tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/SchemaComplianceFixture.cs` +- Test: a new `[SqlServerFact]` (AdminUI side) proving the reaper drops an old-named DB + +**Context.** A killed test process leaks its uniquely-named database forever: +`OtOpcUaAdminUi_Test__` (`AdminUiSqlServerFixture.cs:77`) and +`OtOpcUaConfig_Test_…` (`SchemaComplianceFixture.cs:30`). The fixture comment at 127–128 even +says the timestamp exists "so a leaked one is identifiable" — the reaper was never written. +Natural insertion point: fixture ctor, after the probe early-return (`:75`), before the name +assignment (`:77`). The drop SQL to reuse is `:118-121`; `TryDropDatabase` must be extracted +to a static taking a name. + +**Spec — safety first, this runs DROP DATABASE against a shared server:** + +1. Extract the drop body into a static `TryDropDatabase(string databaseName)` (best-effort, + `DbException`-swallowing, exactly the current semantics); the instance method delegates. +2. Add a static reaper, run **once per process** behind a `Lazy` in `AdminUiSqlServer` + (mirroring the probe): `SELECT name FROM sys.databases WHERE name LIKE + 'OtOpcUaAdminUi\_Test\_%' ESCAPE '\'`, parse the embedded `yyyyMMddHHmmss` (UTC), and drop + ONLY rows **older than 24 hours**; a name whose timestamp does not parse is left alone. + Never throw — a reaper failure must not fail a green run. Log nothing louder than + `Console.WriteLine` (test infra convention in this file). +3. Same shape in `SchemaComplianceFixture` for the `OtOpcUaConfig_Test_` prefix, one-shot per + process. (It has no probe/skip machinery — keep the reaper `catch`-all so an unreachable + server behaves exactly as today.) +4. **Test (red-first is impossible for a time-gated reaper without waiting a day, so pin it + deterministically):** a `[SqlServerFact]` that creates an empty DB named with a >24 h-old + timestamp (e.g. `OtOpcUaAdminUi_Test_20250101000000_`), invokes the reaper's core + (make the core internal-testable, taking the cutoff as a parameter), and asserts the DB is + gone — and a second DB named with a **fresh** timestamp survives the same call. Clean up + the survivor in the test. +5. The mid-run-blip semantics (one-shot probe → mid-run `SqlException` = failures, not skips) + stay as-is — they are already documented at `:34-38`; verify the comment survives your + edit, extend it with one line noting the deliberate non-choice if it doesn't already say so. + +**Commit:** `test(sql): reap >24h-old orphaned test databases at fixture startup (AdminUI + Configuration prefixes)` with pathspecs. + +--- + +### Task 6: MTConnect `AsStream` buffer-ownership comment + +**Classification:** trivial +**Estimated implement time:** ~1 min +**Parallelizable with:** all + +**Files:** +- Modify: `src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.MTConnect/MTConnectStreamsParser.cs` (the + `AsStream` doc comment at lines 241–249) + +**Spec:** extend the existing `` with the ownership facts (verified this round): +the array-backed branch **aliases the caller's array without copying**; the buffer is not +pooled or rented anywhere on this path; parsing is fully synchronous, so the buffer must stay +valid and unmutated only **for the duration of the call**; the returned +`MTConnectStreamsResult` holds no reference into the buffer (`XmlReader` materialises its own +strings). Comment-only — no code change, no test. + +**Commit:** `docs(mtconnect): state AsStream's buffer aliasing and lifetime contract` with pathspec. + +--- + +### Task 7: docker-dev readiness-gated deploy helper + Traefik access log + +**Classification:** small +**Estimated implement time:** ~4 min +**Parallelizable with:** all + +**Files:** +- Create: `docker-dev/deploy.sh` +- Modify: `docker-dev/docker-compose.yml` (Traefik command block, lines ~912-916) +- Modify: `docker-dev/README.md` (the bare POST snippet at lines ~88-91) + +**Context (root-cause facts, record them in the README):** the transient first-POST 404 can NOT +come from the AdminUI (all routes map synchronously before `RunAsync` +(`Program.cs:740` vs `:803`); the endpoint's own failures are 503/401/422, never 404) and can +NOT be Traefik's backend-down answer (that is 503 `no available server`). A 404 from :9200 +means **no Traefik router matched at that instant** — mechanism unconfirmed; the access log +below is how the next occurrence gets diagnosed. + +**Spec:** + +1. `deploy.sh` (bash, `set -euo pipefail`): polls `http://localhost:9200/health/ready` until + HTTP 200 (2 s interval, 120 s cap — a 200 through Traefik proves both the router table and + a ready backend), then POSTs the artifact exactly as the README snippet does + (`X-Api-Key: docker-dev-deploy-key`, JSON body from `$1` or stdin), prints the response, + and exits non-zero on any non-2xx. No retry on the POST itself — the gate is the fix, and + a post-gate 404 should fail loudly (it would be new evidence). +2. Add `--accesslog=true` (and `--accesslog.fields.defaultmode=keep`) to the Traefik command + list so a recurrence shows which router (or none) matched. +3. README: replace the bare POST snippet with `./deploy.sh`, and add a short "first-POST 404" + note carrying the root-cause facts above. +4. Verification is docker-dev-rig-dependent; `bash -n deploy.sh` + a `docker compose config` + parse check are the in-checkout gate. The rig run happens in Task 8's close-out if the rig + is brought up; do not block this task on it. + +**Commit:** `chore(docker-dev): readiness-gated deploy.sh + Traefik access log for the first-POST 404` with pathspecs. + +--- + +### Task 8: Close-out — sweep + Outcomes + register annotations + +**Classification:** standard +**Estimated implement time:** ~10 min (mostly sweep wall-time) +**Parallelizable with:** none (blockedBy all) + +**Files:** +- Modify: `docs/plans/2026-08-17-perf-followups-r2.md` (append `## Outcomes`) +- Modify: `docs/plans/2026-08-17-perf-followups.md` (append-only "closed by " annotations + on the round-1 register items this round closes; the two live-exercise items that stay open + stay open) +- Modify: `docs/plans/2026-08-17-perf-followups-r2.md.tasks.json` (ledger) + +**Steps:** + +1. `dotnet build ZB.MOM.WW.OtOpcUa.slnx` → 0 errors (pre-existing warnings tolerated). +2. Full per-project unit sweep of every `*.Tests` project (`--no-build` after the solution + build), same protocol as round 1. DB-backed suites must RUN (not skip) against + `10.100.0.35,14330`. Expected: 0 failed; new-test count above round 1's 10,358 baseline. +3. S7 integration suite against the live fixture (Task 3's evidence re-confirmed at the final + tree). +4. Append `## Outcomes`: per-task table (commit, outcome, deviation), the TM/CT live evidence + (or the documented fixture limitation), the reaper's first live reap count, any new + follow-up register (only genuinely new items). +5. Annotate the round-1 register (append-only, never rewrite): ACL rollover + capacity hint, + S7 cancellation + one-bad-decode + TM/CT, historian hope-wait, AdminUI reaper (blip + semantics = documented wontfix), MTConnect comment, docker-dev readiness gate — each with + its closing SHA. +6. Commit docs with pathspecs; update the ledger. + +--- + +## Execution notes for the controller + +- Wave 1: Tasks 1–7 dispatched concurrently (all `Files:` contracts disjoint). Task 8 after + all verdicts land. +- Review chains per classification: T1 high-risk (spec serial → code); T2/T3/T4/T5/T8 + standard (spec ∥ code); T7 small (code only); T6 trivial (none). +- Implementers: Opus (user preference), including the trivial task for uniformity. +- Reviewers judge via `git show `; file-disjoint scheduling makes on-disk fallback + acceptable as in round 1. + +--- + +## Outcomes + +*Written at close-out, 2026-08-17, on branch `perf/followups-r2`. All 8 tasks complete. This +round is a **follow-up round**: every item it closes was opened by the round-1 register in +`2026-08-17-perf-followups.md`, and that register is annotated in place with the closing SHAs.* + +### Sweep record + +`dotnet build ZB.MOM.WW.OtOpcUa.slnx` → **0 errors**, 904 warnings — the same two pre-existing +families round 1 recorded (`xUnit1051` cancellation-token advice and the repo's own +`OTOPCUA0001` CapabilityInvoker analyzer firing on test call sites), up 8 from round 1's 896 +because this round's new test call sites are more of the same. No new warning *kind*. + +Full unit sweep — every `*.Tests` project in the solution, run per-project with `--no-build` +against the tree at `580b77ce`. `*.IntegrationTests` are build-only by convention; the S7 suite +ran separately as Task 3's live gate (below). + +**43 / 43 test projects green (exit code 0 on every one).** + +| | Round 1 | **This round** | Δ | +|---|---|---|---| +| Passed | 10 358 | **10 370** | **+12** | +| Failed | 0 | **0** | — | +| Skipped | 19 | **19** | — | +| **Total** | 10 377 | **10 389** | +12 | + +**No test failed, so no isolation re-run was needed, and nothing flaked.** The +12 reconciles +exactly against the three suites this round added tests to, with nothing unaccounted for: + +| Project | Round 1 | This round | Δ | Source | +|---|---|---|---|---| +| `OpcUaServer.Tests` | 476 | **481** | +5 | `SessionAclDecisionCacheTests` 12 → **17** (T1) | +| `Driver.S7.Tests` | 397 | **401** | +4 | `S7SpanReadParityTests` 9 → **13** (T2) | +| `AdminUI.Tests` | 1 537 | **1 540** | +3 | `SqlTestDatabaseReaperTests` (T5) | + +⚠️ **Note the S7 delta is +4, not the +5 the plan estimated** — the plan's task text counted +five *contracts* pinned, which landed as four test methods (one method carries two of them). +T4 added no tests (it reworked 3 of the 5 existing recorder tests in place), and the S7 +**integration** suite's +2 do not appear here because it is build-only in the sweep. + +**All 19 skips are the pre-existing, env-gated ones round 1 recorded, project for project** — +`Core.Tests` (1), `Driver.Galaxy.Tests` (8), `Driver.Historian.Gateway.Tests` (6, the +`LiveIntegration` category needing the `wonder-sql-vd03` VPN), `OpcUaServer.Tests` (1), +`Runtime.Tests` (3). **This round added no skips.** + +The DB-backed suites ran **against a reachable** `10.100.0.35,14330` — executed, not skipped: +`AdminUI.Tests` **1540 passed / 0 skipped** and `Configuration.Tests` **190 / 0 skipped**. That +zero is the load-bearing number for T5: a reaper suite that skipped itself would have proved +nothing about the DDL it runs as `sa`. + +Two verifications outside the sweep proper, because two comment-only fixes (below) landed after +the sweep's build: the solution rebuilt **0 errors**, and `OpcUaServer.Tests` re-ran +**481 / 0 / 1**, unchanged. + +### Per-task outcomes + +| # | Task | Commit(s) | Outcome + deviation | +|---|---|---|---| +| 1 | ACL generation stamp on `Shard` + eviction capacity hint | `1979cf41`, `98d6a190` | Done, **and the review found a second, pre-existing defect that was closed in-round.** The generation is now stamped on `Shard` (ctor + readonly `Generation`); `TryGet` is generation-gated and **non-mutating**; `Set` displaces a mismatched shard and **drops the verdict** if it is still mismatched after the displacement. The eviction capacity hint is gated on the generation matching — a previous generation's fill level is not evidence about this one. `98d6a190` added a monotonic `<=` guard to `InvalidateIfStale` after the reviewer spotted that a stale-generation straggler could roll the stamp *backward* and thrash `ClearAll`. **Falsifications:** removing the stamp check went **deterministically red** on the pin *and* produced **1 357 cross-generation hits** in the stress test; reverting the `<=` guard to `==` rolled the stamp **2 → 1**. 17/17. | +| 2 | S7 cancellation branches + one-bad-decode + shape mismatch | `4f860733`, `120e885b` | Done. The span and multi-var **cancellation reopen** contracts are pinned (hang knobs + entered-TCS + `CreatedPlcCount`), plus one-bad-decode-in-chunk (only that tag goes Bad, **no** fallback) and the short-answer shape mismatch (**whole-chunk** fallback). `120e885b` strengthened the pins to assert the stale handle is **disposed**, not merely replaced. **Falsification:** each `OperationCanceledException` arm was weakened in turn and **exactly the matching test** went red — no arm was covered by a neighbour's test. 13/13. | +| 3 | Timer/Counter live pin — TM/CT area in the `s7_1500` fixture | `fd202d81`, `f797df51` | **LIVE PIN PASSED** vs `10.100.0.35:1102`. Evidence + the fixture quirk below. | +| 4 | Historian recorder tests — bounded watches | `45d67092`, `68461fbf` | Done; three fixed sleeps → bounded watches. Detail below. | +| 5 | Orphaned test-database reaper | `8946644b`, `580b77ce` | Done — **and the code review found a real Critical, fixed pre-merge.** Detail below. | +| 6 | MTConnect `AsStream` ownership comment | `1edfc263` | Done as specified; comment-only, no test. Trivial ⇒ no review. | +| 7 | docker-dev readiness-gated `deploy.sh` + Traefik access log | `a61b3c98`, `9f09a62a` | Done as a **gate plus instrumentation, not a diagnosis** — say so plainly. Detail below. | +| 8 | Close-out — sweep + Outcomes + register annotations | `d54b4fab`, *this commit* | Done. `d54b4fab` carries the two comment-only nits the T1 re-review left for close-out; this commit carries the Outcomes, the sweep record, the round-1 register annotations, and the ledger. | + +### Live pin — S7 Timer/Counter multi-var exclusion (Task 3) + +**2026-08-17, against the `s7_1500` fixture at `10.100.0.35:1102`. PASSED — 4 passed / 1 +env-gated skip.** + +TM and CT areas were added to the fixture profile: **TM0** (`T0 = 0x2456` = 456.0 s, +`T5 = 0x1123` = 12.3 s, `T9`) and **CT0** (`C0 = 4711`, `C7 = 31337`, `C11`). + +- **The claim under test, asserted on real wire shapes:** a batch mixing Timer/Counter tags with + ordinary ones produced **1 block read + 1 multi-var request carrying 3 scalar items + one + 2-byte TM read + one 2-byte CT read**, and `MultiVarItemAreas` **never contains Timer or + Counter**. The round-1 exclusion — added because S7.Net boxes TM/CT as `int` where the + single-read path yields `ushort`, and box parity is load-bearing downstream — now rests on the + wire, not on unit tests alone. +- ⚠️ **Fixture quirk, discovered here and documented with a recaptured live probe transcript:** + python-snap7's server resolves a TM/CT request address as a **BIT address** (it serves byte + `addr >> 3`) where S7.Net and a real CPU send the **device number**. **Device 0 is the fixed + point of both conventions**, which is why value decode is live-pinned at **T0/C0**. +- The device-number leg (T5/C7) is therefore **env-gated on `S7_TIMER_NUMBER_ADDRESSING=1`** — + it is the single skip above, and it is a **ready-made real-CPU gate** rather than a silent + omission. **Not closed by this round:** TM/CT decode at a non-zero device number still needs a + real CPU. + +### Task 4 — what replaced each sleep, and the one place a pass clock does not exist + +Three fixed sleeps became bounded watches on **real observables**, not shorter sleeps: + +- **Shutdown test:** a 25 ms/1 s **negative** watch on the new `RemoveCallCount` and the queue + depth. The 1 s cap is not a guess — it is anchored to the **measured ~150 ms** at which the + falsification tripped, so the cap is roughly 6× the observed signal rather than an arbitrary + round number. `68461fbf` also reduced it to a **single counter read per poll** (two reads per + poll can straddle an increment and compare inconsistent values). +- **Poison-tag test:** a positive watch on `PeekBatchCallCount ≥ 3` — a genuine pass clock. +- ⚠️ **Sequential test: a 25 ms/500 ms negative watch, and this is a disclosed deviation.** A pass + clock is **structurally unavailable** there: the drain is single-flight on `_draining` and the + timer re-arms **only** in `OnDrainResult`, so there is no counter that advances while the + condition under test is false. Verified against the production code and **accepted** rather than + worked around with a fake observable. + +**Falsification:** tripped on `RemoveCallCount` in ~150 ms. 5× stability green. + +### Task 5 — the reaper's Critical, and why the live evidence is shaped the way it is + +The startup reaper drops test databases orphaned **> 24 h** (AdminUI + Configuration prefixes, +per fixture, one-shot `Lazy`, probe-gated on the AdminUI side). + +- ⚠️ **The code review found a real Critical.** The name-shape guard validated only the prefix and + the timestamp, so **any** `..._<14 digits>_` database name on the server would flow + into string-interpolated `ALTER`/`DROP` DDL executed **as `sa`**. Fixed **defense in depth**: + a `Guid.TryParseExact("N")` suffix validation *and* parameterized `QUOTENAME`/`sp_executesql`. + ⚠️ The reviewer's proposed `EXEC('…' + QUOTENAME(@name))` snippet was **itself invalid T-SQL** + (verified live — Msg 102); the accepted fix is not the one that was suggested. +- Also landed: a **3 s reaper `ConnectTimeout`** (a reaper must never be the thing that hangs a + test run), `DatabaseName` minted from the prefix constant rather than re-spelled, the catch + widened to `Exception`, and the reaper tests **joined to the AdminUI SQL collection** — closing + a same-process parallel-collection race that earlier 2-test runs had masked. +- **Live evidence:** planted orphans were reaped **by exactly the right fixture**; non-GUID and + unparseable names were **spared**; the shared server was restored afterwards. 3/3 reaper, + **1540/1540 AdminUI ×3**, 190/190 Configuration. + +### Task 7 — what the docker-dev change does and does not establish + +`deploy.sh` polls `/health/ready` (2 s interval, 120 s cap) and then POSTs **once, un-retried** +(both curls guarded under `set -e`, `--max-time 10/60`), and Traefik now runs `--accesslog`. + +⚠️ **The 404's mechanism is still unconfirmed.** What is *established* is the elimination: the +AdminUI cannot produce it (routes map synchronously before `RunAsync`; the endpoint's own +failure modes are 503/401/422), and Traefik's backend-down answer is 503 `no available server`, +not 404. So a 404 means **no router matched at that instant** — and the access log is how the +**next** occurrence gets named. The gate makes scripted deploys reliable; it does not explain +the bug. + +### Review chain + +7 implementers; **11 review verdicts** (T1 spec + code + delta re-review, T2 spec + code, T3 +spec + code, T4 spec + code, T5 spec + code + re-review, T7 code + re-review); **4 fix rounds** +(T1, T3, T5, T7, plus minors on T2/T4); **1 Critical found and fixed pre-merge** (T5's DDL +injection); **zero findings papered over**. + +Two **falsification-hygiene** lessons from this round, both worth carrying forward: + +- **A falsification must be run against a freshly built binary.** A `when (false)` mutation + combined with a `--no-build` run executed the *stale* binary and reported a vacuous green — + the mutation "passed" without ever having been compiled. +- **A green falsification arm proves nothing until you have seen its red.** T1's `Set`-displacement + behaviour was **unpinned** until a test written specifically for it went red; the existing + tests all passed with the displacement removed. + +### Follow-up register (opened by this round) + +Only genuinely **new or still-open** items. Everything else this round touched is annotated as +closed on the round-1 register. **None blocks the branch.** + +**ACL** + +- **The single-shot CAS can defer stamp publication by one call.** When generation *N* wins the + race for a shared baseline against generation *N+1*, publication of the newer stamp is deferred + one call. **Pre-existing and benign** — it self-heals on the next call and **no verdict is + affected** (a deferred stamp cannot serve a stale grant; the generation gate on `TryGet` is what + decides that, and it is unaffected). Recorded so the next reader does not re-derive it as a bug. + +**S7** + +- **Per-item decode health is last-writer-wins.** Pre-existing; now **pinned and documented** + rather than fixed, because changing it is a behaviour change to how a mixed-outcome chunk + reports driver health, not a test gap. +- **TM/CT decode at a non-zero device number still needs a real CPU.** The test exists and the + env var (`S7_TIMER_NUMBER_ADDRESSING=1`) is ready; python-snap7 cannot serve it (see the + BIT-address quirk above). + +**docker-dev** + +- **The first-POST 404's mechanism is unconfirmed** until the new access log catches an + occurrence. The gate prevents the symptom; the cause is still open. +- **The no-body `POST` `Content-Type` binding is unverified against a live rig** — carried as a + header NOTE in `deploy.sh` rather than silently assumed correct. + +**SQL test infrastructure** + +- **A cross-*process* plant-vs-reap race is inherent to a shared, unlocked server** and is + **accepted**: two test processes racing on the same instance can have one reap what the other + just planted. The 24 h age floor makes it vanishingly unlikely in practice, and the alternative + (a lock table on a shared dev server) costs more than it buys. diff --git a/docs/plans/2026-08-17-perf-followups-r2.md.tasks.json b/docs/plans/2026-08-17-perf-followups-r2.md.tasks.json new file mode 100644 index 00000000..d4b7d19c --- /dev/null +++ b/docs/plans/2026-08-17-perf-followups-r2.md.tasks.json @@ -0,0 +1,15 @@ +{ + "planPath": "docs/plans/2026-08-17-perf-followups-r2.md", + "tasks": [ + {"id": 1, "subject": "Task 1: ACL generation stamp on Shard + eviction capacity hint", "status": "completed", "note": "1979cf41 + follow-up 98d6a190 (monotonic <= guard on InvalidateIfStale closing the reviewer-found backward-rollback thrash; capacity hint gated on generation match); spec ✅ + code APPROVED + delta re-APPROVED; falsifications: stamp-check removal = 1357 cross-generation hits in stress; Set-displacement was unpinned until its own test; == revert = stamp rolled 2->1. Two cosmetic comment nits left for close-out; known residual (pre-existing, benign): single-shot CAS can defer publication one call when gen3 beats gen4 to the same baseline — self-heals, verdicts unaffected"}, + {"id": 2, "subject": "Task 2: S7 cancellation branches + one-bad-decode-in-chunk + shape mismatch", "status": "completed", "note": "4f860733 + fix 120e885b (Disposed assertion on the stale handle); spec ✅ + code APPROVED; falsification bit precisely on both OCE arms; noticed-not-fixed: per-item decode loop health is last-writer-wins (pinned + documented, pre-existing)"}, + {"id": 3, "subject": "Task 3: Timer/Counter live pin — TM/CT area in the s7_1500 fixture", "status": "completed", "note": "fd202d81 + fix f797df51 (README probe transcript recaptured against the shipped profile; CountingPlcFactory thread-safety remark); GATE: exclusion live-pinned at device 0 vs 10.100.0.35:1102 (snap7 resolves TM/CT addr as BIT address, byte=addr>>3; device 0 is the fixed point of both conventions); T5/C7 device-number test env-gated on S7_TIMER_NUMBER_ADDRESSING=1 as the real-CPU gate; spec ✅ + code review findings fixed; 4 passed / 1 env-gated skip live"}, + {"id": 4, "subject": "Task 4: Historian recorder tests — bounded watches", "status": "completed", "note": "45d67092 + fix 68461fbf (cap 2s->1s with measured ~150ms trip anchor; single counter read per poll); spec ✅ (concurrency-test deviation verified against production and accepted) + code APPROVED; falsification tripped on RemoveCallCount in 150ms; noticed-not-fixed: :1271 ExpectNoMsg is TestKit idiom, left alone"}, + {"id": 5, "subject": "Task 5: Orphaned test-database reaper (AdminUI + Configuration)", "status": "completed", "note": "8946644b + fix 580b77ce; spec ✅; code review found a real Critical (unvalidated suffix into interpolated DROP DDL as sa) — fixed defense-in-depth (Guid.TryParseExact shape guard + parameterized QUOTENAME/sp_executesql; reviewer's EXEC() snippet was invalid T-SQL, verified live Msg 102) + short reaper ConnectTimeout + prefix-constant minting + catch widened + collection-join closing a masked parallel-collection race; re-review APPROVED; live: 3/3 reaper, 1540/1540 AdminUI x3, 190/190 Config, shared server restored; known residual: cross-PROCESS plant-vs-reap race inherent to shared server, accepted"}, + {"id": 6, "subject": "Task 6: MTConnect AsStream ownership comment", "status": "completed", "note": "1edfc263; comment-only, build clean; trivial => no review"}, + {"id": 7, "subject": "Task 7: docker-dev readiness-gated deploy.sh + Traefik access log", "status": "completed", "note": "a61b3c98 + fix 9f09a62a (guarded POST curl under set -e, --max-time 10/60); re-review APPROVED; minor deferred as header NOTE: no-body Content-Type binding unverified against a live rig"}, + {"id": 8, "subject": "Task 8: Close-out — sweep + Outcomes + register annotations", "status": "completed", "blockedBy": [1, 2, 3, 4, 5, 6, 7], "note": "Recorded in d4e5c379 (the docs close-out: Outcomes + sweep record on the r2 plan, append-only 'Closed by (r2)' annotations on the round-1 register, this ledger). Preceded by d54b4fab, the two comment-only nits the T1 re-review deferred here. Build 0 errors / 904 warnings (round-1 families, +8 from this round's new test call sites). Sweep 43/43 projects green: 10370 passed / 0 failed / 19 skipped (10389 total) — +12 over round 1's 10358, reconciling exactly to OpcUaServer.Tests +5 (SessionAclDecisionCacheTests 12->17), Driver.S7.Tests +4 (S7SpanReadParityTests 9->13; the plan's '+5' counted contracts, which landed as 4 methods), AdminUI.Tests +3 (SqlTestDatabaseReaperTests). All 19 skips pre-existing and env-gated, project for project; this round added none. DB-backed suites RAN against 10.100.0.35,14330 — AdminUI 1540/0 skipped, Configuration 190/0 skipped. No failures, no flakes, no isolation re-run needed. S7 integration live vs 10.100.0.35:1102: 4 passed / 1 env-gated skip (S7_TIMER_NUMBER_ADDRESSING device-number leg). Post-edit re-verification: solution rebuild 0 errors, OpcUaServer.Tests 481/0/1 unchanged"} + ], + "closeOut": "Round 2 (perf/followups-r2) complete: 7 implementation tasks + close-out, all 8 green. Every item closed here was opened by the round-1 register, which is annotated in place with closing SHAs. Landed: T1 ACL generation stamp on Shard + eviction capacity hint + a reviewer-found backward-rollback thrash closed in-round (1979cf41, 98d6a190); T2 S7 cancellation-reopen / one-bad-decode / shape-mismatch pins (4f860733, 120e885b); T3 Timer/Counter exclusion LIVE-PINNED on a TM/CT-seeded s7_1500 fixture (fd202d81, f797df51); T4 three historian hope-waits -> bounded watches (45d67092, 68461fbf); T5 orphaned-test-DB reaper, including a real Critical (unvalidated name into interpolated sa DDL) found by review and fixed pre-merge (8946644b, 580b77ce); T6 MTConnect AsStream ownership comment (1edfc263); T7 readiness-gated docker-dev deploy.sh + Traefik access log (a61b3c98, 9f09a62a); T8 close-out (d54b4fab + the docs commit). Review chain: 7 implementers, 11 review verdicts, 4 fix rounds, 1 Critical fixed pre-merge, zero findings papered over. Two falsification-hygiene lessons recorded: a --no-build falsification runs a stale binary and reports a vacuous green, and a falsification arm proves nothing until its red has been seen. Five items stay open in the r2 register, none blocking: the benign ACL single-shot-CAS deferred-publication residual; S7 per-item decode health last-writer-wins; TM/CT decode at a non-zero device number (needs a real CPU, env var ready); the docker-dev 404 mechanism (unconfirmed until the access log catches one) and its unverified no-body POST Content-Type binding; the accepted cross-process plant-vs-reap race on the shared SQL server.", + "lastUpdated": "2026-08-17T18:30:00Z" +} diff --git a/docs/plans/2026-08-17-perf-followups.md b/docs/plans/2026-08-17-perf-followups.md index 317119b3..95bc7a20 100644 --- a/docs/plans/2026-08-17-perf-followups.md +++ b/docs/plans/2026-08-17-perf-followups.md @@ -745,36 +745,67 @@ Open items this branch surfaced but deliberately did not close. **None blocks th microseconds and **key revocation/expiry are unaffected** (both are re-checked *above* the cache on every call), so this is a stale *grant walk*, not a stale key. Fix shape if it ever matters: stamp the generation on `Shard` itself, or make the racer wait on the winner. + - **Closed by `1979cf41` + `98d6a190` (r2).** Took the first fix shape — the generation is + stamped on `Shard`, `TryGet` is generation-gated, and `Set` displaces a mismatched shard; + `98d6a190` added the monotonic `<=` guard that stops a stale-generation straggler rolling + the stamp backward. One benign residual remains (see r2's register). - **A fresh `Shard` could take an initial-capacity hint** for a session known to be crawling, to avoid the dictionary's growth rehashes on exactly the workload the per-key ceiling exists for. + - **Closed by `1979cf41` (r2).** The eviction swap seeds the replacement shard with a + capacity hint, gated on the generation matching. **S7** - **No cancellation-branch test on any read path.** Pre-existing, but this branch added a third path (multi-var), so the gap now spans three. + - **Closed by `4f860733` (r2).** The span and multi-var cancellation reopen contracts are + pinned (hang knobs + entered-TCS + `CreatedPlcCount`), and `120e885b` added the assertion + that the stale handle is *disposed*, not merely replaced. - **No integration case for one bad decode inside an otherwise-good chunk** — the per-chunk fallback is unit-tested only. + - **Closed by `4f860733` (r2).** One-bad-decode-in-chunk pinned (only that tag goes Bad, no + fallback), alongside the short-answer shape mismatch (whole-chunk fallback). - **The Timer/Counter exclusion needs a live pin**, which needs a fixture with a TM/CT area. + - **Closed by `fd202d81` (r2).** TM/CT areas added to the `s7_1500` fixture and the exclusion + live-pinned against `10.100.0.35:1102` **at device 0**, the fixed point of snap7's + BIT-address resolution and a real CPU's device-number addressing; the device-number leg + (T5/C7) is env-gated on `S7_TIMER_NUMBER_ADDRESSING=1` as a ready-made real-CPU gate. **Historian** - **Task 3's `Task.Delay(500)` is still a hope-wait** and could become a bounded poll, the same treatment Task 9 gave the durability test. + - **Closed by `45d67092` + `68461fbf` (r2).** All three fixed sleeps became bounded watches on + real observables (`RemoveCallCount`, queue depth, `PeekBatchCallCount`), with the negative + watch's cap anchored to a measured ~150 ms falsification trip. **AdminUI tests** - **A mid-run SQL connectivity blip surfaces as `SqlException` failures, not skips** — the reachability probe is one-shot, taken before the run. + - **Documented wontfix (r2).** The one-shot probe is deliberate — a per-test probe would turn + a genuine mid-run outage into silent skips; verified against the comment at the probe site + and left as-is. - **Orphaned test databases have no reaper.** A killed test process leaves its uniquely-named database behind on `10.100.0.35,14330`. + - **Closed by `8946644b` + `580b77ce` (r2).** A one-shot startup reaper drops >24 h-orphaned + databases per fixture prefix; `580b77ce` fixed a review-found Critical (unvalidated name + into interpolated `sa` DDL) with a GUID-suffix shape guard plus parameterized + `QUOTENAME`/`sp_executesql`. **MTConnect** - **`AsStream` wants a buffer-ownership comment** so a future caller does not have to infer the lifetime from the call site. + - **Closed by `1edfc263` (r2).** The doc comment now states the array-backed aliasing, the + synchronous call-duration lifetime, and that the result holds no reference into the buffer. **docker-dev** - **The first `POST /api/deployments` after boot can 404.** Worth a readiness gate on the deployments endpoint, so scripted deploys do not have to encode a retry. + - **Closed by `a61b3c98` + `9f09a62a` (r2)** — as a *gate plus instrumentation*, not a + diagnosis: `deploy.sh` polls `/health/ready` (2 s/120 s) then POSTs once un-retried, and + Traefik now runs `--accesslog` so the next occurrence names the matching router. **The 404's + mechanism remains unconfirmed** until that log catches one. diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.MTConnect/MTConnectStreamsParser.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.MTConnect/MTConnectStreamsParser.cs index a5409aba..b0d6bdff 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.MTConnect/MTConnectStreamsParser.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.MTConnect/MTConnectStreamsParser.cs @@ -241,7 +241,16 @@ internal static class MTConnectStreamsParser /// /// Views the (already trimmed) bytes as a stream without copying them where the memory is /// array-backed — which it always is on the /sample path, whose framer hands over the - /// part's own byte[]. + /// part's own byte[]. That branch aliases the caller's array; only the + /// non-array-backed fallback copies (via ToArray). + /// + /// Ownership, so a caller can reason about the aliased buffer: nothing on this path pools + /// or rents it (the framer allocates each byte[] fresh), and parsing is fully + /// synchronous, so the buffer need only stay valid and unmutated for the duration of the + /// Parse call. The returned holds no reference + /// into it — materialises its own strings — so the caller may + /// reuse or discard the buffer as soon as Parse returns. + /// /// private static MemoryStream AsStream(ReadOnlyMemory xml) => MemoryMarshal.TryGetArray(xml, out ArraySegment segment) && segment.Array is not null diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs index fa190a03..21b40271 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/Security/SessionAclDecisionCache.cs @@ -32,6 +32,16 @@ namespace ZB.MOM.WW.OtOpcUa.OpcUaServer.Security; /// deploy costs one repopulation and cannot be wrong. Deployments are rare relative to reads. /// /// +/// ⚠️ The invariant that makes that safe is per-shard, not global: a shard can only ever answer for +/// the generation it was built under. The wholesale drop is necessarily two steps — publish the new +/// generation, then purge the shards — because the publish is the compare-exchange that elects +/// the single thread allowed to purge. Between them the stamp already matches while the previous +/// generation's shards are still in the table, so comparing the stamp alone would let a caller arriving +/// in that window read a verdict the new trie never made. Each shard therefore carries its own +/// generation: a mismatched shard is a miss on the read path and is displaced on the store path, which +/// makes the window inert rather than merely narrow. +/// +/// /// Storage is sharded per calling KEY, under a two-level bound. The shard key is /// ApiKeyId ?? Principal, so sessions sharing one API key share one shard and one /// cap — the isolation is across distinct keys, not across @@ -178,7 +188,14 @@ public sealed class SessionAclDecisionCache // TryGetValue rather than GetOrAdd: a session that only ever hits must not mint a shard, and a // session whose shard was just cleared must not resurrect one until it actually stores something. + // + // The shard's OWN generation decides, not the stamp InvalidateIfStale just compared: inside the + // rollover window the stamp already matches and the purge has not run, so the stamp cannot + // distinguish this generation's shard from the last one's. A mismatch is treated as a plain miss and + // is NOT displaced from here — this path stays allocation-free and non-mutating, and the shard is + // reclaimed a moment later by the purging thread or by the next Set on that key. return _shards.TryGetValue(sessionKey, out var shard) + && shard.Generation == generation && shard.Entries.TryGetValue(new ShardKey(operation, realm, nodeIdentifier), out decision); } @@ -205,7 +222,7 @@ public sealed class SessionAclDecisionCache // trie never made. Dropping it costs one recomputation on the next call. if (Generation != generation) return; - var shard = _shards.GetOrAdd(sessionKey, static _ => new Shard()); + var shard = _shards.GetOrAdd(sessionKey, static (_, gen) => new Shard(gen), generation); if (Volatile.Read(ref _globalCount) >= MaxEntries) { @@ -218,22 +235,48 @@ public sealed class SessionAclDecisionCache // re-enumerate an emptying dictionary. The redundancy costs an enumeration, not correctness, // and a CAS-elected clear would add hot-path state for a branch that is a rare fallback. ClearAll(); - shard = _shards.GetOrAdd(sessionKey, static _ => new Shard()); + shard = _shards.GetOrAdd(sessionKey, static (_, gen) => new Shard(gen), generation); } else if (Volatile.Read(ref shard.ApproxCount) >= MaxEntriesPerSession) { - // The inner bound. This REPLACES the shard object rather than emptying the dictionary in - // place — the same move ClearAll makes, and for the same reason. Emptying in place left the - // clear and the counter reset as two steps over storage a racing Set was still inserting - // into: the racer could land in the just-cleared dictionary and increment both counters - // between them, and the Exchange then subtracted an amount that included the racer's fresh - // entry, under-counting _globalCount for good. Swapping the object makes the displaced - // shard unreachable in one atomic step, after which Seal settles its count exactly. - if (_shards.TryUpdate(sessionKey, new Shard(), shard)) - Interlocked.Add(ref _globalCount, -Seal(shard)); + // The inner bound. The replacement is pre-sized to what the shard it displaces was holding: this + // key has just demonstrated it fills its whole budget, and it is about to do so again, so the + // refill would otherwise walk the dictionary's whole growth cascade — a rehash under every one of + // the table's locks at each doubling — to arrive back at a size already known. Clamped to the + // ceiling because the count read here is the pre-seal one — a thread that lost the swap reads + // the sentinel and clamps to no hint at all, which is the right answer for it. Only this site + // hints; a shard minted by GetOrAdd has no such evidence and stays at the default capacity. + // + // The trade: the replacement is built before the swap is attempted, so a thread that loses + // discards a pre-sized dictionary rather than an empty one. That is a bigger throwaway than + // before, and it is accepted — the loss window is a single compare-and-swap wide, and it is + // paid only by threads that overflowed the same shard simultaneously, against a refill cost + // paid by every eviction. + // + // A shard from a PREVIOUS generation contributes no hint: the fill level it reached belongs to a + // set of grants that no longer exists, and this very Displace replaces it with a fresh shard + // stamped to the current generation regardless. Sizing this generation's storage from the last + // one's crawl would be a guess dressed as evidence. + shard = Displace( + sessionKey, shard, generation, + capacityHint: shard.Generation == generation + ? Math.Clamp(Volatile.Read(ref shard.ApproxCount), 0, MaxEntriesPerSession) + : 0); + } - // Whoever won the swap, the live shard is now a different object than the one held above. - shard = _shards.GetOrAdd(sessionKey, static _ => new Shard()); + // The shard must belong to THIS generation before anything is filed in it. Reached in two ways: a + // deploy landed since the shard was minted (the common case — one displacement per key per deploy, + // and the read path has been missing on it since the stamp moved), or the rollover window closed + // between the check at the top of this method and here. + if (shard.Generation != generation) + { + shard = Displace(sessionKey, shard, generation, capacityHint: 0); + + // Still mismatched means a racer re-minted the shard under a generation that has since moved + // again. Drop the decision rather than loop: filing this generation's verdict in another + // generation's shard is the same error in the other direction, and the line above already + // dropped a verdict for the identical reason. + if (shard.Generation != generation) return; } // TryAdd, not an indexer assignment: only a genuine insert may move the counters, or a racing pair @@ -242,6 +285,36 @@ public sealed class SessionAclDecisionCache TryBookInsert(shard); } + /// + /// Replaces a session's live shard with a fresh one for and returns + /// whatever shard is live afterwards. + /// + /// + /// This REPLACES the shard object rather than emptying the dictionary in place — the move + /// makes, and for the same reason. Emptying in place left the clear and the + /// counter reset as two steps over storage a racing was still inserting into: the + /// racer could land in the just-cleared dictionary and increment both counters between them, and the + /// then subtracted an amount that included the + /// racer's fresh entry, under-counting for good. Swapping the object makes + /// the displaced shard unreachable in one atomic step, after which settles its + /// count exactly — and because only the thread that wins the compare-and-swap seals, no shard is + /// sealed twice however many threads arrive here at once. The returned shard is re-read from the + /// table rather than assumed to be the one just built: whoever won the swap, the live shard is now a + /// different object than the caller held. + /// + /// The key whose shard is being displaced. + /// The shard the caller found live. + /// The generation the replacement is built for. + /// Initial entry capacity for the replacement; zero leaves it at the default. + /// The live shard after the swap. + private Shard Displace(string sessionKey, Shard shard, long generation, int capacityHint) + { + if (_shards.TryUpdate(sessionKey, new Shard(generation, capacityHint), shard)) + Interlocked.Add(ref _globalCount, -Seal(shard)); + + return _shards.GetOrAdd(sessionKey, static (_, gen) => new Shard(gen), generation); + } + /// /// Books a just-completed insert against the shard's own counter and the global one, unless the /// shard was displaced first — in which case the entry lives in storage nothing can reach any more @@ -339,10 +412,48 @@ public sealed class SessionAclDecisionCache /// Drops every memoized decision. Called when the authorization generation advances. public void Clear() => ClearAll(); + /// + /// Moves the generation stamp without clearing — reproducing, deterministically, the exact + /// view a racer gets inside 's rollover window, where the new + /// generation is already published but the winner's has not run yet. + /// + /// + /// Tests only. That window is a few instructions wide, so a concurrency test can only make it + /// probable; this makes it certain. The invariant it exercises — a shard can only serve the + /// generation it was built under — is what makes the window harmless, so the pin has to be able + /// to stand inside it. + /// + /// The generation to publish. + internal void AdvanceGenerationForTest(long generation) => + Interlocked.Exchange(ref _generation, generation); + + /// + /// Advances the cache-wide stamp when this call presents a newer generation, and purges on the way. + /// + /// + /// + /// ⚠️ The comparison is <=, not !=, and that is a straggler guard. The + /// generation only ever increases (DataPlaneAuthorityState counts it up rather than + /// deriving it from the revision hash, precisely so it cannot go backwards), but a request + /// can still present an older one: it captured its authority snapshot before a deploy and then + /// lost the scheduling race to a request that captured after. An inequality test treats that + /// straggler as a deploy, rolls the stamp backward, and purges the new generation's + /// freshly-populated shards — so the post-deploy window, when the cache is coldest and doing the + /// most work, is exactly when it thrashes. Verdicts are safe either way now that each shard + /// carries its own generation; what is at stake here is only whether the cache is any use. + /// + /// + /// The straggler's own lookup is unaffected by returning early: its shard-generation check misses + /// against the newer shards regardless, so it recomputes, which is the correct outcome for a + /// request holding a superseded snapshot. _generation starts at -1, below any real + /// generation, so the first one still passes. + /// + /// + /// The generation the calling request is being decided under. private void InvalidateIfStale(long generation) { var seen = Interlocked.Read(ref _generation); - if (seen == generation) return; + if (generation <= seen) return; // Only the thread that actually moves the stamp clears, so a burst of concurrent requests arriving // just after a deploy repopulates once rather than each clearing the others' fresh entries. @@ -375,9 +486,24 @@ public sealed class SessionAclDecisionCache /// either still is the live shard or has been sealed — it can never turn /// into a different generation of the same session's entries under its holder. /// - private sealed class Shard + /// The authorization generation this shard's entries were decided under. + /// + /// Initial entry capacity. Zero leaves at the default — the right choice + /// everywhere except the per-shard eviction swap, which alone has evidence of the size the + /// replacement is about to grow back to. + /// + private sealed class Shard(long generation, int capacity = 0) { - public readonly ConcurrentDictionary Entries = new(); + public readonly ConcurrentDictionary Entries = capacity > 0 + ? new ConcurrentDictionary(Environment.ProcessorCount, capacity) + : new ConcurrentDictionary(); + + /// + /// The generation this shard's entries were decided under, fixed for its lifetime. It is what the + /// read path compares — the cache-wide stamp cannot be trusted alone, because it is published one + /// step before the shards it invalidates are purged. + /// + public readonly long Generation = generation; /// /// Read and written with , never derived from diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/SchemaComplianceFixture.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/SchemaComplianceFixture.cs index 251857f4..1ef229e8 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/SchemaComplianceFixture.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Configuration.Tests/SchemaComplianceFixture.cs @@ -1,3 +1,4 @@ +using System.Globalization; using Microsoft.Data.SqlClient; using Microsoft.EntityFrameworkCore; using Xunit; @@ -13,9 +14,17 @@ namespace ZB.MOM.WW.OtOpcUa.Configuration.Tests; /// public sealed class SchemaComplianceFixture : IDisposable { + /// The name prefix every Configuration test database carries; also the reaper's LIKE anchor. + internal const string TestDatabasePrefix = "OtOpcUaConfig_Test_"; + private const string DefaultServer = "10.100.0.35,14330"; private const string DefaultSaPassword = "OtOpcUaDev_2026!"; + /// How long a test database must have existed before the reaper considers it certainly orphaned. + private static readonly TimeSpan OrphanAge = TimeSpan.FromHours(24); + + private static readonly Lazy Reaper = new(RunReaper, LazyThreadSafetyMode.ExecutionAndPublication); + /// Gets the name of the test database. public string DatabaseName { get; } /// Gets the connection string for the test database. @@ -27,7 +36,13 @@ public sealed class SchemaComplianceFixture : IDisposable var server = Environment.GetEnvironmentVariable("OTOPCUA_CONFIG_TEST_SERVER") ?? DefaultServer; var saPassword = Environment.GetEnvironmentVariable("OTOPCUA_CONFIG_TEST_SA_PASSWORD") ?? DefaultSaPassword; - DatabaseName = $"OtOpcUaConfig_Test_{DateTime.UtcNow:yyyyMMddHHmmss}_{Guid.NewGuid():N}"; + // A killed test process never reaches Dispose, so its database outlives the run. Reap the ones old + // enough to be certainly nobody's, once per process. This fixture has no reachability probe, so an + // unreachable server must leave behaviour exactly as it was: the reaper silently does nothing and + // Migrate() below throws as it always has. + _ = Reaper.Value; + + DatabaseName = $"{TestDatabasePrefix}{DateTime.UtcNow:yyyyMMddHHmmss}_{Guid.NewGuid():N}"; ConnectionString = $"Server={server};Database={DatabaseName};User Id=sa;Password={saPassword};TrustServerCertificate=True;Encrypt=False;"; @@ -48,23 +63,213 @@ public sealed class SchemaComplianceFixture : IDisposable return conn; } - /// Disposes the fixture and drops the test database. + private static int RunReaper() + { + var server = Environment.GetEnvironmentVariable("OTOPCUA_CONFIG_TEST_SERVER") ?? DefaultServer; + var saPassword = Environment.GetEnvironmentVariable("OTOPCUA_CONFIG_TEST_SA_PASSWORD") ?? DefaultSaPassword; + var master = + $"Server={server};Database=master;User Id=sa;Password={saPassword};TrustServerCertificate=True;Encrypt=False;"; + + return SqlTestDatabaseReaper.ReapOrphans(master, TestDatabasePrefix, DateTime.UtcNow - OrphanAge).Count; + } + + /// + /// Disposes the fixture and drops the test database — via the same parameterized + /// the reaper uses, so this file carries + /// exactly one drop-DDL shape. Best-effort like the AdminUI fixture's teardown: the name is + /// self-minted so a swallowed failure only leaks a database the startup reaper reclaims + /// within 24 h. + /// public void Dispose() { var masterConnection = new SqlConnectionStringBuilder(ConnectionString) { InitialCatalog = "master" }.ConnectionString; - using var conn = new SqlConnection(masterConnection); + SqlTestDatabaseReaper.TryDropDatabase(masterConnection, DatabaseName); + } +} + +/// +/// Drops test databases that a killed test process left behind on the shared SQL Server. +/// +/// +/// +/// names its database +/// {prefix}{yyyyMMddHHmmss-UTC}_{guid:N} and drops it in Dispose — which a +/// Ctrl-C, a crashed runner or a killed container never reaches, so the database survives +/// forever on an instance nobody gardens. +/// +/// +/// This is DROP DATABASE against a server other people share, so the rules are deliberately +/// narrow and every one of them is load-bearing: +/// +/// +/// +/// the LIKE is an exact prefix with _ escaped (an unescaped _ is a +/// single-character wildcard in T-SQL) — never widen it; +/// +/// +/// a matching name is dropped only when its whole shape is one this code could have +/// minted — prefix, a parseable 14-digit UTC timestamp, _, then 32 hex digits. That is +/// belt and braces against second-order injection: the name is also passed as a +/// parameter through QUOTENAME rather than interpolated into DDL, but the shape +/// check independently guarantees a candidate cannot contain ] or '; +/// +/// +/// only names strictly older than the cutoff are dropped. At 24 hours that is far beyond +/// any run, so the reaper can never race a live sibling run on the same server; and +/// +/// +/// nothing here ever throws. Unlike this project's Dispose, which deliberately lets a +/// teardown failure surface, opportunistic housekeeping must never fail a green run. +/// +/// +/// +/// Deliberately duplicated from the AdminUI.Tests copy rather than shared: the two suites have no +/// common test-support assembly, and a new one purely for ~100 lines of best-effort housekeeping +/// costs more than the duplication. +/// +/// +internal static class SqlTestDatabaseReaper +{ + private const string TimestampFormat = "yyyyMMddHHmmss"; + private const int ConnectTimeoutSeconds = 3; + + /// + /// Drops every database matching whose embedded creation timestamp is + /// strictly older than . + /// + /// A connection string pointed at master. + /// The exact test-database name prefix, e.g. OtOpcUaConfig_Test_. + /// Databases created strictly before this UTC instant are dropped. + /// The names actually dropped; empty when there was nothing to reap or anything went wrong. + internal static IReadOnlyList ReapOrphans(string masterConnectionString, string prefix, DateTime cutoffUtc) + { + var reaped = new List(); + + try + { + foreach (var name in ListCandidates(masterConnectionString, prefix)) + { + if (!TryParseCreatedUtc(name, prefix, out var createdUtc)) continue; + if (createdUtc >= cutoffUtc) continue; + + try + { + if (TryDropDatabase(masterConnectionString, name)) reaped.Add(name); + } + catch (Exception) + { + // One stubborn database must not stop the sweep, nor fail the run that triggered it. + } + } + } + catch (Exception) + { + // Enumeration failed (server down, no permission). Reaping is opportunistic housekeeping. + } + + if (reaped.Count > 0) + { + Console.WriteLine( + $"[sql-test-reaper] dropped {reaped.Count} orphaned test database(s) older than " + + $"{cutoffUtc:yyyy-MM-dd HH:mm:ss}Z: {string.Join(", ", reaped)}"); + } + + return reaped; + } + + /// + /// Drops the named database, swallowing every failure — this is called unwrapped from + /// finally blocks, so it must be genuinely best-effort. + /// + /// + /// The database name is an identifier, which cannot be parameterised directly, so it rides + /// in as a parameter and QUOTENAME escapes it server-side. Interpolating it into the DDL + /// instead would make any attacker-chosen database name on this shared server a second-order + /// injection executed as sa. + /// + /// A connection string pointed at master. + /// The database to drop. + /// when the statement ran without error. + internal static bool TryDropDatabase(string masterConnectionString, string databaseName) + { + try + { + using var conn = new SqlConnection(masterConnectionString); + conn.Open(); + + using var cmd = conn.CreateCommand(); + + // The QUOTENAME result must be assembled into a variable first: EXEC() accepts only a + // concatenation of literals and variables, so the tempting one-liner + // EXEC('ALTER DATABASE ' + QUOTENAME(@name) + …) is a syntax error, not a subtle bug. + cmd.CommandText = @" +DECLARE @sql nvarchar(max); +IF DB_ID(@name) IS NOT NULL +BEGIN + SET @sql = N'ALTER DATABASE ' + QUOTENAME(@name) + N' SET SINGLE_USER WITH ROLLBACK IMMEDIATE; ' + + N'DROP DATABASE ' + QUOTENAME(@name) + N';'; + EXEC sp_executesql @sql; +END"; + cmd.Parameters.Add(new SqlParameter("@name", databaseName)); + + cmd.ExecuteNonQuery(); + return true; + } + catch (Exception) + { + // Teardown is best-effort: a dropped connection here must not fail an otherwise-green run. + // The database name carries a timestamp, so a leaked one is reaped by the next run instead. + return false; + } + } + + private static List ListCandidates(string masterConnectionString, string prefix) + { + var names = new List(); + + // A short connect timeout, because this runs BEFORE whatever the fixture does next: on an + // unreachable server the default ~15 s would simply be added to the latency the caller already pays + // — here, on top of the connect timeout Migrate() is about to spend proving the same thing. + var probe = new SqlConnectionStringBuilder(masterConnectionString) + { + ConnectTimeout = ConnectTimeoutSeconds, + }.ConnectionString; + + using var conn = new SqlConnection(probe); conn.Open(); using var cmd = conn.CreateCommand(); - cmd.CommandText = $@" -IF DB_ID(N'{DatabaseName}') IS NOT NULL -BEGIN - ALTER DATABASE [{DatabaseName}] SET SINGLE_USER WITH ROLLBACK IMMEDIATE; - DROP DATABASE [{DatabaseName}]; -END"; - cmd.ExecuteNonQuery(); + cmd.CommandText = @"SELECT name FROM sys.databases WHERE name LIKE @pattern ESCAPE '\'"; + cmd.Parameters.Add(new SqlParameter("@pattern", prefix.Replace("_", @"\_", StringComparison.Ordinal) + "%")); + + using var reader = cmd.ExecuteReader(); + while (reader.Read()) names.Add(reader.GetString(0)); + + return names; + } + + private static bool TryParseCreatedUtc(string databaseName, string prefix, out DateTime createdUtc) + { + createdUtc = default; + + if (!databaseName.StartsWith(prefix, StringComparison.Ordinal)) return false; + + var rest = databaseName.AsSpan(prefix.Length); + + // Expect exactly "<14-digit timestamp>_<32 hex digits>" — anything else is not a name this code + // minted. Validating the GUID tail is what bounds the character set of every candidate name: a + // "N"-format GUID is hex only, so no candidate can carry a ']' or a quote into the drop statement. + if (rest.Length < TimestampFormat.Length + 1 || rest[TimestampFormat.Length] != '_') return false; + if (!Guid.TryParseExact(rest[(TimestampFormat.Length + 1)..], "N", out _)) return false; + + return DateTime.TryParseExact( + rest[..TimestampFormat.Length], + TimestampFormat, + CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, + out createdUtc); } } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/README.md b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/README.md index 15cb25e0..358f90c0 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/README.md +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/README.md @@ -76,7 +76,8 @@ without Docker running. ## What's encoded in `profiles/s7_1500.json` -DB1 (1024 bytes) + MB (256 bytes) with typed seeds at known offsets: +DB1 (1024 bytes) + MB (256 bytes) + TM0/CT0 (64 bytes each) with typed seeds at +known offsets: | Address | Type | Seed | Purpose | |---|---|---|---| @@ -116,6 +117,63 @@ inside the holes cluster A's span reads through. No tag maps to them; they are there so a mis-computed slice offset returns garbage instead of a zero that could match by luck. Every seed above is distinct and non-zero for the same reason. +### Timer / Counter (TM / CT) areas + +`TM0` and `CT0` are 64 bytes each — **32 device cells**, since a timer is a 2-byte +S5TIME word and a counter a 2-byte count word, with device number `N` at byte +offset `2 × N`. They exist so `S7_1500SpanReadTests` can pin, against real wire, +that `S7ReadSpanPlanner` excludes Timer/Counter from every span and the multi-var +pass excludes them again on `IsBufferType` — each takes its own area-typed +`ReadBytes` round-trip instead. + +| Address | Byte offset | Seed | Decodes to | +|---|---|---|---| +| `T0` | 0 | `0x2456` | `456.0` s (S5TIME base 2 = ×1 s, BCD 456) | +| `T5` | 10 | `0x1123` | `12.3` s (base 1 = ×0.1 s, BCD 123) | +| `T9` | 18 | `0x0250` | `2.5` s (base 0 = ×0.01 s, BCD 250) | +| `C0` | 0 | `4711` | `4711` (raw big-endian count word) | +| `C7` | 14 | `31337` | `31337` | +| `C11` | 22 | `1234` | `1234` | + +A timer decodes to seconds as a `double` (S7.Net `Timer.FromByteArray`) and a +counter to an `int` count (`Counter.FromByteArray`, raw word — **not** BCD). + +#### ⚠️ Only device **0** is addressable on this fixture + +Live-probed 2026-08-17: snap7's server resolves the TM/CT request address as a +**bit address** — it serves byte `addr >> 3` of the area — whereas S7.Net, and a +real S7 CPU, put the device **number** in that field. Measured with S7netplus +0.20.0 against `10.100.0.35:1102` running **the profile above**: + +``` +ReadBytes(Timer,db=0,start=0,count=8) => [24 56 00 00 00 00 00 00] # TM bytes 0..7: T0 = 0x2456 +ReadBytes(Timer,db=0,start=0,count=2) => [24 56] # T0 -> byte 0. 0>>3 == 2*0, so BOTH conventions agree here +ReadBytes(Timer,db=0,start=5,count=2) => [24 56] # T5 -> 5>>3 = byte 0. WRONG cell: T5 lives at bytes 10..11 (0x1123) +ReadBytes(Timer,db=0,start=80,count=2) => [11 23] # byte 10 needs start 80 (= 10*8): the T5 cell, reached the bit-address way +ReadBytes(Counter,db=0,start=0,count=2) => [12 67] # C0 -> byte 0 = 4711. Both conventions agree +ReadBytes(Counter,db=0,start=7,count=2) => [12 67] # C7 -> 7>>3 = byte 0. WRONG cell: C7 lives at bytes 14..15 (0x7A69 = 31337) +ReadBytes(Counter,db=0,start=112,count=2) => [7A 69] # byte 14 needs start 112 (= 14*8): the C7 cell +``` + +Note lines 2 and 3: asking for `T0` and asking for `T5` return the **same bytes** +— every device 0..7 collapses onto TM byte 0. Same for `C0` / `C7`. + +No error is raised — the reads succeed, they just land on the wrong cell. Device +**0** is the single fixed point of the two conventions (`0 >> 3 == 2 × 0 == 0`), +so `T0` / `C0` are the only cells whose *value* the fixture can pin; that is what +`Timer_and_counter_tags_never_enter_a_multi_var_request` asserts, and the +wire-shape half of that test is unaffected by the quirk. The `2 × N` cells above +are seeded for a real CPU: run +`Timer_and_counter_decode_the_seeded_values_at_their_device_numbers` against one +with + +```bash +S7_SIM_ENDPOINT=:102 S7_TIMER_NUMBER_ADDRESSING=1 \ + dotnet test tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests +``` + +It skips (naming this limitation) whenever that variable is unset. + ## Known limitations From the `snap7.server.Server` docstring upstream: @@ -130,6 +188,9 @@ Not exercised here — needs a lab rig: - S7-1500 Optimized-DB symbolic access - PG / OP / S7-Basic session-type differentiation - PUT/GET-disabled-by-default enforcement +- Device-number addressing of the TM / CT areas (see the ⚠️ above — the reads are + served, but resolved as bit addresses, so only device 0 lands where a CPU + would put it) See [`docs/drivers/S7-Test-Fixture.md`](../../../docs/drivers/S7-Test-Fixture.md) for the full coverage map. diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/profiles/s7_1500.json b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/profiles/s7_1500.json index bca0c603..37820a15 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/profiles/s7_1500.json +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/Docker/profiles/s7_1500.json @@ -1,5 +1,5 @@ { - "_description": "S7-1500 profile — single DB1 (1024 bytes) + MB (256 bytes) with well-known seeds at named offsets for the smoke + byte-order + string tests. Big-endian Siemens wire order throughout.", + "_description": "S7-1500 profile — DB1 (1024 bytes) + MB (256 bytes) + TM/CT (64 bytes each) with well-known seeds at named offsets for the smoke + byte-order + string + Timer/Counter tests. Big-endian Siemens wire order throughout.", "areas": [ { "area": "DB", @@ -59,6 +59,34 @@ { "_desc": "MW10 — span-planner gate: a narrow scalar in a DIFFERENT area from the DB1 leftovers. A block read can never merge across (area, DB); the multi-var pass can, so this pins that the leftover batching crosses the boundary.", "offset": 10, "type": "u16", "value": 4097 } ] + }, + { + "_desc": "TM (timers) — 64 bytes = 32 timer cells. A timer is a 2-byte S5TIME word and timer number N lives at byte offset 2*N, so the offsets below ARE the timer numbers doubled. Values are S5TIME-encoded (bits 12..13 = time base, the remaining three nibbles = a BCD 0..999 count) and each decodes to a distinct NON-ZERO duration, because a zero-valued timer reads the same as a timer that was never served at all (the #536 trap). ⚠️ Only T0 is readable through this fixture — see the CT note below and Docker/README.md §'Timer / Counter (TM / CT) areas'.", + "area": "TM", + "index": 0, + "size": 64, + "seeds": [ + { "_desc": "T0 @ byte 0 — 0x2456: base 2 (×1s), BCD 456 ⇒ 456.0 seconds. Device 0 is the one cell where snap7's address resolution and a real CPU's agree, so this is the seed S7_1500SpanReadTests asserts on.", + "offset": 0, "type": "u16", "value": 9302 }, + { "_desc": "T5 @ byte 10 — 0x1123: base 1 (×0.1s), BCD 123 ⇒ 12.3 seconds. Reachable only from a real CPU (S7_TIMER_NUMBER_ADDRESSING=1).", + "offset": 10, "type": "u16", "value": 4387 }, + { "_desc": "T9 @ byte 18 — 0x0250: base 0 (×0.01s), BCD 250 ⇒ 2.5 seconds. Real CPU only, as above.", + "offset": 18, "type": "u16", "value": 592 } + ] + }, + { + "_desc": "CT (counters) — 64 bytes = 32 counter cells, counter number N at byte offset 2*N. The driver surfaces a counter as the RAW big-endian word (S7Driver.DecodeScalarBlock via S7.Net's Counter.FromByteArray), so these seeds are plain u16 counts; distinct + non-zero for the same reason as the timers. ⚠️ snap7's server resolves the TM/CT request address as a BIT address (byte = addr>>3) instead of as a device NUMBER, while S7.Net (and a real CPU) put the device number there — so a read of C{n} lands on byte n>>3, and device 0 is the only n where the two conventions coincide. Live-probed 2026-08-17; see Docker/README.md.", + "area": "CT", + "index": 0, + "size": 64, + "seeds": [ + { "_desc": "C0 @ byte 0 — count 4711. The device-0 cell both conventions agree on; asserted by S7_1500SpanReadTests.", + "offset": 0, "type": "u16", "value": 4711 }, + { "_desc": "C7 @ byte 14 — count 31337. Reachable only from a real CPU (S7_TIMER_NUMBER_ADDRESSING=1).", + "offset": 14, "type": "u16", "value": 31337 }, + { "_desc": "C11 @ byte 22 — count 1234. Real CPU only, as above.", + "offset": 22, "type": "u16", "value": 1234 } + ] } ] } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/S7_1500/S7_1500SpanReadTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/S7_1500/S7_1500SpanReadTests.cs index d3084ca3..e81da7c7 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/S7_1500/S7_1500SpanReadTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests/S7_1500/S7_1500SpanReadTests.cs @@ -23,6 +23,13 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests.S7_1500; /// analytic model and real wire was found. /// /// +/// Re-run the same day against the same endpoint after the fixture gained its TM0 / CT0 +/// areas: PASSED — 4 passed, 0 failed, 1 skipped (the device number-addressing test, +/// see below). The Timer/Counter batch was served by 4 requests for 7 tags: one DB1 span, +/// one 3-item multi-var carrying only the scalars, and one 2-byte area read apiece for +/// T0 (decoded 456.0 s from S5TIME 0x2456) and C0 (decoded count 4711). +/// +/// /// What the layout buys. The ten tags are positioned so the planner's rules produce a /// known, non-trivial partition rather than one that would pass by accident: /// @@ -48,13 +55,30 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.S7.IntegrationTests.S7_1500; /// /// /// -/// Timer / Counter are NOT covered here. The fixture profile declares only DB1 and -/// MK; python-snap7's server can register TM/CT areas but S7.Net's timer/counter read is a -/// distinct wire shape that the fixture has never served, so pinning the planner's per-tag -/// exclusion live would mean standing up and validating a new fixture area. That exclusion -/// stays unit-covered. Nothing else in this suite depends on it — Timer/Counter tags are -/// rejected by the planner on AREA and by the multi-var pass on IsBufferType, two -/// independent guards. +/// Timer / Counter ARE covered here now. The fixture profile grew TM0 + CT0 (64 +/// bytes each = 32 device cells), so +/// pins the planner's +/// per-tag exclusion against real wire rather than a fake: a Timer and a Counter batched +/// alongside three multi-var-eligible scalars each take their own area-typed +/// ReadBytes round-trip, and the one multi-var request the scalars share carries +/// neither of them. Two independent guards produce that — the planner rejects them on AREA +/// (their offsets are device numbers, not byte addresses) and the multi-var pass on +/// IsBufferType. +/// +/// +/// ⚠️ Fixture limitation — only device 0 is addressable. Live-probed 2026-08-17: +/// snap7's server resolves the TM/CT request address as a BIT address (it serves byte +/// addr >> 3 of the area) where S7.Net — and a real S7 CPU — put the device +/// NUMBER in that field. Measured directly: ReadBytes(Timer, db 0, start 5, count 2) +/// returns TM bytes 0..1, and it takes start 80 (= 10 × 8) to reach the timer seeded +/// at TM byte 10. Device 0 is the single fixed point of the two conventions +/// (0 >> 3 == 2 × 0 == 0), so it is the only device this fixture can pin a +/// VALUE for, and that is what the mixed batch uses. The spec-correct 2 × N cells +/// are seeded too and +/// asserts +/// them — skipped unless S7_TIMER_NUMBER_ADDRESSING=1 declares the endpoint a real +/// CPU. The device-number offset arithmetic itself stays unit-covered +/// (S7ScalarBlockTests, S7SpanReadParityTests). /// /// /// Why a counting factory rather than logs. The driver emits no log on a successful @@ -178,16 +202,137 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) ungrouped.Counters.TotalReadRequests.ShouldBe(SpanLayout.TagNames.Count); } - /// Reads the whole layout once through a freshly-built driver and reports the wire shape. + /// + /// Live pin for the planner's Timer/Counter exclusion: batched alongside three + /// multi-var-eligible scalars, a Timer and a Counter each take their own area-typed block + /// read and neither ever appears as an item of the multi-var request the scalars share. + /// + /// + /// + /// The unit suite pins this against a fake (S7SpanReadParityTests + /// Timer_and_counter_leftovers_never_enter_a_multi_var_request); what only a live + /// run can add is that the excluded reads are ones a PLC actually answers — a driver + /// that put a Timer into a multi-var request would fault the WHOLE chunk on real wire, + /// taking the three innocent scalars down with it into the per-tag fallback. So the + /// scalars' values and the single 3-item request are asserted here too: they are the + /// evidence the exclusion is what kept the batch intact. + /// + /// + /// The Timer/Counter values are asserted at device 0 only — see the type remarks + /// for why this fixture cannot address any other device. + /// + /// + [Fact] + public async Task Timer_and_counter_tags_never_enter_a_multi_var_request() + { + if (sim.SkipReason is not null) Assert.Skip(sim.SkipReason); + + var (snapshots, counters) = await ReadBatchAsync( + TimerCounterLayout.BuildOptions(sim.Host, sim.Port, TimerCounterLayout.MixedBatch), + TimerCounterLayout.Names(TimerCounterLayout.MixedBatch), + "s7-timer-counter"); + + var byName = TimerCounterLayout.Names(TimerCounterLayout.MixedBatch) + .Select((n, i) => (n, snapshots[i])) + .ToDictionary(x => x.n, x => x.Item2); + + foreach (var (name, snapshot) in byName) + snapshot.StatusCode.ShouldBe(0u, $"'{name}' must be Good"); + + // (a) Correct decode off real wire. A Timer surfaces as the S5TIME word's duration in + // seconds (double) and a Counter as the raw count (int) — two different areas, two + // different values, two different CLR types, so a read that reached the wrong area or + // decoded through the wrong arm cannot pass. + byName["TC_Timer"].Value.ShouldBe(TimerCounterLayout.Device0TimerSeconds); + byName["TC_Counter"].Value.ShouldBe(TimerCounterLayout.Device0CounterCount); + + // The co-batched scalars still decode to their own seeds — the exclusion protected them. + byName["TC_SpanB_U16a"].Value.ShouldBe((ushort)40201); + byName["TC_SpanB_U16b"].Value.ShouldBe((ushort)40202); + byName["TC_Lone_U16"].Value.ShouldBe((ushort)60001); + byName["TC_Lone_I16"].Value.ShouldBe((short)-32001); + byName["TC_Lone_Mk"].Value.ShouldBe((ushort)4097); + + // (b) The wire shape. This is the pin: not one multi-var item carries a Timer or Counter. + counters.MultiVarReads.ShouldBe(1, + "the three isolated narrow scalars are past MultiVarReadMinItems, so they share one request"); + counters.MultiVarItems.ShouldBe(3, + "exactly the three scalars — a Timer or Counter joining them would make this 4 or 5"); + counters.MultiVarItemAreas.ShouldNotContain(S7NetDataType.Timer, + "a Timer must never be expressed as a multi-var item: its per-tag path decodes the S5TIME " + + "word itself and does not go through S7.Net's ParseBytes at all"); + counters.MultiVarItemAreas.ShouldNotContain(S7NetDataType.Counter, + "a Counter must never be expressed as a multi-var item — same reason, plus its per-tag " + + "decode surfaces int where S7.Net's own Counter.FromByteArray returns ushort"); + + // …and they arrive instead as their own area-typed block reads, two bytes apiece (one + // S5TIME / counter word), with the device number in the start field. Asserting the shape + // rather than just the count is what distinguishes "excluded to a block read" from + // "excluded to the per-address string path", which is a different wire request entirely. + counters.BlockReadShapes.ShouldContain((S7NetDataType.Timer, 0, TimerCounterLayout.Device0, 2)); + counters.BlockReadShapes.ShouldContain((S7NetDataType.Counter, 0, TimerCounterLayout.Device0, 2)); + counters.BlockReadShapes.ShouldContain((S7NetDataType.DataBlock, 1, 400, 4), + "the two adjacent DB1 words still merge into one span, so this batch is a real three-way split"); + counters.BlockReads.ShouldBe(3, "one span + one Timer + one Counter"); + counters.AddressReads.ShouldBe(0, + "the Timer/Counter exclusion routes to the block-read seam, never to the per-address path"); + } + + /// + /// Verifies a Timer and a Counter at NON-zero device numbers decode their seeded values — + /// the assertion the shared fixture cannot serve. + /// + /// + /// Skipped unless S7_TIMER_NUMBER_ADDRESSING=1 declares the endpoint a device + /// number-addressing CPU, because python-snap7's server is not one: it resolves the TM/CT + /// request address as a bit address, so T5 reads TM byte 0 rather than TM byte 10 + /// (measured 2026-08-17 — see the type remarks). Set the variable alongside + /// S7_SIM_ENDPOINT when pointing this suite at a real S7 CPU seeded to match + /// Docker/profiles/s7_1500.json's TM/CT areas. + /// + [Fact] + public async Task Timer_and_counter_decode_the_seeded_values_at_their_device_numbers() + { + if (sim.SkipReason is not null) Assert.Skip(sim.SkipReason); + if (Environment.GetEnvironmentVariable(TimerCounterLayout.RealCpuEnvVar) != "1") + { + Assert.Skip( + $"python-snap7's server resolves a TM/CT request address as a BIT address (byte = addr>>3), " + + $"not as a device number, so only device 0 is reachable on the fixture. " + + $"Set {TimerCounterLayout.RealCpuEnvVar}=1 (with S7_SIM_ENDPOINT pointing at a real S7 CPU " + + $"seeded like Docker/profiles/s7_1500.json) to run this."); + } + + var (snapshots, _) = await ReadBatchAsync( + TimerCounterLayout.BuildOptions(sim.Host, sim.Port, TimerCounterLayout.DeviceNumbered), + TimerCounterLayout.Names(TimerCounterLayout.DeviceNumbered), + "s7-timer-counter-devnum"); + + snapshots[0].StatusCode.ShouldBe(0u, "'TC_Timer5' must be Good"); + snapshots[1].StatusCode.ShouldBe(0u, "'TC_Counter7' must be Good"); + snapshots[0].Value.ShouldBe(12.3d, "T5 holds S5TIME 0x1123 — base 0.1 s, BCD 123"); + snapshots[1].Value.ShouldBe(31337, "C7 holds the raw count word 31337"); + } + + /// Reads the whole span layout once through a freshly-built driver and reports the wire shape. /// The span budget: the shipped default, or a negative value to disable grouping. /// Instance id, distinct per call so log lines stay attributable. /// The batch's snapshots plus the wire-call counts observed for the read itself. - private async Task<(IReadOnlyList Snapshots, CountingPlcFactory Counters)> + private Task<(IReadOnlyList Snapshots, CountingPlcFactory Counters)> ReadBatchAsync(int maxGapBytes, string driverInstanceId) + => ReadBatchAsync( + SpanLayout.BuildOptions(sim.Host, sim.Port, maxGapBytes), SpanLayout.TagNames, driverInstanceId); + + /// Reads one batch through a freshly-built driver and reports the wire shape. + /// Driver options carrying the layout's raw tags and span budget. + /// The references to read, in the order the driver is asked for them. + /// Instance id, distinct per call so log lines stay attributable. + /// The batch's snapshots plus the wire-call counts observed for the read itself. + private static async Task<(IReadOnlyList Snapshots, CountingPlcFactory Counters)> + ReadBatchAsync(S7DriverOptions options, IReadOnlyList tagNames, string driverInstanceId) { var counters = new CountingPlcFactory(new S7PlcFactory()); - await using var drv = new S7Driver( - SpanLayout.BuildOptions(sim.Host, sim.Port, maxGapBytes), driverInstanceId, counters); + await using var drv = new S7Driver(options, driverInstanceId, counters); await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); @@ -195,7 +340,7 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) // subject here, so the counters start from zero at the read. counters.Reset(); - var snapshots = await drv.ReadAsync(SpanLayout.TagNames, TestContext.Current.CancellationToken); + var snapshots = await drv.ReadAsync(tagNames, TestContext.Current.CancellationToken); return (snapshots, counters); } @@ -260,17 +405,118 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) }; } + /// + /// The Timer/Counter layouts. Two sets: a mixed batch that provokes all three read shapes at + /// once (block span, multi-var, per-tag Timer/Counter), and a device-numbered pair only a + /// real CPU can serve. Addresses map 1:1 to the TM0 / CT0 seeds in + /// Docker/profiles/s7_1500.json. + /// + private static class TimerCounterLayout + { + /// Declares the endpoint a real S7 CPU, which addresses TM/CT by device number. + public const string RealCpuEnvVar = "S7_TIMER_NUMBER_ADDRESSING"; + + /// + /// The one device number snap7's bit-address resolution and a CPU's device-number + /// resolution both land on: 0 >> 3 == 2 × 0 == 0. + /// + public const int Device0 = 0; + + /// T0's seed 0x2456 — S5TIME base 2 (×1 s) over BCD 456. + public const double Device0TimerSeconds = 456.0d; + + /// C0's seed — the raw big-endian count word. + public const int Device0CounterCount = 4711; + + /// + /// A Timer and a Counter batched with scalars laid out to produce every other read shape: + /// two adjacent DB1 words (one merged span) and three isolated narrow scalars, one of + /// them in another area (one 3-item multi-var request). + /// + public static readonly S7TagDefinition[] MixedBatch = + [ + new("TC_SpanB_U16a", "DB1.DBW400", S7DataType.UInt16), + new("TC_SpanB_U16b", "DB1.DBW402", S7DataType.UInt16), + new("TC_Lone_U16", "DB1.DBW500", S7DataType.UInt16), + new("TC_Lone_I16", "DB1.DBW600", S7DataType.Int16), + new("TC_Lone_Mk", "MW10", S7DataType.UInt16), + // Timer tags are typed Float64 (decoded to seconds) and Counter tags Int32 (decoded to + // a count) — the init guard rejects any other typing. Writable:false is mandatory, not + // stylistic: S7TagDefinition defaults Writable to TRUE and the same guard rejects a + // writable Timer/Counter outright (they are read-only this phase). + new("TC_Timer", "T0", S7DataType.Float64, Writable: false), + new("TC_Counter", "C0", S7DataType.Int32, Writable: false), + ]; + + /// The non-zero device numbers, reachable only from a device number-addressing CPU. + public static readonly S7TagDefinition[] DeviceNumbered = + [ + new("TC_Timer5", "T5", S7DataType.Float64, Writable: false), + new("TC_Counter7", "C7", S7DataType.Int32, Writable: false), + ]; + + /// The batch's references, in the order the driver is asked for them. + /// The definition set. + /// The tag names. + public static IReadOnlyList Names(IReadOnlyList defs) + => [.. defs.Select(d => d.Name)]; + + /// Builds driver options for one definition set at the shipped span budget. + /// The fixture hostname or IP address. + /// The fixture port. + /// The definition set. + /// The driver options. + public static S7DriverOptions BuildOptions(string host, int port, S7TagDefinition[] defs) => new() + { + Host = host, + Port = port, + CpuType = S7CpuType.S71500, + Rack = 0, + Slot = 0, + Timeout = TimeSpan.FromSeconds(5), + // As in SpanLayout: a background probe would race the read for the connection gate and + // pollute the wire-shape counts. + Probe = new S7ProbeOptions { Enabled = false }, + SpanReadMaxGapBytes = SpanLayout.DefaultGapBytes, + SpanReadMaxSpanBytes = S7DriverOptions.DefaultSpanReadMaxSpanBytes, + RawTags = S7RawTags.Entries(defs), + }; + } + /// /// decorator that counts the read calls the driver makes, so a /// test can assert the wire shape rather than infer it. Delegates to the real factory, so /// every counted call is the one production would have issued. /// + /// + /// Not thread-safe, by design. Every ReadBatchAsync builds its own factory and + /// the driver serialises all wire calls on its _gate, so nothing here is ever touched + /// concurrently today. A future caller that shared one factory across parallel reads would + /// silently corrupt the counts and shape lists rather than fail loudly — give it a lock, or + /// a factory per batch, before doing that. + /// /// The factory producing the real connection. private sealed class CountingPlcFactory(IS7PlcFactory inner) : IS7PlcFactory { + private readonly List<(S7NetDataType Area, int Db, int Start, int Count)> _blockReadShapes = []; + private readonly List _multiVarItemAreas = []; + /// Block reads issued — one per planned span. public int BlockReads { get; private set; } + /// + /// The (area, DB, start, count) of every block read, in issue order. Counting + /// alone cannot tell a Timer's own 2-byte area read from a span's — the shape can. + /// + public IReadOnlyList<(S7NetDataType Area, int Db, int Start, int Count)> BlockReadShapes + => _blockReadShapes; + + /// + /// The area of every item carried by every multi-var request. A Timer or Counter + /// appearing here is the exact defect the planner's exclusion exists to prevent. + /// + public IReadOnlyList MultiVarItemAreas => _multiVarItemAreas; + /// Multi-var requests issued — one per leftover chunk. public int MultiVarReads { get; private set; } @@ -290,18 +536,26 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) MultiVarReads = 0; MultiVarItems = 0; AddressReads = 0; + _blockReadShapes.Clear(); + _multiVarItemAreas.Clear(); } /// public IS7Plc Create(S7CpuType cpuType, string host, int port, short rack, short slot, TimeSpan timeout) => new CountingPlc(inner.Create(cpuType, host, port, rack, slot, timeout), this); - private void CountBlockRead() => BlockReads++; + private void CountBlockRead(S7NetDataType area, int db, int start, int count) + { + BlockReads++; + _blockReadShapes.Add((area, db, start, count)); + } - private void CountMultiVarRead(int items) + private void CountMultiVarRead(IReadOnlyList? items) { MultiVarReads++; - MultiVarItems += items; + MultiVarItems += items?.Count ?? 0; + if (items is null) return; + foreach (var item in items) _multiVarItemAreas.Add(item.DataType); } private void CountAddressRead() => AddressReads++; @@ -331,7 +585,7 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) public Task ReadBytesAsync( S7NetDataType area, int db, int startByteAdr, int count, CancellationToken cancellationToken) { - owner.CountBlockRead(); + owner.CountBlockRead(area, db, startByteAdr, count); return inner.ReadBytesAsync(area, db, startByteAdr, count, cancellationToken); } @@ -339,9 +593,10 @@ public sealed class S7_1500SpanReadTests(Snap7ServerFixture sim) public Task> ReadMultipleVarsAsync( List items, CancellationToken cancellationToken) { - // Counted before the call: the item count is the request's shape, and S7.Net hands - // the same list back, so reading it afterwards would measure the same thing later. - owner.CountMultiVarRead(items?.Count ?? 0); + // Counted before the call: the items ARE the request's shape, and S7.Net hands the + // same list back with values filled in, so reading them afterwards would measure + // the same thing later. + owner.CountMultiVarRead(items); return inner.ReadMultipleVarsAsync(items!, cancellationToken); } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs index 00160f68..73f661b1 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7SpanReadParityTests.cs @@ -36,6 +36,11 @@ public sealed class S7SpanReadParityTests private const uint StatusBadDeviceFailure = 0x808B0000u; /// OPC UA BadNodeIdUnknown — what an unresolvable reference stamps. private const uint StatusBadNodeIdUnknown = 0x80340000u; + /// + /// OPC UA BadCommunicationError — what the driver's catch-all failure mapping stamps, + /// which is where a malformed multi-var answer (an InvalidDataException) lands. + /// + private const uint StatusBadCommunicationError = 0x80050000u; // ── The mixed tag set ──────────────────────────────────────────────────────────────── @@ -373,6 +378,139 @@ public sealed class S7SpanReadParityTests factory.ReadBytesCalls.ShouldBe(2); } + // ── Malformed multi-var answers ────────────────────────────────────────────────────── + + /// + /// ONE undecodable item in an otherwise-good multi-var chunk spoils only its own tag: its + /// chunk-mates keep the values the batch already carried, and NOBODY is re-read individually. + /// A per-ITEM decode fault is not a chunk fault — the whole-chunk fallback exists for a + /// failed REQUEST, and firing it here would re-read tags that already have good values. + /// + /// + /// Health ends Healthy rather than Degraded because the decode loop stamps + /// health per item in chunk order, so the good item after the bad one re-stamps it. That is + /// the same last-writer-wins behaviour the per-tag loop has always had; it is pinned here so + /// a change to it is a deliberate one. + /// + [Fact] + public async Task One_undecodable_multi_var_item_stamps_only_its_own_tag_Bad() + { + var ct = TestContext.Current.CancellationToken; + var images = Images(); + var factory = new ImageS7PlcFactory(images) { NullItemIndex = 1 }; + using var driver = new S7Driver(Options(ScatteredWords(3), maxGap: 2), "s7-mv-item-fault", factory); + await driver.InitializeAsync("{}", ct); + + var results = await driver.ReadAsync(ScatteredRefs(3), ct); + + // The one item the CPU answered with nothing. + results[1].StatusCode.ShouldBe(StatusBadCommunicationError); + results[1].Value.ShouldBeNull(); + + // Its chunk-mates are untouched, values and all (S{i} lives at DB1.DBW{i * 8}). + var db1 = images[(S7NetDataType.DataBlock, 1)]; + static ushort Word(byte[] image, int at) => (ushort)((image[at] << 8) | image[at + 1]); + results[0].StatusCode.ShouldBe(0u); + results[0].Value.ShouldBe(Word(db1, 0)); + results[2].StatusCode.ShouldBe(0u); + results[2].Value.ShouldBe(Word(db1, 16)); + + // One batch, and NO per-tag fallback at all — not even for the tag that failed to decode, + // which would have failed identically on the per-tag path. + factory.MultiVarCalls.ShouldBe(1); + factory.StringReadCalls.ShouldBe(0); + factory.ReadBytesCalls.ShouldBe(0); + driver.GetHealth().State.ShouldBe(DriverState.Healthy); + } + + /// + /// An answer of the wrong SHAPE — one item short — cannot be mapped back onto the request's + /// indexes, so the driver refuses to guess which tag got which value and falls the whole + /// chunk back to the per-tag path, which still serves every tag Good. + /// + [Fact] + public async Task A_short_multi_var_answer_falls_back_to_per_tag_reads_and_still_serves_good() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()) { ShortAnswer = true }; + using var driver = new S7Driver(Options(ScatteredWords(5), maxGap: 2), "s7-mv-shape", factory); + await driver.InitializeAsync("{}", ct); + + var results = await driver.ReadAsync(ScatteredRefs(5), ct); + + results.ShouldAllBe(s => s.StatusCode == 0u); + results.ShouldAllBe(s => s.Value != null); + factory.MultiVarCalls.ShouldBe(1); + // Every tag of the rejected chunk was re-read individually — including the four the short + // answer DID carry, because a mis-shaped answer says nothing trustworthy about any of them. + factory.StringReadCalls.ShouldBe(5); + driver.GetHealth().State.ShouldBe(DriverState.Healthy); + } + + // ── Cancellation mid-read (STAB-15a) ───────────────────────────────────────────────── + + /// + /// Cancellation observed while a SPAN's block read is in flight abandons a half-read + /// ISO-on-TCP response on the single gated stream, so the handle can't be reused: the OCE + /// must propagate (the caller cancelled — nobody consumes the batch) AND the next read must + /// open a fresh connection. The per-tag path's sibling of this is pinned by + /// S7DriverReconnectTests.Cancelled_read_marks_handle_dead_and_next_read_reopens. + /// + [Fact] + public async Task A_cancelled_span_block_read_marks_the_handle_dead_and_the_next_read_reopens() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()) { HangReadBytes = true }; + using var driver = new S7Driver(Options(NarrowTags(), maxGap: 16), "s7-span-cancel", factory); + await driver.InitializeAsync("{}", ct); + factory.CreatedPlcCount.ShouldBe(1); + + string[] refs = ["A", "B", "C"]; + using var cts = new CancellationTokenSource(); + var reading = driver.ReadAsync(refs, cts.Token); + await factory.ReadBytesEntered.Task.WaitAsync(TimeSpan.FromSeconds(10), ct); + await cts.CancelAsync(); + + await Should.ThrowAsync(async () => await reading); + + // The reopen is the observable half of the contract: the desynced handle was DISPOSED — not + // merely leaked behind a second connection — and the next read builds a new one. + factory.HangReadBytes = false; + var recovered = await driver.ReadAsync(refs, ct); + recovered.ShouldAllBe(s => s.StatusCode == 0u); + factory.CreatedPlcCount.ShouldBe(2); + factory.Plcs[0].Disposed.ShouldBeTrue(); + } + + /// + /// The same contract on the MULTI-VAR leftover path: a cancelled batch request propagates + /// the OCE and marks the handle dead, so the next read reopens. Distinct from the per-chunk + /// fallback — cancellation is the one request fault that must NOT be retried per tag. + /// + [Fact] + public async Task A_cancelled_multi_var_read_marks_the_handle_dead_and_the_next_read_reopens() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ImageS7PlcFactory(Images()) { HangMultiVar = true }; + using var driver = new S7Driver(Options(ScatteredWords(5), maxGap: 2), "s7-mv-cancel", factory); + await driver.InitializeAsync("{}", ct); + factory.CreatedPlcCount.ShouldBe(1); + + var refs = ScatteredRefs(5); + using var cts = new CancellationTokenSource(); + var reading = driver.ReadAsync(refs, cts.Token); + await factory.MultiVarEntered.Task.WaitAsync(TimeSpan.FromSeconds(10), ct); + await cts.CancelAsync(); + + await Should.ThrowAsync(async () => await reading); + + factory.HangMultiVar = false; + var recovered = await driver.ReadAsync(refs, ct); + recovered.ShouldAllBe(s => s.StatusCode == 0u); + factory.CreatedPlcCount.ShouldBe(2); + factory.Plcs[0].Disposed.ShouldBeTrue(); + } + // ── Configurability ────────────────────────────────────────────────────────────────── /// @@ -473,15 +611,61 @@ public sealed class S7SpanReadParityTests /// When set, only the MULTI-VAR read throws this — the per-tag fallback still serves the image. public Exception? MultiVarFault { get; init; } + /// + /// When true, ReadBytesAsync hangs until its token is cancelled, so cancellation is + /// the only way out of a block read (STAB-15a). Settable so a test can turn it back off + /// after observing the cancellation and let the reopened handle read normally. + /// + public bool HangReadBytes { get; set; } + + /// When true, ReadMultipleVarsAsync hangs until its token is cancelled (STAB-15a). + public bool HangMultiVar { get; set; } + + /// Completed the moment a hanging ReadBytesAsync is entered, so a test cancels a read that is genuinely in flight. + public TaskCompletionSource ReadBytesEntered { get; } = new(TaskCreationOptions.RunContinuationsAsynchronously); + + /// Completed the moment a hanging ReadMultipleVarsAsync is entered. + public TaskCompletionSource MultiVarEntered { get; } = new(TaskCreationOptions.RunContinuationsAsynchronously); + + /// + /// When set, the multi-var answer comes back the right shape but with THIS item's + /// Value left null — the per-item decode fault, which must spoil only that tag. + /// + public int? NullItemIndex { get; init; } + + /// + /// When true, the multi-var answer comes back ONE item short — a shape the driver cannot + /// map back onto the request's indexes, so it must reject the whole chunk. + /// + public bool ShortAnswer { get; init; } + + /// How many connections this factory has been asked to build — the reopen observable. + public int CreatedPlcCount; + + /// + /// Every connection this factory built, in build order, so a test can assert what became + /// of the STALE one — a driver that leaked the old handle and merely opened a second + /// would satisfy alone. + /// + public List Plcs { get; } = new(); + /// public IS7Plc Create(S7CpuType cpuType, string host, int port, short rack, short slot, TimeSpan timeout) - => new ImageS7Plc(this); + { + Interlocked.Increment(ref CreatedPlcCount); + var plc = new ImageS7Plc(this); + lock (Plcs) Plcs.Add(plc); + return plc; + } - private sealed class ImageS7Plc(ImageS7PlcFactory owner) : IS7Plc + public sealed class ImageS7Plc(ImageS7PlcFactory owner) : IS7Plc { /// public bool IsConnected { get; private set; } + /// True once the driver has disposed this handle — the discard half of a reopen. + public bool Disposed { get; private set; } + /// public Task OpenAsync(CancellationToken ct) { IsConnected = true; return Task.CompletedTask; } @@ -489,11 +673,18 @@ public sealed class S7SpanReadParityTests public void Close() => IsConnected = false; /// - public Task ReadBytesAsync(S7NetDataType area, int db, int startByteAdr, int count, CancellationToken ct) + public async Task ReadBytesAsync(S7NetDataType area, int db, int startByteAdr, int count, CancellationToken ct) { // Counted BEFORE the injected fault so a test can assert how many block reads were // ATTEMPTED — a failure test that counted only successes would read zero. Interlocked.Increment(ref owner.ReadBytesCalls); + if (owner.HangReadBytes) + { + // Signal first, then hang: the test cancels only once the read is genuinely in + // flight, so it exercises cancel-mid-I/O rather than racing a timer. + owner.ReadBytesEntered.TrySetResult(); + await Task.Delay(System.Threading.Timeout.Infinite, ct).ConfigureAwait(false); + } if (owner.ReadFault is { } fault) throw fault; var image = owner.Images[(area, db)]; if (startByteAdr + count > image.Length) @@ -501,7 +692,7 @@ public sealed class S7SpanReadParityTests throw new PlcException(ErrorCode.ReadData, $"fake image overrun: {area} db{db} @{startByteAdr}+{count} exceeds {image.Length}"); } - return Task.FromResult(image[startByteAdr..(startByteAdr + count)]); + return image[startByteAdr..(startByteAdr + count)]; } /// @@ -512,13 +703,18 @@ public sealed class S7SpanReadParityTests /// ushort, DWord a uint. Like the real library it populates each /// item's Value in place and hands the same list back. /// - public Task> ReadMultipleVarsAsync( + public async Task> ReadMultipleVarsAsync( List items, CancellationToken ct) { // Counted (and captured) BEFORE the injected fault so a fallback test can assert the // batch was ATTEMPTED — counting only successes would read zero. Interlocked.Increment(ref owner.MultiVarCalls); lock (owner.MultiVarItems) owner.MultiVarItems.Add([.. items]); + if (owner.HangMultiVar) + { + owner.MultiVarEntered.TrySetResult(); + await Task.Delay(System.Threading.Timeout.Infinite, ct).ConfigureAwait(false); + } if (owner.MultiVarFault is { } mvFault) throw mvFault; if (owner.ReadFault is { } fault) throw fault; @@ -537,7 +733,12 @@ public sealed class S7SpanReadParityTests }; } - return Task.FromResult>(items); + // The two malformed-answer shapes, injected AFTER decoding so the answer is as good + // as any other batch's apart from the one defect under test. + if (owner.NullItemIndex is { } nullAt) items[nullAt].Value = null; + if (owner.ShortAnswer) return items.GetRange(0, items.Count - 1); + + return items; } /// @@ -584,7 +785,11 @@ public sealed class S7SpanReadParityTests public Task ReadStatusAsync(CancellationToken ct) => Task.CompletedTask; /// - public void Dispose() => IsConnected = false; + public void Dispose() + { + IsConnected = false; + Disposed = true; + } } } } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/AdminUiSqlServerFixture.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/AdminUiSqlServerFixture.cs index 26a8b7bb..02eee6ac 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/AdminUiSqlServerFixture.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/AdminUiSqlServerFixture.cs @@ -1,4 +1,4 @@ -using System.Data.Common; +using System.Globalization; using Microsoft.Data.SqlClient; using Microsoft.EntityFrameworkCore; using Xunit; @@ -74,7 +74,14 @@ public sealed class AdminUiSqlServerFixture : IDisposable SkipReason = AdminUiSqlServer.SkipReason; if (SkipReason is not null) return; - DatabaseName = $"OtOpcUaAdminUi_Test_{DateTime.UtcNow:yyyyMMddHHmmss}_{Guid.NewGuid():N}"; + // A killed test process never reaches Dispose, so its database outlives the run. Reap the ones + // old enough to be certainly nobody's (once per process, and only after the probe answered). + AdminUiSqlServer.ReapOrphanedTestDatabasesOnce(); + + // Mint from the same constant the reaper's LIKE anchors on — a rename that touched only one of the + // two would leave every future database unreapable, with nothing to signal it. + DatabaseName = + $"{AdminUiSqlServer.TestDatabasePrefix}{DateTime.UtcNow:yyyyMMddHHmmss}_{Guid.NewGuid():N}"; ConnectionString = AdminUiSqlServer.ConnectionStringFor(DatabaseName); try @@ -106,27 +113,8 @@ public sealed class AdminUiSqlServerFixture : IDisposable { if (ConnectionString is null || DatabaseName is null) return; - try - { - var master = new SqlConnectionStringBuilder(ConnectionString) { InitialCatalog = "master" }.ConnectionString; - - using var conn = new SqlConnection(master); - conn.Open(); - - using var cmd = conn.CreateCommand(); - cmd.CommandText = $@" -IF DB_ID(N'{DatabaseName}') IS NOT NULL -BEGIN - ALTER DATABASE [{DatabaseName}] SET SINGLE_USER WITH ROLLBACK IMMEDIATE; - DROP DATABASE [{DatabaseName}]; -END"; - cmd.ExecuteNonQuery(); - } - catch (DbException) - { - // Teardown is best-effort: a dropped connection here must not fail an otherwise-green run. - // The database name carries a timestamp, so a leaked one is identifiable. - } + var master = new SqlConnectionStringBuilder(ConnectionString) { InitialCatalog = "master" }.ConnectionString; + SqlTestDatabaseReaper.TryDropDatabase(master, DatabaseName); } private sealed class SqlServerContextFactory(string connectionString) @@ -150,15 +138,30 @@ END"; /// internal static class AdminUiSqlServer { + /// The name prefix every AdminUI test database carries; also the reaper's LIKE anchor. + public const string TestDatabasePrefix = "OtOpcUaAdminUi_Test_"; + private const string DefaultServer = "10.100.0.35,14330"; private const string DefaultSaPassword = "OtOpcUaDev_2026!"; private const int ProbeTimeoutSeconds = 3; + /// How long a test database must have existed before the reaper considers it certainly orphaned. + private static readonly TimeSpan OrphanAge = TimeSpan.FromHours(24); + private static readonly Lazy Probe = new(RunProbe, LazyThreadSafetyMode.ExecutionAndPublication); + private static readonly Lazy Reaper = new(RunReaper, LazyThreadSafetyMode.ExecutionAndPublication); + /// Gets the reason SQL Server is unusable, or when it answered. public static string? SkipReason => Probe.Value; + /// + /// Reaps orphaned AdminUI test databases older than 24 hours, at most once per process. Call only + /// after came back — the reaper never throws, but + /// against a dead server it would just burn a connect timeout for nothing. + /// + public static void ReapOrphanedTestDatabasesOnce() => _ = Reaper.Value; + /// Builds a connection string for the named database on the configured test server. /// The database to connect to. /// The connection string. @@ -171,6 +174,12 @@ internal static class AdminUiSqlServer "TrustServerCertificate=True;Encrypt=False;"; } + private static int RunReaper() => + SqlTestDatabaseReaper.ReapOrphans( + ConnectionStringFor("master"), + TestDatabasePrefix, + DateTime.UtcNow - OrphanAge).Count; + private static string? RunProbe() { var server = Environment.GetEnvironmentVariable("OTOPCUA_CONFIG_TEST_SERVER") ?? DefaultServer; @@ -194,6 +203,183 @@ internal static class AdminUiSqlServer } } +/// +/// Drops test databases that a killed test process left behind on the shared SQL Server. +/// +/// +/// +/// Every fixture here names its database {prefix}{yyyyMMddHHmmss-UTC}_{guid:N} and drops it +/// in Dispose — which a Ctrl-C, a crashed runner or a killed container never reaches, +/// so the database survives forever on an instance nobody gardens. +/// +/// +/// This is DROP DATABASE against a server other people share, so the rules are deliberately +/// narrow and every one of them is load-bearing: +/// +/// +/// +/// the LIKE is an exact prefix with _ escaped (an unescaped _ is a +/// single-character wildcard in T-SQL) — never widen it; +/// +/// +/// a matching name is dropped only when its whole shape is one this code could have +/// minted — prefix, a parseable 14-digit UTC timestamp, _, then 32 hex digits. That is +/// belt and braces against second-order injection: the name is also passed as a +/// parameter through QUOTENAME rather than interpolated into DDL, but the shape +/// check independently guarantees a candidate cannot contain ] or '; +/// +/// +/// only names strictly older than the cutoff are dropped. At 24 hours that is far beyond +/// any run, so the reaper can never race a live sibling run on the same server; and +/// +/// +/// nothing here ever throws. A reaper that fails a green run would be worse than the leak it +/// cleans up. +/// +/// +/// +internal static class SqlTestDatabaseReaper +{ + private const string TimestampFormat = "yyyyMMddHHmmss"; + private const int ConnectTimeoutSeconds = 3; + + /// + /// Drops every database matching whose embedded creation timestamp is + /// strictly older than . + /// + /// A connection string pointed at master. + /// The exact test-database name prefix, e.g. OtOpcUaAdminUi_Test_. + /// Databases created strictly before this UTC instant are dropped. + /// The names actually dropped; empty when there was nothing to reap or anything went wrong. + internal static IReadOnlyList ReapOrphans(string masterConnectionString, string prefix, DateTime cutoffUtc) + { + var reaped = new List(); + + try + { + foreach (var name in ListCandidates(masterConnectionString, prefix)) + { + if (!TryParseCreatedUtc(name, prefix, out var createdUtc)) continue; + if (createdUtc >= cutoffUtc) continue; + + try + { + if (TryDropDatabase(masterConnectionString, name)) reaped.Add(name); + } + catch (Exception) + { + // One stubborn database must not stop the sweep, nor fail the run that triggered it. + } + } + } + catch (Exception) + { + // Enumeration failed (server down, no permission). Reaping is opportunistic housekeeping. + } + + if (reaped.Count > 0) + { + Console.WriteLine( + $"[sql-test-reaper] dropped {reaped.Count} orphaned test database(s) older than " + + $"{cutoffUtc:yyyy-MM-dd HH:mm:ss}Z: {string.Join(", ", reaped)}"); + } + + return reaped; + } + + /// + /// Drops the named database, swallowing every failure — this is called unwrapped from + /// Dispose and from test finally blocks, so it must be genuinely best-effort. + /// + /// + /// The database name is an identifier, which cannot be parameterised directly, so it rides + /// in as a parameter and QUOTENAME escapes it server-side. Interpolating it into the DDL + /// instead would make any attacker-chosen database name on this shared server a second-order + /// injection executed as sa. + /// + /// A connection string pointed at master. + /// The database to drop. + /// when the statement ran without error. + internal static bool TryDropDatabase(string masterConnectionString, string databaseName) + { + try + { + using var conn = new SqlConnection(masterConnectionString); + conn.Open(); + + using var cmd = conn.CreateCommand(); + + // The QUOTENAME result must be assembled into a variable first: EXEC() accepts only a + // concatenation of literals and variables, so the tempting one-liner + // EXEC('ALTER DATABASE ' + QUOTENAME(@name) + …) is a syntax error, not a subtle bug. + cmd.CommandText = @" +DECLARE @sql nvarchar(max); +IF DB_ID(@name) IS NOT NULL +BEGIN + SET @sql = N'ALTER DATABASE ' + QUOTENAME(@name) + N' SET SINGLE_USER WITH ROLLBACK IMMEDIATE; ' + + N'DROP DATABASE ' + QUOTENAME(@name) + N';'; + EXEC sp_executesql @sql; +END"; + cmd.Parameters.Add(new SqlParameter("@name", databaseName)); + + cmd.ExecuteNonQuery(); + return true; + } + catch (Exception) + { + // Teardown is best-effort: a dropped connection here must not fail an otherwise-green run. + // The database name carries a timestamp, so a leaked one is reaped by the next run instead. + return false; + } + } + + private static List ListCandidates(string masterConnectionString, string prefix) + { + var names = new List(); + + // A short connect timeout, because this runs BEFORE whatever the fixture does next: on an + // unreachable server the default ~15 s would simply be added to the latency the caller already pays. + var probe = new SqlConnectionStringBuilder(masterConnectionString) + { + ConnectTimeout = ConnectTimeoutSeconds, + }.ConnectionString; + + using var conn = new SqlConnection(probe); + conn.Open(); + + using var cmd = conn.CreateCommand(); + cmd.CommandText = @"SELECT name FROM sys.databases WHERE name LIKE @pattern ESCAPE '\'"; + cmd.Parameters.Add(new SqlParameter("@pattern", prefix.Replace("_", @"\_", StringComparison.Ordinal) + "%")); + + using var reader = cmd.ExecuteReader(); + while (reader.Read()) names.Add(reader.GetString(0)); + + return names; + } + + private static bool TryParseCreatedUtc(string databaseName, string prefix, out DateTime createdUtc) + { + createdUtc = default; + + if (!databaseName.StartsWith(prefix, StringComparison.Ordinal)) return false; + + var rest = databaseName.AsSpan(prefix.Length); + + // Expect exactly "<14-digit timestamp>_<32 hex digits>" — anything else is not a name this code + // minted. Validating the GUID tail is what bounds the character set of every candidate name: a + // "N"-format GUID is hex only, so no candidate can carry a ']' or a quote into the drop statement. + if (rest.Length < TimestampFormat.Length + 1 || rest[TimestampFormat.Length] != '_') return false; + if (!Guid.TryParseExact(rest[(TimestampFormat.Length + 1)..], "N", out _)) return false; + + return DateTime.TryParseExact( + rest[..TimestampFormat.Length], + TimestampFormat, + CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, + out createdUtc); + } +} + /// /// A that skips itself when the shared test SQL Server is unreachable. /// The xunit v2 equivalent of xunit v3's Assert.Skip — see diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/SqlTestDatabaseReaperTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/SqlTestDatabaseReaperTests.cs new file mode 100644 index 00000000..92d67675 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.AdminUI.Tests/SqlTestDatabaseReaperTests.cs @@ -0,0 +1,148 @@ +using Microsoft.Data.SqlClient; +using Shouldly; +using Xunit; + +namespace ZB.MOM.WW.OtOpcUa.AdminUI.Tests; + +/// +/// Pins against the real shared SQL Server: an aged orphan is +/// dropped, a fresh sibling is not. +/// +/// +/// A pin, not a red-first test. The reaper is time-gated and the behaviour it protects — "a +/// database created by a run that is long over gets dropped, one created by a run that may still be +/// going does not" — has no observable failing state to start from; what it needs is a guard against +/// someone later widening the age window, the LIKE, or the timestamp parse. It therefore drives +/// the internal core with an explicit cutoff rather than waiting 24 hours. +/// +/// +/// Joined to deliberately, though it never touches the +/// fixture: xunit builds a collection fixture before running the collection's tests and serialises them +/// within it, which is what keeps 's own startup reaper from +/// racing this one. Left in its own (parallel) collection, that reaper can drop the aged database this +/// test plants, between the plant and the assertion — observed as an intermittent failure. +/// +[Collection(nameof(AdminUiSqlServerCollection))] +public sealed class SqlTestDatabaseReaperTests +{ + [SqlServerFact] + public void Reap_drops_databases_older_than_the_cutoff_and_leaves_fresh_ones_alone() + { + var master = AdminUiSqlServer.ConnectionStringFor("master"); + + // A name that carries a timestamp from 2025 — unambiguously older than any cutoff this suite uses. + var aged = $"{AdminUiSqlServer.TestDatabasePrefix}20250101000000_{Guid.NewGuid():N}"; + var fresh = $"{AdminUiSqlServer.TestDatabasePrefix}{DateTime.UtcNow:yyyyMMddHHmmss}_{Guid.NewGuid():N}"; + + CreateDatabase(master, aged); + + try + { + CreateDatabase(master, fresh); + + try + { + var reaped = SqlTestDatabaseReaper.ReapOrphans( + master, + AdminUiSqlServer.TestDatabasePrefix, + DateTime.UtcNow - TimeSpan.FromHours(24)); + + reaped.ShouldContain(aged); + DatabaseExists(master, aged).ShouldBeFalse("the aged orphan should have been reaped"); + + reaped.ShouldNotContain(fresh); + DatabaseExists(master, fresh).ShouldBeTrue("a database from a possibly-live run must survive"); + } + finally + { + SqlTestDatabaseReaper.TryDropDatabase(master, fresh); + } + } + finally + { + // No-op when the reaper already took it; belt-and-braces if an assertion failed first. + SqlTestDatabaseReaper.TryDropDatabase(master, aged); + } + } + + [SqlServerFact] + public void Reap_leaves_a_matching_name_whose_timestamp_does_not_parse_alone() + { + var master = AdminUiSqlServer.ConnectionStringFor("master"); + var unparseable = $"{AdminUiSqlServer.TestDatabasePrefix}notatimestamp_{Guid.NewGuid():N}"; + + CreateDatabase(master, unparseable); + + try + { + // The cutoff stays at the production 24 hours — deliberately NOT a far-future one, which would + // sweep away the live database of an AdminUI fixture running in parallel on this shared server. + // It still bites: an unparseable name that fell through to default(DateTime) would read as year + // 0001 and be dropped. + var reaped = SqlTestDatabaseReaper.ReapOrphans( + master, + AdminUiSqlServer.TestDatabasePrefix, + DateTime.UtcNow - TimeSpan.FromHours(24)); + + reaped.ShouldNotContain(unparseable); + DatabaseExists(master, unparseable) + .ShouldBeTrue("a name this code could not have minted is never dropped"); + } + finally + { + SqlTestDatabaseReaper.TryDropDatabase(master, unparseable); + } + } + + [SqlServerFact] + public void Reap_leaves_an_aged_name_whose_suffix_is_not_a_guid_alone() + { + var master = AdminUiSqlServer.ConnectionStringFor("master"); + + // Aged enough to be reaped on the timestamp alone — only the suffix check saves it. That check is + // what bounds the character set of every candidate: without it a database named + // "_" + arbitrary text would be fed to the drop statement, and before the + // statement was parameterised that was a second-order injection running as sa. + var notAGuid = $"{AdminUiSqlServer.TestDatabasePrefix}20250101000000_notaguid"; + + CreateDatabase(master, notAGuid); + + try + { + var reaped = SqlTestDatabaseReaper.ReapOrphans( + master, + AdminUiSqlServer.TestDatabasePrefix, + DateTime.UtcNow - TimeSpan.FromHours(24)); + + reaped.ShouldNotContain(notAGuid); + DatabaseExists(master, notAGuid) + .ShouldBeTrue("only names shaped exactly as this code mints them are ever dropped"); + } + finally + { + SqlTestDatabaseReaper.TryDropDatabase(master, notAGuid); + } + } + + private static void CreateDatabase(string masterConnectionString, string databaseName) + { + using var conn = new SqlConnection(masterConnectionString); + conn.Open(); + + using var cmd = conn.CreateCommand(); + cmd.CommandText = $"CREATE DATABASE [{databaseName}];"; + cmd.ExecuteNonQuery(); + } + + private static bool DatabaseExists(string masterConnectionString, string databaseName) + { + using var conn = new SqlConnection(masterConnectionString); + conn.Open(); + + using var cmd = conn.CreateCommand(); + cmd.CommandText = "SELECT DB_ID(@name);"; + cmd.Parameters.Add(new SqlParameter("@name", databaseName)); + + return cmd.ExecuteScalar() is not (null or DBNull); + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs index 6062c6b7..4d75d858 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.Tests/SessionAclDecisionCacheTests.cs @@ -263,6 +263,166 @@ public sealed class SessionAclDecisionCacheTests } } + /// + /// A request presenting an OLDER generation — one whose authority snapshot was captured before a + /// deploy and which then lost the scheduling race — must not roll the cache stamp backward, and must + /// not purge the new generation's entries on its way past. + /// + /// + /// + /// The generation itself is monotonic by construction; what is not monotonic is the order + /// requests arrive holding it. Treating a straggler as a deploy inverts the stamp and + /// wipes shards that were populated correctly, so the post-deploy window — the coldest the cache + /// ever is, and the busiest repopulating — is precisely when it would thrash. + /// + /// + /// Nothing here uses AdvanceGenerationForTest: this is the ordinary lookup path, + /// observed. The straggler must miss (its snapshot is superseded, so recomputing is right) AND + /// leave everything else standing — a test asserting only the miss passes against the defect, + /// because the straggler misses either way. + /// + /// + [Fact] + public void A_straggler_from_an_older_generation_neither_clears_nor_rolls_the_stamp_back() + { + var cache = new SessionAclDecisionCache(); + + Ask(cache, generation: 2, compute: () => true).ShouldBeTrue(); + cache.Generation.ShouldBe(2); + cache.Count.ShouldBe(1); + + // The straggler: same question, superseded snapshot. + cache.TryGet(generation: 1, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out _) + .ShouldBeFalse("a superseded snapshot must recompute rather than read the newer generation"); + + // Asserted BEFORE the generation-2 lookup below, which would itself restore a rolled-back stamp — + // so a stamp assertion made after it could never fail. (The purge half would still surface, as the + // last lookup would miss; it is the stamp half that needs its assertion here.) + cache.Generation.ShouldBe(2, "the straggler must not have rolled the stamp backward"); + cache.Count.ShouldBe(1, "and must not have purged the current generation's entries"); + + cache.TryGet(generation: 2, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out var decision) + .ShouldBeTrue("the current generation's decision survived the straggler"); + decision.ShouldBeTrue(); + } + + /// + /// The store half of the same window: a Set that meets the previous generation's shard must + /// displace it, not fill it. + /// + /// + /// Filing into an orphaned shard is never wrong — the read path's generation check means + /// nothing stored there can ever be served — which is exactly why it needs its own pin: the symptom + /// is silent, and it is a dead cache rather than a leaking one. Every store for that key would land + /// somewhere unreadable, consuming the key's whole per-shard budget before an eviction swap finally + /// minted a shard for the current generation. Twenty thousand wasted inserts per key per deployment, + /// with a hit rate of zero throughout and nothing in the counters to say so. + /// + [Fact] + public void A_store_meeting_the_previous_generations_shard_displaces_it() + { + var cache = new SessionAclDecisionCache(); + + Ask(cache, generation: 1, compute: () => true).ShouldBeTrue(); + cache.AdvanceGenerationForTest(2); + + // Inside the window: the stamp says 2, the shard in the table was built for 1. + cache.Set(generation: 2, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, decision: false); + + cache.TryGet(generation: 2, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out var decision) + .ShouldBeTrue("the store must have landed in a shard the current generation can read"); + decision.ShouldBeFalse("and it must be the new verdict, not the one it replaced"); + + // The displaced shard was sealed and unbooked, so the survivor is the single new entry. + cache.Count.ShouldBe(1); + cache.TrackedCount.ShouldBe(1); + cache.LiveShardCount.ShouldBe(1); + } + + /// + /// The same rollover, arrived at the way production does — a generation moving under live traffic + /// rather than through the test seam. No hit may ever return a verdict stored under a different + /// generation, and the counters must still settle exactly. + /// + /// + /// + /// The generation is encoded in the stored verdict (gen % 2 == 0), which is what + /// makes a leak visible at all: a cache that answers with the right shape but the wrong + /// generation's data is indistinguishable from a correct one unless the data says which + /// generation it came from. A miss recomputes the encoding for the generation it was asked + /// about, so only a hit can ever disagree. + /// + /// + /// The bumps come from inside the worker mix rather than from a spinning thread of their own, + /// and are spaced far enough apart for entries to accumulate between them — a generation moving + /// faster than a lookup completes makes every call a miss, which is a cache that is never read + /// and therefore a test that pins nothing. + /// + /// + [Fact] + public void No_hit_ever_returns_a_verdict_from_another_generation() + { + var cache = new SessionAclDecisionCache(); + const int workers = 6; + const int writesEach = 30_000; + const int bumpEvery = 500; + const int rounds = 4; + + // A deliberately narrow node and key space: workers must keep landing on entries their peers + // stored, and on shards a bump has just orphaned. Unique identifiers would make every call a miss. + const int nodes = 64; + const int keys = 2; + + for (var r = 0; r < rounds; r++) + { + var round = r; + var generation = (round * 100L) + 1L; + var mismatches = 0; + var start = new Barrier(workers); + var threads = new Thread[workers]; + + for (var w = 0; w < workers; w++) + { + var worker = w; + + threads[w] = new Thread(() => + { + start.SignalAndWait(); + + for (var i = 0; i < writesEach; i++) + { + // One worker advances the generation, so the bump lands in the middle of the others' + // traffic rather than beside it. + if (worker == 0 && i % bumpEvery == 0) Interlocked.Increment(ref generation); + + var gen = Interlocked.Read(ref generation); + var expected = gen % 2 == 0; + + var decided = cache.GetOrAdd( + gen, $"key-{worker % keys}", OpcUaOperation.Read, AddressSpaceRealm.Raw, + $"Plant/dev1/Tag{i % nodes}", () => expected); + + if (decided != expected) Interlocked.Increment(ref mismatches); + } + }) { IsBackground = true }; + } + + foreach (var thread in threads) thread.Start(); + foreach (var thread in threads) thread.Join(); + start.Dispose(); + + mismatches.ShouldBe( + 0, $"round {round}: a hit served a verdict taken under a different generation"); + + var survived = cache.Count; + + cache.LiveShardCount.ShouldBe( + survived, $"round {round}: a shard's own counter drifted from its entries"); + cache.TrackedCount.ShouldBe( + survived, $"round {round}: the global counter drifted from the live shards"); + } + } + /// /// A decision taken while a deployment lands mid-walk is returned but NOT stored, so the new /// generation never inherits a verdict its own trie did not make. @@ -289,6 +449,77 @@ public sealed class SessionAclDecisionCacheTests cache.Count.ShouldBe(1); } + /// + /// The generation-rollover window, made deterministic. Publishing the new generation and purging the + /// shards are two steps, and a racer arriving between them sees a generation that already matches + /// and shards that have not been dropped yet — so it must not be able to read one. + /// + /// + /// + /// AdvanceGenerationForTest is the racer's view exactly: the stamp moves, nothing clears. + /// Before the fix this test served the generation-1 verdict to a generation-2 caller. Key + /// revocation and expiry are re-checked above the cache, so the leak was a stale grant walk + /// rather than a usable revoked key — real, but narrower than it first looks. + /// + /// + /// ⚠️ The assertion is a miss, not a corrected value: serving false from a shard + /// built under the old generation would be just as wrong, and a value assertion would pass on it. + /// + /// + [Fact] + public void A_shard_built_under_the_previous_generation_is_never_served() + { + var cache = new SessionAclDecisionCache(); + + // GetOrAdd, not a bare Set: Set drops a decision whose generation is not already the stamped one, + // and a fresh cache is stamped -1. The lookup inside GetOrAdd is what publishes generation 1. + Ask(cache, generation: 1, compute: () => true).ShouldBeTrue(); + cache.TryGet(generation: 1, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out var stored) + .ShouldBeTrue("the entry must exist before the window opens, or the test proves nothing"); + stored.ShouldBeTrue(); + + // Stand inside the window: the new generation is published, the shards are not yet purged. + cache.AdvanceGenerationForTest(2); + + cache.TryGet(generation: 2, Session, OpcUaOperation.Read, AddressSpaceRealm.Raw, Node, out _) + .ShouldBeFalse("a shard may only answer for the generation it was built under"); + } + + /// + /// A shard displaced by the per-shard eviction swap keeps taking inserts correctly, with the counters + /// still exact — the behaviour pin behind the capacity hint the swap now passes. + /// + /// + /// Pin, not red-first. The hint sizes a dictionary's initial buckets, which is unobservable + /// through the public surface: no assertion here can distinguish a hinted shard from a default one, + /// and none tries to. What it pins is that passing it changed nothing about the refill — that the + /// replacement shard still accepts entries and still books them exactly once. + /// + [Fact] + public void A_shard_replaced_by_the_eviction_swap_still_refills_exactly() + { + var cache = new SessionAclDecisionCache(); + const int overshoot = 12; + + for (var i = 0; i < SessionAclDecisionCache.MaxEntriesPerSession + overshoot; i++) + Ask(cache, generation: 1, session: "crawler-key", node: $"Plant/dev1/Tag{i}", compute: () => true); + + cache.Count.ShouldBe(overshoot); + cache.TrackedCount.ShouldBe(overshoot); + cache.LiveShardCount.ShouldBe(overshoot); + + // The refilled shard serves what it was given, and a fresh insert into it still books once. + Ask(cache, generation: 1, session: "crawler-key", node: "Plant/dev1/Tag20011", + compute: () => throw new InvalidOperationException("this decision was already memoized")) + .ShouldBeTrue(); + Ask(cache, generation: 1, session: "crawler-key", node: "Plant/dev1/Fresh", compute: () => false) + .ShouldBeFalse(); + + cache.Count.ShouldBe(overshoot + 1); + cache.TrackedCount.ShouldBe(cache.Count); + cache.LiveShardCount.ShouldBe(cache.Count); + } + private static bool Ask( SessionAclDecisionCache cache, long generation, diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs index 1ca1c182..2a8c7bde 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using Akka.Actor; using Akka.TestKit.Xunit2; using Xunit; @@ -445,11 +446,15 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit }, TimeSpan.FromSeconds(10)); // And the healthy tag was submitted a BOUNDED number of times — once per blocked pass plus the - // pass that unblocked, never indefinitely. Snapshot it, let several more drain intervals elapse, - // and prove it has stopped growing: an unbounded re-write would still be climbing. + // pass that unblocked, never indefinitely. Snapshot it, wait on the DRAIN'S OWN clock until three + // more passes have demonstrably run (a wall-clock sleep only hopes they did — on a loaded agent it + // can elapse with the drain never scheduled, and the negative assertion below then passes + // vacuously), and prove the count has stopped growing: an unbounded re-write would still climb. int rewrites = writer.Snapshot().Count(w => w.Tag == "Good.Tag"); Assert.InRange(rewrites, 1, maxAttempts + 1); - await Task.Delay(TimeSpan.FromMilliseconds(300)); + + int passes = await WaitForFurtherDrainPassesAsync(outbox, outbox.PeekBatchCallCount, 3, TimeSpan.FromSeconds(5)); + Assert.True(passes >= 3, $"expected >= 3 further drain passes within 5s, observed {passes}"); Assert.Equal(rewrites, writer.Snapshot().Count(w => w.Tag == "Good.Tag")); } @@ -598,8 +603,33 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit await writer.Cancelled.WaitAsync(TimeSpan.FromSeconds(10)); - // Give the (unfixed) fold every chance to book the failure and truncate before we assert it did not. - await Task.Delay(TimeSpan.FromMilliseconds(500)); + // Bounded negative watch — red is immediate when the fold truncates; green costs the window once. + // This guards a NEGATIVE ("the pass unwound without acking"), so instead of sleeping and hoping the + // unwind finished, poll for the BUG's own positive signal: the fold calling RemoveAsync at all, or + // the queued count moving off 2. Either fires the moment the unfixed recorder books the failure and + // truncates, so a regression fails in milliseconds rather than after a fixed sleep; only the passing + // case pays the full window. + // + // 1s is the window, and it is already generous headroom rather than a guess: everything it waits on + // is prompt on this fixture — the cancellation of the writer's `Task.Delay(Timeout.Infinite, ct)` is + // essentially synchronous (and `writer.Cancelled` above has already fired), the fold that would + // truncate runs immediately behind it, and the recorder's own cadence here is a 20ms drain interval + // with a 20-50ms backoff. The unfixed recorder trips this in ~150ms including startup, so the + // remaining ~6x is CI-load slack, not mechanism. + var watch = Stopwatch.StartNew(); + while (watch.Elapsed < TimeSpan.FromSeconds(1)) + { + // Read once per iteration: the condition and its failure message must report the SAME + // observation, or a red run names a count that is not the one that tripped. + int removeCalls = outbox.RemoveCallCount; + Assert.True( + removeCalls == 0, + $"the cancelled pass acked: RemoveAsync ran {removeCalls}x, truncating the queue"); + int queued = await outbox.CountAsync(default); + Assert.True(queued == 2, $"the cancelled pass changed the queue depth: expected 2, saw {queued}"); + await Task.Delay(25); + } + Assert.Equal(2, await outbox.CountAsync(default)); } @@ -853,8 +883,28 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit }, TimeSpan.FromSeconds(10)); - // …and stays alone: with a window of 8 the other two groups would have entered by now. - await Task.Delay(TimeSpan.FromMilliseconds(300)); + // …and stays alone: with a window of 8 the other two groups would have entered by now. Bounded + // negative watch rather than a sleep — red is immediate the moment a second group enters; green + // costs the window once. + // + // The drain-pass clock the other negative watches in this file use is NOT available here: the + // recorder is single-flight (`_draining`), and a blocked pass re-arms no drain timer, so + // PeekBatchCallCount is pinned at 1 for as long as the writer is gated. What makes the short + // window sufficient is that admission is not deferred work — the drain starts every group's task + // eagerly and a free semaphore permit is taken synchronously, so under a window of 8 groups B and + // C would be inside the writer in the same synchronous stretch as A, before the precondition above + // could even observe CallCount >= 1. The genuinely clock-anchored pin is the post-Release + // assertion at the end, which reads the peak after all three groups have demonstrably run. + var watch = Stopwatch.StartNew(); + while (watch.Elapsed < TimeSpan.FromMilliseconds(500)) + { + Assert.True( + writer.MaxObservedConcurrency == 1 && writer.CallCount == 1, + $"a second group entered under a window of 1: calls={writer.CallCount}, " + + $"peak={writer.MaxObservedConcurrency}"); + await Task.Delay(25); + } + Assert.Equal(1, writer.MaxObservedConcurrency); Assert.Equal(1, writer.CallCount); @@ -1231,6 +1281,35 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit mux.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); // no PreStart re-register == no restart } + /// + /// Waits until the recorder has run further drain passes past + /// , and returns how many it actually observed. + /// + /// + /// The drain's own clock, for the negative assertions that need "several more passes have happened" + /// — the recorder is single-flight, so advances once + /// per COMPLETED pass. A wall-clock sleep only hopes the passes ran: on a loaded agent it can elapse + /// with the drain never scheduled, and the negative assertion it guards then passes vacuously. + /// + /// On cap-out the last observation is RETURNED rather than thrown on, so the caller's assert + /// reports the actual shortfall instead of a bare timeout — the same shape as + /// FasterLogHistorizationOutboxTests.ReadCommittedWhenVisibleAsync. + /// + /// + private static async Task WaitForFurtherDrainPassesAsync( + InMemoryOutbox outbox, int baseline, int additionalPasses, TimeSpan cap) + { + var elapsed = Stopwatch.StartNew(); + int observed = outbox.PeekBatchCallCount - baseline; + while (observed < additionalPasses && elapsed.Elapsed < cap) + { + await Task.Delay(25); + observed = outbox.PeekBatchCallCount - baseline; + } + + return observed; + } + /// /// double that BLOCKS every call until , /// recording the peak number of calls in flight simultaneously. That peak is what distinguishes a @@ -1503,6 +1582,7 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit private readonly bool _yieldOnAppend; private int _peekCalls; + private int _removeCalls; /// When non-null, durably appends the first /// entries and then throws this — the production outbox's @@ -1531,6 +1611,21 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit } } + /// Lifetime count of calls — one per acked drain pass, so a + /// non-zero value is positive evidence that the outcome fold decided to TRUNCATE. A count is the + /// only way to observe an ack that removed nothing (an id already gone), which a bare + /// reading cannot distinguish from "the fold never ran". + public int RemoveCallCount + { + get + { + lock (_gate) + { + return _removeCalls; + } + } + } + /// Drop-oldest capacity; 0 means unbounded. /// /// When true, genuinely yields before recording the entry — @@ -1701,6 +1796,7 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit { lock (_gate) { + _removeCalls++; int idx = _entries.FindIndex(e => e.Id == id); if (idx >= 0) {