Improve channel force close logging

[C-Otto]

Background

My node force-closed a channel and the logs don't help me understand why this happened. I'd like this issue to be resolved by updating the log statements to contain the necessary information. In addition to this, I'd appreciate an explanation.

Your environment

• lnd 0.12.1
• Linux server 4.19.0-14-amd64 Fix name typo in README #1 SMP Debian 4.19.171-2 (2021-01-30) x86_64 GNU/Linux
• bitcoind 0.21.0 (bitcoin core)

Expected behaviour

The logs tell me why the channel was force-closed.

Actual behaviour

Note that the force-close transaction has two outputs, one already swept by my peer, the other timelocked for me. This makes me believe that my peer was online (but not connected to my node?).

1. HTLCs, failing with "unable to complete dance error: remote unresponsive"
2. disabling channel
3. Updating link policy?!
4. GossipSyncer is active with peer?!
5. Force-close

(BST)

2021-05-20 03:16:15.988 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID_UNRELATED_NODE1__): forwarding 1 packets to switch
2021-05-20 03:16:16.076 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID__): queueing keystone of ADD open circuit: (Chan ID=__SHORT_CHAN_ID_UNRELATED_NODE1__, HTLC ID=1835)->(Chan ID=__SHORT_CHAN_ID__, HTLC ID=36)
2021-05-20 03:16:16.437 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID__): removing Add packet (Chan ID=__SHORT_CHAN_ID_UNRELATED_NODE1__, HTLC ID=1835) from mailbox
--
2021-05-20 03:33:01.864 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID_UNRELATED_NODE2__): forwarding 1 packets to switch
2021-05-20 03:33:01.952 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID__): queueing keystone of ADD open circuit: (Chan ID=__SHORT_CHAN_ID_UNRELATED_NODE2__, HTLC ID=542)->(Chan ID=__SHORT_CHAN_ID__, HTLC ID=37)
2021-05-20 03:34:02.080 [ERR] HSWC: ChannelLink(__SHORT_CHAN_ID__): failing link: unable to complete dance with error: remote unresponsive
2021-05-20 03:34:02.081 [INF] HSWC: ChannelLink(__SHORT_CHAN_ID__): exited
2021-05-20 03:34:02.082 [INF] HSWC: Removing channel link with ChannelID(__CHANNEL_ID__)
2021-05-20 03:34:02.084 [INF] HSWC: ChannelLink(__SHORT_CHAN_ID__): stopping
2021-05-20 03:34:02.086 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID_UNRELATED_NODE2__): queueing removal of FAIL closed circuit: (Chan ID=__SHORT_CHAN_ID_UNRELATED_NODE2__, HTLC ID=542)->(Chan ID=0:0:0, HTLC ID=0)
2021-05-20 03:34:02.320 [DBG] HSWC: ChannelLink(__SHORT_CHAN_ID_UNRELATED_NODE2__): removing Fail/Settle packet (Chan ID=__SHORT_CHAN_ID_UNRELATED_NODE2__, HTLC ID=542) from mailbox
--
2021-05-20 03:54:48.643 [INF] NANN: Announcing channel(__CHAN_POINT__) disabled [detected]
---
2021-05-20 15:04:00.704 [DBG] HSWC: Unable to find ChannelPoint(__CHAN_POINT__) to update link policy
---
2021-05-20 15:46:09.083 [INF] DISC: GossipSyncer(__REMOTE_PUBKEY__): applying gossipFilter(start=2021-05-20 15:46:09.083263967 +0100 BST m=+1810838.985025483, end=2157-06-26 21:14:24.083263967 +0000 GMT)
---
2021-05-20 15:52:06.400 [DBG] HSWC: Unable to find ChannelPoint(__CHAN_POINT__) to update link policy
---
2021-05-22 14:03:37.887 [INF] CRTR: Pruning channel graph using block 00000000000000000001cec503af2292875dc44437f4875f877cb498e7e4d675 (height=684537)
2021-05-22 14:03:38.091 [INF] CRTR: Block 00000000000000000001cec503af2292875dc44437f4875f877cb498e7e4d675 (height=684537) closed 1 channels
2021-05-22 14:03:38.971 [INF] NTFN: New block: height=684537, sha=00000000000000000001cec503af2292875dc44437f4875f877cb498e7e4d675
2021-05-22 14:03:38.972 [INF] UTXN: Attempting to graduate height=684537: num_kids=0, num_babies=0
2021-05-22 14:03:38.973 [ERR] LTND: Unable to lookup witness: no witnesses
2021-05-22 14:03:39.060 [INF] CNCT: ChannelArbitrator(__CHAN_POINT__): force closing chan
2021-05-22 14:03:39.172 [INF] HSWC: Removing channel link with ChannelID(__CHANNEL_ID__)
2021-05-22 14:03:39.308 [INF] CNCT: Broadcasting force close transaction [...]
2021-05-22 14:03:39.315 [INF] LNWL: Inserting unconfirmed transaction __CLOSE_TX_HASH__
2021-05-22 14:03:39.598 [INF] CNCT: ChannelArbitrator(__CHAN_POINT__): trigger chainTrigger moving from state StateCommitmentBroadcasted to StateCommitmentBroadcasted

Related questions:

• Why didn't lnd reconnect to the peer?
• Why do I see policy/gossip messages for that peer, after the error?

[C-Otto]

I'm in contact with the peer node admin and we're comparing logs. It seems our nodes where connected the entire time, well before the "dance" issue, up to the force-close.

[C-Otto]

From my peer's logs:

(UTC-5)

2021-05-19 21:39:12.988 [ERR] HSWC: ChannelLink(__SHORT_CHAN_ID__): failing link: unable to complete dance with error: remote unresponsive
2021-05-19 21:39:12.988 [INF] HSWC: ChannelLink(__SHORT_CHAN_ID__): exited
2021-05-19 21:39:12.988 [INF] HSWC: Removing channel link with ChannelID(__CHAN_ID__)
2021-05-19 21:39:12.988 [INF] HSWC: ChannelLink(__SHORT_CHAN_ID__): stopping

[Roasbeef]

Is this a duplicate of that other instance? Easier to keep track of things if everything is reported to a single issue.

2021-05-19 21:39:12.988 [ERR] HSWC: ChannelLink(SHORT_CHAN_ID): failing link: unable to complete dance with error: remote unresponsive

This means the remote peer didn't respond w/ a commitment signature when it needed to do so. We added this to detect stale connections, so something was up w/ their node, exactly what I'm not sure but it was effectively "stuck" for 1 minute (the current default timeout). If the node was an ACINQ node, then they've recently fixed a force close divergence related to a divergence in the way nodes sort HTLCs.

[C-Otto]

You mean #5313? Those are/were different channels and issues.

The remote node is lnd 0.13.0 rc something, YTMND, @Max in slack

[Crypt-iQ]

Your version (v0.12.1) and your peer's version (v0.13.0) would force close on each other in certain cases. Two v0.13.0 nodes should not, if they do please file an issue

[C-Otto]

Alright. Could you share some details on this? I guess this shouldn't happen, no matter the versions.

[C-Otto]

Just to clarify: I raised this issue so that the log output can be improved. As a user I want (need?) to know the reason for a force-close. In this specific case I still have no clue.

[Crypt-iQ]

Alright. Could you share some details on this? I guess this shouldn't happen, no matter the versions.

We had some faulty logic in our channel state machine that would cause a force close when going down and up, that's about all I can say without getting too deep into the inner workings of the state machine. See here: #5231

[C-Otto]

Ok. Assuming something like this might happen again, would it be possible to add some information to the logs? Something like "X happened, should not happen, force-closing channel just to be on the safe side" is better than nothing...