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

[helin6]

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 https://github.com/paritytech/json-rpc-interface-spec/ 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]

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]

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]

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:

• Sometimes it takes too many times with the height 0 for light client, is it due to the Peers number about bootnode?
• Is there any light node(with rpc server) write by rust just like wasm-node's javascript?

Thanks again!