paritytech / paritytech/subxt

Falsely reported invalid transaction?

Open
#1,668 13 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Rust
Stars
489
Forks
293
Avg merge
18h 35m
Merged PRs (30d)
3

Description

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:

image

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.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Reproduce the report using the external test's src/main.rs, especially the transaction at line 608, with subxt 0.37. Start by tracing author_submitAndWatchExtrinsic and the TxStatus::Invalid result, then compare it with the later finalized-block events; done means explaining why the invalid status occurs or providing a verified correction.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
blockchain
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
28/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.