Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Test payments with HODL invoices #1341

Draft
wants to merge 1 commit into
base: master
Choose a base branch
from
Draft

Test payments with HODL invoices #1341

wants to merge 1 commit into from

Conversation

ekzyis
Copy link
Member

@ekzyis ekzyis commented Aug 28, 2024

Description

This PR replaces the testSendPayment function by wrapping sendPayment with code that actually attempts to pay an invoice.

That invoice is a HODL invoice and when it is held, we cancel it and return success. If the payment is not received within a timeout, or if the wallet throws an error first, the test fails and the wallet is not attached.

However, I realized that payments might also fail because of insufficient balance. The wallet should still get attached in that case, see TODO.

TODO:

  • how to attach wallet if payment fails due to insufficient balance? can we assume and parse the error message?

update: we will log errors as warnings and not block attachment

  • make sure logger in sendPayment is optional in every wallet
  • make sure we use any config returned by sendPayment (or find an alternative solution for LNC)

I added optional transformConfig to the wallet interface but didn't test yet with LNC

  • test all wallets

Based on #1340

Additional Context

Wallets that can't pay regtest invoices like phoenixd or Blink will not be attachable during development.

Update: test payments will only be used to indicate to the user that something might be wrong but it will not block attachments. We should show errors during test payments as warnings.

Checklist

Are your changes backwards compatible? Please answer below:

On a scale of 1-10 how well and how have you QA'd this change and any features it might affect? Please answer below:

For frontend changes: Tested on mobile? Please answer below:

Did you introduce any new environment variables? If so, call them out explicitly here:

@ekzyis ekzyis added enhancement improvements to existing features wallets labels Aug 28, 2024
@ekzyis ekzyis marked this pull request as draft August 28, 2024 06:48
@ekzyis ekzyis force-pushed the hodl-test-payments branch 5 times, most recently from 6d487fa to 957b520 Compare September 4, 2024 04:20
@ekzyis
Copy link
Member Author

ekzyis commented Sep 4, 2024

Mhh, this PR would be ready for review if it wouldn't be for this mysterious bug:

For some reason, NWC test payments sometimes fail with incorrect_payment_details. This error is thrown when a paid invoice is canceled (but there might also be other cases I am unfamiliar with). So afaict, this means that something is canceling the invoice; however it's not our code.

This looks like a race condition since it only happens sometimes but I made sure that finalizeHodlInvoice runs 60 seconds after we received the payment. To make super sure, I even completely removed that job and the cancel on the client and this bug still happens. So it seems like it's really not our code accidentally canceling the invoice in some cases for some reason.

Additionally, this only happens for test payments and only for NWC. I never had this error with LNbits. NWC payments with actions attached always succeed. The difference is that payments for action settle immediately. When I print the bolt11 for a test payment in the console and pay it manually with sndev stacker_lndcli payinvoice <bolt11> (node NWC is using) and sndev sn_lndcli settleinvoice <preimage>, it works as expected.

I am super confused by this and need to investigate this more.

video
2024-09-04.06-14-10.mp4
Sample invoice flow logs in worker where this bug happened
event invoice_updated triggered with args {
  chain_address: undefined,
  cltv_delta: 80,
  confirmed_at: undefined,
  confirmed_index: undefined,
  created_at: '2024-09-04T05:27:20.000Z',
  description: 'Funding @test01 on stacker.news',
  description_hash: undefined,
  expires_at: '2024-09-04T05:30:20.000Z',
  features: [
    { bit: 9, is_known: true, is_required: false, type: 'tlv_onion' },
    {
      bit: 14,
      is_known: true,
      is_required: true,
      type: 'payment_identifier'
    },
    {
      bit: 17,
      is_known: true,
      is_required: false,
      type: 'multipath_payments_v0'
    }
  ],
  id: '9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003',
  index: 195,
  is_canceled: undefined,
  is_confirmed: false,
  is_held: undefined,
  is_private: false,
  is_push: undefined,
  mtokens: '1000',
  payment: 'd06927af302cdf429635d423091b441d41ace08070cf5db960af9acba97e81ec',
  payments: [],
  received: 0,
  received_mtokens: '0',
  request: 'lnbcrt10n1pnd0macpp5jejuc99nfdwlgtjktd38mmcmm73t7esd5aahp3eh4cml68rc6qpsdpjge6kuerfdenjqsr5v4ehgvp3yphkugrnw3skx6m9wghxuethwvcqzzsxqz95sp56p5j0tes9n0599346s3sjx6yr4q6ecyqwr84mwtq47dvh2t7s8kq9qyyssqh4903ykmm7qf0lpjnrt9f7gtkz2wgd
wxnkmcd7hqrrvtqsc4nnhkhvywf0uv230zr2f6penacc0ufssx9eg8c902pt823ngsc53cn0spyxksdx',
  secret: '',
  tokens: 1
}
event hodl_invoice_updated triggered with args {
  chain_address: undefined,
  cltv_delta: 80,
  confirmed_at: undefined,
  confirmed_index: undefined,
  created_at: '2024-09-04T05:27:20.000Z',
  description: 'Funding @test01 on stacker.news',
  description_hash: undefined,
  expires_at: '2024-09-04T05:30:20.000Z',
  features: [
    { bit: 9, is_known: true, is_required: false, type: 'tlv_onion' },
    {
      bit: 14,
      is_known: true,
      is_required: true,
      type: 'payment_identifier'
    },
    {
      bit: 17,
      is_known: true,
      is_required: false,
      type: 'multipath_payments_v0'
    }
  ],
  id: '9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003',
  index: 195,
  is_canceled: undefined,
  is_confirmed: false,
  is_held: undefined,
  is_private: false,
  is_push: undefined,
  mtokens: '1000',
  payment: 'd06927af302cdf429635d423091b441d41ace08070cf5db960af9acba97e81ec',
  payments: [],
  received: 0,
  received_mtokens: '0',
  request: 'lnbcrt10n1pnd0macpp5jejuc99nfdwlgtjktd38mmcmm73t7esd5aahp3eh4cml68rc6qpsdpjge6kuerfdenjqsr5v4ehgvp3yphkugrnw3skx6m9wghxuethwvcqzzsxqz95sp56p5j0tes9n0599346s3sjx6yr4q6ecyqwr84mwtq47dvh2t7s8kq9qyyssqh4903ykmm7qf0lpjnrt9f7gtkz2wgd
wxnkmcd7hqrrvtqsc4nnhkhvywf0uv230zr2f6penacc0ufssx9eg8c902pt823ngsc53cn0spyxksdx',
  secret: '',
  tokens: 1
}
Trace: checkInvoice:: 9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003
    at checkInvoice (file:///app/worker/wallet.js:116:11)
    at EventEmitter.<anonymous> (file:///app/worker/wallet.js:100:15)
    at EventEmitter.emit (node:events:514:28)
    at EventEmitter.emit (node:domain:489:12)
    at invoiceUpdated (/app/node_modules/lightning/lnd_methods/invoices/subscribe_to_invoice.js:116:50)
    at ClientReadableStreamImpl.<anonymous> (/app/node_modules/lightning/lnd_methods/invoices/subscribe_to_invoice.js:120:14)
    at ClientReadableStreamImpl.emit (node:events:514:28)
    at ClientReadableStreamImpl.emit (node:domain:489:12)
    at addChunk (node:internal/streams/readable:324:12)
    at readableAddChunk (node:internal/streams/readable:297:9)
    at Readable.push (node:internal/streams/readable:234:10)
    at Object.onReceiveMessage (/app/node_modules/@grpc/grpc-js/build/src/client.js:347:24)
    at Object.onReceiveMessage (/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:315:178)
    at <anonymous> (/app/node_modules/@grpc/grpc-js/build/src/resolving-call.js:175:39)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
invoice not found in database 9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003
event hodl_invoice_updated triggered with args {
  chain_address: undefined,
  cltv_delta: 80,
  confirmed_at: undefined,
  confirmed_index: undefined,
  created_at: '2024-09-04T05:27:20.000Z',
  description: 'Funding @test01 on stacker.news',
  description_hash: undefined,
  expires_at: '2024-09-04T05:30:20.000Z',
  features: [
    { bit: 9, is_known: true, is_required: false, type: 'tlv_onion' },
    {
      bit: 14,
      is_known: true,
      is_required: true,
      type: 'payment_identifier'
    },
    {
      bit: 17,
      is_known: true,
      is_required: false,
      type: 'multipath_payments_v0'
    }
  ],
  id: '9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003',
  index: 195,
  is_canceled: undefined,
  is_confirmed: false,
  is_held: true,
  is_private: false,
  is_push: undefined,
  mtokens: '1000',
  payment: 'd06927af302cdf429635d423091b441d41ace08070cf5db960af9acba97e81ec',
  payments: [
    {
      canceled_at: undefined,
      confirmed_at: undefined,
      created_at: '2024-09-04T05:27:24.000Z',
      created_height: 1617,
      in_channel: '1617x23x1',
      is_canceled: false,
      is_confirmed: false,
      is_held: true,
      messages: [],
      mtokens: '1000',
      pending_index: 1,
      timeout: 1700,
      tokens: 1,
      total_mtokens: '1000'
    }
  ],
  received: 1,
  received_mtokens: '1000',
  request: 'lnbcrt10n1pnd0macpp5jejuc99nfdwlgtjktd38mmcmm73t7esd5aahp3eh4cml68rc6qpsdpjge6kuerfdenjqsr5v4ehgvp3yphkugrnw3skx6m9wghxuethwvcqzzsxqz95sp56p5j0tes9n0599346s3sjx6yr4q6ecyqwr84mwtq47dvh2t7s8kq9qyyssqh4903ykmm7qf0lpjnrt9f7gtkz2wgd
wxnkmcd7hqrrvtqsc4nnhkhvywf0uv230zr2f6penacc0ufssx9eg8c902pt823ngsc53cn0spyxksdx',
  secret: '',
  tokens: 1
}
Trace: checkInvoice:: 9665cc14b34b5df42e565b627def1bdfa2bf660da77b70c737ae37fd1c78d003
    at checkInvoice (file:///app/worker/wallet.js:116:11)
    at EventEmitter.<anonymous> (file:///app/worker/wallet.js:100:15)
    at EventEmitter.emit (node:events:514:28)
    at EventEmitter.emit (node:domain:489:12)
    at invoiceUpdated (/app/node_modules/lightning/lnd_methods/invoices/subscribe_to_invoice.js:116:50)
    at ClientReadableStreamImpl.<anonymous> (/app/node_modules/lightning/lnd_methods/invoices/subscribe_to_invoice.js:120:14)
    at ClientReadableStreamImpl.emit (node:events:514:28)
    at ClientReadableStreamImpl.emit (node:domain:489:12)
    at addChunk (node:internal/streams/readable:324:12)
    at readableAddChunk (node:internal/streams/readable:297:9)
    at Readable.push (node:internal/streams/readable:234:10)
    at Object.onReceiveMessage (/app/node_modules/@grpc/grpc-js/build/src/client.js:347:24)
    at Object.onReceiveMessage (/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:315:178)
    at <anonymous> (/app/node_modules/@grpc/grpc-js/build/src/resolving-call.js:175:39)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Logs generated running this patch with console.log and cancel by us excluded
diff --git a/api/resolvers/wallet.js b/api/resolvers/wallet.js
index 03965f6a..9d3c2c81 100644
--- a/api/resolvers/wallet.js
+++ b/api/resolvers/wallet.js
@@ -415,6 +415,7 @@ const resolvers = {
       if (!timingSafeEqual(Buffer.from(hmac), Buffer.from(hmac2))) {
         throw new GraphQLError('bad hmac', { extensions: { code: 'FORBIDDEN' } })
       }
+      console.log('cancelInvoice::', hash)
       await finalizeHodlInvoice({ data: { hash }, lnd, models, boss })
       return await models.invoice.findFirst({ where: { hash } })
     },
diff --git a/wallets/index.js b/wallets/index.js
index eaca1f7c..179d63a1 100644
--- a/wallets/index.js
+++ b/wallets/index.js
@@ -182,11 +182,12 @@ function useConfig (wallet) {
 
     logger.info('sending test payment:', `payment_hash=${inv.hash}`)
 
+    let invHeldPromise, paymentPromise
     try {
-      const paymentPromise = wallet.sendPayment(inv.bolt11, config, context)
+      paymentPromise = wallet.sendPayment(inv.bolt11, config, context)
 
       // test is successful if invoice is held
-      const invHeldPromise = invoice.waitUntilPaid({
+      invHeldPromise = invoice.waitUntilPaid({
         id: inv.id,
         waitFor: inv => inv.isHeld
       })
@@ -207,11 +208,12 @@ function useConfig (wallet) {
       // which we will never do for test payments
       logger.ok('test payment received')
     } catch (err) {
+      console.log(invHeldPromise, paymentPromise)
       // test payment failures are not blocking attachment,
       // we only want to let the user know that there _might_ be an issue
       logger.warn('test payment failed:', err.message)
     } finally {
-      await invoice.cancel(inv)
+      // await invoice.cancel(inv)
     }
   }, [invoice, wallet])
 
diff --git a/wallets/nwc/index.js b/wallets/nwc/index.js
index 254ac428..e980e936 100644
--- a/wallets/nwc/index.js
+++ b/wallets/nwc/index.js
@@ -72,6 +72,8 @@ export async function nwcCall ({ nwcUrl, method, params }, { logger, timeout } =
     const decrypted = await nip04.decrypt(secret, walletPubkey, response.content)
     const content = JSON.parse(decrypted)
 
+    console.log(content)
+
     if (content.error) throw new Error(content.error.message)
     if (content.result) return content.result
 
diff --git a/worker/index.js b/worker/index.js
index 759d6ad7..3387d09d 100644
--- a/worker/index.js
+++ b/worker/index.js
@@ -88,7 +88,7 @@ async function work () {
 
   if (isServiceEnabled('payments')) {
     await subscribeToWallet(args)
-    await boss.work('finalizeHodlInvoice', jobWrapper(finalizeHodlInvoice))
+    // await boss.work('finalizeHodlInvoice', jobWrapper(finalizeHodlInvoice))
     await boss.work('checkPendingDeposits', jobWrapper(checkPendingDeposits))
     await boss.work('checkPendingWithdrawals', jobWrapper(checkPendingWithdrawals))
     await boss.work('autoDropBolt11s', jobWrapper(autoDropBolt11s))
diff --git a/worker/wallet.js b/worker/wallet.js
index 4ffdaf88..f5845eb1 100644
--- a/worker/wallet.js
+++ b/worker/wallet.js
@@ -113,6 +113,7 @@ function subscribeToHodlInvoice (args) {
 }
 
 export async function checkInvoice ({ data: { hash }, boss, models, lnd }) {
+  console.trace('checkInvoice::', hash)
   const inv = await getInvoice({ id: hash, lnd })
 
   // invoice could be created by LND but wasn't inserted into the database yet
@@ -371,6 +372,7 @@ export async function autoDropBolt11s ({ models, lnd }) {
 // The callback subscriptions above will NOT get called for JIT invoices that are already paid.
 // So we manually cancel the HODL invoice here if it wasn't settled by user action
 export async function finalizeHodlInvoice ({ data: { hash }, models, lnd, boss, ...args }) {
+  console.log('finalizeHodlInvoice::', hash)
   const inv = await getInvoice({ id: hash, lnd })
   if (inv.is_confirmed) {
     return
@@ -398,6 +400,8 @@ export async function finalizeHodlInvoice ({ data: { hash }, models, lnd, boss,
     return
   }
 
+  console.log('cancelHodlInvoice::', hash)
+
   await cancelHodlInvoice({ id: hash, lnd })
   // sync LND invoice status with invoice status in database
   await checkInvoice({ data: { hash }, models, lnd, ...args })
@@ -410,8 +414,8 @@ export async function checkPendingDeposits (args) {
     try {
       await checkInvoice({ data: { hash: d.hash }, ...args })
       await sleep(10)
-    } catch {
-      console.error('error checking invoice', d.hash)
+    } catch (err) {
+      console.error('error checking invoice', d.hash, err)
     }
   }
 }

This works for LNbits consistently but for some reason, the invoice is _sometimes_ canceled on the backend when a NWC payment is held for NWC.

This means that Promise.race rejects because paymentPromise rejects before invHeldPromise.
@huumn
Copy link
Member

huumn commented Sep 4, 2024

Is it expiring?

@ekzyis
Copy link
Member Author

ekzyis commented Sep 5, 2024

Is it expiring?

No, it has the normal expiry of 3 minutes and when it is held, we run finalizeHodlInvoice in 60 seconds but the error is thrown before

@huumn
Copy link
Member

huumn commented Sep 5, 2024

I'll try to pull this today and look at it

@huumn
Copy link
Member

huumn commented Sep 19, 2024

I this is caused because --allow-self-payments is not set in lnd and the destination rejects the payment.

Edit: Actually, that might be unrelated.

@ekzyis
Copy link
Member Author

ekzyis commented Sep 27, 2024

I this is caused because --allow-self-payments is not set in lnd and the destination rejects the payment.

Edit: Actually, that might be unrelated.

Yes, unrelated, it should then fail every time and it's not a circular payment since it goes from stacker_lnd to sn_lnd (it is, route is stacker_lnd > sn_lnd > stacker_lnd). It also only happens with NWC (afaict even though it doesn't make sense to me) and not with LNbits but they use the same node.

Does this mean you were able to reproduce the bug? Not necessarily consistently, but it at least also happened on your machine at least once?

@huumn
Copy link
Member

huumn commented Sep 27, 2024

Does this mean you were able to reproduce the bug? Not necessarily consistently, but it at least also happened on your machine at least once?

I was getting that invalid payment details message because I was doing p2p noncustodial zap to the same node. It was exactly as you described - an unexpected cancelation of the invoice.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement improvements to existing features wallets
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants