search

smol-dot / smoldot

Lightweight client for Substrate-based chains, such as Polkadot and Kusama.
GNU General Public License v3.0
180 stars 48 forks source link

Justification targets a block that isn't in the chain. #1970

Open helin6 opened 8 hours ago

helin6 commented 8 hours ago

Hi, I used subxt light client to connect to my local substrate node, but it doesn't connect(sometimes it worked well). Here are the debug logs:

Details

2024-09-24T07:34:54.164232Z INFO smoldot: Chain initialization complete for local_testnet. Name: "Local Testnet". Genesis hash: 0xc21d…76fd. Chain specification starting at: 0x3c3c…b4dc (#7031) 2024-09-24T07:34:54.164922Z DEBUG network: chain-added; id=local_testnet 2024-09-24T07:34:54.164990Z INFO smoldot: Chain specification of local_testnet contains a `genesis.raw` item. It is possible to significantly improve the initialization time by replacing the `"raw": ...` field with `"stateRootHash": "0xf189547aa60118c8df2b59e1be66cee41fbb556166e765cdffcc29c3add5538a"` 2024-09-24T07:34:54.165400Z DEBUG runtime-local_testnet: block-runtime-download-start; block_hash=0x3c3c…b4dc 2024-09-24T07:34:54.165795Z DEBUG runtime-local_testnet: runtime-download-error; block_hashes=0x3c3c…b4dc, error=StorageQuery(StorageQueryError { errors: [] }) 2024-09-24T07:34:54.165869Z DEBUG network: discovery-skipped-no-peer; chain=local_testnet 2024-09-24T07:34:54.166838Z DEBUG json-rpc-local_testnet: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"1", "method":"chain_getFinalizedHead","params":null} 2024-09-24T07:34:54.167125Z DEBUG network: slot-assigned; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:54.167506Z WARN json-rpc-local_testnet: The JSON-RPC client has just called a JSON-RPC function from the legacy JSON-RPC API (chain_getFinalizedHead). Legacy JSON-RPC functions have loose semantics and cannot be properly implemented on a light client. You are encouraged to use the new JSON-RPC API instead. The legacy JSON-RPC API functions will be deprecated and removed in the distant future. 2024-09-24T07:34:54.167914Z DEBUG network: connection-started; expected_peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, remote_addr=/ip4/127.0.0.1/tcp/30333, local_peer_id=12D3KooWByNSUjxNwKcEcnQBX1rCYB5FsDKihDUAe85uF2PYRyKn 2024-09-24T07:34:54.168278Z DEBUG network: slot-assigned; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.168697Z DEBUG network: connection-started; expected_peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, remote_addr=/ip4/127.0.0.1/tcp/30334, local_peer_id=12D3KooWGrwaLYijezuFozmokekYzAFUhxRNxf1KsSAfquEFCQ83 2024-09-24T07:34:54.172235Z DEBUG network: handshake-finished; remote_addr=/ip4/127.0.0.1/tcp/30333, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:54.172290Z DEBUG network: gossip-open-start; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:54.172394Z DEBUG network: handshake-finished; remote_addr=/ip4/127.0.0.1/tcp/30334, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.172442Z DEBUG network: gossip-open-start; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.174370Z DEBUG network: gossip-open-success; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, best_number=10724, best_hash=0x289d…9e45 2024-09-24T07:34:54.174511Z DEBUG network: gossip-open-success; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, best_number=10724, best_hash=0xf3f7…e028 2024-09-24T07:34:54.174816Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, start=0x289d…9e45, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.174908Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, start=0xf3f7…e028, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.183090Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, num_blocks=128, block_data_total_size=32.1 kiB 2024-09-24T07:34:54.183425Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, num_blocks=128, block_data_total_size=32.0 kiB 2024-09-24T07:34:54.184278Z DEBUG network: grandpa-neighbor-packet-received; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, round_number=802, set_id=35, commit_finalized_height=10721 2024-09-24T07:34:54.192219Z DEBUG network: warp-sync-request-started; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, start=0x3c3c…b4dc 2024-09-24T07:34:54.192274Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, start=0xc456…5702, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.192487Z DEBUG network: grandpa-neighbor-packet-received; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, round_number=802, set_id=35, commit_finalized_height=10721 2024-09-24T07:34:54.195047Z DEBUG network: warp-sync-request-success; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, num_fragments=8, is_finished=true 2024-09-24T07:34:54.195322Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, start=0xc456…5702, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.196130Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0xe9cf…8d7e, verified_height=7434 2024-09-24T07:34:54.196830Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x06df…299b, verified_height=8027 2024-09-24T07:34:54.197521Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x8ca0…0ba1, verified_height=8606 2024-09-24T07:34:54.198214Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x7fbc…5692, verified_height=8659 2024-09-24T07:34:54.198905Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x741b…16ed, verified_height=9175 2024-09-24T07:34:54.199594Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0xc53e…48e8, verified_height=9769 2024-09-24T07:34:54.199709Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, num_blocks=128, block_data_total_size=32.1 kiB 2024-09-24T07:34:54.200326Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x1992…3f53, verified_height=10365 2024-09-24T07:34:54.202183Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, num_blocks=128, block_data_total_size=32.1 kiB 2024-09-24T07:34:54.225892Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, start=0x0c55…ff62, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.225986Z DEBUG network: blocks-request-started; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, start=0x0c55…ff62, num=256, descending=true, header=true, body=false, justifications=true 2024-09-24T07:34:54.226683Z DEBUG sync-service-local_testnet: warp-sync-fragment-verify-success; sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, verified_hash=0x464e…86ca, verified_height=10721 2024-09-24T07:34:54.232813Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, num_blocks=128, block_data_total_size=32.0 kiB 2024-09-24T07:34:54.233170Z DEBUG network: blocks-request-success; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, num_blocks=128, block_data_total_size=32.0 kiB 2024-09-24T07:34:54.258280Z DEBUG network: storage-proof-request-started; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, block_hash=0x464e…86ca 2024-09-24T07:34:54.258365Z DEBUG network: call-proof-request-started; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, block_hash=0x464e…86ca, function=BabeApi_configuration 2024-09-24T07:34:54.258533Z DEBUG sync-service-local_testnet: finality-proof-verify-error; error=FinalityVerify(UnknownTargetBlock { block_number: 10365, block_hash: [25, 146, 47, 122, 44, 248, 111, 82, 190, 218, 46, 158, 148, 95, 218, 94, 143, 131, 225, 218, 253, 200, 140, 3, 97, 64, 199, 123, 229, 54, 63, 83] }), sender=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.258545Z WARN sync-service-local_testnet: Error while verifying justification: Justification targets a block (#10365) that isn't in the chain. 2024-09-24T07:34:54.258589Z DEBUG network: slot-unassigned; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, ban_duration=10s, reason=user-ban, user_reason=bad-justification 2024-09-24T07:34:54.258671Z DEBUG network: gossip-closed; chain=local_testnet, peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.258739Z DEBUG sync-service-local_testnet: finality-proof-verify-error; error=FinalityVerify(UnknownTargetBlock { block_number: 10365, block_hash: [25, 146, 47, 122, 44, 248, 111, 82, 190, 218, 46, 158, 148, 95, 218, 94, 143, 131, 225, 218, 253, 200, 140, 3, 97, 64, 199, 123, 229, 54, 63, 83] }), sender=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:54.258749Z WARN sync-service-local_testnet: Error while verifying justification: Justification targets a block (#10365) that isn't in the chain. 2024-09-24T07:34:54.258798Z DEBUG network: slot-unassigned; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, ban_duration=10s, reason=user-ban, user_reason=bad-justification 2024-09-24T07:34:54.258868Z DEBUG network: gossip-closed; chain=local_testnet, peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:54.647008Z DEBUG network: storage-proof-request-success; chain=local_testnet, target=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, total_size=3.0 MiB 2024-09-24T07:34:54.673199Z DEBUG network: call-proof-request-success; chain=local_testnet, target=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, total_size=1.2 kiB 2024-09-24T07:34:54.673651Z DEBUG network: identify-request-received; peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD 2024-09-24T07:34:54.673756Z DEBUG network: identify-request-received; peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob 2024-09-24T07:34:56.173686Z DEBUG network: pong; peer_id=12D3KooWBQrJEujQhZW8iQCbxjeyKNsRZsnEqs7j97TBsUxzL7ob, remote_addr=/ip4/127.0.0.1/tcp/30333, ping_time=612.959µs 2024-09-24T07:34:56.173730Z DEBUG network: pong; peer_id=12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD, remote_addr=/ip4/127.0.0.1/tcp/30334, ping_time=599.125µs

helin6 commented 8 hours ago

I also used js demo for wasm-node to connect with local node, same duck with this warn log: Error while verifying justification: Justification targets a block that isn't in the chain.

tomaka commented 6 hours ago

Thank you for the report.

This is normally harmless. The last time I've looked into it, it was simply a race condition where Substrate sends us a GrandPa commit message concerning a block before smoldot was able to download (or even know the existence of) the block in question. While smoldot discards the justification corresponding to this warning, once it learns about the existence of the block it can query finality info again, so the only thing that's been lost is a bit of time.

This race condition can only really be fixed by tweaking the networking protocol, which is a lot of efforts for this small problem.

I've considered simply removing the warning, but I'm been reluctant to do so because it might hide legitimate bugs.

helin6 commented 5 hours ago

Thank you for the report.

This is normally harmless. The last time I've looked into it, it was simply a race condition where Substrate sends us a GrandPa commit message concerning a block before smoldot was able to download (or even know the existence of) the block in question. While smoldot discards the justification corresponding to this warning, once it learns about the existence of the block it can query finality info again, so the only thing that's been lost is a bit of time.

This race condition can only really be fixed by tweaking the networking protocol, which is a lot of efforts for this small problem.

I've considered simply removing the warning, but I'm been reluctant to do so because it might hide legitimate bugs.

Thanks for your response! I got it and there are two questions for me now:

Thanks again!