### Context: Testing reported regression of the new `txpool` when using `YAP` runtime ([#6089](https://github.com/paritytech/polkadot-sdk/pull/6089)) ### Environment *nodes binaries*: master, `7d5d72027eee124451f9c7d10d7cab5167f2f57e` *runtime* `YAP`: [#6089](https://github.com/paritytech/polkadot-sdk/pull/6089), `56f1fe5f3a55527e60a0d20d036678402796b7e1` :::spoiler zombienet file ``` [relaychain] default_image = "parity/polkadot:latest" default_command = "polkadot" chain = "rococo-local" [[relaychain.nodes]] name = "alice" ws_port = 9944 validator = true [[relaychain.nodes]] name = "bob" validator = true [[parachains]] id = 2000 cumulus_based = true # polkadot-parachain build-spec --chain yap-westend-live-2022 > yap.json chain = "yap-westend-live-2022.json" [[parachains.collators]] name = "charlie" validator = true image = "parity/polkadot-parachain:latest" command = "polkadot-parachain" # command = "test-parachain" ws_port = 9933 rpc_port = 8833 args = [ "--force-authoring", "--pool-limit 500000", "--pool-kbytes 2048000", "--rpc-max-connections 15000", "--rpc-max-response-size 150", "-lbasic-authorship=info", "-ltxpool=info", "-lsync=info", "-laura::cumulus=info", "-lpeerset=info", "-lsub-libp2p=info", "--pool-type=fork-aware", "--state-pruning=1024", "--rpc-max-subscriptions-per-connection=128000" ] ``` ::: *Test command*: ``` ttxt tx --send-threshold 20000 --chain=sub '--ws=ws://127.0.0.1:9933' from-single-account --account alice --count 64000` ``` ### Observation When executing w/o logs 7032 transactions are getting to the block (expected), but they are never finalized. :::spoiler `log` ``` 2024-11-20T16:07:31.135545Z INFO ttxt::block_monitor: FINALIZED block block_number=29 block_hash=0xf37cfed3cd3b55f723d3c6a62c3f77a86f7a5f5dcce5f241b62e5da34ee85ec7 extrinsics_count=2 2024-11-20T16:07:31.135905Z INFO ttxt::block_monitor: BEST block block_number=37 block_hash=0x61d428fd649a32413d57a51c2e3b94bfa5b44b5746b8420b02351a701b47a51a extrinsics_count=2 2024-11-20T16:07:32.929581Z INFO ttxt::block_monitor: FINALIZED block block_number=30 block_hash=0xcbe03e45262b33064f0596ad884e3287ad5b01f9c6edcf714cfb2cf575f4f6b8 extrinsics_count=2 2024-11-20T16:07:36.355125Z INFO ttxt::block_monitor: BEST block block_number=38 block_hash=0x59ad01c62086948cc2e10593e09bf67034b366cd2eea9c16a3ae5f1fdffc265b extrinsics_count=2 2024-11-20T16:07:40.933057Z INFO ttxt::block_monitor: FINALIZED block block_number=31 block_hash=0xb2b214b8b6ba2c6cc470ad93fab429e242755ab50527c440ccabf3fd35ff30fc extrinsics_count=2 2024-11-20T16:07:43.007687Z INFO ttxt::block_monitor: BEST block block_number=39 block_hash=0x7bb83d0f144c2aac69615099362b0c986fdd7def64ec4625a9b2f364189b0ae4 extrinsics_count=7032 2024-11-20T16:07:44.336179Z INFO ttxt::block_monitor: BEST block block_number=40 block_hash=0xec486a3bb4823f1cc2043e91a7def6c80a5b51474dc0b679ab16e31951fc07c7 extrinsics_count=7032 2024-11-20T16:07:44.934896Z INFO ttxt::block_monitor: FINALIZED block block_number=32 block_hash=0xe5758d50f01a67a238055e36a855f331a07b0f14b105b7a62fa150e6c1d3103c extrinsics_count=2 2024-11-20T16:07:49.145608Z INFO ttxt::block_monitor: BEST block block_number=41 block_hash=0x714d669a3bc4914c50cc99da74dd124a5c747c4502452da4056645480ce44ca6 extrinsics_count=7032 2024-11-20T16:07:50.501275Z INFO ttxt::block_monitor: BEST block block_number=42 block_hash=0x1adf0621ab3ef2c0b9b7db42eba874a74cc8aeeec26e7bae536315170521381d extrinsics_count=7032 2024-11-20T16:07:52.938687Z INFO ttxt::block_monitor: FINALIZED block block_number=33 block_hash=0x3c4a6eeace6fbdffa0f748a8ea5552bf1d4c67e50c117bd5cff1e8b1377a04c4 extrinsics_count=2 2024-11-20T16:07:56.940461Z INFO ttxt::block_monitor: FINALIZED block block_number=34 block_hash=0xf6ea174488a519bfe8eaae5e8581d79d910558b11764f9e296a84b35c755b772 extrinsics_count=2 2024-11-20T16:08:04.943590Z INFO ttxt::block_monitor: FINALIZED block block_number=35 block_hash=0xde070dbbdcbcce052b3cfba4e14f5b48772975ab1ccc326a6f76b08dd5c8a81b extrinsics_count=2 2024-11-20T16:08:08.945947Z INFO ttxt::block_monitor: FINALIZED block block_number=36 block_hash=0x7f2864d6108e132b27df229b408f08194844ff1aa563851e5907a9af249ba72d extrinsics_count=2 2024-11-20T16:08:12.185169Z INFO ttxt::block_monitor: BEST block block_number=43 block_hash=0x4b217c1efd413c1401d2c6c019c887a12f83da8ba8f2a3ec3f81c146d2e080a4 extrinsics_count=2 2024-11-20T16:08:12.355231Z INFO ttxt::block_monitor: BEST block block_number=44 block_hash=0x8d57b947b4b94c28efdc1c07b65604f8c85216678e4df389a3e846e5e723455e extrinsics_count=2 2024-11-20T16:08:19.155634Z INFO ttxt::block_monitor: BEST block block_number=45 block_hash=0x55056910548c39abdc82c9237f9a78c3ac845762cc4ffc24d0775df1bc605360 extrinsics_count=7032 2024-11-20T16:08:20.394833Z INFO ttxt::block_monitor: BEST block block_number=46 block_hash=0x09f910247206b0b698cfe98c0ebf800fd115d2923450a9863a7569f92394ffcf extrinsics_count=7032 2024-11-20T16:08:20.955971Z INFO ttxt::block_monitor: FINALIZED block block_number=37 block_hash=0x013c27989ebfefd71d282cf7de3c0aa066d0bae87e0edff25395fe5410197ee8 extrinsics_count=2 2024-11-20T16:08:28.958718Z INFO ttxt::block_monitor: FINALIZED block block_number=38 block_hash=0x291c1f353214e84afcf8b5addccb7626608073df38fd65997829ee5eef940f3f extrinsics_count=2 2024-11-20T16:08:32.960331Z INFO ttxt::block_monitor: FINALIZED block block_number=39 block_hash=0x7b068d6b063518574d990e8e449a35502e2c0a6976775a305ffae2d75386ca34 extrinsics_count=2 2024-11-20T16:08:36.354775Z INFO ttxt::block_monitor: BEST block block_number=47 block_hash=0x9c359e7d229d7a667a357933a6e5905413d2ba7b3d2ab9b713047979873cb7db extrinsics_count=2 2024-11-20T16:08:40.963857Z INFO ttxt::block_monitor: FINALIZED block block_number=40 block_hash=0x7189f0ec485119338667ab2aa22a628e8ff7090c459a3006b5af29aa66ff3ece extrinsics_count=2 2024-11-20T16:08:43.046840Z INFO ttxt::block_monitor: BEST block block_number=48 block_hash=0xeb1398941184b0285fb701e9c0fff8d5d989b7aeb9c53490d3574fd817e32252 extrinsics_count=7032 2024-11-20T16:08:44.263274Z INFO ttxt::block_monitor: BEST block block_number=49 block_hash=0x2bcee28fa25ebe26c25782bea0f019eb238dd04a6210dbace04cdf50fcebe9c9 extrinsics_count=7032 2024-11-20T16:08:44.966030Z INFO ttxt::block_monitor: FINALIZED block block_number=41 block_hash=0x97c4fa9d672004c7eed69399d8191a0bd3cc87eccfe7a9ef73fcd97c7b75177b extrinsics_count=2 2024-11-20T16:08:48.987476Z INFO ttxt::block_monitor: BEST block block_number=50 block_hash=0x5dc7cfa45c80c11ad18d69e64334060aa479bc57e175cd4744f5f190e0335782 extrinsics_count=7032 2024-11-20T16:08:50.243662Z INFO ttxt::block_monitor: BEST block block_number=51 block_hash=0x299ffaa3ca684affd86eefe7004459647990555301c0b7a91ee96a51f4c8161d extrinsics_count=7032 2024-11-20T16:08:52.970016Z INFO ttxt::block_monitor: FINALIZED block block_number=42 block_hash=0xa85ea5e228ae14b5db9eb132607ce286bc4c9a56692821825a4a097f9cb95567 extrinsics_count=2 2024-11-20T16:08:56.971809Z INFO ttxt::block_monitor: FINALIZED block block_number=43 block_hash=0x968d8f706d93adcaa2f474aea7e5b4e5f4b0f251b1b4386dc2b8e58455796410 extrinsics_count=2 2024-11-20T16:09:04.975126Z INFO ttxt::block_monitor: FINALIZED block block_number=44 block_hash=0xd517f03614d5a98390c6a649c650326b9e4650d96fc99ffe94551249877cd97c extrinsics_count=2 2024-11-20T16:09:08.976987Z INFO ttxt::block_monitor: FINALIZED block block_number=45 block_hash=0x00ed7634032a3431b93f3019a3a328454a5e97f4addb44a988d558f2b913b6f7 extrinsics_count=2 2024-11-20T16:09:12.186996Z INFO ttxt::block_monitor: BEST block block_number=52 block_hash=0x1598ac93e0c95dbf0f3b54b01e83d3679ff10284bcb452dba0a8f12f2caa30e3 extrinsics_count=2 2024-11-20T16:09:12.357036Z INFO ttxt::block_monitor: BEST block block_number=53 block_hash=0x7a6f08e5c77af59e739f2870d678f850acaa9d5b24dc2f36e4009d8c0e22925b extrinsics_count=2 2024-11-20T16:09:19.150896Z INFO ttxt::block_monitor: BEST block block_number=54 block_hash=0x02bd4dc29c9d4f3534758671bd719a977379e155479271f6dff8c471cbf7e4fa extrinsics_count=7032 ``` ::: The same setup with `asset-hub-rococo` works as expected - transaction are finalized. ### Analysis For `YAP` runtime txs are not finalized, because blocks which are finalized (and their parents), are not reported to the tranasction pool at the time they were imported (what means that they were most likely not imported as the best block). Following analysis shows step-by-step what happened. Please note that for the analysis purpose only 10 transaction were sent. The image shows forks in the analyzed test run: ![image](https://hackmd.io/_uploads/SJkYzFiMJe.png =50%x) During the execution the transaction pool was aware of `BLOCK9` and prepared txs for `BLOCK10`: ``` maintain: txs:(0, 10) views:[2;[(8, 10, 0), (9, 10, 0)]] event:NewBestBlock { hash: BLOCK9, tree_route: Some(TreeRoute { route: [HashAndNumber { number: 8, hash: BLOCK8 }, HashAndNumber { number: 7, hash: BLOCK7 }, HashAndNumber { number: 6, hash: BLOCK6 }, HashAndNumber { number: 7, hash: BLOCK7f01 }, HashAndNumber { number: 8, hash: BLOCK8f01 }], pivot: 2 }) } took:1.314888ms 🙌 Starting consensus session on top of parent BLOCK9 (#9) 🎁 Prepared block for proposing at 10 (3 ms) [hash: BUSY; parent_hash: BLOCK9; extrinsics_count: 12 🔖 Pre-sealed block for proposal at 10. Hash now BLOCK10, previously BUSY. ``` But it was never finalized. Instead `BLOCK10f03` was. But `BLOCKf901` (and actually none of its *fxx* parents) was never reported to the txpool. The pool was not able to provide any transactions to the builder constructing `BLOCK10f03`. Here is the log with info what was `Finalized`: ``` maintain: txs:(0, 10) views:[2;[(8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK1, tree_route: [] } took:173.81µs maintain: txs:(0, 10) views:[2;[(8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK2, tree_route: [] } took:113.609µs maintain: txs:(0, 10) views:[2;[(8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK3, tree_route: [] } took:206.509µs maintain: txs:(0, 10) views:[3;[(8, 10, 0), (10, 0, 0), (11, 10, 0)]] event:Finalized { hash: BLOCK4, tree_route: [] } took:273.309µs maintain: txs:(0, 10) views:[3;[(13, 0, 0), (8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK5, tree_route: [] } took:116.74µs maintain: txs:(0, 10) views:[3;[(15, 0, 0), (8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK6f01, tree_route: [] } took:135.339µs maintain: txs:(0, 10) views:[3;[(15, 0, 0), (8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK7f02, tree_route: [] } took:98.56µs maintain: txs:(0, 10) views:[2;[(15, 0, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK8f02, tree_route: [] } took:128.54µs maintain: txs:(0, 10) views:[2;[(15, 0, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK9f01, tree_route: [] } took:104.43µs maintain: txs:(0, 10) views:[2;[(15, 0, 0), (19, 0, 0)]] event:Finalized { hash: BLOCK10f03, tree_route: [] } took:137.67µs maintain: txs:(0, 10) views:[2;[(15, 0, 0), (19, 0, 0)]] event:Finalized { hash: BLOCK11f02, tree_route: [] } took:91.14µs maintain: txs:(0, 10) views:[2;[(15, 0, 0), (19, 0, 0)]] event:Finalized { hash: BLOCK12f02, tree_route: [] } took:121.709µs maintain: txs:(0, 10) views:[3;[(15, 0, 0), (19, 0, 0), (20, 10, 0)]] event:Finalized { hash: BLOCK13f02, tree_route: [] } took:256.71µs maintain: txs:(0, 10) views:[3;[(15, 0, 0), (19, 0, 0), (22, 0, 0)]] event:Finalized { hash: BLOCK14f01, tree_route: [] } took:160.25µs maintain: txs:(0, 10) views:[2;[(19, 0, 0), (24, 0, 0)]] event:Finalized { hash: BLOCK15f02, tree_route: [] } took:135.79µs ``` And here is excerpt with `NewBestBlock` events notified to the pool: ``` maintain: txs:(0, 0) views:[1;[(1, 0, 0)]] event:NewBestBlock { hash: BLOCK1, tree_route: None } took:189.89µs maintain: txs:(0, 0) views:[1;[(2, 0, 0)]] event:NewBestBlock { hash: BLOCK2, tree_route: None } took:149.69µs maintain: txs:(0, 0) views:[1;[(3, 0, 0)]] event:NewBestBlock { hash: BLOCK3, tree_route: None } took:182.2µs maintain: txs:(0, 0) views:[1;[(4, 0, 0)]] event:NewBestBlock { hash: BLOCK4, tree_route: None } took:143.89µs maintain: txs:(0, 0) views:[1;[(5, 0, 0)]] event:NewBestBlock { hash: BLOCK5, tree_route: None } took:237.629µs maintain: txs:(0, 0) views:[1;[(6, 0, 0)]] event:NewBestBlock { hash: BLOCK6, tree_route: None } took:195.079µs maintain: txs:(0, 0) views:[1;[(7, 0, 0)]] event:NewBestBlock { hash: BLOCK7, tree_route: None } took:314.91µs maintain: txs:(0, 0) views:[1;[(8, 0, 0)]] event:NewBestBlock { hash: BLOCK8, tree_route: None } took:210.56µs maintain: txs:(0, 10) views:[2;[(8, 10, 0), (9, 10, 0)]] event:NewBestBlock { hash: BLOCK9, tree_route: Some(TreeRoute { route: [HashAndNumber { number: 8, hash: BLOCK8 }, HashAndNumber { number: 7, hash: BLOCK7 }, HashAndNumber { number: 6, hash: BLOCK6 }, HashAndNumber { number: 7, hash: BLOCK7f01 }, HashAndNumber { number: 8, hash: BLOCK8f01 }], pivot: 2 }) } took:1.314888ms maintain: txs:(0, 10) views:[2;[(8, 10, 0), (10, 0, 0)]] event:NewBestBlock { hash: BLOCK10, tree_route: None } took:957.158µs maintain: txs:(0, 10) views:[3;[(8, 10, 0), (10, 0, 0), (11, 10, 0)]] event:NewBestBlock { hash: BLOCK11, tree_route: Some(TreeRoute { route: [HashAndNumber { number: 10, hash: BLOCK10 }, HashAndNumber { number: 9, hash: BLOCK9 }, HashAndNumber { number: 8, hash: BLOCK8f01 }, HashAndNumber { number: 7, hash: BLOCK7f01 }, HashAndNumber { number: 6, hash: BLOCK6 }, HashAndNumber { number: 5, hash: BLOCK5 }, HashAndNumber { number: 6, hash: BLOCK6f01 }, HashAndNumber { number: 7, hash: BLOCK7f02 }, HashAndNumber { number: 8, hash: BLOCK8f02 }, HashAndNumber { number: 9, hash: BLOCK9f01 }, HashAndNumber { number: 10, hash: BLOCK10f01 }], pivot: 5 }) } took:2.867275ms maintain: txs:(0, 10) views:[3;[(8, 10, 0), (10, 0, 0), (12, 0, 0)]] event:NewBestBlock { hash: BLOCK12, tree_route: None } took:1.154017ms ``` The block `BLOCKf901` was never reported, but interestingly, the `tree_route` provided here: ``` maintain: txs:(0, 10) views:[2;[(8, 10, 0), (9, 10, 0)]] event:NewBestBlock { hash: BLOCK9, tree_route: Some( TreeRoute { route: [ HashAndNumber { number: 8, hash: BLOCK8 }, HashAndNumber { number: 7, hash: BLOCK7 }, HashAndNumber { number: 6, hash: BLOCK6 }, HashAndNumber { number: 7, hash: BLOCK7f01 }, HashAndNumber { number: 8, hash: BLOCK8f01 } ], pivot: 2 }) } ... ``` indicates that some components *"thinks"* that `Block8f01` was previously reported as the best block. The new `txpool` has some fallback mechanism to handle this case, but by design under some circumstances it may provide `0` txs. It seems that here pool did its job right: ``` txpool: [Parachain] maintain: txs:(0, 10) views:[3;[(15, 0, 0), (8, 10, 0), (10, 0, 0)]] event:Finalized { hash: BLOCK6f01, tree_route: [] } took:135.339µs sc_basic_authorship::basic_authorship: [Parachain] 🙌 Starting consensus session on top of parent BLOCK9f01 (#9) txpool: [Parachain] fatp::ready_at_with_timeout at BLOCK9f01 allowed delay: 166.549914ms txpool: [Parachain] fatp::ready_at BLOCK9f01 pending keys: [BLOCK9f01] txpool: [Parachain] fatp::ready_at_light BLOCK9f01 txpool: [Parachain] fatp::ready_at_light BLOCK9f01 -> empty, took:6.51µs txpool: [Parachain] Timeout fired waiting for transaction pool at block: (BLOCK9f01). Proceeding with production. basic-authorship: [Parachain] Attempting to push transactions from the pool at BLOCK9f01. basic-authorship: [Parachain] No more transactions, proceeding with proposing. sc_basic_authorship::basic_authorship: [Parachain] 🎁 Prepared block for proposing at 10 (168 ms) [hash: JILL; parent_hash: BLOCK9f01; extrinsics_count: 2 aura::cumulus: [Parachain] 🔖 Pre-sealed block for proposal at 10. Hash now BLOCK10f03, previously JILL. ``` ### Next steps Possible solutions: - importing fork blocks as best blocks, - notifying every block to txpool (what was already discussed many times, but so far it seemed that we can live w/o that). - adding one more fallback in `ready_at` to txpool - it could simply return `ready_at` for the recent best block.