ETH swap client connectivity stops the recovery of BTC funds

[LePremierHomme]

Background

In a scenario where, during a swap, the maker xud node crashes while the taker is delaying his settlement, the recovery procedure is being cancelled once one of the swap clients isn't available, even if it's not related to the funds to be recovered.

For example, when maker has an incoming payment in BTC, and outgoing payment in ETH, it looks like Connext client being temporarily offline stops the recovery of BTC funds:

(outcome 1)

14/07/2020 14:05:56.509 [DB] trace: Executing (default): SELECT `id`, `tokenAddress`, `decimalPlaces`, `swapClient` FROM `currencies` AS `Currency`;
14/07/2020 14:05:56.517 [SWAPS-RECOVERY] info: recovering swap deal 74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110
14/07/2020 14:05:56.523 [CONNEXT] info: new status: Initialized
14/07/2020 14:05:56.518 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap 74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110
14/07/2020 14:05:56.519 [SWAPS-RECOVERY] warn: could not recover deal 74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110 because ETH swap client is offline
14/07/2020 14:05:56.524 [CONNEXT] info: trying to verify connection to connext
.
.
.
14/07/2020 14:05:56.567 [CONNEXT] info: new status: ConnectionVerified
.
.
.
14/07/2020 14:06:01.500 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap 74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110
14/07/2020 14:06:01.502 [CONNEXT] trace: sending request to /hashlock-status/0x74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110/0x0000000000000000000000000000000000000000: undefined
14/07/2020 14:06:01.531 [DB] trace: Executing (default): UPDATE `swapdeals` SET `rPreimage`='63e8f013e2cdd2d82dd544d71b289f56583e6791ba331f5379e5ca6ad45bac26' WHERE `rHash` = '74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110'
14/07/2020 14:06:01.536 [LND-BTC] debug: settling invoice for 74240dc5db623fe47ce84ae77c6b616acd9307f358a0f33f608dafa6388da110 with preimage 63e8f013e2cdd2d82dd544d71b289f56583e6791ba331f5379e5ca6ad45bac26
14/07/2020 14:06:01.548 [SWAPS-RECOVERY] info: recovered BTC swap payment of 1 using preimage 63e8f013e2cdd2d82dd544d71b289f56583e6791ba331f5379e5ca6ad45bac26

Sometimes, on the same scenario, the BTC aren't being recovered at all. The difference is perhaps due to the exact timing of the taker settlement and the maker crash.

(outcome 2)

14/07/2020 14:01:27.518 [SWAPS-RECOVERY] info: recovering swap deal a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5
14/07/2020 14:01:27.524 [CONNEXT] info: new status: Initialized
14/07/2020 14:01:27.520 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5
14/07/2020 14:01:27.520 [SWAPS-RECOVERY] warn: could not recover deal a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5 because ETH swap client is offline
14/07/2020 14:01:27.525 [CONNEXT] info: trying to verify connection to connext
.
.
.
14/07/2020 14:01:27.567 [CONNEXT] info: new status: ConnectionVerified
.
.
.

14/07/2020 14:01:32.502 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5
14/07/2020 14:01:32.503 [CONNEXT] trace: sending request to /hashlock-status/0xa27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5/0x0000000000000000000000000000000000000000: undefined
14/07/2020 14:01:32.533 [SWAPS-RECOVERY] debug: swap for a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5 still has pending payments and will be monitored
14/07/2020 14:01:33.526 [CONNEXT] trace: sending request to /balance/0x0000000000000000000000000000000000000000: undefined
14/07/2020 14:01:36.536 [CONNEXT] trace: sending request to /balance/0x0000000000000000000000000000000000000000: undefined
14/07/2020 14:01:37.502 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5
14/07/2020 14:01:37.503 [CONNEXT] trace: sending request to /hashlock-status/0xa27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5/0x0000000000000000000000000000000000000000: undefined
14/07/2020 14:01:37.533 [SWAPS-RECOVERY] debug: swap for a27200198e7315fef45ac6f77aa4431788b6ac913e2ce78dffd18b34d1c2c5b5 still has pending payments and will be monitored

Steps to reproduce

testMakerCrashedAfterSendDelayedSettlementConnextOut test is implemented in the connext_instability_recovery_issue branch. All other instability tests are disabled.

In the test, the recovery procedure intervals were tweaked to 5sec.
The test currently asserts only that BTC funds were recovered after 10sec wait. This means that in outcome 1, the test are passing, but the issue can be seen consistently in the logs. The test happen to fail only in outcome 2.

To run locally:

$ npm run test:sim:clean:xud
$ npm run test:sim:clean:custom-xud
$ npm run test:sim:clean:connext
$ npm run test:sim:build:xud
$ npm run test:sim:build:connext
$ npm run test:sim:build:test
$ npm run test:sim:run:instability

Latest CI run:

https://github.com/ExchangeUnion/xud/runs/869600254 (logs are printed for inspection even when test passes).

Expected behaviour

BTC funds should be recovered independently of ETH swap client connectivity.

[sangaman]

When xud starts up, we do have a brief wait for all swap clients to try to come online (I believe it's 5 seconds) before we move onto other initialization tasks including recovering crashed swaps. We could potentially change this but I don't see this as an issue assuming I'm understanding correctly and it doesn't delay things more than a few seconds.

But even when do attempt to claim our funds after a crash, we often times do rely on the outgoing swap client to retrieve the preimage for us. Based on the logs in outcome 2, it looks like we try to fetch the preimage for the outgoing payment from the connext client, but connext is reporting that the payment is still pending (and thus has no preimage to give us). Are you certain in this case that the connext payment has gone through?

[LePremierHomme]

As discussed internally, it is expected to use the outgoing payment swap client to retrieve a missing preimage. Hence outcome 1 behaviour not a problem.

Regarding outcome 2 - I played a bit with the taker delay / maker crash timing, but didn't manage to reproduce it.

16/07/2020 14:29:18.068 [SWAPS-RECOVERY] info: recovering swap deal 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e
16/07/2020 14:29:18.071 [CONNEXT] info: new status: Initialized
16/07/2020 14:29:18.069 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e
16/07/2020 14:29:18.069 [SWAPS-RECOVERY] warn: could not recover deal 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e because ETH swap client is offline
16/07/2020 14:29:18.071 [CONNEXT] info: trying to verify connection to connext
.
.
(connext client still not connected)
.
.
16/07/2020 14:29:20.058 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e
16/07/2020 14:29:20.059 [CONNEXT] trace: sending request to /hashlock-status/0x7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e/0x0000000000000000000000000000000000000000: undefined
16/07/2020 14:29:20.087 [SWAPS-RECOVERY] debug: swap for 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e still has pending payments and will be monitored
.
.
(connext client connected, taker didn’t settle yet)
.
.
16/07/2020 14:29:22.059 [SWAPS-RECOVERY] debug: checking outgoing payment status for swap 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e
16/07/2020 14:29:22.060 [CONNEXT] trace: sending request to /hashlock-status/0x7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e/0x0000000000000000000000000000000000000000: undefined
16/07/2020 14:29:22.108 [DB] trace: Executing (default): UPDATE `swapdeals` SET `rPreimage`='2fb537b7fb403e3d68a7eb3bf6ed4161bfb48d547a0c0c070509c9ea2042f170' WHERE `rHash` = '7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e'
16/07/2020 14:29:22.119 [LND-BTC] debug: settling invoice for 7f061cfa6aeddb39e2a91eea93fca2c182e62efba2c2228bae0e43616cba8f1e with preimage 2fb537b7fb403e3d68a7eb3bf6ed4161bfb48d547a0c0c070509c9ea2042f170
16/07/2020 14:29:22.137 [SWAPS-RECOVERY] info: recovered BTC swap payment of 1 using preimage 2fb537b7fb403e3d68a7eb3bf6ed4161bfb48d547a0c0c070509c9ea2042f170

Looks like it's working properly. But to verify connext payment anyway, i've put the ETH balance assertion (outgoing payment) before the BTC one (incoming payment).