Falsely reported invalid transaction?

[s0me0ne-unkn0wn]

I'm working on a test that uses zombients v2 and subxt. Basically, it submits some transaction, waits for its finalization, and sends the next transaction based on the events generated by the previous one, thus proving the correctness of the expected behavior.

Sometimes, the entire test runs through successfully, but it's rare. More often, some transaction fails with TxStatus::Invalid { message: "Transaction is invalid (eg because of a bad nonce, signature etc)" }. Most often, this one fails although sometimes it happens with the other transactions. Here's what that looks like in the logs:

[2024-07-03T08:16:47Z TRACE coretime_revenue_test] Created tx [249, 1, 132, 0, 212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125, 1, 186, 217, 65, 5, 98, 177, 99, 184, 118, 82, 244, 123, 72, 149, 60, 219, 125, 128, 217, 173, 34, 74, 36, 229, 236, 74, 213, 227, 130, 87, 176, 63, 159, 107, 17, 97, 167, 93, 147, 141, 240, 14, 45, 98, 109, 200, 22, 178, 197, 72, 231, 136, 153, 202, 81, 210, 82, 209, 182, 55, 126, 248, 21, 136, 84, 0, 12, 0, 0, 50, 12, 3, 0, 0, 0, 1, 0, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 1, 0, 0, 0]
[2024-07-03T08:16:47Z TRACE jsonrpsee_core::client::async_client] subscription; method="author_submitAndWatchExtrinsic"
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: send: (Text (fin 1) (rsv 000) (mask (1 b78cc1dc)) (len 339))
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: Sender flushing connection
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 53))
[2024-07-03T08:16:47Z TRACE tracing::span] -- subscription;
[2024-07-03T08:16:47Z TRACE coretime_revenue_test] Submitted: TxProgress { sub: "<subscription>", ext_hash: 0xaec95e6ffe93255c28e64ed4b326d2a51ed438eb5561f122733bdc83e1abe50b, client: "<client>" }
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 113))
[2024-07-03T08:16:47Z TRACE coretime_revenue_test] Transaction status IGNORED: Validated
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: recv: (Ping (fin 1) (rsv 000) (mask (0 0)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: send: (Pong (fin 1) (rsv 000) (mask (1 4b5669f)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 2eaac993: Receiver flushing connection
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 506deefa: recv: (Ping (fin 1) (rsv 000) (mask (0 0)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 506deefa: send: (Pong (fin 1) (rsv 000) (mask (1 c5113ce8)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 506deefa: Receiver flushing connection
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 7b0068a5: recv: (Ping (fin 1) (rsv 000) (mask (0 0)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 7b0068a5: send: (Pong (fin 1) (rsv 000) (mask (1 98933f74)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 7b0068a5: Receiver flushing connection
[2024-07-03T08:16:47Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:47Z TRACE soketto::connection] 1394fcd6: recv: (Ping (fin 1) (rsv 000) (mask (0 0)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 1394fcd6: send: (Pong (fin 1) (rsv 000) (mask (1 782270b8)) (len 0))
[2024-07-03T08:16:47Z TRACE soketto::connection] 1394fcd6: Receiver flushing connection
[2024-07-03T08:16:48Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:48Z TRACE soketto::connection] 2eaac993: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 115))
[2024-07-03T08:16:48Z ERROR coretime_revenue_test] Transaction ERROR Ok(Invalid { message: "Transaction is invalid (eg because of a bad nonce, signature etc)" }): Transaction is invalid (eg because of a bad nonce, signature etc)
[2024-07-03T08:16:48Z TRACE jsonrpsee-client] Closing subscription: Str("aZAmMIJPTYM16Sau")
[2024-07-03T08:16:48Z TRACE soketto::connection] 2eaac993: send: (Text (fin 1) (rsv 000) (mask (1 e1a1f71a)) (len 90))
[2024-07-03T08:16:48Z TRACE soketto::connection] 2eaac993: Sender flushing connection
[2024-07-03T08:16:48Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:48Z TRACE soketto::connection] 2eaac993: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 40))
[2024-07-03T08:16:53Z TRACE soketto] read 2 bytes
[2024-07-03T08:16:53Z TRACE soketto] read 2 bytes

The interesting thing is that the transaction indeed gets successfully finalized, as can be seen in PJS:

Moreover, if I leave the network running after the failure, my event watcher sees the events I was expecting in the finalized block:

[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Finalized parachain block 73
[2024-07-03T08:17:17Z TRACE jsonrpsee_core::client::async_client] method_call; method="state_getStorage"
[2024-07-03T08:17:17Z TRACE soketto::connection] 506deefa: send: (Text (fin 1) (rsv 000) (mask (1 493f4a49)) (len 202))
[2024-07-03T08:17:17Z TRACE soketto::connection] 506deefa: Sender flushing connection
[2024-07-03T08:17:17Z TRACE soketto] read 2 bytes
[2024-07-03T08:17:17Z TRACE soketto::connection] 1394fcd6: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 72))
[2024-07-03T08:17:17Z TRACE tracing::span] -- method_call;
[2024-07-03T08:17:17Z TRACE soketto] read 2 bytes
[2024-07-03T08:17:17Z TRACE soketto] read 2 bytes
[2024-07-03T08:17:17Z TRACE soketto::connection] 506deefa: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 905))
[2024-07-03T08:17:17Z TRACE soketto] read 2 bytes
[2024-07-03T08:17:17Z TRACE soketto::connection] 7b0068a5: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 71))
[2024-07-03T08:17:17Z TRACE tracing::span] -- method_call;
[2024-07-03T08:17:17Z TRACE tracing::span] -- method_call;
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'System::ExtrinsicSuccess'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: System :: ExtrinsicSuccess
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'System::ExtrinsicSuccess'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: System :: ExtrinsicSuccess
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Balances::Withdraw'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Balances :: Withdraw
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Broker::RevenueClaimBegun'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Broker :: RevenueClaimBegun
[2024-07-03T08:17:17Z TRACE coretime_revenue_test] RevenueClaimBegun {
        region: RegionId {
            begin: 3,
            core: 1,
            mask: CoreMask(
                [
                    255,
                    255,
                    255,
                    255,
                    255,
                    255,
                    255,
                    255,
                    255,
                    255,
                ],
            ),
        },
        max_timeslices: 1,
    }
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Broker::RevenueClaimItem'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Broker :: RevenueClaimItem
[2024-07-03T08:17:17Z TRACE coretime_revenue_test] RevenueClaimItem {
        when: 3,
        amount: 25000000,
    }
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Balances::Transfer'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Balances :: Transfer
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Broker::RevenueClaimPaid'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Broker :: RevenueClaimPaid
[2024-07-03T08:17:17Z TRACE coretime_revenue_test] RevenueClaimPaid {
        who: AccountId32(
            [
                212,
                53,
                147,
                199,
                21,
                253,
                211,
                28,
                97,
                20,
                26,
                189,
                4,
                169,
                159,
                214,
                130,
                44,
                133,
                88,
                133,
                76,
                205,
                227,
                154,
                86,
                132,
                231,
                165,
                109,
                162,
                125,
            ],
        ),
        amount: 25000000,
        next: None,
    }
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'Balances::Deposit'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: Balances :: Deposit
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'TransactionPayment::TransactionFeePaid'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: TransactionPayment :: TransactionFeePaid
[2024-07-03T08:17:17Z DEBUG subxt_core::events] Decoding Event 'System::ExtrinsicSuccess'
[2024-07-03T08:17:17Z DEBUG coretime_revenue_test] Got event: System :: ExtrinsicSuccess

I'm using subxt 0.37. Any ideas on what's happening here would be very appreciated.

[niklasad1]

Hmm interesting, do you know which transaction status message that subxt decodes as invalid? Maybe we removed those subscription messages logs from the jsonrpsee client but would be interesting to know here... (it should quite trivial to find out with wireshark)

EDIT:

I haven't been able to re-produce this myself but if you can apply my PR and re-run it again then we will able to see the transaction status submitted by the node.

Also, another thingy to assert is that the nonce is unique whether the same account is used to send transactions concurrently....

[s0me0ne-unkn0wn]

Thanks for the debug patch! Caught it in the very first run:

2024-07-03T18:02:23.084371Z  INFO coretime_revenue_test: Alice is going to claim her revenue    
2024-07-03T18:02:23.084381Z TRACE method_call{method="chain_getFinalizedHead"}: jsonrpsee-client: send="{\"jsonrpc\":\"2.0\",\"id\":31,\"method\":\"chain_getFinalizedHead\"}"
2024-07-03T18:02:23.084391Z TRACE soketto::connection: cba3ae5e: send: (Text (fin 1) (rsv 000) (mask (1 d30fc991)) (len 59))    
2024-07-03T18:02:23.084395Z TRACE soketto::connection: cba3ae5e: Sender flushing connection    
2024-07-03T18:02:23.084436Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.084439Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 103))    
2024-07-03T18:02:23.084449Z TRACE method_call{method="chain_getFinalizedHead"}: jsonrpsee-client: recv="{\"jsonrpc\":\"2.0\",\"result\":\"0x022ebf67cb3eb15bf3f31b6f4e06589b15c07934b5f3e3d5334cba265ff24c22\",\"id\":31}"
2024-07-03T18:02:23.084460Z TRACE method_call{method="chain_getHeader"}: jsonrpsee-client: send="{\"jsonrpc\":\"2.0\",\"id\":32,\"method\":\"chain_getHeader\",\"params\":[\"0x022ebf67cb3eb15bf3f31b6f4e06589b15c07934b5f3e3d5334cba265ff24c22\"]}"
2024-07-03T18:02:23.084471Z TRACE soketto::connection: cba3ae5e: send: (Text (fin 1) (rsv 000) (mask (1 4e355d6e)) (len 132))    
2024-07-03T18:02:23.084475Z TRACE soketto::connection: cba3ae5e: Sender flushing connection    
2024-07-03T18:02:23.084526Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.084528Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.084530Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 586))    
2024-07-03T18:02:23.084549Z TRACE method_call{method="chain_getHeader"}: jsonrpsee-client: recv="{\"jsonrpc\":\"2.0\",\"result\":{\"digest\":{\"logs\":[\"0x0661757261200243161100000000\",\"0x045250535288574606300f0eb03b8f9e9c7c2e7cf5ed79a4ff642e182e3a9e055ffe7ddde3455501\",\"0x05617572610101f64ba4f6c324811de457b8a9503849f5e89adcfb58f92418095fa7e4b9a77e4a0e531f1fb9e38b4439382d5de405f14ad52220833316f58ab60240ecc6b21883\"]},\"extrinsicsRoot\":\"0x4fe2c77472eea60e5f7ce91a3bf80f4ba0e63459e8104cd19e858fb725bdb7af\",\"number\":\"0x45\",\"parentHash\":\"0x7ecf71c0a352cf2418acb8fa30a03f2677dcc8d2b4e3c2a4c9a3532fef114cf3\",\"stateRoot\":\"0x6aa537f38d3900c2f9a0e0c217f224b776c334478649abb23045d12d1ef5f12f\"},\"id\":32}"
2024-07-03T18:02:23.084576Z TRACE method_call{method="state_call"}: jsonrpsee-client: send="{\"jsonrpc\":\"2.0\",\"id\":33,\"method\":\"state_call\",\"params\":[\"AccountNonceApi_account_nonce\",\"0xd43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d\",\"0x022ebf67cb3eb15bf3f31b6f4e06589b15c07934b5f3e3d5334cba265ff24c22\"]}"
2024-07-03T18:02:23.084585Z TRACE soketto::connection: cba3ae5e: send: (Text (fin 1) (rsv 000) (mask (1 965cc4db)) (len 228))    
2024-07-03T18:02:23.084590Z TRACE soketto::connection: cba3ae5e: Sender flushing connection    
2024-07-03T18:02:23.084763Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.084765Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 47))    
2024-07-03T18:02:23.084774Z TRACE method_call{method="state_call"}: jsonrpsee-client: recv="{\"jsonrpc\":\"2.0\",\"result\":\"0x03000000\",\"id\":33}"
2024-07-03T18:02:23.084836Z TRACE coretime_revenue_test: Created tx [249, 1, 132, 0, 212, 53, 147, 199, 21, 253, 211, 28, 97, 20, 26, 189, 4, 169, 159, 214, 130, 44, 133, 88, 133, 76, 205, 227, 154, 86, 132, 231, 165, 109, 162, 125, 1, 120, 200, 113, 226, 242, 118, 21, 195, 13, 41, 55, 62, 25, 151, 201, 32, 89, 118, 86, 126, 200, 183, 35, 56, 30, 28, 86, 23, 34, 177, 1, 20, 112, 73, 255, 57, 68, 46, 52, 242, 32, 185, 44, 100, 106, 102, 23, 91, 62, 111, 203, 13, 157, 46, 175, 242, 35, 91, 171, 10, 142, 172, 83, 136, 84, 0, 12, 0, 0, 50, 12, 3, 0, 0, 0, 1, 0, 255, 255, 255, 255, 255, 255, 255, 255, 255, 255, 1, 0, 0, 0]    
2024-07-03T18:02:23.084849Z TRACE subscription{method="author_submitAndWatchExtrinsic"}: jsonrpsee-client: send="{\"jsonrpc\":\"2.0\",\"id\":34,\"method\":\"author_submitAndWatchExtrinsic\",\"params\":[\"0xf9018400d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d0178c871e2f27615c30d29373e1997c9205976567ec8b723381e1c561722b101147049ff39442e34f220b92c646a66175b3e6fcb0d9d2eaff2235bab0a8eac538854000c0000320c030000000100ffffffffffffffffffff01000000\"]}"
2024-07-03T18:02:23.084860Z TRACE soketto::connection: cba3ae5e: send: (Text (fin 1) (rsv 000) (mask (1 fff35190)) (len 339))    
2024-07-03T18:02:23.084864Z TRACE soketto::connection: cba3ae5e: Sender flushing connection    
2024-07-03T18:02:23.085247Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.085253Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 53))    
2024-07-03T18:02:23.085271Z TRACE subscription{method="author_submitAndWatchExtrinsic"}: jsonrpsee-client: recv="{\"jsonrpc\":\"2.0\",\"result\":\"hpMDw2EmqWVByFuK\",\"id\":35}"
2024-07-03T18:02:23.085279Z TRACE coretime_revenue_test: Submitted: TxProgress { sub: "<subscription>", ext_hash: 0x8bb0cbd5d21b0ead264b5967d70ae2a067a5801081ff0c5dfa450d9ee9e3171c, client: "<client>" }    
2024-07-03T18:02:23.085887Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.085893Z TRACE soketto::connection: 153e1dd5: recv: (Ping (fin 1) (rsv 000) (mask (0 0)) (len 0))    
2024-07-03T18:02:23.085896Z TRACE soketto::connection: 153e1dd5: send: (Pong (fin 1) (rsv 000) (mask (1 f924fa33)) (len 0))    
2024-07-03T18:02:23.085899Z TRACE soketto::connection: 153e1dd5: Receiver flushing connection    
2024-07-03T18:02:23.126094Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:23.126119Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 113))    
2024-07-03T18:02:23.126157Z TRACE jsonrpsee-client: subscription = author_extrinsicUpdate, sub_id = "hpMDw2EmqWVByFuK", item = "ready"
2024-07-03T18:02:23.126185Z TRACE coretime_revenue_test: Transaction status IGNORED: Validated    
2024-07-03T18:02:24.028821Z TRACE soketto: read 2 bytes    
2024-07-03T18:02:24.028850Z TRACE soketto::connection: cba3ae5e: recv: (Text (fin 1) (rsv 000) (mask (0 0)) (len 115))    
2024-07-03T18:02:24.028891Z TRACE jsonrpsee-client: subscription = author_extrinsicUpdate, sub_id = "hpMDw2EmqWVByFuK", item = "invalid"
2024-07-03T18:02:24.028997Z ERROR coretime_revenue_test: Transaction ERROR Ok(Invalid { message: "Transaction is invalid (eg because of a bad nonce, signature etc)" }): Transaction is invalid (eg because of a bad nonce, signature etc)    
2024-07-03T18:02:24.029003Z TRACE jsonrpsee-client: Closing subscription: Str("hpMDw2EmqWVByFuK")

I also have my suspicions about the culprit. I noticed that in the node logs, there's a reorg around block 73 where the "invalid" transaction was included (most probably due to paritytech/polkadot-sdk#3205, which is still affecting the parachains running with lookahead collator, otherwise I cannot explain forks on the single-collator chain):

2024-07-03 20:02:06 [Parachain] 🏆 Imported #72 (0x3533…f331 → 0xa86e…cd3d)    
2024-07-03 20:02:06 [Parachain] PoV size { header: 0.21875kb, extrinsics: 3.8740234375kb, storage_proof: 3.890625kb }
2024-07-03 20:02:06 [Parachain] Compressed PoV size: 7.0712890625kb
2024-07-03 20:02:07 [Relaychain] 💤 Idle (3 peers), best: #88 (0x7710…81f1), finalized #85 (0x122d…20d9), ⬇ 2.1kiB/s ⬆ 2.9kiB/s    
2024-07-03 20:02:07 [Parachain] 💤 Idle (0 peers), best: #72 (0xa86e…cd3d), finalized #66 (0x2287…cabe), ⬇ 0.3kiB/s ⬆ 0.1kiB/s    
2024-07-03 20:02:12 [Relaychain] 🏆 Imported #89 (0x7710…81f1 → 0xe789…5ca3)    
2024-07-03 20:02:12 [Parachain] 🙌 Starting consensus session on top of parent 0xa86e3536e1971c38c546b6ac098dad4dd19b539627538bdd133c890e691bcd3d    
2024-07-03 20:02:12 [Parachain] 🎁 Prepared block for proposing at 73 (1 ms) [hash: 0x35cf67a86a98870cfbf5eec4bed5dda8a6f5881cb7621e90e5417a638974f4d6; parent_hash: 0xa86e…cd3d; extrinsics (2): [0xcac3…24c4, 0xae52…6b10]    
2024-07-03 20:02:12 [Parachain] 🔖 Pre-sealed block for proposal at 73. Hash now 0x6c5f76b20a937b541b2d2a1ded3329baf349d83df75c77a100d75924d134b5ea, previously 0x35cf67a86a98870cfbf5eec4bed5dda8a6f5881cb7621e90e5417a638974f4d6.
2024-07-03 20:02:12 [Parachain] 🏆 Imported #73 (0xa86e…cd3d → 0x6c5f…b5ea)    
2024-07-03 20:02:12 [Parachain] PoV size { header: 0.21875kb, extrinsics: 3.8740234375kb, storage_proof: 3.890625kb }
2024-07-03 20:02:12 [Parachain] Compressed PoV size: 7.0712890625kb
2024-07-03 20:02:12 [Relaychain] 💤 Idle (3 peers), best: #89 (0xe789…5ca3), finalized #86 (0xd78a…1f6d), ⬇ 1.6kiB/s ⬆ 2.4kiB/s    
2024-07-03 20:02:12 [Parachain] 💤 Idle (0 peers), best: #73 (0x6c5f…b5ea), finalized #67 (0xe502…9dba), ⬇ 0.3kiB/s ⬆ 0.2kiB/s    
2024-07-03 20:02:17 [Relaychain] 💤 Idle (3 peers), best: #89 (0xe789…5ca3), finalized #87 (0x9478…e9ab), ⬇ 1.1kiB/s ⬆ 0.9kiB/s    
2024-07-03 20:02:17 [Parachain] 💤 Idle (0 peers), best: #73 (0x6c5f…b5ea), finalized #68 (0x7ecf…4cf3), ⬇ 0.3kiB/s ⬆ 0.1kiB/s    
2024-07-03 20:02:18 [Relaychain] 🏆 Imported #90 (0xe789…5ca3 → 0xce6e…f3fc)    
2024-07-03 20:02:18 [Parachain] 🙌 Starting consensus session on top of parent 0x6c5f76b20a937b541b2d2a1ded3329baf349d83df75c77a100d75924d134b5ea    
2024-07-03 20:02:18 [Parachain] 🎁 Prepared block for proposing at 74 (1 ms) [hash: 0xd5743f172569c4a07520ee62ef8c66d4b7c7a7fc8673f7390df284c68f8de280; parent_hash: 0x6c5f…b5ea; extrinsics (2): [0xd790…a210, 0xa235…7f83]    
2024-07-03 20:02:18 [Parachain] 🔖 Pre-sealed block for proposal at 74. Hash now 0x5eabb1825c6495c0f90eca4fe5087ae0bf06597fc79544458869b2b5c4958229, previously 0xd5743f172569c4a07520ee62ef8c66d4b7c7a7fc8673f7390df284c68f8de280.
2024-07-03 20:02:18 [Parachain] 🏆 Imported #74 (0x6c5f…b5ea → 0x5eab…8229)    
2024-07-03 20:02:18 [Parachain] PoV size { header: 0.21875kb, extrinsics: 3.8740234375kb, storage_proof: 3.8125kb }
2024-07-03 20:02:18 [Parachain] Compressed PoV size: 6.9912109375kb
2024-07-03 20:02:22 [Relaychain] 💤 Idle (3 peers), best: #90 (0xce6e…f3fc), finalized #88 (0x7710…81f1), ⬇ 2.1kiB/s ⬆ 2.7kiB/s    
2024-07-03 20:02:22 [Parachain] 💤 Idle (0 peers), best: #74 (0x5eab…8229), finalized #69 (0x022e…4c22), ⬇ 0.2kiB/s ⬆ 91 B/s    
2024-07-03 20:02:24 [Relaychain] 👶 New epoch 9 launching at block 0x715a…dc03 (block slot 286671624 >= start slot 286671624).    
2024-07-03 20:02:24 [Relaychain] 👶 Next epoch starts at slot 286671634    
2024-07-03 20:02:24 [Relaychain] 🏆 Imported #91 (0xce6e…f3fc → 0x715a…dc03)    
2024-07-03 20:02:24 [Parachain] 🙌 Starting consensus session on top of parent 0xa86e3536e1971c38c546b6ac098dad4dd19b539627538bdd133c890e691bcd3d    
2024-07-03 20:02:24 [Parachain] 🎁 Prepared block for proposing at 73 (4 ms) [hash: 0x790bd2c51883a768dd9f9359535b742cd1aaf9b5dcfaa37639f2aa14d97c0ee9; parent_hash: 0xa86e…cd3d; extrinsics (3): [0x3826…f591, 0x51db…e12b, 0x8bb0…171c]    
2024-07-03 20:02:24 [Parachain] 🔖 Pre-sealed block for proposal at 73. Hash now 0x7900c230db8e70dc960cc117e1d4524260213d8227463b9b7754e795340d2dcb, previously 0x790bd2c51883a768dd9f9359535b742cd1aaf9b5dcfaa37639f2aa14d97c0ee9.
2024-07-03 20:02:24 [Parachain] 🆕 Imported #73 (0xa86e…cd3d → 0x7900…2dcb)    
2024-07-03 20:02:24 [Parachain] PoV size { header: 0.21875kb, extrinsics: 3.9990234375kb, storage_proof: 4.68359375kb }
2024-07-03 20:02:24 [Parachain] Compressed PoV size: 7.4892578125kb
2024-07-03 20:02:24 [Parachain] 🙌 Starting consensus session on top of parent 0x7900c230db8e70dc960cc117e1d4524260213d8227463b9b7754e795340d2dcb    
2024-07-03 20:02:24 [Parachain] 🎁 Prepared block for proposing at 74 (1 ms) [hash: 0x99424e7e562086da2082537237c57f1a95e98eee196859ddde0606fbe2931fe3; parent_hash: 0x7900…2dcb; extrinsics (2): [0x5854…1f39, 0x51db…e12b]    
2024-07-03 20:02:24 [Parachain] 🔖 Pre-sealed block for proposal at 74. Hash now 0x8b4a8ec46c7e27036225234cd6993505d607b7524ee487191e54cbadc2f7638e, previously 0x99424e7e562086da2082537237c57f1a95e98eee196859ddde0606fbe2931fe3.
2024-07-03 20:02:24 [Parachain] 🆕 Imported #74 (0x7900…2dcb → 0x8b4a…638e)    
2024-07-03 20:02:24 [Parachain] PoV size { header: 0.21875kb, extrinsics: 3.8740234375kb, storage_proof: 3.6904296875kb }
2024-07-03 20:02:24 [Parachain] Compressed PoV size: 6.8828125kb
2024-07-03 20:02:27 [Relaychain] 💤 Idle (3 peers), best: #91 (0x715a…dc03), finalized #88 (0x7710…81f1), ⬇ 2.7kiB/s ⬆ 4.8kiB/s    
2024-07-03 20:02:27 [Parachain] 💤 Idle (0 peers), best: #74 (0x5eab…8229), finalized #69 (0x022e…4c22), ⬇ 0.2kiB/s ⬆ 0.2kiB/s    
2024-07-03 20:02:30 [Relaychain] 🏆 Imported #92 (0x715a…dc03 → 0x6c9c…8f65)    
2024-07-03 20:02:30 [Parachain] 🙌 Starting consensus session on top of parent 0x8b4a8ec46c7e27036225234cd6993505d607b7524ee487191e54cbadc2f7638e    
2024-07-03 20:02:30 [Parachain] 🎁 Prepared block for proposing at 75 (1 ms) [hash: 0xc7a41f722bc0ed17c6838abb7c7a948f2d2a76caf07b822615d170bebf43b004; parent_hash: 0x8b4a…638e; extrinsics (2): [0x7e9d…2f68, 0x439b…9920]    
2024-07-03 20:02:30 [Parachain] 🔖 Pre-sealed block for proposal at 75. Hash now 0x58b21ef39293e775e52b5d9744bb8dd82cbc6e4403aadfc39282e7d0ce07349f, previously 0xc7a41f722bc0ed17c6838abb7c7a948f2d2a76caf07b822615d170bebf43b004.
2024-07-03 20:02:30 [Parachain] ♻  Reorg on #74,0x5eab…8229 to #75,0x58b2…349f, common ancestor #72,0xa86e…cd3d    
2024-07-03 20:02:30 [Parachain] 🏆 Imported #75 (0x8b4a…638e → 0x58b2…349f)    

Now, I don't know how fork-aware the subxt (or its backends) are. If they are not, that may be a natural failure when subxt sees the block been thrown away but the transaction gets finalized on another fork. WDYT?

[niklasad1]

Now, I don't know how fork-aware the subxt (or its backends) are. If they are not, that may be a natural failure when subxt sees the block been thrown away but the transaction gets finalized on another fork. WDYT?

Gotcha, so yes would be nice to support for sure.

For subxt it depends which rpc backend that is used:

1. Legacy: it's simply a wrapper around author_submitAndWatch and I think we need to subscribe to blocks internally to determine whether a fork occurred (shouldn't be that hard to support)
2. Unstable (rpc v2): It's fundamentally different and it is based on chainHead_v1_follow and it could already support because it already subscribes to blocks and has a logic embedded into but I'm not sure whether we actually check it for forks properly.

So, you try to the unstable backend meanwhile but no guarantees. You can instantiate by:

    use subxt::backend::unstable::UnstableBackend;
    use subxt::OnlineClient;

    let (backend, mut driver) = UnstableBackend::builder().build(RpcClient::new(rpc.clone()));
    tokio::spawn(async move {
        while let Some(val) = driver.next().await {
            if let Err(e) = val {
                eprintln!("Error driving unstable backend: {e}; terminating client");
            }
        }
    });
    let api: OnlineClient<PolkadotConfig> = OnlineClient::from_backend(Arc::new(backend)).await?;

//cc @lexnv @jsdw Do you know whether the unstable backend is fork-aware currently?

[lexnv]

IIUC, the issue happens with the legacy Backend (although I expect a similar behavior to happen with the "unstable" Backend):

• T0: we submit a transaction author_submitAndWatchExtrinsic
• T1: the transaction status is txStatus::Validated which corresponds to the substrate's Ready status -- transaction has been included in the ready queue
• T2: a reorg happens and the transaction pool decides the transaction is no longer valid -- returns Invalid
• T3: the transaction is later on included in the canonical chain

In subxt, we rely on the RPCs exposed by the node:

https://github.com/paritytech/subxt/blob/b076f4c66ca2b7627f32d899211ea99a47db1c28/subxt/src/backend/legacy/mod.rs#L331-L346

For the legacy backend: we rely entirely on author_submitAndWatchExtrinsic to provide us back with the status. For the unstable backend: we correlate the transaction status with the chainHead api to provide back a pinned block.

If the author_submitAndWatchExtrinsic and the new transaction API (unstable backend) are fork-aware, we should also be fork-aware.

I expect the issue is coming from the substrate's transaction pool and this is happening because the tx pool is not fork aware currently.

Offhand, I don't think there's something we can do from the subxt perspective to guard against this case:

• we can subscribe to blocks in the legacy API, and when we see an invalid transaction status wait for more blocks (but how many? and when?)
• we can provide an event for our streams that wrap block productions, which says there's been a fork. However, that can also happen on a higher level, even better at the user level, which looks similar to:

let sub = subscribe_finalized_block_hasesh();

let mut blocks = HashMap<Block::Hash, Block::Hash>::new(); // parent hash to block hash
while let Ok(Some(hash)) = sub.next().await? {
  let parent_hash = hash.parent_hash();
  if blocks.entry(parent_hash) {
     Occupied(oc) => {
        println!("Fork detected on parent: {parent_hash}");
    }
...
}

And then users can wrap the subxt subscribe_finalized_block_hasesh stream and generate their events

enum BlockEvent {
   Produced(block)
   Forked(parent, block)
}

TLDR; we need https://github.com/paritytech/polkadot-sdk/pull/4775

[michalkucharczyk]

TLDR; we need paritytech/polkadot-sdk#4775

I'd say: https://github.com/paritytech/polkadot-sdk/pull/4639. This one https://github.com/paritytech/polkadot-sdk/pull/4775 is just for testing builds.

[s0me0ne-unkn0wn]

I'm trying the unstable backend, and it fails with RPC error: ErrorObject { code: MethodNotFound, message: "Method not found", data: None } soon after the test starts. Well, I suppose that's why it's called "unstable" :grin:

Full log just in case: revenue-test2.log

[niklasad1]

I'm trying the unstable backend, and it fails with RPC error: ErrorObject { code: MethodNotFound, message: "Method not found", data: None } soon after the test starts. Well, I suppose that's why it's called "unstable" 😁

Full log just in case: revenue-test2.log

Weird, you don't which method call that caused that? I couldn't find it from the logs but I would guess that the polkadot parachain may not have the rpc v2 impl enabled?

[s0me0ne-unkn0wn]

Weird, you don't which method call that caused that?

I'm not totally sure as well, but according to the INFO logs, the only possible place where it could happen is get_total_issuance

I would guess that the polkadot parachain may not have the rpc v2 impl enabled?

Oh I'm no expert here :) How do you enable/disable it in a cumulus-based node?

Anyway, I'm developing a workaround behavior for tests, and it seems to work with the legacy RPC, so I hope it's enough for now and we all are waiting for the fork-aware txpool! :crossed_fingers:

[niklasad1]

Oh I'm no expert here :) How do you enable/disable it in a cumulus-based node?

The chain spec RPC stuff is implemented as a rpc extension and if it's not enabled such as https://github.com/paritytech/polkadot-sdk/blob/master/polkadot/rpc/src/lib.rs#L146 then it's not enabled on the node.

I checked locally right now and the polkadot-parachain (cumulus) doesn't provide these RPCs:

➜ jsonrpsee (with-client-sub-logs) ✗ diff polkadot.json polkadot_parachain.json
15,18d14
<             "babe_epochAuthorship",
<             "beefy_getFinalizedHead",
<             "beefy_subscribeJustifications",
<             "beefy_unsubscribeJustifications",
28,30d23
<             "chainSpec_v1_chainName",
<             "chainSpec_v1_genesisHash",
<             "chainSpec_v1_properties",
57,64d49
<             "grandpa_proveFinality",
<             "grandpa_roundState",
<             "grandpa_subscribeJustifications",
<             "grandpa_unsubscribeJustifications",
<             "mmr_generateProof",
<             "mmr_root",
<             "mmr_verifyProof",
<             "mmr_verifyProofStateless",
95d79
<             "sync_state_genSyncSpec",

Thus, chainSpec_v1 needs to added here for it to work but no idea why it wasn't enabled...

Maybe @lexnv knows or simply just missed ^^

[lexnv]

I think I've missed that, indeed chainSpec_v1 should be enable there, thanks for catching this!

It might be a good idea to also enable sync_state_getSyncStpec while at it. A proper spec-ed API is pending grandpa / babe code cleanups, we can probably enable this in the meanwhile as well