search

pendulum-chain / spacewalk

Apache License 2.0
35 stars 7 forks source link

Allow to recover from 'Transaction was usurped by another with the same nonce' error #566

Open ebma opened 2 weeks ago

ebma commented 2 weeks ago

Context

When the vault executes multiple issue/redeem requests at the same time, sometimes it happens that it's using the same nonce. Usually, this shouldn't happen as the nonce is tracked locally but apparently, there are still some cases were the nonce is not properly increased.

This happened in the following cases on a vault. Three pending requests were about to be executed but two of them failed. Due to this error, the execution is not retried (until the next restart). 

ct 24 08:02:35.423  INFO vault::oracle::collector::proof_builder: get_txset_from_horizon_archive(): Adding archived tx set for slot 54087699
Oct 24 08:02:35.428  WARN vault::oracle::collector::proof_builder: get_txset(): Proof Building for slot 54087699: no txset found
Oct 24 08:02:36.165  WARN vault::oracle::collector::proof_builder: get_envelopes(): Proof Building for slot 54087750: 2 envelopes is not enough to build proof
Oct 24 08:02:36.165  INFO vault::oracle::collector::proof_builder: ask_overlay_for_envelopes(): Proof Building for slot 54087750: requesting to StellarNode for messages...
Oct 24 08:02:36.165  WARN vault::oracle::collector::proof_builder: build_proof(): Couldn't build proof for slot 54087750 due to missing envelopes
Oct 24 08:02:44.143  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54076295
Oct 24 08:02:45.432  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54087699
Oct 24 08:02:46.168  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54087750
Oct 24 08:02:48.687 ERROR vault::issue: Issue task for slot 54087699 failed with error: "SubxtRuntimeError(Transaction(Invalid(\"Transaction was usurped by another with the same nonce\")))"
Oct 24 08:02:48.687 ERROR vault::issue: Issue task for slot 54076295 failed with error: "SubxtRuntimeError(Transaction(Invalid(\"Transaction was usurped by another with the same nonce\")))"
Oct 24 08:03:22.033  INFO vault::requests::structs: Successfully executed Redeem request #0x33a3…77ec
Oct 24 08:03:22.033  INFO vault::requests::execution: Successfully executed open Redeem request #0x33a33f91cdad3a33fd26091f708d02ad645b89d98090c0b3e0246cf85c9277ec
Oct 24 08:07:19.062  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:12:20.201  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:17:18.741  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar

After the restart, it happened again with the one of the two remaining requests.

ct 24 08:18:31.987  INFO vault::oracle::collector::proof_builder: get_txset_from_horizon_archive(): Adding archived tx set for slot 54076295
Oct 24 08:18:31.999  WARN vault::oracle::collector::proof_builder: get_txset(): Proof Building for slot 54076295: no txset found
Oct 24 08:18:41.705  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54087699
Oct 24 08:18:42.002  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54076295
Oct 24 08:18:42.137  WARN runtime::retry: Cannot replace existing transaction - next retry in 0.877 s
Oct 24 08:18:43.177  WARN runtime::retry: Cannot replace existing transaction - next retry in 2.197 s
Oct 24 08:18:45.589  WARN runtime::retry: Cannot replace existing transaction - next retry in 4.965 s
Oct 24 08:18:50.764  WARN runtime::retry: Cannot replace existing transaction - next retry in 8.030 s
Oct 24 08:18:59.006  WARN runtime::retry: Cannot replace existing transaction - next retry in 13.553 s
Oct 24 08:19:12.770  WARN runtime::retry: Transaction is invalid: "Transaction is outdated" - next retry in 30.250 s
Oct 24 08:19:23.884  INFO vault::issue: Successfully executed Issue #0xed0c82d689bda11bb8555a6ed24de16209f389f419285167b98a5e2c7a3f8784 for slot 54087699
Oct 24 08:19:35.989  INFO vault::redeem: Received new RequestRedeemEvent RequestRedeem { redeem_id: 0x10c1fd4baa540ae06d7cffc41fabba9a2ce66278fe516c55495dee8d3e465e47, redeemer: AccountId32([172, 127, 66, 188, 33, 9, 77, 158, 208, 225, 109, 255, 108, 138, 183, 222, 218, 46, 208, 249, 26, 117, 55, 240, 35, 247, 68, 24, 167, 77, 207, 113]), vault_id: VaultId { account_id: AccountId32([244, 6, 43, 86, 214, 43, 63, 62, 131, 129, 225, 236, 26, 218, 58, 18, 223, 57, 197, 182, 162, 94, 100, 174, 113, 246, 117, 40, 223, 18, 31, 11]), currencies: VaultCurrencyPair {collateral: Static(XCM(10)), wrapped: Static(XLM) } }, amount: 10000000000, asset: Static(XLM), fee: 0, premium: 0, stellar_address: [117, 55, 235, 150, 22, 60, 23, 152, 183, 228, 156, 97, 158, 127, 65, 147, 24, 252, 226, 28, 39, 170, 175, 76, 168, 178, 153, 164, 70, 83, 42, 104],transfer_fee: 0 }. Trying to execute...
Oct 24 08:19:36.100  INFO transfer_stellar_asset{request_type=Redeem request_id=0x10c1fd4baa540ae06d7cffc41fabba9a2ce66278fe516c55495dee8d3e465e47}: vault::requests::structs: For Redeem request #0x10c1…5e47: Sending 100000 stroops of AssetTypeNative to PublicKeyTypeEd25519([117, 55, 235, 150, 22, 60, 23, 152, 183, 228, 156, 97, 158, 127, 65, 147, 24, 252, 226, 28, 39, 170, 175, 76, 168, 178, 153, 164, 70, 83, 42, 104]) from StellarWallet [public key: GDDOKFOJ2UVYTGYTBQM54JAHNJNN35DARA4LX37KXKTNJGNVZWYEZNSI, public network: true]
Oct 24 08:19:41.171  INFO transfer_stellar_asset{request_type=Redeem request_id=0x10c1fd4baa540ae06d7cffc41fabba9a2ce66278fe516c55495dee8d3e465e47}: vault::requests::structs: For Redeem request #0x10c1…5e47: Successfully sent stellar payment to PublicKeyTypeEd25519([117, 55, 235, 150, 22, 60, 23, 152, 183, 228, 156, 97, 158, 127, 65, 147, 24, 252, 226, 28, 39, 170, 175, 76, 168, 178, 153, 164, 70, 83, 42, 104]) for 10000000000
Oct 24 08:19:41.171  WARN vault::oracle::collector::proof_builder: get_envelopes(): Proof Building for slot 54087932: 1 envelopes is not enough to build proof
Oct 24 08:19:41.171  INFO vault::oracle::collector::proof_builder: ask_overlay_for_envelopes(): Proof Building for slot 54087932: requesting to StellarNode for messages...
Oct 24 08:19:41.171  WARN vault::oracle::collector::proof_builder: build_proof(): Couldn't build proof for slot 54087932 due to missing envelopes
Oct 24 08:19:51.172  WARN vault::oracle::collector::proof_builder: get_envelopes(): Proof Building for slot 54087932: 4 envelopes is not enough to build proof
Oct 24 08:19:51.172  INFO vault::oracle::collector::proof_builder: ask_overlay_for_envelopes(): Proof Building for slot 54087932: requesting to StellarNode for messages...
Oct 24 08:19:51.172  WARN vault::oracle::collector::proof_builder: build_proof(): Couldn't build proof for slot 54087932 due to missing envelopes
Oct 24 08:20:01.178  INFO vault::oracle::agent: get_proof(): Successfully build proof for slot 54087932
Oct 24 08:20:06.157 ERROR vault::issue: Issue task for slot 54076295 failed with error: "SubxtRuntimeError(Transaction(Invalid(\"Transaction was usurped by another with the same nonce\")))"
Oct 24 08:20:58.251  INFO vault::requests::structs: Successfully executed Redeem request #0x10c1…5e47
Oct 24 08:20:58.251  INFO vault::redeem: Completed Redeem request #0x10c1fd4baa540ae06d7cffc41fabba9a2ce66278fe516c55495dee8d3e465e47 with amount 10000000000
Oct 24 08:23:16.133  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:28:16.179  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:33:16.158  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:38:18.008  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:43:16.937  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:48:16.160  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar
Oct 24 08:53:16.529  INFO vault::oracle::agent: listen_for_stellar_messages(): health check: received message from Stellar

TODO

ebma commented 2 weeks ago

@pendulum-chain/product this is a bug fix/improvement because sometimes requests are not executed properly if a multitude of them are pending at the same time.

prayagd commented 6 days ago

considering this a bug and taking it as priority as there may be multiple offramp request could be created which leads to multiple redeem requests