state_getKeysPaged times out (with small pages)

[josepot]

In some instances the state_getKeysPaged RPC call times out, even when requesting very small items.

For instance, when trying to retrieve the keys of the storage entry Staking.Nominators, the following request:

{
  id: 'thisOneFails',
  jsonrpc: '2.0',
  method: 'state_getKeysPaged',
  params: [
    '0x5f3e4907f716ac89b6347d15ececedca9c6a637f62ae2af1c7e31eed7e96be04',
    2,
    '0x5f3e4907f716ac89b6347d15ececedca9c6a637f62ae2af1c7e31eed7e96be04'
  ]
}

always fails.

However, the equivalent request for the Staking.Validators entry:

 {
  id: 'thisOneWorks',
  jsonrpc: '2.0',
  method: 'state_getKeysPaged',
  params: [
    '0x5f3e4907f716ac89b6347d15ececedca88dcde934c658227ee1dfafcd6e16903',
    2,
    '0x5f3e4907f716ac89b6347d15ececedca88dcde934c658227ee1dfafcd6e16903'
  ]
}

works perfectly fine.

Here you can find a demonstration of this issue

[tomaka]

What do you mean by "timed out"? Is it a timeout enforced by PolkadotJS?

This RPC call is implemented by downloading every single key of the prefix then keeping only the appropriate count and the ones that follow the start key.
There's no way for a light client to implement this RPC call in an optimal way, which is why there's no equivalent in the new JSON-RPC API.
I can however try to optimize it a bit through guesswork/heuristics.

[josepot]

What do you mean by "timed out"? Is it a timeout enforced by PolkadotJS?

Nope. I'm not using PolkadotJS, please have a look at the demo that I've provided.

The response that I get from smoldot for the problematic request is:

{
  "jsonrpc":"2.0",
  "id":"thisOneFails",
  "error":{"code":-32000,"message":"Storage query errors:\n- Timeout\n- Timeout"}
}

This RPC call is implemented by downloading every single key of the prefix then keeping only the appropriate count and the ones that follow the start key.

🤔 then I don't quite understand why that request is failing, since that request is only asking for the first 2 keys... I found this on the docs section of the metadata entry of Staking.Nominator, which perhaps could be relevant? I'm not sure TBH:

The map from nominator stash key to their nomination preferences, namely the validators that
they wish to support.                                                                   
                                                                                            
Note that the keys of this storage map might become non-decodable in case the            
[`Config::MaxNominations`] configuration is decreased. In this rare case, these nominators
are still existent in storage, their key is correct and retrievable (i.e. `contains_key`
indicates that they exist), but their value cannot be decoded. Therefore, the non-decodable
nominators will effectively not-exist, until they re-submit their preferences such that it
is within the bounds of the newly set `Config::MaxNominations`.                        
                                                                                        
This implies that `::iter_keys().count()` and `::iter().count()` might return different   
values for this map. Moreover, the main `::count()` is aligned with the former, namely the 
number of keys that exist.                                                              
                                                                                           
Lastly, if any of the nominators become non-decodable, they can be chilled immediately via
[`Call::chill_other`] dispatchable by anyone.                                            
                                                                                            
TWOX-NOTE: SAFE since `AccountId` is a secure hash.                                       

I can however try to optimize it a bit through guesswork/heuristics.

That would be amazing! Because having the ability of iterating over the Staking.Nominators entries (even if had to be done very slowly) is quite a critical functionality for some dApss 🙏

Thanks @tomaka !

[tomaka]

The time out is probably caused by the fact that the response is too large. This would be solved by finishing the transition to state_version=1, but also by splitting big requests into smaller ones.

[josepot]

This would be solved by finishing the transition to state_version=1

Sorry, but I'm not following, could you please elaborate on this? 🙏

but also by splitting big requests into smaller ones

🤔 how could that be done from the side of the consumer? The demo that I provided is only requesting for 2 keys...

[tomaka]

These are just notes for myself, not addressed to you as reporter of the issue.

[josepot]

FWIW querying the values of this exact same storage key with the new JSON-RPC API seems to work perfectly fine.

[josepot]

FWIW querying the values of this exact same storage key with the new JSON-RPC API seems to work perfectly fine.

I take this back... 😞 I mistakenly tried it against the Staking.Validators key while I thought that I was trying it against Staking.Nominators. I'm very sorry about that!

Trying a descendantValues storage query with the new JSON-RPC API with the Staking.Nominators key (0x5f3e4907f716ac89b6347d15ececedca9c6a637f62ae2af1c7e31eed7e96be04) results in the emission of the operationInaccessible event.

I get that fixing this could be pretty challenging, and I don’t want to be that person, but this issue is kinda holding up a demo I’m working on. If it's a big pain to sort out, I can shift the demo around a bit.

Any chance you could let me know if this is fixable, and what the timeline might look like?

Thanks a ton! 🙏

[tomaka]

As mentioned in #1209, this issue is presumed fixed in v2.0.4 (#1213).
I'm leaving this issue open so that you can confirm whether this is the case. If it is still not working, I'd need logs to debug.

[josepot]

As mentioned in #1209, this issue is presumed fixed in v2.0.4 (#1213). I'm leaving this issue open so that you can confirm whether this is the case. If it is still not working, I'd need logs to debug.

Unfortunately v2.0.4 does not only not fix this issue, but it also breaks some storage requests that were previously working. Basically, what I'm experiencing is: I receive an operationStorageDone event before I have received any storage items. I will setup a stackblitz POC to demo the issue. Do you prefer me to do that in a new issue or should I reuse this one?

[tomaka]

Found the problem, and it was already there before #1209, just #1209 revealed it 😬

[josepot]

2.0.5 fixed the issue introduced by 2.0.4. Unfortunately, though, with 2.0.5 I still get the operationInaccessible event when I try to query the descendantValues of Staking.Nominators on polkadot 😞

[tomaka]

Please provide some debug (log level 4) logs.

[josepot]

Please provide some debug (log level 4) logs.

here you go:
logs.txt

[tomaka]

Please provide some debug (log level 4) logs.

here you go: logs.txt

Is this all? I don't see any event being sent back regarding the chainHead_storage after the started event.
It seems that the logs end when the request was still ongoing.

[josepot]

Please provide some debug (log level 4) logs.

here you go: logs.txt

Is this all? I don't see any event being sent back regarding the chainHead_storage after the started event. It seems that the logs end when the request was still ongoing.

The last log:

[json-rpc-polkadot] JSON-RPC <= {"jsonrpc":"2.0","method":"chainHead_unstable_followEvent","params":{"subscription":"1","result":{"e…

is the operationInaccessible event.

[josepot]

Here, I enhanced the smoldot logs with my own logs. I hope that helps
logs.txt

EDIT: I just updated the logs with a small improvement.

[tomaka]

Ah right I forgot that the storage events were now reported as chainHead_follow

[tomaka]

Unfortunately I can't figure out the problem from these logs, it seems to actually not be related to what I've been saying earlier and might be caused by for example a failure to decode the networking response or something like that.
I'm going to investigate locally today or tomorrow.

[tomaka]

Note for self: here's the small demo tweak I use to test this:

defaultChain.then(async (chain) => {
    chain.sendJsonRpc('{"jsonrpc":"2.0","id":1,"method":"chainHead_unstable_follow","params":[true]}');
    const subId = JSON.parse(await chain.nextJsonRpcResponse()).result;
    const finHash = JSON.parse(await chain.nextJsonRpcResponse()).params.result.finalizedBlockHash;
    chain.sendJsonRpc('{"jsonrpc":"2.0","id":2,"method":"chainHead_unstable_storage","params":["1","' + finHash + '",[{"key":"0x5f3e4907f716ac89b6347d15ececedca9c6a637f62ae2af1c7e31eed7e96be04","type":"descendantsValues"}],null]}');
    while (true) {
        const resp = JSON.parse(await chain.nextJsonRpcResponse());
        if (resp.params && resp.params.result.event.startsWith('operation'))
            console.log(resp);
    }
});

It might become useful later.

[josepot]

It seems that 2.0.6 fixes this issue 🎉 Should I close this @tomaka ?