Nodes test failure

[cjen1-msft]

The error is that when we test_kill_primary_no_reqs it looks like it could be pulling the wrong txid, or one which is from a subsequently rolled back transaction.

https://github.com/microsoft/CCF/actions/runs/21722536850/job/62655953700?pr=7637

2026-02-05 18:37:16.517 | INFO     | {rotation} reconfiguration:wait_for_reconfiguration_to_complete:60 - [3] GET /node/consensus
2026-02-05 18:37:16.517 | INFO     | {rotation} reconfiguration:wait_for_reconfiguration_to_complete:60 - 200 {"details":{"acks":{"5ad3b48677fc70b1dc83fa14613acf115a711547a38b4731cc07ec00a380d94d":{"last_received_ms":0,"seqno":0},"e97a2e290a0c102d38ac8a7c8dbcd705a3ee1a9ad38e0d919bbb73c6d0925ec9":{"last_received_ms":0,"seqno":0}},"configs":[{"idx":39,"nodes":{"5ad3 + 522 chars
2026-02-05 18:37:16.528 | ERROR    | {cft} infra.runner:log_exception:194 - Failure in cft: RuntimeError('Transaction ID 2.25 is marked invalid and will never be committed')
Traceback (most recent call last):

  File "/usr/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
    └ <Thread(cft, started 131846826354368)>
  File "/usr/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
    │             │             └ <Thread(cft, started 131846826354368)>
    │             └ <Thread(cft, started 131846826354368)>
    └ <Thread(cft, started 131846826354368)>
  File "/__w/CCF/CCF/tests/nodes.py", line 255, in run
    test_kill_primary_no_reqs(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 0x77e9fbc125a0>
    └ <function test_kill_primary_no_reqs at 0x77e9fbc0c5e0>
  File "/__w/CCF/CCF/tests/suite/test_requirements.py", line 22, in wrapper
    return func(*args, **kwargs)
           │     │       └ {}
           │     └ (<infra.network.Network object at 0x77e9fbc125a0>, Namespace(binary_dir='/__w/CCF/CCF/build', library_dir='/__w/CCF/CCF/build', ...
           └ <function test_kill_primary_no_reqs at 0x77e9fbc0c540>
  File "/__w/CCF/CCF/tests/nodes.py", line 80, in test_kill_primary_no_reqs
    c.wait_for_commit(r)
    │                 └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"6287239d726797e436f23bdda21...
    └ <infra.clients.CCFClient object at 0x77e9fd909400>
  File "/__w/CCF/CCF/tests/infra/clients.py", line 1319, in wait_for_commit
    infra.commit.wait_for_commit(self, response.seqno, response.view, timeout)
    │                            │     │               │              └ 3
    │                            │     │               └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"6287239d726797e436f23bdda21...
    │                            │     └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"6287239d726797e436f23bdda21...
    │                            └ <infra.clients.CCFClient object at 0x77e9fd909400>
    └ <module 'infra' from '/__w/CCF/CCF/tests/infra/__init__.py'>
  File "/__w/CCF/CCF/tests/infra/commit.py", line 52, in wait_for_commit
    raise RuntimeError(

RuntimeError: Transaction ID 2.25 is marked invalid and will never be committed

2026-02-05 18:37:16.531 | INFO     | {reconfiguration} infra.consortium:vote_using_majority:307 - [0] GET /node/tx?transaction_id=2.56

[cjen1-msft]

Another repro:

https://github.com/microsoft/CCF/actions/runs/21842045932/job/63028632733?pr=7554

[eddyashton]

Another repro here, blocking a release:
https://github.com/microsoft/CCF/actions/runs/22345021892/job/64657894266#step:8:4865

The error is on the same TxID:

Traceback (most recent call last):

  File "/usr/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
    └ <Thread(cft, started 137960180508352)>
  File "/usr/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
    │             │             └ <Thread(cft, started 137960180508352)>
    │             └ <Thread(cft, started 137960180508352)>
    └ <Thread(cft, started 137960180508352)>
  File "/__w/CCF/CCF/tests/nodes.py", line 255, in run
    test_kill_primary_no_reqs(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 0x7d795c0df890>
    └ <function test_kill_primary_no_reqs at 0x7d795c0e1da0>
  File "/__w/CCF/CCF/tests/suite/test_requirements.py", line 22, in wrapper
    return func(*args, **kwargs)
           │     │       └ {}
           │     └ (<infra.network.Network object at 0x7d795c0df890>, Namespace(binary_dir='/__w/CCF/CCF/build', library_dir='/__w/CCF/CCF/build', ...
           └ <function test_kill_primary_no_reqs at 0x7d795c0e1d00>
  File "/__w/CCF/CCF/tests/nodes.py", line 80, in test_kill_primary_no_reqs
    c.wait_for_commit(r)
    │                 └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"def063dea67a8b3e718ffdc4e71...
    └ <infra.clients.CCFClient object at 0x7d795a027c20>
  File "/__w/CCF/CCF/tests/infra/clients.py", line 1319, in wait_for_commit
    infra.commit.wait_for_commit(self, response.seqno, response.view, timeout)
    │                            │     │               │              └ 3
    │                            │     │               └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"def063dea67a8b3e718ffdc4e71...
    │                            │     └ Response(status_code=200, body=b'{"current_service_create_txid":"2.1","current_view":3,"primary_id":"def063dea67a8b3e718ffdc4e71...
    │                            └ <infra.clients.CCFClient object at 0x7d795a027c20>
    └ <module 'infra' from '/__w/CCF/CCF/tests/infra/__init__.py'>
  File "/__w/CCF/CCF/tests/infra/commit.py", line 52, in wait_for_commit
    raise RuntimeError(

RuntimeError: Transaction ID 2.24 is marked invalid and will never be committed

This 2.24 comes from a /node/network response, shortly after an election:

    # Verify that the TxID reported just after an election is valid
    # Note that the first TxID read after an election may be of a signature
    # Tx (time-based signature generation) in the new term rather than the
    # last entry in the previous term
    for node in network.get_joined_nodes():
        with node.client() as c:
            r = c.get("/node/network")
            c.wait_for_commit(r)

2026-02-24 10:13:46.744 | INFO     | {cft} __main__:test_kill_primary_no_reqs:63 - [2] GET /app/commit?view_history=true
2026-02-24 10:13:46.744 | INFO     | {cft} __main__:test_kill_primary_no_reqs:63 - 200 {"transaction_id":"2.23","view_history":["1.1","2.1","3.24"]}
2026-02-24 10:13:46.766 | INFO     | {cft} __main__:test_kill_primary_no_reqs:79 - [1] GET /node/network
2026-02-24 10:13:46.766 | INFO     | {cft} __main__:test_kill_primary_no_reqs:79 - 200 @2.24 {"current_service_create_txid":"2.1","current_view":3,"primary_id":"def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44","recovery_count":0,"service_certificate":"-----BEGIN CERTIFICATE-----\nMIIB2DCCAV2gAwIBAgIQTI4NIfUZ0qKpVvBBlr8gyDAKBggqhkj + 678 chars

The node logs, particularly on node 1, show that the election was called and one at 2.23, yet somehow this node has an entry at 2.24:

2026-02-24T10:13:46.671271Z 0   [info ] CCF/src/node/channels.h:792          | Node channel with n[def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44] is now established.
2026-02-24T10:13:46.671370Z 0   [info ] CCF/src/consensus/aft/raft.h:1819    | Recv request_pre_vote to n[f6858265d27d89b93e6be884577262c160f5cf371b56300eea097a29910998fe] from n[def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44]: granted vote to candidate at 2.23 with local state at 2.23
2026-02-24T10:13:46.671379Z 0   [info ] CCF/src/consensus/aft/raft.h:1899    | Send request_pre_vote_response from n[f6858265d27d89b93e6be884577262c160f5cf371b56300eea097a29910998fe] to n[def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44]: true
2026-02-24T10:13:46.672884Z 0   [info ] CCF/src/consensus/aft/raft.h:2249    | Becoming follower n[f6858265d27d89b93e6be884577262c160f5cf371b56300eea097a29910998fe]: 3.23
2026-02-24T10:13:46.672900Z 0   [info ] CCF/src/consensus/aft/raft.h:1819    | Recv request_vote to n[f6858265d27d89b93e6be884577262c160f5cf371b56300eea097a29910998fe] from n[def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44]: granted vote to candidate at 2.23 with local state at 2.23
2026-02-24T10:13:46.672911Z 0   [info ] CCF/src/consensus/aft/raft.h:1884    | Send request_vote_response from n[f6858265d27d89b93e6be884577262c160f5cf371b56300eea097a29910998fe] to n[def063dea67a8b3e718ffdc4e71e7a58e4053752f9a11805e3f2ffcdc8877e44]: true
2026-02-24T10:13:46.775074Z 0   [info ][rollback] /consensus/aft/raft.h:1270 | Dropping conflicting branch. Rolling back 1 entries, beginning with 2.24.

We have no further information on what 2.24 is. I assume a signature? But it must have arrived after node 1 sent its vote response, right? Else it would have voted no! But that surely rules out the idea of it coming from node 0, which is already dead by here - its death is what triggers the election.

[eddyashton]

Another repro here:
https://github.com/microsoft/CCF/actions/runs/22439764574/job/64978849734