reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend #1724

shamardy · 2023-03-16T22:40:18Z

mm2src/mm2_main/src/lp_swap/swap_watcher.rs

cipig · 2023-03-17T00:37:54Z

tried and maker is still failing the swap although takerpayment was sent fine: https://polygonscan.com/tx/0x0934ae0afd1c1d59cf6e0fadaf12fc992473528183f4cd61764b0b44d3de4790

{
   "error_events" : [
      "StartFailed",
      "NegotiateFailed",
      "TakerFeeValidateFailed",
      "MakerPaymentTransactionFailed",
      "MakerPaymentDataSendFailed",
      "MakerPaymentWaitConfirmFailed",
      "TakerPaymentValidateFailed",
      "TakerPaymentWaitConfirmFailed",
      "TakerPaymentSpendFailed",
      "TakerPaymentSpendConfirmFailed",
      "MakerPaymentWaitRefundStarted",
      "MakerPaymentRefundStarted",
      "MakerPaymentRefunded",
      "MakerPaymentRefundFailed",
      "MakerPaymentRefundFinished"
   ],
   "events" : [
      {
         "event" : {
            "data" : {
               "lock_duration" : 7800,
               "maker_amount" : "62.96899679392804964082473948598945873051742573353275148582957266875671063023915217826046556761327458",
               "maker_coin" : "SYS",
               "maker_coin_htlc_pubkey" : "025d81c96aa4269c5946c0bd8dad7785ae0f4f595e7aea2ec4f8fe71f77ebf74a9",
               "maker_coin_start_block" : 1581993,
               "maker_payment_confirmations" : 1,
               "maker_payment_lock" : 1679028304,
               "maker_payment_requires_nota" : false,
               "maker_payment_trade_fee" : {
                  "amount" : "0.0001",
                  "coin" : "SYS",
                  "paid_from_trading_vol" : false
               },
               "my_persistent_pub" : "025d81c96aa4269c5946c0bd8dad7785ae0f4f595e7aea2ec4f8fe71f77ebf74a9",
               "p2p_privkey" : null,
               "secret" : "27efcc0e81417e6f6dd0d3cc0175fb4ddf1ca2d4ff6cd6c8b25071ceffa57658",
               "secret_hash" : "b21af70407dccd7cf008211f727981bb1b837550",
               "started_at" : 1679012704,
               "taker" : "3c5ba1d7ef6fa015eb33defb3aba2a961898a51bbb7ff30344d07ba75ad3f289",
               "taker_amount" : "14.58343070640505675691645244215938303341902313624678663239074550128534704370179948586118251928020566",
               "taker_coin" : "AGEUR-PLG20",
               "taker_coin_htlc_pubkey" : "025d81c96aa4269c5946c0bd8dad7785ae0f4f595e7aea2ec4f8fe71f77ebf74a9",
               "taker_coin_start_block" : 40431037,
               "taker_coin_swap_contract_address" : "9130b257d37a52e52f21054c4da3450c72f595ce",
               "taker_payment_confirmations" : 3,
               "taker_payment_requires_nota" : false,
               "taker_payment_spend_trade_fee" : {
                  "amount" : "0.0162047325",
                  "coin" : "MATIC",
                  "paid_from_trading_vol" : false
               },
               "uuid" : "a605e11d-9555-4367-8b69-e89d0ade24e1"
            },
            "type" : "Started"
         },
         "timestamp" : 1679012704563
      },
      {
         "event" : {
            "data" : {
               "maker_coin_htlc_pubkey" : "023c5ba1d7ef6fa015eb33defb3aba2a961898a51bbb7ff30344d07ba75ad3f289",
               "maker_coin_swap_contract_addr" : null,
               "taker_coin_htlc_pubkey" : "023c5ba1d7ef6fa015eb33defb3aba2a961898a51bbb7ff30344d07ba75ad3f289",
               "taker_coin_swap_contract_addr" : "9130b257d37a52e52f21054c4da3450c72f595ce",
               "taker_payment_locktime" : 1679020504,
               "taker_pubkey" : "000000000000000000000000000000000000000000000000000000000000000000"
            },
            "type" : "Negotiated"
         },
         "timestamp" : 1679012706568
      },
      {
         "event" : {
            "data" : null,
            "type" : "MakerPaymentInstructionsReceived"
         },
         "timestamp" : 1679012710738
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "f32b569b23811a9330f0d54981ab74650cb0fe0c2e9df6088843b85c77ae676b",
               "tx_hex" : "f8ae82067985186ba217408303345094e0b52e49357fd4daf2c15e02058dce6bc0057db480b844a9059cbb000000000000000000000000d8997941dd1346e9231118d5685d866294f59e5b0000000000000000000000000000000000000000000000000042ae35b0f1c414820136a0d05ff68d36771f08dc956b48752a4de20160fff812fc6abc9a04418b25e104b9a04d2314f813bcf96320c28fb9abf8b1f97ebc5f32c2985de8948d389fb5b0ad27"
            },
            "type" : "TakerFeeValidated"
         },
         "timestamp" : 1679012710742
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "6b00b9b683cd1bc625e2da948ac3b64ccc4636357310a08985cf6085a5688303",
               "tx_hex" : "0100000001430927c641a1cae2be57040869277437b9a26aaca967a64c8d761221482aa1f6020000006a47304402206a73095af2006c8fceaefd66e11a4f0631daa0cc3602590e76f5bec3ab1176bd022038e2942bf0000d71b726677e13e4c98fabbc5d36a5b62315d585c49af45d3b650121025d81c96aa4269c5946c0bd8dad7785ae0f4f595e7aea2ec4f8fe71f77ebf74a9ffffffff035f1053770100000017a9144b3c5fae897f1d990eb95f87066dcd48f92b6dc2870000000000000000166a14b21af70407dccd7cf008211f727981bb1b8375506e26fe0f030000001976a914793634de8c88ec851b4b595f2f87a2071ae79c5b88ac66b31364"
            },
            "type" : "MakerPaymentSent"
         },
         "timestamp" : 1679012710942
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "0934ae0afd1c1d59cf6e0fadaf12fc992473528183f4cd61764b0b44d3de4790",
               "tx_hex" : "f9012e82067a8516c4bcfb80830249f0949130b257d37a52e52f21054c4da3450c72f595ce80b8c49b415b2a6246c05f8f14817bc5e2a544006f9c46b4f75c4867b2418926d788c35a38e2f5000000000000000000000000000000000000000000000000ca62c0f60dcc20f4000000000000000000000000e0b52e49357fd4daf2c15e02058dce6bc0057db40000000000000000000000005535280d956b00f22a30a51f2e43e3cfdf5099ceb21af70407dccd7cf008211f727981bb1b837550000000000000000000000000000000000000000000000000000000000000000000000000000000006413d1d8820136a08df525e47f89659c2486f86c69a58f696d6c3fa57faf8d8a0fb013481129c80da0245af8422330b2e69ae5676ced01b9e040a49ff72007eec0d75f844a52c112ae"
            },
            "type" : "TakerPaymentReceived"
         },
         "timestamp" : 1679012954232
      },
      {
         "event" : {
            "type" : "TakerPaymentWaitConfirmStarted"
         },
         "timestamp" : 1679012954236
      },
      {
         "event" : {
            "data" : {
               "error" : "maker_swap:1030] !taker_coin.validate_taker_payment: eth:3686] Payment state is not PAYMENT_STATE_SENT, got 0"
            },
            "type" : "TakerPaymentValidateFailed"
         },
         "timestamp" : 1679012969948
      },
      {
         "event" : {
            "data" : {
               "wait_until" : 1679032004
            },
            "type" : "MakerPaymentWaitRefundStarted"
         },
         "timestamp" : 1679012969953
      },
      {
         "event" : {
            "type" : "MakerPaymentRefundStarted"
         },
         "timestamp" : 1679012970017
      }
   ],
   "gui" : "mpm",
   "maker_amount" : "62.96899679392804964082473948598945873051742573353275148582957266875671063023915217826046556761327458",
   "maker_coin" : "SYS",
   "maker_coin_usd_price" : null,
   "mm_version" : "1.0.0-beta_10580_bugfix-evm-payment-state_e113ce5c5_Linux_CI",
   "my_order_uuid" : "a234b3a2-fe12-441c-abfa-cb366c7a3f54",
   "success_events" : [
      "Started",
      "Negotiated",
      "MakerPaymentInstructionsReceived",
      "TakerFeeValidated",
      "MakerPaymentSent",
      "TakerPaymentReceived",
      "TakerPaymentWaitConfirmStarted",
      "TakerPaymentValidatedAndConfirmed",
      "TakerPaymentSpent",
      "TakerPaymentSpendConfirmStarted",
      "TakerPaymentSpendConfirmed",
      "Finished"
   ],
   "taker_amount" : "14.58343070640505675691645244215938303341902313624678663239074550128534704370179948586118251928020566",
   "taker_coin" : "AGEUR-PLG20",
   "taker_coin_usd_price" : null,
   "type" : "Maker",
   "uuid" : "a605e11d-9555-4367-8b69-e89d0ade24e1"
}

console on maker during swap failure:

17 00:29:14, maker_swap:956] INFO Taker payment tx 0934ae0afd1c1d59cf6e0fadaf12fc992473528183f4cd61764b0b44d3de4790
+--- 17 00:29:14 -------
| (4:09) [swap uuid=a605e11d-9555-4367-8b69-e89d0ade24e1] Taker payment wait confirm started...
| (0:00/99:49) [AGEUR-PLG20] Waiting for confirmations…
· 2023-03-17 00:29:29 +0000 [AGEUR-PLG20] Waiting for confirmations… Confirmed.
+--- 17 00:29:29 -------
| (4:25) [swap uuid=a605e11d-9555-4367-8b69-e89d0ade24e1] Taker payment validate failed...
+--- 17 00:29:38 -------
| (4:33) [swap uuid=a605e11d-9555-4367-8b69-e89d0ade24e1] Maker payment refund started...

shamardy · 2023-03-17T12:33:16Z

tried and maker is still failing the swap although takerpayment was sent fine:

Do you use the same RPC node for these swaps? Can you try at least 2 other RPC nodes, it's really strange that this is still failing in validate_taker_payment since it passed the check in the wait_for_confirmations function where payment state was not 0
https://github.com/KomodoPlatform/atomicDEX-API/blob/e113ce5c5ef2c28f12eda7703e9789965d491434/mm2src/coins/eth.rs#L3911-L3921
So it seems that the RPC node is returning an outdated state sometimes after returning the updated state, maybe this RPC fetches the info from a different source everytime and sometimes it gets it from an outdated source.

Anyways, if it's not the RPC node then it must be something specific to polygon since this only happens with them.

shamardy · 2023-03-17T12:37:26Z

@cipig was the taker able to automatically refund the payment? I also fixed this part which was unrelated to the payment state bug.

cipig · 2023-03-17T13:12:26Z

Do you use the same RPC node for these swaps? Can you try at least 2 other RPC nodes

both maker and taker are using https://polygon-rpc.com
it's their main, loadbalanced endpoint... open the URL in browser to see which endpoints are used and with which weight
the other endpoints mentioned here https://chainlist.org/chain/137 are mainly the same ones as the ones behind https://polygon-rpc.com, so idk if it makes sense to add them separately/additionally

we had some of them added to config in the past, separately, but it didn't make a difference, the notifications about 0 MATIC balance were still there in ADEX DEsktop
and on the makers too, this error is sometimes shown when posting PLG20 orders: rpc:211] dispatcher_legacy:141] lp_ordermatch:4541] check_balance:157] Not enough base coin MATIC balance for swap: available 0, required at least 0.0314015625, locked by swaps Some(BigDecimal("0")) although that maker has 33.496046513733041102 MATIC

cipig · 2023-03-17T13:16:33Z

@cipig was the taker able to automatically refund the payment? I also fixed this part which was unrelated to the payment state bug.

i had this one that refunded automatically after 8h

the error block range is too wide was still in the logs... it starts ~2h after swap started... but the swap was refunded successfully

shamardy · 2023-03-17T14:16:29Z

it's their main, loadbalanced endpoint

Then it seems that my guess was correct in that this endpoint fetches the info from a different source everytime and sometimes it gets it from a source that is a bit late, you use 3 confirmations for these swaps and in this list https://chainlist.org/chain/137 some servers sometimes are lagging by 3 or more blocks. I can also guess that this problem doesn't happen with every polygon swap, or does it?

I think you would need to use higher confirmations for polygon swaps if you continue using this loadbalanced endpoint (there is also the problem of block reorganizations in polygon that requires high number of confirmations), or you can use 3 confirmations but the source of data would have to be only one server to avoid race conditions.

we had some of them added to config in the past, separately, but it didn't make a difference, the notifications about 0 MATIC balance were still there in ADEX DEsktop
and on the makers too, this error is sometimes shown when posting PLG20 orders: rpc:211] dispatcher_legacy:141] lp_ordermatch:4541] check_balance:157] Not enough base coin MATIC balance for swap: available 0, required at least 0.0314015625, locked by swaps Some(BigDecimal("0")) although that maker has 33.496046513733041102 MATIC

This is a different issue, but I understand that using one server only will return outdated data sometimes. It seems having higher confirmations is the best solution.

the error block range is too wide was still in the logs...

I will look into that, it's because polygon blocktime is very low, so the search for spend events in the logs uses a large block range after sometime which is not accepted. It used to loop without ever returning that's why automatic refunds didn't work but this part is fixed in this PR. This problem shouldn't happen in ETH as far as I can see, but if we will support EVM chains with fast blocktimes or L2 ETH chains this should be fixed.

cipig · 2023-03-17T14:27:00Z

I can also guess that this problem doesn't happen with every polygon swap, or does it?

No, it doesn't, many swaps are working fine.
I will increase required_confirmations for PLG20 to 9 (from 3) and see how it goes.

shamardy · 2023-03-17T14:33:04Z

No, it doesn't, many swaps are working fine.
I will increase required_confirmations for PLG20 to 9 (from 3) and see how it goes.

This will decrease the occurrence of this issue a lot. But it can still happen rarely.

caglaryucekaya

If the problem is with RPC nodes, is calling the eth_getTransactionByHash and confirming the swap payment state in the wait_for_confirmations method still useful? It looks like these fixes only shifted the point of failure.

shamardy · 2023-03-17T18:01:24Z

If the problem is with RPC nodes, is calling the eth_getTransactionByHash and confirming the swap payment state in the wait_for_confirmations method still useful? It looks like these fixes only shifted the point of failure.

I agree, I wasn't aware of the exact problem at first and I used Artem's suggestions here #1630 (comment) for the fix, but after @cipig testing, I found out the real problem. I moved this to in progress to check if this fix is actually needed, I will optimize the calls in the wait_for_confirmation function since they are currently excessive, we call eth_getTransactionReceipt in every loop until confirmation even after we got the receipt successfully once. We can call it until 1 confirmation then only use the block number to know if we got enough confirmations, then call it again to make sure it still has the right confirmations (to make sure no block reorgs happened), I can even use eth_getTransactionByHash in the second check.

I still think I should leave the refactor of having a struct for ConfirmPaymentInput, since it will make it easier to add fields to it in the future. This PR also solves a problem where auto refund doesn't happen sometimes because of an endless loop.

shamardy · 2023-03-20T19:54:25Z

@caglaryucekaya @laruh @cipig this ready for another review/testing after I applied the changes proposed here #1724 (comment).

We can call it until 1 confirmation then only use the block number to know if we got enough confirmations, then call it again to make sure it still has the right confirmations (to make sure no block reorgs happened), I can even use eth_getTransactionByHash in the second check.

I used eth_getTransactionReceipt for the second check as well since it actually make no difference which method to call and to reuse the same transaction_confirmed_at function instead of making another function for getting confirmed_at from eth_getTransactionByHash.

caglaryucekaya

Great work! I have one minor comment

caglaryucekaya · 2023-03-20T22:06:14Z

mm2src/coins/eth.rs

+                    .await
+                {
+                    Ok(conf) => {
+                        if conf == confirmed_at {


You can add status.append(" Confirmed.") here.

Thank you for finding this, looks like I missed it in the refactor.

laruh

LGTM! as i can see you also fixed tbtc test, thanks!

cipig · 2023-03-21T11:58:26Z

did a bunch of swaps, had only once a problem with a specific mm2 node of mine
was stuck in getting nonce for sending makerpayment (MATIC)

| (3:00) [swap uuid=249cb9f4-2a46-442f-ae24-e7b84fd606cf] Taker fee validated...
| (2:57) [sign-and-send] get_addr_nonce…

happened twice in a row... first swap was already in refund mode: https://dexapi.cipig.net/public/error.php?uuid=cd679db0-0cb1-4cce-8ee1-ccd80b6aa3cd (same reason)
then i restarted mm2 while i saw that the second swap will also fail
after restart, the second swap continued fine and finished successfully
so either mm2 got stuck or it is related to the RPC endpoint (https://polygon-rpc.com)
not sure if related to this PR though, but maybe a retry is possible in such cases... i would assume that the second try has a chance to be tried on a different endpoint (https://polygon-rpc.com switches them in the background) and thus has a chance to succeed

shamardy · 2023-03-21T14:03:53Z

was stuck in getting nonce for sending makerpayment (MATIC)

@cipig Probably related to the below code, let's open another issue for it and I can work on it next week since this is unrelated to this PR.
https://github.com/KomodoPlatform/atomicDEX-API/blob/e441ffa9681598ab5cbeb171ffe10fe8a5cc8768/mm2src/coins/eth.rs#L3982-L4007
P.S. I really want evm swaps to be as stable as possible since we will add more layers to it with watchers and native swaps in the future.

shamardy · 2023-03-21T14:07:00Z

Moved this to in progress again, since the below confirmation_block_number makes us wait for 1 additional confirmation to the required_confirms, this is causing trade_test_electrum_and_eth_coins to take a long time too.
https://github.com/KomodoPlatform/atomicDEX-API/blob/e441ffa9681598ab5cbeb171ffe10fe8a5cc8768/mm2src/coins/eth.rs#L1774

…ecks for overflow

caglaryucekaya · 2023-03-21T15:41:15Z

#1724 (comment) I didn't understand the problem with the old confirmation block number, why does it wait for 1 additional confirmation?

shamardy · 2023-03-21T16:04:30Z

I didn't understand the problem with the old confirmation block number, why does it wait for 1 additional confirmation?

if the required_confirms are 1 and the transaction is confirmed in block 100 then confirmation_block_number should be 100 which means this line should be

let confirmation_block_number = confirmed_at + required_confirms - 1;

I didn't subtract 1 before the latest commit, I found the problem because trade_test_electrum_and_eth_coins was taking a long time.

caglaryucekaya · 2023-03-21T16:12:52Z

if the required_confirms are 1 and the transaction is confirmed in block 100 then confirmation_block_number should be 100 which means this line should be

Okay thanks, I didn't know that the first block the transaction is mined is also counted as confirmation.

caglaryucekaya

LGTM 🔥

shamardy added 3 commits March 17, 2023 00:38

wait for confirmation of evm swap payment state initialization

847ceb5

remove unneeded todo related to checking payment state for QRC20

8cc8d2c

remove another todo that is not needed

bccb69c

shamardy commented Mar 16, 2023

View reviewed changes

mm2src/mm2_main/src/lp_swap/swap_watcher.rs Outdated Show resolved Hide resolved

shamardy requested review from cipig, caglaryucekaya and laruh March 16, 2023 22:56

shamardy added the under review label Mar 16, 2023

fix test_tx_history_tbtc_non_segwit

e113ce5

shamardy added in progress Changes will be made from the author and removed under review labels Mar 17, 2023

caglaryucekaya suggested changes Mar 17, 2023

View reviewed changes

shamardy added 2 commits March 20, 2023 16:56

remove wait_for_payment_state_initialization check

af9e4b7

reduce eth wait_for_confirmations calls

263ca43

shamardy changed the title ~~Wait for confirmation of evm swap payment state initialization~~ reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend Mar 20, 2023

fix another endless loop issue introduced by the new code

020ff25

shamardy added under review and removed in progress Changes will be made from the author labels Mar 20, 2023

caglaryucekaya suggested changes Mar 20, 2023

View reviewed changes

laruh previously approved these changes Mar 21, 2023

View reviewed changes

log confirmation by adding status.append(" Confirmed.")

e441ffa

shamardy dismissed laruh’s stale review via e441ffa March 21, 2023 12:47

shamardy added 2 commits March 21, 2023 14:51

add entry for #1724 in change log

606def8

Merge remote-tracking branch 'origin/dev' into bugfix-evm-payment-state

b54dbef

shamardy added in progress Changes will be made from the author and removed under review labels Mar 21, 2023

fix confirmation_block_number to be the right block number and add ch…

ba4a267

…ecks for overflow

shamardy added under review and removed in progress Changes will be made from the author labels Mar 21, 2023

caglaryucekaya approved these changes Mar 21, 2023

View reviewed changes

shamardy merged commit b0cc19e into dev Mar 21, 2023

shamardy deleted the bugfix-evm-payment-state branch March 21, 2023 17:43

ca333 mentioned this pull request Mar 27, 2023

[release] 1.0.1-beta #1721

Merged

shamardy mentioned this pull request Apr 14, 2023

avoid waiting for all EVM nodes to sync the latest nonce #1757

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend #1724

reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend #1724

shamardy commented Mar 16, 2023

cipig commented Mar 17, 2023 •

edited

shamardy commented Mar 17, 2023

shamardy commented Mar 17, 2023

cipig commented Mar 17, 2023

cipig commented Mar 17, 2023

shamardy commented Mar 17, 2023

cipig commented Mar 17, 2023

shamardy commented Mar 17, 2023

caglaryucekaya left a comment

shamardy commented Mar 17, 2023

shamardy commented Mar 20, 2023

caglaryucekaya left a comment

caglaryucekaya Mar 20, 2023

shamardy Mar 21, 2023

shamardy Mar 21, 2023

laruh left a comment

cipig commented Mar 21, 2023 •

edited

shamardy commented Mar 21, 2023

shamardy commented Mar 21, 2023

caglaryucekaya commented Mar 21, 2023

shamardy commented Mar 21, 2023 •

edited

caglaryucekaya commented Mar 21, 2023

caglaryucekaya left a comment

reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend #1724

reduce evm wait_for_confirmations calls, fix endless loop in wait_for_htlc_tx_spend #1724

Conversation

shamardy commented Mar 16, 2023

cipig commented Mar 17, 2023 • edited

shamardy commented Mar 17, 2023

shamardy commented Mar 17, 2023

cipig commented Mar 17, 2023

cipig commented Mar 17, 2023

shamardy commented Mar 17, 2023

cipig commented Mar 17, 2023

shamardy commented Mar 17, 2023

caglaryucekaya left a comment

Choose a reason for hiding this comment

shamardy commented Mar 17, 2023

shamardy commented Mar 20, 2023

caglaryucekaya left a comment

Choose a reason for hiding this comment

caglaryucekaya Mar 20, 2023

Choose a reason for hiding this comment

shamardy Mar 21, 2023

Choose a reason for hiding this comment

shamardy Mar 21, 2023

Choose a reason for hiding this comment

laruh left a comment

Choose a reason for hiding this comment

cipig commented Mar 21, 2023 • edited

shamardy commented Mar 21, 2023

shamardy commented Mar 21, 2023

caglaryucekaya commented Mar 21, 2023

shamardy commented Mar 21, 2023 • edited

caglaryucekaya commented Mar 21, 2023

caglaryucekaya left a comment

Choose a reason for hiding this comment

cipig commented Mar 17, 2023 •

edited

cipig commented Mar 21, 2023 •

edited

shamardy commented Mar 21, 2023 •

edited