search

ElementsProject / peerswap

MIT License
110 stars 40 forks source link

make lwk available #288

Closed YusukeShimizu closed 4 months ago

YusukeShimizu commented 8 months ago

lbtc swap with lwk

Description

Previously, lbtc swap required running elementsd, but now it can be done with lwk. Because elementsd requires a lot of resources, making it available in lwk will allow more users to perform swaps.

setup

see docs/setup_lwk.md.

Specification

lwk and esplora-electrs connection is required. New json rpc api client is implemented for connection to lwk.

Connection to esplora-electrs using go-electrum. esplora-electrs is also used by lwk as a blockchain.

Configuration

The user can choose to use lwk instead of elements for lbtc swap. It has the following configuration items.

type LWKConf struct {
    SignerName       string
    WalletName       string
    LWKEndpoint      string
    ElementsEndpoint string
    Network          string
    LiquidSwaps      *bool
}

The user can choose to set up a wallet that holds the signer. Default uses the same default endpoint (blockstream.info:995) as lwk, but the user can choose his own electrum for ElementsEndpoint.

wallet

Peerswap's onchain wallet provide the following features.

type Wallet interface {
    GetAddress() (string, error)
    SendToAddress(string, uint64) (string, error)
    GetBalance() (uint64, error)
    CreateAndBroadcastTransaction(swapParams *swap.OpeningParams, asset []byte) (txid, rawTx string, fee uint64, err error)
    SendRawTx(rawTx string) (txid string, err error)
    GetFee(txSize int64) (uint64, error)
}

GetAddress() (string, error)

This method is used to get the address of the wallet. Use lwk address.

SendToAddress(string, uint64) (string, error)

This method is used to send money to a specific address. lwk send to create a psbt, sign to sign it, and broadcast to broadcast it.

CreateAndBroadcastTransaction(swapParams *swap.OpeningParams, asset []byte) (txid, rawTx string, fee uint64, err error)

This method is used to create and broadcast opening tx. The interface has been split into the following two interfaces, but they will be merged into a single interface for lwk support. Existing bitcoin wallets will also be changed, but functionality will remain the same.

CreateFundedTransaction(preparedTx *transaction.Transaction) (rawTx string, fee uint64, err error)
FinalizeFundedTransaction(unpreparedTx string) (preparedTxHex string, err error)

SendRawTx(rawTx string) (txid string, err error)

This method is used to broadcast the closing tx. This is done using electrum cient's blockchain.transaction.broadcast method.

GetFee(txSize int64) (uint64, error)

This method is used to get the fee blockchain.estimatefee.

tx watcher

tx watcher is a function that monitors onchain status and notifies opening tx and closing tx.
The following interface must be implemented.

type TxWatcher interface {
    AddWaitForConfirmationTx(swapId, txId string, vout, startingHeight uint32, scriptpubkey []byte)
    AddWaitForCsvTx(swapId, txId string, vout uint32, startingHeight uint32, scriptpubkey []byte)
    AddConfirmationCallback(func(swapId string, txHex string, err error) error)
    AddCsvCallback(func(swapId string) error)
    GetBlockHeight() (uint32, error)
    StartWatchingTxs() error
}

So far, peerswap has used bitcoind/elementsd, but lwk uses the electrum client on which lwk depends.

AddWaitForConfirmationTx(swapId, txId string, vout, startingHeight uint32, scriptpubkey []byte)

Wait for a specific tx to be confirmed with a specific block height. This function uses the electrum client blockchain.scriptthash.get_history.

AddWaitForCsvTx(swapId, txId string, vout uint32, startingHeight uint32, scriptpubkey []byte)

Wait for a specific tx to reach the csv limit at a specific block height. This function uses the electrum client blockchain.scriptthash.get_history.

GetBlockHeight() (uint32, error)

Function to retrieve block height. Use blockchain.headers.subscribe of electrum client.

StartWatchingTxs() error

Function to start tx watcher. Periodically calls blockchain.scripthash.get_history of electrum client and executes callback when the condition is met.

grubles commented 6 months ago

CLN as swap-out sender seems to be unable to get the starting block height from LWK?

Using CLN 24.02.2 and LWK 0.3.0

2eb4834f573c060d9200ce77544a29b48a0aa5923 got msgtype: a45d for swap: efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc
2024-05-08T19:09:05.555Z DEBUG   plugin-peerswap: [FSM] event:id: efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc, Event_OnTxOpenedMessage on State_SwapOutSender_AwaitTxBroadcastedMessage
2024-05-08T19:09:05.584Z INFO    plugin-peerswap: [FSM] Action failure could not get starting block height of the swap.
2024-05-08T19:09:05.585Z DEBUG   plugin-peerswap: [FSM] event:id: efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc, Event_ActionFailed on State_SwapOutSender_AwaitTxConfirmation
2024-05-08T19:09:05.591Z DEBUG   plugin-peerswap: [FSM] event:id: efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc, Event_ActionSucceeded on State_SwapOutSender_SendPrivkey
2024-05-08T19:09:05.592Z DEBUG   035ca2fe4793a5e789ce846062eb4834f573c060d9200ce77544a29b48a0aa5923-connectd: peer_out INVALID 42081
2024-05-08T19:09:05.599Z DEBUG   plugin-peerswap: [FSM] event:id: efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc, Event_ActionSucceeded on State_SwapOutSender_SendCoopClose
2024-05-08T19:09:05.600Z INFO    plugin-peerswap: [Swap:efa2c9c38ea24acff600af12d61677f50679b0e2d137fcd037c760411eaa4cfc] Swap claimed cooperatively
YusukeShimizu commented 6 months ago

CLN as swap-out sender seems to be unable to get the starting block height from LWK?

The block height may not be set immediately after start-up because lwk subscribe and hold block updates. I have added a process that waits until the block height is retrieved on start-up, so could you please verify this again?

https://github.com/ElementsProject/peerswap/pull/288/commits/103c4f55cf31d76e97af014b4c5c3ca3a83cc032

grubles commented 6 months ago

Running the latest commits, peerswap appears to be running fine but when trying listswaps, it returns as if it's still starting up:

$ lightning-cli --signet peerswap-listswaps
{
   "code": -1,
   "message": "peerswap is still in the process of starting up"
}

2024-05-10T15:33:22.232Z INFO    plugin-peerswap: Cln synced, continue...
2024-05-10T15:33:22.260Z INFO    plugin-peerswap: Liquid swaps enabled
2024-05-10T15:33:22.261Z INFO    plugin-peerswap: Starting bitcoin client with chain:signet, rpcuser:__cookie__, rpcpassword:******,, rpchost:http://127.0.0.1, rpcport:38332
2024-05-10T15:33:22.263Z INFO    plugin-peerswap: Bitcoin swaps enabled
YusukeShimizu commented 6 months ago

When all setups have been completed, there should be a log saying peerswap initialized, but it doesn't appear to be there. Can you share the config file with me?

grubles commented 6 months ago

Yeah sure. It seemed to work before on the older commit. 

[LWK]
signername="testsigner1"
walletname="testwallet1"
lwkendpoint="http://localhost:32111"
network="liquid-testnet"
liquidswaps=true
YusukeShimizu commented 6 months ago

Defalut electrs backend needs to perform a tls connection. I confirm that peerswap is initialised and peerswap-listswaps can be done by the commit. https://github.com/ElementsProject/peerswap/pull/288/commits/1bfe02c63c32fdca4f487a72916521eab2c1e40e

Can you please confirm this?

grubles commented 6 months ago

Okay the latest commits fixed it.

grubles commented 5 months ago

CLN PeerSwap still allows me to start a swap-out with the LWK backend shut down. To reproduce, shut down the running LWK server while CLN is running before attempting a swap-out. Then try the swap-out.

The swap will eventually become stuck at this point:

      {
         "id": "20a0dc7de9571334652f9ac551b126bf08099865a76abbc7f732d67cbfecdd8e",
         "created_at": 1718204649,
         "asset": "lbtc",
         "type": "swap-out",
         "role": "sender",
         "state": "State_SwapOutSender_ClaimSwap",
         "initiator_node_id": "036e680823a129ac9a2eeb8c43514a5b6cb09ae28e3e698a0e34aaa8865d6cc344",
         "peer_node_id": "035ca2fe4793a5e789ce846062eb4834f573c060d9200ce77544a29b48a0aa5923",
         "amount": 9008040,
         "channel_id": "194668x21x0",
         "opening_tx_id": "3212fa7d8ce763161a7c701e5af84112607b13690e6879ea08c0f9505c71f9a2",
         "lnd_chan_id": 214039729557274624
      }

Even when LWK is restarted, CLN PeerSwap isn't able to recover after about 30 seconds have passed:

Here peerswap stops retrying the LWK backend after ~30 seconds:

2024-06-12T17:28:56.515Z INFO    plugin-peerswap: Error claiming tx with preimage failed to call api request: POST http://localhost:32111 giving up after 2 attempt(s): Post \"http://localhost:32111\": dial tcp [::1]:32111: connect: connection refused

Here the LWK backend is restarted but peerswap does nothing:

2024-06-12T17:29:02.306Z DEBUG   plugin-peerswap: New block received. block height:1433751
2024-06-12T17:30:02.804Z DEBUG   plugin-peerswap: New block received. block height:1433752
2024-06-12T17:31:02.663Z DEBUG   plugin-peerswap: New block received. block height:1433753
YusukeShimizu commented 5 months ago

I have confirmed that the following in my environment: https://github.com/ElementsProject/peerswap/pull/288/commits/aa9550b8740d5dab29a638dc43af028052092b9e

bin/clncli peerswap-swap-out $CLNSHORTCHANID 1000000 lbtc
{
   "message": "liquid_unavailable",
   "code": -1
}

The log details are as follows:

peerswap-playground-cln1-1       | 2024-06-12T23:30:14.737Z DEBUG   lightningd: Calling rpc_command hook of plugin peerswap
peerswap-playground-cln1-1       | 2024-06-12T23:30:14.742Z INFO    plugin-peerswap: trying to send command peerswap-swap-out, but failed to connect: Post \"http://elementsd:8332/wallet/peerswap\": dial tcp: lookup elementsd on 127.0.0.11:53: no such host
peerswap-playground-cln1-1       | 2024-06-12T23:30:14.742Z DEBUG   lightningd: Plugin peerswap returned from rpc_command hook call

Even when LWK is restarted, CLN PeerSwap isn’t able to recover after about 30 seconds have passed:

Recovery of swaps occurs only when the plugin is restarted.
This may also be useful for other backend recovery scenarios, but identifying the impact and formulating an adequate strategy will require further consideration.

For reconnection to electrs, I have set a prime number interval (37 seconds). https://github.com/ElementsProject/peerswap/pull/288/commits/1d98fe2d2f63d7c8c3c095fb72ffd33797d9944a

grubles commented 5 months ago

{ "message": "liquid_unavailable", "code": -1 }

Peerswap now doesn't try a swap-out if LWK server is shutdown, but I'm not seeing that specific error message:

$ lightning-cli --signet peerswap-swap-out 194668x21x0 9008040 lbtc
lightning-cli: Reading enable response: No such file or directory

Strangely, when I go to shutdown CLN v24.05, the recover plugin crashes now?:

2024-06-13T16:46:28.894Z INFO    plugin-peerswap: trying to send command listpeerchannels, but failed to connect: lwk connection failed: failed to call api request: POST http://localhost:32111 giving up after 2 attempt(s): Post \"http://localhost:32111\": dial tcp [::1]:32111: connect: connection refused
2024-06-13T16:46:29.800Z INFO    plugin-recover: Killing plugin: exited during normal operation
2024-06-13T16:46:29.802Z **BROKEN** plugin-recover: Plugin marked as important, shutting down lightningd!
$ lightning-cli --signet stop
lightning-cli: Reading enable response: No such file or directory
[user@fedora peerswap]$ recover: FATAL SIGNAL 11 (version v24.05)
0x428f0f send_backtrace
        common/daemon.c:33
0x428fa3 crashdump
        common/daemon.c:75
0xffffa6cc47ef ???
        ???:0
0x4142e4 jsonrpc_stream_start
        plugins/libplugin.c:382
0x4144f3 command_done_raw
        plugins/libplugin.c:530
0x415e6f forward_error
        plugins/libplugin.c:584
0x418dfb handle_rpc_reply
        plugins/libplugin.c:982
0x41905f rpc_read_response_one
        plugins/libplugin.c:1183
0x4190ff rpc_conn_read_response
        plugins/libplugin.c:1207
0x4bc51f next_plan
        ccan/ccan/io/io.c:60
0x4bcaeb do_plan
        ccan/ccan/io/io.c:408
0x4bcbab io_ready
        ccan/ccan/io/io.c:418
0x4bea7b io_loop
        ccan/ccan/io/poll.c:455
0x4194b7 plugin_main
        plugins/libplugin.c:2209
0x414147 main
        plugins/recover.c:291
0xffffa67e09db ???
        ???:0
0xffffa67e0aaf ???
        ???:0
0x4107ef ???
        ???:0
0xffffffffffffffff ???
        ???:0
YusukeShimizu commented 5 months ago

This is not expected behavior. I will investigate.

YusukeShimizu commented 5 months ago

Could not reproduce. But, in my environment, I have confirmed that sometimes the following is displayed

lightning-cli: Reading enable response: Bad address

It seems to be a bug related to the glightning plugin hook, but the cause has not been identified. The hook mechanism is unstable, so changed to check at the start of swap out

YusukeShimizu commented 5 months ago

Summarise the problems that have occurred when the backend is down and the measures taken to deal with them. For verification, I use https://github.com/YusukeShimizu/peerswap-playground/tree/master/lnd_lwk.

hung in State_SwapOutSender_ClaimSwap.

Transition from State_SwapOutSender_ClaimSwap is not possible if lwk is stopped
This is because the CreatePreimageSpendingTransaction fails, Event_OnRetry is set and retries are repeated.

The Event_OnRetry is designed to execute 20 retries and stop the process if it still fails.
In the meantime, if the lwk is not restarted, the process will be stopped.

To rescue the hang, peerswap itself needs to be restarted with lwk restarted and the RECOVER process carried out.

solution

Allow retries with backoff during Event_OnRetry and perform a coop close if it eventually fails.

procedure

./bin/pscli peerswap1 swapout --channel_id $CHANID --sat_amt 1000000 --asset lbtc
{
  "swap":  {
    "id":  "4ef286a1b67b11b6256fc4f33a6f0b2a0dab80bbf97383f7b28eabf425a655af",
    "created_at":  "1719187011",
    "asset":  "lbtc",
    "type":  "swap-out",
    "role":  "sender",
    "state":  "State_SwapOutSender_AwaitTxConfirmation",
    "initiator_node_id":  "03a2398d621172e94b296853b67d51974dba7d3eb25f49408dd76fac03055fa2c6",
    "peer_node_id":  "0372a196c83b1ec8406cf14e9165fabe418f49d25f511366b15bc01bce3659dd08",
    "amount":  "1000000",
    "channel_id":  "116:1:1",
    "opening_tx_id":  "dca5b4f8cf4aaf989f15508557db7d2274d83273a854695e3f77ff4b7ca613b2",
    "claim_tx_id":  "",
    "cancel_message":  "",
    "lnd_chan_id":  "127543348887553"
  }
}

In this state, lwk down and generate the block.

./bin/elements-cli -rpcwallet=peerswap1 -generate 3
{
  "address": "el1qqgur95kqj5h8r25dc9rs7vj63xzdzxjr3fz25ph290s7m0equygstuh6ukh590ev2ggfw7r0ywpkqq29vx7djuzksgjy8x0wp",
  "blocks": [
    "3d6a07837fe3e35fc5d35bf46baea8d9275e2b94f1d11462d19cfefb7ac0dd95",
    "8edd881f0ff22a4efc2b339e372f070932e49589d44c5b214fc300f38431c5e6",
    "2212796f8e922d25541556e4720a7575a5266a6efc1935052a47ecc552e5e0b4"
  ]
}

The state transitions as follows
State_SwapOutSender_AwaitTxConfirmation->State_SwapOutSender_ValidateTxAndPayClaimInvoice->State_SwapOutSender_ClaimSwap

./bin/pscli peerswap1 listswaps
{
  "swaps":  [
    {
      "id":  "4ef286a1b67b11b6256fc4f33a6f0b2a0dab80bbf97383f7b28eabf425a655af",
      "created_at":  "1719187011",
      "asset":  "lbtc",
      "type":  "swap-out",
      "role":  "sender",
      "state":  "State_SwapOutSender_ClaimSwap",
      "initiator_node_id":  "03a2398d621172e94b296853b67d51974dba7d3eb25f49408dd76fac03055fa2c6",
      "peer_node_id":  "0372a196c83b1ec8406cf14e9165fabe418f49d25f511366b15bc01bce3659dd08",
      "amount":  "1000000",
      "channel_id":  "116:1:1",
      "opening_tx_id":  "dca5b4f8cf4aaf989f15508557db7d2274d83273a854695e3f77ff4b7ca613b2",
      "claim_tx_id":  "",
      "cancel_message":  "",
      "lnd_chan_id":  "127543348887553"
    }
  ]
}

In this state, restarting the lwk causes a transition from State_SwapOutSender_ClaimSwap to State_ClaimedPreimage. 

./bin/pscli peerswap1 listswaps
{
  "swaps":  [
    {
      "id":  "4ef286a1b67b11b6256fc4f33a6f0b2a0dab80bbf97383f7b28eabf425a655af",
      "created_at":  "1719187011",
      "asset":  "lbtc",
      "type":  "swap-out",
      "role":  "sender",
      "state":  "State_ClaimedPreimage",
      "initiator_node_id":  "03a2398d621172e94b296853b67d51974dba7d3eb25f49408dd76fac03055fa2c6",
      "peer_node_id":  "0372a196c83b1ec8406cf14e9165fabe418f49d25f511366b15bc01bce3659dd08",
      "amount":  "1000000",
      "channel_id":  "116:1:1",
      "opening_tx_id":  "dca5b4f8cf4aaf989f15508557db7d2274d83273a854695e3f77ff4b7ca613b2",
      "claim_tx_id":  "06e677aa5eab366e4321b98c8589003fcf9f68b658f6089c12e0131e9e89335a",
      "cancel_message":  "",
      "lnd_chan_id":  "127543348887553"
    }
  ]
}

hung in State_SwapOutSender_AwaitTxConfirmation

Transition from State_SwapOutSender_AwaitTxConfirmation is not possible in a situation where block subscribe is not possible.

When the block's subscribe is resumed, if the safety limit is exceeded, the private key is sent and a transition is made to State_ClaimedCoop, but the same transition is made if the csv limit is exceeded.
If the responder performs csv close, it also becomes State_ClaimedCoop, but in the case of csv close, it should become State_ClaimedCSV and there is no mechanism to detect this state.

solution

It may be possible to get onchain information to determine if the csv is displayed correctly, but this needs to be considered.
Alternatively, if the csv limit is exceeded, it may be possible to exit as State_ClaimedCSV

procedure

./bin/pscli peerswap1 swapout --channel_id $CHANID --sat_amt 1000000 --asset lbtc
{
  "swap":  {
    "id":  "b28c312d3deeedaa576820ef0f81a1e0b31b7e22dc48fc88247b5dee470621b1",
    "created_at":  "1719189360",
    "asset":  "lbtc",
    "type":  "swap-out",
    "role":  "sender",
    "state":  "State_SwapOutSender_AwaitTxConfirmation",
    "initiator_node_id":  "03d627f50febcb572d0c7c20bc1a3d74bbb0fb38bf2923e36693f92cf1530b5b17",
    "peer_node_id":  "02946f5695612919b1ef1a86a767699800e09389a2447c023f9eb0e0613b0cf1c3",
    "amount":  "1000000",
    "channel_id":  "116:1:1",
    "opening_tx_id":  "3c4095ebaea17b2ee9972094a1897841adf275cbad47fcb93ce2dc85c095dceb",
    "claim_tx_id":  "",
    "cancel_message":  "",
    "lnd_chan_id":  "127543348887553"
  }
}

In this state, lwk and electrs are turned down and the block is generated.
Generate as much as the safetyLimit is exceeded.

./bin/elements-cli -rpcwallet=peerswap1 -generate 100

Restart peerswap,lwk,electrs. Transition to State_SwapOutSender_AwaitTxConfirmation -> State_SwapOutSender_SendPrivkey -> State_ClaimedCoop.

./bin/pscli peerswap1 listswaps
{
  "swaps":  [
    {
      "id":  "b28c312d3deeedaa576820ef0f81a1e0b31b7e22dc48fc88247b5dee470621b1",
      "created_at":  "1719189360",
      "asset":  "lbtc",
      "type":  "swap-out",
      "role":  "sender",
      "state":  "State_ClaimedCoop",
      "initiator_node_id":  "03d627f50febcb572d0c7c20bc1a3d74bbb0fb38bf2923e36693f92cf1530b5b17",
      "peer_node_id":  "02946f5695612919b1ef1a86a767699800e09389a2447c023f9eb0e0613b0cf1c3",
      "amount":  "1000000",
      "channel_id":  "116:1:1",
      "opening_tx_id":  "3c4095ebaea17b2ee9972094a1897841adf275cbad47fcb93ce2dc85c095dceb",
      "claim_tx_id":  "",
      "cancel_message":  "exceeded safe swap range.",
      "lnd_chan_id":  "127543348887553"
    }
  ]
}

Remarks

To State_SwapOutSender_AwaitTxConfirmation, even if swapout is enforced with lwk down, the latest commit cannot transition because validation has been added. 

/clncli peerswap-swap-out $CLNSHORTCHANID 1000000 lbtc
pscli peerswap1 swapout --channel_id $CHANID --sat_amt 1000000 --asset lbtc
2024/06/16 02:02:06 rpc error: code = Unknown desc = liquid backend not reachable: lwk connection failed: failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host
YusukeShimizu commented 5 months ago

After the start of swapout;
if lwk is assumed to be stopped After about 10 minutes of back-off, the priv key is sent and the coop closed.

log ```sh 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnSwapOutStarted on 2024-06-26 09:22:00 2024/06/26 00:22:00 [INFO] [Swap:87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef] Start new swap-out: peer: 03457dabca72cdf096e7f27cd78673796306c21fc684d25f0ae714a87009ca9750 chanId: 116:1:1 initiator: 03b70410f1fc0b37fea10a92df8179b66362f8ac9cbb3058e8b69d897a5311caf0 amount 1000000 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_CreateSwap 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_SendRequest 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] [Messenger] From: 03457dabca72cdf096e7f27cd78673796306c21fc684d25f0ae714a87009ca9750 got msgtype: a45b for swap: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnFeeInvoiceReceived on State_SwapOutSender_AwaitAgreement 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] Using minimum fee rate of 0.1 sat/kw 2024-06-26 09:22:00 2024/06/26 00:22:00 [DEBUG] PayInvoiceViaChannel: payment still in flight 2024-06-26 09:22:01 2024/06/26 00:22:01 [DEBUG] PayInvoiceViaChannel: payment still in flight 2024-06-26 09:22:02 2024/06/26 00:22:02 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_PayFeeInvoice 2024-06-26 09:22:02 2024/06/26 00:22:02 [INFO] [Swap:87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef] Paid Feeinvoice of 300 sats 2024-06-26 09:22:02 2024/06/26 00:22:02 [DEBUG] [Messenger] From: 03457dabca72cdf096e7f27cd78673796306c21fc684d25f0ae714a87009ca9750 got msgtype: a45d for swap: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef 2024-06-26 09:22:02 2024/06/26 00:22:02 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnTxOpenedMessage on State_SwapOutSender_AwaitTxBroadcastedMessage 2024-06-26 09:22:02 2024/06/26 00:22:02 [DEBUG] Await confirmation for tx with id: bc68c580af45fad42f77d5451d96d64449a698dafce07c309e5fafc6fc2eb97b on swap 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef 2024-06-26 09:22:10 2024/06/26 00:22:10 [DEBUG] [Messenger] From: 03457dabca72cdf096e7f27cd78673796306c21fc684d25f0ae714a87009ca9750 got same message for swap: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef 2024-06-26 09:22:10 2024/06/26 00:22:10 [INFO] [MsgListener]: Handler failed: Message already exists 2024-06-26 09:22:15 2024/06/26 00:22:15 [DEBUG] New block received. block height:18 2024-06-26 09:22:15 2024/06/26 00:22:15 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnTxConfirmed on State_SwapOutSender_AwaitTxConfirmation 2024-06-26 09:22:20 2024/06/26 00:22:20 [DEBUG] [Messenger] From: 03457dabca72cdf096e7f27cd78673796306c21fc684d25f0ae714a87009ca9750 got same message for swap: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef 2024-06-26 09:22:25 2024/06/26 00:22:25 [DEBUG] PayInvoiceViaChannel: payment still in flight 2024-06-26 09:22:26 2024/06/26 00:22:26 [DEBUG] PayInvoiceViaChannel: payment still in flight 2024-06-26 09:22:27 2024/06/26 00:22:27 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_ValidateTxAndPayClaimInvoice 2024-06-26 09:22:29 2024/06/26 00:22:29 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:22:30 2024/06/26 00:22:30 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:22:31 2024/06/26 00:22:31 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:22:32 2024/06/26 00:22:32 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:22:33 2024/06/26 00:22:33 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:22:36 2024/06/26 00:22:36 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:22:38 2024/06/26 00:22:38 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:22:48 2024/06/26 00:22:48 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:22:49 2024/06/26 00:22:49 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:08 2024/06/26 00:23:08 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:10 2024/06/26 00:23:10 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:11 2024/06/26 00:23:11 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:13 2024/06/26 00:23:13 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:24 2024/06/26 00:23:24 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:26 2024/06/26 00:23:26 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:27 2024/06/26 00:23:27 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:29 2024/06/26 00:23:29 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:35 2024/06/26 00:23:35 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:37 2024/06/26 00:23:37 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:23:55 2024/06/26 00:23:55 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:23:57 2024/06/26 00:23:57 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:24:06 2024/06/26 00:24:06 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:24:07 2024/06/26 00:24:07 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:24:18 2024/06/26 00:24:18 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:24:19 2024/06/26 00:24:19 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:24:27 2024/06/26 00:24:27 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:24:29 2024/06/26 00:24:29 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:24:46 2024/06/26 00:24:46 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:24:47 2024/06/26 00:24:47 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:24:48 2024/06/26 00:24:48 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:24:49 2024/06/26 00:24:49 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:25:05 2024/06/26 00:25:05 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:25:07 2024/06/26 00:25:07 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:25:18 2024/06/26 00:25:18 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:25:19 2024/06/26 00:25:19 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:25:29 2024/06/26 00:25:29 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:25:31 2024/06/26 00:25:31 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:25:47 2024/06/26 00:25:47 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:25:48 2024/06/26 00:25:48 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:25:51 2024/06/26 00:25:51 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnRetry on State_SwapOutSender_ClaimSwap 2024-06-26 09:25:54 2024/06/26 00:25:54 [INFO] Error claiming tx with preimage failed to call api request: POST http://lwk:32113 giving up after 2 attempt(s): Post "http://lwk:32113": dial tcp: lookup lwk: no such host 2024-06-26 09:26:09 2024/06/26 00:26:09 [INFO] [MsgListener]: Handler failed: Message already exists 2024-06-26 09:32:00 2024/06/26 00:32:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_OnTimeout on State_SwapOutSender_ClaimSwap 2024-06-26 09:32:00 2024/06/26 00:32:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_SendPrivkey 2024-06-26 09:32:00 2024/06/26 00:32:00 [DEBUG] [FSM] event:id: 87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef, Event_ActionSucceeded on State_SwapOutSender_SendCoopClose 2024-06-26 09:32:00 2024/06/26 00:32:00 [INFO] [Swap:87a67002b3ef6f5a3de545b80df36ea5b5db61d0e1ec1e99e8e12919a368c4ef] Swap claimed cooperatively ```

Also, confirm that the number of groutine occurrences is normal in the debug run.
This no longer results in blocksubscriber outages.

grubles commented 5 months ago

Tested both CLN and LND as swap-out sender. Can confirm the swap now ends up as claimed coop after ~10 minutes with LWK down, instead of getting stuck.

YusukeShimizu commented 4 months ago

Thank you for your review. Can you please confirm that I have made the following corrections?

nepet commented 4 months ago

Looks good to me! Ack 66fead062425ff3b408b9b489307997eb0a2b0ba

grubles commented 4 months ago

Tested ACK 66fead0