StateDigestMismatch in election test

[achamayou]

https://github.com/microsoft/CCF/actions/runs/18779614419/job/53582774718?pr=7407

2025-10-24 13:02:23.361 | INFO     | {cft} infra.clients:post:1224 - [1|cose=member0] POST /gov/members/state-digests/9d56092c9d290589f7e041d077b63c59a984b62ce67f2b2c447714fc0b42fb41:ack?api-version=2024-07-01 {'memberId': '9d56092c9d290589f7e041d077b63c59a984b62ce67f2b2c447714fc0b42fb41', 'stateDigest': '2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712'}
2025-10-24 13:02:23.361 | INFO     | {cft} infra.clients:post:1224 - 400 {"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\nExpected\n \nReceived\n 2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712"}}
2025-10-24 13:02:23.362 | INFO     | {cft} infra.network:log_stack_traces:555 - Logging stack traces for all nodes
2025-10-24 13:02:24.474 | ERROR    | {cft} infra.remote:log_stack_trace:222 - Stack trace of process 12480 written to /__w/CCF/CCF/build/workspace/cft_election_test_0/stack_trace
2025-10-24 13:02:25.605 | ERROR    | {cft} infra.remote:log_stack_trace:222 - Stack trace of process 12498 written to /__w/CCF/CCF/build/workspace/cft_election_test_1/stack_trace
2025-10-24 13:02:26.707 | ERROR    | {cft} infra.remote:log_stack_trace:222 - Stack trace of process 12523 written to /__w/CCF/CCF/build/workspace/cft_election_test_2/stack_trace
2025-10-24 13:02:26.707 | INFO     | {cft} infra.network:network:1834 - Stopping network
2025-10-24 13:02:26.707 | INFO     | {cft} infra.node:stop:482 - Stopping node 0
2025-10-24 13:02:26.707 | INFO     | {cft} infra.remote:stop:236 - [127.145.92.131] closing
2025-10-24 13:02:26.821 | INFO     | {cft} infra.node:stop:482 - Stopping node 1
2025-10-24 13:02:26.821 | INFO     | {cft} infra.remote:stop:236 - [127.16.48.184] closing
2025-10-24 13:02:26.935 | INFO     | {cft} infra.node:stop:482 - Stopping node 2
2025-10-24 13:02:26.936 | INFO     | {cft} infra.remote:stop:236 - [127.10.192.13] closing
2025-10-24 13:02:27.050 | INFO     | {cft} infra.network:stop_all_nodes:941 - All nodes stopped
2025-10-24 13:02:27.133 | ERROR    | {cft} infra.runner:log_exception:194 - Failure in cft: AssertionError(Response(status_code=400, body=b'{"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\\nExpected\\n \\nReceived\\n 2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712"}}', seqno=None, view=None, headers=Headers({'content-length': '179', 'content-type': 'application/json'})))
Traceback (most recent call last):

  File "/usr/lib/python3.12/threading.py", line 1075, in _bootstrap_inner
    self.run()
    └ <Thread(cft, started 125864790939328)>
  File "/usr/lib/python3.12/threading.py", line 1012, in run
    self._target(*self._args, **self._kwargs)
    │             │             └ <Thread(cft, started 125864790939328)>
    │             └ <Thread(cft, started 125864790939328)>
    └ <Thread(cft, started 125864790939328)>
  File "/__w/CCF/CCF/tests/election.py", line 190, in run
    network.start_and_open(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 0x72792e33f7a0>
  File "/__w/CCF/CCF/tests/infra/network.py", line 674, in start_and_open
    self.open(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 0x72792e33f7a0>
  File "/__w/CCF/CCF/tests/infra/network.py", line 638, in open
    self.consortium.activate(get_target_node(args, primary))
    │                        │               │     └ <infra.node.Node object at 0x72792f4a0d70>
    │                        │               └ Namespace(binary_dir='/__w/CCF/CCF/build', library_dir='/__w/CCF/CCF/build', debug_nodes=[], log_level='info', log_format_json=F...
    │                        └ <function Network.open.<locals>.get_target_node at 0x72792d99f920>
    └ <infra.network.Network object at 0x72792e33f7a0>
  File "/__w/CCF/CCF/tests/infra/consortium.py", line 154, in activate
    m.ack(remote_node)
    │     └ <infra.node.Node object at 0x72792efae9c0>
    └ <infra.member.Member object at 0x72792ea38740>
  File "/__w/CCF/CCF/tests/infra/member.py", line 346, in ack
    return self.gov_api_impl_inst.ack(
  File "/__w/CCF/CCF/tests/infra/member.py", line 127, in ack
    assert r.status_code == http.HTTPStatus.NO_CONTENT, r
           │                │                           └ Response(status_code=400, body=b'{"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\\nExpect...
           │                └ <module 'http' from '/usr/lib/python3.12/http/__init__.py'>
           └ Response(status_code=400, body=b'{"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\\nExpect...

AssertionError: <red>400</> <yellow>{"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\nExpected\n \nReceived\n 2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712"}}</>

Traceback (most recent call last):
  File "/__w/CCF/CCF/tests/election.py", line 257, in <module>
    cr.run(1)
    └ <infra.runner.ConcurrentRunner object at 0x72792e33cfe0>
  File "/__w/CCF/CCF/tests/infra/runner.py", line 283, in run
    raise RuntimeError(FAILURES)
                       └ ['Failure in cft: AssertionError(Response(status_code=400, body=b\'{"error":{"code":"StateDigestMismatch","message":"Submitted s...
RuntimeError: ['Failure in cft: AssertionError(Response(status_code=400, body=b\'{"error":{"code":"StateDigestMismatch","message":"Submitted state digest is not valid.\\\\nExpected\\\\n \\\\nReceived\\\\n 2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712"}}\', seqno=None, view=None, headers=Headers({\'content-length\': \'179\', \'content-type\': \'application/json\'})))']

[achamayou]

The error message implies there is a state digest entry for the member (which we expect), but that the value is empty (\nExpected\n \), which we don't.

[achamayou]

Looks like there was an election that rolled back the write of the digest specifically:

2025-10-24 13:02:23.340 | INFO     | {cft} infra.clients:post:1224 - [1|cose=member0] POST /gov/members/state-digests/9d56092c9d290589f7e041d077b63c59a984b62ce67f2b2c447714fc0b42fb41:update?api-version=2024-07-01
2025-10-24 13:02:23.340 | INFO     | {cft} infra.clients:post:1224 - 200 @2.7 {"memberId":"9d56092c9d290589f7e041d077b63c59a984b62ce67f2b2c447714fc0b42fb41","stateDigest":"2fc163c92a128c30c6d804af310e700405de214655e186fc699a132baab8a712"}

2025-10-24T13:02:22.483222Z        0   [info ][gov] /gov/gov_endpoint_registry.h:58 | RequestCompletedEvent: POST /members/state-digests/{memberId}:update 200 1ms 1 attempt(s)
2025-10-24T13:02:23.333054Z        0   [info ] CCF/src/consensus/aft/raft.h:2051    | Becoming follower n[89f5e2ac4fb386ffafd28b2c00cfc5c066959b2b4d51a24930ada4caafb0295f]: 3.6
2025-10-24T13:02:23.333087Z        0   [info ] CCF/src/consensus/aft/raft.h:1775    | Voting against candidate at 2.6 because local state is at 2.8
2025-10-24T13:02:23.333111Z        0   [info ] CCF/src/consensus/aft/raft.h:1788    | Send request vote response from n[89f5e2ac4fb386ffafd28b2c00cfc5c066959b2b4d51a24930ada4caafb0295f] to n[645bdf5dec6315414bc61974b3f83957ba749bc7e9d4738217f3923fd88ebadc]: false
2025-10-24T13:02:23.333213Z        0   [info ] CCF/src/consensus/aft/raft.h:1567    | Recv append entries response to n[89f5e2ac4fb386ffafd28b2c00cfc5c066959b2b4d51a24930ada4caafb0295f] from n[645bdf5dec6315414bc61974b3f83957ba749bc7e9d4738217f3923fd88ebadc]: no longer leader
2025-10-24T13:02:23.339918Z        0   [info ] CCF/src/consensus/aft/raft.h:1567    | Recv append entries response to n[89f5e2ac4fb386ffafd28b2c00cfc5c066959b2b4d51a24930ada4caafb0295f] from n[692316837bc231637ec5ed44fe14f694d3060050c0625d703b3e97c03c75266c]: no longer leader

[achamayou]

The election was called by node 2:

2025-10-24T13:02:22.051969Z        0   [info ] CCF/src/host/ledger.h:1401           | Found divergent ledger entry at 5
2025-10-24T13:02:22.147510Z        0   [info ] CCF/src/consensus/aft/raft.h:581     | Election timer has become active
2025-10-24T13:02:22.246728Z        0   [info ] CCF/src/node/node_state.h:2472       | [global] node_endorsed_certificates global hook at version 5, with 1 writes
2025-10-24T13:02:22.246784Z        0   [info ] CCF/src/node/node_state.h:2498       | [global] Accepting network connections
2025-10-24T13:02:22.247545Z        0   [info ] CCF/src/node/node_state.h:2059       | Network TLS connections now accepted
2025-10-24T13:02:22.247572Z        0   [info ] CCF/src/node/node_state.h:2530       | [global] Member frontend is NOT open
2025-10-24T13:02:22.247590Z        0   [info ] CCF/src/node/node_state.h:2531       | [global] Self-signed node cert remains:
-----BEGIN CERTIFICATE-----
MIIB2DCCAV6gAwIBAgIQfRZcorWlMdKb0QQsYx97cDAKBggqhkjOPQQDAzATMREw
DwYDVQQDDAhDQ0YgTm9kZTAeFw0yNTEwMjQxMzAyMTlaFw0yNTEwMjUxMzAyMTha
MBMxETAPBgNVBAMMCENDRiBOb2RlMHYwEAYHKoZIzj0CAQYFK4EEACIDYgAEOqE2
Djci2i72cvjkoLn6Kan7pjEzA1zsbyUH/EZZf9nDnE+6kysStDk3pgj46FJSOiww
oD8KMbpGIpTbkNMMrB4wCIuGzo4lTHANpoti7Wzs2LwlHHBygz5iRAW3SHmTo3cw
dTASBgNVHRMBAf8ECDAGAQH/AgEBMA4GA1UdDwEB/wQEAwIChDAdBgNVHQ4EFgQU
4hZSh9FPSr6hptJ2dKN3L7xqyCswHwYDVR0jBBgwFoAU4hZSh9FPSr6hptJ2dKN3
L7xqyCswDwYDVR0RBAgwBocEfwrADTAKBggqhkjOPQQDAwNoADBlAjEA0NpIvxQW
VXmEcSqr04kTT95Mwz9NEmJtKWBH5ceB7JmG33esscTDn4T+i/1726/5AjB6dD3k
Xll74C7V4O3fgS50MqY2tARhyjmjr22npIUPLOIXVDV9sAgtHzV7U1yxqWQ=
-----END CERTIFICATE-----

2025-10-24T13:02:22.247607Z        0   [info ] CCF/src/node/node_state.h:2536       | [global] Opening members frontend
2025-10-24T13:02:22.247621Z        0   [info ] CCF/src/node/rpc/frontend.h:948      | Opening frontend
2025-10-24T13:02:23.034688Z        0   [info ] CCF/src/consensus/aft/raft.h:1944    | Becoming candidate n[645bdf5dec6315414bc61974b3f83957ba749bc7e9d4738217f3923fd88ebadc]: 3
2025-10-24T13:02:23.317361Z        0   [info ] CCF/src/consensus/aft/raft.h:1658    | Send request vote from n[645bdf5dec6315414bc61974b3f83957ba749bc7e9d4738217f3923fd88ebadc] to n[692316837bc231637ec5ed44fe14f694d3060050c0625d703b3e97c03c75266c] at 6

Seemingly because there was no heartbeat from the primary between 2025-10-24T13:02:22.247621Z and 2025-10-24T13:02:23.034688Z?

The message about the divergent ledger entry is surprising, it sounds like there were pre-existing ledger files somehow? I am not sure how that's possible.