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

Planned stop of the Primary takes 30 s: host waits for the peer's open LocalDb sync stream before Akka leaves (failover delayed) #906

New Issue
Closed
opened 2026-11-13 03:14:48 -05:00 by dohertj2 · 2 comments
dohertj2 commented 2026-11-13 03:14:48 -05:00
Owner
Copy Link
Copy Source

Seen on QA 2026-11-13 during the lmxopcua#780 ScriptedAlarm-seam rolling restart (c9640f5c).

Restart-Service OtOpcUaHost on the Primary vq04 at 08:07:21Z took about 30 s to stop. Until it stopped, the Secondary vq03 stayed at ServiceLevel 240 with /health/active 503 (sampled every ~4 s), and moved to 250 only at about 08:07:52Z.

vq04 log (EST):

  • 03:07:21.289 Application is shutting down...
  • 30 s with nothing but the periodic DbCommand lines;
  • 03:07:51.292 Error reading message. System.IO.IOException: The request stream was aborted.;
  • 03:07:51.293 HTTP POST /localdb_sync.v1.LocalDbSync/Sync responded 200 in 76909.9139 ms;
  • 03:07:51.302 CoordinatedShutdown invoked …, then Leaving, OldestChanged → vq03, singleton hand-over done at 03:07:52.

So the host waits for the peer's open LocalDb sync stream (vq03 is the sync client, LocalDb__Replication__PeerAddress) until Kestrel's graceful-shutdown timeout (the 30 s default) aborts it. Only then does Akka CoordinatedShutdown run and leave the cluster. During those 30 s the stopping Primary still holds the Primary role and keeps the Secondary at 240.

The sync client side stops fast: vq03 restarted at 08:06:30Z and was ready again in 10 s. That explains why the 2026-11-13 failover gate, which stopped vq03, saw a 1 s stop, while today's stop of vq04 took 30 s.

Not checked: whether vq04 still answered OPC UA reads in that window. The OPC UA endpoint may already have been stopping, which would leave the pair with no node at 250 for about 30 s on a planned stop of the Primary.

Possible fixes:

  • complete or cancel the long-lived LocalDbSync/Sync streams on ApplicationStopping, through a token the service observes;
  • or run the Akka leave before the Kestrel drain;
  • or lower the HostOptions.ShutdownTimeout for that endpoint.

The stream belongs to the ZB.MOM.WW.LocalDb.Replication sync service hosted in OtOpcUa (scadaproj LocalDb lib). ScadaBridge's site pairs may show the same thing.

Record: docs/deploy/2026-11-13-780-scriptedalarm-qa-and-vd03-flip.md.

Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi

**Seen on QA 2026-11-13 during the lmxopcua#780 ScriptedAlarm-seam rolling restart (c9640f5c).** `Restart-Service OtOpcUaHost` on the **Primary** vq04 at 08:07:21Z took about **30 s to stop**. Until it stopped, the Secondary vq03 stayed at ServiceLevel **240** with `/health/active` 503 (sampled every ~4 s), and moved to 250 only at about 08:07:52Z. vq04 log (EST): - `03:07:21.289 Application is shutting down...` - 30 s with nothing but the periodic DbCommand lines; - `03:07:51.292 Error reading message. System.IO.IOException: The request stream was aborted.`; - `03:07:51.293 HTTP POST /localdb_sync.v1.LocalDbSync/Sync responded 200 in 76909.9139 ms`; - `03:07:51.302 CoordinatedShutdown invoked …`, then `Leaving`, OldestChanged → vq03, singleton hand-over done at 03:07:52. So the host waits for the peer's **open LocalDb sync stream** (vq03 is the sync client, `LocalDb__Replication__PeerAddress`) until Kestrel's graceful-shutdown timeout (the 30 s default) aborts it. Only then does Akka `CoordinatedShutdown` run and leave the cluster. During those 30 s the stopping Primary still holds the Primary role and keeps the Secondary at 240. The sync **client** side stops fast: vq03 restarted at 08:06:30Z and was ready again in 10 s. That explains why the 2026-11-13 failover gate, which stopped vq03, saw a 1 s stop, while today's stop of vq04 took 30 s. **Not checked:** whether vq04 still answered OPC UA reads in that window. The OPC UA endpoint may already have been stopping, which would leave the pair with **no node at 250 for about 30 s** on a planned stop of the Primary. **Possible fixes:** - complete or cancel the long-lived `LocalDbSync/Sync` streams on `ApplicationStopping`, through a token the service observes; - or run the Akka leave before the Kestrel drain; - or lower the `HostOptions.ShutdownTimeout` for that endpoint. The stream belongs to the `ZB.MOM.WW.LocalDb.Replication` sync service hosted in OtOpcUa (scadaproj LocalDb lib). ScadaBridge's site pairs may show the same thing. Record: `docs/deploy/2026-11-13-780-scriptedalarm-qa-and-vd03-flip.md`. Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi
dohertj2 added the type:bugpriority:p2cross-repo labels 2026-11-13 03:14:49 -05:00
dohertj2 commented 2026-11-13 03:34:35 -05:00
Author
Owner
Copy Link
Copy Source

Fixed on master dcff5ae9 (OtOpcUa host) + library fix on scadaproj main 3ddb083 (unpublished, follow-up scadaproj#57). No deploy done.

Root cause. Two things combined:

  1. Shutdown order. WebApplication starts the web server after every hosted service the app registers, so it stops it first. Akka.Hosting's StopAsync, which runs CoordinatedShutdown (leave + singleton hand-over), only runs after Kestrel has finished draining.
  2. The drain never finished early. Kestrel waits for open requests up to HostOptions.ShutdownTimeout (30 s default). The peer's /localdb_sync.v1.LocalDbSync/Sync stream never ends on its own. ZB.MOM.WW.LocalDb 0.3.7's LocalDbSyncService observes only context.CancellationToken, and ASP.NET Core cancels that only when Kestrel aborts the request at the end of the drain. Nothing linked ApplicationStopping into it. That matches the vq04 log: 30 s of silence, then "request stream was aborted", then CoordinatedShutdown.

From the hosted-service order, the OPC UA endpoint (OtOpcUaServerHostedService, registered before AddAkka) stops after Akka, so vq04 most likely still served at 250 during the window. The real cost was a 30 s delay in failover on a planned stop.

Fix (OtOpcUa host, dcff5ae9):

  • GracefulClusterLeaveService (IHostedLifecycleService). Its StoppingAsync runs before any hosted service's StopAsync, Kestrel's included. It raises ApplicationStopping (idempotent), then runs and awaits CoordinatedShutdown.Run(ClrExitReason), bounded by the host shutdown token. The node leaves the cluster while Kestrel is still up, so /health/active keeps answering. It deliberately does not call Cluster.Leave: that path ends in ClusterLeavingReason, and Akka.Hosting then sets Environment.ExitCode = -1, so a supervisor would read the planned stop as a crash. Akka.Hosting's own later Run call returns the same completed task.
  • ShutdownStreamCancellationInterceptor, innermost on the shared gRPC pipeline after the auth gates. It gives every client-, server- and duplex-streaming call a context whose token is linked with ApplicationStopping, and refuses new streams Unavailable once stopping has begun. GetHttpContext() is preserved. This also covers the mesh telemetry and command streams.

Library (scadaproj 3ddb083, not published): LocalDbSyncService takes an optional IHostApplicationLifetime, links ApplicationStopping into the stream token and refuses new streams Unavailable while stopping. Wire-compatible. 262/262. Both halves were mutation-killed.

Evidence. These are test measurements, not a docker-dev or box measurement. GracefulStopWithOpenSyncStreamTests uses a real WebApplication, Kestrel h2c, the real MapZbLocalDbSync behind LocalDbSyncAuthInterceptor, a single-member Akka cluster and a real SyncBackgroundService peer holding the stream, with an 8 s drain budget. A wrapped IServer timestamps when the drain begins.

stop cluster member removed Kestrel drain began
without fix (positive control) 8863 ms (= budget) 8841 ms 0 ms
with fix 895 ms 892 ms 894 ms

With production's 30 s budget, the "without" row is the QA 30 s.

Mutations:

  • StoppingAsync does not run CoordinatedShutdown: the order assertion fails (drain at 1 ms, removed at 893 ms).
  • The interceptor passes the original context: stop 8006 ms, fails.

Tests. Release solution build: 0 warnings. Host.Tests 288/288. Host.IntegrationTests 339/342 with 2 skipped and 1 failure: FailoverDuringDeployTests.Deployment_started_with_node_b_down_does_not_seal_without_it. It passed 3/3 in isolation, and its TwoNodeClusterHarness uses neither new component (no gRPC pipeline, no leave service), so I'm treating it as a load flake. After rebase: the LocalDb, MeshGrpc and #906 filter passed 114/114.

ScadaBridge has the same exposure on site pairs. It maps MapZbLocalDbSync() and cancels only its own SiteStreamGrpcServer streams on ApplicationStopping, and Kestrel stops before its AkkaHostedService. Not changed and not measured; tracked in scadaproj#57.

Closing: the OtOpcUa fix is complete on its own. The library publish and pins are in scadaproj#57, and the fix takes effect on DEV/QA at the next OtOpcUa deploy.

Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi

**Fixed on `master` `dcff5ae9`** (OtOpcUa host) + library fix on scadaproj `main` `3ddb083` (unpublished, follow-up scadaproj#57). No deploy done. **Root cause.** Two things combined: 1. **Shutdown order.** `WebApplication` starts the web server after every hosted service the app registers, so it **stops it first**. Akka.Hosting's `StopAsync`, which runs `CoordinatedShutdown` (leave + singleton hand-over), only runs after Kestrel has finished draining. 2. **The drain never finished early.** Kestrel waits for open requests up to `HostOptions.ShutdownTimeout` (30 s default). The peer's `/localdb_sync.v1.LocalDbSync/Sync` stream never ends on its own. `ZB.MOM.WW.LocalDb` 0.3.7's `LocalDbSyncService` observes only `context.CancellationToken`, and ASP.NET Core cancels that only when Kestrel aborts the request at the **end** of the drain. Nothing linked `ApplicationStopping` into it. That matches the vq04 log: 30 s of silence, then "request stream was aborted", then CoordinatedShutdown. From the hosted-service order, the OPC UA endpoint (`OtOpcUaServerHostedService`, registered before `AddAkka`) stops **after** Akka, so vq04 most likely still served at 250 during the window. The real cost was a 30 s delay in failover on a planned stop. **Fix (OtOpcUa host, `dcff5ae9`):** - `GracefulClusterLeaveService` (`IHostedLifecycleService`). Its `StoppingAsync` runs before **any** hosted service's `StopAsync`, Kestrel's included. It raises `ApplicationStopping` (idempotent), then runs and awaits `CoordinatedShutdown.Run(ClrExitReason)`, bounded by the host shutdown token. The node leaves the cluster while Kestrel is still up, so `/health/active` keeps answering. It deliberately does not call `Cluster.Leave`: that path ends in `ClusterLeavingReason`, and Akka.Hosting then sets `Environment.ExitCode = -1`, so a supervisor would read the planned stop as a crash. Akka.Hosting's own later `Run` call returns the same completed task. - `ShutdownStreamCancellationInterceptor`, innermost on the shared gRPC pipeline after the auth gates. It gives every client-, server- and duplex-streaming call a context whose token is linked with `ApplicationStopping`, and refuses new streams `Unavailable` once stopping has begun. `GetHttpContext()` is preserved. This also covers the mesh telemetry and command streams. **Library (scadaproj `3ddb083`, not published):** `LocalDbSyncService` takes an optional `IHostApplicationLifetime`, links `ApplicationStopping` into the stream token and refuses new streams `Unavailable` while stopping. Wire-compatible. 262/262. Both halves were mutation-killed. **Evidence.** These are test measurements, not a docker-dev or box measurement. `GracefulStopWithOpenSyncStreamTests` uses a real `WebApplication`, Kestrel h2c, the real `MapZbLocalDbSync` behind `LocalDbSyncAuthInterceptor`, a single-member Akka cluster and a real `SyncBackgroundService` peer holding the stream, with an 8 s drain budget. A wrapped `IServer` timestamps when the drain begins. | | stop | cluster member removed | Kestrel drain began | |---|---|---|---| | without fix (positive control) | **8863 ms** (= budget) | 8841 ms | 0 ms | | with fix | **895 ms** | 892 ms | 894 ms | With production's 30 s budget, the "without" row is the QA 30 s. Mutations: - `StoppingAsync` does not run CoordinatedShutdown: the order assertion fails (drain at 1 ms, removed at 893 ms). - The interceptor passes the original context: stop 8006 ms, fails. **Tests.** Release solution build: 0 warnings. `Host.Tests` 288/288. `Host.IntegrationTests` 339/342 with 2 skipped and 1 failure: `FailoverDuringDeployTests.Deployment_started_with_node_b_down_does_not_seal_without_it`. It passed 3/3 in isolation, and its `TwoNodeClusterHarness` uses neither new component (no gRPC pipeline, no leave service), so I'm treating it as a load flake. After rebase: the LocalDb, MeshGrpc and #906 filter passed 114/114. **ScadaBridge** has the same exposure on site pairs. It maps `MapZbLocalDbSync()` and cancels only its own `SiteStreamGrpcServer` streams on `ApplicationStopping`, and Kestrel stops before its `AkkaHostedService`. Not changed and not measured; tracked in scadaproj#57. Closing: the OtOpcUa fix is complete on its own. The library publish and pins are in scadaproj#57, and the fix takes effect on DEV/QA at the next OtOpcUa deploy. Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi
dohertj2 commented 2026-11-13 07:53:50 -05:00
Author
Owner
Copy Link
Copy Source

Deployed and proven on the QA pair, 2026-11-13. Master 76e73e7d: the host graceful leave plus LocalDb 0.3.8. Record: docs/deploy/2026-11-13-vd03-qa-to-76e73e7d.md (5baf05f6).

Before vs after on the same node. vq04 is the LocalDb sync server, and vq03 holds its stream open.

Before: c9640f5c, the window's stop of vq04, 12:35Z After: 76e73e7d, leg 2, vq04 Primary, 12:44Z
Application is shutting down → Leaving 30.0 s: 07:35:26.975 → LocalDbSync/Sync responded 200 07:35:56.989 → Leaving 07:35:57.020 local 21 ms: 07:44:07.479 → Sync responded 200 .480 → Host stopping: leaving the Akka cluster before the web server drains its open requests (lmxopcua#906). .483 → Leaving .500 → Akka CoordinatedShutdown completed in 236 ms
Stop-Service 30.1 s 5.7 s
Peer at ServiceLevel 250 ~31 s (#780 record) 0.47 s (vq03 subscription), /health/active 200 on the first 0.5 s sample

Leg 1 (stop vq03, the sync client, while Primary): #906 line, CoordinatedShutdown 647 ms, vq04 at 250 in 0.36 s.

Both legs:

  • no SCM recovery restart; the restarted node came back at 240 with no failback;
  • localdb-replication connected with backlog 0 afterwards;
  • canary Good on both endpoints.

Note. Stop-Service is ~6 s rather than 1–3 s. After the leave, the log shows ~5 s ending in SERVER - Service Fault Occurred. Reason=BadTimeout. This is most likely the OPC UA stack closing the gate's own open subscription session. It does not delay the hand-over.

Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi

**Deployed and proven** on the QA pair, 2026-11-13. Master `76e73e7d`: the host graceful leave plus LocalDb 0.3.8. Record: `docs/deploy/2026-11-13-vd03-qa-to-76e73e7d.md` (`5baf05f6`). **Before vs after on the same node.** vq04 is the LocalDb sync server, and vq03 holds its stream open. | | Before: `c9640f5c`, the window's stop of vq04, 12:35Z | After: `76e73e7d`, leg 2, vq04 Primary, 12:44Z | |---|---|---| | `Application is shutting down` → `Leaving` | **30.0 s**: 07:35:26.975 → `LocalDbSync/Sync responded 200` 07:35:56.989 → `Leaving` 07:35:57.020 local | **21 ms**: 07:44:07.479 → `Sync responded 200` .480 → `Host stopping: leaving the Akka cluster before the web server drains its open requests (lmxopcua#906).` .483 → `Leaving` .500 → `Akka CoordinatedShutdown completed in 236 ms` | | `Stop-Service` | 30.1 s | 5.7 s | | Peer at ServiceLevel 250 | ~31 s (#780 record) | **0.47 s** (vq03 subscription), `/health/active` 200 on the first 0.5 s sample | **Leg 1** (stop vq03, the sync client, while Primary): `#906` line, CoordinatedShutdown 647 ms, **vq04 at 250 in 0.36 s**. Both legs: - no SCM recovery restart; the restarted node came back at 240 with **no failback**; - `localdb-replication` connected with backlog 0 afterwards; - canary Good on both endpoints. **Note.** `Stop-Service` is ~6 s rather than 1–3 s. After the leave, the log shows ~5 s ending in `SERVER - Service Fault Occurred. Reason=BadTimeout`. This is most likely the OPC UA stack closing the gate's own open subscription session. It does not delay the hand-over. Claude-Session: https://claude.ai/code/session_01GT67ACmpMR7b9LGRPLijMi
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
auto-managed
queue management
 blocked
Blocked by dependency or external hold
 cross-driver
queue management
 cross-repo
Needs coordinated change in another family repo (wire contract etc.)
 driver/abcip
queue management
 driver/ablegacy
queue management
 driver/focas
queue management
 driver/mqtt
MQTT / Sparkplug B broker-subscribe driver
 driver/opcuaclient
queue management
 driver/s7
queue management
 driver/twincat
queue management
 migrated
Migrated from a markdown backlog (2026-11 standardization)
 phase/1
queue management
 phase/2
queue management
 phase/3
queue management
 phase/4
queue management
 phase/5
queue management
 phase/6
queue management
 priority:p0
Must-have / blocking
 priority:p1
High priority
 priority:p2
Normal priority
 priority:p3
Low priority / nice to have
 queue/blocked
queue management
 queue/done
queue management
 queue/failed
queue management
 queue/in-progress
queue management
 queue/queued
queue management
 type:bug
Defect in shipped behaviour
 type:debt
Technical debt / hygiene
 type:deploy-gate
Rollout/deploy/migration step not yet done on an environment
 type:docs
Documentation work
 type:feature
Feature implementation
 type:followup
Follow-up deferred from a plan, PR or gate
 type:infra
Infrastructure and scaffolding
 type:review-finding
Unfixed finding from an architecture/code review
 type:test
Test work
No Label cross-repo priority:p2 type:bug
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#906
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?