[bug]: commitment transaction dips peer below chan reserve: internal error causing eclair to FC

[TrezorHannes]

Background

For unknown reason (possible racecondition) my LND instance identified that a downstream HTLC commitment would have caused a channel peer balance going negative, and below our chan reserve for that channel.
That caused my LND to send my peer an internal error. @DerEwige running Eclair, which immediately going on-chain when receiving an internal error.

Two things to validate:

• the negative balance might happen quite often, for instance when > 1 HTLCs opened at the same time. Why would this cause an internal error and not just a failing HTLC?
• could we identify a different error message, being more verbose, to avoid other implementations interpreting this as a major issue and going on-chain?

Your environment

• version of lnd: lnd version 0.16.2-beta commit=v0.16.2-beta
• which operating system (uname -a on *Nix): Linux debian-nuc 5.10.0-20-amd64 #1 SMP Debian 5.10.158-2 (2022-12-13) x86_64 GNU/Linux
• version of btcd, bitcoind, or other backend: Bitcoin Core version v24.0.1
• any other relevant environment details: LND latest release AMD64 binary

Steps to reproduce

Log excerpt (full log grep of channel-id and pubkey attached)

2023-05-01 01:48:09.421 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 239283580 mSAT is larger than 234681168 mSAT
2023-05-01 01:48:17.098 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 766964171 mSAT is larger than 746420614 mSAT
2023-05-01 01:49:35.142 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 74920943 mSAT is larger than 11413159 mSAT
2023-05-01 01:53:07.050 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 63151008 mSAT is larger than 11413159 mSAT
2023-05-01 01:59:08.683 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 21053936 mSAT is larger than 11413159 mSAT
2023-05-01 01:59:50.614 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 207614045 mSAT is larger than 11413159 mSAT
2023-05-01 02:02:31.406 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 50011450 mSAT is larger than 11413159 mSAT
2023-05-01 02:02:47.147 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 50011450 mSAT is larger than 11413159 mSAT
2023-05-01 02:03:09.108 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 20556850 mSAT is larger than 11413159 mSAT
2023-05-01 02:04:24.172 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 11863529 mSAT is larger than 11413159 mSAT
2023-05-01 02:06:55.592 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): insufficient bandwidth to route htlc: 73006424 mSAT is larger than 11413159 mSAT
2023-05-01 02:08:36.525 [ERR] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): failing link: unable to update commitment: commitment transaction dips peer below chan reserve: our balance below chan reserve with error: internal error
2023-05-01 02:08:36.525 [ERR] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): link failed, exiting htlcManager
2023-05-01 02:08:36.525 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): exited
2023-05-01 02:08:36.525 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): stopping
2023-05-01 02:08:55.257 [INF] PEER: Peer(023631624e30ef7bcb2887e600da8e59608a093718bc40d35b7a57145a0f3db9af): Loading ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0), isPending=false
2023-05-01 02:08:55.257 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): starting
2023-05-01 02:08:55.257 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0)
2023-05-01 02:08:55.257 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): HTLC manager started, bandwidth=0 mSAT
2023-05-01 02:08:55.257 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): attempting to re-synchronize
2023-05-01 02:11:54.862 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): stopping
2023-05-01 02:11:54.862 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): error when syncing channel states: link shutting down
2023-05-01 02:11:54.862 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): exited
2023-05-01 02:12:04.983 [INF] PEER: Peer(023631624e30ef7bcb2887e600da8e59608a093718bc40d35b7a57145a0f3db9af): Loading ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0), isPending=false
2023-05-01 02:12:04.983 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): starting
2023-05-01 02:12:04.983 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0)
2023-05-01 02:12:04.983 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): HTLC manager started, bandwidth=0 mSAT
2023-05-01 02:12:04.984 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): attempting to re-synchronize
2023-05-01 02:15:03.445 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): stopping
2023-05-01 02:15:03.445 [WRN] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): error when syncing channel states: link shutting down
[....]
2023-05-01 02:40:20.520 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0)
2023-05-01 02:40:20.520 [INF] HSWC: ChannelLink(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): attempting to re-synchronize
2023-05-01 02:41:14.987 [INF] NTFN: Dispatching confirmed spend notification for outpoint=b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0, script=0 b0b3c81deb80ca8d88999cee148c5b2b5f1abef226d4d434139bdde0679f903e at current height=787714: 3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b[0] spending b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0 at height=787714
2023-05-01 02:41:14.996 [INF] CNCT: Unilateral close of ChannelPoint(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0) detected
2023-05-01 02:41:14.997 [INF] CNCT: ChannelArbitrator(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): remote party has closed channel out on-chain
2023-05-01 02:41:28.618 [INF] CNCT: ChannelArbitrator(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): still awaiting contract resolution
2023-05-01 02:41:28.737 [INF] CNCT: *contractcourt.commitSweepResolver(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): Sweeping with witness type: CommitmentToRemoteConfirmed
2023-05-01 02:41:28.737 [INF] CNCT: *contractcourt.commitSweepResolver(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): sweeping commit output
2023-05-01 02:43:14.539 [INF] CNCT: *contractcourt.commitSweepResolver(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): local commitment output fully resolved by sweep tx: 6cf35d29f4170599173ed44cbd0bb5e8280699049447528c51405c906f416192
2023-05-01 02:43:14.578 [INF] CNCT: ChannelArbitrator(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): a contract has been fully resolved!
2023-05-01 02:43:14.578 [INF] CNCT: ChannelArbitrator(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0): still awaiting contract resolution
2023-05-01 02:59:20.520 [ERR] PEER: Peer(023631624e30ef7bcb2887e600da8e59608a093718bc40d35b7a57145a0f3db9af): Channel(b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0) request enabling failed due to inactive link

Expected behaviour

Proposal above, details better evaluated by folks who're more acustomed to cross-implementation error relays.

• let the HTLC fail with usual process
• don't send internal error

Actual behaviour

Sending an internal-error causing eclair to force-close
speedupln-fc.log

[DerEwige]

Here is the log from my side:

eclair.2023-05-01_02.log:2023-05-01 02:07:43,762 INFO  f.a.e.p.r.ChannelRelay PAY h:170265fb62c658c174b0dd7688e2d8d669c0271507991d608897b051af2148e0 p:9d5d0308 - relaying htlc #230485 from channelId=ebe6bd43f9ee41617fcc455c869eaba86a5edc98a0e4bd25ac698b2054bc508e to requestedShortChannelId=768220x2458x0 nextNode=037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3
eclair.2023-05-01_02.log:2023-05-01 02:07:49,525 INFO  f.a.e.p.r.ChannelRelay PAY h:170265fb62c658c174b0dd7688e2d8d669c0271507991d608897b051af2148e0 p:89da5cb3 - relaying htlc #230486 from channelId=ebe6bd43f9ee41617fcc455c869eaba86a5edc98a0e4bd25ac698b2054bc508e to requestedShortChannelId=768220x2458x0 nextNode=037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3
eclair.2023-05-01_02.log:2023-05-01 02:08:31,599 INFO  f.a.e.p.r.ChannelRelay PAY h:170265fb62c658c174b0dd7688e2d8d669c0271507991d608897b051af2148e0 p:d1610534 - relaying htlc #230491 from channelId=ebe6bd43f9ee41617fcc455c869eaba86a5edc98a0e4bd25ac698b2054bc508e to requestedShortChannelId=768220x2458x0 nextNode=037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3
eclair.2023-05-01_02.log:2023-05-01 02:08:36,629 ERROR f.a.e.c.fsm.Channel n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - peer sent error: ascii='internal error' bin=696e7465726e616c206572726f72
eclair.2023-05-01_02.log:2023-05-01 02:08:36,654 INFO  f.a.e.c.p.TxPublisher n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - publishing commit-tx txid=3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b spending b7e5622b25741ec8a5349feffe52059c58a0ae4e6dbf9ad466e6acfaab28c3ef:0 with id=39906b51-14ec-4cbf-a4e5-4b631ec3a1a1 (0 other attempts)
eclair.2023-05-01_02.log:2023-05-01 02:08:36,654 INFO  f.a.e.c.p.TxPublisher n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - publishing replaceable local-anchor spending 3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b:0 with id=d09acaa5-d561-47dc-9a62-38bf41aec4b1 (0 other attempts)
eclair.2023-05-01_02.log:2023-05-01 02:08:36,661 INFO  f.a.e.db.DbEventHandler n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - paying mining fee=0 sat for txid=3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b desc=commit-tx
eclair.2023-05-01_02.log:2023-05-01 02:08:36,661 INFO  f.a.e.c.p.TxPublisher n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - publishing local-main-delayed txid=b1a8e6c334074579d7cc5ad4726dc213f45ac49297b033585fa1dab4a60d3dc1 spending 3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b:5 with id=a8602e0e-210c-40a2-a91e-d854330f4434 (0 other attempts)
eclair.2023-05-01_02.log:2023-05-01 02:08:36,662 INFO  f.a.e.c.p.TxPublisher n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 - publishing replaceable htlc-timeout spending 3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b:4 with id=0cd27a09-d278-4d6b-b266-8ba550bf9f00 (0 other attempts)
eclair.2023-05-01_02.log:2023-05-01 02:08:36,662 INFO  f.a.e.c.p.TxTimeLocksMonitor n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 t:a8602e0e - local-main-delayed has a relative timeout of 360 blocks, watching parentTxId=3daf8760142f17a9a5156be37a6da706deafe088c61e1b0275d313be666cb67b
eclair.2023-05-01_02.log:2023-05-01 02:08:36,688 INFO  f.a.e.c.p.TxTimeLocksMonitor n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 t:0cd27a09 - delaying publication of htlc-timeout until block=788378 (current block=787704)
eclair.2023-05-01_02.log:2023-05-01 02:08:36,704 INFO  f.a.e.c.p.ReplaceableTxFunder n:037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3 c:efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7 t:d09acaa5 - skipping local-anchor: commit feerate is high enough (feerate=2500 sat/kw)

I just see that my node received an "internal error" from my peer and then force closed.

@Crypt-iQ Looks like another case of a link sending out "internal error" causing a force close

[ziggie1984]

@DerEwige could you check in your logs which was the latest UpdateAddHTLC msg which lead to this behaviour, especially the amt you tried to put on the remotes commitment transaction. What essentially happened is, your node tried to add an HTLC to the remotes commitment but at the current feerate your peer would have been forced to go below reserve.

According to the spec your SENDING node should:

if it is not responsible for paying the Bitcoin fee:
SHOULD NOT offer amount_msat if, once the remote node adds that HTLC to its commitment transaction, it cannot pay the fee for the updated local or remote transaction at the current feerate_per_kw while maintaining its channel reserve.

The RECEIVING node followed the spec in a way:

receiving an amount_msat that the sending node cannot afford at the current feerate_per_kw (while maintaining its channel reserve and any to_local_anchor and to_remote_anchor costs):
SHOULD send a warning and close the connection, or send an error and fail the channel.

Definitely worth checking why eclair added the htlc although it would force the peer to go below reserve.

Whether lnd sends a warning and closes the connection or sends an internal error should also be reevaluated.

[DerEwige]

ould you check in your logs which was the latest UpdateAddHTLC msg which lead to this behaviour, especially the amt you tried to put on the remotes commitment transaction. What essentially happened is, your node tried to add an HTLC to the remotes commitment but at the current feerate your peer would have been forced to go below reserve.

Unfortunately, I have most of my eclair running on log level “WARN”. This is due to the excessive amount of logs my rebalancing produces. So I don’t have any additional logs from my side.

I can only see from the logs of my plugin that I tried to send out payment through this channel:

eclair.2023-05-01_02.log:2023-05-01 02:08:36,329 INFO f.a.c.ChannelDB_ActiveBalancer_Multibalance - 768220x2458x0 Send through route [768220x2458x0, 734274x2495x1, 562892x872x0, 778983x2811x0] 0 0 0.0

The RECEIVING node followed the spec in a way:

receiving an amount_msat that the sending node cannot afford at the current feerate_per_kw (while maintaining its channel reserve and any to_local_anchor and to_remote_anchor costs):
SHOULD send a warning and close the connection, or send an error and fail the channel.

This case applies if the sender falls below the reserve.
But in this case, the receiving node could not afford the fees.

According to the spec your SENDING node should:

if it is not responsible for paying the Bitcoin fee:
SHOULD NOT offer amount_msat if, once the remote node adds that HTLC to its commitment transaction, it cannot pay the fee for the updated local or remote transaction at the current feerate_per_kw while maintaining its channel reserve.

This one applies. My node should not have sent the HTLC.
But there might bee a fee estimate discrepancy at this point?
My node might want 10 sat/vb and think it is good.
And when I try to add the HTLC the remote peer might disagree and want 15 sat/vb which would dip him below the reserve?

Somehow the specs does not say anything about how the receiver should act if it would dip him below the reserve? Did I miss that part?

[ziggie1984]

This case applies if the sender falls below the reserve.
But in this case, the receiving node could not afford the fees.

From my perspective this is the same, when you add an HTLC to the remote commit (sending an Update_ADD_HTLC), you as the sender need to make sure that you evaluate the transaction limits beforehand meaning that adding this new output in the current fee-environment should not let your peer fall below reserve. Your peer will just receive the amt and try to add it to the transaction at current feelimits, if that forces the peer to fall below its reserve it should fail this attempt (this is also what happened)

Somehow the specs does not say anything about how the receiver should act if it would dip him below the reserve? Did I miss that part?

Every channel has a synchronized feerate in sat/kweight which only the initiator can change via the update_fee msg. So the feerate was definitely the same, but why eclair and lnd diverged in the final calculation of the transaction is strange, maybe some rounding issue. Thats why I asked you supply the amount so that one could backtrace whether the boundaries were breached or not, but without logs very hard to do so.

But I must say this new check for an HTLC which is added to our commitment is very new (since 16.0 I think) so maybe something which will happen more often now(https://github.com/lightningnetwork/lnd/blob/master/lnwallet/channel.go#L3640)

Commit: 47c5809 (new fresh stuff^^) => not really new just log verbose level changed

[Roasbeef]

could we identify a different error message, being more verbose, to avoid other implementations interpreting this as a major issue and going on-chain?

From the spec PoV, the channel basically can't continue at this point. Similarly, if someone else us an invalid pre-image, that's also an invalid action and the channels can't continue.

This might ultimately be a interoperability issue: does the HTLC eclair send actually dip below the reserve? If so, can we repro that exact scenario to dig into the accounting between the implementations? Is it an mSAT rounding thing?

[DerEwige]

I had a second force close with the same issue:

peer logs:

2023-05-07 16:37:21.363 [ERR] HSWC: ChannelLink(8f50bc54208b69ac25bde4a098dc5e6aa8ab9e865c45cc7f6141eef943bde6eb:1): failing link: unable to update commitment: commitment transaction dips peer below chan reserve: our balance below chan reserve with error: internal error
2023-05-07 16:37:21.366 [ERR] HSWC: ChannelLink(8f50bc54208b69ac25bde4a098dc5e6aa8ab9e865c45cc7f6141eef943bde6eb:1): link failed, exiting htlcManager
2023-05-07 16:37:21.366 [INF] HSWC: ChannelLink(8f50bc54208b69ac25bde4a098dc5e6aa8ab9e865c45cc7f6141eef943bde6eb:1): exited
2023-05-07 16:37:21.366 [INF] HSWC: ChannelLink(8f50bc54208b69ac25bde4a098dc5e6aa8ab9e865c45cc7f6141eef943bde6eb:1): stopping

my logs:

2023-05-07 16:37:21,481 ERROR f.a.e.c.fsm.Channel n:020ca6f9aaebc3c8aab77f3532112649c28a0bfb1539d0c2a42f795fb6e4c363b2 c:ebe6bd43f9ee41617fcc455c869eaba86a5edc98a0e4bd25ac698b2054bc508e - peer sent error: ascii='internal error' bin=696e7465726e616c206572726f72
2023-05-07 16:37:21,511 INFO  f.a.e.c.p.TxPublisher n:020ca6f9aaebc3c8aab77f3532112649c28a0bfb1539d0c2a42f795fb6e4c363b2 c:ebe6bd43f9ee41617fcc455c869eaba86a5edc98a0e4bd25ac698b2054bc508e - publishing commit-tx txid=76a55a85d7c8ea382d2de31dc3e5de0191f0e52f94d5eee260a9e19379da5720 spending 8f50bc54208b69ac25bde4a098dc5e6aa8ab9e865c45cc7f6141eef943bde6eb:1 with id=940b27af-fd2e-41e4-afa0-7251f0db4238 (0 other attempts)

I will also open a issue with eclair and link the two issues

[t-bast]

This might ultimately be a interoperability issue: does the HTLC eclair send actually dip below the reserve? If so, can we repro that exact scenario to dig into the accounting between the implementations? Is it an mSAT rounding thing?

This is the important question.

Eclair does check reserve requirements (for sender and receiver) before sending an HTLC: https://github.com/ACINQ/eclair/blob/77b333731f618395f33d69d1fe0aba2c86cdba58/eclair-core/src/main/scala/fr/acinq/eclair/channel/Commitments.scala#L440

@DerEwige your node has all the information we need to debug this. Can you:

1. Run the channel command for the force-closed channel and share its output: this will give us the state of the channel (including the feerate for the commitment transaction) before the force-close
2. Search your logs for the outgoing HTLC that triggered the force-close, and share its amount
3. If there are multiple HTLCs that were added at the same time, make sure to include all of them

We should be able to create a unit test based on that data on both eclair and lnd to see why reserve calculation doesn't match.

[DerEwige]

@t-bast

Run the channel command for the force-closed channel and share its output: this will give us the state of the channel (including the feerate for the commitment transaction) before the force-close

channel_fc1.log
channel_fc2.log
Channel data for both force closes

Search your logs for the outgoing HTLC that triggered the force-close, and share its amount
If there are multiple HTLCs that were added at the same time, make sure to include all of them

Unfortunately I run this logback config:

	<logger name="fr.acinq.eclair.router" level="WARN"/>
	<logger name="fr.acinq.eclair.Diagnostics" level="WARN"/>
	<logger name="fr.acinq.eclair.channel.Channel" level="WARN"/>
	<logger name="fr.acinq.eclair.channel.fsm.Channel" level="WARN"/>
	<logger name="fr.acinq.eclair.io.Peer" level="WARN"/>
	<logger name="fr.acinq.eclair.payment.send.PaymentLifecycle" level="WARN"/>

So the HTLC is not logged.

[t-bast]

Thanks, that should be enough to replay the latest state and figure out why there is a mismatch between eclair and lnd. I'll investigate that state and share the contents of a unit test to try in both eclair and lnd to figure out where our balance calculation diverges.

[t-bast]

I have been able to reproduce the flow of messages that leads to the two channel states shared by @DerEwige.
Both of them have exactly the same pattern, so I'll only detail what happened to first one (with channel_id efc328abfaace666d49abf6d4eaea0589c0552feef9f34a5c81e74252b62e5b7).

First of all, an HTLC eclair -> lnd is cross-signed without any issues:

  Eclair                      LND
    |                          |
    | update_add_htlc          | htlc_id = 1_477_859
    |------------------------->|
    | commit_sig               |
    |------------------------->|
    |           revoke_and_ack |
    |<-------------------------|
    |               commit_sig |
    |<-------------------------|
    | revoke_and_ack           |
    |------------------------->|

At that point, both commitments are synchronized and contain only that HTLC.

Then eclair and lnd try adding an HTLC at the same time:

  Eclair                      LND
    |                          |
    | update_add_htlc          | htlc_id = 1_477_861
    |------------------------->|
    |          update_add_htlc | htlc_id = 120_896
    |<-------------------------|
    | commit_sig    commit_sig |
    |-----------+  +-----------|
    |            \/            |
    |            /\            |
    |<----------+  +---------->|
    |           revoke_and_ack |
    |<-------------------------|
    | revoke_and_ack           |
    |------------------------->|
    | commit_sig               |
    |------------------------->|
    |                    error |
    |<-------------------------|

Here are the details of the commitments when eclair receives lnd's error message:

• commitment feerate: 2500 sat/kw
• channel reserve: 30_000 sat (same on both sides)
• eclair's commitment:
  • commitment number: 3_194_658
  • to_local: 2_836_315_792 msat
  • to_remote: 34_367_703 msat
  • HTLC OUT: id=1_477_859 amount=117_941_049 msat
  • HTLC IN: id=120_896 amount=11_375_456 msat
• lnd's commitment:
  • commitment number: 3_195_511
  • to_local: 45_743_159 msat
  • to_remote: 2_756_274_986 msat
  • HTLC IN: id=1_477_859 amount=117_941_049 msat
  • HTLC IN: id=1_477_861 amount=80_040_806 msat
• lnd's next commitment (signed by eclair, previous not revoked yet):
  • commitment number: 3_195_512
  • to_local: 34_367_703 msat
  • to_remote: 2_756_274_986 msat
  • HTLC IN: id=1_477_859 amount=117_941_049 msat
  • HTLC IN: id=1_477_861 amount=80_040_806 msat
  • HTLC OUT: id=120_896 amount=11_375_456 msat

You can check that in the files shared by @DerEwige.

The important thing to note is that there is nothing that makes either peer dip into their reserve.
The difference between lnd's current commitment and the next one (which seems to trigger the force-close) is an additional HTLC going from lnd to eclair.
So it isn't triggered by something eclair sent, lnd decided to add that HTLC (and it doesn't make anyone dip into their reserve).
It seems to me that this internal error sent by lnd shouldn't be treated as an error, as there's nothing wrong with the state of the commitments or the messages exchanged.
@Roasbeef can you (or someone else from lnd) confirm this?
I'm very tempted to explicitly parse internal error messages and ignore them in eclair (like core-lightning does), as such bugs are very costly for our users who end up paying for a force-close.