dohertj2/lmxopcua
1
0
Fork 0
Code Issues 8 Pull Requests Actions Packages Projects Releases Wiki Activity

Transient ConfigDb error during artifact load empties the served address space (logs claim "rebuild becomes no-op") #485

New Issue
Closed
opened 2026-07-21 02:17:26 -04:00 by dohertj2 · 3 comments
dohertj2 commented 2026-07-21 02:17:26 -04:00
Owner
Copy Link
Copy Source

Summary

When OpcUaPublishActor.LoadArtifact fails on a transient ConfigDb error, the node removes its entire served address space while logging that the rebuild became a no-op. The two statements disagree, and the destructive one wins.

Observed on the docker-dev rig while driving the LocalDb follow-up live gate (SQL Server was stopped and restarted to exercise boot-from-cache). Node site-b-1 took a deploy whose artifact load raced the recovering SQL connection:

[06:11:20 ERR] An error occurred using the connection to database 'OtOpcUa' on server 'sql,1433'.
[06:11:20 WRN] DriverHost site-b-1:4053: failed to load artifact for SubscribeBulk (43d54397cb1548d5b4d878351b0296a0)
[06:11:20 WRN] DriverHost site-b-1:4053: not caching deployment 43d54397cb1548d5b4d878351b0296a0 — its artifact was empty or could not be loaded, so it is not a usable last-known-good configuration.
[06:11:20 ERR] An error occurred using the connection to database 'OtOpcUa' on server 'sql,1433'.
[06:11:20 WRN] OpcUaPublish: failed to load artifact for deployment 43d54397cb1548d5b4d878351b0296a0; rebuild becomes no-op
[06:11:20 INF] AddressSpaceApplier: applied plan (kind=PureRemove, added=0, removed=16, changed=0, surgicalTags=0, renamedFolders=0, rebuild=True)
[06:11:20 INF] OpcUaPublish: applied rebuild (correlation=715d246efd1744f4b6354998f77ea214, added=0, removed=16, changed=0, rebuild=True)

A client browsing that node between the failure and the next restart sees an empty address space, with no error to distinguish "this node has no tags" from "this node lost its configuration to a database blip".

What behaved correctly

  • The LocalDb cache layer refused to store the bad artifact — not caching deployment … not a usable last-known-good configuration. The cache is not poisoned, and boot-from-cache still serves the previous good configuration.
  • The node recovers fully on restart (raw subtree materialised (containers=16, …)), so this is transient rather than permanent.

Expected

An artifact that could not be loaded should leave the currently-served address space untouched (hold last-known-good and surface the failure), not compute a PureRemove plan against an empty artifact. That is what the rebuild becomes no-op log already claims is happening — the log and the behaviour should be made to agree, in the log's favour.

Notes

  • Same failure class as the LocalDb Phase 1 live-gate check-3 defect (9137cb41), where a cache-booted node logged success but served 1 node instead of 16: an empty/failed artifact read being treated as a legitimate empty configuration.
  • Pre-existing, and unrelated to the LocalDb follow-up work that surfaced it — site-b-1 has replication switched off entirely. It was induced by that gate's deliberate SQL flapping.
  • Worth checking whether SubscribeBulk's own failed to load artifact path has the same shape (drivers unsubscribed on a transient DB error).

Reproduction sketch

  1. Bring up docker-dev, deploy, confirm a node serves its raw subtree.
  2. docker stop otopcua-dev-sql-1, then docker start it.
  3. Immediately POST :9200/api/deployments (with X-Api-Key: docker-dev-deploy-key) so a driver node applies while its EF connection is still recovering.
  4. Browse that node: the address space is empty until it is restarted.

Evidence recorded in docs/plans/2026-07-21-localdb-followups-live-gate.md ("Unrelated finding").

## Summary When `OpcUaPublishActor.LoadArtifact` fails on a transient ConfigDb error, the node **removes its entire served address space** while logging that the rebuild became a no-op. The two statements disagree, and the destructive one wins. Observed on the `docker-dev` rig while driving the LocalDb follow-up live gate (SQL Server was stopped and restarted to exercise boot-from-cache). Node `site-b-1` took a deploy whose artifact load raced the recovering SQL connection: ``` [06:11:20 ERR] An error occurred using the connection to database 'OtOpcUa' on server 'sql,1433'. [06:11:20 WRN] DriverHost site-b-1:4053: failed to load artifact for SubscribeBulk (43d54397cb1548d5b4d878351b0296a0) [06:11:20 WRN] DriverHost site-b-1:4053: not caching deployment 43d54397cb1548d5b4d878351b0296a0 — its artifact was empty or could not be loaded, so it is not a usable last-known-good configuration. [06:11:20 ERR] An error occurred using the connection to database 'OtOpcUa' on server 'sql,1433'. [06:11:20 WRN] OpcUaPublish: failed to load artifact for deployment 43d54397cb1548d5b4d878351b0296a0; rebuild becomes no-op [06:11:20 INF] AddressSpaceApplier: applied plan (kind=PureRemove, added=0, removed=16, changed=0, surgicalTags=0, renamedFolders=0, rebuild=True) [06:11:20 INF] OpcUaPublish: applied rebuild (correlation=715d246efd1744f4b6354998f77ea214, added=0, removed=16, changed=0, rebuild=True) ``` A client browsing that node between the failure and the next restart sees an **empty address space**, with no error to distinguish "this node has no tags" from "this node lost its configuration to a database blip". ## What behaved correctly - The **LocalDb cache layer refused to store the bad artifact** — `not caching deployment … not a usable last-known-good configuration`. The cache is not poisoned, and boot-from-cache still serves the previous good configuration. - The node **recovers fully on restart** (`raw subtree materialised (containers=16, …)`), so this is transient rather than permanent. ## Expected An artifact that could not be loaded should leave the currently-served address space **untouched** (hold last-known-good and surface the failure), not compute a `PureRemove` plan against an empty artifact. That is what the `rebuild becomes no-op` log already claims is happening — the log and the behaviour should be made to agree, in the log's favour. ## Notes - Same failure **class** as the LocalDb Phase 1 live-gate check-3 defect (`9137cb41`), where a cache-booted node logged success but served 1 node instead of 16: an empty/failed artifact read being treated as a legitimate empty configuration. - **Pre-existing**, and unrelated to the LocalDb follow-up work that surfaced it — `site-b-1` has replication switched off entirely. It was induced by that gate's deliberate SQL flapping. - Worth checking whether `SubscribeBulk`'s own `failed to load artifact` path has the same shape (drivers unsubscribed on a transient DB error). ## Reproduction sketch 1. Bring up `docker-dev`, deploy, confirm a node serves its raw subtree. 2. `docker stop otopcua-dev-sql-1`, then `docker start` it. 3. Immediately `POST :9200/api/deployments` (with `X-Api-Key: docker-dev-deploy-key`) so a driver node applies while its EF connection is still recovering. 4. Browse that node: the address space is empty until it is restarted. Evidence recorded in `docs/plans/2026-07-21-localdb-followups-live-gate.md` ("Unrelated finding").
dohertj2 commented 2026-07-21 02:29:59 -04:00
Author
Owner
Copy Link
Copy Source

Fixed on master (c7f5b9cf).

OpcUaPublishActor.HandleRebuild now treats an artifact it could not obtain as no answer rather than an empty configuration, and abandons the rebuild with the served address space — and _lastApplied — intact, so the retry diffs against what is actually materialised.

The reasoning for keying on "zero bytes": nothing legitimate produces a zero-length blob. An operator who really deletes everything still deploys a JSON document with empty arrays, so the only honest reading of no bytes is that the read failed. That also covers the missing-row case, not just the exception the outage produced.

The two situations are now logged differently — a warning when there is a live address space being protected, debug when nothing has been deployed to the node yet — and the loader's own "the rebuild is abandoned" line is finally true.

Tests (OpcUaPublishActorRebuildTests):

  • Rebuild_keeps_the_last_known_good_address_space_when_the_artifact_load_fails — written RED first and verified failing for the right reason (the load error tore down eq-2's subtree). It also asserts the follow-up redeploy of the same composition is an empty-plan no-op, proving _lastApplied survived.
  • Rebuild_still_removes_equipment_a_readable_artifact_genuinely_dropped — positive control: the guard suppresses teardown only when the read failed, not when the config genuinely changed.

Not separately live-gated. The live gate that found this already supplies the production evidence for the seam: its log shows the LoadArtifact catch block firing immediately before the PureRemove, and the guard sits inline on that same path in the same actor — there is no DI wiring or capability interface for it to go inert behind.

Fixed on `master` (`c7f5b9cf`). `OpcUaPublishActor.HandleRebuild` now treats an artifact it could not obtain as **no answer** rather than **an empty configuration**, and abandons the rebuild with the served address space — and `_lastApplied` — intact, so the retry diffs against what is actually materialised. The reasoning for keying on "zero bytes": nothing legitimate produces a zero-length blob. An operator who really deletes everything still deploys a JSON document with empty arrays, so the only honest reading of no bytes is that the read failed. That also covers the missing-row case, not just the exception the outage produced. The two situations are now logged differently — a warning when there is a live address space being protected, debug when nothing has been deployed to the node yet — and the loader's own "the rebuild is abandoned" line is finally true. Tests (`OpcUaPublishActorRebuildTests`): - `Rebuild_keeps_the_last_known_good_address_space_when_the_artifact_load_fails` — written RED first and verified failing for the right reason (the load error tore down `eq-2`'s subtree). It also asserts the follow-up redeploy of the same composition is an empty-plan no-op, proving `_lastApplied` survived. - `Rebuild_still_removes_equipment_a_readable_artifact_genuinely_dropped` — positive control: the guard suppresses teardown only when the read failed, not when the config genuinely changed. Not separately live-gated. The live gate that found this already supplies the production evidence for the seam: its log shows the `LoadArtifact` catch block firing immediately before the `PureRemove`, and the guard sits inline on that same path in the same actor — there is no DI wiring or capability interface for it to go inert behind.
dohertj2 commented 2026-07-21 02:40:30 -04:00
Author
Owner
Copy Link
Copy Source

Driver-side half fixed too, on master (5aad1e33).

The address-space fix exposed an asymmetry: DriverHostActor.ReconcileDrivers and PushDesiredSubscriptionsFromArtifact read the artifact exactly the same way. Their throw paths already returned early, but empty bytes flowed onwards as a real answer — zero driver specs, so DriverSpawnPlanner planned every running child for StopChild, and then an empty desired set dropped each surviving driver's live subscription handle. A node lost its entire field I/O and still ACKed Applied. Left alone, the earlier fix would have produced the worst of both: nodes still served, no values behind them.

Both sites now skip on empty. The two guards are independent, because PushDesiredSubscriptions does its own ConfigDb read and the row can go missing between them. The ReconcileDrivers doc comment claiming an empty blob made it "effectively a no-op" was also corrected — with children running it was the opposite.

Tests (DriverHostActorUnreadableArtifactTests), RED-first and verified failing: after the empty dispatch the driver list came back empty. Seeding a zero-length ArtifactBlob reproduces byte-for-byte what the missing-row case delivers, so the race did not have to be constructed.

Worth recording one thing, because it nearly slipped through. The subscription assertion is an absence (UnsubscribeCount == 0), and the unsubscribe is an async self-tell — so with the second guard deleted the test still went green. It was passing on a race, not on the guard. The fix was a second control that observes that same unsubscribe arriving (dropping a driver's last tag genuinely does clear its subscription), which calibrates the settle window and makes the absence mean something. With the guard deleted the suite now correctly goes RED.

Driver-side half fixed too, on `master` (`5aad1e33`). The address-space fix exposed an asymmetry: `DriverHostActor.ReconcileDrivers` and `PushDesiredSubscriptionsFromArtifact` read the artifact exactly the same way. Their *throw* paths already returned early, but empty bytes flowed onwards as a real answer — zero driver specs, so `DriverSpawnPlanner` planned every running child for `StopChild`, and then an empty desired set dropped each surviving driver's live subscription handle. A node lost its entire field I/O and still ACKed Applied. Left alone, the earlier fix would have produced the worst of both: nodes still served, no values behind them. Both sites now skip on empty. The two guards are independent, because `PushDesiredSubscriptions` does its own ConfigDb read and the row can go missing between them. The `ReconcileDrivers` doc comment claiming an empty blob made it "effectively a no-op" was also corrected — with children running it was the opposite. Tests (`DriverHostActorUnreadableArtifactTests`), RED-first and verified failing: after the empty dispatch the driver list came back empty. Seeding a zero-length `ArtifactBlob` reproduces byte-for-byte what the missing-row case delivers, so the race did not have to be constructed. Worth recording one thing, because it nearly slipped through. The subscription assertion is an *absence* (`UnsubscribeCount == 0`), and the unsubscribe is an async self-tell — so with the second guard deleted the test still went green. It was passing on a race, not on the guard. The fix was a second control that observes that same unsubscribe *arriving* (dropping a driver's last tag genuinely does clear its subscription), which calibrates the settle window and makes the absence mean something. With the guard deleted the suite now correctly goes RED.
dohertj2 commented 2026-07-21 03:02:43 -04:00
Author
Owner
Copy Link
Copy Source

Live-gated on docker-dev — both fixes verified. Full evidence: docs/plans/2026-07-21-issue-485-live-gate.md (master 5627d325).

The RED control was not staged. site-a-1 had hit this exact bug during the previous gate's SQL flapping and had been serving an empty address space for 34 minutes on the pre-fix image — PureRemove, removed=17, browse returning only the root folder. The bug in its natural habitat. Rebuilding on the fixed image restored it to 18 nodes, and the induction then failed to reproduce the teardown.

Since the original trigger was a race, the gate drives the empty-bytes branch instead — byte-for-byte what the code sees when the row cannot be read, and the branch the driver-side guards key on (their throw paths already returned early). docker pause on the target node opens the window deterministically: pause, deploy, blank the blob, unpause. Both runs measured <1s of pause, well inside acceptable-heartbeat-pause = 10s, so no failover was triggered.

All three guards fired in production, on two nodes:

  • no usable artifact for deployment f4b9dd63... — KEEPING the currently served address space rather than tearing it down — no PureRemove; browse before vs after diffs identical (18 = 18, and 22 = 22 on central-2).
  • read back empty; skipping reconcile and keeping the 1 running driver(s) — and keeping the 5 running driver(s) on central-2.
  • read back empty; skipping SubscribeBulk and keeping the live subscriptions.

For the subscription guard the log line is not the proof — the values are. ns=2;s=pymodbus/plc/HR200X read 56278 @ 06:59:51, then 56336 @ 07:00:21 and 56354 @ 07:00:30, with the induction at 07:00:07. Live Modbus data kept arriving straight across the event.

Two controls: a genuine deploy applied normally on both nodes immediately afterwards (AddRemoveMix, SubscribeBulk pushed 5 references across 4 driver(s)), so the guards suppress teardown and not deployment; and of the six nodes exactly one took the guard path — the five unpaused nodes read the real artifact and applied it, confirming the window caused the condition rather than a global change.

One thing the gate surfaced that these fixes do not address, filed as #486: ApplyAndAck advances _currentRevision and writes NodeDeploymentState = Applied before knowing whether anything applied, so a node that skipped reports success for a revision it never applied — and since dispatch short-circuits on a revision match, it cannot self-heal from a re-dispatch. Pre-existing, and reporting-only (the data plane stayed healthy throughout, as the values above show).

**Live-gated on docker-dev — both fixes verified.** Full evidence: `docs/plans/2026-07-21-issue-485-live-gate.md` (master `5627d325`). The RED control was not staged. site-a-1 had hit this exact bug during the *previous* gate's SQL flapping and had been serving an empty address space for 34 minutes on the pre-fix image — `PureRemove, removed=17`, browse returning only the root folder. The bug in its natural habitat. Rebuilding on the fixed image restored it to 18 nodes, and the induction then failed to reproduce the teardown. Since the original trigger was a race, the gate drives the **empty-bytes** branch instead — byte-for-byte what the code sees when the row cannot be read, and the branch the driver-side guards key on (their throw paths already returned early). `docker pause` on the target node opens the window deterministically: pause, deploy, blank the blob, unpause. Both runs measured <1s of pause, well inside `acceptable-heartbeat-pause = 10s`, so no failover was triggered. All three guards fired in production, on two nodes: - `no usable artifact for deployment f4b9dd63... — KEEPING the currently served address space rather than tearing it down` — **no PureRemove**; browse before vs after diffs identical (18 = 18, and 22 = 22 on central-2). - `read back empty; skipping reconcile and keeping the 1 running driver(s)` — and `keeping the 5 running driver(s)` on central-2. - `read back empty; skipping SubscribeBulk and keeping the live subscriptions`. For the subscription guard the log line is not the proof — the values are. `ns=2;s=pymodbus/plc/HR200X` read **56278 @ 06:59:51**, then **56336 @ 07:00:21** and **56354 @ 07:00:30**, with the induction at 07:00:07. Live Modbus data kept arriving straight across the event. Two controls: a genuine deploy applied normally on both nodes immediately afterwards (`AddRemoveMix`, `SubscribeBulk pushed 5 references across 4 driver(s)`), so the guards suppress teardown and not deployment; and of the six nodes exactly one took the guard path — the five unpaused nodes read the real artifact and applied it, confirming the window caused the condition rather than a global change. One thing the gate surfaced that these fixes do **not** address, filed as #486: `ApplyAndAck` advances `_currentRevision` and writes `NodeDeploymentState = Applied` before knowing whether anything applied, so a node that skipped reports success for a revision it never applied — and since dispatch short-circuits on a revision match, it cannot self-heal from a re-dispatch. Pre-existing, and reporting-only (the data plane stayed healthy throughout, as the values above show).
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
auto-managed
queue management
 cross-driver
queue management
 driver/abcip
queue management
 driver/ablegacy
queue management
 driver/focas
queue management
 driver/opcuaclient
queue management
 driver/s7
queue management
 driver/twincat
queue management
 phase/1
queue management
 phase/2
queue management
 phase/3
queue management
 phase/4
queue management
 phase/5
queue management
 phase/6
queue management
 queue/blocked
queue management
 queue/done
queue management
 queue/failed
queue management
 queue/in-progress
queue management
 queue/queued
queue management
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/lmxopcua#485
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?