Election failed in snapshot test

[maxtropets]

Link to CI job

Logs: logs.zip

Traceback:

Traceback (most recent call last):

  File "/usr/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
    └ <Thread(operations, started 137494855153344)>
  File "/usr/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
    │             │             └ <Thread(operations, started 137494855153344)>
    │             └ <Thread(operations, started 137494855153344)>
    └ <Thread(operations, started 137494855153344)>
  File "/__w/CCF/CCF/tests/e2e_operations.py", line 2900, in run
    run_manual_snapshot_tests(args)
    │                         └ Namespace(binary_dir='/__w/CCF/CCF/build', library_dir='/__w/CCF/CCF/build', debug_nodes=[], log_level='info', log_format_json=F...
    └ <function run_manual_snapshot_tests at 0x7d0d121dcd60>
  File "/__w/CCF/CCF/tests/e2e_operations.py", line 516, in run_manual_snapshot_tests
    test_snapshot_selection(network, args)
    │                       │        └ Namespace(binary_dir='/__w/CCF/CCF/build', library_dir='/__w/CCF/CCF/build', debug_nodes=[], log_level='info', log_format_json=F...
    │                       └ <infra.network.Network object at 0x7d0d121bd7f0>
    └ <function test_snapshot_selection at 0x7d0d121dce00>
  File "/__w/CCF/CCF/tests/e2e_operations.py", line 642, in test_snapshot_selection
    network.wait_for_node_commit_sync()
    └ <infra.network.Network object at 0x7d0d121bd7f0>
  File "/__w/CCF/CCF/tests/infra/network.py", line 1699, in wait_for_node_commit_sync
    assert expected == commits, f"Multiple commit values: {commits}"
           │           │                                   └ ['2.50', '3.51', '3.51']
           │           └ ['2.50', '3.51', '3.51']
           └ ['2.50', '2.50', '2.50']

AssertionError: Multiple commit values: ['2.50', '3.51', '3.51']

Traceback (most recent call last):
  File "/__w/CCF/CCF/tests/schema.py", line 247, in <module>
    cr.run()
    └ <infra.runner.ConcurrentRunner object at 0x7d0d126d5820>
  File "/__w/CCF/CCF/tests/infra/runner.py", line 283, in run
    raise RuntimeError(FAILURES)
                       └ ['Failure in operations: AssertionError("Multiple commit values: [\'2.50\', \'3.51\', \'3.51\']")']
RuntimeError: ['Failure in operations: AssertionError("Multiple commit values: [\'2.50\', \'3.51\', \'3.51\']")']

[eddyashton]

Similar Python stack to #7687, but in a totally different top-level test. Worrying!

[eddyashton]

Noting that this is since #7698 merged, which moved the test in question. Maybe that made it flakier? It certainly added the wait_for_commit_sync at the end of the test.

[eddyashton]

Similar to #7687, the lagging node 0 seems to become a follower very shortly after we've last polled /commit. By the time we call /consensus to gather diagnostic state, it looks like they've caught up (they're in the correct view at least?).

2026-03-04 14:25:03.589 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - [0] GET /node/commit
2026-03-04 14:25:03.589 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - 200 {"transaction_id":"2.50"}
2026-03-04 14:25:03.605 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - [1] GET /node/commit
2026-03-04 14:25:03.605 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - 200 {"transaction_id":"3.51"}
2026-03-04 14:25:03.621 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - [2] GET /node/commit
2026-03-04 14:25:03.621 | INFO     | {operations} infra.network:wait_for_node_commit_sync:1686 - 200 {"transaction_id":"3.51"}

Near-concurrently in the node logs:

# Node 0
2026-03-04T14:25:03.561922Z 0   [info ] CCF/src/consensus/aft/raft.h:2249    | Becoming follower n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e]: 3.50
2026-03-04T14:25:03.561960Z 0   [info ] CCF/src/consensus/aft/raft.h:1966    | Recv request_pre_vote_response to n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e] from: n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: we aren't a candidate
2026-03-04T14:25:03.670431Z 0   [info ] CCF/src/consensus/aft/raft.h:1819    | Recv request_pre_vote to n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e] from n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: granted vote to candidate at 3.51 with local state at 2.50
2026-03-04T14:25:03.670471Z 0   [info ] CCF/src/consensus/aft/raft.h:1899    | Send request_pre_vote_response from n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e] to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: true
2026-03-04T14:25:03.672707Z 0   [info ] CCF/src/consensus/aft/raft.h:2249    | Becoming follower n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e]: 4.50
2026-03-04T14:25:03.672739Z 0   [info ] CCF/src/consensus/aft/raft.h:1819    | Recv request_vote to n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e] from n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: granted vote to candidate at 3.51 with local state at 2.50
2026-03-04T14:25:03.672763Z 0   [info ] CCF/src/consensus/aft/raft.h:1884    | Send request_vote_response from n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e] to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: true

# Node 1
2026-03-04T14:25:03.560758Z 0   [info ] CCF/src/consensus/aft/raft.h:1899    | Send request_pre_vote_response from n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da] to n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e]: false
2026-03-04T14:25:03.669262Z 0   [info ] CCF/src/consensus/aft/raft.h:2098    | Becoming pre-vote candidate n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: 3
2026-03-04T14:25:03.671548Z 0   [info ] CCF/src/consensus/aft/raft.h:2017    | Recv request vote response to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da] from n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e]: they voted yes
2026-03-04T14:25:03.671586Z 0   [info ] CCF/src/consensus/aft/raft.h:2147    | Becoming candidate n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: 4
2026-03-04T14:25:03.671687Z 0   [info ] CCF/src/consensus/aft/raft.h:1953    | Recv request vote response to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da] from n[8df5b6ba83212cb634da30d974da8cd6c989473482e8232edf556a942ba522e8]: stale (4 != 3)
2026-03-04T14:25:03.673881Z 0   [info ] CCF/src/consensus/aft/raft.h:2017    | Recv request vote response to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da] from n[1b7fb9ee5317f94dc8db0bba1360107c0843dd1ee5ea523820a7eabb02b1230e]: they voted yes
2026-03-04T14:25:03.673948Z 0   [info ] CCF/src/consensus/aft/raft.h:2203    | Becoming leader n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da]: 4
2026-03-04T14:25:03.674034Z 0   [info ] CCF/src/consensus/aft/raft.h:1966    | Recv request_vote_response to n[b8fd3b1161ef382240ae81ea1b7fff979e9b13d7a4969a188553521c4a3dc1da] from: n[8df5b6ba83212cb634da30d974da8cd6c989473482e8232edf556a942ba522e8]: we aren't a candidate

So perhaps this wait_for_node_commit_sync() function is not waiting long enough? Perhaps affected by the pre-vote delay? I'll fiddle with timings to see if I can get a consistent repro.

[eddyashton]

Alright, this instance is flaky because the prior call is only wait_for_primary_in, not wait_for_primary_unanimity, so can return while we're still seeing active election churn from the resuming nodes. Easy standalone fix.

I'll also check the partitions_test instance, and what state it ensures prior to this call.

wait_for_node_commit_sync uses a short (3s) timeout. I think it should be auto-derived, generally far shorter (a signature + a few roundtrips! Nowhere near an election!) to catch these missing preconditions.