dohertj2/ScadaBridge
1
0
Fork 0
Code Issues 2 Pull Requests Actions Packages Projects Releases Wiki Activity

Scripts: WriteBatchAndWaitAsync handshake fast-paths on the previous run's cached CompleteFlag (MesMoveOut returns stale BatchID/result) #36

New Issue
Open
opened 2026-09-10 14:17:35 -04:00 by dohertj2 · 1 comment
dohertj2 commented 2026-09-10 14:17:35 -04:00
Owner
Copy Link
Copy Source

Summary

WriteBatchAndWaitAsync(values, "MoveOutFlag", true, "MoveOutCompleteFlag", true, 25s) can be satisfied instantly by the previous run's cached True on the response attribute. The script resets MoveOutCompleteFlag = false immediately before the call, but that write has not echoed back from the device yet, so the event-driven wait fast-paths on the stale value. The script then reads MoveOutSuccessfulFlag / MoveOutBatchID / MoveOutErrorText before the Galaxy receiver has processed the request, and returns whatever the receiver last reported.

Observed on QA (vq03/vq04, build 2b9a7c3c), instance Z28061, CvdReactor MesMoveOut (template script 14) and MesMoveIn (13). The same pattern exists in the base MESReceiver.MoveIn / MoveOut scripts (15, 16, 25, 26, 37, 38) and in MesSampleData (36).

Evidence (all UTC, 2026-09-10)

Run Root execution AttributeWait on MoveOutCompleteFlag Script result What Galaxy actually did
17:49:50 3c85cc1f-825f-481c-9e15-316eb29ef4c3 matched in 0 ms, 16 ms after the script wrote it False WasSuccessful:true, BatchID:28944 ended BT batch 28944 at 17:49:51.48 (happened to finish inside the 1 s delay)
18:02:30 b3dd07f2-8ec6-4987-ab44-c474065263b1 matched in 0 ms WasSuccessful:false, ErrorText:"" wrote MoveOutErrorText = "Error updating database : Machine batch not found" at 18:02:31.144, CompleteFlag at 18:02:31.16 — after the script's read
18:03:58 (MoveIn) 6e15783d-1e61-4713-97e0-870013e710c3 matched in 0 ms BatchID:28944 (stale) created batch 28950 at 18:03:59.65
18:04:24 cd5c3bfa-dd10-4e00-9dc9-a1e21c2ddcf6 matched in 0 ms WasSuccessful:false, ErrorText:"" ended batch 28950 successfully; SuccessfulFlag = True at 18:04:25.154, script read at ~18:04:25.19
18:08:09 (patched script) 81db04ad-8c06-4d18-8d20-ccb5597c8279 reset-echo wait 207 ms, then completion wait 1194 ms WasSuccessful:true, BatchID:28944, Data: 16 rows ended batch 28944 at 18:08:10.85

The Sept 3 MES runs on the same SAPID/container (FBC47A3A…, F800A775…) returned "Machine batch not found" with BatchID:28944 — same signature: the batch id is the receiver's last known value, not confirmation of this request.

The fixed Task.Delay(1000) after the wait masks the race only when the receiver completes inside a second; on QA it completes in roughly 0.4–1.2 s, so the outcome is a coin flip.

Interim mitigation applied on QA (config only, not in the repo)

Template scripts 13 and 14 were edited on the QA central (audit entries after AuditLogEntries 383) to add, right after rx.Attributes["<X>CompleteFlag"] = false;:

if (!await rx.Attributes.WaitAsync("<X>CompleteFlag", false, System.TimeSpan.FromSeconds(10)))
    return new { WasSuccessful=false, ErrorText="Timeout waiting for <X>CompleteFlag to reset", BatchID=0, ... };

With that in place the completion wait observed a real edge (see the last row above). Z28061 redeployed as deployment record 110.

Proposed follow-up

  1. Runtime: give WriteBatchAndWaitAsync (and WaitAsync when used as a handshake) an edge-triggered option — e.g. waitForTransition: true / an explicit "arm after the reset echo" step — so a handshake wait cannot fast-path on the pre-existing cached value. Alternatively make WriteBatchAndWaitAsync accept a reset key/value it writes and waits for before writing the trigger.
  2. Scripts: port the reset-echo wait into the checked-in template scripts / receiver templates (base MESReceiver.MoveIn/MoveOut, CvdReactor MesMoveIn/MesMoveOut/MesSampleData) so the fix is not QA-config-only, and replace the fixed Task.Delay(1000) with a wait on the result attributes where possible.
  3. Test: a ScopeAccessors/ScriptRuntimeContext test that writes false, leaves the cache at true (no device echo yet) and asserts the handshake wait does not match until the echo arrives.

Related: the same session found the QA site had never received a system-artifact deployment (no BTDB definition on the site), which is why the dbo.MachineCycle read in MesMoveOut failed silently before today; that was fixed operationally with deploy artifacts --site-id 2 and is not part of this issue.

Implementation and remaining deployment gates (2026-10-13)

The runtime reset-echo overload is already implemented on main (b623fdb0). Fresh rebuilt hermetic HandshakeResetEchoTests verification passed all three cases: legacy cached-true behavior; reset echo before fresh completion; reset timeout. The earlier no-build invocation matched no tests and is not verification evidence.

This issue remains open for the database-owned script rollout: deploy the supporting runtime then port/compile the reset-echo calls in QA and production scripts 13, 14, 36 and receiver scripts 15, 16, 25, 26, 37, 38. Deployment register row119 is in docs/plans/2026-09-10-handshake-reset-echo.md. No database script writes or deployments occurred in this run. Historical live OPC UA rig evidence remains historical; these three cases used local fakes.

## Summary `WriteBatchAndWaitAsync(values, "MoveOutFlag", true, "MoveOutCompleteFlag", true, 25s)` can be satisfied instantly by the **previous run's cached `True`** on the response attribute. The script resets `MoveOutCompleteFlag = false` immediately before the call, but that write has not echoed back from the device yet, so the event-driven wait fast-paths on the stale value. The script then reads `MoveOutSuccessfulFlag` / `MoveOutBatchID` / `MoveOutErrorText` before the Galaxy receiver has processed the request, and returns whatever the receiver last reported. Observed on QA (vq03/vq04, build `2b9a7c3c`), instance Z28061, CvdReactor `MesMoveOut` (template script 14) and `MesMoveIn` (13). The same pattern exists in the base `MESReceiver.MoveIn` / `MoveOut` scripts (15, 16, 25, 26, 37, 38) and in `MesSampleData` (36). ## Evidence (all UTC, 2026-09-10) | Run | Root execution | AttributeWait on `MoveOutCompleteFlag` | Script result | What Galaxy actually did | |---|---|---|---|---| | 17:49:50 | `3c85cc1f-825f-481c-9e15-316eb29ef4c3` | matched in **0 ms**, 16 ms after the script wrote it `False` | `WasSuccessful:true, BatchID:28944` | ended BT batch 28944 at 17:49:51.48 (happened to finish inside the 1 s delay) | | 18:02:30 | `b3dd07f2-8ec6-4987-ab44-c474065263b1` | matched in **0 ms** | `WasSuccessful:false, ErrorText:""` | wrote `MoveOutErrorText = "Error updating database : Machine batch not found"` at 18:02:31.144, `CompleteFlag` at 18:02:31.16 — after the script's read | | 18:03:58 (MoveIn) | `6e15783d-1e61-4713-97e0-870013e710c3` | matched in **0 ms** | `BatchID:28944` (stale) | created batch **28950** at 18:03:59.65 | | 18:04:24 | `cd5c3bfa-dd10-4e00-9dc9-a1e21c2ddcf6` | matched in **0 ms** | `WasSuccessful:false, ErrorText:""` | ended batch 28950 successfully; `SuccessfulFlag = True` at 18:04:25.154, script read at ~18:04:25.19 | | 18:08:09 (patched script) | `81db04ad-8c06-4d18-8d20-ccb5597c8279` | reset-echo wait **207 ms**, then completion wait **1194 ms** | `WasSuccessful:true, BatchID:28944, Data: 16 rows` | ended batch 28944 at 18:08:10.85 | The Sept 3 MES runs on the same SAPID/container (`FBC47A3A…`, `F800A775…`) returned `"Machine batch not found"` with `BatchID:28944` — same signature: the batch id is the receiver's last known value, not confirmation of this request. The fixed `Task.Delay(1000)` after the wait masks the race only when the receiver completes inside a second; on QA it completes in roughly 0.4–1.2 s, so the outcome is a coin flip. ## Interim mitigation applied on QA (config only, not in the repo) Template scripts 13 and 14 were edited on the QA central (audit entries after `AuditLogEntries` 383) to add, right after `rx.Attributes["<X>CompleteFlag"] = false;`: ```csharp if (!await rx.Attributes.WaitAsync("<X>CompleteFlag", false, System.TimeSpan.FromSeconds(10))) return new { WasSuccessful=false, ErrorText="Timeout waiting for <X>CompleteFlag to reset", BatchID=0, ... }; ``` With that in place the completion wait observed a real edge (see the last row above). Z28061 redeployed as deployment record 110. ## Proposed follow-up 1. **Runtime:** give `WriteBatchAndWaitAsync` (and `WaitAsync` when used as a handshake) an edge-triggered option — e.g. `waitForTransition: true` / an explicit "arm after the reset echo" step — so a handshake wait cannot fast-path on the pre-existing cached value. Alternatively make `WriteBatchAndWaitAsync` accept a reset key/value it writes and waits for before writing the trigger. 2. **Scripts:** port the reset-echo wait into the checked-in template scripts / receiver templates (base `MESReceiver.MoveIn`/`MoveOut`, CvdReactor `MesMoveIn`/`MesMoveOut`/`MesSampleData`) so the fix is not QA-config-only, and replace the fixed `Task.Delay(1000)` with a wait on the result attributes where possible. 3. **Test:** a `ScopeAccessors`/`ScriptRuntimeContext` test that writes `false`, leaves the cache at `true` (no device echo yet) and asserts the handshake wait does **not** match until the echo arrives. Related: the same session found the QA site had never received a system-artifact deployment (no `BTDB` definition on the site), which is why the `dbo.MachineCycle` read in `MesMoveOut` failed silently before today; that was fixed operationally with `deploy artifacts --site-id 2` and is not part of this issue. ## Implementation and remaining deployment gates (2026-10-13) The runtime reset-echo overload is already implemented on main (b623fdb0). Fresh rebuilt hermetic HandshakeResetEchoTests verification passed all three cases: legacy cached-true behavior; reset echo before fresh completion; reset timeout. The earlier no-build invocation matched no tests and is not verification evidence. This issue remains open for the database-owned script rollout: deploy the supporting runtime then port/compile the reset-echo calls in QA and production scripts 13, 14, 36 and receiver scripts 15, 16, 25, 26, 37, 38. Deployment register row119 is in docs/plans/2026-09-10-handshake-reset-echo.md. No database script writes or deployments occurred in this run. Historical live OPC UA rig evidence remains historical; these three cases used local fakes.
dohertj2 commented 2026-09-10 15:54:26 -04:00
Author
Owner
Copy Link
Copy Source

Runtime fix landed on local main @ 31b1b8db (16 commits, NOT pushed yet; QA/prod scripts deliberately untouched).

  • New reset-aware overload: Attributes.WriteBatchAndWaitAsync(values, flagKey, flagValue, responseKey, responseValue, timeout, resetKey, resetValue, resetTimeout?) -> HandshakeResult { Matched, Value, Quality, TimedOut, Phase (Reset|Response), ErrorMessage, ResetFailed }. It writes the reset, waits event-driven for the device to ECHO it, and only then writes batch + trigger and waits for the response. A null resetValue throws before any write. The two waits are additive (size ExecutionTimeoutSeconds above resetTimeout + timeout).
  • Edge-triggered wait rejected (design §2): a subscription reports changes from the last reported value, so a device flipping reset->done inside one sampling interval never reports the reset and such a wait never resolves. The reset must be observed before the trigger is written.
  • Composition only (ScriptRuntimeContext.WriteBatchResetAndWait over the existing legs); no InstanceActor/message/proto change. Mirrored on ScriptCompileSurface, SandboxScriptHost, FlowShapePredictor.
  • Tests: HandshakeResetEchoTests pins the stale-cache case over the real InstanceActor + DCL probe (legacy overload fast-paths; reset-aware one holds the batch until the echo). SiteRuntime 806 / ScriptAnalysis 83 / Commons 853 / CentralUI ScriptAnalysis 85 green.
  • Rig live gate docker/seed-handshake-demo.sh: two consecutive runs both Matched=true Phase=Response; on run 2 (cache holding run 1's True) the reset-echo wait held 751 ms before the trigger went out. Design doc §10.
  • Found on the way: data-sourced SCALAR writes reach OPC UA as String variants -> BadTypeMismatch on any non-String node (register row 120; MxGateway path unaffected).

Remaining for this issue: port QA/prod MES scripts 13/14/15/16/25/26/36/37/38 onto the overload and drop the Task.Delay(1000) — deferred-work register row 119 (needs this build on the target central + sites first). Design: docs/plans/2026-09-10-handshake-reset-echo-design.md

Runtime fix landed on local main @ 31b1b8db (16 commits, NOT pushed yet; QA/prod scripts deliberately untouched). - New reset-aware overload: Attributes.WriteBatchAndWaitAsync(values, flagKey, flagValue, responseKey, responseValue, timeout, resetKey, resetValue, resetTimeout?) -> HandshakeResult { Matched, Value, Quality, TimedOut, Phase (Reset|Response), ErrorMessage, ResetFailed }. It writes the reset, waits event-driven for the device to ECHO it, and only then writes batch + trigger and waits for the response. A null resetValue throws before any write. The two waits are additive (size ExecutionTimeoutSeconds above resetTimeout + timeout). - Edge-triggered wait rejected (design §2): a subscription reports changes from the last reported value, so a device flipping reset->done inside one sampling interval never reports the reset and such a wait never resolves. The reset must be observed before the trigger is written. - Composition only (ScriptRuntimeContext.WriteBatchResetAndWait over the existing legs); no InstanceActor/message/proto change. Mirrored on ScriptCompileSurface, SandboxScriptHost, FlowShapePredictor. - Tests: HandshakeResetEchoTests pins the stale-cache case over the real InstanceActor + DCL probe (legacy overload fast-paths; reset-aware one holds the batch until the echo). SiteRuntime 806 / ScriptAnalysis 83 / Commons 853 / CentralUI ScriptAnalysis 85 green. - Rig live gate docker/seed-handshake-demo.sh: two consecutive runs both Matched=true Phase=Response; on run 2 (cache holding run 1's True) the reset-echo wait held 751 ms before the trigger went out. Design doc §10. - Found on the way: data-sourced SCALAR writes reach OPC UA as String variants -> BadTypeMismatch on any non-String node (register row 120; MxGateway path unaffected). Remaining for this issue: port QA/prod MES scripts 13/14/15/16/25/26/36/37/38 onto the overload and drop the Task.Delay(1000) — deferred-work register row 119 (needs this build on the target central + sites first). Design: docs/plans/2026-09-10-handshake-reset-echo-design.md
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
No items
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
dohertj2 (dohertj2)
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dohertj2/ScadaBridge#36
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?