`listpays` returning status `failed` and then status `complete`

Issue and Steps to Reproduce

Can't reproduce this since it's a very weird and obscure bug that sometimes happens on https://t.me/lntxbot.

I have the following flow for when bot users want to pay invoices to the external world:

Add an entry to the bot database with the outgoing payment with invoice details (payment_hash, amount etc) and pending=true.
Call pay on lightning-rpc with the invoice given by the user.
Listen for sendpay_success and sendpay_failure events through lightningd's plugin interface.
If a sendpay_success comes for the givenpayment_hash, change the database entry topending=false`.
If a sendpay_failure comes for the given payment_hash, do an immediate check on listpays -k payment_hash=... and if the result is failed, delete the payment entry from the database; if it's pending do nothing or if it's complete (won't happen, probably) set it to pending=false as above.
Also whenever a user sends an invoice to be paid we check if there is an entry on the bot database for that same payment_hash, so the user can't have two pending pays with the same hash.

However, something weird is going on and I can't figure out.

Apparently in some very rare cases listpays is returning failed and so the bot database entry is being deleted (this is the log line from the lntxbot server with the full listpays output):

lntxbot 2:09PM DBG payment marked as failed after inspection hash=8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3 listpays="{\"pays\":[{\"bolt11":\"lnbc2140u1ps8exqgpp53w82he7a5j46ret8rla604lry0flqeegr845xu7w5zy52h0nqm3sdqqxqyjw5q9qtzqqqqqq9qsqsp5ufct9a2xqhdhvy98dd789qrecyjhwu3mxsw9lqd08a4c49tgg04srzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcllak86mhak20ucqqqqlgqqqqqeqqjqgkn3p4f6t5jsf68s4stwst5u6l5nnlvvpeq3448zwrrgy0rnqav405sulw97ju7mp8uvuttdae9rtd8klgtp3jqf85hhaff7eu768fqqunhwue\",\"destination\":\"02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6\",\"payment_hash\":\"8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3\",\"status\":\"failed\",\"created_at\":1618834175,\"label\":\"user=36974\",\"amount_sent_msat\":\"0msat\"}]}"

And then some moments later we're getting a sendpay_success, which then matches nothing on the database since the entry was deleted previously.

I don't see how that could ever happen since I'm checking the database before issuing a pay, right? So I'm considering that this may be a failure with the listpays output or pay is trying to pay again even after returning failed.

So one issue I see with that specific payment that triggered the error is that in its listpays item it doesn't have a bolt11:

2021-04-19-123921_903x715_scrot

Here is the full output for listsendpays -k payment_hash=8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3:

{
   "payments": [
      {
         "id": 113291,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 2,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 138007080,
         "amount_msat": "138007080msat",
         "msatoshi_sent": 138023018,
         "amount_sent_msat": "138023018msat",
         "created_at": 1618834175,
         "status": "failed",
         "label": "user=36974",
         "bolt11": "lnbc2140u1ps8exqgpp53w82he7a5j46ret8rla604lry0flqeegr845xu7w5zy52h0nqm3sdqqxqyjw5q9qtzqqqqqq9qsqsp5ufct9a2xqhdhvy98dd789qrecyjhwu3mxsw9lqd08a4c49tgg04srzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcllak86mhak20ucqqqqlgqqqqqeqqjqgkn3p4f6t5jsf68s4stwst5u6l5nnlvvpeq3448zwrrgy0rnqav405sulw97ju7mp8uvuttdae9rtd8klgtp3jqf85hhaff7eu768fqqunhwue"
      },
      {
         "id": 113292,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 3,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 75992920,
         "amount_msat": "75992920msat",
         "msatoshi_sent": 76002595,
         "amount_sent_msat": "76002595msat",
         "created_at": 1618834178,
         "status": "failed",
         "label": "user=36974",
         "bolt11": "lnbc2140u1ps8exqgpp53w82he7a5j46ret8rla604lry0flqeegr845xu7w5zy52h0nqm3sdqqxqyjw5q9qtzqqqqqq9qsqsp5ufct9a2xqhdhvy98dd789qrecyjhwu3mxsw9lqd08a4c49tgg04srzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcllak86mhak20ucqqqqlgqqqqqeqqjqgkn3p4f6t5jsf68s4stwst5u6l5nnlvvpeq3448zwrrgy0rnqav405sulw97ju7mp8uvuttdae9rtd8klgtp3jqf85hhaff7eu768fqqunhwue"
      },
      {
         "id": 113293,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 4,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 138007080,
         "amount_msat": "138007080msat",
         "msatoshi_sent": 138025398,
         "amount_sent_msat": "138025398msat",
         "created_at": 1618834181,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113295,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 5,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 138007080,
         "amount_msat": "138007080msat",
         "msatoshi_sent": 138023317,
         "amount_sent_msat": "138023317msat",
         "created_at": 1618834182,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113294,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 6,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 75992920,
         "amount_msat": "75992920msat",
         "msatoshi_sent": 76004355,
         "amount_sent_msat": "76004355msat",
         "created_at": 1618834182,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113296,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 7,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 75992920,
         "amount_msat": "75992920msat",
         "msatoshi_sent": 76002894,
         "amount_sent_msat": "76002894msat",
         "created_at": 1618834182,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113297,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 8,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 138007080,
         "amount_msat": "138007080msat",
         "msatoshi_sent": 138023018,
         "amount_sent_msat": "138023018msat",
         "created_at": 1618834183,
         "status": "complete",
         "payment_preimage": "2b044d8a80b4b2e722ff5e95d4fb35335dbb597e3b826fca15a38735af3247ce",
         "label": "user=36974"
      },
      {
         "id": 113298,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 9,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 75992920,
         "amount_msat": "75992920msat",
         "msatoshi_sent": 76002595,
         "amount_sent_msat": "76002595msat",
         "created_at": 1618834183,
         "status": "complete",
         "payment_preimage": "2b044d8a80b4b2e722ff5e95d4fb35335dbb597e3b826fca15a38735af3247ce",
         "label": "user=36974"
      },
      {
         "id": 113193,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 10,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157382344,
         "amount_sent_msat": "157382344msat",
         "created_at": 1618795998,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113194,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 11,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157382344,
         "amount_sent_msat": "157382344msat",
         "created_at": 1618795999,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113195,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 12,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157383501,
         "amount_sent_msat": "157383501msat",
         "created_at": 1618796001,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113196,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 13,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157384917,
         "amount_sent_msat": "157384917msat",
         "created_at": 1618796003,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113197,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 14,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157383501,
         "amount_sent_msat": "157383501msat",
         "created_at": 1618796004,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113198,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 15,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157383501,
         "amount_sent_msat": "157383501msat",
         "created_at": 1618796006,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113199,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 16,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 157364451,
         "amount_msat": "157364451msat",
         "msatoshi_sent": 157383501,
         "amount_sent_msat": "157383501msat",
         "created_at": 1618796008,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113201,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 17,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 82763918,
         "amount_msat": "82763918msat",
         "msatoshi_sent": 82774276,
         "amount_sent_msat": "82774276msat",
         "created_at": 1618796010,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113200,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 18,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 74600533,
         "amount_msat": "74600533msat",
         "msatoshi_sent": 74610067,
         "amount_sent_msat": "74610067msat",
         "created_at": 1618796010,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113202,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 19,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 82763918,
         "amount_msat": "82763918msat",
         "msatoshi_sent": 82774276,
         "amount_sent_msat": "82774276msat",
         "created_at": 1618796012,
         "status": "failed",
         "label": "user=36974"
      },
      {
         "id": 113203,
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "partid": 20,
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "msatoshi": 74600533,
         "amount_msat": "74600533msat",
         "msatoshi_sent": 74610067,
         "amount_sent_msat": "74610067msat",
         "created_at": 1618796012,
         "status": "failed",
         "label": "user=36974"
      }
   ]
}

Can you spot something?

`getinfo` output

{
   "id": "02c16cca44562b590dd279c942200bdccfd4f990c3a69fad620c10ef2f8228eaff",
   "alias": "@lntxbot",
   "color": "296683",
   "num_peers": 37,
   "num_pending_channels": 2,
   "num_active_channels": 22,
   "num_inactive_channels": 2,
   "address": [
      {
         "type": "ipv4",
         "address": "5.2.67.89",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "v0.9.3-107-ga020602",
   "blockheight": 679798,
   "network": "bitcoin",
   "msatoshi_fees_collected": 32991436,
   "fees_collected_msat": "32991436msat",
   "lightning-dir": "/home/fiatjaf/.lightning1/bitcoin"
}

First a bit of context for anyone who stumbles across this. There are two levels of RPC involved her:

sendpay is a single attempt to deliver a payment over a specified route, of a specific value. It can fail for a variety of reasons and is not necessarily associated with an invoice or an overarching pay process (see next item).
pay is the overarching payment process, basically saying here's an invoice, do whatever it takes to pay it. This payment process involves computing routes, handling special data such as routehints, firing off sendpay commands and handling their success or failure to drive the overall process forwards.

They are also listed separately, listsendpays shows individual sendpay attempts, while listpays takes the individual attempts and merges them back into information about the pay. pay calls are also not stored as such in the database, rather we aggregate the information from the stored sendpay commands.

Back on topic: why don't all listsendpay entries have a bolt11 associated. There are two reasons for this: a) not all sendpay calls were initiated by a call to pay, and b) in order to keep redundant information stored in the DB, and therefore bloat, small we annotate only the root sendpay command with the bolt11 since all other sendpay invocations are part of the same tree of attempts.

As an example of (a) the sendpay calls done by the rebalance plugin which initiates sendpay on circular routes to rebalance. These are not associated with an invoice, hence the missing annotation.

To your specific point: always use listpays to determine if a payment is still ongoing, there might be a bit of quiescent time on listsendpays while we recompute the routes and prepare for the next sendpay (likely for the last few parts of a payment). I am also working on plugin notifications #4492, which will allow the pay plugin to send notifications when it finishes a pay process, so you can then subscribe to that instead. Some reconciliation might still be required when lightningd restarts while a pay process is in progress (this will not be resumed to avoid double paying), but that's a far smaller number of cases.

By the way, I think you might have stumbled over the pay command aborted by a restart since you explicitly say you were using listpays, but only provide a listsendpays output.

I didn't provide the output of listpays because it would be very uninteresting and useless I imagined, but here is it:

~> lightning-cli listpays -k payment_hash=8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3
{
   "pays": [
      {
         "bolt11": "lnbc2140u1ps8exqgpp53w82he7a5j46ret8rla604lry0flqeegr845xu7w5zy52h0nqm3sdqqxqyjw5q9qtzqqqqqq9qsqsp5ufct9a2xqhdhvy98dd789qrecyjhwu3mxsw9lqd08a4c49tgg04srzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcllak86mhak20ucqqqqlgqqqqqeqqjqgkn3p4f6t5jsf68s4stwst5u6l5nnlvvpeq3448zwrrgy0rnqav405sulw97ju7mp8uvuttdae9rtd8klgtp3jqf85hhaff7eu768fqqunhwue",
         "destination": "02fa5a222c70a78660f7b7402635897d0e55de7036ad3c55d4bab63eb77ed94fe6",
         "payment_hash": "8b8eabe7dda4aba1e5671ffba7d7e323d3f0672819eb4373cea089455df306e3",
         "status": "complete",
         "created_at": 1618834175,
         "label": "user=36974",
         "preimage": "2b044d8a80b4b2e722ff5e95d4fb35335dbb597e3b826fca15a38735af3247ce",
         "amount_msat": "214000000msat",
         "amount_sent_msat": "214025613msat",
         "number_of_parts": 2
      }
   ]
}

It does have a bolt11 entry on it, though, so I think this ticket's title is wrong.

The problem here is identifying how can I possibly be getting a failed status from listpays and then a complete later. Or if someone had any idea of some mistake I might have done when implementing these checks on my side.

I don't understand how can a restart may have caused this. If there was a restart then listpays would have returned the correct thing anyway (at least that was my understanding last time I tried to read the code for the pay plugin).

Could it be some race condition that causes listpays to return failed and then start attempting a new payment again?

Or maybe it is something related to MPP. pay sends 10 shards. 1 fails, so it assumes the others will fail too as 10 are needed for the amount to be complete and returns failed. But the other 9 shards are still in-flight and eventually one of them succeeds (due to a bug on the receiving node, which I have seen happen with Phoenix some days ago but the ACINQ people didn't believe me) so it changes to complete?

Just coming up with hypotheses.

This just happened again, with an amountless invoice from Muun Wallet.

The user said he was trying to send 99000 satoshis frm lntxbot to Muun, but the payments were failing. So he tried just 9000 and it worked.

# listsendpays:

{
   "payments": [
      {
         "id": 123316,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029029,
         "amount_sent_msat": "9029029msat",
         "created_at": 1620270424,
         "status": "failed",
         "label": "user=272865",
         "bolt11": "lnbc1psfxh8hpp5jestgerkwz549we3h9a4pdh979gvrm9cc28ug45ye4nztv9hdscqdqqcqzzgxqrrssrzjqw8c7yfutqqy3kz8662fxutjvef7q2ujsxtt45csu0k688lkzu3ldwm5ydvusmdgcyqqqqryqqqqhwqqpysp50rcdznqt0ya65gsjne4z3ekqpfng7xmfvcnkqeg2zkpaue8zy4sq9qypqsqyhe74zg8lwjkxs8pg0qxfsxe3pfekkzfuh3c3hqggrplq4vzlyaxk04p7czlk36nnxmtyfyjg2s0hmqsc8ynmwnk9222ccv3fu3ntqsqehxcfl"
      },
      {
         "id": 123317,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 1,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029118,
         "amount_sent_msat": "9029118msat",
         "created_at": 1620270430,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123318,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 2,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9030011,
         "amount_sent_msat": "9030011msat",
         "created_at": 1620270431,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123319,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 3,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029779,
         "amount_sent_msat": "9029779msat",
         "created_at": 1620270433,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123320,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 4,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029058,
         "amount_sent_msat": "9029058msat",
         "created_at": 1620270436,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123321,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 5,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029118,
         "amount_sent_msat": "9029118msat",
         "created_at": 1620270437,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123322,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 6,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029119,
         "amount_sent_msat": "9029119msat",
         "created_at": 1620270438,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123323,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 7,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029119,
         "amount_sent_msat": "9029119msat",
         "created_at": 1620270439,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123324,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 8,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029137,
         "amount_sent_msat": "9029137msat",
         "created_at": 1620270440,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123325,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 9,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029137,
         "amount_sent_msat": "9029137msat",
         "created_at": 1620270441,
         "status": "failed",
         "label": "user=272865"
      },
      {
         "id": 123326,
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "partid": 10,
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "msatoshi": 9000000,
         "amount_msat": "9000000msat",
         "msatoshi_sent": 9029238,
         "amount_sent_msat": "9029238msat",
         "created_at": 1620270442,
         "status": "complete",
         "payment_preimage": "b582c07592b760891cbe99ab4aeaead93b3fbeddb9a73cfb6293d29e0bc9a3c6",
         "label": "user=272865"
      }
   ]
}

The sum of all payment attempts above is 99000 satoshis. However only the last one succeeded, but it was initiated from a new call to pay.

That makes me think the plugin is somehow mixing the two different pay attempts. The first attempt was reported as failed, but still had shards in-flight. Then the second attempt was started, status moved to pending, then all of the shards from the first attempt failed, the status changed to failed, just after that the second attempt succeeded, the status changed to complete.

That's my best guess so far. Just leaving it written here.

# listpays

{
   "pays": [
      {
         "bolt11": "lnbc1psfxh8hpp5jestgerkwz549we3h9a4pdh979gvrm9cc28ug45ye4nztv9hdscqdqqcqzzgxqrrssrzjqw8c7yfutqqy3kz8662fxutjvef7q2ujsxtt45csu0k688lkzu3ldwm5ydvusmdgcyqqqqryqqqqhwqqpysp50rcdznqt0ya65gsjne4z3ekqpfng7xmfvcnkqeg2zkpaue8zy4sq9qypqsqyhe74zg8lwjkxs8pg0qxfsxe3pfekkzfuh3c3hqggrplq4vzlyaxk04p7czlk36nnxmtyfyjg2s0hmqsc8ynmwnk9222ccv3fu3ntqsqehxcfl",
         "destination": "02287d16a6bef584486be78a02e95eb7c82d7405b3128dbb658663516ce0207cab",
         "payment_hash": "9660b4647670a952bb31b97b50b6e5f150c1ecb8c28fc45684cd6625b0b76c30",
         "status": "complete",
         "created_at": 1620270424,
         "label": "user=272865",
         "preimage": "b582c07592b760891cbe99ab4aeaead93b3fbeddb9a73cfb6293d29e0bc9a3c6",
         "amount_msat": "9000000msat",
         "amount_sent_msat": "9029238msat"
      }
   ]
}

It happened again now. This time the user told me attempted to pay again just one second after receiving the error message for the first attempt, which contributes to my previous hypothesis above.

{
   "payments": [
      {
         "id": 125050,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 2,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 10484000,
         "amount_msat": "10484000msat",
         "msatoshi_sent": 10486503,
         "amount_sent_msat": "10486503msat",
         "created_at": 1620418409,
         "status": "failed",
         "label": "user=326537",
         "bolt11": "lnbc104840n1psft8h7pp59gufxwxp6sasxn3ryc57mga95uz90ds6ct7tc053lln3mzezuzvsdqqxqyjw5q9qtzqqqqqq9qsqsp55pay2nhn6lpgyett8cm4e8m3erphhr5lfs983z3r5p69vpqdphhsrzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glclle0gcwtewqa8sqqqqlgqqqqqeqqjqnyendkcjmvjj3k86f7ulgcfr05854dps7a982xjsugfga6jdt9rxyypj5m7gpjrneqd59c4zr4e6c2hmefe3j8vyemlzgdyxvzyermqp053u87"
      },
      {
         "id": 125051,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 3,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 10484000,
         "amount_msat": "10484000msat",
         "msatoshi_sent": 10487058,
         "amount_sent_msat": "10487058msat",
         "created_at": 1620418410,
         "status": "complete",
         "payment_preimage": "4a9aa3ede94466f99b6fe18b7692d90c170d2883e42aa1b076f676c6cdf1d692",
         "label": "user=326537"
      },
      {
         "id": 125022,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 4,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 8786359,
         "amount_msat": "8786359msat",
         "msatoshi_sent": 8788537,
         "amount_sent_msat": "8788537msat",
         "created_at": 1620418316,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125023,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 5,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698975,
         "amount_sent_msat": "1698975msat",
         "created_at": 1620418317,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125024,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 6,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 8786359,
         "amount_msat": "8786359msat",
         "msatoshi_sent": 8789245,
         "amount_sent_msat": "8789245msat",
         "created_at": 1620418317,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125025,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 7,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698907,
         "amount_sent_msat": "1698907msat",
         "created_at": 1620418318,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125026,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 8,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698930,
         "amount_sent_msat": "1698930msat",
         "created_at": 1620418319,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125027,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 9,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698930,
         "amount_sent_msat": "1698930msat",
         "created_at": 1620418320,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125028,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 10,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698930,
         "amount_sent_msat": "1698930msat",
         "created_at": 1620418320,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125029,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 11,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698939,
         "amount_sent_msat": "1698939msat",
         "created_at": 1620418321,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125030,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 12,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698958,
         "amount_sent_msat": "1698958msat",
         "created_at": 1620418322,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125031,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 13,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698949,
         "amount_sent_msat": "1698949msat",
         "created_at": 1620418323,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125032,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 14,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698975,
         "amount_sent_msat": "1698975msat",
         "created_at": 1620418324,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125033,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 15,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 1697641,
         "amount_msat": "1697641msat",
         "msatoshi_sent": 1698865,
         "amount_sent_msat": "1698865msat",
         "created_at": 1620418325,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125034,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 16,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915430,
         "amount_sent_msat": "915430msat",
         "created_at": 1620418326,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125035,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 17,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784481,
         "amount_sent_msat": "784481msat",
         "created_at": 1620418326,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125036,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 18,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915451,
         "amount_sent_msat": "915451msat",
         "created_at": 1620418327,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125037,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 19,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784481,
         "amount_sent_msat": "784481msat",
         "created_at": 1620418327,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125038,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 20,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915459,
         "amount_sent_msat": "915459msat",
         "created_at": 1620418328,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125039,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 21,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784490,
         "amount_sent_msat": "784490msat",
         "created_at": 1620418328,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125040,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 22,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915474,
         "amount_sent_msat": "915474msat",
         "created_at": 1620418329,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125041,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 23,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784500,
         "amount_sent_msat": "784500msat",
         "created_at": 1620418330,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125042,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 24,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915529,
         "amount_sent_msat": "915529msat",
         "created_at": 1620418331,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125043,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 25,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784453,
         "amount_sent_msat": "784453msat",
         "created_at": 1620418331,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125044,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 26,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915487,
         "amount_sent_msat": "915487msat",
         "created_at": 1620418332,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125045,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 27,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784506,
         "amount_sent_msat": "784506msat",
         "created_at": 1620418332,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125046,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 28,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915481,
         "amount_sent_msat": "915481msat",
         "created_at": 1620418333,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125047,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 29,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784503,
         "amount_sent_msat": "784503msat",
         "created_at": 1620418333,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125048,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 30,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 914299,
         "amount_msat": "914299msat",
         "msatoshi_sent": 915529,
         "amount_sent_msat": "915529msat",
         "created_at": 1620418334,
         "status": "failed",
         "label": "user=326537"
      },
      {
         "id": 125049,
         "payment_hash": "2a389338c1d43b034e232629eda3a5a70457b61ac2fcbc3e91ffe71d8b22e099",
         "partid": 31,
         "destination": "02e6f48d50c016ec064c011655e1479ef44b1c029b3aeb32539e2f461cbcb81d3c",
         "msatoshi": 783342,
         "amount_msat": "783342msat",
         "msatoshi_sent": 784485,
         "amount_sent_msat": "784485msat",
         "created_at": 1620418335,
         "status": "failed",
         "label": "user=326537"
      }
   ]
}

I think you're right, the aggregation code in listpays only takes the hash into consideration and we don't have a good grouping key to differentiate what initiated the sendpay we store in the database. The obvious solution would be to add a grouping key such as sendpaygroup that is constant across all sendpays that were initiated by the same pay. This would also future-proof the pay command for when PTLCs become an option, in which case the payment_hash is no longer constant for a payment.

I wonder at what point we might have to add a free-form metadata field to things in the DB in order to handle these things, but for now the sendpaygroup key seems sufficient.

I opened #4525 to hammer out the details for a metadata table that'd be really useful in this case. Maybe it's better to get that working instead of making a one-off fix for this since we'd have to wire things through the sendpay command anyway. What do you think? Would that be useful for your lntxbot as well?

Not useful for lntxbot directly, but I like the idea. I actually implemented it inside lntxbot as well, having a blob field for custom plugins (in this case all the plugins were written by me anyway, but still the same approach) and on LNbits I implemented a similar thing: each extension can inject arbitrary metadata on each payment/invoice it creates.

Plugin notifications would probably be the best solution for this specific issue, though (as long as pay emit the correct values, which might depend on the existence of the metadata table?).

Does this mean payment statuses will never be failed then complete again? Or did this involve some bigger change in the API? Are there new notification events or have the behavior of notifications changed?

Does this mean payment statuses will never be failed then complete again? Or did this involve some bigger change in the API? Are there new notification events or have the behavior of notifications changed?

That is indeed the effect, with one caveat: we now have multiple entries in listpays with the same payment_hash (one for each time pay [bolt11] was called). So you'll have to use the tuple (payment_hash, groupid) to identify which result is meant. Once that's done then each payment will only ever move through the state-machine monotonically:

pending -> complete
pending -> failed

Thus the flaky behavior pending -> failed -> pending -> complete you observed will not happen anymore :+1:

ElementsProject / lightning