Possible loss? of funds bug when using htlc_accepted hook

[daywalker90]

I'm currently missing about 600k sats from listfunds. Please look at these force close txs:
https://mempool.space/address/bc1q78n64w0q5ec6m86j7m9fupz0fqjt03kzlj7zsjgyuezfp00tmres9fp720
https://mempool.space/address/bc1qts3g5rfsf0ance3tx072vm0qwe5q2uf6gvkeafu9kzw0hue9yh2qx0u972
https://mempool.space/address/bc1qacsdf9npstwuaz3qgqvlx7trwv9ek8dndgslj8r30w6pyed49zmsh2lq4z
The stuck htlcs with around 200k sats are still on that script address and are missing from my listfunds despite the time lock being over. Any help to recover these would be highly appreciated!

This is what happened on all 3 of these:
I wrote a plugin for rebalancing and used my htlc_accepted hook instead of invoices. I craft the routes myself and on the final hop i set a 20 blocks delay. This worked fine for a while and i probably had 1000+ successfull rebalances without any problems. But then these force closes happened. When i looked in the logs this is what i saw in the normal case where my plugin resolved a rebalance (from memory):

lightningd: calling plugin hook
plugin: log line with payment_hash and preimage
plugin returned from hook with result "resolved"

In the force close cases i saw this, all within 1s:

lightningd: calling plugin hook
plugin: log line with payment_hash and preimage
lightningd: htlc about to expire, force closing (???)

So right before the Ok(json!({"result":"resolve","payment_key":pi})) return of my plugin cln rather force closed the channel and now has apparently lost track (?) of these htlcs.

[cdecker]

Is the channel still being listed in listpeers? If yes it likely will still sweep them. For background: the unilateral close timeout is buy one of the timeouts. Each HTLC has their own timeout that will be longer than the unilateral close timeouts in some cases.

Also, if you didn't settle the HTLC using the preimage before the HTLC timeout gut, then the HTLC value still belongs to the sender, not you, so they'll sweep eventually

[daywalker90]

No they are no longer in listpeers and since these are rebalances i'm the sender right?

[daywalker90]

to be clear: i looked for this because i'm missing aroung 600k sats and this fits too perfectly for it to be a coincidence

[daywalker90]

i managed to reproduce this on my testnet node using the htlc_accepted hook version of the plugin, which i modified to also not delete pays immediately and i'll post this as an example of one of the force closed channels:

{
         "id": "036497fee1a0b963a63f0b4374819d9016fcca9c09dbef4cb427a2d0146649b025",
         "connected": true,
         "num_channels": 1,
         "netaddr": [
            "11.212.3.1:35372"
         ],
         "features": "800000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000002000888a52a1",
         "channels": [
            {
               "state": "ONCHAIN",
               "scratch_txid": "295def5d47a21e4be8f6c85bfa22eff9377e88a285c6e476da6ce37e01cebac4",
               "last_tx_fee_msat": "227000msat",
               "feerate": {
                  "perkw": 253,
                  "perkb": 1012
               },
               "owner": "onchaind",
               "short_channel_id": "2423803x22x5",
               "direction": 1,
               "channel_id": "074deddc4bec712285affa36db7f887ad6c85fe87f22e6e88ada7d14a5a6dd2f",
               "funding_txid": "2adda6a5147dda8ae8e6227fe85fc8d67a887fdb36faaf852271ec4bdced4d07",
               "funding_outnum": 5,
               "close_to_addr": "tb1qyg7f62kjj5d3nlcr0vxnsjuqc7dt0cmkkr7fap",
               "close_to": "0014223c9d2ad2951b19ff037b0d384b80c79ab7e376",
               "private": false,
               "opener": "local",
               "closer": "remote",
               "alias": {
                  "local": "11721046x1626367x40683"
               },
               "features": [
                  "option_static_remotekey"
               ],
               "funding": {
                  "local_msat": "100000000msat",
                  "remote_msat": "0msat",
                  "pushed_msat": "0msat",
                  "local_funds_msat": "100000000msat",
                  "remote_funds_msat": "0msat"
               },
               "msatoshi_to_us": 19121657,
               "to_us_msat": "19121657msat",
               "msatoshi_to_us_min": 2335026,
               "min_to_us_msat": "2335026msat",
               "msatoshi_to_us_max": 100000000,
               "max_to_us_msat": "100000000msat",
               "msatoshi_total": 100000000,
               "total_msat": "100000000msat",
               "fee_base_msat": "0msat",
               "fee_proportional_millionths": 1200,
               "dust_limit_satoshis": 546,
               "dust_limit_msat": "546000msat",
               "max_htlc_value_in_flight_msat": 18446744073709551615,
               "max_total_htlc_in_msat": "18446744073709551615msat",
               "their_channel_reserve_satoshis": 1000,
               "their_reserve_msat": "1000000msat",
               "our_channel_reserve_satoshis": 1000,
               "our_reserve_msat": "1000000msat",
               "spendable_msatoshi": 17494657,
               "spendable_msat": "17494657msat",
               "receivable_msatoshi": 78878343,
               "receivable_msat": "78878343msat",
               "htlc_minimum_msat": 1,
               "minimum_htlc_in_msat": "1msat",
               "minimum_htlc_out_msat": "1000msat",
               "maximum_htlc_out_msat": "99000000msat",
               "their_to_self_delay": 6,
               "our_to_self_delay": 144,
               "max_accepted_htlcs": 10,
               "state_changes": [
                  {
                     "timestamp": "2023-03-09T23:37:19.459Z",
                     "old_state": "CHANNELD_AWAITING_LOCKIN",
                     "new_state": "CHANNELD_NORMAL",
                     "cause": "user",
                     "message": "Lockin complete"
                  },
                  {
                     "timestamp": "2023-03-11T15:37:00.782Z",
                     "old_state": "CHANNELD_NORMAL",
                     "new_state": "AWAITING_UNILATERAL",
                     "cause": "protocol",
                     "message": "Fulfilled HTLC 486 SENT_REMOVE_COMMIT cltv 2424059 hit deadline"
                  },
                  {
                     "timestamp": "2023-03-11T15:40:00.932Z",
                     "old_state": "AWAITING_UNILATERAL",
                     "new_state": "FUNDING_SPEND_SEEN",
                     "cause": "onchain",
                     "message": "Onchain funding spend"
                  },
                  {
                     "timestamp": "2023-03-11T15:40:00.957Z",
                     "old_state": "FUNDING_SPEND_SEEN",
                     "new_state": "ONCHAIN",
                     "cause": "onchain",
                     "message": "Onchain init reply"
                  }
               ],
               "status": [
                  "ONCHAIN:Tracking our own unilateral close",
                  "ONCHAIN:5 outputs unresolved: in 134 blocks will spend DELAYED_OUTPUT_TO_US (295def5d47a21e4be8f6c85bfa22eff9377e88a285c6e476da6ce37e01cebac4:1) using OUR_DELAYED_RETURN_TO_WALLET"
               ],
               "in_payments_offered": 487,
               "in_msatoshi_offered": 700671740,
               "in_offered_msat": "700671740msat",
               "in_payments_fulfilled": 483,
               "in_msatoshi_fulfilled": 483000000,
               "in_fulfilled_msat": "483000000msat",
               "out_payments_offered": 638,
               "out_msatoshi_offered": 11199893454,
               "out_offered_msat": "11199893454msat",
               "out_payments_fulfilled": 476,
               "out_msatoshi_fulfilled": 562878343,
               "out_fulfilled_msat": "562878343msat",
               "htlcs": [
                  {
                     "direction": "in",
                     "id": 486,
                     "msatoshi": 1000000,
                     "amount_msat": "1000000msat",
                     "expiry": 2424059,
                     "payment_hash": "b9b42cfe91e61f91c135d41ed62e372fd71f82c409c76c7734021740ecffd445",
                     "state": "SENT_REMOVE_COMMIT",
                     "status": "Waiting for the htlc_accepted hook of plugin sling"
                  }
               ]
            }
         ]
      }

listsendpays -k payment_hash=b9b42cfe91e61f91c135d41ed62e372fd71f82c409c76c7734021740ecffd445
{
   "payments": [
      {
         "id": 14171,
         "payment_hash": "b9b42cfe91e61f91c135d41ed62e372fd71f82c409c76c7734021740ecffd445",
         "groupid": 1,
         "destination": "03da2efc78ba5420088e636e542e3b484d3e514e2fca7672c0450215f7a9f2fd3e",
         "msatoshi": 1000000,
         "amount_msat": "1000000msat",
         "msatoshi_sent": 1001504,
         "amount_sent_msat": "1001504msat",
         "created_at": 1678549017,
         "completed_at": 1678549021,
         "status": "complete",
         "payment_preimage": "fb944ebf005260e3114ce6cd586e36eb79a05d898c93c14a2039b1f28e7f6fff"
      }
   ]
}

and the force close tx:
https://mempool.space/testnet/tx/295def5d47a21e4be8f6c85bfa22eff9377e88a285c6e476da6ce37e01cebac4
where the htlc amount goes to the same address than my side of the balance:
https://mempool.space/testnet/address/tb1q05f974nlztjuzspp4s9nznmgrcane4r4pyxmqamr4nphphjexgfsjmt09p
(same pattern as on mainnet)

here are the logs filtered by the pubkey of the force closed channel (is that enough?):
036497fee1a0b963a63f0b4374819d9016fcca9c09dbef4cb427a2d0146649b025.log

with my layman knowledge reading the logs it looks like the htlc got fully accepted but then the channel decided to force close the channel anyways because it hit a deadline(which it didn't actually)

also: the same might have happened with the invoice version of my plugin (have to wait for the timeout to see) so maybe this is not connected to the hook, but can't say for sure yet.

[daywalker90]

on testnet i was using 23.02 and on mainnet the hook related fc's were on 22.11 and the invoice one on 23.02 aswell. On testnet i was using much smaller amounts and they already got swept to my wallet including the htlcs. So maybe this got fixed in 23.02. But these fc's shouldn't have happened in the first place.

[daywalker90]

the htlc on the invoice related fc is also not getting swept by my node: https://mempool.space/address/bc1qpc5uxfaykrpa7dvx7kk99md0yv7jgefj9lzpeqe4pl7p07wfg0pq7k80lq

[daywalker90]

if i understand this correctly:

lightning/lightningd/peer_htlcs.c

Line 2646 in bfc6fed

return hin->cltv_expiry - (ld->config.cltv_expiry_delta + 1)/2;

it makes sense why a force close was triggered since my cltv-delta was 140 and the last delay on the route was 50. So it was probably always a race between accepting the htlc and the deadline check. What i dont understand yet is why on mainnet they did not get swept but on testnet they did. Also why getroute and pay get away with routes that have 9 as the default last delay.