Restarting pair node advertises ServiceLevel 255 for ~10 s before its first redundancy snapshot (outranks the real Primary) #885

New Issue

2026-11-12T10:23:33-05:00

dohertj2 commented

2026-11-12 10:23:33 -05:00

Found during the #801 pair-behaviour gate on the local docker-dev central pair. The image was #884's fix branch (cc76249a), so the SDK session-headroom overwrite is out of the picture.

Symptom

A pair node that is restarting serves Server.ServiceLevel = 255 from the moment its OPC UA endpoint listens until its first redundancy snapshot arrives. That's about 10–13 s on the rig. During that window it outranks the real Primary (250), so a client that picks the highest ServiceLevel would choose the node that hasn't even joined the cluster yet.

Polling i=2267 once a second while the old Primary (central-2) was docker started after a failover kill:

15:18:46 | c1 wire=240 | c2 [exited]
15:18:48 | c1 wire=240 | c2 wire=255     <- c2 log: 15:18:49 "SDK started, address-space + ServiceLevel sinks bound"
15:18:51 | c1 wire=240 | c2 wire=255
15:18:54 | c1 wire=240 | c2 wire=255
15:18:56 | c1 wire=240 | c2 wire=255
15:18:59 | c1 wire=200 | c2 wire=255     <- c2 log: 15:18:59 "Welcome from central-1" (joined)
15:19:02 | c1 wire=250 | c2 wire=240

(central-1's 240 → 200 → 250 is its own promotion. It passes through the Stale tier for about 3 s while the redundancy-state singleton moves. That's expected.)

Cause

OpcUaPublishActor.RecomputeServiceLevel returns early while _localNode is null || _lastSnapshot is null. Until the node joins and receives the singleton's first RedundancyStateChanged, nothing is published, so the SDK's built-in 255 stands. SDK 2.0.1 also writes 255 explicitly at server init (ServerInternalData, serverObject.ServiceLevel.Value = 255). #719/#720 made a requested level survive the binding race, but no level is requested in this window. docs/Redundancy.md says "a starting or detached node never leaves the SDK default 255". That holds only once a snapshot exists.

The same window happens on every cold start and on a rolling restart of either node. It's most visible after a failover, when the surviving Primary is still at 240/200 and the rejoining node shows 255.

Suggested fix (not done here)

Publish a low "not yet in service" level, for example 0 or the 2–199 degraded band, at SDK binding time when no level has been requested yet. For example, DeferredServiceLevelPublisher.SetInner could replay 0 when it holds no request, or OpcUaPublishActor could publish 0 before the first snapshot. Then cover it with a test that binds with no request and reads i=2267 ≠ 255. This needs #884's claim, or SDK 2's session-headroom logic will lift any value ≥ 200 back to 255. A value below 200 is left alone either way.

Repro

docker-dev, both central nodes healthy.
docker kill otopcua-dev-central-2-1; sleep 20; docker start otopcua-dev-central-2-1.
Poll otopcua-cli read -u opc.tcp://localhost:4841 -n i=2267 every second. It reads 255 until the node logs Welcome from [...central-1...].

Found during the #801 pair-behaviour gate on the local docker-dev central pair. The image was #884's fix branch (`cc76249a`), so the SDK session-headroom overwrite is out of the picture. ## Symptom A pair node that is restarting serves `Server.ServiceLevel = 255` from the moment its OPC UA endpoint listens until its first redundancy snapshot arrives. That's about **10–13 s** on the rig. During that window it **outranks the real Primary (250)**, so a client that picks the highest ServiceLevel would choose the node that hasn't even joined the cluster yet. Polling `i=2267` once a second while the old Primary (central-2) was `docker start`ed after a failover kill: ``` 15:18:46 | c1 wire=240 | c2 [exited] 15:18:48 | c1 wire=240 | c2 wire=255 <- c2 log: 15:18:49 "SDK started, address-space + ServiceLevel sinks bound" 15:18:51 | c1 wire=240 | c2 wire=255 15:18:54 | c1 wire=240 | c2 wire=255 15:18:56 | c1 wire=240 | c2 wire=255 15:18:59 | c1 wire=200 | c2 wire=255 <- c2 log: 15:18:59 "Welcome from central-1" (joined) 15:19:02 | c1 wire=250 | c2 wire=240 ``` (central-1's 240 → 200 → 250 is its own promotion. It passes through the Stale tier for about 3 s while the `redundancy-state` singleton moves. That's expected.) ## Cause `OpcUaPublishActor.RecomputeServiceLevel` returns early while `_localNode is null || _lastSnapshot is null`. Until the node joins and receives the singleton's first `RedundancyStateChanged`, nothing is published, so the SDK's built-in 255 stands. SDK 2.0.1 also writes 255 explicitly at server init (`ServerInternalData`, `serverObject.ServiceLevel.Value = 255`). #719/#720 made a *requested* level survive the binding race, but no level is requested in this window. `docs/Redundancy.md` says "a starting or detached node never leaves the SDK default 255". That holds only once a snapshot exists. The same window happens on every cold start and on a rolling restart of either node. It's most visible after a failover, when the surviving Primary is still at 240/200 and the rejoining node shows 255. ## Suggested fix (not done here) Publish a low "not yet in service" level, for example 0 or the 2–199 degraded band, at SDK binding time when no level has been requested yet. For example, `DeferredServiceLevelPublisher.SetInner` could replay 0 when it holds no request, or `OpcUaPublishActor` could publish 0 before the first snapshot. Then cover it with a test that binds with no request and reads `i=2267` ≠ 255. This needs #884's claim, or SDK 2's session-headroom logic will lift any value ≥ 200 back to 255. A value below 200 is left alone either way. ## Repro 1. docker-dev, both central nodes healthy. 2. `docker kill otopcua-dev-central-2-1; sleep 20; docker start otopcua-dev-central-2-1`. 3. Poll `otopcua-cli read -u opc.tcp://localhost:4841 -n i=2267` every second. It reads 255 until the node logs `Welcome from [...central-1...]`.

dohertj2 added the type:bug priority:p2 labels 2026-11-12 10:23:34 -05:00

dohertj2 referenced this issue

2026-11-12 10:45:14 -05:00

SDK2 live gate: AVEVA history, consumer compatibility and paired-cluster rollout #801

dohertj2 referenced this issue

2026-11-12 11:04:02 -05:00

SDK 2.0.1: Server.ServiceLevel reads 255 on both pair nodes — SDK session-headroom calculator overwrites 250/240/200 (publisher never claims IServerServiceLevelControl) #884

dohertj2 referenced this issue from a commit

2026-11-12 11:11:15 -05:00

fix(redundancy): advertise ServiceLevel 0 until the node has a redundancy level (#885)

dohertj2 commented

2026-11-12 11:20:44 -05:00

Fixed on master in 3fff439b, on top of #884's claim (f66b9dae/5e3fb422).

Fix

OtOpcUaSdkServer now writes StartupServiceLevel = 0 in OnNodeManagerStartedAsync. The decompiled SDK 2.0.1 StandardServer.StartApplicationAsync runs that override after CreateServerObjectAsync has written its 255 and SetSessionManager has run, and before SetServerState(Running). So no session can ever read 255. The SdkServiceLevelPublisher claim (#884) replays whatever level the redundancy layer has already requested when the host binds. If nothing has been requested yet, 0 stands until the first snapshot.

Why 0. It's the design's existing level for this state. docs/Redundancy.md defines Down / Detached as 0, and ServiceLevelCalculator returns 0 for a member that isn't Up/Joining. A node with no redundancy snapshot has no role yet. 0 is also below the SDK 2 session-headroom floor of 200, so the SDK never lifts it, even before the claim.

Single node. The node still settles: its first snapshot publishes 250 exactly as before. The new test covers this, and so does the rig (all three pairs settle, see below).

Test

ServiceLevelBindingReplayTests.Node_with_no_requested_level_advertises_the_startup_level_until_one_is_published checks three stages:

It reads 0 on the first session, before any publisher is bound.
It still reads 0 after a bind with nothing to replay, with session churn under the claim.
It reads 250 once a level is published.

Mutation check: with the startup write disabled, the test fails on the first read, which returns 255.

The existing replay theory's 0 case no longer tells "replayed" apart from "not replayed", so I commented it. The 100 case remains the replay evidence.

Suites: OpcUaServer.Tests 1265/0/1 skipped. OpcUaServer.IntegrationTests 310 passed / 35 skipped / 0 failed. Host.Tests hosted-service + health 44/44.

Rig (docker-dev, image built from `3fff439b`, ACL off)

Polled i=2267 on both central nodes. Each sample opens a fresh session, roughly every 2 s:

Cold start of all six nodes: c1 0 → 100 → 240, c2 110 → 250. No 255 at any point.
Kill the Primary (c2), then docker start it 45 s later: c1 240 → 200 → 250. c2 reads 0 for about 6 s (the old 255 window), then 240. It never reads above 240.
docker restart of the Secondary (c2): 0 → 100 → 240.

Full record on #801.

**Fixed on `master` in `3fff439b`, on top of #884's claim (`f66b9dae`/`5e3fb422`).** ## Fix `OtOpcUaSdkServer` now writes `StartupServiceLevel = 0` in `OnNodeManagerStartedAsync`. The decompiled SDK 2.0.1 `StandardServer.StartApplicationAsync` runs that override after `CreateServerObjectAsync` has written its 255 and `SetSessionManager` has run, and **before** `SetServerState(Running)`. So no session can ever read 255. The `SdkServiceLevelPublisher` claim (#884) replays whatever level the redundancy layer has already requested when the host binds. If nothing has been requested yet, 0 stands until the first snapshot. **Why 0.** It's the design's existing level for this state. `docs/Redundancy.md` defines Down / Detached as 0, and `ServiceLevelCalculator` returns 0 for a member that isn't Up/Joining. A node with no redundancy snapshot has no role yet. 0 is also below the SDK 2 session-headroom floor of 200, so the SDK never lifts it, even before the claim. **Single node.** The node still settles: its first snapshot publishes 250 exactly as before. The new test covers this, and so does the rig (all three pairs settle, see below). ## Test `ServiceLevelBindingReplayTests.Node_with_no_requested_level_advertises_the_startup_level_until_one_is_published` checks three stages: - It reads **0** on the first session, before any publisher is bound. - It still reads **0** after a bind with nothing to replay, with session churn under the claim. - It reads **250** once a level is published. **Mutation check:** with the startup write disabled, the test fails on the first read, which returns 255. The existing replay theory's `0` case no longer tells "replayed" apart from "not replayed", so I commented it. The `100` case remains the replay evidence. **Suites:** `OpcUaServer.Tests` 1265/0/1 skipped. `OpcUaServer.IntegrationTests` 310 passed / 35 skipped / 0 failed. `Host.Tests` hosted-service + health 44/44. ## Rig (docker-dev, image built from `3fff439b`, ACL off) Polled `i=2267` on both central nodes. Each sample opens a fresh session, roughly every 2 s: - **Cold start of all six nodes:** c1 `0 → 100 → 240`, c2 `110 → 250`. No 255 at any point. - **Kill the Primary (c2), then `docker start` it 45 s later:** c1 `240 → 200 → 250`. c2 reads **`0` for about 6 s** (the old 255 window), then `240`. It never reads above 240. - **`docker restart` of the Secondary (c2):** `0 → 100 → 240`. Full record on #801.

dohertj2 closed this issue

2026-11-12 11:20:45 -05:00

dohertj2 referenced this issue

2026-11-12 11:20:59 -05:00

SDK2 live gate: AVEVA history, consumer compatibility and paired-cluster rollout #801

dohertj2 referenced this issue

2026-11-12 17:04:19 -05:00

SDK2 live gate: AVEVA history, consumer compatibility and paired-cluster rollout #801

dohertj2 referenced this issue

2026-11-13 06:45:05 -05:00

Resolve standard non-transparent redundancy metadata deferred by current server #717

Sign in to join this conversation.