Investigate partitions_test failure: "Adjacent signatures at T.X and T.X+1"

[eddyashton]

#4908 changed how we produced the first signature in a new term, and added a test to confirm this didn't lead to redundant adjacent signatures.

The partitions_test has an occasional failure showing these adjacent signatures are sometimes produced:
https://dev.azure.com/MSRC-CCF/CCF/_build/results?buildId=66238&view=logs&j=abb827b0-1387-5f0d-393d-8da14bd7f99d&t=776cc0e6-a7f3-556a-baca-d314f367d1cc

The relevant output from the primary at the time (node 8) in the above repro, showing Signed at 211 to Signed at 212, is the following:

2023-03-03T03:35:30.165954Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1037     | Looking for match with 39.210, from 40.210, best answer is 209
2023-03-03T03:35:30.165957Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1658     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa]: failed
2023-03-03T03:35:30.206215Z -0.001 0   [debug] ../src/node/history.h:750            | Signed at 211 in view: 42, previous signature was at 210
2023-03-03T03:35:30.206222Z -0.001 0   [debug] ../src/kv/store.h:928                | Store::commit 211 globally_committable
2023-03-03T03:35:30.206226Z -0.001 0   [trace] ../src/kv/store.h:962                | Inserting pending tx at 211
2023-03-03T03:35:30.207289Z -0.002 0   [trace] ../src/kv/untyped_map_handle.cpp:159 | KV[public:ccf.internal.signatures]::put(<uint8[8]: hex=00 00 00 00 00 00 00 00>, <uint8[1133]: ascii={"cert":"-----BEGIN CERTIFICATE-----\nMIIBxjCCAUygAwIBAgIRAOZRvLoNz5hN609hz5cuieowCgYIKoZIzj0EAwMwFjEU\nMBIGA1UEAwwLQ0NGIE5ldHdvcmswHhcNMjMwMzAzMDMzNDU5WhcNMjQwMzAyMDMz\nNDU4WjATMREwDwYDVQQDDAhDQ0YgTm9kZTB2MBAGByqGSM49AgEGBSuBBAAiA2IA\nBO1RRDW8/vWIID0kBugJKJ3cQDOGeY2DeqeSsPqaDMV9tw4vXc8QPZSjsT18/8by\nar4Tnzoe4/f4WuCZiUQT1g07UJVq+6njc77Iam+/Yn0wyqcBsUUjJmQMwlYehItG\nmaNhMF8wDAYDVR0TAQH/BAIwADAdBgNVHQ4EFgQUqovi1w8bTTlHEqBQe/RpWf7q\n/QQwHwYDVR0jBBgwFoAUX8MErmM0QdAhHsrRikJgfuRHy1cwDwYDVR0RBAgwBocE\nf9D+mjAKBggqhkjOPQQDAwNoADBlAjBLlnTilCWAoZcpMBqB3j6sxpQ7/oDXd9E7\nj8RabST3RM1Gq7ImZH76+4kmE2bB9xMCMQCFJQbMIHKRKNNtKuQtYjiCgpAyR4Oe\nnuQbZq02cK6HOzJVkbFyANxhOt24WYHIwHU=\n-----END CERTIFICATE-----\n","commit_seqno":0,"commit_view":0,"hashed_nonce":"0000000000000000000000000000000000000000000000000000000000000000","node":"062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6","root":"a20693dfdbc8c04edc716ad67df4f35484f9322c574f2a8fb8d4d0bc6552c597","seqno":211,"sig":"MGUCMQDRUO0Ua38VzePCg05bk/uh0S9G8ZmYlNuIv9vwtIQFjBqeOSqBl56/KfagnMk82akCMEHt44uz0fRdZ16+OFSuMIR6WEXN9a1eztERInu1Y70Yc2D12AdnjW/sJCO5wgQxbA==","view":42}>)
2023-03-03T03:35:30.207298Z -0.002 0   [trace] ../src/node/history.h:437            | mt_serialize_size (210,210) 176
2023-03-03T03:35:30.207303Z -0.002 0   [trace] ../src/kv/untyped_map_handle.cpp:159 | KV[public:ccf.internal.tree]::put(<uint8[8]: hex=00 00 00 00 00 00 00 00>, <uint8[176]: hex=00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 d2 d3 49 f5 61 f1 01 b6 7e 03 af 17 77 42 b1 0a aa 19 36 f5 e3 c6 7b 29 1e 0f 1a d3 ed d0 2a d2 71 a8 e0 19 7a 96 a0 6d 68 ed 78 f0 74 09 c5 65 43 4f 58 9f 04 80 b1 88 45 83 23 5d 6f 96 00 e6 a4 36 44 de 2f 1a 74 3f 70 f9 a3 e8 3e c9 2f d0 5a 49 83 16 1c de bb b8 ad ce 85 88 1b c4 de 1d 68 1f c7 2f 20 38 9b 4d 38 25 38 30 5a 93 c1 ca 92 6f d3 64 a6 4c c3 62 3b 30 c7 d8 bb 30 5f 04 e0 74 14 13 dc 5f ce 7b b8 12 ca 2b be ed 7b f3 5e af 9a 84 cd ba 5e 13 e2 9e 67 bb e0 96 7f ca a6>)
2023-03-03T03:35:30.207307Z -0.002 0   [trace] ../src/kv/committable_tx.h:75        | Commit evidence: ce:42.211:b66c24fc3ff793f2045a0a718f6c561cb11655a223d9991914878083b6e6ab7d
2023-03-03T03:35:30.207311Z -0.002 0   [trace] ../src/node/history.h:86             | History [0] <sha256 9e1aa05d532157928ff10b23d2af0d5b604b499523115f38f8198157b95ea2e1>
2023-03-03T03:35:30.207315Z -0.002 0   [debug] ../src/kv/store.h:1007               | Batching 211 (1616) during commit of 42.211
2023-03-03T03:35:30.207318Z -0.002 0   [trace] ../src/kv/store.h:972                | Couldn't find 212 = 210 + 2, giving up on batch while committing 42.211
2023-03-03T03:35:30.207322Z -0.002 0   [debug] ../src/consensus/aft/raft.h:789      | Replicating 1 entries
2023-03-03T03:35:30.207326Z -0.002 0   [debug] ../src/consensus/aft/raft.h:808      | Replicated on leader n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6]: 211 committable (0 hooks)
2023-03-03T03:35:30.207330Z -0.002 0   [debug] ../src/consensus/aft/raft.h:822      | membership: Active leadership: Leader
2023-03-03T03:35:30.207357Z        100 [trace] ../src/host/ledger.h:1205            | Wrote entry at 211 [committable: true, force chunk after: false]
2023-03-03T03:35:30.207361Z -0.002 0   [debug] ../src/consensus/aft/impl/state.h:38 | Updating view to: 42 at version: 211
2023-03-03T03:35:30.207366Z -0.002 0   [debug] ../src/consensus/aft/impl/state.h:55 | Resulting views: 1, 1, 23, 23, 23, 23, 23, 23, 28, 29, 29, 67, 67, 82, 82, 82, 82, 82, 82, 96, 101, 101, 105, 110, 113, 113, 123, 123, 123, 123, 123, 123, 123, 123, 123, 123, 146, 155, 155, 210, 211, 211
2023-03-03T03:35:30.263532Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1092     | Sending append entries to node n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] in batches of 12, covering the range 211 -> 211
2023-03-03T03:35:30.263540Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1122     | Sending sub range 211 -> 211
2023-03-03T03:35:30.263547Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1146     | Send append entries from n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] to n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386]: (40.210, 42.211] (210)
2023-03-03T03:35:30.263551Z -0.001 0   [trace] ../src/node/channels.h:891           | -> n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] (ESTABLISHED): send(1, 57 bytes, 0 bytes) (nonce=66)
2023-03-03T03:35:30.263590Z        100 [debug] ../src/host/node_connections.h:384   | send AE to node n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] [1777]: 211, 210
2023-03-03T03:35:30.263595Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1092     | Sending append entries to node n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] in batches of 12, covering the range 211 -> 211
2023-03-03T03:35:30.263600Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1122     | Sending sub range 211 -> 211
2023-03-03T03:35:30.263604Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1146     | Send append entries from n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] to n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b]: (40.210, 42.211] (210)
2023-03-03T03:35:30.263608Z -0.001 0   [trace] ../src/node/channels.h:891           | -> n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] (ESTABLISHED): send(1, 57 bytes, 0 bytes) (nonce=94)
2023-03-03T03:35:30.263632Z        100 [debug] ../src/host/node_connections.h:384   | send AE to node n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] [1777]: 211, 210
2023-03-03T03:35:30.263637Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1092     | Sending append entries to node n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] in batches of 12, covering the range 211 -> 211
2023-03-03T03:35:30.263641Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1122     | Sending sub range 211 -> 211
2023-03-03T03:35:30.263644Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1146     | Send append entries from n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] to n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e]: (40.210, 42.211] (210)
2023-03-03T03:35:30.263648Z -0.001 0   [trace] ../src/node/channels.h:891           | -> n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] (ESTABLISHED): send(1, 57 bytes, 0 bytes) (nonce=200)
2023-03-03T03:35:30.263671Z        100 [debug] ../src/host/node_connections.h:384   | send AE to node n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] [1777]: 211, 210
2023-03-03T03:35:30.263676Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1092     | Sending append entries to node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] in batches of 12, covering the range 210 -> 211
2023-03-03T03:35:30.263680Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1122     | Sending sub range 210 -> 210
2023-03-03T03:35:30.263683Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1146     | Send append entries from n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] to n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa]: (39.209, 40.210] (210)
2023-03-03T03:35:30.263687Z -0.001 0   [trace] ../src/node/channels.h:891           | -> n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] (ESTABLISHED): send(1, 57 bytes, 0 bytes) (nonce=198)
2023-03-03T03:35:30.263712Z        100 [debug] ../src/host/node_connections.h:384   | send AE to node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] [1777]: 210, 209
2023-03-03T03:35:30.263717Z -0.001 0   [trace] ../src/consensus/aft/raft.h:1122     | Sending sub range 211 -> 211
2023-03-03T03:35:30.263721Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1146     | Send append entries from n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] to n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa]: (40.210, 42.211] (210)
2023-03-03T03:35:30.263728Z -0.001 0   [trace] ../src/node/channels.h:891           | -> n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] (ESTABLISHED): send(1, 57 bytes, 0 bytes) (nonce=199)
2023-03-03T03:35:30.263749Z        100 [debug] ../src/host/node_connections.h:384   | send AE to node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] [1777]: 211, 210
2023-03-03T03:35:30.265866Z        100 [trace] ../src/host/tcp.h:746                | Allocating 16384 bytes for TCP read (49152 of quota remaining)
2023-03-03T03:35:30.265878Z        100 [debug] ../src/host/node_connections.h:40    | from node n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] received 133 bytes
2023-03-03T03:35:30.265883Z        100 [debug] ../src/host/node_connections.h:86    | node in: from node n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386], size 129, type 1
2023-03-03T03:35:30.265947Z        100 [trace] ../src/host/tcp.h:746                | Allocating 16384 bytes for TCP read (49152 of quota remaining)
2023-03-03T03:35:30.265957Z        100 [debug] ../src/host/node_connections.h:40    | from node n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] received 133 bytes
2023-03-03T03:35:30.265960Z        100 [debug] ../src/host/node_connections.h:86    | node in: from node n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e], size 129, type 1
2023-03-03T03:35:30.266144Z        100 [trace] ../src/host/tcp.h:746                | Allocating 16384 bytes for TCP read (49152 of quota remaining)
2023-03-03T03:35:30.266154Z        100 [debug] ../src/host/node_connections.h:40    | from node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] received 133 bytes
2023-03-03T03:35:30.266158Z        100 [debug] ../src/host/node_connections.h:86    | node in: from node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa], size 129, type 1
2023-03-03T03:35:30.267218Z -0.002 0   [trace] ../src/node/channels.h:224           | <- n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] (ESTABLISHED): decrypt(25 bytes, 0 bytes) (nonce=73)
2023-03-03T03:35:30.267222Z -0.002 0   [debug] ../src/consensus/aft/raft.h:1666     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[ae106c31aa2cda89a60c86b160adb548b92e267048f96c7bdb05ba2fcc26d386] for index 211: success
2023-03-03T03:35:30.267226Z -0.002 0   [debug] ../src/consensus/aft/raft.h:2188     | In update_commit, new_commit_cft_idx: 210, last_idx: 211
2023-03-03T03:35:30.267229Z -0.002 0   [debug] ../src/consensus/aft/raft.h:2210     | Commit if possible 210 (ci: 210) (ti 40)
2023-03-03T03:35:30.267235Z -0.001 0   [trace] ../src/node/channels.h:224           | <- n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] (ESTABLISHED): decrypt(25 bytes, 0 bytes) (nonce=200)
2023-03-03T03:35:30.267238Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1666     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[39c6a463bd1af2a5478fe2a75df5bf5c80f7f1c1b7e7de37ef0ce1c3220bb40e] for index 211: success
2023-03-03T03:35:30.267241Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2188     | In update_commit, new_commit_cft_idx: 211, last_idx: 211
2023-03-03T03:35:30.267244Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2210     | Commit if possible 211 (ci: 210) (ti 42)
2023-03-03T03:35:30.267247Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2313     | Starting commit
2023-03-03T03:35:30.267250Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2329     | Compacting...
2023-03-03T03:35:30.267253Z -0.001 0   [trace] ../src/node/history.h:395            | mt_flush_to index=211
2023-03-03T03:35:30.267256Z -0.001 0   [trace] ../src/node/history.h:86             | History [3] <sha256 07c6245c9ecdf88ab5f25b534bb5a96f6e7438ff0609accca3a370c221a1ad7b>
2023-03-03T03:35:30.267260Z        100 [debug] ../src/host/ledger.h:1266            | Ledger commit: 211/211
2023-03-03T03:35:30.267266Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2333     | Commit on n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6]: 211
2023-03-03T03:35:30.267269Z -0.001 0   [trace] ../src/node/channels.h:224           | <- n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] (ESTABLISHED): decrypt(25 bytes, 0 bytes) (nonce=221)
2023-03-03T03:35:30.267272Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1666     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] for index 210: success
2023-03-03T03:35:30.267275Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2188     | In update_commit, new_commit_cft_idx: 211, last_idx: 211
2023-03-03T03:35:30.267278Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2210     | Commit if possible 211 (ci: 211) (ti 42)
2023-03-03T03:35:30.268384Z        100 [trace] ../src/host/tcp.h:746                | Allocating 16384 bytes for TCP read (49152 of quota remaining)
2023-03-03T03:35:30.268394Z        100 [debug] ../src/host/node_connections.h:40    | from node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] received 133 bytes
2023-03-03T03:35:30.268398Z        100 [debug] ../src/host/node_connections.h:86    | node in: from node n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa], size 129, type 1
2023-03-03T03:35:30.269460Z -0.001 0   [trace] ../src/node/channels.h:224           | <- n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] (ESTABLISHED): decrypt(25 bytes, 0 bytes) (nonce=222)
2023-03-03T03:35:30.269464Z -0.001 0   [debug] ../src/consensus/aft/raft.h:1666     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[5b80a388064f2b6f15bd952a02faf266e30342eaa1598d4c0d441074eae507fa] for index 211: success
2023-03-03T03:35:30.269468Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2188     | In update_commit, new_commit_cft_idx: 211, last_idx: 211
2023-03-03T03:35:30.269471Z -0.001 0   [debug] ../src/consensus/aft/raft.h:2210     | Commit if possible 211 (ci: 211) (ti 42)
2023-03-03T03:35:30.270200Z        100 [trace] ../src/host/tcp.h:746                | Allocating 16384 bytes for TCP read (49152 of quota remaining)
2023-03-03T03:35:30.270212Z        100 [debug] ../src/host/node_connections.h:40    | from node n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] received 133 bytes
2023-03-03T03:35:30.270217Z        100 [debug] ../src/host/node_connections.h:86    | node in: from node n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b], size 129, type 1
2023-03-03T03:35:30.271279Z -0.002 0   [trace] ../src/node/channels.h:224           | <- n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] (ESTABLISHED): decrypt(25 bytes, 0 bytes) (nonce=54)
2023-03-03T03:35:30.271284Z -0.002 0   [debug] ../src/consensus/aft/raft.h:1666     | Recv append entries response to n[062e57f05447e4370d35f0b492dff1b669257ef5332c7c424934f5de36bd21c6] from n[40aeaeb8e2df29a6e2b9c5a3177b136d8cb888e3bfcbd3ce3e07b8cee3f4546b] for index 211: success
2023-03-03T03:35:30.271288Z -0.002 0   [debug] ../src/consensus/aft/raft.h:2188     | In update_commit, new_commit_cft_idx: 211, last_idx: 211
2023-03-03T03:35:30.271291Z -0.002 0   [debug] ../src/consensus/aft/raft.h:2210     | Commit if possible 211 (ci: 211) (ti 42)
2023-03-03T03:35:30.306258Z -0.001 0   [debug] ../src/node/history.h:750            | Signed at 212 in view: 42, previous signature was at 211
2023-03-03T03:35:30.306264Z -0.001 0   [debug] ../src/kv/store.h:928                | Store::commit 212 globally_committable
2023-03-03T03:35:30.306268Z -0.001 0   [trace] ../src/kv/store.h:962                | Inserting pending tx at 212

[achamayou]

Another occurrence: https://dev.azure.com/MSRC-CCF/CCF/_build/results?buildId=66592&view=logs&j=f3457e4b-102d-5a4f-f801-dc119e4853a8&t=ec4c947d-98d7-5162-4c2f-20c4a5e8f908

[jumaffre]

Another occurrence: https://dev.azure.com/MSRC-CCF/CCF/_build/results?buildId=66630&view=logs&j=abb827b0-1387-5f0d-393d-8da14bd7f99d&t=776cc0e6-a7f3-556a-baca-d314f367d1cc&l=1905

[eddyashton]

Removed this assertion in #5121.