feat(swaps): monitor pending payments before fail (#1822)

* 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.

This also fixes a case where the maker would not cancel its invoice when
an outgoing payment would fail and the very first `lookupPayment` call
would confirm that it had failed.

Fixes #1799. Fixes #1794. Fixes #1708.

* test(sim): handle no force close for taker

This modifies the simulation tests to account for the maker properly
canceling the invoice for its incoming payment once its outgoing payment
htlc expires. Rather than expecting the channel with the taker to maker
payment to expire and force close, it expects the invoice to be canceled
and for the channel to remain open. It ensures that the balances on the
channel do not change.

lib/connextclient/ConnextClient.ts

@@ -445,6 +445,7 @@ class ConnextClient extends SwapClient {
       const assetId = this.getTokenAddress(currency);
       const transferStatusResponse = await this.getHashLockStatus(rHash, assetId);
 
+      this.logger.trace(`hashlock status for payment with hash ${rHash} is ${transferStatusResponse.status}`);
       switch (transferStatusResponse.status) {
         case 'PENDING':
           return { state: PaymentState.Pending };
@@ -457,6 +458,7 @@ class ConnextClient extends SwapClient {
         case 'FAILED':
           return { state: PaymentState.Failed };
         default:
+          this.logger.debug(`no hashlock status for payment with hash ${rHash}: ${JSON.stringify(transferStatusResponse)}`);
           return { state: PaymentState.Pending };
       }
     } catch (err) {

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<string, SwapDealInstance> = 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();

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<void>((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
@@ -1033,15 +1053,25 @@ class Swaps extends EventEmitter {
       try {
         deal.rPreimage = await swapClient.sendPayment(deal);
       } catch (err) {
-        this.logger.debug(`sendPayment in resolveHash failed due to ${err.message}`);
+        this.logger.debug(`sendPayment in resolveHash for swap ${deal.rHash} 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 && paymentStatus.preimage) {
+          // just kidding, turns out the payment actually went through and we have the preimage!
+          // so we can continue with the swap
+          this.logger.debug(`payment for swap ${deal.rHash} succeeded despite sendPayment error, preimage is ${paymentStatus.preimage}`);
+          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 +1080,6 @@ class Swaps extends EventEmitter {
             case errorCodes.PAYMENT_REJECTED:
               await this.failDeal({
                 deal,
-                paymentState,
                 failureReason: SwapFailureReason.PaymentRejected,
                 errorMessage: err.message,
               });
@@ -1059,25 +1088,43 @@ 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.
+          this.logger.info(`started monitoring pending payment for swap ${deal.rHash}, will check every ${SwapRecovery.PENDING_SWAP_RECHECK_INTERVAL / 1000} seconds`);
+          const pendingPaymentPromise = new Promise<string>((resolve, reject) => {
+            const recheckTimer = setInterval(async () => {
+              this.logger.trace(`checking pending payment status for swap ${deal.rHash}`);
+              const paymentStatus = await swapClient.lookupPayment(rHash, deal.takerCurrency, deal.destination);
+              this.logger.trace(`payment for swap ${deal.rHash} is in ${PaymentState[paymentStatus.state]} status}`);
+              if (paymentStatus.state === PaymentState.Succeeded && paymentStatus.preimage) {
+                // 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 +1213,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,13 +1225,9 @@ 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.');
 
-    this.logger.trace(`failing deal ${deal.rHash} in state ${SwapState[deal.state]} & phase ${SwapPhase[deal.phase]} due to ${SwapFailureReason[failureReason]}`);
-
     // If we are already in error state and got another error report we
     // aggregate all error reasons by concatenation
     if (deal.state === SwapState.Error) {
@@ -1194,11 +1237,11 @@ class Swaps extends EventEmitter {
           deal.errorMessage += ` (${failedCurrency})`;
         }
       }
-      this.logger.debug(`new deal error message for ${deal.rHash}: + ${deal.errorMessage}`);
+      this.logger.trace(`new deal error message for ${deal.rHash}: + ${deal.errorMessage}`);
       return;
     }
 
-    let logMessage = `deal ${deal.rHash} failed due to ${SwapFailureReason[failureReason]}`;
+    let logMessage = `deal ${deal.rHash} failed in state ${SwapState[deal.state]} & phase ${SwapPhase[deal.phase]} due to ${SwapFailureReason[failureReason]}`;
     if (failedCurrency) {
       logMessage += ` (${failedCurrency})`;
     }
@@ -1251,20 +1294,14 @@ class Swaps extends EventEmitter {
 
     clearTimeout(this.timeouts.get(deal.rHash));
     this.timeouts.delete(deal.rHash);
+
     if (deal.role === SwapRole.Maker) {
-      if (deal.phase === SwapPhase.SwapAccepted) {
-        // if we are the maker and we have accepted a swap deal but we haven't yet started paying the taker
-        // then we should cancel the invoice for our incoming payment if one exists
+      // if we are the maker and we have accepted a swap deal or were sending a payment that
+      // has since failed then we should cancel the invoice for our incoming payment this
+      // will cancel any incoming HTLCs rather than letting them expire and force close channels
+      if (deal.phase === SwapPhase.SwapAccepted || deal.phase === SwapPhase.SendingPayment) {
         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)!;

test/simulation/custom-xud.patch

@@ -1,11 +1,11 @@
 diff --git a/lib/Xud.ts b/lib/Xud.ts
-index 08402caa..c9972d25 100644
+index 52ed8b5b4..93c5029b3 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 3a2367f52..ec1712119 100644
 --- a/lib/swaps/Swaps.ts
 +++ b/lib/swaps/Swaps.ts
-@@ -721,6 +721,24 @@ class Swaps extends EventEmitter {
+@@ -729,6 +729,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);
+@@ -749,7 +767,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 {
+@@ -773,6 +793,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 {
-
+@@ -860,6 +890,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 {
-
+@@ -1041,6 +1076,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 {
+@@ -1051,6 +1098,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(() => {
@@ -131,11 +139,11 @@ 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 {
+         this.logger.debug(`sendPayment in resolveHash for swap ${deal.rHash} failed due to ${err.message}`);
+@@ -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!);
+@@ -1302,8 +1377,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 {
-
+@@ -1367,9 +1445,14 @@ class Swaps extends EventEmitter {
+ 
          if (deal.role === SwapRole.Maker) {
            // the maker begins execution of the swap upon accepting the deal
 +