txpool prunning issue when async backing is enabled

[serban300]

Stumbled upon this issue while investigating some bridge zombienet test failures after async backing was enabled on AssetHub Rococo.

Reproduction steps

1. Make sure that async backing is enabled on AssetHub Rococo: Check that UNINCLUDED_SEGMENT_CAPACITY is set to 3
2. Modify bridge_hub_rococo_local_network.toml in order to keep only 1 collator for AssetHub Rococo
3. Start a zombienet from bridge_hub_rococo_local_network.toml
4. Modify bridges_common.sh::call_polkadot_js_api() by removing --noWait
5. Execute $POLKADOT_SDK/cumulus/scripts/bridges_rococo_westend.sh reserve-transfer-assets-from-asset-hub-rococo-local . This script tries to send a limited_reserve_transfer_assets extrinsic to AssetHub Rococo

Result

{
  "limitedReserveTransferAssets": {
    "events": [],
    "status": "Ready"
  }
}
{
  "limitedReserveTransferAssets": {
    "events": [],
    "status": "Invalid"
  }
}

We can also get:

RpcError: 1014: Priority is too low: (349 vs 349): The transaction has too low priority to replace another transaction already in the pool.

But the root cause is the same.

Root cause

2024-02-05 11:16:00.028 DEBUG tokio-runtime-worker basic-authorship: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Pushed to the block.    
2024-02-05 11:16:00.028 DEBUG tokio-runtime-worker basic-authorship: [Parachain] No more transactions, proceeding with proposing.    
2024-02-05 11:16:00.029  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 4 (4 ms) [hash: 0xf328025dc93ead94a02cb9f1de30f8c298f36cf6c2db0f8cf01ab4be2f563b92; parent_hash: 0x7764…1b9a; extrinsics (3): [0xc9f4…3509, 0x5bde…22e0, 0x16f3…03b1]    
2024-02-05 11:16:00.031  INFO tokio-runtime-worker aura::cumulus: [Parachain] 🔖 Pre-sealed block for proposal at 4. Hash now 0xf3195f8b72801492df5ea2cbec916eea95ec30543f678cf551229915be7249fb, previously 0xf328025dc93ead94a02cb9f1de30f8c298f36cf6c2db0f8cf01ab4be2f563b92.
2024-02-05 11:16:00.031  INFO tokio-runtime-worker substrate: [Parachain] ✨ Imported #4 (0xf319…49fb)    
2024-02-05 11:16:00.032  INFO tokio-runtime-worker aura::cumulus: [Parachain] PoV size { header: 0.216796875kb, extrinsics: 3.7861328125kb, storage_proof: 7.0263671875kb }
2024-02-05 11:16:00.032  INFO tokio-runtime-worker aura::cumulus: [Parachain] Compressed PoV size: 7.0234375kb
2024-02-05 11:16:00.033 DEBUG tokio-runtime-worker parachain::collation-generation: [Relaychain] candidate is generated candidate_hash=0x3fe3ad3d88f6008be25ac10777c60bae968824c19dfdc7fe6a1059c8619d7a6d pov_hash=0x8831fcaf45472142631ce93bea179ab470a973a3b2ea5df44f982c0d7920fa85 relay_parent=0x4340775035cb1af2f77e7ca4d2421884bac7ea8bbaed42d0547a18f6773d1aa1 para_id=1000 traceID=84923528853503810641460319152517811118
2024-02-05 11:16:00.033 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Received session info session_index=1
2024-02-05 11:16:00.034 DEBUG tokio-runtime-worker parachain::collator-protocol: [Relaychain] Accepted collation, connecting to validators. para_id=1000 candidate_relay_parent=0x4340…1aa1 relay_parent_mode=Enabled { max_candidate_depth: 0, allowed_ancestry_len: 0 } candidate_hash=0x3fe3ad3d88f6008be25ac10777c60bae968824c19dfdc7fe6a1059c8619d7a6d pov_hash=0x8831fcaf45472142631ce93bea179ab470a973a3b2ea5df44f982c0d7920fa85 core=CoreIndex(1) current_validators=[Public(583660b57b1d247f1b5313099099de74f53579a9a26ad3c7de0119fbd03c7b60 (5E4NDym5...))] traceID=84923528853503810641460319152517811118
2024-02-05 11:16:00.034 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators request peer_set=Collation requested=1 failed_to_resolve=0
2024-02-05 11:16:00.034 DEBUG tokio-runtime-worker parachain::validator-discovery: [Relaychain] New ConnectToValidators resolved request peer_set=Collation num_peers=1 removed=0
2024-02-05 11:16:00.034  INFO tokio-runtime-worker sc_basic_authorship::basic_authorship: [Parachain] 🙌 Starting consensus session on top of parent 0xf3195f8b72801492df5ea2cbec916eea95ec30543f678cf551229915be7249fb    
2024-02-05 11:16:00.036 TRACE tokio-runtime-worker txpool: [Parachain] Transaction pool already processed block  #4    
2024-02-05 11:16:00.036 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Attempting to push transactions from the pool.    
2024-02-05 11:16:00.036 DEBUG tokio-runtime-worker basic-authorship: [Parachain] Pool status: PoolStatus { ready: 1, ready_bytes: 171, future: 0, future_bytes: 0 }    
2024-02-05 11:16:00.036 TRACE tokio-runtime-worker basic-authorship: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Pushing to the block.    
2024-02-05 11:16:00.037 TRACE tokio-runtime-worker xcm::weight: [Parachain] WeightInfoBounds message: Xcm([SetFeesMode { jit_withdraw: true }, TransferReserveAsset { assets: Assets([Asset { id: AssetId(Location { parents: 1, interior: Here }), fun: Fungible(5000000000000) }]), dest: Location { parents: 2, interior: X2([GlobalConsensus(Westend), Parachain(1000)]) }, xcm: Xcm([]) }])    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker txpool: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Reported as invalid. Will skip sub-chains while iterating.    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker basic-authorship: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Invalid transaction: Extrinsic is not valid: TransactionValidityError::Invalid(InvalidTransaction::Stale)    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker basic-authorship: [Parachain] No more transactions, proceeding with proposing.    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker txpool: [Parachain] Removing invalid transactions: [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1]    
2024-02-05 11:16:00.037 TRACE tokio-runtime-worker txpool: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Removed as part of the subtree.    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker txpool: [Parachain] Removed invalid transactions: [Transaction { hash: 0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1, priority: 349, valid_till: 63, bytes: 171, propagate: true, source: TransactionSource::External, requires: [], provides: [d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d01000000], data: 8400d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d0116d6429e89f7a2ff15ee24845c87e60584b697b40858a43b4701c53857a32e1f1b05b2dc89213d07f9414a2d2cc7451c90da6eca271d6ad6f6445196fc8ef18c05000400001f08030202090400a10f0300010100d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d0304000100000b005039278c040000000000}]    
2024-02-05 11:16:00.037 DEBUG tokio-runtime-worker txpool: [Parachain] [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Extrinsic invalid

From the node logs we see that the tx is included successfully in block 4, but then it's not prunned from the txpool. Then an attempt is made to also include it in block 5, but because it's already present in block 4, we get [0x16f37ab286e4ff51cc5c487c00a0a5e7615b1bb87a064bc29f31cf9bad0b03b1] Invalid transaction: Extrinsic is not valid: TransactionValidityError::Invalid(InvalidTransaction::Stale) and finally the client received the Invalid result.

[bkchr]

Should be this: #1202

[bkchr]

For now just ignore any "error" reports, they are very likely wrong.

[serban300]

Yes, will try to do this temporarily as a workaround. Thank you for the suggestion !

[bkchr]

5db7a7e & 42ac088 are how I fixed the coretime tests.