Something seems wrong with "Witness produced block at wrong time" #557

New issue

Open

opened 2023-08-02 18:49:18 +00:00 by christophersanborn · 3 comments

christophersanborn commented

2023-08-02 18:49:18 +00:00

(Migrated from gitlab.com)

The stuck node agrees with the rest of the network up to one block behind its head block. But its head block differs. As a result, all later blocks accepted by the network as a whole are "unlinkable" to the stuck node. Frustratingly, though, the stuck node will not "switch forks" to reject its divergent head block and adopt the correct block in its place.

Details:

The majority of the network (including every block producer) have accepted and built upon block 003d5d1bac18277d5c3fcbbce40f9997a2da80db at block height 4021531. The stuck node however has a different block in this position (and no blocks beyond it).

The stuck node is able to receive the correct block, as receipt of this block is seen in the p2p logs. Each time it receives the block, the node rejects it due to "Witness produced block at wrong time," and then immediately disconnects the remote node which offered this (correct) block. As a result of which, the stuck node spends most of its time with zero peers (as determined by get_connected_peers API call), and only occasionally accepts a remote connection, only to later reject it (presumably for offering this block).

Receipt and rejection of the node are seen in the log of STUCK NODE (165.232.84.196) here:

2023-08-02T16:00:08.207 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] Failed to push sync block 4021531 (id:003d5d1bac18277d5c3fcbbce40f9997a2da80db): client rejected sync block sent by peer: {"code":10,"name":"assert_exception","message":"Assert Exception","stack":[{"context":{"level":"error","file":"db_block.cpp","line":350,"method":"verify_signing_witness","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"new_block.witness == wid: Witness produced block at wrong time","data":{"block witness":"1.6.9","scheduled":"1.6.7","slot_num":2}},{"context":{"level":"warn","file":"db_block.cpp","line":306,"method":"_push_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"new_block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]}}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]},"block_id":"003d5d1bac18277d5c3fcbbce40f9997a2da80db"},"sync_mode":true}}]}                     node.cpp:3322
2023-08-02T16:00:08.208 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] disconnecting client 24.199.104.149:19777 because it offered us the rejected block                  node.cpp:3461

And also we see the rejection of the subsequent block for "block does not link to known chain" (although it does link to the rejected block).

2023-08-02T16:00:08.208 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] Failed to push sync block 4021532 (id:003d5d1c10a389887514104066e84109a5f9ef5f): client rejected sync block sent by peer: {"code":90006,"name":"unlinkable_block_exception","message":"unlinkable block","stack":[{"context":{"level":"error","file":"application.cpp","line":458,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"Error when pushing block:\n${e}","data":{"e":"3080000 unlinkable_block_exception: unlinkable block\nblock does not link to known chain\n    {}\n    th_a  db_block.cpp:219 _push_block\n\n    {\"new_block\":{\"previous\":\"003d5d1bac18277d5c3fcbbce40f9997a2da80db\",\"timestamp\":\"2023-08-01T23:10:57\",\"witness\":\"1.6.4\",\"next_secret_hash\":\"86434b6c7aeef5e5eac2c54aa40ccd28d18397ed\",\"previous_secret\":\"a5902d2f502fcac35d36086cb16a5c520073a7e7\",\"transaction_merkle_root\":\"0000000000000000000000000000000000000000\",\"extensions\":[],\"witness_signature\":\"1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea\",\"transactions\":[]}}\n    th_a  db_block.cpp:306 _push_block"}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1bac18277d5c3fcbbce40f9997a2da80db","timestamp":"2023-08-01T23:10:57","witness":"1.6.4","next_secret_hash":"86434b6c7aeef5e5eac2c54aa40ccd28d18397ed","previous_secret":"a5902d2f502fcac35d36086cb16a5c520073a7e7","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea","transactions":[]},"block_id":"003d5d1c10a389887514104066e84109a5f9ef5f"},"sync_mode":true}}]}                    node.cpp:3322

For another view, in the p2p logs of the NON-stuck node, we see the same moment, where the non-stuck node logs the the remote node rejected it:

2023-08-02T16:00:08.273 p2p:message read_loop on_closing_connectio ] Peer 165.232.84.196:19777 is disconnecting us because of an error: You offered us a block that we reject as invalid, exception: {"co
de":10,"name":"assert_exception","message":"Assert Exception","stack":[{"context":{"level":"error","file":"db_block.cpp","line":350,"method":"verify_signing_witness","hostname":"","thread_name":"th_a",
"timestamp":"2023-08-02T16:00:08"},"format":"new_block.witness == wid: Witness produced block at wrong time","data":{"block witness":"1.6.9","scheduled":"1.6.7","slot_num":2}},{"context":{"level":"warn
","file":"db_block.cpp","line":306,"method":"_push_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"new_block":{"previous":"003d5d1ae0b3acc11c5dac5b7897
40fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction
_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3
848f2f8414c4e94a8e08c63","transactions":[]}}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"
},"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac
01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451b
d7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]},"block_id":"003d5d1bac18277d5c3fcbbce40f9997a2da80db"},"sync_mode":true}}]}
                      node.cpp:3175

General commentary:

The reason given for rejecting the block is "Witness produced block at wrong time," but this seems improbable, as the rest of the network has accepted that the block is in the proper time slot (accounting for missed blocks). Note that this occurred during a window when there a several missed blocks in a row. So there is a gap between 4021530 and 4021531 (and a bigger gap on the stuck chain than on the non-stuck chain). But still, the network selected a chain (and achieved a quorum — LIB has advanced). The stuck node is failing to realize and follow the consensus chain.

Additional details:

Block 4021530 (agreed on both chains):

+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| Key                     | Value                                                                                                                              |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| extensions              | []                                                                                                                                 |
| next_secret_hash        | 2c9ff9cc0a7e6d4845f3940e8d429bfec9840b81                                                                                           |
| previous                | 003d5d19a7693242c00e33520ca7cf431610e10a                                                                                           |
| previous_secret         | 988fd40275dd1e964d0c3a420ce00f38c095cb7b                                                                                           |
| timestamp               | 2023-08-01T23:10:45                                                                                                                |
| transaction_merkle_root | 0000000000000000000000000000000000000000                                                                                           |
| transactions            | []                                                                                                                                 |
|                         |                                                                                                                                    |
| witness                 | 1.6.7                                                                                                                              |
| witness_signature       | 1f3c24f91fc469274d78b473823ff14c490a7eea895dafd5598342a02cebec4688633e7ac4502cb404d97b9747ed0342fd47466b7a580ee09dd6fc9a900c709085 |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+

Block 4021531 (first from main chain then from stuck chain):

Main chain:

+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| Key                     | Value                                                                                                                              |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| extensions              | []                                                                                                                                 |
| next_secret_hash        | 039afde5ee444470c8309ad38f4036aac01d7ad9                                                                                           |
| previous                | 003d5d1ae0b3acc11c5dac5b789740fde725dcd4                                                                                           |
| previous_secret         | 110c00469b8313c9b12c04245ff4db972083c687                                                                                           |
| timestamp               | 2023-08-01T23:10:54                                                                                                                |
| transaction_merkle_root | 0000000000000000000000000000000000000000                                                                                           |
| transactions            | []                                                                                                                                 |
|                         |                                                                                                                                    |
| witness                 | 1.6.9                                                                                                                              |
| witness_signature       | 1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63 |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+

Stuck chain:

+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| Key                     | Value                                                                                                                              |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| extensions              | []                                                                                                                                 |
| next_secret_hash        | e869f17058c0470ad95cc29ab54c9c8f72467bef                                                                                           |
| previous                | 003d5d1ae0b3acc11c5dac5b789740fde725dcd4                                                                                           |
| previous_secret         | 515290d6ec3b6c3bb2983e3cfe52f7c40f630639                                                                                           |
| timestamp               | 2023-08-01T23:11:03                                                                                                                |
| transaction_merkle_root | 0000000000000000000000000000000000000000                                                                                           |
| transactions            | []                                                                                                                                 |
|                         |                                                                                                                                    |
| witness                 | 1.6.2                                                                                                                              |
| witness_signature       | 1f7e2615eba3cde19e72dfe5eab3b8d1f48a5f25f69143ef38f7e29774b208a63a42311d2805fef8356a928357829fcba87d80b5844278f6f22e4ed45f7083c0bd |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+

Block 4021532 (only on non-stuck chain):

+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| Key                     | Value                                                                                                                              |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+
| extensions              | []                                                                                                                                 |
| next_secret_hash        | 86434b6c7aeef5e5eac2c54aa40ccd28d18397ed                                                                                           |
| previous                | 003d5d1bac18277d5c3fcbbce40f9997a2da80db                                                                                           |
| previous_secret         | a5902d2f502fcac35d36086cb16a5c520073a7e7                                                                                           |
| timestamp               | 2023-08-01T23:10:57                                                                                                                |
| transaction_merkle_root | 0000000000000000000000000000000000000000                                                                                           |
| transactions            | []                                                                                                                                 |
|                         |                                                                                                                                    |
| witness                 | 1.6.4                                                                                                                              |
| witness_signature       | 1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea |
+-------------------------+------------------------------------------------------------------------------------------------------------------------------------+

This ticket looks at two nodes on the public test net (out of about 11 in total). One node is stuck, and will not advance past the block that it is stuck at. The other node is keeping up with the rest of the network. The stuck node is NOT a block producer (though it is configured to act as a SON). The stuck node agrees with the rest of the network up to one block behind its head block. But its head block differs. As a result, all later blocks accepted by the network as a whole are "unlinkable" to the stuck node. Frustratingly, though, the stuck node will not "switch forks" to reject its divergent head block and adopt the correct block in its place. ### Details: The majority of the network (including every block producer) have accepted and built upon block `003d5d1bac18277d5c3fcbbce40f9997a2da80db` at block height 4021531. The **stuck node** however has a different block in this position (and no blocks beyond it). The stuck node is able to receive the correct block, as receipt of this block is seen in the p2p logs. Each time it receives the block, the node rejects it due to "Witness produced block at wrong time," and then immediately disconnects the remote node which offered this (correct) block. As a result of which, the stuck node spends most of its time with zero peers (as determined by `get_connected_peers` API call), and only occasionally accepts a remote connection, only to later reject it (presumably for offering this block). Receipt and rejection of the node are seen in the log of STUCK NODE (165.232.84.196) here: ```plaintext 2023-08-02T16:00:08.207 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] Failed to push sync block 4021531 (id:003d5d1bac18277d5c3fcbbce40f9997a2da80db): client rejected sync block sent by peer: {"code":10,"name":"assert_exception","message":"Assert Exception","stack":[{"context":{"level":"error","file":"db_block.cpp","line":350,"method":"verify_signing_witness","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"new_block.witness == wid: Witness produced block at wrong time","data":{"block witness":"1.6.9","scheduled":"1.6.7","slot_num":2}},{"context":{"level":"warn","file":"db_block.cpp","line":306,"method":"_push_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"new_block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]}}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]},"block_id":"003d5d1bac18277d5c3fcbbce40f9997a2da80db"},"sync_mode":true}}]} node.cpp:3322 2023-08-02T16:00:08.208 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] disconnecting client 24.199.104.149:19777 because it offered us the rejected block node.cpp:3461 ``` And also we see the rejection of the subsequent block for "block does not link to known chain" (although it does link to the rejected block). ```plaintext 2023-08-02T16:00:08.208 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] Failed to push sync block 4021532 (id:003d5d1c10a389887514104066e84109a5f9ef5f): client rejected sync block sent by peer: {"code":90006,"name":"unlinkable_block_exception","message":"unlinkable block","stack":[{"context":{"level":"error","file":"application.cpp","line":458,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"Error when pushing block:\n${e}","data":{"e":"3080000 unlinkable_block_exception: unlinkable block\nblock does not link to known chain\n {}\n th_a db_block.cpp:219 _push_block\n\n {\"new_block\":{\"previous\":\"003d5d1bac18277d5c3fcbbce40f9997a2da80db\",\"timestamp\":\"2023-08-01T23:10:57\",\"witness\":\"1.6.4\",\"next_secret_hash\":\"86434b6c7aeef5e5eac2c54aa40ccd28d18397ed\",\"previous_secret\":\"a5902d2f502fcac35d36086cb16a5c520073a7e7\",\"transaction_merkle_root\":\"0000000000000000000000000000000000000000\",\"extensions\":[],\"witness_signature\":\"1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea\",\"transactions\":[]}}\n th_a db_block.cpp:306 _push_block"}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1bac18277d5c3fcbbce40f9997a2da80db","timestamp":"2023-08-01T23:10:57","witness":"1.6.4","next_secret_hash":"86434b6c7aeef5e5eac2c54aa40ccd28d18397ed","previous_secret":"a5902d2f502fcac35d36086cb16a5c520073a7e7","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea","transactions":[]},"block_id":"003d5d1c10a389887514104066e84109a5f9ef5f"},"sync_mode":true}}]} node.cpp:3322 ``` For another view, in the p2p logs of the NON-stuck node, we see the same moment, where the non-stuck node logs the the remote node rejected it: ```plaintext 2023-08-02T16:00:08.273 p2p:message read_loop on_closing_connectio ] Peer 165.232.84.196:19777 is disconnecting us because of an error: You offered us a block that we reject as invalid, exception: {"co de":10,"name":"assert_exception","message":"Assert Exception","stack":[{"context":{"level":"error","file":"db_block.cpp","line":350,"method":"verify_signing_witness","hostname":"","thread_name":"th_a", "timestamp":"2023-08-02T16:00:08"},"format":"new_block.witness == wid: Witness produced block at wrong time","data":{"block witness":"1.6.9","scheduled":"1.6.7","slot_num":2}},{"context":{"level":"warn ","file":"db_block.cpp","line":306,"method":"_push_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08"},"format":"","data":{"new_block":{"previous":"003d5d1ae0b3acc11c5dac5b7897 40fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction _merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3 848f2f8414c4e94a8e08c63","transactions":[]}}},{"context":{"level":"warn","file":"application.cpp","line":469,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2023-08-02T16:00:08" },"format":"","data":{"blk_msg":{"block":{"previous":"003d5d1ae0b3acc11c5dac5b789740fde725dcd4","timestamp":"2023-08-01T23:10:54","witness":"1.6.9","next_secret_hash":"039afde5ee444470c8309ad38f4036aac 01d7ad9","previous_secret":"110c00469b8313c9b12c04245ff4db972083c687","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f6fa752d15bc8235ef37451b d7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63","transactions":[]},"block_id":"003d5d1bac18277d5c3fcbbce40f9997a2da80db"},"sync_mode":true}}]} node.cpp:3175 ``` ### General commentary: The reason given for rejecting the block is "Witness produced block at wrong time," but this seems improbable, as the rest of the network has accepted that the block is in the proper time slot (accounting for missed blocks). Note that this occurred during a window when there a several missed blocks in a row. So there is a gap between 4021530 and 4021531 (and a bigger gap on the stuck chain than on the non-stuck chain). But still, the network selected a chain (and achieved a quorum — LIB has advanced). The stuck node is failing to realize and follow the consensus chain. ### Additional details: ##### Block 4021530 (agreed on both chains): ```plaintext +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | Key | Value | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | extensions | [] | | next_secret_hash | 2c9ff9cc0a7e6d4845f3940e8d429bfec9840b81 | | previous | 003d5d19a7693242c00e33520ca7cf431610e10a | | previous_secret | 988fd40275dd1e964d0c3a420ce00f38c095cb7b | | timestamp | 2023-08-01T23:10:45 | | transaction_merkle_root | 0000000000000000000000000000000000000000 | | transactions | [] | | | | | witness | 1.6.7 | | witness_signature | 1f3c24f91fc469274d78b473823ff14c490a7eea895dafd5598342a02cebec4688633e7ac4502cb404d97b9747ed0342fd47466b7a580ee09dd6fc9a900c709085 | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ ``` ##### Block 4021531 (first from main chain then from stuck chain): Main chain: ```plaintext +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | Key | Value | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | extensions | [] | | next_secret_hash | 039afde5ee444470c8309ad38f4036aac01d7ad9 | | previous | 003d5d1ae0b3acc11c5dac5b789740fde725dcd4 | | previous_secret | 110c00469b8313c9b12c04245ff4db972083c687 | | timestamp | 2023-08-01T23:10:54 | | transaction_merkle_root | 0000000000000000000000000000000000000000 | | transactions | [] | | | | | witness | 1.6.9 | | witness_signature | 1f6fa752d15bc8235ef37451bd7925861ffe11a773c0027f0ff4c7221292e38cc62350a85f2f111c642365284a45dbb65b1860c59e3848f2f8414c4e94a8e08c63 | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ ``` Stuck chain: ```plaintext +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | Key | Value | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | extensions | [] | | next_secret_hash | e869f17058c0470ad95cc29ab54c9c8f72467bef | | previous | 003d5d1ae0b3acc11c5dac5b789740fde725dcd4 | | previous_secret | 515290d6ec3b6c3bb2983e3cfe52f7c40f630639 | | timestamp | 2023-08-01T23:11:03 | | transaction_merkle_root | 0000000000000000000000000000000000000000 | | transactions | [] | | | | | witness | 1.6.2 | | witness_signature | 1f7e2615eba3cde19e72dfe5eab3b8d1f48a5f25f69143ef38f7e29774b208a63a42311d2805fef8356a928357829fcba87d80b5844278f6f22e4ed45f7083c0bd | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ ``` ##### Block 4021532 (only on non-stuck chain): ```plaintext +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | Key | Value | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ | extensions | [] | | next_secret_hash | 86434b6c7aeef5e5eac2c54aa40ccd28d18397ed | | previous | 003d5d1bac18277d5c3fcbbce40f9997a2da80db | | previous_secret | a5902d2f502fcac35d36086cb16a5c520073a7e7 | | timestamp | 2023-08-01T23:10:57 | | transaction_merkle_root | 0000000000000000000000000000000000000000 | | transactions | [] | | | | | witness | 1.6.4 | | witness_signature | 1f3b2793754b8b3dda8ecac8ff222db81a22fc5d3d368d43a4dde24c73fc9cef413de377bf88861e7d8028673a1b6af02846de657f8f5e157f61f4ca827c7aefea | +-------------------------+------------------------------------------------------------------------------------------------------------------------------------+ ```

christophersanborn commented

2023-08-02 18:49:18 +00:00

(Migrated from gitlab.com)

assigned to @vampik

christophersanborn commented

2023-08-02 19:06:23 +00:00

(Migrated from gitlab.com)

Uploading selected p2p logs and block contents from each of the referenced nodes:

SON-node-stuck-20230802.tar.gz

Uploading selected p2p logs and block contents from each of the referenced nodes: [SON-node-stuck-20230802.tar.gz](/uploads/61d09c63aa05a907f9f3c970e86522d5/SON-node-stuck-20230802.tar.gz)

christophersanborn commented

2023-08-07 16:10:32 +00:00

(Migrated from gitlab.com)

Console log from earlier today

Context:

My (public test net) SON node (SON only, not block-producing) is "stuck" at block 4119567 (about two days old, timestamp 2023-08-05T14:00:00 -- a maintenance block. It hasn't applied a block since. Note, the node is NOT on a "fork" -- this block is found on the majority network.
My node is spending most of its time with no connected peers. Either my node is rejecting remotes, or the remotes are rejecting my node.
When it occasionally establishes a peer connection, it receives blocks from 4119568 onwards from the peer. The blocks it receives are blocks that were accepted by the majority network (all BP witnesses are producing).
Block 4119568 has timestamp 2023-08-05T14:00:12 -- four slots past 4119567 (the network clearly missed three blocks at this time) and was produced by witness 1.6.5.
My node rejects 4119568 with Witness produced block at wrong time {"block witness":"1.6.5", "scheduled":"1.6.2", "slot_num":4}
Because my node rejected 4119568, it then also rejects all future blocks (4119569 onwards) with block does not link to known chain.
It then disconnects all peers (or is disconnected by them) and goes back into a long period of no connected peers.

Console log snippet:

1982000ms th_a       witness.cpp:267               maybe_produce_block  ] slot: 59460 scheduled_witness: 1.6.8 scheduled_time: 2023-08-07T15:33:00 now: 2023-08-07T15:33:02 
1982001ms th_a       witness.cpp:202               block_production_loo ] Not producing block because I don't have the private key for TEST5TK5F739VKuZQ2YChs1F11kJgSHUw7EWmES4yxBdz2aCaaSWzR
1982669ms th_a       db_block.cpp:300              _push_block          ] Failed to push new block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.5","scheduled":"1.6.2","slot_num":4}
    th_a  db_block.cpp:944 validate_block_header

    {"next_block.block_num()":4119568}
    th_a  db_block.cpp:799 _apply_block
1982671ms th_a       application.cpp:460           handle_block         ] Error when pushing block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.5","scheduled":"1.6.2","slot_num":4}
    th_a  db_block.cpp:944 validate_block_header

    {"next_block.block_num()":4119568}
    th_a  db_block.cpp:799 _apply_block

    {"new_block":{"previous":"003edc0f779f2c06059d54f4e4380b51b733b7e8","timestamp":"2023-08-05T14:00:12","witness":"1.6.5","next_secret_hash":"32dff84aef73278beec99441fa5206e05735b49a","previous_secret":"ad8b28be0f765de94c0fdd4b64e57e0f4ed5df2d","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"205894a1bc27841e2549e0aaf132ce509df4c4860cab849954ed97352dddc404871354d63b1ed563d075ef77f990531d2feb613a5b8847ddc2406e942900ec1f0d","transactions":[]}}
    th_a  db_block.cpp:306 _push_block
1982672ms th_a       fork_database.cpp:65          push_block           ] Pushing block to fork database that failed to link: 003edc11ad3d759e9d337626619614de0cfa524d, 4119569
1982672ms th_a       fork_database.cpp:66          push_block           ] Head: 4119568, 003edc10a128e85b2d3fe46300a74f2b576365b0
1982673ms th_a       application.cpp:457           handle_block         ] Error when pushing block:
3080000 unlinkable_block_exception: unlinkable block
block does not link to known chain
    {}
    th_a  fork_database.cpp:86 _push_block

    {"new_block":{"previous":"003edc10a128e85b2d3fe46300a74f2b576365b0","timestamp":"2023-08-05T14:00:15","witness":"1.6.6","next_secret_hash":"722b9d67b4259ab75357704db8bd189b6017f287","previous_secret":"9efa4fdedcefbdcb9eaa744b948bdca3d9b878a6","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f126a87dc6d087d5153c4a3070e9406b5c4d4984977096ee929da8688857a7a6138395a53b7b889d7af3cf0364f22c603f57eb5c5782a2dfde2a05e7171127833","transactions":[]}}
    th_a  db_block.cpp:306 _push_block

### Console log from earlier today Context: - My (public test net) SON node (SON only, not block-producing) is "stuck" at block 4119567 (about two days old, timestamp `2023-08-05T14:00:00` -- a maintenance block. It hasn't applied a block since. Note, the node is NOT on a "fork" -- this block is found on the majority network. - My node is spending _most_ of its time with no connected peers. Either my node is rejecting remotes, or the remotes are rejecting my node. - When it occasionally establishes a peer connection, it receives blocks from 4119568 onwards from the peer. The blocks it receives are blocks that were accepted by the majority network (all BP witnesses are producing). - Block 4119568 has timestamp `2023-08-05T14:00:12` -- four slots past 4119567 (the network clearly missed three blocks at this time) and was produced by witness `1.6.5`. - My node rejects 4119568 with `Witness produced block at wrong time {"block witness":"1.6.5", "scheduled":"1.6.2", "slot_num":4}` - Because my node rejected 4119568, it then also rejects all future blocks (4119569 onwards) with `block does not link to known chain`. - It then disconnects all peers (or is disconnected by them) and goes back into a long period of no connected peers. Console log snippet: ``` 1982000ms th_a witness.cpp:267 maybe_produce_block ] slot: 59460 scheduled_witness: 1.6.8 scheduled_time: 2023-08-07T15:33:00 now: 2023-08-07T15:33:02 1982001ms th_a witness.cpp:202 block_production_loo ] Not producing block because I don't have the private key for TEST5TK5F739VKuZQ2YChs1F11kJgSHUw7EWmES4yxBdz2aCaaSWzR 1982669ms th_a db_block.cpp:300 _push_block ] Failed to push new block: 10 assert_exception: Assert Exception next_block.witness == scheduled_witness: Witness produced block at wrong time {"block witness":"1.6.5","scheduled":"1.6.2","slot_num":4} th_a db_block.cpp:944 validate_block_header {"next_block.block_num()":4119568} th_a db_block.cpp:799 _apply_block 1982671ms th_a application.cpp:460 handle_block ] Error when pushing block: 10 assert_exception: Assert Exception next_block.witness == scheduled_witness: Witness produced block at wrong time {"block witness":"1.6.5","scheduled":"1.6.2","slot_num":4} th_a db_block.cpp:944 validate_block_header {"next_block.block_num()":4119568} th_a db_block.cpp:799 _apply_block {"new_block":{"previous":"003edc0f779f2c06059d54f4e4380b51b733b7e8","timestamp":"2023-08-05T14:00:12","witness":"1.6.5","next_secret_hash":"32dff84aef73278beec99441fa5206e05735b49a","previous_secret":"ad8b28be0f765de94c0fdd4b64e57e0f4ed5df2d","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"205894a1bc27841e2549e0aaf132ce509df4c4860cab849954ed97352dddc404871354d63b1ed563d075ef77f990531d2feb613a5b8847ddc2406e942900ec1f0d","transactions":[]}} th_a db_block.cpp:306 _push_block 1982672ms th_a fork_database.cpp:65 push_block ] Pushing block to fork database that failed to link: 003edc11ad3d759e9d337626619614de0cfa524d, 4119569 1982672ms th_a fork_database.cpp:66 push_block ] Head: 4119568, 003edc10a128e85b2d3fe46300a74f2b576365b0 1982673ms th_a application.cpp:457 handle_block ] Error when pushing block: 3080000 unlinkable_block_exception: unlinkable block block does not link to known chain {} th_a fork_database.cpp:86 _push_block {"new_block":{"previous":"003edc10a128e85b2d3fe46300a74f2b576365b0","timestamp":"2023-08-05T14:00:15","witness":"1.6.6","next_secret_hash":"722b9d67b4259ab75357704db8bd189b6017f287","previous_secret":"9efa4fdedcefbdcb9eaa744b948bdca3d9b878a6","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f126a87dc6d087d5153c4a3070e9406b5c4d4984977096ee929da8688857a7a6138395a53b7b889d7af3cf0364f22c603f57eb5c5782a2dfde2a05e7171127833","transactions":[]}} th_a db_block.cpp:306 _push_block ```