Batch transaction sending fails

[gleb-urvanov]

Batch sending transactions (balance.transfer and others) fails on joystream node,but works for substrate node template.

The following code

    let nonce = new BN(0);
    const keyring = new Keyring({ type: 'sr25519' });
    const sudo = keyring.addFromUri('//Alice');
    const nKeyPairs: KeyringPair[] = new Array();
    for (let i = 0; i < 10; i++) {
      nKeyPairs.push(keyring.addFromUri('//Bob'));
    }
    await Promise.all(
      nKeyPairs.map(async keyPair => {
        this.api.tx.balances.transfer(keyPair.address, new BN(100)).signAndSend(sudo, { nonce: nonce });
        nonce = nonce.addn(1);
      })
    );

Will result in first 2 transactions to be processed and included to blocks, one per block. The rest 8 are removed from the tx pool with the following error message seen for each: Extrinsic invalid: 0xf1368a77daa999b89984e37bc45d9ecd95b93d42fce0f601247c6d94299f1ef2

The same code, run against the substrate node (build from substrate c37bb0853) will result in all 10 transactions processed and included in a single block.

Similar transactions, sent consecutively (after previous one is included in block) will succeed both on joystream and substrate nodes.

[gleb-urvanov]

The issue also happens if the destination and the amount to be sent are not the same for batch transactions. The issue is not caused by tx processing time, the code was tested on more powerful hardware and with increased block construction time, the result is the same (two transactions processed, one per block). The issue does not happen if the transactions are sent from different accounts. In this case, several transactions are included in single block, as expected. During the testing several times I was able to receive tx status status.isFuture for the nonce value 2, while sending batch of more than 2 transactions with nonces 0, 1, 2.. N. Testing with RUST_BACKTRACE and with the node built in debug mode gave me no additional information.

[mnaamani]

I finally got around to testing this.

I can confirm that I'm able to replicate the issue as described. It is appearing only for the latest joystream-node release, and not the substrate node built from upstream repo from same commit release. The problem also doesn't exist for Acropolis release (prior version of joystream-node)

So there is a clearly an implementation issue in our node itself. Will investigate further.

[mnaamani]

Also @gleb-urvanov, clearly my suspicion that there was a bug in the code snippet turned out to be false.

Although the way the code is written to send out all the transactions before awaiting on the prior signAndSend() is what is resulting in the status Future sometimes.

[mnaamani]

After looking at the implementation of the services.rs for any issues, I also investigated possibility that polkadot-js api was perhaps sending invalid transactions (perhaps related to how the nonce or era was being encoded), I couldn't find any issue.

So with some additional logging: joystream-node --dev --log debug,transaction-pool,txpool I was able to see what was going on:

2020-05-07 10:46:42.005 tokio-runtime-worker-8 INFO substrate_basic_authorship::basic_authorship  Starting consensus session on top of parent 0xdad72f3f76aa469fe7c9a06b26ad721adc4897695d6ecd1ecee00b9eeade4906
2020-05-07 10:46:42.103 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  Attempting to push transactions from the pool.
2020-05-07 10:46:42.104 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x7f9e9128d6fce95323cffcad5d395f66a87261d01a0b091ff29c05ee81b1aa67] Pushed to the block.
2020-05-07 10:46:42.105 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0xe65ffd9fa38b24c73d470d19b9f447fac3742df230f2ff52ba062dded1b3545d] Pushed to the block.
2020-05-07 10:46:42.106 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  Block seems full, but will try 7 more transactions before quitting.
2020-05-07 10:46:42.107 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0xb8880ffa802826136cf37cde18a9b8af28f33e7b1263ecd8a17434d76463280d] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.108 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x27479982e4f439c9c5b0b85b5ad879621e48c8ce70aaea4756ca7ab88c43c1ef] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.108 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x0fe8bb919ff3b77cc105ec6f6e31c92ca49401fbc9e84c26de54bb594c5fcb23] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.109 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0xa285c76c5d7d09af8355eabe0a9694db80e7b0ab84364f6352892f349235c74b] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.110 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x93076eb0616d155464fb3bbc54f78cf5c723c6a56d5187964aea183cb24bb60f] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.111 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x2852419a49a9da60a4197a81c3b00902c18be6fed10e74e4320bf93668ad57b9] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.112 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0xbe5ff5d7a61b55f2c681fef605232722b9f5fb2ec42369ffe40636cb6f3608b6] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG substrate_basic_authorship::basic_authorship  [0x57023f0ea5690f9839729e5374483c87f2b768a9a5fee5e4ecb286635de900dd] Invalid transaction: Extrinsic error: ApplyError::Validity(TransactionValidityError::Invalid(InvalidTransaction::Future))
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  Banning invalid transactions: [0xb8880ffa802826136cf37cde18a9b8af28f33e7b1263ecd8a17434d76463280d, 0x27479982e4f439c9c5b0b85b5ad879621e48c8ce70aaea4756ca7ab88c43c1ef, 0x0fe8bb919ff3b77cc105ec6f6e31c92ca49401fbc9e84c26de54bb594c5fcb23, 0xa285c76c5d7d09af8355eabe0a9694db80e7b0ab84364f6352892f349235c74b, 0x93076eb0616d155464fb3bbc54f78cf5c723c6a56d5187964aea183cb24bb60f, 0x2852419a49a9da60a4197a81c3b00902c18be6fed10e74e4320bf93668ad57b9, 0xbe5ff5d7a61b55f2c681fef605232722b9f5fb2ec42369ffe40636cb6f3608b6, 0x57023f0ea5690f9839729e5374483c87f2b768a9a5fee5e4ecb286635de900dd]
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0x57023f0ea5690f9839729e5374483c87f2b768a9a5fee5e4ecb286635de900dd] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0xbe5ff5d7a61b55f2c681fef605232722b9f5fb2ec42369ffe40636cb6f3608b6] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0x2852419a49a9da60a4197a81c3b00902c18be6fed10e74e4320bf93668ad57b9] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0x93076eb0616d155464fb3bbc54f78cf5c723c6a56d5187964aea183cb24bb60f] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0xa285c76c5d7d09af8355eabe0a9694db80e7b0ab84364f6352892f349235c74b] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0x0fe8bb919ff3b77cc105ec6f6e31c92ca49401fbc9e84c26de54bb594c5fcb23] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0x27479982e4f439c9c5b0b85b5ad879621e48c8ce70aaea4756ca7ab88c43c1ef] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 DEBUG txpool  [0xb8880ffa802826136cf37cde18a9b8af28f33e7b1263ecd8a17434d76463280d] Removed as invalid: 
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0x57023f0ea5690f9839729e5374483c87f2b768a9a5fee5e4ecb286635de900dd
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0xbe5ff5d7a61b55f2c681fef605232722b9f5fb2ec42369ffe40636cb6f3608b6
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0x2852419a49a9da60a4197a81c3b00902c18be6fed10e74e4320bf93668ad57b9
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0x93076eb0616d155464fb3bbc54f78cf5c723c6a56d5187964aea183cb24bb60f
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0xa285c76c5d7d09af8355eabe0a9694db80e7b0ab84364f6352892f349235c74b
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0x0fe8bb919ff3b77cc105ec6f6e31c92ca49401fbc9e84c26de54bb594c5fcb23
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0x27479982e4f439c9c5b0b85b5ad879621e48c8ce70aaea4756ca7ab88c43c1ef
2020-05-07 10:46:42.113 tokio-runtime-worker-8 WARN transaction-pool  Extrinsic invalid: 0xb8880ffa802826136cf37cde18a9b8af28f33e7b1263ecd8a17434d76463280d

So I looked at basic_authorship module propose_with

Followed the code path to realize that the exhausted_resources() call was returning true because the block weight was being exceeded. This led me to look at the weight of the transfer call and the runtime configuration.

The weight of a balances::transfer() call is 1_000_000

The max block height of the runtime was also 1_000_000

So simply increasing the block limit resolved it.

Setting the limit so low was clearly a mistake by yours truly.

[bedeho]

Just to add my two cents, based on conversations internally, my understanding is that the core issue driving this is that the block authoring logic in Substrate is making a mistake in not handling the case where there are more pending transactions than there is space for in a block. This would seem like a very basic issue, but apparently it's not well dealt with.

In the absence of this bad handling there would be no need to increase this limit, even if a higher limit is also on its own practical.

[mnaamani]

That's correct instead of deferring transactions that didn't fit into the current block being authored/proposed, to a future block they were being dropped from the transaction pool altogether.

[mnaamani]

The issue is resolved in latest version of substrate.