chain_subscribeFinalizedHeads subscription seems to not produce blocks

[lexnv]

We have detected a regression in subxt when switching from

• smoldot 0.16.0 to 0.17.0
• smoldot-light 0.14.0 to 0.15.0

After further investigating the issue, the culprit seems to be the chain_subscribeFinalizedHeads subscription.
The subxt::finalized_headers_subscription subscribes to chain_subscribeFinalizedHeads, then tries to consume 4 finalized blocks from the subscription.

2024-01-30T12:42:06.465155Z DEBUG json-rpc-polkadot: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"7", "method":"chain_subscribeFinalizedHeads","params":[]}
2024-01-30T12:42:06.465190Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","id":"7","result":"2"}
2024-01-30T12:42:06.465203Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0x5c327dda59b4b4dd79a6c83d24cdd34f9e7c67a3cbe4b30b2743c2c606370959","extrinsicsRoot":"0x4617f45edd1b4d2e6234d846ce5a0995e500a3a38e76f746430642561f87a…
2024-01-30T12:42:06.465232Z DEBUG json-rpc-polkadot: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"8", "method":"chain_getFinalizedHead","params":[]}
2024-01-30T12:42:06.465288Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","id":"8","result":"0xf7eae1ee7ada4c14159a4fa59405cfd8739bfa53f0aaee795bcbf3184beb5d63"}
2024-01-30T12:42:06.465312Z DEBUG json-rpc-polkadot: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"9", "method":"chain_getHeader","params":["0xf7eae1ee7ada4c14159a4fa59405cfd8739bfa53f0aaee795bcbf3184beb5d63"]}
2024-01-30T12:42:06.465360Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","id":"9","result":{"parentHash":"0x5c327dda59b4b4dd79a6c83d24cdd34f9e7c67a3cbe4b30b2743c2c606370959","extrinsicsRoot":"0x4617f45edd1b4d2e6234d846ce5a0995e500a3a38e76f746430642561f87a079","stateRoot":"0xf930dec93372d195ed127f51492fe19…
2024-01-30T12:42:06.465397Z DEBUG json-rpc-polkadot: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"10", "method":"chain_getFinalizedHead","params":[]}
2024-01-30T12:42:06.465430Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","id":"10","result":"0xf7eae1ee7ada4c14159a4fa59405cfd8739bfa53f0aaee795bcbf3184beb5d63"}
2024-01-30T12:42:12.731617Z DEBUG json-rpc-polkadot: json-rpc-response-yielded; response={"jsonrpc":"2.0","method":"chain_newHead","params":{"subscription":"1","result":{"parentHash":"0xede259d945d1effa9557c1f980f2384ab7b254ba543dcfb26e5d3be729a30f2b","extrinsicsRoot":"0x1693a183ee32a1a0e5cf6673091c4fc50aaadefb44b0a5d3cc2263328a410582","…
2024-01-30T12:42:12.731661Z DEBUG json-rpc-polkadot: json-rpc-request-queued; request={"jsonrpc":"2.0","id":"11", "method":"chain_unsubscribeNewHeads","params":["1"]}

From the previous logs, extracted from the attached regression-log.txt, smoldot provides one notification response for the subscription id 2. However, we receive all responses in the older version of smoldot.

The older version produces the expected logs with the 4 finalized blocks, extracted from the attached older-version-log.txt:

2024-01-30T12:48:30.341562Z DEBUG json-rpc-polkadot: JSON-RPC => {"jsonrpc":"2.0","id":"7", "method":"chain_subscribeFinalizedHeads","params":[]}
2024-01-30T12:48:30.341622Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","id":"7","result":"2"}
2024-01-30T12:48:30.341646Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0x9d59cecd7b4e5f8d988824e4dd7458a53dbd10831982fc77a8689b3e27499190","extrinsicsRoot":"0x17be37f3c5902a93633c7c7fecbb6bcf1dd634045bc69e13779cc5d8c7fc5…
2024-01-30T12:48:30.341696Z DEBUG json-rpc-polkadot: JSON-RPC => {"jsonrpc":"2.0","id":"8", "method":"chain_getFinalizedHead","params":[]}
2024-01-30T12:48:30.341755Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","id":"8","result":"0x0cc58741d95cbce516bdfa3d3916cba25e30693154aa330a4f3b763dbd0da1a4"}
2024-01-30T12:48:30.341789Z DEBUG json-rpc-polkadot: JSON-RPC => {"jsonrpc":"2.0","id":"9", "method":"chain_getHeader","params":["0x0cc58741d95cbce516bdfa3d3916cba25e30693154aa330a4f3b763dbd0da1a4"]}
2024-01-30T12:48:30.341843Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","id":"9","result":{"parentHash":"0x9d59cecd7b4e5f8d988824e4dd7458a53dbd10831982fc77a8689b3e27499190","extrinsicsRoot":"0x17be37f3c5902a93633c7c7fecbb6bcf1dd634045bc69e13779cc5d8c7fc5d03","stateRoot":"0xd5eca3a1fcfa117746312c0eab99ffc…
2024-01-30T12:48:30.341902Z DEBUG json-rpc-polkadot: JSON-RPC => {"jsonrpc":"2.0","id":"10", "method":"chain_getFinalizedHead","params":[]}
2024-01-30T12:48:30.341940Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","id":"10","result":"0x0cc58741d95cbce516bdfa3d3916cba25e30693154aa330a4f3b763dbd0da1a4"}
2024-01-30T12:48:30.670506Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0x0cc58741d95cbce516bdfa3d3916cba25e30693154aa330a4f3b763dbd0da1a4","extrinsicsRoot":"0xa8006216585c93a13cf581ba8400c7f87fd8282135d6a4c86a7be35ac893d…
2024-01-30T12:48:30.670557Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0x544c4d06a62aa624d779c58d7dbca94bceec132d4b7a9f9479d3d8ec2a9b2aeb","extrinsicsRoot":"0xa959bd598db790e2f3b6a8d0119d95b25b185220679cd8032393a76e223f8…
2024-01-30T12:48:36.351851Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_newHead","params":{"subscription":"1","result":{"parentHash":"0xedfdcfbd2ee86df42a045a374a992d40eeb9509a96621f8652a50a65f203396c","extrinsicsRoot":"0x16d8fdc92697d43e558a309f88aa6a81efe5480d4a46e8a9ffd0422df966d06e","…
2024-01-30T12:48:36.351886Z DEBUG json-rpc-polkadot: JSON-RPC => {"jsonrpc":"2.0","id":"11", "method":"chain_unsubscribeNewHeads","params":["1"]}
2024-01-30T12:48:43.130056Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0xda9450fa241ea5a0baaa10360504ca83fa2e49b3b601ba1388c21b988d560065","extrinsicsRoot":"0x42d3420beecf8c4ca44e043f1e5fcbfb5e9d880766a77fb26ccc4e583f557…
2024-01-30T12:48:43.130107Z DEBUG json-rpc-polkadot: JSON-RPC <= {"jsonrpc":"2.0","method":"chain_finalizedHead","params":{"subscription":"2","result":{"parentHash":"0x333a4444a960a50cb9c2cb1fedcf686967d35b287f8b4eb7f979cbb373fe6bf2","extrinsicsRoot":"0x3aba4eb413da1b6dfde4536d1e6c2f5b64029e5b83a809065e147ff19fa90…

Repro steps

git clone https://github.com/paritytech/subxt.git
cd subxt/testing/integration-tests

# Origin Master with smoldot 0.16.0 and smoldot-light 0.14.0
# 3 iterations of the test finishes in 29.57s, 36.12s, 40.42s (average 35.37s)
git checkout 7762da8 
cargo test --release --package integration-tests --features unstable-light-client -- --nocapture

# PR with smoldot 0.17.0 and smoldot-light 0.15.0
# This runs for more than 10 minutes
git checkout lexnv/update-smoldot
cargo test --release --package integration-tests --features unstable-light-client -- --nocapture

Logs

Logs have been captured with RUST_LOG="trace,polling=info,async_io=info,soketto=info" cargo test --release --package integration-tests --features unstable-light-client -- --nocapture

older-version-log.txt
regression-log.txt

cc paritytech/subxt#1400

Please let me know if I could provide more details/logs here, since I can reproduce the issue constantly 🙏

[tomaka]

This is off-topic, but I would suggest you take a look at the logs that SubXT generates and truncate the JSON-RPC responses, because 2/3rds of the log file is the metadata being dumped

[tomaka]

What I suspect happens is:
With the old version of smoldot, we perform a warp sync, after which we send a GrandPa neighbor packet to everyone to inform them of an update to our finalized block.
With the new version of smoldot, we don't warp sync and thus don't send a neighbor packet, and thus peers don't send back GrandPa commits.

Normally, immediately after opening a GrandPa substream we send a neighbor packet, and this should be enough, but for some reason this doesn't work. Knowing the Substrate code here, I wouldn't be surprised if it was a Substrate issue.

[tomaka]

Maybe it would be a good idea to ask for justifications of blocks that peers report to have finalized but for which we haven't received a commit.

[lexnv]

The old rpcs are producing blocks, however the current version of smoldot is slower to produce finalized blocks:

• chore(deps): Update smoldot to the latest version paritytech/subxt#1400

15:22:59.314045Z TRACE subxt-light-client-background-task Received from smoldot response='{"jsonrpc":"2.0","id":"9","result":"0xa9a22c3a556f0e9256cb98c0e99490b3b82e10f1c4ca1dd4b80cf144b06eb4e4"}' chain=ChainId(0)
Finalized hash: 0xa9a22c3a556f0e9256cb98c0e99490b3b82e10f1c4ca1dd4b80cf144b06eb4e4 took 975.477µs

15:25:50.187944Z sync-service-polkadot warp-sync-chain-information-build-success 
15:25:50.188179Z sync-service-polkadot GrandPa warp sync finished to #21372707 (0x8335…1420) 
15:25:53.922377Z INFO runtime-polkadotSuccessfully compiled runtime. Spec version: 1002004. Size of `:code`: 1.5 MiB. 

15:25:53.923444Z TRACE subxt-light-client-background-task Received from smoldot response='{"jsonrpc":"2.0","id":"11","result":{"parentHash":"0xec91a63f92615a4da43c3a116deef5367e416e4860bbe92dbadb0c7cb2d1b019","extrinsicsRoot":"0x2bd1e3e97ed1a08afd6fcbc4d6df599ad74625715b6761675d22f5e334de467c","stateRoot":"0xe41a8120251c7a800d329b69a01e6d912615' chain=ChainId(0)
Second block took 174.610506318s

Version used (a similar behavior is present on origin/main):

• smoldot v0.18.0
• smoldot-light v0.16.2

With an older version of smoldot v0.16.0 and smoldot-light v0.14.0 the syncing + subxt testing takes ~30ms

smoldot-logs-grandpa.txt

Let me know if I could provide more info, thanks 🙏

[lexnv]

The old RPCs are now producing blocks as expected, have raised #1896 for a sync regression, thanks 🙏