Payment state is not PAYMENT_STATE_SENT, got 0 on Polygon.

[cipig]

Some PLG20 (Polygon) swap fail

TAKER console:

· 2022-03-15 22:36:03 +0000 [] lp_ordermatch:2844] Entering the taker_swap_loop ETH-PLG20/QTUM with uuid: a8c63959-f7f2-499e-8551-b093e33ff825
15 22:36:03, atomicdex_gossipsub:behaviour:188] INFO Subscribed to topic: swap/a8c63959-f7f2-499e-8551-b093e33ff825
15 22:36:03, lp_swap:963] ERROR No such swap with the uuid 'a8c63959-f7f2-499e-8551-b093e33ff825'
+--- 15 22:36:06 -------
| (0:00) [swap uuid=a8c63959-f7f2-499e-8551-b093e33ff825] Started...
15 22:36:07, taker_swap:1034] Taker fee tx hash 0b890e59068a9623d87203f9e076a58e22d991b2b0ccde56a1191efe81fce545
+--- 15 22:36:14 -------
| (0:09) [swap uuid=a8c63959-f7f2-499e-8551-b093e33ff825] Taker fee sent...
15 22:36:15, taker_swap:1086] Got maker payment c472efbec24c3ab7d7e2b91c0b5de4be855f05680fc877c2eabf415e56c4786d
15 22:36:15, taker_swap:1099] Before wait confirm
+--- 15 22:36:23 -------
| (0:17) [swap uuid=a8c63959-f7f2-499e-8551-b093e33ff825] Maker payment wait confirm started...
| (0:07/51:49) [ETH-PLG20] Waiting for confirmations…
· 2022-03-15 22:36:45 +0000 [ETH-PLG20] Waiting for confirmations… Confirmed.
15 22:36:45, taker_swap:1114] After wait confirm
+--- 15 22:36:46 -------
| (0:41) [swap uuid=a8c63959-f7f2-499e-8551-b093e33ff825] Maker payment wait confirm started...
· 2022-03-15 22:36:47 +0000 [swap uuid=a8c63959-f7f2-499e-8551-b093e33ff825] Finished

TAKER swap file/error:

      {
         "event" : {
            "data" : {
               "tx_hex" : "f9012c6d850ba7366480830249f0949130b257d37a52e52f21054c4da3450c72f595ce80b8c49b415b2a41ef12a3fd6325ee73ba7215fe82b03a1aa6fc88740cf669e483b682d98aeac2000000000000000000000000000000000000000000000000005b47fb104cda9e0000000000000000000000007ceb23fd6bc0add59e62ac25578270cff1b9f619000000000000000000000000042c35b21846301e57029c6095a2910e455c2ec3eace8d9ee3f2a1189805d3d966e872b178f5bd6b00000000000000000000000000000000000000000000000000000000000000000000000000000000623151c4820135a04d08156f822a02807b2d35dfc31917231d47747ef750fb4d5c7a5cb5de9409e7a03066503de18b9eff4d51d7e73b02fa14b871ef8b62255f93ec01f81185cacbb2",
               "tx_hash" : "c472efbec24c3ab7d7e2b91c0b5de4be855f05680fc877c2eabf415e56c4786d"
            },
            "type" : "MakerPaymentReceived"
         },
         "timestamp" : 1647383775377
      },
      {
         "event" : {
            "type" : "MakerPaymentWaitConfirmStarted"
         },
         "timestamp" : 1647383775378 10:36:15
      },
      {
         "event" : {
            "data" : {
               "error" : "taker_swap:1129] !validate maker payment: eth:2557] Payment state is not PAYMENT_STATE_SENT, got 0"
            },
            "type" : "MakerPaymentValidateFailed"
         },
         "timestamp" : 1647383807541 10:36:47
      },
      {
         "timestamp" : 1647383807543,
         "event" : {
            "type" : "Finished"
         }
      }

makerpayment from Mar-15-2022 10:36:13 PM +UTC: https://polygonscan.com/tx/0xc472efbec24c3ab7d7e2b91c0b5de4be855f05680fc877c2eabf415e56c4786d

taker failed swap with MakerPaymentValidateFailed on 10:36:47, looks like 30s

we are using https://polygon-rpc.com RPC node
i assume the tx took longer then 30s to propagate/be indexed by the PLG20 RPC node, so my suggestion is to increase the timeout from MakerPaymentWaitConfirmStarted to MakerPaymentValidateFailed to 60s

another such failed swap from today: https://dexapi.cipig.net/public/error.php?uuid=c66b6457-449e-4dda-bc8d-75a50e8ea995
same error, Payment state is not PAYMENT_STATE_SENT, got 0

EDIT: could the problem be solved by increasing the required_confirmations on PLG20 to eg 10?
we are currently using this:

    "avg_blocktime": 0.03,
    "required_confirmations": 3

btw, this happens sometimes:
15 23:04:57, coins:web3_transport:178] WARN web3_transport:177] Error requesting 'https://polygon-rpc.com/': 60s timeout expired
but idk which API call, mus be setprice, my_balance or get_fee
anyway, just wanted to mention that timeouts on PLG20 RPC nodes are not totally unusual and we should consider it

[artemii235]

@Milerius Could you take a look this or next week?

[Milerius]

@Milerius Could you take a look this or next week?

Yes

[artemii235]

@cipig NB #1225 (comment)

[cipig]

had another such failed swap on maker side, even after #1716 on both maker and taker

{
   "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" : "2557.658802072388474759568962187632768143370283109960990305511567726236916302962419373527480591711406",
               "maker_coin" : "RVN",
               "maker_coin_htlc_pubkey" : "02dbd8c73e2e80e4f3cf88d2f04a9d2d0df4269496608b14a3e17556fdcb01e0c1",
               "maker_coin_start_block" : 2712147,
               "maker_payment_confirmations" : 1,
               "maker_payment_lock" : 1678890705,
               "maker_payment_requires_nota" : false,
               "maker_payment_trade_fee" : {
                  "amount" : "0.01",
                  "coin" : "RVN",
                  "paid_from_trading_vol" : false
               },
               "my_persistent_pub" : "02dbd8c73e2e80e4f3cf88d2f04a9d2d0df4269496608b14a3e17556fdcb01e0c1",
               "p2p_privkey" : null,
               "secret" : "9f8460b5caae021bd6da39749c0098f0b69addb4cb14bf24bdc25a03257ab35c",
               "secret_hash" : "718faab9ecca929b56ef595acea13982b4b37301",
               "started_at" : 1678875105,
               "taker" : "3c5ba1d7ef6fa015eb33defb3aba2a961898a51bbb7ff30344d07ba75ad3f289",
               "taker_amount" : "0.039732206426673726",
               "taker_coin" : "PAXG-PLG20",
               "taker_coin_htlc_pubkey" : "02dbd8c73e2e80e4f3cf88d2f04a9d2d0df4269496608b14a3e17556fdcb01e0c1",
               "taker_coin_start_block" : 40369945,
               "taker_coin_swap_contract_address" : "9130b257d37a52e52f21054c4da3450c72f595ce",
               "taker_payment_confirmations" : 3,
               "taker_payment_requires_nota" : false,
               "taker_payment_spend_trade_fee" : {
                  "amount" : "0.0324349575",
                  "coin" : "MATIC",
                  "paid_from_trading_vol" : false
               },
               "uuid" : "9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0"
            },
            "type" : "Started"
         },
         "timestamp" : 1678875105837
      },
      {
         "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" : 1678882906,
               "taker_pubkey" : "000000000000000000000000000000000000000000000000000000000000000000"
            },
            "type" : "Negotiated"
         },
         "timestamp" : 1678875107843
      },
      {
         "event" : {
            "data" : null,
            "type" : "MakerPaymentInstructionsReceived"
         },
         "timestamp" : 1678875112241
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "3d84978a2d7a3f935b83007c6bccb7c459a334731c23d9f754616d4263cfd6df",
               "tx_hex" : "f8ae820652852d44a210408303345094553d3d295e0f695b9228246232edf400ed3560b580b844a9059cbb000000000000000000000000d8997941dd1346e9231118d5685d866294f59e5b00000000000000000000000000000000000000000000000000005af3107a4000820135a0e0b9aede57a149060951a721d0ff1980b97bbd2235cd37a058afc0790edc3a02a05a5d105dca323f03ddb7570fa9b98941241efb6e20b3b119d2f9f6bbb6eb2869"
            },
            "type" : "TakerFeeValidated"
         },
         "timestamp" : 1678875112245
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "2eb86d0a0862748c95836b6870df7408a31f26f5cf11bee6e6f6e7274bcf82d1",
               "tx_hex" : "01000000013a2abda761fc476f49fac60b459ee0d340f09c742837d92e01ec198bcf2ecaff020000006b4830450221009fd4d9d1319a6e38a669dfc1955159461ef0ed8526ed635ec9ea452bec95131b02202088f009cbc1032b9f01c268616976a673d9cb3e728c494b9bdc35b319a582bc012102dbd8c73e2e80e4f3cf88d2f04a9d2d0df4269496608b14a3e17556fdcb01e0c1ffffffff038f9dd58c3b00000017a9144e4bb2c0e38bd07e3fd033242e26cd7d96c2ec94870000000000000000166a14718faab9ecca929b56ef595acea13982b4b37301566b41514a0000001976a914124b0846223ef78130b8e544b9afc3b09988238688ace8991164"
            },
            "type" : "MakerPaymentSent"
         },
         "timestamp" : 1678875112331
      },
      {
         "event" : {
            "data" : {
               "tx_hash" : "6ebd35f3816c5db932d7600534e1b7123c9e76b4a76e8e2940b54bbcd13739aa",
               "tx_hex" : "f9012e82065385342855a1c0830249f0949130b257d37a52e52f21054c4da3450c72f595ce80b8c49b415b2a1193f03934574e71097f4cc86b874efb61d53864c043078e5b5ec26aa1fdc477000000000000000000000000000000000000000000000000008d283b3234523e000000000000000000000000553d3d295e0f695b9228246232edf400ed3560b5000000000000000000000000f2ed2ac92489106c942c9e32c6a912ba61af93e3718faab9ecca929b56ef595acea13982b4b37301000000000000000000000000000000000000000000000000000000000000000000000000000000006411b85a820136a05676a15685cc533685fb4b046d8f4e57b5cbfef95048db63eca1bc36048b367ea05214385a7e318b9416a8377c6f5a9b01ba6ebfc02a9fcd2db3ab0d8231719e71"
            },
            "type" : "TakerPaymentReceived"
         },
         "timestamp" : 1678875236634
      },
      {
         "event" : {
            "type" : "TakerPaymentWaitConfirmStarted"
         },
         "timestamp" : 1678875236658
      },
      {
         "event" : {
            "type" : "TakerPaymentValidatedAndConfirmed"
         },
         "timestamp" : 1678875252672
      },
      {
         "event" : {
            "data" : {
               "error" : "maker_swap:1076] !taker_coin.send_maker_spends_taker_payment: eth:3254] Payment SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: 1619, gas_price: 224015000000, gas: 150000, action: Call(0x9130b257d37a52e52f21054c4da3450c72f595ce), value: 0, data: [155, 65, 91, 42, 17, 147, 240, 57, 52, 87, 78, 113, 9, 127, 76, 200, 107, 135, 78, 251, 97, 213, 56, 100, 192, 67, 7, 142, 91, 94, 194, 106, 161, 253, 196, 119, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 141, 40, 59, 50, 52, 82, 62, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 85, 61, 61, 41, 94, 15, 105, 91, 146, 40, 36, 98, 50, 237, 244, 0, 237, 53, 96, 181, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 242, 237, 42, 201, 36, 137, 16, 108, 148, 44, 158, 50, 198, 169, 18, 186, 97, 175, 147, 227, 113, 143, 170, 185, 236, 202, 146, 155, 86, 239, 89, 90, 206, 161, 57, 130, 180, 179, 115, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 100, 17, 184, 90] }, v: 310, r: 39108506445612594649169380366610379104235903366644446785579341376435266467454, s: 37125379462603762323354074480169832345737339747347948921084503086853516271217, hash: 0x6ebd35f3816c5db932d7600534e1b7123c9e76b4a76e8e2940b54bbcd13739aa }, sender: 0x15c577f4b9fbe66735a9bff9b0b5d3ea2854bfaa, public: Some(0x3c5ba1d7ef6fa015eb33defb3aba2a961898a51bbb7ff30344d07ba75ad3f2890c7e83dfe4a34a21b636d8dc0074f619e962da35d4bc60d1fe88c956cafaa09e) } state is not PAYMENT_STATE_SENT, got 0"
            },
            "type" : "TakerPaymentSpendFailed"
         },
         "timestamp" : 1678875252931
      },
      {
         "event" : {
            "data" : {
               "wait_until" : 1678894405
            },
            "type" : "MakerPaymentWaitRefundStarted"
         },
         "timestamp" : 1678875252937
      },
      {
         "event" : {
            "type" : "MakerPaymentRefundStarted"
         },
         "timestamp" : 1678875252941
      }
   ],
   "gui" : "mpm",
   "maker_amount" : "2557.658802072388474759568962187632768143370283109960990305511567726236916302962419373527480591711406",
   "maker_coin" : "RVN",
   "maker_coin_usd_price" : null,
   "mm_version" : "1.0.0-beta_10542_bugfix-evm-tx-disappear_c2c9da2ef_Linux_CI",
   "my_order_uuid" : "92dde773-2831-4e06-b6f6-0b44d64301e7",
   "success_events" : [
      "Started",
      "Negotiated",
      "MakerPaymentInstructionsReceived",
      "TakerFeeValidated",
      "MakerPaymentSent",
      "TakerPaymentReceived",
      "TakerPaymentWaitConfirmStarted",
      "TakerPaymentValidatedAndConfirmed",
      "TakerPaymentSpent",
      "TakerPaymentSpendConfirmStarted",
      "TakerPaymentSpendConfirmed",
      "Finished"
   ],
   "taker_amount" : "0.039732206426673726",
   "taker_coin" : "PAXG-PLG20",
   "taker_coin_usd_price" : null,
   "type" : "Maker",
   "uuid" : "9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0"
}

it failed right away, without any retry or so... console on maker looked like this:

+--- 15 10:13:28 -------
| (1:42) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Maker payment sent...
15 10:13:37, coins:rpc_clients:175] INFO Waiting for tx 2eb86d0a0862748c95836b6870df7408a31f26f5cf11bee6e6f6e7274bcf82d1 confirmations, now 0, required 1, requires_notarization false
+--- 15 10:13:52 -------
| (2:06) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Maker payment sent...
15 10:13:56, maker_swap:951] INFO Taker payment tx 6ebd35f3816c5db932d7600534e1b7123c9e76b4a76e8e2940b54bbcd13739aa
+--- 15 10:13:59 -------
| (2:14) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Taker payment wait confirm started...
| (0:03/101:48) [PAXG-PLG20] Waiting for confirmations…
· 2023-03-15 10:14:12 +0000 [PAXG-PLG20] Waiting for confirmations… Confirmed.
+--- 15 10:14:12 -------
| (2:26) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Taker payment wait confirm started...
+--- 15 10:14:20 -------
| (2:34) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Maker payment refund started...

and takerpayment (PAXG-PLG20) was fine and mined: https://polygonscan.com/tx/0x6ebd35f3816c5db932d7600534e1b7123c9e76b4a76e8e2940b54bbcd13739aa

maybe a retry logic similar to PR 1716 would solve this issue too... though i have no idea what actually happens here

[cipig]

the consequences of the error from the swap in the last comment are this:

maker shows | (190:42) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Maker payment refund started...

taker has not yet failed swap and shows this in logs:

| (190:20) [swap uuid=9e9bdea7-e60c-41b8-a9d9-28208f7d0ba0] Taker payment sent...
15 13:22:07, coins:eth:1900] ERROR Error getting spend events: eth:3644] RPC error: Error { code: InvalidRequest, message: "block range is too wide", data: None }

screenshot of taker:

so the only way for taker to refund the swap is to restart, else it will continue forever

[shamardy]

had another such failed swap on maker side, even after #1716 on both maker and taker

maybe a retry logic similar to PR 1716 would solve this issue too... though i have no idea what actually happens here

Yeah, sure. I will work on that. I didn't fix this in #1716 to not do excessive/unnecessary calls until we can be sure that payment state issue was not solved by the PR. It seems that this is another race condition issue where payment state is sometimes updated in RPC node after the transaction is confirmed and returned from eth_getTransactionByHash.

[cipig]

i got this error again on a PLG20 swap
maker sent makerpayment: https://polygonscan.com/tx/0x22c897e53694ea33399a8b9abd420bdc5967bc5d1dceaca7ce377c5fc13d133a
but taker failed the swap with taker_swap:1391] !validate maker payment: eth:3676] Payment state is not PAYMENT_STATE_SENT, got 0 on MakerPaymentValidateFailed: https://dexapi.cipig.net/public/error.php?uuid=beb70383-b382-43f8-9f44-c10b2d9b6538
both are using latest mm2 from dev and 20 confirmations for PLG20
taker just had this in log:

· 2023-03-28 21:27:14 +0000 [] lp_ordermatch:3016] Entering the taker_swap_loop USDT-PLG20/CDN with uuid: beb70383-b382-43f8-9f44-c10b2d9b6538
· 2023-03-28 21:27:16 +0000 [] taker_swap:756] Taker swap beb70383-b382-43f8-9f44-c10b2d9b6538 has successfully started
+--- 28 21:27:16 -------
| (0:00) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Started...
+--- 28 21:27:25 -------
| (0:09) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Maker payment wait confirm started...
| (0:03/51:54) [USDT-PLG20] Waiting for confirmations…
+--- 28 21:27:49 -------
| (0:33) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Maker payment wait confirm started...
| (0:27/51:54) [USDT-PLG20] Waiting for confirmations…
+--- 28 21:28:13 -------
| (0:57) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Maker payment wait confirm started...
| (0:51/51:54) [USDT-PLG20] Waiting for confirmations…
+--- 28 21:28:37 -------
| (1:21) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Maker payment wait confirm started...
| (1:16/51:54) [USDT-PLG20] Waiting for confirmations…
+--- 28 21:29:01 -------
| (1:45) [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Maker payment wait confirm started...
| (1:40/51:54) [USDT-PLG20] Waiting for confirmations…
· 2023-03-28 21:29:08 +0000 [USDT-PLG20] Waiting for confirmations… Confirmed.
· 2023-03-28 21:29:08 +0000 [swap uuid=beb70383-b382-43f8-9f44-c10b2d9b6538] Finished

[shamardy]

maker sent makerpayment: https://polygonscan.com/tx/0x22c897e53694ea33399a8b9abd420bdc5967bc5d1dceaca7ce377c5fc13d133a

Were you the taker? if not, they might have used an outdated version that uses less confirmations.

both are using latest mm2 from dev and 20 confirmations for PLG20

Sorry, never mind. Just saw this.

[shamardy]

There seems to be a node with a high weight (11%) that is lagging by more than 20 blocks in this list https://polygon-rpc.com/, maybe this is the problem.

[shamardy]

There seems to be a node with a high weight (11%) that is lagging by more than 20 blocks in this list https://polygon-rpc.com/, maybe this is the problem.

It's this node, weight is getting reduced for it now.

[shamardy]

I am not sure if such thing should be solved from the API side, but I will look into it in more details this week. Maybe we can retry the payment status call a few times in payment validation stage, but this will not solve very edge cases where multiple nodes are lagging and they are the ones that return the response.

[cipig]

There seems to be a node with a high weight (11%) that is lagging by more than 20 blocks in this list https://polygon-rpc.com/, maybe this is the problem.

Yes, could well be. Looks like we need to run our own infrastructure for every chain that we really want to use. The public RPC nodes are unreliable and slow anyway. I see it on my order placing rounds... takes 10 minutes when BEP20 is involved (run by us) and 17 minutes when PLG20 is involved (public crap)... and there are 2 coins in a round, the other one is UTXO... so the public PLG20 are at least half the speed of our BEP20 nodes, likely even slower.

[shamardy]

@cipig can this issue be closed? are you getting anymore of these errors?

[cipig]

haven't seen this specific error since a longer time
collected this from the last 2 weeks:

https://dexapi.cipig.net/public/error.php?uuid=f691a5f1-e639-47c2-8ec5-cd7bdb224d17 can't find tx
https://dexapi.cipig.net/public/error.php?uuid=2d37cfa6-cc54-4dd5-9b38-9261c409a6e3 nonce too low
https://dexapi.cipig.net/public/error.php?uuid=f2e3ec54-2e52-49d2-9c7a-190d980d1de7 nonce too low
https://dexapi.cipig.net/public/error.php?uuid=cc8686ea-b152-4d27-ad8c-ef51d78636f1 nonce too low

the "can't find tx" is mentioned in some other issue... and the "nonce too low" happens when you do more then one swap with same EVM chain at the same time (sometimes... the more swaps, the higher the chance)
anyway, not part of this issue, so closing