Relai: Sweep is not executed after closed channel

[roeierez]

closing tx: https://blockstream.info/address/bc1qegwvckjfq8fv8terqxcu9nuv7dffn7n9y3htn69qjm8kmly0mzuqepk3m9
Node ID: 03606df0218e00b1d739db696e8d95ddfbff25293463395b95f21bb45638f10433
https://github.com/breez/breez-sdk-relai/issues/23

[cdecker]

This looks like an instance of #439, checking logs to corroborate this theory.

• It is the node closing the channel due to two stuck outgoing HTLCs Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by OUR_UNILATERAL (3a499df8882d890845ece833017263a176f3f90f6c0f0c2178faeacc01a31114)
• It is an anchor channel based on the presence of the two anchor outputs (330sats)

I notice that there are some lines related to HTLCs in onchaind being printed:

2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-connectd: Handed peer, entering loop
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-chan#1: onchain_failed_our_htlc
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-chan#1: HTLC id 60 failonion = (nil), failmsg = 0x3183e88, preimage = (nil)
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   lightningd: Plugin chanbackup returned from peer_connected hook call
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   lightningd: Calling peer_connected hook of plugin gl-plugin-internal
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-chan#1: onchain_failed_our_htlc
2024-04-26T13:07:41+02:00 {} stdout: DEBUG   0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835-chan#1: HTLC id 61 failonion = (nil), failmsg = 0x318d2d8, preimage = (nil)

[cdecker]

The good news is that the output is still being tracked:

Tracking output 3a499df8882d890845ece833017263a176f3f90f6c0f0c2178faeacc01a31114:2: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US

So this might still happen, I just couldn't find the time at which it'll be cleared. Keeping this open until we either end up in #439 or it is resolved.

[cdecker]

Looking at this again, we now see that there is a sweep transaction in the mempool of blockstream.info:

https://blockstream.info/tx/a95b6543f8ff3347628e2d3c07d94d649d21e830956cd27c38ce880716b5cfad?input:0&expand

This one has a low feerate, but it is being swept.

[cdecker]

Looking a bit further into this and it looks as follows:

The second stage HTLC transaction is what onchaind is currently trying to materialize on-chain:

RBF HTLC txid 3f312c8d7bb770eb2e3e83af6da8ef18c26e6fa19813513ec7026fd3d025b4f9 (fee 0sat) with txid 999c5f3d661740d35722b822d03307c940103de1c85a86d1b075a63ca7cfd76c (fee 6407sat)

Fetching this TX from the DB we find this:

{
    "addresses": [
        "bc1qmrqamgvftcr7sgd2un0hky78q59mlxpnzjydwn",
        "bc1qrddunzkgw2tpcelx5ljrk2809akm0duaa6m8622sc24pal2jdngqnxq0mq",
        "bc1qrlpmleqz5twrw4qph2kzq35ztpmmad3x3zkcgm9s5gg3p9aszpjsmqh0jv"
    ],
    "block_height": -1,
    "block_index": -1,
    "confirmations": 0,
    "double_spend": false,
    "fees": 6407,
    "hash": "999c5f3d661740d35722b822d03307c940103de1c85a86d1b075a63ca7cfd76c",
    "inputs": [
        {
            "addresses": [
                "bc1qrlpmleqz5twrw4qph2kzq35ztpmmad3x3zkcgm9s5gg3p9aszpjsmqh0jv"
            ],
            "age": 835979,
            "output_index": 2,
            "output_value": 72000,
            "prev_hash": "463972904772472b38fa1cc907e5143a5af1a008cb373179c22f4d824d72e11f",
            "script_type": "pay-to-witness-script-hash",
            "sequence": 1,
            "witness": [
                "",
                "30440220502fb0c8b252503ca6d2e852dc2a8eb7ddeefe4749bd3c2cf1c362fe96037c450220735d0d3ee41b30b1b470f94840ed16eb573860147d3c3948d6f8db4c118b489683",
                "3045022100a83d8ce261070b4a2b70c3de6b781b547639c9b2ae6de13cb593a03b951c07da022056f6a3a4fa9c2f8c5104c6382beb2d231c589df8cff040de5f0eed26072f40f883",
                "",
                "76a914b6708b88601edd3b3665385bbec012798f17d5498763ac672102236960f205efaff42abf92402bc7333910eb9357e4171ff3098749952e56965e7c820120876475527c2103221e1a195a8122edda735703f43e7395d46ebd328177bde3348d76556c02bc5d52ae67a91436f52a71f9d483647a6126734e7ef74fd55018c488ac6851b27568"
            ]
        },
        {
            "addresses": [
                "bc1qmrqamgvftcr7sgd2un0hky78q59mlxpnzjydwn"
            ],
            "age": 841340,
            "output_index": 1,
            "output_value": 231722,
            "prev_hash": "fe770e36682f73a91ee4fbe535828825f2900067492777510d1fa834f9161f93",
            "script_type": "pay-to-witness-pubkey-hash",
            "sequence": 4294967293,
            "witness": [
                "30450221008d570a8a2969cab9c5ce651e8efeeaf730b92a83efe050246ff018a3c3b13799022070bc5e47d5b5a307efa03b8135e4fd75f46ed3cc4968bb8eea6e26f9931120fc01",
                "025ce59295027ce550e4119024b926053a062abec50101f95a348c35376bd05662"
            ]
        }
    ],
    "lock_time": 835914,
    "opt_in_rbf": true,
    "outputs": [
        {
            "addresses": [
                "bc1qrddunzkgw2tpcelx5ljrk2809akm0duaa6m8622sc24pal2jdngqnxq0mq"
            ],
            "script": "00201b5bc98ac872961c67e6a7e43b28ef2f6db7b79deeb67d2950c2aa1efd526cd0",
            "script_type": "pay-to-witness-script-hash",
            "value": 72000
        },
        {
            "addresses": [
                "bc1qmrqamgvftcr7sgd2un0hky78q59mlxpnzjydwn"
            ],
            "script": "0014d8c1dda1895e07e821aae4df7b13c7050bbf9833",
            "script_type": "pay-to-witness-pubkey-hash",
            "value": 225315
        }
    ],
    "preference": "low",
    "received": "2024-05-15T12:40:18.258664904Z",
    "relayed_by": "35.170.65.89",
    "size": 561,
    "total": 297315,
    "ver": 2,
    "vin_sz": 2,
    "vout_sz": 2,
    "vsize": 265
}

So it is taking the 72ksat output and the 231722sat output of the closing transaction (HTLC and to_us respectively) to materialize the HTLC transaction. However that output has been spent by fe770e36682f73a91ee4fbe535828825f2900067492777510d1fa834f9161f93. So onchaind is still stuck in the materialization step, when we really should be sweeping the HTLC using the timeout branch. @rustyrussell and I expect this to be related to the restart not replaying the onchaind notifications correctly, thus onchaind misses that the HTLCs have been materialized.

The good news is that once we have fixed this we can just trigger a rescan and it will be picked up correctly.

[roeierez]

@cdecker LMK when you do the rescan so we will update the user. Does it need any cln upgrade?

[cdecker]

Well, yes, because I'm working on the v24.02 upgrade and won't put that aside for a one-off fix.