failing link: unable to update commitment: cannot add duplicate keystone with error: internal error

[C-Otto]

Background

The error message "failing link: unable to update commitment: cannot add duplicate keystone with error: internal error" appeared in my logs, for reasons I don't understand. Afterwards the channel was unusable and my peer (running CLN) immediately force-closed the channel at 01:26.

The force-close transaction contains one outgoing HTLC (timeout, according to lncli closedchannels) with size 200003 sat.

My peer says:

I’m getting hit by several force closes for all kind of reasons in the last couple days. Ours is just “internal error” in my log

Relevant snippet from my logs:

01:26:09.438 [INF] PEER: NodeKey(PUBKEY) loading ChannelPoint(CHANPOINT)
01:26:09.439 [DBG] CNCT: New ChainEventSubscription(id=15) for ChannelPoint(CHANPOINT)
01:26:09.439 [INF] HSWC: ChannelLink(CHANPOINT): starting
01:26:09.439 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(CHANPOINT)
01:26:09.439 [INF] HSWC: ChannelLink(CHANPOINT): HTLC manager started, bandwidth=3663215408 mSAT
01:26:09.439 [INF] HSWC: ChannelLink(CHANPOINT): attempting to re-synchronize
01:26:09.439 [INF] PEER: Negotiated chan series queries with PUBKEY
01:26:09.519 [ERR] RPCS: [connectpeer]: error connecting to peer: already connected to peer: PUBKEY@IP2:48304
01:26:09.519 [ERR] RPCS: [/lnrpc.Lightning/ConnectPeer]: already connected to peer: PUBKEY@IP2:48304
01:26:09.839 [INF] HSWC: ChannelLink(CHANPOINT): received re-establishment message from remote side
01:26:09.851 [DBG] HSWC: ChannelLink(CHANPOINT): loaded 0 fwd pks
01:26:11.237 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=6133225)->(Chan ID=CHAN_ID, HTLC ID=4619)
01:26:11.991 [DBG] HSWC: ChannelLink(CHANPOINT): removing Add packet (Chan ID=0:0:0, HTLC ID=6133225) from mailbox
01:26:13.366 [DBG] HSWC: ChannelLink(CHANPOINT): settle-fail-filter &{1 [0]}
01:26:13.366 [DBG] HSWC: ChannelLink(CHANPOINT): Failed to send 500059997 mSAT
01:26:15.297 [DBG] CNCT: ChannelArbitrator(CHANPOINT): attempting state step with trigger=chainTrigger from state=StateDefault
01:26:15.297 [DBG] CNCT: ChannelArbitrator(CHANPOINT): new block (height=734163) examining active HTLC's
01:26:15.297 [DBG] CNCT: ChannelArbitrator(CHANPOINT): checking commit chain actions at height=734163, in_htlc_count=0, out_htlc_count=2
01:26:15.297 [DBG] CNCT: ChannelArbitrator(CHANPOINT): no actions for chain trigger, terminating
01:26:15.297 [DBG] CNCT: ChannelArbitrator(CHANPOINT): terminating at state=StateDefault
01:26:16.485 [DBG] HSWC: ChannelLink(CHANPOINT): settle-fail-filter &{1 [0]}
01:26:16.485 [DBG] HSWC: ChannelLink(CHANPOINT): Failed to send 1000047000 mSAT
01:26:26.905 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=6133240)->(Chan ID=CHAN_ID, HTLC ID=4620)

01:26:26.956 [ERR] HSWC: ChannelLink(CHANPOINT): failing link: unable to update commitment: cannot add duplicate keystone with error: internal error

01:26:26.956 [INF] HSWC: ChannelLink(CHANPOINT): exited
01:26:26.957 [INF] HSWC: ChannelLink(CHANPOINT): stopping

Your environment

• lnd 0.14.3-beta-rc1
• Linux server 5.10.0-10-amd64 #1 SMP Debian 5.10.84-1 (2021-12-08) x86_64 GNU/Linux
• bitcoind v23

Steps to reproduce

Have non-anchor channel with CLN behind tor. Have somewhat flaky connection. Send HTLCs to peer.

[Roasbeef]

lnd 0.14.3-beta-rc1

Any reason this node is running the production release of this version?

I wonder if this was actually an inadvertent HTLC replay attempt....

[C-Otto]

I checked the commits following rc1 and didn't see anything that interested me, so I didn't update (I might be wrong, of course, updating as we speak). What do you mean with "production release"? I'm running my own version with a few patches (logging, non-random channel picking for parallel channels).

[Crypt-iQ]

This could happen if c-lightning was sending settles earlier than expected, but I don't think they're doing that: #6246

Do you have more in-depth logs you can share leading up to this point? Are PEER debug logs off?

[C-Otto]

I have debuglevel=info,CNCT=debug,DISC=warn,HSWC=debug,NANN=debug,WTCL=warn. What exactly do you need? The logs above show everything I have for the CHANPOINT (EDIT: In that timeframe).

[Crypt-iQ]

Did your logs rotate or something? The channel has a history of 4620 htlc's so hopefully there are more logs from before the reestablish message was received

[C-Otto]

I have lots of logs, no worries. Just tell me what you need, I won't send over gigabytes of logs, though :)

[Crypt-iQ]

I think you should have at least one log line that is identical to the one pasted above (HTLC ID=4620 is what matters):

queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=<can be anything>)->(Chan ID=CHAN_ID, HTLC ID=4620)

If you could send ~1min before the earliest identical log line until the point pasted in the OP, that would help narrow things down. I don't need the channel ids/payment hashes/ips/pubkeys etc, HSWC logs only.

[C-Otto]

Yes.

22:10:16.275 [INF] HSWC: ChannelLink(CHANPOINT): HTLC manager started, bandwidth=4163275405 mSAT
22:10:16.275 [INF] HSWC: ChannelLink(CHANPOINT): attempting to re-synchronize
22:10:16.276 [INF] PEER: Negotiated chan series queries with PUBKEY
22:10:18.611 [INF] HSWC: ChannelLink(CHANPOINT): received re-establishment message from remote side
22:10:18.618 [DBG] HSWC: ChannelLink(CHANPOINT): loaded 46 fwd pks
22:10:18.618 [DBG] HSWC: ChannelLink(CHANPOINT): removing completed fwd pkg for height=13475
[...]
22:10:19.218 [DBG] HSWC: ChannelLink(CHANPOINT): removing completed fwd pkg for height=13520
22:10:32.588 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=6124133)->(Chan ID=CHANID, HTLC ID=4618)
22:10:32.659 [DBG] HSWC: ChannelLink(CHANPOINT): removing Add packet (Chan ID=0:0:0, HTLC ID=6124133) from mailbox
22:11:08.935 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=OTHER_CHANID, HTLC ID=7856)->(Chan ID=CHANID, HTLC ID=4619)
22:11:39.744 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=6124179)->(Chan ID=CHANID, HTLC ID=4620)
22:11:44.869 [DBG] CNCT: ChannelArbitrator(CHANPOINT): attempting state step with trigger=chainTrigger from state=StateDefault
22:11:44.869 [DBG] CNCT: ChannelArbitrator(CHANPOINT): new block (height=734142) examining active HTLC's
22:11:44.869 [DBG] CNCT: ChannelArbitrator(CHANPOINT): checking commit chain actions at height=734142, in_htlc_count=0, out_htlc_count=1
22:11:44.869 [DBG] CNCT: ChannelArbitrator(CHANPOINT): no actions for chain trigger, terminating
22:11:44.869 [DBG] CNCT: ChannelArbitrator(CHANPOINT): terminating at state=StateDefault
22:12:04.253 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=0:0:0, HTLC ID=6124191)->(Chan ID=CHANID, HTLC ID=4621)
22:12:08.995 [ERR] HSWC: ChannelLink(CHANPOINT): failing link: unable to complete dance with error: remote unresponsive
22:12:08.995 [INF] HSWC: ChannelLink(CHANPOINT): exited
22:12:08.995 [INF] HSWC: ChannelLink(CHANPOINT): stopping

[C-Otto]

In between those (22:12:08 and 01:26:09) I don't have any HSWC log message for that peer/channel.

[Crypt-iQ]

Do you see this and if so, what time? I might be missing a space or something - this will be under OTHER_CHANID's chanpoint

queueing removal of SETTLE closed circuit: (Chan ID=OTHER_CHANID, HTLC ID=7856)->(Chan ID=CHANID, HTLC ID=4619)

[C-Otto]

22:11:08.935 [DBG] HSWC: ChannelLink(CHANPOINT): queueing keystone of ADD open circuit: (Chan ID=OTHER_CHANID, HTLC ID=7856)->(Chan ID=CHAN_ID, HTLC ID=4619)
22:12:08.996 [DBG] HSWC: ChannelLink(OTHER_CHANPOINT): queueing removal of FAIL closed circuit: (Chan ID=OTHER_CHANID, HTLC ID=7856)->(Chan ID=0:0:0, HTLC ID=0)
22:12:09.018 [DBG] HSWC: ChannelLink(OTHER_CHANPOINT): removing Fail/Settle packet (Chan ID=OTHER_CHANID, HTLC ID=7856) from mailbox