Retirement helper masks NodeNotRetiredCommitted after an election as an invalid transaction ID

[cjen1-msft]

nodes_test failed during rotation / test_retire_primary in this Debug CI job, reporting:

ValueError: None.None is not a valid transaction ID

The preceding response was 400 NodeNotRetiredCommitted from DELETE /node/network/nodes/{id}.

Probable cause: after ~3-second ledger I/O stalls, another election occurred. The helper continued polling the previously selected primary, now a follower. Its local GET reported the node removable, but the DELETE forwarded to the new primary, whose committed watermark had not caught up. The helper ignored the error status and passed the absent transaction ID to the commit checker.

Suggested fix: refresh the primary and retry NodeNotRetiredCommitted within the existing timeout; check response success before waiting for commit.

Diagnosed from logs and source; not reproduced locally. The retirement code is unchanged by #8435, and a causal link to that PR is not established.

[achamayou]

Root cause confirmed from the attempt-1 logs-e2e-debug artifact

I pulled the node logs from the failing attempt (rotation_nodes_test_{5,6,7,8}/out) and traced Retirement 5. The probable cause in the description is correct, with two refinements that explain details in the test log:

1. The 3s of removable_nodes -> [] polls were not because retired_committed had not been written. Node 6 (the retiring primary) wrote retired_committed=true for itself at 7.128 before stepping down (that is why every response says last_written: 128). Node 7 held 7.128 locally but its commit index was stuck at 127 for ~3.2s: its term-8 signature 8.130 could not be acked because the host ledger write open(ledger_130) blocked for 3.065s on nodes 5, 6 and 8 simultaneously (time_bound_logger: Operation took too long). A new leader cannot advance commit past prior-term entries until an entry of its own term is replicated to a quorum, so get_globally_committed(node 6) on node 7 kept returning the pre-7.128 value.
2. The same stall caused the second election. Node 8 processed no AppendEntries while its host was blocked, its randomised election timeout (0.5x to 1x of 4000ms, Raft::restart_election_timeout) expired, and it won term 9 at 14:09:13.977 - about 5ms after node 7 finally committed 130. Node 8 became leader with commit_idx 127 and only committed its first term-9 entry (9.131) at 14:09:14.079, 12ms after the DELETE.

So there was a ~100ms window (13.977 to 14.079) where the ex-primary node 7 (follower, commit 130) considered node 6 removable, while the actual primary node 8 (commit 127) did not. The helper's GET /node/network/removable_nodes is ForwardingRequired::Sometimes (executed locally on node 7), while DELETE /node/network/nodes/{id} is ForwardingRequired::Always (forwarded to node 8). The 400 is a legitimate, transient rejection from the service; the helper then passed the TxID-less error response to Checker.__call__, which called wait_for_commit(None, None) and raised the ValueError that masked it.

Key log lines (2026-09-23 14:09:xx UTC)

Time	Node	Line
10.405 / 10.487 / 10.590	6 (92009e)	Becoming retired, phase 1/2/3 ... 7 at 126 / 127 / 127
10.791	6	Becoming retired, phase 4 ... 7 at 128 / Proposing that f5adde... becomes candidate
10.799 / 10.802	8 (5edc8a), 5 (eb124b)	Becoming follower ...: 8.127 (commit_idx 127)
10.801	7 (f5adde)	Becoming leader ...: 8
10.848	test	New primary after 0.22s is 7 (f5adde...) in term 8
10.976 to 13.948	test	27x [7] GET /node/network/removable_nodes -> 200 @8.130 {"nodes":[]}
13.968	5, 6, 8	Operation took too long (3.065s): Creating ledger file - open(N.ledger.current/ledger_130) / Writing ledger entry - 2224 bytes, committable=true
13.969 / 13.974 / 13.977	8	Becoming pre-vote candidate: 8 / Becoming candidate: 9 / Becoming leader: 9
13.970	7	Removed 92009e... from nodes known to consensus (global hook for 7.128, commit crossed 128 only now)
13.972 / 13.975	7	Recv request_pre_vote ... granted vote to candidate at 8.130 with local state at 8.130 / Becoming follower ...: 9.130
14.063	test	[7] GET /node/network/removable_nodes -> 200 @8.131 {"nodes":[{... "92009e...", "last_written":128}]}
14.067	test	[7] DELETE /node/network/nodes/92009e... -> 400 NodeNotRetiredCommitted
14.076	7	Dropping conflicting branch. Rolling back 1 entries, beginning with 8.131.
14.079	8	Removed 92009e... from nodes known to consensus (commit crossed 128 on the new primary)
18.265	test	ValueError('None.None is not a valid transaction ID')

What happened

sequenceDiagram
    autonumber
    participant T as Test helper (Network.retire_node)
    participant N7 as Node 7 (f5adde)
    participant N8 as Node 8 (5edc8a)
    participant N5 as Node 5 (eb124b)
    participant N6 as Node 6 (92009e, primary term 7)

    Note over T,N6: 14:09:10.36 to 10.62 - remove_node proposal for node 6 accepted, node 6 status=Retired at 7.126
    N6->>N6: 7.127 signature, commit 127 => Completed, RetiredNodeCleanup runs
    N6->>N6: 7.128 sets retired_committed=true for node 6, 7.129 signature
    N6->>N6: commit 128 => global hook => RetiredCommitted (10.791)
    N6->>N7: ProposeRequestVote (nominate successor)
    N7->>N5: RequestVote term 8
    N7->>N8: RequestVote term 8
    N5-->>N7: vote yes (node 5 commit_idx 127)
    N8-->>N7: vote yes (node 8 commit_idx 127)
    Note over N7: 10.801 Becoming leader term 8, commit_idx still 127 (7.128 not yet committed here)
    T->>N7: wait_for_new_primary => node 7, term 8 (10.848)
    N7->>N7: 8.130 signature (should_sign on become_leader)
    N7->>N8: AppendEntries 8.130
    N7->>N5: AppendEntries 8.130
    N7->>N6: AppendEntries 8.130
    rect rgb(255, 235, 205)
        Note over N8,N6: 10.9 to 13.968 - host ledger write open(ledger_130) blocks for 3.065s on nodes 5, 6 and 8 (no acks, no ticks delivered)
        loop 27 polls, 10.976 to 13.948
            T->>N7: GET /node/network/removable_nodes (read-only, executes locally)
            N7-->>T: 200 @8.130 nodes=[] (globally committed view is at 127, before 7.128)
            T->>N7: GET /node/network/nodes/node6
            N7-->>T: 200 @8.130 status=Retired, last_written=128
        end
    end
    N5-->>N7: ack 8.130 (13.968)
    N8-->>N7: ack 8.130 (13.968)
    Note over N7: 13.970 commit_idx 127 to 130, global hook for 7.128 fires (Removed node 6 from nodes known to consensus)
    Note over N8: 13.969 randomised election timeout (0.5x to 1x of 4000ms) expired during the stall
    N8->>N7: RequestPreVote (candidate log at 8.130)
    N7-->>N8: pre-vote granted (log up to date)
    N8->>N7: RequestVote term 9
    Note over N7: 13.975 Becoming follower 9.130
    N7-->>N8: vote granted
    Note over N8: 13.977 Becoming leader term 9, commit_idx still 127 (cannot advance until a term-9 entry is replicated)
    N8->>N8: 9.131 signature
    T->>N7: GET /node/network/removable_nodes (14.063)
    N7-->>T: 200 @8.131 nodes=[node 6] (node 7 commit_idx 130 covers 7.128)
    T->>N7: DELETE /node/network/nodes/node6 (14.067)
    Note over N7: follower and endpoint is ForwardingRequired::Always
    N7->>N8: forward DELETE
    Note over N8: get_globally_committed(node 6) at commit_idx 127 => retired_committed=false
    N8-->>N7: 400 NodeNotRetiredCommitted
    N7-->>T: 400 NodeNotRetiredCommitted (no x-ms-ccf-transaction-id header)
    T->>T: check_commit(r) => wait_for_commit(seqno=None, view=None)
    Note over T: ValueError - None.None is not a valid transaction ID (masks the 400)
    N8->>N7: AppendEntries 9.131
    N7->>N7: 14.076 Dropping conflicting branch, rolling back 8.131
    N7-->>N8: ack 9.131
    Note over N8: 14.079 commit 131, global hook for 7.128 fires on the new primary - 12ms after the DELETE

Loading

Would-be fix

Test-infra only; the service behaved correctly. In Network.retire_node (tests/infra/network.py), inspect the DELETE status before handing the response to the commit checker: treat 400 NodeNotRetiredCommitted as transient (re-resolve the primary with find_primary() and keep polling within the existing timeout), fail immediately with the full response on any other non-2xx, and only call check_commit on a 2xx. Optionally, infra.checker.Checker.__call__ could assert a 2xx before wait_for_commit, so any future occurrence reports the real response instead of None.None.

sequenceDiagram
    autonumber
    participant T as Test helper (Network.retire_node, fixed)
    participant N7 as Node 7 (leader term 8, follower from 13.975)
    participant N8 as Node 8 (leader term 9 from 13.977)

    T->>N7: GET /node/network/removable_nodes (14.063)
    N7-->>T: 200 @8.131 nodes=[node 6]
    T->>N7: DELETE /node/network/nodes/node6 (14.067)
    N7->>N8: forward (follower, ForwardingRequired::Always)
    Note over N8: get_globally_committed(node 6) at commit_idx 127 => retired_committed=false
    N8-->>N7: 400 NodeNotRetiredCommitted
    N7-->>T: 400 NodeNotRetiredCommitted
    rect rgb(220, 245, 220)
        Note over T: FIX - inspect r.status_code before check_commit(r)
        alt 400 NodeNotRetiredCommitted (transient - primary changed, new primary commit_idx not caught up)
            T->>T: log response, sleep 0.1s
            T->>T: remote_node = network.find_primary() => node 8
            Note over N8: 14.079 commit 131 (first term-9 entry) - node 6 retired_committed is now committed on the primary
            T->>N8: GET /node/network/removable_nodes
            N8-->>T: 200 nodes=[node 6]
            T->>N8: DELETE /node/network/nodes/node6
            N8-->>T: 200 @9.132 true
            T->>N8: GET /node/tx?transaction_id=9.132 (wait_for_commit, only on a 2xx)
            N8-->>T: Committed
            Note over T: node 6 removed, network.nodes updated, test proceeds
        else any other non-2xx
            Note over T: fail immediately with the full response instead of ValueError None.None
        else still not removable when the existing timeout expires
            Note over T: TimeoutError with the last response, as today
        end
    end

Loading

Consistent with the description, the retirement code path is unchanged by #8435; the trigger was a CI runner disk stall, which can hit any branch.