[HSWC] LND fails an HTLC without any reason

[ziggie1984]

Background

I (node A) have a channel to a peer (node c), which is fully functional, but as soon as I build up a route with a CLN node (node b) in between node C does fail the HTLC and does not forward it to the final destination (node A). So the payment flow is:

nodeA -> nodeB -> nodeC -> node A

The logs on node C show that it is able to build up the incoming HTLC, but immediately fails the payment without any reason

2022-05-03 20:27:28.291 [DBG] PEER: Received UpdateAddHTLC(chan_id=CHAN_ID, id=15819, amt=20001020 mSAT, expiry=734996, hash=95220d268ae8aab9c61d881a077585a99dedf738ed72d3d96ededc52a5b55af7) from FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.292 [TRC] HSWC: ChannelLink(TO_CHAN:0): receive upstream htlc with payment hash(95220d268ae8aab9c61d881a077585a99dedf738ed72d3d96ededc52a5b55af7), assigning index: 15819
2022-05-03 20:27:28.301 [DBG] RPCS: [channelbalance] local_balance=28374259559 mSAT remote_balance=53148802441 mSAT unsettled_local_balance=0 mSAT unsettled_remote_balance=0 mSAT pending_open_local_balance=0 mSAT pending_open_remote_balance=0 mSAT
2022-05-03 20:27:28.431 [DBG] PEER: Received CommitSig(chan_id=CHAN_ID, num_htlcs=1) from FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.444 [DBG] PEER: Sending RevokeAndAck(chan_id=CHAN_ID, rev=f48c646fc66d24fc425839aec092e0fbac691f99b368d9e5e39a6087d8b32e08, next_point=0374294cab6125b26e93a9437e47b8c520abdfc38b86e8ed0546ca7a02dc983ff0) to FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.455 [TRC] HSWC: Deleting resolved circuits: ([]channeldb.CircuitKey) (cap=1) {
}

2022-05-03 20:27:28.459 [DBG] PEER: Sending CommitSig(chan_id=CHAN_ID, num_htlcs=1) to FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.661 [DBG] PEER: Received RevokeAndAck(chan_id=CHAN_ID, rev=bfa7606c56875f7fb3c4ccac4a1f2da997d8424e7d49056d6ccb936e330de730, next_point=03fa02f18e520faeec920620828353d8562f313ba7c201abd962ee56f7caa07ad2) from FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.673 [DBG] HSWC: Sent 0 satoshis and received 0 satoshis in the last 10 seconds (0.300000 tx/sec)
2022-05-03 20:27:28.676 [TRC] HSWC: ChannelLink(TO_CHAN:0): processing 1 remote adds for height 32258
2022-05-03 20:27:28.703 [DBG] HSWC: ChannelLink(TO_CHAN:0): forwarding 1 packets to switch
2022-05-03 20:27:28.705 [DBG] HSWC: ChannelLink(TO_CHAN:0): queueing removal of FAIL closed circuit: (Chan ID=730071:856:0, HTLC ID=15819)->(Chan ID=734461:1155:1, HTLC ID=0)
2022-05-03 20:27:28.705 [TRC] HSWC: Notifying forwarding failure event: forward over (Chan ID=730071:856:0, HTLC ID=15819) -> (Chan ID=734461:1155:1, HTLC ID=0)
2022-05-03 20:27:28.705 [DBG] PEER: Sending UpdateFailHTLC(chan_id=CHAN_ID, id=15819, reason=34c0276bde3c9ac93ab8f45ae400e5fa954a058b544d5dd025828112c5b112eeedc6ebaa7453e2885dc8d6a2d173f6bc8ec70bbc4289589311b9cbae7c26ccc67bcbbabac702f82282e3f58b7aaa6c631b35fc637714341fda94b54d4de04fd7ac8919c5df2be537cdd1449c95547013003e5d52d5e5131e0a0b58502e82b86718d46e61d38c23a1a6bcb77533e715d4c6279946194714511a3b7322e3aca72731ae6e4b5b9ffe619a4fd807f3f47fe40fd3cd779058414393a135a966761fd7296ba114a6ccb6af9e8547421e1a124aca380c332041d0e8f9794485bd76ff73b85734ab003c5e9974718aa89abaadf0404465485fcf523182bc23532ab07fbb39f4ab98a0791266e0bc8b226af45a27bcd37a13d71d1e2e6178609499bd2a11a9a56c2f) to FROM_PUBKEY@FROM_IP:9735
2022-05-03 20:27:28.718 [TRC] HSWC: Deleting resolved circuits: ([]channeldb.CircuitKey) (len=1 cap=1) {
 (channeldb.CircuitKey) (Chan ID=730071:856:0, HTLC ID=15819)

On my node I only get the Temporary Channel Failure in my logs:

lnd.log.21002.gz:2022-05-03 20:27:29.731 [DBG] HSWC: ChannelLink(OUT_CHAN:11): settle-fail-filter &{1 [0]}
lnd.log.21002.gz:2022-05-03 20:27:29.731 [DBG] HSWC: ChannelLink(OUT_CHAN:11): Failed to send 20001060 mSAT
lnd.log.21002.gz:2022-05-03 20:27:29.731 [TRC] HSWC: ChannelLink(OUT_CHAN:11): processing 0 remote adds for height 43710
lnd.log.21002.gz:2022-05-03 20:27:29.731 [DBG] HSWC: Closed completed FAIL circuit for HASH: (0:0:0, 152777) <-> (OUT_CHAN, 15772)
lnd.log.21002.gz:2022-05-03 20:27:29.731 [DBG] HSWC: Storing result for paymentID=152777
lnd.log.21002.gz:2022-05-03 20:27:29.736 [DBG] HSWC: Received network result *lnwire.UpdateFailHTLC for attemptID=152777
lnd.log.21002.gz:2022-05-03 20:27:29.740 [DBG] HSWC: Tearing down open circuit with FAIL pkt, removing circuit=(Chan ID=0:0:0, HTLC ID=152777) with keystone=(Chan ID=OUT_CHAN, HTLC ID=15772)
lnd.log.21002.gz:2022-05-03 20:27:29.740 [TRC] HSWC: Deleting resolved circuits: ([]channeldb.CircuitKey) (len=1 cap=1) {
lnd.log.21002.gz:2022-05-03 20:27:29.740 [WRN] CRTR: Attempt 152777 for payment HASH failed: TemporaryChannelFailure(update=(*lnwire.ChannelUpdate)(0x400ed72d10)({
lnd.log.21002.gz:2022-05-03 20:27:29.745 [DBG] HSWC: Closed completed FAIL circuit for HASH: (0:0:0, 152777) <-> (OUT_CHAN, 15772)
lnd.log.21002.gz:2022-05-03 20:27:29.745 [DBG] HSWC: Closed completed FAIL circuit for HASH: (0:0:0, 152777) <-> (OUT_CHAN, 15772)
lnd.log.21002.gz:2022-05-03 20:27:29.746 [TRC] HSWC: Notifying forwarding failure event: send over (Chan ID=OUT_CHAN, HTLC ID=15772)

Your environment

• Node A

• version of lnd : v0.14.3-beta.rc1

• which operating system (uname -a on *Nix): aarch64 GNU/Linux

• version of btcd, bitcoind, or other backend : bitcoind

• any other relevant environment details

• Node C

• version of lnd : version 0.14.2-beta

• which operating system (uname -a on *Nix): aarch64 GNU/Linux

• version of btcd, bitcoind, or other backend : bitcoind

• any other relevant environment details

• Node B (CLN Node)

Steps to reproduce

Node C opened a Channel to Node A, after that try rebalancing this channel

Expected behaviour

Forward the failure or at least show failure message why it fails on Node C. I know that node A will not know about the error bc of privacy, but Node C should see it

Actual behaviour

Node C fails the forward of the Outgoing HTLC without any failure although HSWC is on TRACE

[Roasbeef]

Does node A have a single channel?

At a scan I think it's running into either that (preventing a circular forward), or a dust related check. Both those checks have less logging than some of the existing policy checks.

[Roasbeef]

Also just to confirm: if you remove node B then everything works?

[Roasbeef]

2022-05-03 20:27:28.705 [DBG] HSWC: ChannelLink(TO_CHAN:0): queueing removal of FAIL closed circuit: (Chan ID=730071:856:0, HTLC ID=15819)->(Chan ID=734461:1155:1, HTLC ID=0)

I think maybe your labeling is off here: this is printed when the incoming channel (the link) gets a failure message from the switch to cancel back an HTLC.

[ziggie1984]

Does node A have a single channel?

Channel at C-A
NodeC: 0.02747813 │ NodeA:0.01250011

so dust or reserve should not be a problem.

Also just to confirm: if you remove node B then everything works?

Yes as soon as exchange the CLN node with an LND node it works

I verified with 2 CLN nodes for "Node B" and both fail

For LND nodes for Node B it works (verified 2)

[ziggie1984]

I think maybe your labeling is off here: this is printed when the incoming channel (the link) gets a failure message from the switch to cancel back an HTLC.

2022-05-03 20:27:28.291 [DBG] PEER: Received UpdateAddHTLC(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, id=15819, amt=20001020 mSAT, expiry=734996, hash=95220d268ae8aab9c61d881a077585a99dedf738ed72d3d96ededc52a5b55af7) from 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.292 [TRC] HSWC: ChannelLink(5e301ccdc928bdb4c01edbdf63de5d6d0b83342621ce290133b09d353c4fd2f3:0): receive upstream htlc with payment hash(95220d268ae8aab9c61d881a077585a99dedf738ed72d3d96ededc52a5b55af7), assigning index: 15819
2022-05-03 20:27:28.301 [DBG] RPCS: [channelbalance] local_balance=28374259559 mSAT remote_balance=53148802441 mSAT unsettled_local_balance=0 mSAT unsettled_remote_balance=0 mSAT pending_open_local_balance=0 mSAT pending_open_remote_balance=0 mSAT
2022-05-03 20:27:28.431 [DBG] PEER: Received CommitSig(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, num_htlcs=1) from 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.444 [DBG] PEER: Sending RevokeAndAck(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, rev=f48c646fc66d24fc425839aec092e0fbac691f99b368d9e5e39a6087d8b32e08, next_point=0374294cab6125b26e93a9437e47b8c520abdfc38b86e8ed0546ca7a02dc983ff0) to 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.455 [TRC] HSWC: Deleting resolved circuits: ([]channeldb.CircuitKey) (cap=1) {
}

2022-05-03 20:27:28.459 [DBG] PEER: Sending CommitSig(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, num_htlcs=1) to 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.661 [DBG] PEER: Received RevokeAndAck(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, rev=bfa7606c56875f7fb3c4ccac4a1f2da997d8424e7d49056d6ccb936e330de730, next_point=03fa02f18e520faeec920620828353d8562f313ba7c201abd962ee56f7caa07ad2) from 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.673 [DBG] HSWC: Sent 0 satoshis and received 0 satoshis in the last 10 seconds (0.300000 tx/sec)
2022-05-03 20:27:28.676 [TRC] HSWC: ChannelLink(5e301ccdc928bdb4c01edbdf63de5d6d0b83342621ce290133b09d353c4fd2f3:0): processing 1 remote adds for height 32258
2022-05-03 20:27:28.703 [DBG] HSWC: ChannelLink(5e301ccdc928bdb4c01edbdf63de5d6d0b83342621ce290133b09d353c4fd2f3:0): forwarding 1 packets to switch
2022-05-03 20:27:28.705 [DBG] HSWC: ChannelLink(5e301ccdc928bdb4c01edbdf63de5d6d0b83342621ce290133b09d353c4fd2f3:0): queueing removal of FAIL closed circuit: (Chan ID=730071:856:0, HTLC ID=15819)->(Chan ID=734461:1155:1, HTLC ID=0)
2022-05-03 20:27:28.705 [TRC] HSWC: Notifying forwarding failure event: forward over (Chan ID=730071:856:0, HTLC ID=15819) -> (Chan ID=734461:1155:1, HTLC ID=0)
2022-05-03 20:27:28.705 [DBG] PEER: Sending UpdateFailHTLC(chan_id=f3d24f3c359db0330129ce212634830b6d5dde63dfdb1ec0b4bd28c9cd1c305e, id=15819, reason=34c0276bde3c9ac93ab8f45ae400e5fa954a058b544d5dd025828112c5b112eeedc6ebaa7453e2885dc8d6a2d173f6bc8ec70bbc4289589311b9cbae7c26ccc67bcbbabac702f82282e3f58b7aaa6c631b35fc637714341fda94b54d4de04fd7ac8919c5df2be537cdd1449c95547013003e5d52d5e5131e0a0b58502e82b86718d46e61d38c23a1a6bcb77533e715d4c6279946194714511a3b7322e3aca72731ae6e4b5b9ffe619a4fd807f3f47fe40fd3cd779058414393a135a966761fd7296ba114a6ccb6af9e8547421e1a124aca380c332041d0e8f9794485bd76ff73b85734ab003c5e9974718aa89abaadf0404465485fcf523182bc23532ab07fbb39f4ab98a0791266e0bc8b226af45a27bcd37a13d71d1e2e6178609499bd2a11a9a56c2f) to 0298f6074a454a1f5345cb2a7c6f9fce206cd0bf675d177cdbf0ca7508dd28852f@73.114.40.246:9735
2022-05-03 20:27:28.718 [TRC] HSWC: Deleting resolved circuits: ([]channeldb.CircuitKey) (len=1 cap=1) {
 (channeldb.CircuitKey) (Chan ID=730071:856:0, HTLC ID=15819)

this is the original log of Node C without label replacement form my side

[ziggie1984]

Some other details:

So Node C activated circular-rebalances, and as soon as I try to pay via its channel (same channel for incoming and outgoing HTLC) it fails in the same way

[ziggie1984]

I have still no real understanding of the failure but I think adding more logging would be the best way to go.