Is amount added to fee when compared to fee budget in keysend?

[hMsats]

keysend basically stopped working for me (c-lightning: v0.10.2). It looks like the amount sent is added to the routing fee and then checked against the maximum routing fee.

lightning-cli keysend 03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df 600000
{
   "code": 210,
   "message": "Ran out of routes to try after 1 attempt: see `paystatus`",
   "attempts": [
      {
         "status": "failed",
         "failreason": "Fee exceeds our fee budget: 603452msat > 5000msat, discarding route",
         "partid": 0,
         "amount": "600000msat"
      }
   ]
}

lightning-cli keysend 03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df 700000
{
   "code": 210,
   "message": "Ran out of routes to try after 1 attempt: see `paystatus`",
   "attempts": [
      {
         "status": "failed",
         "failreason": "Fee exceeds our fee budget: 703526msat > 5000msat, discarding route",
         "partid": 0,
         "amount": "700000msat"
      }
   ]
}

[cdecker]

This is very strange, given that we reuse the same exact fee budgeting code in the pay plugin as well. I'm thinking this might either be a display issue (using the wrong number in the error message), an unrelated log line from the exempt fee paymod (unlikely since that'd not be fatal) or a node along the route charging an exorbitant fee.

Can you share the endpoint node IDs, so we can check for the latter case?

[cdecker]

The lines in question are the following:

lightning/plugins/libplugin-pay.c

Line 852 in 5a5cf8c

if (amount_msat_greater(fee, p->constraints.fee_budget)) {

The fee is computed in the line above, based on the selected path, making a mixup of fee and amount unlikely. I wonder why the payment is aborted at this point, since a path exceeding it's fee budget would fail the attempt, but shouldn't fail the overall payment process (that'd usually run into a "No route found" after excluding all previous attempts). Could it really be that someone on the network is asking for 100% routing fee? 🤔

[hMsats]

@cdecker I don't know what you mean by "endpoint node IDs" but I tried the last payment again with the same result and added paystatus. Hopefully that's enough:

lightning-cli keysend 03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df 700000
{
   "code": 210,
   "message": "Ran out of routes to try after 1 attempt: see `paystatus`",
   "attempts": [
      {
         "status": "failed",
         "failreason": "Fee exceeds our fee budget: 703526msat > 5000msat, discarding route",
         "partid": 0,
         "amount": "700000msat"
      }
   ]
}
lightning-cli paystatus
{
   "pay": [
      {
         "bolt11": "lnbc14u1pscjyf0pp5rqszdv5yf9665yk9q9flkrzy8lfkvuqce2pdlswzew6ntj3v6gtqdqqxqyjw5q9qtzqqqqqq9qsqsp5gthu0n0drwm2xjyvl2uy3y7gzuq3lmwzjr8m65r6jqa7sv7rrrvqrzjqwryaup9lh50kkranzgcdnn2fgvx390wgj5jd07rwr3vxeje0glcll6uxf2839lrjcqqqqlgqqqqqeqqjqa6qhtusscs6tkg64aacvgv5qsxla4q9guxzdn4j72yu0sewfyve4t9uu7flunu83wz674z36evaksnklge49hgek4nkqjdakgmg8xqqq3gmta4",
         "amount_msat": "1400000msat",
         "amount_msat": "1400000msat",
         "destination": "020da2764a3ff36f2ac4b090f29f5d5e3c39c4e0e86e0bec00da5c32547897e396",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-09T13:45:35.774Z",
               "age_in_seconds": 2000712,
               "end_time": "2021-11-09T13:45:51.870Z",
               "state": "completed",
               "success": {
                  "id": 1063,
                  "payment_preimage": "fc1a66e9dae4bb8930b77f8610009baadb0dac1348c5da2545cb6f887cef7e0f"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc17780n1psezgs4pp5n5hkhy36eztphpfnd2e6a0v2f59g3v45rde5m6w9nv8k9l64j7vsdqqcqzzgxqrrssrzjqw8c7yfutqqy3kz8662fxutjvef7q2ujsxtt45csu0k688lkzu3ldwglq30acv7kzvqqqqryqqqqthqqpysp5hplj9u09a998zsg0uqfd5ghy6l94mm4yn840g0q43aurlg9we4xq9qypqsqxqhvmwwk5g5e0dw5etnf8t0rupcpauwa3zw7ejrg6gtrzthvvxthzlcd62gf0766lgcpa7ntca9srp88gf259fttg2zu5gh5kq8cylsqg3wdhc",
         "amount_msat": "1778000msat",
         "amount_msat": "1778000msat",
         "destination": "02ac6d5f86fe6b8b67bd660a3ee8e469c2fcd2dcf3bd44e9766e545fb283f6c71f",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-14T14:51:02.845Z",
               "age_in_seconds": 1564786,
               "end_time": "2021-11-14T14:51:25.414Z",
               "state": "completed",
               "success": {
                  "id": 1064,
                  "payment_preimage": "e52fb202ac3dc3177d23b87b68414172401c39db20c91041aae2c72f6f183123"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc177820n1psezfqupp5yzffams5c9fe2ttzfclf72xw2cvsnf6ajw75drymd55djhmtyj0sdqqcqzzgxqrrssrzjqw8c7yfutqqy3kz8662fxutjvef7q2ujsxtt45csu0k688lkzu3ldrnxfar2lv86m5qqqqryqqqqthqqpysp53p939uukcz3ce7n05ckry5kljy008pell33au46qakv0g8lykqes9qypqsq8npy0dvc53w9ks8nvk6yt28q0hjfehd7uqpc85c5hu8adfl0y3l4xqyygxpv6ce4sgvauja2vlm68f2l3t539y3xq7kqm60d5pw8vqsp7alsa8",
         "amount_msat": "17782000msat",
         "amount_msat": "17782000msat",
         "destination": "03fa7c6e7cd0e423cc229323c930ced58932d91227e936647e583d37cbb9ea6131",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-14T14:58:52.042Z",
               "age_in_seconds": 1564317,
               "end_time": "2021-11-14T14:59:02.461Z",
               "state": "completed",
               "success": {
                  "id": 1065,
                  "payment_preimage": "2b10541d01c4a81fc62ea171895f0b92bd722680247c37458c58190a27299392"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc16u1pseyu4tpp5hhg0j94g4mympz0yge2v5uza0dr7quahz2vtfne427akkkxnr6tsdqcgfz9ggrfdemx76trv5srgwp5xqy9gcqcqpjsp54hsd60sruc99jytm92e0uuz6ycaz6zsw8c8pknr209lr786zgv6qrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssqzd67rmf3y0pt9pccgfhd9f66y9fxjynrpru689tq0wc087pwr0a8rykkhhqj5ypyxmqd85fj3r75azjd9wfwthphqlrv7cvlfz8hu9qqtksaxe",
         "amount_msat": "1600000msat",
         "amount_msat": "1600000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-16T14:42:03.271Z",
               "age_in_seconds": 1392526,
               "end_time": "2021-11-16T14:42:05.395Z",
               "state": "completed",
               "success": {
                  "id": 1073,
                  "payment_preimage": "957718bb4c1920a182e25fb23b7781dab22bceb4c6a728a376c08b07569d611c"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc24u1psegqr0pp5fuagfmrecl27mnf6k3uqf00l05czam4pvjt4cys8vcc9w4hpsh7sdqcgfz9ggrfdemx76trv5srgwp4xqy9gcqcqpjsp5xyuf4p5p9qdcdftmvsey0x3cc3yk023r4xpdyd7ky9lmm97dkelqrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssq3q282n4ma32aqf7nq6rfx0g8jvwzmerrnd9vtsl99twpz728eh9hm3pamdnxnpr99dn5e9zd80cj2qagqya00jw4d6lfh0yc52uczesp4jyhn5",
         "amount_msat": "2400000msat",
         "amount_msat": "2400000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-17T19:03:02.668Z",
               "age_in_seconds": 1290466,
               "end_time": "2021-11-17T19:03:05.401Z",
               "state": "completed",
               "success": {
                  "id": 1074,
                  "payment_preimage": "6d128c2f5e78fa509bba4e8bdc5ddc2d7d0d83ba8707bb8285395b458d9c92de"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc25u1psesz9hpp5rrrm4029a35h88f2apcjjqleqxp6t76v37vnhszt2eq7smj0099sdqcgfz9ggrfdemx76trv5srgwpkxqy9gcqcqpjsp58ezxgknx6a66nujxar5d026pfkp87s44vr9slvqamey49sul3hkqrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssq944l5feup7t8pqrpxn3vevahqj2tvkt4383m3zycd6u6k0438663ed6u7ptnwurefg6lmucyqj7zxr53uwacnutvvm6p3m5mawl8dggp5ktpru",
         "amount_msat": "2500000msat",
         "amount_msat": "2500000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-20T20:27:04.162Z",
               "age_in_seconds": 1026225,
               "end_time": "2021-11-20T20:27:12.596Z",
               "state": "completed",
               "success": {
                  "id": 1075,
                  "payment_preimage": "a94a444946febbb4c6d58f0663332314b29643786a9a82fd43155caef93a0f12"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc35u1ps6yqc0pp5gyrurzhfhyx88u8zra3n6xs90y39xe66q9xyywkvy7l5paxdayxqdqcgfz9ggrfdemx76trv5srgwfsxqy9gcqcqpjsp5ku7rvhj2rzjpjwcg0sxwdta6rj9kcmy3u0tj3we7tzrnf2v55j2qrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssq0h8t0wqg8tf6du4swl3hagjcsap8ay6u5aacnpz9qsuvffcaj4982zwqh9ng246sye2zpwn92mjhlv6rcn7gkd8lneux4at3hkrnwqqqvf2t3c",
         "amount_msat": "3500000msat",
         "amount_msat": "3500000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-28T10:06:03.729Z",
               "age_in_seconds": 372285,
               "end_time": "2021-11-28T10:06:11.295Z",
               "state": "completed",
               "success": {
                  "id": 1078,
                  "payment_preimage": "b82b12021cc6b8bee241c55b4ba779af3bfd69e2450febbda5f1e08b7fa763e2"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc60u1ps6xhuepp5tvuy09a7033fu3rh8nudsr69ws9m464jm25xq3k5q4zdhw839dwqdqcgfz9ggrfdemx76trv5srgwf3xqy9gcqcqpjsp53rkyeufuqk7gr6xctce0r72mkfdat5esdj0kpw23auelzy890ftqrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssqpu28xycktl0xzha4jynlg9m5rc4rws7dmy5frq4w77rtcvvmjsmn6ukwj5dhwhp00l3s7h68cpny2udj4wgl4tn56yrc24sq9ffmdfgqmkkd59",
         "amount_msat": "6000000msat",
         "amount_msat": "6000000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-11-29T10:51:03.418Z",
               "age_in_seconds": 283186,
               "end_time": "2021-11-29T10:51:07.580Z",
               "state": "completed",
               "success": {
                  "id": 1119,
                  "payment_preimage": "d19540a78137cd41c7fe65438988817f24e2694824e21c00823e4d9087a0ed2d"
               }
            }
         ]
      },
      {
         "bolt11": "lnbc15u1ps6drk9pp5yle9c00l5m395na2n9guw55z7df3kfjymxrrf2wl6v6g6q4mtfgsdqcgfz9ggrfdemx76trv5srgwfnxqy9gcqcqpjsp5gm4frdn9wz2zhaxs9lav2a9ge6wpafpzyjn53m2xyunah9l4nqjsrzjq2ygy3qzn3vsjkfs8z43nunfj378yr0rgglyj9u3k3k8eyhhvfumvzt32uqqjgcqqqqqqqqpqqqqqqgqyg9qyyssq2j9ejefwrvs4ctlgrz9v23csjx9dwp99tcq4guj6aellq4lluwnjwe2sp373fdcca737pe7l6magsev6uuusj3jlupftjxt57nzykpgq6fsz8z",
         "amount_msat": "1500000msat",
         "amount_msat": "1500000msat",
         "destination": "02aecde3b3dde450889755d4dbce538e6b9e9dfa7702d14b5bc5c4379e1b330392",
         "attempts": [
            {
               "strategy": "Initial attempt",
               "start_time": "2021-12-01T20:51:05.200Z",
               "age_in_seconds": 74384,
               "end_time": "2021-12-01T20:51:11.142Z",
               "state": "completed",
               "success": {
                  "id": 1140,
                  "payment_preimage": "0321b0300aebce7b10bc8aec9345816f1abce6cb1081104a149529e375b112d1"
               }
            }
         ]
      }
   ]
}

[hMsats]

I just retried lightning-cli keysend 03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df 700000 and this time it worked just fine. Yesterday I restarted my server but changed nothing. A second equal payment also went fine. I will retry next week.

But this one failed, not with with the amount, but it looks familiar:

lightning-cli keysend 021f7430cce1b1ec01675bd575c0785ee2150d1d3167588b7e52a8050d2df2d28e 700000
{
   "code": 210,
   "message": "Ran out of routes to try after 1 attempt: see `paystatus`",
   "attempts": [
      {
         "status": "failed",
         "failreason": "Fee exceeds our fee budget: 21896msat > 5000msat, discarding route",
         "partid": 0,
         "amount": "700000msat"
      }
   ]
}
lightning-cli paystatus 
{
   "pay": []
}

This one also was fine (it wasn't the last time I tried) lightning-cli keysend 02968717f9c0d5ee223b2d0d250c7a54be4602b27d0994f098b8ef76bc85d497ce 700000

[cdecker]

So the flakiness of the results suggests to me that it is indeed due to the routes varying wildly. The 100%+ fees seem to me to be indeed due to a misconfigured routing node in your vicinity, and since it's the last route available it gets excluded and any subsequent attempt fails to find a route (which is correct, the only way to send anyway would be to actually pay the 100%+ fees).

[hMsats]

@cdecker By debugging the software with a lot of print statements, I was able to solve the above problems in the C code.
I don't think it's a general solution but it's a solution for the above problem. My advantage was that I could reproduce the problem, my disadvantage is that I'm not a lightning expert.

Before the fix:

lightning-cli keysend 02854fa7f2babfe819c8f715c8fee50a15762236823328f61207519ec6e5e09fb5 600000
{
   "code": 210,
   "message": "Ran out of routes to try after 1 attempt: see `paystatus`",
   "attempts": [
      {
         "status": "failed",
         "failreason": "Fee exceeds our fee budget: 5809msat > 5000msat, discarding route",
         "partid": 0,
         "amount": "600000msat"
      }
   ]
}

After the fix:

lightning-cli keysend 02854fa7f2babfe819c8f715c8fee50a15762236823328f61207519ec6e5e09fb5 600000
{
   "destination": "02854fa7f2babfe819c8f715c8fee50a15762236823328f61207519ec6e5e09fb5",
   "payment_hash": "be6fc71d1d4632b0e93e4c59be11db9494c530c34c56fc0c7b59da206dae8957",
   "created_at": 1641588482.400,
   "parts": 1,
   "msatoshi": 600000,
   "amount_msat": "600000msat",
   "msatoshi_sent": 604615,
   "amount_sent_msat": "604615msat",
   "payment_preimage": "4a1df2709cd1d4f3598a840a58896029966eff28eb284d88a53615e5651d170d",
   "status": "complete"
}

This is what happens:

After it's detected in payment_getroute(struct payment *p) that the fee exceeds the fee budget, payment_fail is called in libplugin-pay.c. In payment_fail, p->step is set to PAYMENT_STEP_FAILED. After that payment_continue(p) is called a great number of times where mod != NULL (this made it seem like payments continued while in reality it wasn't). This goes on until mod = NULL. After that payment_continue(p) executes the switch switch (p->step) with step = 32 = case PAYMENT_STEP_FAILED but this statement calls payment_finished(p) and that finishes the complete payment. By placing case PAYMENT_STEP_FAILED: above case PAYMENT_STEP_RETRY_GETROUTE: my problem was solved!

Now I understand that this might cause other problems but I think this is enough to solve the problem more in general. I get the impression that there should be a PAYMENT_STEP_FAILED and a PAYMENT_FAILED or a payment_fail() and a payment_step_fail().

BTW the next payment_fail in payment_getroute(struct payment *p) also stops the payment completely.

[cdecker]

Very interesting, would you mind sharing the diff for me to check and maybe toll into the libplugin-pay? I'm a bit confused as to how aborting earlier can result in a successful payment after all, maybe the code can help my understanding.

Generally speaking we differentiate between payment attempts (individual htlcs or retried ones) and the overall payment process (sum of all htlcs we send out). The payment_step functions usually refer to individual htlcs, and failing them will result in the getting split or retried. Aborting the overall payment process cannot possibly end up with a successful payment, hence my confusion

[hMsats]

In the meantime, I made the hack a little more intelligent than I said above. I made a copy of payment_fail() and called it payment_fail2(). The only thing I changed in payment_fail2() is PAYMENT_STEP_FAILED -> PAYMENT_STEP_RETRY_GETROUTE. Where the fee is compared to the fee budget payment_fail2() is called instead of payment_fail() in case of failure (around the comment /* Ensure that our fee and CLTV budgets are respected. */).

Here's the diff:
~/lightning_test/plugins/libplugin-pay.c is the original libplugin-pay.c

BN [2003] diff libplugin-pay.c ~/lightning_test/plugins/libplugin-pay.c
855c855
< 		payment_fail2(
---
> 		payment_fail(
1486d1485
< 
2150,2163d2148
< 	va_start(ap, fmt);
< 	p->failreason = tal_vfmt(p, fmt, ap);
< 	va_end(ap);
< 
< 	paymod_log(p, LOG_INFORM, "%s", p->failreason);
< 
< 	payment_continue(p);
< }
< 
< void payment_fail2(struct payment *p, const char *fmt, ...)
< {
< 	va_list ap;
< 	p->end_time = time_now();
< 	payment_set_step(p, PAYMENT_STEP_RETRY_GETROUTE);

I find the diff a bit strange, I would expect:

void payment_fail2(struct payment *p, const char *fmt, ...)
{
        va_list ap;
        p->end_time = time_now();
        payment_set_step(p, PAYMENT_STEP_RETRY_GETROUTE);
        va_start(ap, fmt);
        p->failreason = tal_vfmt(p, fmt, ap);
        va_end(ap);

        paymod_log(p, LOG_INFORM, "%s", p->failreason);

        payment_continue(p);
}

but it's broken into pieces but nevertheless it's all there.

[hMsats]

@cdecker You can also find my libplugin-pay.c here.