Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lwk: add backoff for send #326

Merged
merged 2 commits into from
Nov 5, 2024
Merged

lwk: add backoff for send #326

merged 2 commits into from
Nov 5, 2024

Conversation

YusukeShimizu
Copy link
Contributor

Handles retries in case of a "missing transaction" error.
It uses an exponential backoff strategy for retries, with a maximum of 5 retries.

fixes: #325

Send sends a request using the lwkclient and handles retries
 in case of a "missing transaction" error.
It uses an exponential backoff strategy for
retries, with a maximum of 5 retries. This is a temporary workaround
for an issue where a missing transaction
error occurs even when the UTXO exists.
If the issue persists, the backoff strategy may need adjustment.

- Implement retry logic in the `send` function of `lwkclient` using an
  exponential backoff strategy to handle "missing transaction" errors.

fixes: #325
@grubles
Copy link
Collaborator

grubles commented Nov 2, 2024

Ok I think I've triggered the backoff for this swap attempt:

$ ./builds/peerswap/out/pscli swapin --sat_amt 100000001 --channel_id 214039729557274624 --asset lbtc
2024/11/02 09:26:28 rpc error: code = Unknown desc = failed to fund transaction: permanent error: failed to call api request: POST http://localhost:32111 giving up after 1 attempt(s): context deadline exceeded

Though in other canceled attempts I will get this error:

2024/11/01 12:57:11 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_SwapInSender_OnSwapInRequested on 
2024/11/01 12:57:11 [INFO] [Swap:4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab] Start new swap-in: peer: 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344 chanId: 194668:21:0 initiator: 035ca2fe4793a5e789ce846062eb4834f573c060d9200ce77544a29b48a0aa5923 amount 100000001
2024/11/01 12:57:11 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_ActionSucceeded on State_SwapInSender_CreateSwap
2024/11/01 12:57:11 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_ActionSucceeded on State_SwapInSender_SendRequest
2024/11/01 12:57:12 [DEBUG] [Messenger] From: 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344 got msgtype: a459 for swap: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab
2024/11/01 12:57:12 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_SwapInSender_OnAgreementReceived on State_SwapInSender_AwaitAgreement
2024/11/01 12:57:13 [INFO] error getting fee: cannot estimate fee for 7 blocks.
2024/11/01 12:57:13 [DEBUG] using minimum fee rate of 0.1 sat/vbyte
2024/11/01 12:57:13 [INFO] [FSM] Action failure failed to get raw transaction: missing transaction
2024/11/01 12:57:13 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_ActionFailed on State_SwapInSender_BroadcastOpeningTx
2024/11/01 12:57:13 [DEBUG] [FSM] Canceling because of failed to get raw transaction: missing transaction
2024/11/01 12:57:13 [DEBUG] [FSM] event:id: 4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab, Event_ActionSucceeded on State_SendCancel
2024/11/01 12:57:13 [INFO] [Swap:4ee04c58b8a037004b487211584102504413dc6de06e933cf17511b2a7a12eab] Swap canceled. Reason: failed to get raw transaction: missing transaction

@YusukeShimizu
Copy link
Contributor Author

YusukeShimizu commented Nov 3, 2024

Thank you for your investigation.

The core issue lies in the failure to retrieve the result after broadcasting the transaction. In this situation, even though the transaction itself is valid on the network, the system cancels the swap, causing a problem where the balance decreases and cannot be recovered.

  • Misunderstanding: Initially, I assumed that a missing transaction error occurred during the fund transaction (LWK's send command).
  • Reality: The fund transaction itself is executed correctly. The issue arises after broadcasting the transaction, where it fails to retrieve the result. Due to this failure, while the swap is canceled, the transaction has already been processed, leading to a decrease in balance that cannot be reclaimed.

Solution

I will introduce backoff handling when retrieving transaction results. This can potentially mitigate errors caused by temporary failures or delays.

27077a8

Considerations

The case where a swap is canceled even though an opening tx was broadcast may not only occur with LWK/electrs but could also happen with other backends. However, the probability is low.

In the future, it may be necessary to implement a manual fund recovery command. For now, we will focus on stabilizing within the LWK environment and consider further actions if issues arise.

Additional Information

"failed to fund transaction: permanent error" occurs when there’s an error with LWK's send command but does not trigger backoff. Backoff only occurs when a "missing transaction" error is returned.

GetRawTransaction retrieves the raw transaction data
for a given transaction and handles retries in case of a
"missing transaction" error. It uses an exponential backoff strategy
for retries, with a maximum of 10 retries. This is a
temporary workaround for an issue where a missing transaction error
occurs even when the UTXO exists.
If the issue persists, the backoff strategy may need adjustment.

fixes: #325
@grubles
Copy link
Collaborator

grubles commented Nov 4, 2024

Looks like this swap hit the "missing transaction" error, retried, and was able to eventually succeed:

2024/11/04 17:31:08 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_SwapInSender_OnSwapInRequested on 
2024/11/04 17:31:08 [INFO] [Swap:07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2] Start new swap-in: peer: 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344 chanId: 194668:21:0 initiator: 035ca2fe4793a5e789ce846062eb4834f573c060d9200ce77544a29b48a0aa5923 amount 10000001
2024/11/04 17:31:08 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_ActionSucceeded on State_SwapInSender_CreateSwap
2024/11/04 17:31:08 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_ActionSucceeded on State_SwapInSender_SendRequest
2024/11/04 17:31:09 [DEBUG] [Messenger] From: 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344 got msgtype: a459 for swap: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2
2024/11/04 17:31:09 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_SwapInSender_OnAgreementReceived on State_SwapInSender_AwaitAgreement
2024/11/04 17:31:10 [INFO] error getting fee: cannot estimate fee for 7 blocks.
2024/11/04 17:31:10 [DEBUG] using minimum fee rate of 0.1 sat/vbyte
2024/11/04 17:31:12 [INFO] Error during operation: missing transaction
2024/11/04 17:31:12 [INFO] Retrying due to missing transaction error: missing transaction
2024/11/04 17:31:13 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_ActionSucceeded on State_SwapInSender_BroadcastOpeningTx
2024/11/04 17:31:13 [DEBUG] [RedundantSender] start sending messages of type 42077 to 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344
2024/11/04 17:31:13 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_ActionSucceeded on State_SwapInSender_SendTxBroadcastedMessage
2024/11/04 17:31:13 [DEBUG] [PaymentWatcher] Swap: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2: Add new payment watcher for payreq lntbs100000010n1pnjjpxapp54xur2ysyyvlgve72klgh6d4cal7epecmv50gz87hc6ms9murk7zqdy6wpjk2unnwashqgrvvf6xxgrrd3skjmfqxyungd3k8puryvtcxqsrqdmxvg6rse3nx56nzephxsukyvnpxpjnjv3cxvcxzdesvsexywrrxg6xzd3jxfjrsvnzvg6kzwr98yunxwtpx93xywf5vyckgvtxxgcqpaxqrrsssp5ycsgyq7j4x09nl2kkrgl92f3z268qxmlh0tjua9dk9s6nk9nm92q9p4gqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqpqysgqyvxhkex9feg52y6v0xpds4mlflustxjmgaqz6ztna72da7f2tje45f4zvcans904a4dhzmf4m3japuwjmlwjwm0avc694h38rjzpdhsqu5lc5c of type "claim"
2024/11/04 17:32:03 [DEBUG] New block received. block height:1642537
2024/11/04 17:33:06 [DEBUG] New block received. block height:1642538
2024/11/04 17:33:13 [DEBUG] [PaymentWatcher] Swap: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2: Calling paymentCallback
2024/11/04 17:33:13 [DEBUG] [FSM] event:id: 07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2, Event_OnClaimInvoicePaid on State_SwapInSender_AwaitClaimPayment
2024/11/04 17:33:13 [INFO] [Swap:07fb48f3551d749b2a0e92830a70d2b8c24a622d82bb5a8e9939a1bb94a1d1f2] Swap claimed with preimage b6c9d90ed753f7353e10a112c53856ba686ff6074c989ecfe6dd7cb065f464e7
2024/11/04 17:33:13 [DEBUG] [RedundantSender] stop sending messages of type 42077 to 036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344

A different swap was canceled because the LWK backend was unreachable:

2024/11/04 19:42:29 [INFO] Error during operation: missing transaction
2024/11/04 19:42:29 [INFO] Retrying due to missing transaction error: missing transaction
2024/11/04 19:42:30 [INFO] Error during operation: missing transaction
2024/11/04 19:42:30 [INFO] Retrying due to missing transaction error: missing transaction
2024/11/04 19:42:32 [INFO] Error during operation: missing transaction
2024/11/04 19:42:32 [INFO] Retrying due to missing transaction error: missing transaction
2024/11/04 19:42:33 [INFO] failed to ping electrum server: request timeout
2024/11/04 19:42:33 [INFO] reconnecting to electrum server
2024/11/04 19:42:33 [INFO] Error during operation: dial tcp: lookup blockstream.info: i/o timeout
2024/11/04 19:42:33 [INFO] [FSM] Action failure failed to get raw transaction: permanent error: dial tcp: lookup blockstream.info: i/o timeout
2024/11/04 19:42:33 [DEBUG] [FSM] event:id: 3346e599606681a6465a6f397c012aaa29aa917aa54dbf386d13251eab9148d0, Event_ActionFailed on State_SwapInSender_BroadcastOpeningTx
2024/11/04 19:42:33 [DEBUG] [FSM] Canceling because of failed to get raw transaction: permanent error: dial tcp: lookup blockstream.info: i/o timeout
2024/11/04 19:42:33 [DEBUG] [FSM] event:id: 3346e599606681a6465a6f397c012aaa29aa917aa54dbf386d13251eab9148d0, Event_ActionSucceeded on State_SendCancel
2024/11/04 19:42:33 [INFO] [Swap:3346e599606681a6465a6f397c012aaa29aa917aa54dbf386d13251eab9148d0] Swap canceled. Reason: failed to get raw transaction: permanent error: dial tcp: lookup blockstream.info: i/o timeout

Tested ACK 27077a8

@grubles grubles merged commit df76452 into master Nov 5, 2024
8 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Swaps canceled due to "missing transaction" when using LWK backend
2 participants