"invalid transaction" error after submitting a few transactions with polkadot.js

[noot]

Describe the bug

• after submitting 2-3 transactions with polkadot.js, transactions start to fail with invalid transaction and the log in the node shows:

EROR[05-06|18:28:52] [ext_crypto_sr25519_verify_version_2] failed to validate signature pkg=runtime module=go-wasmer error=nil caller=imports.go:681

• this is likely due to the message being signed and what the runtime expects not matching, potentially nonce or some other field is not being updated properly after txs are sent

Expected Behavior

• transactions should not error with invalid signature

To Reproduce

Steps to reproduce the behaviour:

1. run dev node, i was using --chain dev here feat: add --chain dev option #1561 or you can also manually set the babe-threshold on development and enable WS (tried w/ both and it was the same issue)
2. in a new folder:

npm init -y
npm i @polkadot/api@2.8.1

3. copy paste this code into a file transfer.js which transfers from alice to bob:

const { ApiPromise, WsProvider, Keyring } = require('@polkadot/api');

async function main() {
	const wsProvider = new WsProvider('ws://127.0.0.1:8546');
	const api = await ApiPromise.create({ provider: wsProvider });

	const keyring = new Keyring({ type: 'sr25519' });
	const aliceKey = keyring.addFromUri('//Alice');
	const ADDR_Alice = aliceKey.publicKey 
	const addrBob = keyring.addFromUri('//Bob').publicKey;
	let account = await api.query.system.account(ADDR_Alice);
	console.log(`balance: ${account.data.free}`)

	const txHash = await api.tx.balances.transfer(addrBob, 12345)
	    .signAndSend(aliceKey);

	console.log(`submitted with hash ${txHash}`);
	console.log('all done');

	const unsub = await api.rpc.chain.subscribeNewHeads(async (lastHeader) => {
		console.log(`latest block: #${lastHeader.number} `);
	    let {block} = await api.rpc.chain.getBlock();
	    if (block.extrinsics.length > 1) {
	    	console.log(`found extrinsic in block ${lastHeader.number}`)
	    	unsub()
	    }

	 	account = await api.query.system.account(ADDR_Alice);
		console.log(`balance: ${account.data.free}`)
	});
}

main();

4. node transfer.js, run it 3 or more times until you see the invalid transaction error

[edwardmack]

I noticed some things that may help troubleshooting this bug, using the transfer.js script I added nonce to balance query. Sometimes when a tx is finalized, the nonce for the account isn't getting incremented:

emack@ed-Oryx-Pro:~/.gossamer_test/scripts$ node transfer.js 
2021-05-07 17:04:52        API/INIT: RPC methods not decorated: chain_getFinalizedHeadByRound
api: @polkadot/api v2.8.1
balance: 19342813113826965215548997 nonce: 5
submitted with hash 0xac5d01c3eda84ed25c188a3402af3dd8a5eef9e21d49295eebad4f26a3954984
all done
latest block: #36 
balance: 19342813113826965215548997 nonce: 5
latest block: #37 
found extrinsic in block 37
balance: 19342813113825544899604582 nonce: 6
^C
emack@ed-Oryx-Pro:~/.gossamer_test/scripts$ node transfer.js 
2021-05-07 17:05:03        API/INIT: RPC methods not decorated: chain_getFinalizedHeadByRound
api: @polkadot/api v2.8.1
balance: 19342813113826965215548997 nonce: 5
submitted with hash 0xcfc26de3086f249a43e0458290bbd42d82aa6e1d9f1d58960fbb56788a493808
all done
latest block: #39 
balance: 19342813113826965215548997 nonce: 5
latest block: #39 
found extrinsic in block 39
balance: 19342813113825544899605522 nonce: 6
^C

Then running transfer.js still works, even tho the tx with nonce 5 seems to be in two different blocks. Is this normal?

[edwardmack]

When testing with transfer.js I would get error:

2021-05-07 17:05:56        RPC-CORE: submitExtrinsic(extrinsic: Extrinsic): Hash:: 1010: Invalid Transaction: null
(node:20958) UnhandledPromiseRejectionWarning: Error: 1010: Invalid Transaction: null
...

indicating the transaction failed to validate, I saw two different errors happening on the node:

• the node failed to validate the transaction returning [1 0 5] (AncientBirthBlock). Then re-running transfer.js would often work.

• However, when the node failed to validate the transaction returning [1 0 4] (BadProof, the error described in the issue), re-running transfer.js would always fail.

[noot]

I noticed some things that may help troubleshooting this bug, using the transfer.js script I added nonce to balance query. Sometimes when a tx is finalized, the nonce for the account isn't getting incremented:

emack@ed-Oryx-Pro:~/.gossamer_test/scripts$ node transfer.js 
2021-05-07 17:04:52        API/INIT: RPC methods not decorated: chain_getFinalizedHeadByRound
api: @polkadot/api v2.8.1
balance: 19342813113826965215548997 nonce: 5
submitted with hash 0xac5d01c3eda84ed25c188a3402af3dd8a5eef9e21d49295eebad4f26a3954984
all done
latest block: #36 
balance: 19342813113826965215548997 nonce: 5
latest block: #37 
found extrinsic in block 37
balance: 19342813113825544899604582 nonce: 6
^C
emack@ed-Oryx-Pro:~/.gossamer_test/scripts$ node transfer.js 
2021-05-07 17:05:03        API/INIT: RPC methods not decorated: chain_getFinalizedHeadByRound
api: @polkadot/api v2.8.1
balance: 19342813113826965215548997 nonce: 5
submitted with hash 0xcfc26de3086f249a43e0458290bbd42d82aa6e1d9f1d58960fbb56788a493808
all done
latest block: #39 
balance: 19342813113826965215548997 nonce: 5
latest block: #39 
found extrinsic in block 39
balance: 19342813113825544899605522 nonce: 6
^C

Then running transfer.js still works, even tho the tx with nonce 5 seems to be in two different blocks. Is this normal?

it looks like the first transfer didn't go through since the balance didn't change between the two script runs?

[noot]

When testing with transfer.js I would get error:

2021-05-07 17:05:56        RPC-CORE: submitExtrinsic(extrinsic: Extrinsic): Hash:: 1010: Invalid Transaction: null
(node:20958) UnhandledPromiseRejectionWarning: Error: 1010: Invalid Transaction: null
...

indicating the transaction failed to validate, I saw two different errors happening on the node:

• the node failed to validate the transaction returning [1 0 5] (AncientBirthBlock). Then re-running transfer.js would often work.
• However, when the node failed to validate the transaction returning [1 0 4] (BadProof, the error described in the issue), re-running transfer.js would always fail.

interesting, good to know there are two errors. I think the BadProof one is more concerning for now since it always causes a failure, but would be good to fix both

[noot]

this might potentially be related to #1580

[noot]

@EclesioMeloJunior yes, that is likely the issue - maybe you could find how polkadot.js is populating those fields and see if it's calling some gossamer RPC method to do that? I'd suggest setting a log to see which RPC method is being called (see dot/rpc/subscription/websocket.go HandleComm)

[EclesioMeloJunior]

Fixed by PR #1605