Transactions removed from mempool

[garethtdavies]

I was bulk sending payments - spaced apart by 10 seconds as have issues before with sending multiple transactions within a short time frame.

In this case, transactions were sent successfully from nonce 4->80 and were all received. Nonce 81-86 were sent via GraphQL and payment hashes returned for each but these payments were never received. An example is below.

8Y6GSZvuW1bNvwe67GWKMnyhR6UWs2sCQ5kfTjprZuFS2UDBoHqhCZb3VX4Sprdr6Q6hebxWx56QDt5pr12MFLbRpE6mE2a8ZkQ1XDRJYYv3GCgKsNehkJF9AoJf37Rrjq2UZkqD8M7FubJ3ZCcdwBLQwAeen6cANvYvtQr1bbAUERcLQFR6B44oMnj6B3UEQSPsSBdL9ftkL7Sw85kqwfWPar4Z6SNXAVZ3Z6kPAK27TqVpt4oDj4GGwyWQVvJC9vezrroJw6UxhjgeEWxmM7RhrKaH8XmkP4HZx5hsj6AKT8Ex38aM8d97kSZPYdHQXn6EW2mXXaiuut479m2hveuwjqnzLPRPGKUznZnTycGMzBHZp1XE7Hbx5Danmhen33sHVmMGKonXn2T4

The transaction with nonce 87 had an error from GraphQL of Error creating user command. Looking at the GraphQL query it seems that it may have passed in a value of null for the nonce (I have no idea why as the signed transaction is nonce 87).

All the pending transactions in the mempool were dropped i.e. 81->86. I tried to resend but faced the "already seen" error so was forced to resign the tx and resend and was successful.

While I would expect the transaction with nonce 87 to have failed given a seemingly invalid nonce, I was not expecting the previously broadcasted tx to be dropped.

[garethtdavies]

Archive.zip

I think the logs are here but this looks like where they are dropped.

{"timestamp":"2021-03-18 17:04:36.592959Z","level":"Info","source":{"module":"Network_pool__Transaction_pool","location":"File \"src/lib/network_pool/transaction_pool.ml\", line 531, characters 8-29"},"message":"Locally generated commands $cmds dropped because they conflicted with a committed command.","metadata":{"$duplicated_keys":["host","peer_id","port"],"cmds":[{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","nonce":"85","valid_until":"4294967295","memo":"E4Z4SeYHiiuNXGWBGh66vSMJfbBgtih9E1PDa6EMEnqxzGZ9XgNCW"},"body":["Payment",{"source_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","receiver_pk":"B62qjJ8mNz65hUKWTh5wYbaHDa9nqfhz21JbY4ts69xBNYhTQxbQzCJ","token_id":"1","amount":"37333809323"}]},"signer":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","signature":"7mXMsHXgYVEmtHokpzGDBQARJVNxsdncXhYEjtwVFXp4NoaFCSDMwcTenUZD6WdTTqXi1dBUBkn2k3jMQFheWoTw7n52cA4z"}],"hash":"CkpZwjzzk4jTxJAnzL14UbNTRCBn4p7HzLbgMULc86t1NwwFfUCyS"},{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","nonce":"84","valid_until":"4294967295","memo":"E4Z4SeYHiiuNXGWBGh66vSMJfbBgtih9E1PDa6EMEnqxzGZ9XgNCW"},"body":["Payment",{"source_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","receiver_pk":"B62qpGyTotKHjKuT9GNb9SG2gH44RwkdpzfFSpvrTLTNx77onpvwfpE","token_id":"1","amount":"37333809323"}]},"signer":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","signature":"7mX9ixpZ4Yo6PnjzhKq3qWjac2iYRC2hEe9axrsxwt7Kgyx4hoG5cNPsht78aCcUB5W4tdawZ5tpgJoywQX6Kast1D7BXLr6"}],"hash":"CkpYqmnmMJk32qBfkKbRGdyU3p7L1ZGtFFY6pakLfb5MrDybWwHog"},{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","nonce":"83","valid_until":"4294967295","memo":"E4Z4SeYHiiuNXGWBGh66vSMJfbBgtih9E1PDa6EMEnqxzGZ9XgNCW"},"body":["Payment",{"source_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","receiver_pk":"B62qowSjKkwtESnVZtaZpvuPJFbkygn5CZo5Ym9AKTHX7hMjMEhGGKY","token_id":"1","amount":"37333809323"}]},"signer":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","signature":"7mXUkM5ssZsYJ82iH4Ygmijvci37PpCe6FMUVAUojdQro4DwdEMKHLnC5EpAGYWP6QH4zVecmiscaLTPjuhzv6nimkJ73kZu"}],"hash":"CkpZVpM1S1TbufVjY9wK8pHBxeMnix4BHjTnh2bqRxV3LUZqwYBfs"},{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","nonce":"82","valid_until":"4294967295","memo":"E4Z4SeYHiiuNXGWBGh66vSMJfbBgtih9E1PDa6EMEnqxzGZ9XgNCW"},"body":["Payment",{"source_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","receiver_pk":"B62qowXgtSfrWgMwvP6yxe3Z3JnpRHKZhsWCRLETNvMnT7ezeT6rA4c","token_id":"1","amount":"37333809323"}]},"signer":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","signature":"7mXKhQ3TCvh3aphthAn7af61hY24DwoYfqD76m4dYV3KWxc67M3pkP3nMfr7aiZY567CFGs5XuBNp3P4GaGoJLBJ6QCQ1qM8"}],"hash":"Ckpa7wYAvFqer75cN7JaDzNSypEoCnqbXWmyTaCi8pNor2CgQgH46"},{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","nonce":"81","valid_until":"4294967295","memo":"E4Z4SeYHiiuNXGWBGh66vSMJfbBgtih9E1PDa6EMEnqxzGZ9XgNCW"},"body":["Payment",{"source_pk":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","receiver_pk":"B62qnYnbEvsgp6XxhniNMSJWA43S1KhWFTa5yj8eNxesUT4oy1SC7r3","token_id":"1","amount":"37333809323"}]},"signer":"B62qk9WYHu2PBYv4EyEubnVQURcwpiV2ysuYYoMdwi8YTnwZQ7H4bLM","signature":"7mXLdQwrbepWkCHkRiJNgCWCNczR7nabfFbNCoKw12PjHNdU3mhzVCyySuZshXYJLz1C9He9Pn35v7d7Ejp3oaSbNahtgKfx"}],"hash":"CkpZjrM384FU6M45hVobQvo4hGjJWXRiGwCX8GppySAneSkJRwU9y"}]```

[garethtdavies]

So, I just realized I'm not passing the nonce of the signed transactions to broadcast. So it must be inferring the nonce and this causes the issues above as perhaps if it fails it returns null and that has the effect of invalidating all the other transactions in the mempool?

To resolve, I will pass the nonce correctly but will leave it open as unsure if the other behavior is expected.

[mnguyen-io]

Hi there - I experienced a similar/same issue today when issuing payments via the mina CLI (mina client send-payment). I was looping through a few payments (19 or so) and somewhere in between there (at about payment 11-13) it seems the payment failed. There was a 1minute sleep between commands isseud. When looking up the transaction based on the returned paymentID (yes - a paymentID was returned for the failed transactions), I may have been a bit too late to find it as the status came back as UNKNOWN.

Logs show an error for one of the transactions, but no error for the other. The one that came up with an error (below) was executed 1 minute before the other one that I could not find an error for although I can see a 'Schedule payment' command for it in the logs.

{"timestamp":"2021-04-01 21:26:03.237540Z","level":"Info","source":{"module":"Network_pool__Transaction_pool","location":"File \"src/lib/network_pool/transaction_pool.ml\", line 531, characters 8-29"},"message":"Locally generated commands $cmds dropped because they conflicted with a committed command.","metadata":{"cmds":[{"data":["Signed_command",{"payload":{"common":{"fee":"0.01","fee_token":"1","fee_payer_pk":"B62qqSUUCnoC8Vehw5xwhrnaNxhk6Xe3FcBhngoxyXCbJBfvVhiqia1","nonce":"17","valid_until":"4294967295","memo":"E4Yd7qwaRCHR6t7i6ToM98eSUy5eKKadQUPZX7Vpw4CWBvWyd8fzK"},"body":["Payment",{"source_pk":"B62qqSUUCnoC8Vehw5xwhrnaNxhk6Xe3FcBhngoxyXCbJBfvVhiqia1","receiver_pk":"B62qmru4aEDszwLFvH59BtZnU4QLC52nrSRBJW1EfdAp8cD5drg8QFM","token_id":"1","amount":"1418704594000"}]},"signer":"B62qqSUUCnoC8Vehw5xwhrnaNxhk6Xe3FcBhngoxyXCbJBfvVhiqia1","signature":"7mX4kKQYEtQWUC7VDVT9YWm5sjjQJVD7DnCSDnDyDT1f2HPFr68Mogu3zadUbR7deTTzkVkZaQCXRjJFutuVoEMPUpmSDJUp"}],"hash":"CkpYzYLk6Vc3UqQc2KZMoGaDHTLSa7PRMJRfja3BBJPs1DxqzyscE"}],"host":"143.110.214.194","peer_id":"12D3KooWPsXJjMhRiqYQz5xs3qTxzt5uQ3DjMN2WRN81siTRhk8k","pid":8433,"port":8302}}

[nerdvibe]

faced this exact issue as well. Will try to re-sign and re-broadcast

[garethtdavies]

This issue is still present on mina-daemon:1.2.0beta1-c856692-mainnet. While it is now possible to rebroadcast the dropped transactions (which is a huge help) transactions are still dropped when sending with a small or no delay between sending counter to the instructions here https://docs.minaprotocol.com/en/using-mina/send-payment#rate-limiting.

[deepthiskumar]

@garethtdavies could you please add logs for the period you were seeing this issue?

[garethtdavies]

@garethtdavies could you please add logs for the period you were seeing this issue?

Should be in here - only logged at info. tx-dropped.json.zip

[deepthiskumar]

The transactions are not getting dropped by the node that's generated it because of the log already present in the pool when they are sent again. I'm also seeing many of these transactions on our nodes the first time they were sent. However, many are getting rejected either because they were out of order or because some transactions did not make it to a node and so the node rejected the ones that followed.

For example, one of the seeds received transactions in the following nonce order: 6471 6473 6472 6474 6475 and so on These are from different senders

As a result there is a delay in transactions getting into the pool and eventually (after 50 mins) rebroadcasts stop.

Also, the PR #8473 that fixes the original issue is only on beta release. Nodes that are not running beta would still drop transactions from their pools and cause transaction pool inconsistencies (probably are causing gossip inconsistency as well?)

I don't see any logs in our seeds that say the rate limit was exceeded, so that doesn't seem to be the issue here.

[p-shahi]

Relates to https://github.com/MinaProtocol/mina/discussions/9868

[p-shahi]

No update on this issue at the moment, we are looking to refactor the transaction pool which should address this but that is not a high priority at the moment

[shimkiv]

Similar issue is very easy to reproduce by

• Spinning up local lightweight network introduced by these changes https://github.com/MinaProtocol/mina/pull/13287.
• And then create simple value transfer txns once in 3-5 seconds in total amount of txn to be ~150-200.