search

ElementsProject / lightning

Core Lightning — Lightning Network implementation focusing on spec compliance and performance
Other
2.84k stars 901 forks source link

MPP pay splits into too many subpayments #3926

Closed thestick613 closed 4 years ago

thestick613 commented 4 years ago

I have an outbound channel with an BTC to Lightning exchange worth 2.000.000 satoshi, with enough capacity. I try to swap my 2.000.000 satoshi for the same amount, but on-chain. Lightningd splits the payment into too many subpayments, and eventually fails, even though the destination is only one hop away, and has enough capacity.

ZmnSCPxj commented 4 years ago

Can you provide logs? In particular a message "Split into " in the inform-level logs (though debug-level logs would be best).

Is the receiver also forwarding/receiving payments at the same time as well?

thestick613 commented 4 years ago

First time i tried this, i ended up with #3846, then with #3848 and then with #3851, and then with #3915. The logs always looked like this:

ZmnSCPxj commented 4 years ago

I observe something similar in the failure cases of #3913 as well, which I think are mitigated by #3914. Are you paying to a node that is unpublished (i.e. is not visible on 1ml.com)?

ZmnSCPxj commented 4 years ago

The reason the logs are important is that we have to know if it is the presplit splitter that is too aggressive, or the adaptive splitter.

ZmnSCPxj commented 4 years ago

Finally: if you do not want to try paying again for a while due to the extant bugs: how many channels do you have?

ZmnSCPxj commented 4 years ago

And if possible: if the destination is published, how many channels does it have? If the destination is not published, how many routehints were on the invoice?

@cdecker maybe we should consider as well the HTLC budget on the payee end, not just on the payer end? In #3916 @thestick613 claims to have over 100 HTLCs pending, if those are from a single pay attempt that suggests the payer node has ~10 channels or so I think, perhaps it is the payee that is not able to handle that many incoming HTLCs due to having fewer channels?

thestick613 commented 4 years ago

Logs incoming:

2020-08-12T12:53:06.135Z INFO plugin-pay: Split into 51 sub-payments due to initial size (499907000msat > 10000000msat)
2020-08-12T12:53:06.687Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.688Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.689Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.740Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.762Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.767Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.770Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.771Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.774Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.776Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.777Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.803Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.803Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.804Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.804Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.951Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.951Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.952Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.952Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.952Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.978Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.979Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:06.980Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.015Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.016Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.093Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.094Z UNUSUAL plugin-pay: Could not update the channel hint for 579336x1618x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.094Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.094Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.094Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.102Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.103Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.103Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.206Z UNUSUAL plugin-pay: Could not update the channel hint for 605257x1187x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:07.352Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.353Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.355Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.361Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.362Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.363Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.364Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.365Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.366Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.367Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.368Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.370Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.371Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.375Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.448Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.451Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.452Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.452Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.452Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.468Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.469Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.470Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.473Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.474Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.474Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:07.518Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:07.561Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 25715sat)
2020-08-12T12:53:08.651Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.653Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.654Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.658Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.659Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.664Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.666Z UNUSUAL plugin-pay: Could not update the channel hint for 630131x2397x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:08.669Z UNUSUAL plugin-pay: Could not update the channel hint for 630131x2397x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:08.674Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.681Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.694Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.695Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.703Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.707Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.738Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.738Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.739Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.739Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:08.740Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)
2020-08-12T12:53:09.011Z INFO 02913d84886059292845f870c5229f103dd8d7d71d7e9fc6fd52f75a40486d2187-chan#57145: htlc 28 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:09.052Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:09.135Z UNUSUAL plugin-pay: Could not update the channel hint for 612040x2823x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:09.137Z UNUSUAL plugin-pay: Could not update the channel hint for 612040x2823x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:09.222Z UNUSUAL plugin-pay: Could not update the channel hint for 612040x2823x0/1. Could be a concurrent `getroute` call.
2020-08-12T12:53:09.337Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:09.337Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 24366sat)
2020-08-12T12:53:09.718Z INFO 03c2abfa93eacec04721c019644584424aab2ba4dff3ac9bdab4e9c97007491dda-chan#29279: htlc 476 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:09.727Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.263Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 425 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.272Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.360Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 290 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.362Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 287 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.371Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.374Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.478Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 426 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.479Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 427 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.484Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.486Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.577Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 3156sat)
2020-08-12T12:53:10.794Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 301 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.795Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 302 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.796Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 293 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.797Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 294 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.798Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 299 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.799Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 296 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.800Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 292 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.806Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.809Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.810Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.811Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.811Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.812Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.813Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-12T12:53:10.843Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 430 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.844Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 429 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.845Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 432 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.846Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 428 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-12T12:53:10.846Z INFO 03634bda49c9c42afd876d8288802942c49e58fbec3844ff54b46143bfcb6cdfaf-chan#57168: htlc 431 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)

and it goes on like this for a while

The pay command outputed, which i hope means it failed.

{
   "code": 210,
   "message": "Ran out of routes to try after 328 attempts: see `paystatus`",
   "attempts": [
    [...]
}

The payment size is ~500.000 satoshi. I have over 16 channels that have this much available to pay capacity. It just seems odd to split the payment into 51 subpayments.

thestick613 commented 4 years ago

And surprisingly ... legacypay same_bolt_11 5 minutes later worked.

ZmnSCPxj commented 4 years ago

It just seems odd to split the payment into 51 subpayments.

Indeed. It looks like we did not test the case where the payer has substantially greater number of channels than the payee, or even the average number of channels that a typical network node has. We should probably get some statistics for the median number of channels that a network node has, or maybe mean to bias it for the benefit of the majority of the network.

We estimate a certain number of HTLCs that each outgoing channel can have; if you do not mess around with some of the more obscure options we have, I think we go with 10 HTLCs per outgoing channel. Since you have 16 channels, that amounts to 160 HTLCs limit.

Then, at the presplit stage, we take your 500,000-sat invoice and divide it into 10,000-sat lots (the 10,000-sat is hardcoded, based on @cdecker statistics that 83% of 10,000-sat HTLCs reach random destinations from his controlled nodes). This results in about 50 initial HTLCs. Since this is far lower than the 160 HTLCs limit we got from you having 16 channels, the presplitter goes ahead with splitting into 10,000-sat lots (if the number of lots were greater than our computed HTLCs limit, we would have increased the lot size accordingly). You got 51 lots because we do not actually split into exact lot sizes of 10,000 sats each, we randomize a bit, so getting 49->51 lots is expected, more rarely a wider spread, but that is approximately what we expect.

But the root is really that the payer has a ton of channels and that made us assume that the limit on the number of HTLCs was far greater than what the rest of the network, and/or the receiver, can handle.

Our initial HTLC limit should be the lowest among:

This prevents the following issues:

Those are probably the reason why you get these logs:

    2020-08-12T12:53:08.651Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)

And surprisingly ... legacypay same_bolt_11 5 minutes later worked.

Not a surprise. Our new pay in 0.9.0 is the first "serious" implementation of outgoing MPP, so we expect bugs (just not as bad as was reported LOL), which is why legacypay still exists.

ZmnSCPxj commented 4 years ago

Those are probably the reason why you get these logs:

    2020-08-12T12:53:08.651Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs)

No, that is incorrect, who the heck wrote that? We only get errors that detailed if and only if it is a local error. Remote errors just get the failure code and a useless "reply from remote" message. So it looks like we tried to pile on the 51 sub-payments on a single channel (probably because it was the most direct route to the destination), which choked. We should not do that. Instead, we should round-robin the outgoing channels, as I suggested in #3894. The reason why we should avoid piling such HTLCs on a single channel is that we want to avoid incorrect capacity estimates of our local channels.

Nevertheless, we do see some later WIRE_TEMPORARY_CHANNEL_FAILURE: Reply from remote messages, and since a later legacypay succeeded, those failures did not have anything to do with capacity but instead about number of HTLCs. So throttling the number of HTLCs depending on the connectivity of the payee (and the average connectivity of network nodes?) would probably work just as well.

ZmnSCPxj commented 4 years ago

Hi @thestick613 , I wrote #3936 based on your report, if you have the inclination, could you check that PR and see if it fixes your problem?

whitslack commented 4 years ago

I just ran into a mega case of this. Why do you split a large payment into so many tiny payments right away, without first trying the large payment? Basically, why run a "presplitter" at all? Isn't the adaptive splitter all you need?

I tried to pay a ~3.8-Msat invoice, and C-Lightning foolishly split my payment into 385 sub-payments, which of course was never going to work. Most of the attempts failed with "WIRE_TEMPORARY_CHANNEL_FAILURE: Too many HTLCs."

Worse, it was completely unclear to me whether the overall payment attempt had actually been abandoned or was still ongoing in the background. The pay command returned "code": 210, "message": "Ran out of routes to try after 731 attempts: see paystatus", but many of the elements in the returned attempts array had "status": "pending", which suggests that I should not re-attempt the payment. When I look at paystatus, many of the elements in the attempts array have "strategy": "Still have 9 attempts left", which also suggests that I should not re-attempt the payment.

How am I supposed to know when C-Lightning has fully abandoned my payment attempt? It is unclear to me whether/when I will be guaranteed that the payment failed safely and I will not lose this money.

ZmnSCPxj commented 4 years ago

When pay returns, it will stop reattempting. Sub-payments may remain pending, but those are partial payments and the receiver will not claim them since they will not add up to the expected amount. Once pay returns that invoice will not be paid as long as you do not re-execute.

However, you should not execute a new pay command with the same invoice once it fails, as previous pending sub-payments are not considered. What we should properly do on our side should be to check if there is a previous payment attempt with pending sub-payments and to resume that (i.e. this is a bug on our end). As is, with 0.9.0, doing something like this may cause the pay command to ignore the existing pending payments and get badly lost funds and so on.

So:

whitslack commented 4 years ago

Sub-payments may remain pending, but those are partial payments and the receiver will not claim them since they will not add up to the expected amount.

Is that cryptographically enforced or merely a typical node policy? Couldn't a receiver say, "oh yeah, I'll claim sub-payments totaling 80% of the invoice amount"? (Ah, I see you edited your reply to acknowledge this possibility further down.)

However, you should not execute a new pay command with the same invoice once it fails […] As is, with 0.9.0, doing something like this may cause the pay command to ignore the existing pending payments and get badly lost funds and so on.

This warning needs to go in the manpage!

  • On pay failure, you can consider the invoice as "not paid" even with pending sub-payments, those will eventually be returned by the payee after 60 seconds or so (if they follow BOLT spec).

60 seconds? So how do I still have attempts in "strategy": "Still have 9 attempts left" almost two hours later? The invoice expired after 15 minutes. Shouldn't all sub-payment attempts have cratered by now?

in theory the receiver can decide to later accept a smaller amount than what was indicated in the invoice. Sigh.

Yeaaahhhhhh.

  • BUT after a failure you should cowardly refuse to pay the failed invoice unless all pending sub-payments have definitely failed (which "should" not take more than 60 seconds modulo communication delays, for some definition of the word "should").

How would I know when/if that has occurred? paystatus doesn't report how many sub-payments are still pending.

whitslack commented 4 years ago

in theory the receiver can decide to later accept a smaller amount than what was indicated in the invoice.

If this were to happen, how would I find out about it?

ZmnSCPxj commented 4 years ago

@whitslack how many channels do you have and why did presplitter allow 385?? wow.

@cdecker I think we should consider not returning immediately once we have decided to stop retrying and a failing payment comes on. The current pay runs the following risks:

I think the above two items above deserve their own issue.... The easy fix is to simply:

This also gives us a decent point at which to delete the entire payment tree.

This seems to be an argument for having a flat array of payments we consider as pending, as well.

ZmnSCPxj commented 4 years ago

So how do I still have attempts in "strategy": "Still have 9 attempts left" almost two hours later?

Are they still pending? Because "strategy" is just the last string we wrote into the why field. If pay has given up on it that strategy will never be changed.

ZmnSCPxj commented 4 years ago

If this were to happen, how would I find out about it?

Months later when your LN node has 0 funds on it. :(. In theory you could keep polling the listsendpays command for those. Aaargh. I will be going to sleep in a while. Sigh.

For now, you might want to use legacypay, which is probably a lot safer, though the current listpays will probably not report legacypay (maybe, not sure, have not touched that code). Sigh.

ZmnSCPxj commented 4 years ago

This warning needs to go in the manpage!

FWIW I just realized this utterly bad behavior now. Sigh.

whitslack commented 4 years ago

how many channels do you have

$ lightning-cli listpeers | jq '[.peers[] | .channels[] | select(.state == "CHANNELD_NORMAL")] | length'
420

and why did presplitter allow 385?? wow.

I have no idea. It seems quite excessive. I get that 3.8 Msat is a larger payment than would typically be sent over the Lightning Network, but I wanted to try out the new multi-part payments functionality, and I figured the whole point of MPP is to allow sending large payments. But splitting 3.8 Msat into ~10-ksat chunks is pretty ridiculous, IMHO.

whitslack commented 4 years ago

In theory you could keep polling the listsendpays command for those.

Thanks for the tip.

$ lightning-cli -k listsendpays payment_hash=##redacted## | jq 'reduce (.payments[].status) as $status ({}; .[$status] += 1)'
{
  "failed": 730
}

730 sub-payment attempts in failed status and none in any other status. So I take this to mean that the payee did not claim any of the sub-payments.

whitslack commented 4 years ago

Disconcerting that pay reported 731 attempts, but listsendpays returns only 730 attempts for that payment_hash. :/

ZmnSCPxj commented 4 years ago

I have no idea.

The presplitter allocates 10 HTLCs per outgoing channel (if your default max-concurrent-htlcs is 30). More specifically, it allocates max-concurrent-htlcs times the number of channels, divided by 3. If you set max-concurrent-channels to 5, and have 420 channels, the presplitter would have been perfectly willing to split it up to 700 parts......... HAHAHAHAHA

The presplitter will not split to lower than 10,000-sat parts (the adaptive splitter will not split lower than 100-sat parts). Since your initial limit is 700 parts, but you were sending 3,800,000 sats, the presplitter went with 380 x 10,000 parts (the extra 5 is due to randomizing the splits, you actually get "around" 380 parts, with some randomness).

That is a very popular node you are running there.

For now, I suggest using legacypay, or if that is not possible for you, --disable-mpp.

whitslack commented 4 years ago

That is a very popular node you are running there.

And here I was thinking that I was doing myself a favor by getting my node "well established" in the network while chain fees are still somewhat affordable. I never imagined that a better connected node would be less able to complete a payment! 😅

ZmnSCPxj commented 4 years ago

Haha, yes. #3936 should help with that issue, if you are willing to get on master and in addition pull the PR as well.

It is very hard to have tests that simulate a heavily-connected node, for the very simple reason we have to run tons of lightningd instances to simulate a heavily-connected node, so a bit difficult here in dev-land to get such a heavily-connected node that we can play around with. Hmmmmmmmm.

thestick613 commented 4 years ago

I'll try again when bitcoin fees are lower.

thestick613 commented 4 years ago

Tried with #3936 

2020-08-15T06:36:58.528Z INFO plugin-pay: Split into 20 sub-payments due to initial size (1999934000msat > 99996700msat)
2020-08-15T06:36:59.013Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.015Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.037Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.037Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.044Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.048Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.049Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.055Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.058Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.060Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.181Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.181Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.184Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.187Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.189Z UNUSUAL plugin-pay: Could not update the channel hint for 614927x1433x0/1. Could be a concurrent `getroute` call.
2020-08-15T06:36:59.194Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.195Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.196Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.197Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.202Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.215Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.216Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.221Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.274Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.274Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:36:59.275Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (WIRE_TEMPORARY_CHANNEL_FAILURE: Capacity exceeded - HTLC fee: 33951sat)
2020-08-15T06:37:00.388Z INFO 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-chan#64530: htlc 267 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-15T06:37:00.395Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-15T06:37:00.669Z INFO 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-chan#64530: htlc 268 failed from 1th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-15T06:37:00.676Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-15T06:37:00.821Z INFO 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-chan#64530: htlc 266 failed from 1th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-15T06:37:00.831Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-15T06:37:00.900Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 319 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:00.901Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 321 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:00.902Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 322 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:00.902Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 320 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:00.908Z UNUSUAL plugin-pay: Node #2 (03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:00.908Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:00.908Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:00.909Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:00.909Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:00.909Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:00.909Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:00.909Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.246Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 326 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.598Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 334 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.599Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 329 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.600Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 335 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.601Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 328 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.601Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 327 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.602Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 330 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.603Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 331 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.604Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 332 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.604Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 333 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:01.612Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.612Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.612Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.612Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.613Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.613Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.613Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.613Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.614Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.614Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.614Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.614Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.614Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.614Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.615Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.615Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:01.615Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:01.615Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:02.224Z INFO 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-chan#64530: htlc 269 failed from 1th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2020-08-15T06:37:02.229Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-08-15T06:37:02.738Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 336 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:02.739Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 337 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:02.740Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 338 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:02.747Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:02.747Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:02.747Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:02.747Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:02.748Z UNUSUAL plugin-pay: Node #2 (03952f8756c036669440e06c782c7f21732886ccf04052e0e6e792f8f5a490f6aa) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:02.748Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:03.321Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 340 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.322Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 339 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.323Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 341 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.329Z UNUSUAL plugin-pay: Node #2 (02a04446caa81636d60d63b066f2814cbd3a6b5c258e3172cbdded7a16e2cfff4c) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:03.330Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:03.330Z UNUSUAL plugin-pay: Node #2 (02a04446caa81636d60d63b066f2814cbd3a6b5c258e3172cbdded7a16e2cfff4c) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:03.330Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:03.331Z UNUSUAL plugin-pay: Node #2 (02a04446caa81636d60d63b066f2814cbd3a6b5c258e3172cbdded7a16e2cfff4c) claimed #1 (023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1) sent them invalid cltv
2020-08-15T06:37:03.331Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-08-15T06:37:03.603Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 343 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.604Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 345 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.605Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 344 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)
2020-08-15T06:37:03.605Z INFO 023662f1db3d0527dab0869e30f183021db7dc44f6f2e32ece42dd124846c89ca1-chan#74914: htlc 342 failed from 0th node with code 0x100d (WIRE_INCORRECT_CLTV_EXPIRY)

In the end, it failed as well.

thestick613 commented 4 years ago 
   "code": 210,
   "message": "Ran out of routes to try after 341 attempts: see `paystatus`",
   "attempts": [...]
thestick613 commented 4 years ago

Tried a different, smaller one (0.01 BTC) with https://boltz.exchange/, and MPP pay seemed to work. The pay command took 15-20 minutes to execute, and i was almost going to Ctrl+C it. I can send you guys the full lightningd logs (the first failure, then the second successfull one) if it helps you improve the algorithm. I guess you could merge #3936, since it's not the first time i tried paying 0.01 to that specific node, but it's the first time it worked.

ZmnSCPxj commented 4 years ago

15 minutes, heck. Did you feed a retry_for param? If it exceeded the retry_for (default 60 seconds I think) for a long time, then it seems somebody on the network is slow... which is more likely to be hit if we start with lots of little subpayments, as well. Sigh.

Getting #3917 merged in would be much more helpful to help figure out the bad behavior of the algorithm. In particular we are not currently printing any logs when the adaptive splitter triggers. So existing logs, while useful, could be improved. Sorry for this. @cdecker @niftynei @rustyrussell I would rather not merge unilaterally, please review #3917? In any case thanks for the effort @thestick613, sorry for the losses incurred in fees testing this, and yes please provide logs if possible.

Looks to me we want to consider having a paymod that merges multiple failing subpayments. But by what rule do we use to determine if we should merge instead of split? Obviously at some point our channel hints are poisoned, since the same error is reported for both insufficient msat capacity and insufficient HTLC capacity: the answer to insufficient msat capacity is split, but the answer to insufficient HTLC capacity is merge.

This is complicated by the fact that at least some of the HTLC-capacity limit is caused by onchain fees. So if onchain fees are high, every split-out becomes expensive. In particular, there will always exist some N where a single N-amount HTLC can pass through a channel, but two N/2 HTLCs cannot. What we need is to figure out whether our splits are above or below this N. If it is above, we should split, if it is below, we should merge. Hmmmmmm.

thestick613 commented 4 years ago

I just wrote pay bolt11, no extra parameters. I can probably wait for #3917 before attempting any more pays. I've sent you guys some logs.

ZmnSCPxj commented 4 years ago

Received, thanks!

fiatjaf commented 4 years ago

Sorry, I don't have logs or anything, just some anedoctal evidence: I tried 3 times over a couple of hours to pay a 1344342 sat invoice right now with pay and saw the message: INFO plugin-pay: Split into 133 sub-payments due to initial size (1344342000msat > 10000000msat), then the payment failed with a ton of WIRE_TEMPORARY_CHANNEL_FAILURE.

Then I tried legacypay and the payment went through immediately.

The receiver was a node with only 5 channels.

Besides that, I don't really have good stats on this, but it seems payments originating from t.me/lntxbot are failing more since I upgraded to 0.9.x, or at least that's what the number of people complaining say (which is never too much, so the increase may be a coincidence).

My uninformed opinion is that the splitting is too aggressive.

whitslack commented 4 years ago

If the pay command returns with failure, but we still have payments pending, we run the risk that the receiver might decide to just claim partial funds. This is irrational if the preimage is valuable (the atomicity of Base AMP / MPP is based on this assumption!) but if for example this is a custodial service that credits / debits a user account, well, it would be possible to hack this into a receiver and have it claim partial funds.

@ZmnSCPxj: Is claiming a partial payment actually possible? I just came across some messages between you and \@roasbeef discussing how atomic multipath payments would prevent the claiming of any sub-payment until all sub-payments have been routed through. Am I misunderstanding?

ZmnSCPxj commented 4 years ago

@whitslack yes. It would be irrational to do so if the preimage is somehow inherently valuable, with equal value to the invoice amount (for example, if it unlocks some onchain HTLC, or if it is the decryption key of some valuable data, or it is used as an authorization to access some resource, or somebody will beat you up if you don't pay them and can show a preimage to prove you paid them).

However, if the preimage is not valuable, claiming a partial payment may be rational.

Consider the case where a custodial service exists on Lightning (custodial services are evil, of course). The evil custodial service could support paying an arbitrary invoice.

A user of that custodial service could attack the custodial service if it knows the custodial service performs MPP, and treats failure of one sub-payment as failure of the entire sub-payment.

Thus, it is required not to consider a payment as definitely failed until all sub-payments have failed. If we consider the payment as failed if some sub-payment is failed, then we risk falling victim to the above attack.

ZmnSCPxj commented 4 years ago

@whitslack what you linked is not the same as MPP, incidentally. The current MPP system has the assumption that the invoice preimage is valuable (proof-of-payment). AMP does not have this assumption, but loses proof-of-payment completely (it is basically a multipath keysend payment, with the key being sent sharded over all splits).

whitslack commented 4 years ago

@ZmnSCPxj: In your attack scenario, all of the sub-payments are successfully routed all the way to the payee (the attacker), but the attacker chooses to reject some of them. Can the attack also succeed if the attacker does NOT learn of all of the sub-payments — i.e., if only some of the sub-payments route all the way to the attacker while others fail in mid-route due to channel capacity exhaustion or outstanding HTLC limits?

what you linked is not the same as MPP, incidentally.

Ahh! I was wondering why the "AMP" acronym was quietly replaced with "MPP." I was thinking that MPP was still atomic, so thank you for the clarification. I think this is a point that does not have enough visibility to the user community. I know for me personally, the atomicity guarantee is more important than proof of payment, as I'm nearly always paying payees whom I trust; it's the software between us that I don't trust.

ZmnSCPxj commented 4 years ago

Can the attack also succeed if the attacker does NOT learn of all of the sub-payments — i.e., if only some of the sub-payments route all the way to the attacker while others fail in mid-route due to channel capacity exhaustion or outstanding HTLC limits?

Yes.

I was thinking that MPP was still atomic, so thank you for the clarification. I think this is a point that does not have enough visibility to the user community. I know for me personally, the atomicity guarantee is more important than proof of payment, as I'm nearly always paying payees whom I trust; it's the software between us that I don't trust.

MPP is still atomic assuming you value the proof-of-payment. For example, in a reverse submarine swap / loop out / whatever the heck they call it these days.

The trust in the software can be increased by us reporting failure if and only if all parts are failures. In the case the payee is trying to abuse your trust, you would see the payment as stuck even if our software has given up paying. I am still trying to grok this part of the new paymod code. Maybe @cdecker can help.