Repeated operationInaccessible on call TaggedTransactionQueue_validate_transaction for System.apply_authorized_upgrade

[voliva]

Before broadcasting transactions, polkadot-api validates them with a runtime call to TaggedTransactionQueue_validate_transaction.

We have this issue in papi-console polkadot-api/papi-console#35 where they wanted to try sending a System.apply_authorized_upgrade (unsigned tx) for polkadot 1.4, but the transaction doesn't get broadcasted.

Looking at the JSON-RPC logs, it seems that the call gets stuck in a loop of operationInaccessible, and retrying it after a few ms.

Looking at the logs I can see that smoldot internally retries a few times until it fails as well:

smoldot[json-rpc-polkadot(4)] json-rpc-request-queued; request={"jsonrpc":"2.0","id":"2-46","method":"chainHead_v1_call","params":["GtJnfhu95ow96MjjAoA5bWczUeW4K5Tb3U1BKJ68qD8c","0xe895f3db599e2dc8d7209b48a864822c12310e3bdae7060e62131af9803c6888","TaggedTransactionQueue_validate_transaction","0x02eee77100040002d…
smoldot[runtime-polkadot(5)] foreground-pin-pinned-block-runtime; subscription_id=4, block_hash=0xe895…6888
smoldot[runtime-polkadot(4)] foreground-runtime-call-start; block_hash=0xe895…6888, block_number=24913412, block_state_trie_root_hash=0x5f1e…1fb4, function_name=TaggedTransactionQueue_validate_transaction, required_api_version=None, parameters_vectored=0x02ee…6888, total_attempts=3, timeout_per_request=20s
smoldot[runtime-polkadot(5)] foreground-runtime-call-request-start; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, call_proof_target=12D3KooWS9ZcvRxyzrSf6p63QfTCWs12nLoNKhGux865crgxVA4H
smoldot[network(4)] call-proof-request-started; chain=polkadot, target=12D3KooWS9ZcvRxyzrSf6p63QfTCWs12nLoNKhGux865crgxVA4H, block_hash=0xe895…6888, function=TaggedTransactionQueue_validate_transaction
smoldot[network(4)] call-proof-request-error; chain=polkadot, target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha, error=Request(Substream(SubstreamReset))
smoldot[runtime-polkadot(5)] foreground-runtime-call-progress-fail; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, remaining_attempts=2, error=Request(Request(Substream(SubstreamReset)))
smoldot[runtime-polkadot(5)] foreground-runtime-call-request-start; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, call_proof_target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha
smoldot[network(4)] call-proof-request-started; chain=polkadot, target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha, block_hash=0xe895…6888, function=TaggedTransactionQueue_validate_transaction
smoldot[network(4)] call-proof-request-error; chain=polkadot, target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha, error=Request(Substream(SubstreamReset))
smoldot[runtime-polkadot(5)] foreground-runtime-call-progress-fail; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, remaining_attempts=1, error=Request(Request(Substream(SubstreamReset)))
smoldot[runtime-polkadot(5)] foreground-runtime-call-request-start; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, call_proof_target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha
smoldot[network(4)] call-proof-request-started; chain=polkadot, target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha, block_hash=0xe895…6888, function=TaggedTransactionQueue_validate_transaction
smoldot[network(4)] call-proof-request-error; chain=polkadot, target=12D3KooWHJBMZgt7ymAdTRtadPcGXpJw79vBGe8z53r9JMkZW7Ha, error=Request(Substream(SubstreamReset))
smoldot[runtime-polkadot(5)] foreground-runtime-call-progress-fail; block_hash=0xe895…6888, function_name=TaggedTransactionQueue_validate_transaction, parameters_vectored=0x02ee…6888, remaining_attempts=0, error=Request(Request(Substream(SubstreamReset)))
smoldot[json-rpc-polkadot(4)] json-rpc-response-yielded; response={"jsonrpc":"2.0","method":"chainHead_v1_followEvent","params":{"subscription":"GtJnfhu95ow96MjjAoA5bWczUeW4K5Tb3U1BKJ68qD8c","result":{"event":"operationInaccessible","operationId":"ED7hNy4zcJyTwSQ9c8pg56o4U6CNUMLUyNFNo8K8sg6G"}}}

My suspicion is that is due to the size of the call (as System.apply_authorized_upgrade has the compressed runtime wasm as payload), might be related to #1526, but for runtime calls.

Please let me know if you need a reproduction repo or better logs.

[tomaka]

My suspicion is that is due to the size of the call (as System.apply_authorized_upgrade has the compressed runtime wasm as payload), might be related to #1526, but for runtime calls.

It unfortunately looks like this is indeed the case.

When it comes to debugging this, the situation is the same as for #1985 (comment): from the smoldot point of view I can't know why the full node resets the substream, so we have to do the same kind of debugging as what I explain in that issue.