JSON-RPC messages arrive out of order

[josepot]

The chainHead subscription implementation is not fully compliant with the JSON-RPC specification, as messages occasionally arrive out of order. This can cause inconsistencies in the event handling process. Below is an example demonstrating this issue:

{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"newBlock","blockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a","parentBlockHash":"0xd0a64ca092b6ae44620ae99b3d6cf66664f2eaab8da5d8637304516fd29822f0","newRuntime":null}}}
{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"bestBlockChanged","bestBlockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a"}}}
{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"bestBlockChanged","bestBlockHash":"0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d"}}}
{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"finalized","finalizedBlockHashes":["0xb1796a1e2d6ef0d4ea4ae8c8a6126689389c336f2ee460356b47de5515559ca3"],"prunedBlockHashes":[]}}}
{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"newBlock","blockHash":"0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d","parentBlockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a","newRuntime":null}}}

In this sequence, the third message (bestBlockChanged with bestBlockHash 0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d) should logically be the last one, as it refers to a block that has not yet been received via the newBlock event.

This issue was identified by @ryanleecode while working with the RPC endpoint wss://westend-people-rpc.polkadot.io, which is believed to be running the latest version of the node. The issue was originally reported in this Polkadot-API issue.

According to the JSON-RPC spec, the order of these messages is critical to ensure correct event processing.

cc @jsdw @lexnv @bkchr

[jsdw]

Noted; we're having a look!

[jsdw]

@JoseP, by any chance do you have the ability to produce those logs with timestamps? Knowing which events were sent together (or close) might help narrow down the code path, as might a few lines of extra context at the end of those logs :) No worries if not though as we will be trying to reproduce the issue locally anyway!

[josepot]

@Josep, by any chance do you have the ability to produce those logs with timestamps?

yeah, the original logs that Ryan captured using the polkadot-api/logs-provider have the timestamps:

1-2024-08-28T17:29:10.088Z->>-{"jsonrpc":"2.0","id":"1-38","method":"chainHead_v1_unpin","params":["w2bkfzBzOuXeldcS",["0xb70b2af07a93a3c038b0824eda7a388845c881370d51032ad405be0ff1fb0699"]]}
1-2024-08-28T17:29:10.195Z-<<-{"jsonrpc":"2.0","result":null,"id":"1-38"}
1-2024-08-28T17:29:12.219Z-<<-{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"newBlock","blockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a","parentBlockHash":"0xd0a64ca092b6ae44620ae99b3d6cf66664f2eaab8da5d8637304516fd29822f0","newRuntime":null}}}
1-2024-08-28T17:29:12.224Z-<<-{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"bestBlockChanged","bestBlockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a"}}}
1-2024-08-28T17:29:18.234Z-<<-{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"bestBlockChanged","bestBlockHash":"0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d"}}}
1-2024-08-28T17:29:18.237Z-<<-{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"finalized","finalizedBlockHashes":["0xb1796a1e2d6ef0d4ea4ae8c8a6126689389c336f2ee460356b47de5515559ca3"],"prunedBlockHashes":[]}}}
1-2024-08-28T17:29:18.237Z-<<-{"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"w2bkfzBzOuXeldcS","result":{"event":"newBlock","blockHash":"0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d","parentBlockHash":"0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a","newRuntime":null}}}

The actual format is: ISO_DATE followed by -<<- for incoming messages or ->>- for outcoming messages, followed by the JSON message.

[lexnv]

Have modified the chainHead-cli tool to subscribe to the chainHead follow method and panic in case a best block is received before a new block:

RUST_LOG=info cargo run -- subscribe

I can't seem to reproduce this for around ~10 minutes, but will keep this running.

Looking at the logs, this seems to happen after the initialized event indeed. Thanks a lot for the details here Josep! 🙏

One thing worth considering here would be changing the subscription stream of new blocks:

polkadot-sdk/substrate/client/api/src/client.rs

Lines 64 to 74 in cc7ebe0

	/// A source of blockchain events.
	pub trait BlockchainEvents<Block: BlockT> {
	/// Get block import event stream.
	///
	/// Not guaranteed to be fired for every imported block, only fired when the node
	/// has synced to the tip or there is a re-org. Use `every_import_notification_stream()`
	/// if you want a notification of every imported block regardless.
	fn import_notification_stream(&self) -> ImportNotifications<Block>;
	/// Get a stream of every imported block.
	fn every_import_notification_stream(&self) -> ImportNotifications<Block>;

We currently use import_notification_stream, instead of every_import_notification_stream but that needs a closer look

[lexnv]

I was able to reproduce the issue with the chainHead-cli.

2024-08-29T10:57:36.275176Z  INFO chainhead_cli: Raw event: RawValue({"bestBlockHash":"0x2f08058c7e373b9c6165db91cd3f3bb75037e0b298dcb8c3e481af9d41a9eef0","event":"bestBlockChanged"})
2024-08-29T10:57:36.275231Z  INFO chainhead_cli: BestBlock event: BestBlock { event: "bestBlockChanged", bestBlockHash: "0x2f08058c7e373b9c6165db91cd3f3bb75037e0b298dcb8c3e481af9d41a9eef0" }
2024-08-29T10:57:36.275245Z  INFO chainhead_cli:  block entry Entry(VacantEntry("0x2f08058c7e373b9c6165db91cd3f3bb75037e0b298dcb8c3e481af9d41a9eef0"))
thread 'main' panicked at src/main.rs:251:25:

                        (best vacant) Expected block entry occupied with New state

I believe the culprit comes from:

polkadot-sdk/substrate/client/rpc-spec-v2/src/chain_head/chain_head_follow.rs

Lines 564 to 585 in cc7ebe0

	if is_in_pruned_list || is_not_last_finalized {
	// We need to generate a best block event.
	let best_block_hash = self.client.info().best_hash;
	// Defensive check against state missmatch.
	if best_block_hash == current_best_block {
	// The client doest not have any new information about the best block.
	// The information from `.info()` is updated from the DB as the last
	// step of the finalization and it should be up to date.
	// If the info is outdated, there is nothing the RPC can do for now.
	debug!(
	target: LOG_TARGET,
	"[follow][id={:?}] Client does not contain different best block",
	self.sub_id,
	);
	} else {
	// The RPC needs to also submit a new best block changed before the
	// finalized event.
	self.current_best_block = Some(best_block_hash);
	events
	.push(FollowEvent::BestBlockChanged(BestBlockChanged { best_block_hash }));
	}

Will try to reproduce locally to gain some extra insights.

[josepot]

I can't seem to reproduce this for around ~10 minutes, but will keep this running.

Looking at the logs, this seems to happen after the initialized event indeed. Thanks a lot for the details here Josep! 🙏

I'm pretty sure that this only happens when a new block is discovered that belongs to a new fork and that block also happens to now be the best-block. So, yeah, that's why this can take a very long time to reproduce.

In the logs you can see exactly that happening: block 0xb2499db97650a723e2e3adeac3393cd395827db5aeef4512f4ab8c6a925a278a gets announced and 5ms later it's reported as the best block, then the problematic message appears (10ms later) stating that the best-block is now 0xa5770d656f360a3cb1aa8be285ecec748e7063b1317eddc9f36db3dc8a78573d (which has never been seen before). What happens next is interesting, though: 3ms later 2 messages arrive "together" the first message announces finality, and then we get the message that announces the newBlock event of the problematic block.