Swaps failed without sending a transfer proof

[sethforprivacy]

Hi there,

I've been running on mainnet and so far have had two swaps fail completely.

Here are the relevant logs (AFAICT) on both:

Swap dbf32b87-2a14-4848-a1a5-9bddd3e752da:

 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=started rate=0.00569700 BTC
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=bitcoin lock transaction in mempool rate=0.00569700 BTC
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Waiting for Bitcoin transaction finality txid=redacted required_confirmation=2
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Waiting for Bitcoin transaction finality txid=redacted seen_confirmations=1 needed_confirmations=2
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Waiting for Bitcoin transaction finality txid=redacted seen_confirmations=2 needed_confirmations=2
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=btc is locked rate=0.00570300 BTC
DEBUG swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Successfully initiated Monero transfer amount=0.117310280264 XMR to=redacted tx_id=redacted
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=xmr lock transaction sent rate=0.00570300 BTC
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Waiting for Monero transaction finality txid=redacted target_confirmations=1
DEBUG swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Failed to retrieve tx from blockchain: JSON-RPC request failed with code -1: Failed to get transaction from daemon: JSON-RPC request failed with code -1: Failed to get transaction from daemon txid=redacted
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Received new confirmation for Monero lock tx txid=redacted seen_confirmations=1 needed_confirmations=1
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=xmr is locked rate=0.00570100 BTC
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=xmr lock transfer proof sent rate=0.00570100 BTC
 WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
	- CloseNotify alert received
 txid=redacted
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=xmr lock transfer proof sent rate=0.00568200 BTC
 WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
	- CloseNotify alert received
 txid=redacted
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=cancel timelock is expired rate=0.00567700 BTC
DEBUG swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Assuming cancel transaction is already broadcasted because: Failed to broadcast Bitcoin cancel transaction redacted: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-26,\"message\":\"non-BIP68-final\"}")))
 INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=btc is cancelled rate=0.00567700 BTC
DEBUG Found relevant Bitcoin transaction txid=redacted status=unseen
DEBUG Found relevant Bitcoin transaction txid=redacted status=unseen
 WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
	- CloseNotify alert received
 txid=redacted
 WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
	- CloseNotify alert received
 txid=redacted
ERROR swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: error=Failed to monitor refund transaction
ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=dbf32b87-2a14-4848-a1a5-9bddd3e752da
DEBUG A swap stopped without sending a transfer proof: request channel closed

Swap 2c5487d-e29d-4753-9a19-49a64e40cb20:

(For further context on this swap, see #648)

 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00564200 BTC
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Failed to monitor refund transaction
ERROR Swap failed: Failed to monitor refund transaction: Failed while waiting for next status update: channel closed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO Resuming swap swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is cancelled rate=0.00568200 BTC
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Advancing state state=btc is punishable rate=0.00567700 BTC
 WARN swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Failed to publish punish transaction: Failed to broadcast Bitcoin punish transaction redacted: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-25,\"message\":\"bad-txns-inputs-missingorspent\"}")))
 INFO swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: Falling back to refund
ERROR swap{id=f2c5487d-e29d-4753-9a19-49a64e40cb20}: error=Electrum(Protocol(String("missing transaction")))
ERROR Swap failed: Electrum(Protocol(String("missing transaction"))) swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20

My ASB was up and reachable AFAICT throughout both swaps, though I saw similar lines to the below for each swap:

 WARN Failed to get status of script: Failed to subscribe to header notifications: Made one or multiple attempts, all errored:
	- CloseNotify alert received
 txid=redacted

Let me know if there is any other data I can gather or provide around this.

Version: running the x86_64 artifact from https://github.com/comit-network/xmr-btc-swap/actions/runs/1141616002 to test the fix in #649.

[sethforprivacy]

Screenshots from the f2c5487d-e29d-4753-9a19-49a64e40cb20 swap partner:

[sethforprivacy]

Swap 2c5487d-e29d-4753-9a19-49a64e40cb20 was able to refund properly:

DEBUG Swap completed swap_id=f2c5487d-e29d-4753-9a19-49a64e40cb20 final_state=xmr is refunded

[sethforprivacy]

Swap dbf32b87-2a14-4848-a1a5-9bddd3e752da was able to refund properly as well:

2021-08-19 14:25:50  WARN swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Failed to publish punish transaction: Failed to broadcast Bitcoin punish transaction REDACTED: Electrum(Protocol(String("sendrawtransaction RPC error: {\"code\":-25,\"message\":\"bad-txns-inputs-missingorspent\"}")))
2021-08-19 14:25:50  INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Falling back to refund
2021-08-19 14:25:50  INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Advancing state state=btc is refunded rate=0.00570600 BTC
2021-08-19 14:25:50  INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Waiting for Monero transaction finality txid=REDACTED target_confirmations=10
2021-08-19 14:25:50  INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Received new confirmation for Monero lock tx txid=REDACTED seen_confirmations=589 needed_confirmations=10
2021-08-19 14:25:55 DEBUG Found relevant Bitcoin transaction txid=REDACTED status=unseen
2021-08-19 14:26:05  INFO swap{id=dbf32b87-2a14-4848-a1a5-9bddd3e752da}: Monero transferred back to default wallet tx=REDACTED monero_address=REDACTED
2021-08-19 14:26:06 DEBUG Swap completed swap_id=dbf32b87-2a14-4848-a1a5-9bddd3e752da final_state=xmr is refunded

Important note I just realized -- both only refunded (or were seen by the ASB as refunded) after restarting the ASB client.

[thomaseizinger]

Unsure what to do about this, we may want to configure the electron client to do more retries in case the connection gets closed.

[rishflab]

We added more retried to the electrum client in 0.8.2. Has the issue been resolved after upgrading. Would like to close this issue if so.

[sethforprivacy]

We added more retried to the electrum client in 0.8.2. Has the issue been resolved after upgrading. Would like to close this issue if so.

I unfortunately cannot test ATM, but retries should correct the issue as it was always resolved after an ASB restart (forcing a reconnection attempt to Electrum).