From 85c5c9e84e421c8a987a70985cf9ee98942bac29 Mon Sep 17 00:00:00 2001 From: Daniel McNally Date: Tue, 18 Aug 2020 15:21:31 -0400 Subject: [PATCH] feat(swaps): monitor pending payments before fail This monitors all swap client payments until their resolution without putting deals into `SwapRecovery`. Previously, if a call to send payment failed but the payment was still in pending status (as has been the case with Connext), then we would fail the swap deal and monitor the payment in `SwapRecovery`. This had several downsides, namely: 1. Since the deal is marked as having failed in the database, if xud restarts while payment monitoring is ongoing, it won't resume monitoring because it sees the swap as having failed in the database. We only recover swaps that were "active" at the time xud shut down. See #1799. 2. When a deal is failed, the maker order it attempted to swap re-enters the order book and is available to be matched again. However, since the payment for the original deal is still pending, it may still go through, meaning that the order can be "double filled" in such a case. See #1794. By monitoring all pending payments to their resolution, we ensure that we don't fail deals that wind up completing. Fixes #1799. Fixes #1794. --- lib/swaps/SwapRecovery.ts | 3 +- lib/swaps/Swaps.ts | 103 ++++++++++++++++++--------- test/simulation/custom-xud.patch | 68 ++++++++++-------- test/simulation/tests-instability.go | 16 ++--- 4 files changed, 116 insertions(+), 74 deletions(-) diff --git a/lib/swaps/SwapRecovery.ts b/lib/swaps/SwapRecovery.ts index 090618c4b..3759f6a35 100644 --- a/lib/swaps/SwapRecovery.ts +++ b/lib/swaps/SwapRecovery.ts @@ -16,11 +16,12 @@ interface SwapRecovery { * ensuring that we do not lose funds on a partially completed swap. */ class SwapRecovery extends EventEmitter { + public static readonly PENDING_SWAP_RECHECK_INTERVAL = 300000; + /** A map of payment hashes to swaps where we have a pending outgoing payment but don't know the preimage. */ private pendingSwaps: Map = new Map(); private pendingSwapsTimer?: NodeJS.Timeout; /** The time in milliseconds between checks on the status of pending swaps. */ - private static readonly PENDING_SWAP_RECHECK_INTERVAL = 300000; constructor(private swapClientManager: SwapClientManager, private logger: Logger) { super(); diff --git a/lib/swaps/Swaps.ts b/lib/swaps/Swaps.ts index 318e552f9..70f15b0d4 100644 --- a/lib/swaps/Swaps.ts +++ b/lib/swaps/Swaps.ts @@ -731,16 +731,36 @@ class Swaps extends EventEmitter { try { await swapClient.settleInvoice(rHash, rPreimage, currency); } catch (err) { - // if we couldn't settle the invoice then we fail the deal which throws - // it into recovery where we will try to settle our payment again this.logger.error(`could not settle invoice for deal ${rHash}`, err); - this.logger.alert(`incoming ${currency} payment with hash ${rHash} could not be settled with preimage ${rPreimage}, this is not expected and funds may be at risk`); - await this.failDeal({ - deal, - failureReason: SwapFailureReason.UnexpectedClientError, - errorMessage: err.message, - }); - return; + if (deal.role === SwapRole.Maker) { + // if we are the maker, we must be able to settle the invoice otherwise we lose funds + // we will continuously retry settling the invoice until it succeeds + // TODO: determine when we are permanently unable (due to htlc expiration or unknown invoice hash) to + // settle an invoice and fail the deal, rather than endlessly retrying settle invoice calls + this.logger.alert(`incoming ${currency} payment with hash ${rHash} could not be settled with preimage ${rPreimage}, this is not expected and funds may be at risk`); + + const settleRetryPromise = new Promise((resolve) => { + const settleRetryTimer = setInterval(async () => { + try { + await swapClient.settleInvoice(rHash, rPreimage, currency); + this.logger.info(`successfully settled invoice for deal ${rHash} on retry`); + resolve(); + clearInterval(settleRetryTimer); + } catch (err) { + this.logger.error(`could not settle invoice for deal ${rHash}`, err); + } + }, SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL); + }); + await settleRetryPromise; + } else { + // if we are the taker, funds are not at risk and we may simply fail the deal + await this.failDeal({ + deal, + failureReason: SwapFailureReason.UnexpectedClientError, + errorMessage: err.message, + }); + return; + } } // if we succeeded in settling our incoming payment we update the deal phase & state @@ -1035,13 +1055,22 @@ class Swaps extends EventEmitter { } catch (err) { this.logger.debug(`sendPayment in resolveHash failed due to ${err.message}`); - const failDeal = async (paymentState: PaymentState) => { + // the send payment call failed but we first double check its final status, so + // we only fail the deal when we know our payment won't go through. otherwise + // we extract the preimage if the payment went through in spite of the error + // or we fail the deal and go to SwapRecovery if it's still pending + const paymentStatus = await swapClient.lookupPayment(rHash, deal.takerCurrency, deal.destination); + if (paymentStatus.state === PaymentState.Succeeded) { + // just kidding, turns out the payment actually went through and we have the preimage! + // so we can continue with the swap + deal.rPreimage = paymentStatus.preimage!; + } else if (paymentStatus.state === PaymentState.Failed) { + // we've confirmed the payment has failed for good, so we can fail the deal switch (err.code) { case errorCodes.FINAL_PAYMENT_ERROR: await this.failDeal({ deal, peer, - paymentState, failedCurrency: deal.takerCurrency, failureReason: SwapFailureReason.SendPaymentFailure, errorMessage: err.message, @@ -1050,7 +1079,6 @@ class Swaps extends EventEmitter { case errorCodes.PAYMENT_REJECTED: await this.failDeal({ deal, - paymentState, failureReason: SwapFailureReason.PaymentRejected, errorMessage: err.message, }); @@ -1059,25 +1087,40 @@ class Swaps extends EventEmitter { await this.failDeal({ deal, peer, - paymentState, failedCurrency: deal.takerCurrency, failureReason: SwapFailureReason.UnknownError, errorMessage: err.message, }); break; } - }; - - // the payment failed but we first double check its final status, so we - // only fail the deal when we know our payment won't go through. otherwise - // we extract the preimage if the payment went through in spite of the error - // or we fail the deal and go to SwapRecovery if it's still pending - const paymentStatus = await swapClient.lookupPayment(rHash, deal.takerCurrency, deal.destination); - if (paymentStatus.state === PaymentState.Succeeded) { - deal.rPreimage = paymentStatus.preimage!; - } else { - await failDeal(paymentStatus.state); throw err; + } else { + // the payment is in limbo, and could eventually go through. we need to make + // sure that the taker doesn't claim our payment without us having a chance + // to claim ours. we will monitor the outcome here. + const pendingPaymentPromise = new Promise((resolve, reject) => { + const recheckTimer = setInterval(async () => { + const paymentStatus = await swapClient.lookupPayment(rHash, deal.takerCurrency, deal.destination); + if (paymentStatus.state === PaymentState.Succeeded) { + // the payment went through, we resolve the promise to the resolved preimage + resolve(paymentStatus.preimage!); + clearInterval(recheckTimer); + } else if (paymentStatus.state === PaymentState.Failed) { + // the payment finally failed, so we can fail the deal + await this.failDeal({ + deal, + peer, + failedCurrency: deal.takerCurrency, + failureReason: SwapFailureReason.SendPaymentFailure, + errorMessage: err.message, + }); + reject(err); + clearInterval(recheckTimer); + } + }, SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL); + }); + + deal.rPreimage = await pendingPaymentPromise; } } @@ -1166,7 +1209,7 @@ class Swaps extends EventEmitter { /** * Fails a deal and optionally sends a SwapFailurePacket to a peer, if provided. */ - private failDeal = async ({ deal, failureReason, failedCurrency, errorMessage, peer, reqId, paymentState }: + private failDeal = async ({ deal, failureReason, failedCurrency, errorMessage, peer, reqId }: { deal: SwapDeal, failureReason: SwapFailureReason, @@ -1178,8 +1221,6 @@ class Swaps extends EventEmitter { peer?: Peer, /** An optional reqId in case the SwapFailedPacket is in response to a swap request. */ reqId?: string, - /** The state of the outgoing payment involved with this swap. */ - paymentState?: PaymentState, }) => { assert(deal.state !== SwapState.Completed, 'Can not fail a completed deal.'); @@ -1257,14 +1298,6 @@ class Swaps extends EventEmitter { // then we should cancel the invoice for our incoming payment if one exists const swapClient = this.swapClientManager.get(deal.makerCurrency)!; swapClient.removeInvoice(deal.rHash).catch(this.logger.error); // we don't need to await the remove invoice call - } else if ((paymentState === undefined || paymentState === PaymentState.Pending) && - (deal.phase === SwapPhase.SendingPayment || deal.phase === SwapPhase.PreimageResolved)) { - // if the swap fails while we are in the middle of sending payment as the maker - // and we haven't confirmed that our outgoing payment is no longer pending - // we need to make sure that the taker doesn't claim our payment without us having a chance - // to claim ours. we will send this swap to recovery to monitor its outcome - const swapDealInstance = await this.repository.getSwapDeal(deal.rHash); - await this.swapRecovery.recoverDeal(swapDealInstance!); } } else if (deal.phase === SwapPhase.SendingPayment) { const swapClient = this.swapClientManager.get(deal.takerCurrency)!; diff --git a/test/simulation/custom-xud.patch b/test/simulation/custom-xud.patch index 94d7a68a8..47c3bff74 100644 --- a/test/simulation/custom-xud.patch +++ b/test/simulation/custom-xud.patch @@ -1,11 +1,11 @@ diff --git a/lib/Xud.ts b/lib/Xud.ts -index 08402caa..c9972d25 100644 +index 759acb001..6f5772574 100644 --- a/lib/Xud.ts +++ b/lib/Xud.ts @@ -87,6 +87,11 @@ class Xud extends EventEmitter { this.logger.info('config file loaded'); } - + + this.logger.info('CUSTOM-XUD'); + if (process.env.CUSTOM_SCENARIO) { + this.logger.info(`CUSTOM_SCENARIO=${process.env.CUSTOM_SCENARIO}`); @@ -15,18 +15,15 @@ index 08402caa..c9972d25 100644 if (!this.config.rpc.disable) { // start rpc server first, it will respond with UNAVAILABLE error diff --git a/lib/swaps/SwapRecovery.ts b/lib/swaps/SwapRecovery.ts -index 090618c4..820f8909 100644 +index 3759f6a35..4089dc944 100644 --- a/lib/swaps/SwapRecovery.ts +++ b/lib/swaps/SwapRecovery.ts -@@ -28,7 +28,21 @@ class SwapRecovery extends EventEmitter { - +@@ -29,7 +29,18 @@ class SwapRecovery extends EventEmitter { + public beginTimer = () => { if (!this.pendingSwapsTimer) { - this.pendingSwapsTimer = setInterval(this.checkPendingSwaps, SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL); + let interval = SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL; -+ if (process.env.CUSTOM_SCENARIO === 'INSTABILITY::MAKER_CLIENT_CRASHED_BEFORE_SETTLE') { -+ interval = 2000; -+ } + if (process.env.CUSTOM_SCENARIO === 'INSTABILITY::MAKER_CRASH_WHILE_SENDING') { + interval = 2000; + } @@ -40,12 +37,12 @@ index 090618c4..820f8909 100644 + this.pendingSwapsTimer = setInterval(this.checkPendingSwaps, interval); } } - + diff --git a/lib/swaps/Swaps.ts b/lib/swaps/Swaps.ts -index 908f4cc3..b72ab4dc 100644 +index b3c2b88c9..31f487fe6 100644 --- a/lib/swaps/Swaps.ts +++ b/lib/swaps/Swaps.ts -@@ -721,6 +721,24 @@ class Swaps extends EventEmitter { +@@ -733,6 +733,24 @@ class Swaps extends EventEmitter { // if the swap has already been failed, then we leave the swap recovery module // to attempt to settle the invoice and claim funds rather than do it here try { @@ -69,8 +66,19 @@ index 908f4cc3..b72ab4dc 100644 + this.logger.info('SETTLING INVOICE'); await swapClient.settleInvoice(rHash, rPreimage, currency); } catch (err) { - // if we couldn't settle the invoice then we fail the deal which throws -@@ -745,6 +763,16 @@ class Swaps extends EventEmitter { + this.logger.error(`could not settle invoice for deal ${rHash}`, err); +@@ -753,7 +771,9 @@ class Swaps extends EventEmitter { + } catch (err) { + this.logger.error(`could not settle invoice for deal ${rHash}`, err); + } +- }, SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL); ++ }, process.env.CUSTOM_SCENARIO === 'INSTABILITY::MAKER_CLIENT_CRASHED_BEFORE_SETTLE' ? ++ 2000 : ++ SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL); + }); + await settleRetryPromise; + } else { +@@ -777,6 +797,16 @@ class Swaps extends EventEmitter { * accepted, initiates the swap. */ private handleSwapAccepted = async (responsePacket: packets.SwapAcceptedPacket, peer: Peer) => { @@ -87,8 +95,8 @@ index 908f4cc3..b72ab4dc 100644 assert(responsePacket.body, 'SwapAcceptedPacket does not contain a body'); const { quantity, rHash, makerCltvDelta } = responsePacket.body; const deal = this.getDeal(rHash); -@@ -832,6 +860,11 @@ class Swaps extends EventEmitter { - +@@ -864,6 +894,11 @@ class Swaps extends EventEmitter { + try { await makerSwapClient.sendPayment(deal); + @@ -99,10 +107,10 @@ index 908f4cc3..b72ab4dc 100644 } catch (err) { // first we must handle the edge case where the maker has paid us but failed to claim our payment // in this case, we've already marked the swap as having been paid and completed -@@ -1013,6 +1046,18 @@ class Swaps extends EventEmitter { - +@@ -1045,6 +1080,18 @@ class Swaps extends EventEmitter { + this.logger.debug('Executing maker code to resolve hash'); - + + if (process.env.CUSTOM_SCENARIO === 'SECURITY::MAKER_1ST_HTLC_STALL') { + this.logger.info(`CUSTOM_SCENARIO: ${process.env.CUSTOM_SCENARIO}`); + const makerSwapClient = this.swapClientManager.get(deal.makerCurrency)!; @@ -116,11 +124,11 @@ index 908f4cc3..b72ab4dc 100644 + } + const swapClient = this.swapClientManager.get(deal.takerCurrency)!; - + // we update the phase persist the deal to the database before we attempt to send payment -@@ -1023,6 +1068,13 @@ class Swaps extends EventEmitter { +@@ -1055,6 +1102,13 @@ class Swaps extends EventEmitter { assert(deal.state !== SwapState.Error, `cannot send payment for failed swap ${deal.rHash}`); - + try { + if (process.env.CUSTOM_SCENARIO === 'INSTABILITY::MAKER_CRASH_WHILE_SENDING') { + setTimeout(() => { @@ -132,10 +140,10 @@ index 908f4cc3..b72ab4dc 100644 deal.rPreimage = await swapClient.sendPayment(deal); } catch (err) { this.logger.debug(`sendPayment in resolveHash failed due to ${err.message}`); -@@ -1073,10 +1125,21 @@ class Swaps extends EventEmitter { +@@ -1128,10 +1182,21 @@ class Swaps extends EventEmitter { } } - + + if (process.env.CUSTOM_SCENARIO === 'INSTABILITY::MAKER_CRASH_AFTER_SEND_BEFORE_PREIMAGE_RESOLVED') { + this.logger.info(`CUSTOM_SCENARIO: ${process.env.CUSTOM_SCENARIO}`); + process.exit(); @@ -155,10 +163,10 @@ index 908f4cc3..b72ab4dc 100644 return deal.rPreimage; } else { // If we are here we are the taker -@@ -1084,6 +1147,16 @@ class Swaps extends EventEmitter { +@@ -1139,6 +1204,16 @@ class Swaps extends EventEmitter { assert(htlcCurrency === undefined || htlcCurrency === deal.takerCurrency, 'incoming htlc does not match expected deal currency'); this.logger.debug('Executing taker code to resolve hash'); - + + if (process.env.CUSTOM_SCENARIO === 'SECURITY::TAKER_2ND_HTLC_STALL') { + this.logger.info(`CUSTOM_SCENARIO: ${process.env.CUSTOM_SCENARIO}`); + return ''; @@ -172,8 +180,8 @@ index 908f4cc3..b72ab4dc 100644 return deal.rPreimage; } } -@@ -1259,8 +1332,11 @@ class Swaps extends EventEmitter { - await this.swapRecovery.recoverDeal(swapDealInstance!); +@@ -1304,8 +1379,11 @@ class Swaps extends EventEmitter { + swapClient.removeInvoice(deal.rHash).catch(this.logger.error); // we don't need to await the remove invoice call } } else if (deal.phase === SwapPhase.SendingPayment) { - const swapClient = this.swapClientManager.get(deal.takerCurrency)!; @@ -184,10 +192,10 @@ index 908f4cc3..b72ab4dc 100644 + swapClient.removeInvoice(deal.rHash).catch(this.logger.error); // we don't need to await the remove invoice call + } } - + this.logger.trace(`emitting swap.failed event for ${deal.rHash}`); -@@ -1324,9 +1400,14 @@ class Swaps extends EventEmitter { - +@@ -1369,9 +1447,14 @@ class Swaps extends EventEmitter { + if (deal.role === SwapRole.Maker) { // the maker begins execution of the swap upon accepting the deal + diff --git a/test/simulation/tests-instability.go b/test/simulation/tests-instability.go index 9c026eec2..e2e8d4f4f 100644 --- a/test/simulation/tests-instability.go +++ b/test/simulation/tests-instability.go @@ -136,7 +136,7 @@ func testMakerCrashedDuringSwapConnextIn(net *xudtest.NetworkHarness, ht *harnes ht.act.connect(net.Alice, net.Bob) ht.act.verifyConnectivity(net.Alice, net.Bob) - err = openETHChannel(ht.ctx, net.Bob, 400, 0) + err = openETHChannel(ht.ctx, net.Bob, 40000, 0) ht.assert.NoError(err) // Save the initial balances. @@ -148,7 +148,7 @@ func testMakerCrashedDuringSwapConnextIn(net *xudtest.NetworkHarness, ht *harnes aliceOrderReq := &xudrpc.PlaceOrderRequest{ OrderId: "maker_order_id", Price: 40, - Quantity: 1, + Quantity: 100, PairId: "BTC/ETH", Side: xudrpc.OrderSide_SELL, } @@ -265,7 +265,7 @@ func testMakerConnextClientCrashedBeforeSettlement(net *xudtest.NetworkHarness, ht.act.connect(net.Alice, net.Bob) ht.act.verifyConnectivity(net.Alice, net.Bob) - err = openETHChannel(ht.ctx, net.Bob, 400, 0) + err = openETHChannel(ht.ctx, net.Bob, 40000, 0) ht.assert.NoError(err) // Save the initial balances. @@ -281,7 +281,7 @@ func testMakerConnextClientCrashedBeforeSettlement(net *xudtest.NetworkHarness, aliceOrderReq := &xudrpc.PlaceOrderRequest{ OrderId: "maker_order_id", Price: 40, - Quantity: 1, + Quantity: 100, PairId: "BTC/ETH", Side: xudrpc.OrderSide_SELL, } @@ -409,7 +409,7 @@ func testMakerCrashedAfterSendDelayedSettlementConnextOut(net *xudtest.NetworkHa ht.act.connect(net.Alice, net.Bob) ht.act.verifyConnectivity(net.Alice, net.Bob) - err = openETHChannel(ht.ctx, net.Alice, 400, 0) + err = openETHChannel(ht.ctx, net.Alice, 40000, 0) ht.assert.NoError(err) // Save the initial balances. @@ -425,7 +425,7 @@ func testMakerCrashedAfterSendDelayedSettlementConnextOut(net *xudtest.NetworkHa aliceOrderReq := &xudrpc.PlaceOrderRequest{ OrderId: "maker_order_id", Price: 40, - Quantity: 1, + Quantity: 100, PairId: "BTC/ETH", Side: xudrpc.OrderSide_BUY, } @@ -497,7 +497,7 @@ func testMakerCrashedAfterSendDelayedSettlementConnextIn(net *xudtest.NetworkHar ht.act.connect(net.Alice, net.Bob) ht.act.verifyConnectivity(net.Alice, net.Bob) - err = openETHChannel(ht.ctx, net.Bob, 400, 0) + err = openETHChannel(ht.ctx, net.Bob, 40000, 0) ht.assert.NoError(err) // Save the initial balances. @@ -513,7 +513,7 @@ func testMakerCrashedAfterSendDelayedSettlementConnextIn(net *xudtest.NetworkHar aliceOrderReq := &xudrpc.PlaceOrderRequest{ OrderId: "maker_order_id", Price: 40, - Quantity: 1, + Quantity: 100, PairId: "BTC/ETH", Side: xudrpc.OrderSide_SELL, }