Incorrect CLTV expiry in new payment flow

[rustyrussell]

$ lightning-cli pay  LNBC10U1P03VAF5PP59852G5NJUJGRTXH93P7YWKWLYLME3YFT8Q8JCKUMQ7WDZ8EGF8CQDQG2F6HXARECQZPGXQYPR9QSP523EJEG6DZ0FXJCPSK5FJW7HJSJZYLJSGKDMVDA296RX90WQEQW7Q9QY9QSQ958DS79CJTA4PQ02DAVK95NPJ5F3X3GC3FGK2P2JF5Y4EL5QTPD4JJFU85YJ6X8H0ZF7AAU00TMZGGKHVZV6J72UL4GUM7UGGSDQV9GPZ04Y4U
{
   "code": 210,
   "message": "Ran out of routes to try after 50 attempts: see `paystatus`",
   "attempts": [
      {
         "status": "pending",
         "partid": 1,
         "amount": "1000000msat"
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 2,
         "amount": "126605msat",
         "parent_partid": 1
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 7,
         "amount": "126605msat",
         "parent_partid": 2
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 11,
         "amount": "126605msat",
         "parent_partid": 7
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 15,
         "amount": "126605msat",
         "parent_partid": 11
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 19,
         "amount": "126605msat",
         "parent_partid": 15
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 23,
         "amount": "126605msat",
         "parent_partid": 19
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 27,
         "amount": "126605msat",
         "parent_partid": 23
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 31,
         "amount": "126605msat",
         "parent_partid": 27
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 35,
         "amount": "126605msat",
         "parent_partid": 31
      },
      {
         "status": "pending",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 39,
         "amount": "126605msat",
         "parent_partid": 35
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 43,
         "amount": "59780msat",
         "parent_partid": 39
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 44,
         "amount": "66825msat",
         "parent_partid": 39
      },
      {
         "status": "pending",
         "partid": 3,
         "amount": "23655msat",
         "parent_partid": 1
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 4,
         "amount": "192528msat",
         "parent_partid": 1
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 10,
         "amount": "192528msat",
         "parent_partid": 4
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 14,
         "amount": "192528msat",
         "parent_partid": 10
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 18,
         "amount": "192528msat",
         "parent_partid": 14
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 22,
         "amount": "192528msat",
         "parent_partid": 18
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 26,
         "amount": "192528msat",
         "parent_partid": 22
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 30,
         "amount": "192528msat",
         "parent_partid": 26
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 34,
         "amount": "192528msat",
         "parent_partid": 30
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 38,
         "amount": "192528msat",
         "parent_partid": 34
      },
      {
         "status": "pending",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 42,
         "amount": "192528msat",
         "parent_partid": 38
      },
      {
         "status": "pending",
         "partid": 49,
         "amount": "94673msat",
         "parent_partid": 42
      },
      {
         "status": "pending",
         "partid": 50,
         "amount": "97855msat",
         "parent_partid": 42
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 5,
         "amount": "439705msat",
         "parent_partid": 1
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 9,
         "amount": "439705msat",
         "parent_partid": 5
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 13,
         "amount": "439705msat",
         "parent_partid": 9
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 17,
         "amount": "439705msat",
         "parent_partid": 13
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 21,
         "amount": "439705msat",
         "parent_partid": 17
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 25,
         "amount": "439705msat",
         "parent_partid": 21
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 29,
         "amount": "439705msat",
         "parent_partid": 25
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 33,
         "amount": "439705msat",
         "parent_partid": 29
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 37,
         "amount": "439705msat",
         "parent_partid": 33
      },
      {
         "status": "pending",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 41,
         "amount": "439705msat",
         "parent_partid": 37
      },
      {
         "status": "pending",
         "partid": 47,
         "amount": "226990msat",
         "parent_partid": 41
      },
      {
         "status": "pending",
         "partid": 48,
         "amount": "212715msat",
         "parent_partid": 41
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)",
         "partid": 6,
         "amount": "217507msat",
         "parent_partid": 1
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 8,
         "amount": "217507msat",
         "parent_partid": 6
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 12,
         "amount": "217507msat",
         "parent_partid": 8
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 16,
         "amount": "217507msat",
         "parent_partid": 12
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 20,
         "amount": "217507msat",
         "parent_partid": 16
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 24,
         "amount": "217507msat",
         "parent_partid": 20
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 28,
         "amount": "217507msat",
         "parent_partid": 24
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 32,
         "amount": "217507msat",
         "parent_partid": 28
      },
      {
         "status": "failed",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 36,
         "amount": "217507msat",
         "parent_partid": 32
      },
      {
         "status": "pending",
         "failreason": "failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)",
         "partid": 40,
         "amount": "217507msat",
         "parent_partid": 36
      },
      {
         "status": "pending",
         "partid": 45,
         "amount": "115757msat",
         "parent_partid": 40
      },
      {
         "status": "pending",
         "partid": 46,
         "amount": "101750msat",
         "parent_partid": 40
      }
   ]
}

pay plugin logs:

2020-07-21T06:52:54.670Z INFO plugin-pay: Payment fee constraint 5000msat is below exemption threshold, allowing a maximum fee of 5000msat
2020-07-21T06:52:54.671Z INFO plugin-pay: Split into 5 sub-payments due to initial size (1000000msat > 300000msat)
2020-07-21T06:52:57.862Z DEBUG plugin-pay: Added a channel hint for 577480x1296x0/0: enabled true, estimated capacity 94953msat
2020-07-21T06:52:57.862Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:52:57.862Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/2 (126605msat), new partid 7. 8 attempts left\n
2020-07-21T06:52:58.404Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:52:58.404Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/6 (217507msat), new partid 8. 8 attempts left\n
2020-07-21T06:52:58.956Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:52:58.956Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/5 (439705msat), new partid 9. 8 attempts left\n
2020-07-21T06:52:59.922Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:52:59.923Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/4 (192528msat), new partid 10. 8 attempts left\n
2020-07-21T06:53:02.464Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:02.464Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:02.464Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/7 (126605msat), new partid 11. 7 attempts left\n
2020-07-21T06:53:03.279Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:03.279Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:03.279Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/8 (217507msat), new partid 12. 7 attempts left\n
2020-07-21T06:53:04.795Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:04.795Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:04.795Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/9 (439705msat), new partid 13. 7 attempts left\n
2020-07-21T06:53:05.451Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:05.451Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:05.451Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/10 (192528msat), new partid 14. 7 attempts left\n
2020-07-21T06:53:08.904Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:08.904Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:08.904Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/11 (126605msat), new partid 15. 6 attempts left\n
2020-07-21T06:53:09.589Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:09.589Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:09.589Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/12 (217507msat), new partid 16. 6 attempts left\n
2020-07-21T06:53:10.915Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:10.915Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:10.915Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/13 (439705msat), new partid 17. 6 attempts left\n
2020-07-21T06:53:11.583Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:11.583Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:11.583Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/14 (192528msat), new partid 18. 6 attempts left\n
2020-07-21T06:53:15.021Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:15.021Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:15.021Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/15 (126605msat), new partid 19. 5 attempts left\n
2020-07-21T06:53:16.404Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:16.404Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:16.404Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/16 (217507msat), new partid 20. 5 attempts left\n
2020-07-21T06:53:17.151Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:17.151Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:17.151Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/17 (439705msat), new partid 21. 5 attempts left\n
2020-07-21T06:53:17.843Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:17.843Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:17.843Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/18 (192528msat), new partid 22. 5 attempts left\n
2020-07-21T06:53:20.720Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:20.720Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:20.720Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/19 (126605msat), new partid 23. 4 attempts left\n
2020-07-21T06:53:21.453Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:21.453Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:21.453Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/20 (217507msat), new partid 24. 4 attempts left\n
2020-07-21T06:53:22.868Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:22.868Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:22.868Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/21 (439705msat), new partid 25. 4 attempts left\n
2020-07-21T06:53:23.667Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:23.667Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:23.667Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/22 (192528msat), new partid 26. 4 attempts left\n
2020-07-21T06:53:26.482Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:26.483Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:26.483Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/23 (126605msat), new partid 27. 3 attempts left\n
2020-07-21T06:53:27.211Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:27.211Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:27.211Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/24 (217507msat), new partid 28. 3 attempts left\n
2020-07-21T06:53:28.630Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:28.631Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:28.631Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/25 (439705msat), new partid 29. 3 attempts left\n
2020-07-21T06:53:29.444Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:29.445Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:29.445Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/26 (192528msat), new partid 30. 3 attempts left\n
2020-07-21T06:53:32.240Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:32.240Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:32.240Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/27 (126605msat), new partid 31. 2 attempts left\n
2020-07-21T06:53:32.942Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:32.942Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:32.942Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/28 (217507msat), new partid 32. 2 attempts left\n
2020-07-21T06:53:33.669Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:33.669Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:33.669Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/29 (439705msat), new partid 33. 2 attempts left\n
2020-07-21T06:53:35.370Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:35.370Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:35.370Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/30 (192528msat), new partid 34. 2 attempts left\n
2020-07-21T06:53:38.087Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:38.087Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:38.087Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/31 (126605msat), new partid 35. 1 attempts left\n
2020-07-21T06:53:38.740Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:38.740Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:38.740Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/32 (217507msat), new partid 36. 1 attempts left\n
2020-07-21T06:53:40.138Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:40.138Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:40.138Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/33 (439705msat), new partid 37. 1 attempts left\n
2020-07-21T06:53:40.869Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:40.869Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:40.869Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/34 (192528msat), new partid 38. 1 attempts left\n
2020-07-21T06:53:44.456Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:44.456Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:44.456Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/35 (126605msat), new partid 39. 0 attempts left\n
2020-07-21T06:53:45.185Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:45.186Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:45.186Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/36 (217507msat), new partid 40. 0 attempts left\n
2020-07-21T06:53:45.919Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:45.919Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:45.919Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/37 (439705msat), new partid 41. 0 attempts left\n
2020-07-21T06:53:46.618Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:46.619Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:46.619Z DEBUG plugin-pay: Retrying 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/38 (192528msat), new partid 42. 0 attempts left\n
2020-07-21T06:53:50.266Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:50.267Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:50.297Z UNUSUAL plugin-pay: Could not update the channel hint for 577480x1296x0/0. Could be a concurrent `getroute` call.
2020-07-21T06:53:51.698Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:51.698Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:52.388Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:52.388Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:53.019Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:53:53.019Z INFO plugin-pay: Lower limit of adaptive splitter reached (66825msat < 100000msat), not splitting further.
2020-07-21T06:53:53.167Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:53.167Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:55.239Z INFO plugin-pay: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (reply from remote)
2020-07-21T06:53:55.239Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/43
2020-07-21T06:53:56.658Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:56.658Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:56.658Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/45
2020-07-21T06:53:56.658Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:56.658Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:56.658Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/46
2020-07-21T06:53:57.388Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:57.388Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:57.388Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/47
2020-07-21T06:53:57.389Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:57.389Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:57.389Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/48
2020-07-21T06:53:58.112Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:58.112Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:58.112Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/50
2020-07-21T06:53:58.112Z UNUSUAL plugin-pay: Node #2 (03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898) claimed #1 (03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) sent them invalid cltv
2020-07-21T06:53:58.112Z INFO plugin-pay: failed: WIRE_INCORRECT_CLTV_EXPIRY (reply from remote)
2020-07-21T06:53:58.112Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/49
2020-07-21T06:55:00.571Z INFO plugin-pay: failed: WIRE_MPP_TIMEOUT (reply from remote)
2020-07-21T06:55:00.571Z INFO plugin-pay: Payment deadline expired, not retrying (partial-)payment 29e8a45272e490359ae5887c4759df27f798912b380f2c5b9b079cd11f2849f0/3

[cdecker]

Bit of a lengthy writeup of my explorations, but I thought I'd share them in case anyone has an idea of what it might be.

I tampered with my pay plugin to make sure I don't accidentally pay the invoice you specified above (it'll presplit, but stop after starting the first sub-payment which is insufficient to settle the invoice). This allowed my to test this a couple of times from my node (which happens to also be a direct peer of 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f which appears to be the node we are giving some wrong instructions.

I noticed that the issue appears mainly when we only have a 2-hop route, whereas any longer route seems to work fine. I'll need to verify this against some different destinations, but so far it's working like clockwork.

Testing the same route manually using getroute and sendpay however works as expected:

$ echo $ROUTE[
  {
    "id": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
    "channel": "636733x2469x0",
    "direction": 1,
    "msatoshi": 300000,
    "amount_msat": "300000msat",
    "delay": 153,
    "style": "tlv"
  },
  {
    "id": "03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
    "channel": "576389x1922x0",
    "direction": 0,
    "msatoshi": 300000,
    "amount_msat": "300000msat",
    "delay": 9,
    "style": "tlv"
  }
]

$ lcli sendpay "$ROUTE" e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898 && lcli waitsendpay e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898
{
   "message": "Monitor status with listpays or waitsendpay",
   "id": 272489,
   "payment_hash": "e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
   "destination": "03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
   "msatoshi": 300000,
   "amount_msat": "300000msat",
   "msatoshi_sent": 300000,
   "amount_sent_msat": "300000msat",
   "created_at": 1595341535,
   "status": "pending"
}
{
   "code": 203,
   "message": "failed: WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS (reply from remote)",
   "data": {
      "id": 272489,
      "payment_hash": "e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
      "destination": "03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
      "msatoshi": 300000,
      "amount_msat": "300000msat",
      "msatoshi_sent": 300000,
      "amount_sent_msat": "300000msat",
      "created_at": 1595341535,
      "status": "pending",
      "erring_index": 2,
      "failcode": 16399,
      "failcodename": "WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS",
      "erring_node": "03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
      "erring_channel": "576389x1922x0",
      "erring_direction": 0,
      "raw_message": "400f00000000000493e00009c4a0"
   }
}

This uses the usual probe trick of using a payment_hash that isn't known to the destination. Notice that it doesn't yield a CLTV error, so there must be something we're messing up. The following are the options I can think of at the moment:

• We fail to parse the getroute request
• We fail to build correct payloads for the onion
• We pass the payloads wrongly to createonion
• We fail to call sendonion correctly (basically the only thing that might happen is that we botch the first_hop since the rest is covered by HMACs)
• Some random other reason I just can't think of atm

getroute result to onion payloads

Writing out the getroute result yields the following:

[
  {
    "id": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
    "channel": "636733x2469x0",
    "direction": 1,
    "msatoshi": 299879,
    "amount_msat": "299879msat",
    "delay": 184,
    "style": "tlv"
  },
  {
    "id": "03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898",
    "channel": "576389x1922x0",
    "direction": 0,
    "msatoshi": 299879,
    "amount_msat": "299879msat",
    "delay": 40,
    "style": "tlv"
  }
]

Interpreted by c-lightning as this (dumping the elements of p->route:

route[0] = 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f, cltv=184, scid=636733x2469x0/1
route[1] = 03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898, cltv=40, scid=576389x1922x0/0

And encoded as onion payloads:

   onion_hop[0]: 2
         field[2]=049367
         field[4]=09c4c8
         field[6]=08cb850007820000
         serialized=0203049367040309c4c8060808cb850007820000
   onion_hop[1]: 2
         field[2]=049367
         field[4]=09c4c8
         field[8]=54732ca34d13d2696030b513277af284844fca08b376c6f545d0cc57b81903bc0f4240
         serialized=0203049367040309c4c8082354732ca34d13d2696030b513277af284844fca08b376c6f545d0cc57b81903bc0f4240

The CLTV entries (field[4]) match up since the destination checks the incoming CLTV for tampering.

This seems all correct, the CLTV fields from the penultimate hop are copied over to the final hop so it can verify, and the values appear to be encoded correctly.

Comparison of pay vs sendpay

Notice the following are new attempts, so the values will change slightly from above!

Let's try to compare the createonion call in sphinx.c to see if there are
significant changes between going through pay or sendpay. The following is
the dump from pay:

    XXX createonionpacket 2 hops
    XXX   sphinx_hop_payload[0]=14  02 03 019a36  04 03 09c4c8  06 08 08cb850007820000, nodeid=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f
    XXX   sphinx_hop_payload[1]=2f  02 03 019a36  04 03 09c4c8  08 23 54732ca34d13d2696030b513277af284844fca08b376c6f545d0cc57b81903bc0f4240, nodeid=03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898

And the following is through sendpay:

    XXX createonionpacket 2 hops
    XXX   sphinx_hop_payload[0]=14  02 03 0493e0  04 03 09c4ad  06 08 08cb850007820000, nodeid=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f
    XXX   sphinx_hop_payload[1]=0a  02 03 0493e0  04 03 09c4ad, nodeid=03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898

Again all of this appears to be correct, and the values match up mostly: pay fuzzes the CTLV values and the amount values, but the important thing is that the second to last node and the last one match up.

[cdecker]

Debugging the first_hop, first from sendpay:

first_hop: 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f 636733x2469x0 300000msat 153

And then from pay:

first_hop: 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f 636733x2469x0 51102msat 184

Notice that the discrepancy in th final CLTV comes from the invoice which specified a final CLTV delta of at least 40, whereas the default without invoice is 9.

[cdecker]

After delving into the wire messages resulting from calling pay and a perfectly matching sendpay call (same route, fixed session_key for the onion, same blockheight, and adding some instrumentation) I found that the onions are identical except for a single bit:

The following is from pay:

XXX getroute [{"id":"03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f","channel":"636733x2469x0","direction":1,"msatoshi":30000,"amount_msat":"30000msat","delay":184,"style":"tlv"},{"id":"03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898","channel":"576389x1922x0","direction":0,"msatoshi":30000,"amount_msat":"30000msat","delay":40,"style":"tlv"}]
XXX session_key 4141414141414141414141414141414141414141414141414141414141414141
XXX hop[0]: pubkey=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f payload=1302027530040309c4e0060808cb850007820000
XXX hop[1]: pubkey=03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898 payload=2e02027530040309c4e0082354732ca34d13d2696030b513277af284844fca08b376c6f545d0cc57b81903bc0f4240

and this one is from sendpay:

XXX session_key 4141414141414141414141414141414141414141414141414141414141414141
XXX hop[0]: pubkey=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f payload=1302027530040309c4e1060808cb850007820000
XXX hop[1]: pubkey=03e1210c8d4b236a53191bb172701d76ec06dfa869a1afffcfd8f4e07d9129d898 payload=2e02027530040309c4e1082354732ca34d13d2696030b513277af284844fca08b376c6f545d0cc57b81903bc0f4240

Notice the difference in the last byte of the 04 TLV field (040309c4e0 vs 040309c4e1). This is an off-by-one on the CLTVs in the onion payloads. This in turn comes from this line here:

lightning/lightningd/pay.c

Line 760 in 23af241

base_expiry = get_block_height(ld->topology) + 1;

If I add the same courtesy +1 to the absolute CLTV computed by the pay plugin we get absolutely identical onions, which is what I was hoping to see.

This leads me to the conclusion that they were expecting a +1 on the final CLTV delta, and sendpay adds that to the base_expiry whereas I forgot about that in the onion payload creation.

See f5b6120 for the really trivial fix (if that really fixes it...)

The bigger problem is that the recipient is wrong: it should not send an incorrect cltv expiry error, because we are using its desired expiry, and secondly that +1 is only a courtesy to allow for a block being found in the meantime. So either ACINQ or ZeusLN.app are wrong, but how to tell?

I was unable to test that my solution works since the channel was closed just before I could test it. So if anybody finds an endpoint with the same behavior let me know :-)

[cdecker]

Since I couldn't replicate this issue in a test (presumably because the erring node is not a c-lightning node), I did the next best thing and probed the network both with and without the +1 to the CLTV. The result makes me very confident that the issue is resolved by the change: after 4000+ probes with the +1 change not a single failed attempt due to an incorrect CLTV, whereas probing without the +1 produced dozens after only 100 probed nodes.

I think it's save to say we have solved by working around this, but we might want to investigate which implementation is causing this quirk.