Outgoing Channel force closed without any HTLC on channel.

[BhaagBoseDK]

Background

Consider A-B-C - I am B (03c5528c628681aa17ab9e117aa3ee6f06c750dfb17df758ecabcd68f1567ad8c1)
I have channel with
A = XMRK 033878501f9a4ce97dba9a6bba4e540eca46cb129a322eb98ea1749ed18ab67735
C = SWISS NATIONAL NODE 024eac466254511fc135d43ab676155c3b3a2db9c63a4a85ad8a76ad2520652ab0

Channel B-C was Force closed, without any visible HTLC waiting to the resolved on chain. The on-chain transaction 9c302a4a31adcbebb64a5bfffc5fb3d9408a0038ca0a3fad33684395f02e3926 also does not have any HTLC output spent. Just 2 anchors and 2 channel balance outputs.

Details:

I record an hourly snapshot of pending HTLCs on my node so that I can trace any open HTLCs during a force close. It is a simple out put of lncli listchannels | jq -r '.[][] | .remote_pubkey, .pending_htlcs[] ' | grep "{" -B1 -A8 to a log file.

---Tue 26 Apr 01:15:30 UTC 2022---
Current block ...  733581

At snapshot time above, my logs showed the following HTLC from A->B

033878501f9a4ce97dba9a6bba4e540eca46cb129a322eb98ea1749ed18ab67735
---> ⚡️ 💰X 3⃣ 🐟 💀 🚫 xmrk                      
{
"incoming": true,
"amount": "6521",
"hash_lock": "2a0efebe830d19c5d71aab6819823a3a45c6436c7ffb32e9adb0607d4ed1c618",
"expiration_height": 733736,
...in 155 blocks
"htlc_index": "989",
"forwarding_channel": "767332672493912065",
"forwarding_htlc_index": "1885"
}

However, there was no record of corresponding OutGoing HTLC to C. The forwarding channel 767332672493912065 is B->C but in these snap shots there is no record of the HTLC pending between B->C

Fast forward the HTLC snapshot logs carry on until there was 21 blocks left to expiry (the snapshot is at 23 blocks)

---Wed 27 Apr 00:13:19 UTC 2022---
Current block ...  733713
033878501f9a4ce97dba9a6bba4e540eca46cb129a322eb98ea1749ed18ab67735
---> ⚡️ 💰X 3⃣ 🐟 💀 🚫 xmrk
{
"incoming": true,
"amount": "6521",
"hash_lock": "2a0efebe830d19c5d71aab6819823a3a45c6436c7ffb32e9adb0607d4ed1c618",
"expiration_height": 733736,
...in 23 blocks
"htlc_index": "989",
"forwarding_channel": "767332672493912065",
"forwarding_htlc_index": "1885"
}

Since my CLTV delta is 21, if A-B have 21 blocks to expiry B-C would HTC would have expired by block 733715

At block 733715, channel B-C was closed

2022-04-27 00:31:45.928 [INF] NTFN: New block: height=733715, sha=000000000000000000048cb1f2a7dc5560fabf47e806d2926b688c85fee0e0ee
2022-04-27 00:31:45.941 [INF] UTXN: Attempting to graduate height=733715: num_kids=0, num_babies=0
2022-04-27 00:31:45.947 [INF] CRTR: Block 000000000000000000048cb1f2a7dc5560fabf47e806d2926b688c85fee0e0ee (height=733715) closed 0 channels
2022-04-27 00:31:45.948 [ERR] LTND: Unable to lookup witness: no witnesses
2022-04-27 00:31:45.969 [INF] HSWC: Garbage collected 17 shared secret hashes at height=733715
2022-04-27 00:31:45.978 [INF] NTFN: Block disconnected from main chain: height=733715, sha=000000000000000000048cb1f2a7dc5560fabf47e806d2926b688c85fee0e0ee
2022-04-27 00:31:45.980 [INF] CNCT: ChannelArbitrator(1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1): force closing chan
2022-04-27 00:31:45.994 [INF] HSWC: Removing channel link with ChannelID(290fbba65e3352636a4d00734efe15d5e5dc73791f0b56e7520f524937807e1e)
2022-04-27 00:31:46.041 [INF] CNCT: Broadcasting force close transaction 9c302a4a31adcbebb64a5bfffc5fb3d9408a0038ca0a3fad33684395f02e3926, ChannelPoint(1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1): (*wire.MsgTx)(0x400eec6300)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=1) {
  (*wire.TxIn)(0x40067b2960)({
   PreviousOutPoint: (wire.OutPoint) 1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=4 cap=4) {
    ([]uint8) <nil>,
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 5d 36 2f 37  c4 db 2f b0 5d d9 de 50  |0D. ]6/7../.]..P|
     00000010  11 92 fe 3b 97 d9 6a 94  67 e4 bf 97 37 bc 28 8e  |...;..j.g...7.(.|
     00000020  f8 f8 f5 b1 02 20 53 ad  93 50 d3 17 3a d9 ff cb  |..... S..P..:...|
     00000030  02 7c 6f 3b 11 99 46 b0  28 23 92 87 4c 25 3d a1  |.|o;..F.(#..L%=.|
     00000040  75 b3 d3 b3 04 4f 01                              |u....O.|
    },
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 b7 b3 56  ae c5 e4 cd a1 0f bb 14  |0E.!...V........|
     00000010  0a f8 a0 f0 a7 64 72 69  4d d7 38 cb 14 55 e1 7c  |.....driM.8..U.||
     00000020  bc af b5 e4 61 02 20 05  59 4a b3 dc f3 df 12 6f  |....a. .YJ.....o|
     00000030  50 0a 51 09 ae c1 bb 1f  e4 f1 c4 7c 68 fa 3c 11  |P.Q........|h.<.|
     00000040  15 e4 61 e4 d3 f8 0c 01                           |..a.....|
    },
    ([]uint8) (len=71 cap=500) {
     00000000  52 21 02 d1 d5 ff 6d b2  c5 a0 c0 2e 10 9f ee 79  |R!....m........y|
     00000010  cb 7f 28 1f 50 49 63 92  4d d1 9e 3f 37 9d 25 8e  |..(.PIc.M..?7.%.|
     00000020  bb f7 da 21 03 48 d2 cc  50 f8 68 e6 e3 f5 29 44  |...!.H..P.h...)D|
     00000030  a2 2c 3a a4 f2 67 5b 0d  af 94 89 6b ee 12 f5 94  |.,:..g[....k....|
     00000040  16 f6 9c 8b 4f 52 ae                              |....OR.|
    }
   },
   Sequence: (uint32) 2159634665
  })
 },
 TxOut: ([]*wire.TxOut) (len=4 cap=4) {
  (*wire.TxOut)(0x401a7d5a40)({
   Value: (int64) 330,
   PkScript: ([]uint8) (len=34 cap=34) {
    00000000  00 20 70 d0 a8 ca 46 69  f3 ee 00 41 a3 d3 43 10  |. p...Fi...A..C.|
    00000010  aa a0 70 5c 77 7d 17 00  a7 e1 e8 6c bf ca d9 7c  |..p\w}.....l...||
    00000020  8b d0                                             |..|
   }
  }),
  (*wire.TxOut)(0x401a7d5a60)({
   Value: (int64) 330,
   PkScript: ([]uint8) (len=34 cap=34) {
    00000000  00 20 dd 6b 53 f1 75 16  33 a8 53 9c f1 56 ea 0f  |. .kS.u.3.S..V..|
    00000010  fe 39 49 27 65 9a 58 ef  5d ec 92 79 33 e2 4b 79  |.9I'e.X.]..y3.Ky|
    00000020  18 42                                             |.B|
   }
  }),
  (*wire.TxOut)(0x401a7d5a80)({
   Value: (int64) 1895723,
   PkScript: ([]uint8) (len=34 cap=34) {
    00000000  00 20 4a 4d 87 a7 3b 1b  75 9f 0f e0 fc 14 ee 18  |. JM..;.u.......|
    00000010  44 fc 13 12 71 b3 a9 4f  92 a2 5c 78 e2 33 2e 51  |D...q..O..\x.3.Q|
    00000020  b2 fb                                             |..|
   }
  }),
  (*wire.TxOut)(0x401a7d5aa0)({
   Value: (int64) 4100908,
   PkScript: ([]uint8) (len=34 cap=34) {
    00000000  00 20 fa a9 52 b6 81 1f  f5 aa 84 fd 42 e4 9a d2  |. ..R.......B...|
    00000010  ed 83 c9 0f 8e cd 1b ce  bb ec 60 e3 f2 48 81 77  |..........`..H.w|
    00000020  7d 37                                             |}7|
   }
  })
 },
 LockTime: (uint32) 542883943
})

2022-04-27 00:31:46.047 [INF] LNWL: Inserting unconfirmed transaction 9c302a4a31adcbebb64a5bfffc5fb3d9408a0038ca0a3fad33684395f02e3926

Some more logs at block 733716

2022-04-27 00:47:40.631 [INF] NTFN: New block: height=733716, sha=00000000000000000002fe877d38c1d4ba4c74cdcf17e238b172016aa876a3c3
2022-04-27 00:47:40.633 [INF] NTFN: Dispatching confirmed spend notification for outpoint=1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1, script=0 36dce9f9f2de776b6c3ff0c273903b839e766ae7b07961f9cf0c75c456aeab08 at current height=733716: 9c302a4a31adcbebb64a5bfffc5fb3d9408a0038ca0a3fad33684395f02e3926[0] spending 1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1 at height=733716
2022-04-27 00:47:40.637 [INF] UTXN: Attempting to graduate height=733716: num_kids=0, num_babies=0
2022-04-27 00:47:40.676 [INF] HSWC: Garbage collected 38 shared secret hashes at height=733716
2022-04-27 00:47:40.695 [INF] CNCT: Local unilateral close of ChannelPoint(1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1) detected
2022-04-27 00:47:40.699 [INF] CNCT: ChannelArbitrator(1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1): local on-chain channel close

Your environment

umbrel@umbrel:~/lndlog $ lncli getinfo
{
    "version": "0.14.2-beta commit=v0.14.2-beta",
    "commit_hash": "1e511be523eb8e97c4e2d9c89a7a263963a3929f",
    "identity_pubkey": "03c5528c628681aa17ab9e117aa3ee6f06c750dfb17df758ecabcd68f1567ad8c1",
    "alias": "⚡G-Spot-21_69_420⚡",
    "color": "#216942",
    "num_pending_channels": 0,
    "num_active_channels": 227,
    "num_inactive_channels": 3,
    "num_peers": 220,
    "block_height": 733764,
    "block_hash": "00000000000000000006ad122edc211cec946ec47bb2a55657917a048fe3b372",
    "best_header_timestamp": "1651047520",
    "synced_to_chain": true,
    "synced_to_graph": true,
    "testnet": false,
    "chains": [
        {
            "chain": "bitcoin",
            "network": "mainnet"
        }
    ],
    "uris": [
        "03c5528c628681aa17ab9e117aa3ee6f06c750dfb17df758ecabcd68f1567ad8c1@82.16.240.248:9735",
        "03c5528c628681aa17ab9e117aa3ee6f06c750dfb17df758ecabcd68f1567ad8c1@zacadqiqgi43tdv4ztjet2fh22f72ol2tokotp5cqdbszgx6tpyqdxad.onion:9735"
    ],

Steps to reproduce

See above. The behaviour is weird.

Expected behaviour

If there is no HTLC pending on outgoing channel B->C it should not be force closed.

Actual behaviour

Channel B->C was force closed without any HTLC on it.

[Crypt-iQ]

This is normal behavior, there are scenarios in which lnd should close out the channel even though there are no HTLCs on our local commitment

[BhaagBoseDK]

what are those scenarios and how can one find them easily in the logs?

[ziggie1984]

Still very coincidential that the channel force-close happened the moment a hypothetical HTLC timeout between B-C would trigger the force-close. So in the above scenario it looks like lnd was thinking it had an HTLC between B-C. It would be interesting how the HTLC circuit behaved for the incoming HTLC, so no more log information for this one ?

[BhaagBoseDK]

no, unfortunately I do not have DEBUG setup on my lnd logs or subsystems.
however it is a long standing request to have proper logging at INF/ERR level when a channel is being force closed.
#6363
or
#5324

Today lnd only logs

2022-04-27 00:31:45.980 [INF] CNCT: ChannelArbitrator(1f7e803749520f52e7560b1f7973dce5d515fe4e73004d6a6352335ea6bb0f29:1): force closing chan
which does not tell anything about what is going on.

[BhaagBoseDK]

is this HTLC small enough to be considered trimmed?

[C-Otto]

https://bitcoin.stackexchange.com/questions/113335/unilateral-close-because-of-htlc-in-remote-commitment

[Roasbeef]

So I think we can close this as a duplicate of #2992?

[BhaagBoseDK]

While I had another force close today for precisely the same reason (#2992).

May be a point to consider

When a peer disconnects, it is marked as pending disable (to be announced as disable after chan-disable-timeout)

Could the flow of HTLC be stopped going towards channels marked as pending disabled? This could save on ping latency and would only apply to actually "suspect" channels instead of pinging every peer on every htlc which could be performance hit.

[BhaagBoseDK]

closing as a duplicate of #2992