stuck channel, waiting for sweep that already happened

[ksedgwic]

Issue and Steps to Reproduce

Channel appears "stuck" waiting for a sweep that has already happened

• The node is running in testnet w/ a VLS signer. The signer version was tracking our v0.11.0 release candidates.
• The machine involved was tracking the CLN RC candidates as they happened, is now running CLN v24.02.

Investigating because VLS thinks this channel should be forgotten (but is waiting for forget_channel from CLN and is nagging ...)

Wed 2024-02-28 19:03:06 PST home4 vlsd2[1882874]: [2024-02-29 03:03:06.982 vlsd2/lightning_signer::monitor WARN] expected forget_channel for 0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d780700000000000000 overdue by 363 blocks

Questions:

• Why are we still broadcasting the sweep after we saw it?
• Did we miss the sweep?
• There was a reorg, we saw the sweep confirmed twice, is this significant?
• What is the eventual resolution of this? Will it eventually clear?

Additional files:
2024-02-stuck-channel.tar.gz

Additional files in the tarball:

• listpeerchannels.md listpeerchannels 0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78
• 1f15802b.log grep 1f15802b lightning.log
• 867dc568.log grep 867dc568 lightning.log
• 2024-02-24_19:00.log journalctl around the sweep

Channel facts:

dbid: 7
vls-chan: 0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d780700000000000000
funding: abeef1db3a355927a10def6464585bd9abdb93c4aa11659c3beb1c912bed7898:0
closing: 867dc568dc494a9c86657b4f4f60cf5dcac06f41baa831ab9f58a9f5cbf49cd2 @ 2024-02-23 12:44 (Pacific)
sweep: 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f @ 2024-02-24 19:34 (Pacific)

We saw the sweep: (grep 1f15802b6)

2024-02-23T23:50:19.478Z DEBUG   lightningd: Deferring broadcast of txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f until block 2579409
2024-02-25T03:14:13.141Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:15:05.740Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:16:03.985Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:16:36.235Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:17:10.467Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:17:58.693Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:18:54.925Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:19:54.166Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:20:28.423Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:21:11.729Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:22:09.993Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:22:43.230Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:23:24.496Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:24:18.783Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:24:55.052Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:25:44.283Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:26:43.548Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:27:27.831Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:28:16.095Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:29:11.350Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:29:47.583Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:30:37.877Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:31:20.147Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:32:18.412Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:33:11.664Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:34:02.912Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: RBF onchain txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat) with txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f (fee 122sat)
2024-02-25T03:34:13.992Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-chan#7: Got UTXO spend for 867dc568dc494a9c86657b4f4f60cf5dcac06f41baa831ab9f58a9f5cbf49cd2:0: 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f
2024-02-25T03:34:13.996Z DEBUG   wallet: Owning output 0 984703sat (SEGWIT) txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f CONFIRMED
2024-02-25T03:34:14.027Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-onchaind-chan#7: Resolved OUR_UNILATERAL/DELAYED_OUTPUT_TO_US by our proposal OUR_DELAYED_RETURN_TO_WALLET (1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f)
2024-02-25T03:34:14.034Z DEBUG   lightningd: Got first depth change ->4294967295 for 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f
2024-02-25T03:53:14.699Z DEBUG   lightningd: Got depth change 1->0 for 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f REORG
2024-02-25T03:53:14.985Z DEBUG   wallet: Owning output 0 984703sat (SEGWIT) txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f CONFIRMED
2024-02-27T22:27:26.645Z DEBUG   lightningd: Broadcasting txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f
2024-02-28T02:13:31.472Z DEBUG   lightningd: Broadcasting txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f
2024-02-28T02:23:29.724Z DEBUG   lightningd: Broadcasting txid 1f15802b6190435849354b438d32cddb1aa3574483f63137bb631a735430136f

Why are we rebroadcasting after we've seen the sweep?

Much later node is still looking for the sweep:

2024-02-29T03:21:03.534Z DEBUG   lightningd: Got depth change 609->610 for 867dc568dc494a9c86657b4f4f60cf5dcac06f41baa831ab9f58a9f5cbf49cd2
2024-02-29T03:21:03.545Z DEBUG   0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78-onchaind-chan#7: billboard: 1 outputs unresolved: waiting confirmation that we spent DELAYED_OUTPUT_TO_US (867dc568dc494a9c86657b4f4f60cf5dcac06f41baa831ab9f58a9f5cbf49cd2:0) using OUR_DELAYED_RETURN_TO_WALLET

From listpeerchannels 0274fa8311c650e76a1897db1cca2fb20d598ded5b62d72f452fd2debea3499d78:

         "state_changes": [
            {
               "timestamp": "2024-01-04T23:23:02.428Z",
               "old_state": "CHANNELD_AWAITING_LOCKIN",
               "new_state": "CHANNELD_NORMAL",
               "cause": "user",
               "message": "Lockin complete"
            },
            {
               "timestamp": "2024-02-23T20:38:39.946Z",
               "old_state": "CHANNELD_NORMAL",
               "new_state": "CHANNELD_SHUTTING_DOWN",
               "cause": "user",
               "message": "User or plugin invoked close command"
            },
            {
               "timestamp": "2024-02-23T20:41:40.391Z",
               "old_state": "CHANNELD_SHUTTING_DOWN",
               "new_state": "AWAITING_UNILATERAL",
               "cause": "user",
               "message": "Forcibly closed by `close` command timeout"
            },
            {
               "timestamp": "2024-02-23T20:44:54.519Z",
               "old_state": "AWAITING_UNILATERAL",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-23T20:44:54.919Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-23T21:05:26.901Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-23T21:05:27.071Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-23T23:50:18.627Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-23T23:50:18.898Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-27T22:27:25.543Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-27T22:27:25.947Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-28T02:13:29.952Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-28T02:13:30.256Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-28T02:23:28.854Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-28T02:23:29.476Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-28T02:24:52.997Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-28T02:24:53.963Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-28T08:00:23.355Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-28T08:00:23.604Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            },
            {
               "timestamp": "2024-02-29T00:12:28.637Z",
               "old_state": "ONCHAIN",
               "new_state": "FUNDING_SPEND_SEEN",
               "cause": "user",
               "message": "Onchain funding spend"
            },
            {
               "timestamp": "2024-02-29T00:12:29.775Z",
               "old_state": "FUNDING_SPEND_SEEN",
               "new_state": "ONCHAIN",
               "cause": "user",
               "message": "Onchain init reply"
            }
         ],
         "status": [
            "ONCHAIN:Tracking our own unilateral close",
            "ONCHAIN:1 outputs unresolved: waiting confirmation that we spent DELAYED_OUTPUT_TO_US (867dc568dc494a9c86657b4f4f60cf5dcac06f41baa831ab9f58a9f5cbf49cd2:0) using OUR_DELAYED_RETURN_TO_WALLET"
         ],

[cdecker]

@rustyrussell probably knows the closing sequence best. We generally react to on-chain events, and try to be as stateless as possible, as state can diverge (reorg being one such occurrence). So it's not surprising we rebroadcast transactions a whole bunch of time.

It should have noticed 1f15 being confirmed and have marked the sweep as completed, but the funds were swept correctly seeing that we have the Owning output 0 lines in the logs, so it's mostly a bookkeeping issue.