Lnd: Node forced closed a channel with zapread.com, not sure why

Created on 13 Sep 2020 · 65Comments · Source: lightningnetwork/lnd

Background

My node force-closed a channel with zapread.com, it was a good and active channel, I am not sure why my node decided to force-close the channel, some relevant things that I found, full log attached

2020-09-02 04:58:55.181 [ERR] HSWC: ChannelLink(563360:2528:1): failing link: ChannelPoint(25194f104e65a27cfd6867ac8e8708c9cb898e1212a51ff1862ffb03cc1e340b:1): received error from peer: chan_id=0b341ecc03fb2f86f11fa512128e89cbc908878eac6768fd7ca2654e104f1924, err=internal error with error: remote error
2020-09-02 04:58:55.185 [ERR] HSWC: ChannelLink(563360:2528:1): link failed, exiting htlcManager
2020-09-02 04:58:55.185 [INF] HSWC: ChannelLink(563360:2528:1): exited

.
.
.

2020-09-02 12:45:07.278 [INF] DISC: GossipSyncer(037659a0ac8eb3b8d0a720114efc861d3a940382dcfa1403746b4f8f6b2e8810ba): applying gossipFilter(start=0001-01-01 00:00:00 +0000 UTC, end=0001-01-01 00:00:00 +0000 UTC)
2020-09-02 12:45:07.279 [INF] DISC: GossipSyncer(0231eccc6510eb2e1c97c8a190d6ea096784aa7c358355442055aac8b20654f932): applying gossipFilter(start=2020-09-02 12:45:07.279317998 +0000 UTC m=+408745.563033846, end=2156-10-09 19:13:22.279317998 +0000 UTC m=+4295376040.563033846)
2020-09-02 12:45:37.279 [INF] DISC: Broadcasting 265 new announcements in 18 sub batches
2020-09-02 12:46:03.069 [INF] CRTR: Processed channels=0 updates=232 nodes=0 in last 59.998613183s
2020-09-02 12:47:03.069 [INF] CRTR: Processed channels=0 updates=272 nodes=0 in last 59.999710346s
2020-09-02 12:47:07.338 [INF] DISC: Broadcasting 388 new announcements in 18 sub batches
2020-09-02 12:48:03.069 [INF] CRTR: Processed channels=0 updates=170 nodes=3 in last 59.999843239s
2020-09-02 12:48:37.433 [INF] DISC: Broadcasting 219 new announcements in 17 sub batches
2020-09-02 12:48:54.682 [INF] CRTR: Pruning channel graph using block 0000000000000000000e65c5c2126e7c902fa09351b8087ab331182eeabebfab (height=646431)
2020-09-02 12:48:56.056 [INF] NTFN: New block: height=646431, sha=0000000000000000000e65c5c2126e7c902fa09351b8087ab331182eeabebfab
2020-09-02 12:48:56.059 [ERR] LTND: Unable to lookup witness: no witnesses
2020-09-02 12:48:56.060 [INF] UTXN: Attempting to graduate height=646431: num_kids=0, num_babies=0
2020-09-02 12:48:56.413 [INF] HSWC: Garbage collected 1 shared secret hashes at height=646431
2020-09-02 12:48:56.467 [INF] CNCT: ChannelArbitrator(25194f104e65a27cfd6867ac8e8708c9cb898e1212a51ff1862ffb03cc1e340b:1): force closing chan
2020-09-02 12:48:56.611 [INF] HSWC: Removing channel link with ChannelID(0b341ecc03fb2f86f11fa512128e89cbc908878eac6768fd7ca2654e104f1924)
2020-09-02 12:48:57.822 [INF] CRTR: Block 0000000000000000000e65c5c2126e7c902fa09351b8087ab331182eeabebfab (height=646431) closed 1 channels
2020-09-02 12:49:00.967 [INF] CNCT: Broadcasting force close transaction d9ad30a963638a6efe405b608e1746b55092cb877e620d7135fe083becadbc51, ChannelPoint(25194f104e65a27cfd6867ac8e8708c9cb898e1212a51ff1862ffb03cc1e340b:1): (*wire.MsgTx)(0x40016b6200)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=1) {
  (*wire.TxIn)(0x40072170e0)({
   PreviousOutPoint: (wire.OutPoint) 25194f104e65a27cfd6867ac8e8708c9cb898e1212a51ff1862ffb03cc1e340b:1,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=4 cap=4) {
    ([]uint8) <nil>,
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 cb 77 1a  b5 0a 77 19 78 f8 6e d1  |0E.!..w...w.x.n.|
     00000010  5b d3 0d f2 c5 09 b8 0a  f1 cd 7b e4 d5 37 54 ca  |[.........{..7T.|
     00000020  03 8c fd 45 41 02 20 00  98 e9 33 4e 9b 54 72 1c  |...EA. ...3N.Tr.|
     00000030  03 46 f9 80 7b f3 3f 2c  ff 9c 9b bf 9d bf fb d6  |.F..{.?,........|
     00000040  57 0f d7 89 b8 b5 9f 01                           |W.......|
    },
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 c7 1b 89  a9 bb 26 e3 70 62 da 92  |0E.!......&.pb..|
     00000010  18 79 e4 b3 c6 2d cd d2  23 55 33 82 6b 6d 69 e5  |.y...-..#U3.kmi.|
     00000020  4f e5 15 e8 ed 02 20 1a  0f c3 a1 e3 78 c9 60 02  |O..... .....x.`.|
     00000030  23 33 20 47 70 0b 4c a2  71 0a 75 5c 8c f0 ef 90  |#3 Gp.L.q.u\....|
     00000040  5a b2 d8 b8 21 92 e2 01                           |Z...!...|
    },
    ([]uint8) (len=71 cap=500) {
     00000000  52 21 02 10 09 28 9d 07  68 3c dc 41 e5 b6 c5 45  |R!...(..h<.A...E|
     00000010  2d e9 ae e4 2f 24 5a bd  7f c5 ca 2b 7f 81 87 f7  |-.../$Z....+....|
     00000020  1f 5f f9 21 03 fd 59 d9  e6 f3 cc 0b 54 bb 88 11  |._.!..Y.....T...|
     00000030  8b 8e b1 aa 2d 5e f7 f3  b2 35 7f 05 9d 84 d4 0e  |....-^...5......|
     00000040  ab 89 94 d2 d9 52 ae                              |.....R.|
    }
   },
   Sequence: (uint32) 2160573938
  })
 },
 TxOut: ([]*wire.TxOut) (len=2 cap=2) {
  (*wire.TxOut)(0x4004b83480)({
   Value: (int64) 18918,
   PkScript: ([]uint8) (len=22 cap=22) {
    00000000  00 14 34 61 63 e4 5b 89  ae dd 6b 9d 6f 3d bf 58  |..4ac.[...k.o=.X|
    00000010  17 fd c8 2e d4 61                                 |.....a|
   }
  }),
  (*wire.TxOut)(0x4004b834a0)({
   Value: (int64) 151877,
   PkScript: ([]uint8) (len=34 cap=34) {
    00000000  00 20 64 f9 21 c5 22 fc  e3 38 b4 97 59 36 eb a5  |. d.!."..8..Y6..|
    00000010  6d c4 1f 4a 2d 1d 25 d9  18 9b 7d 9b 3b d8 cc cf  |m..J-.%...}.;...|
    00000020  4a db                                             |J.|
   }
  })
 },
 LockTime: (uint32) 540252184
})

2020-09-02 12:49:01.181 [INF] LNWL: Inserting unconfirmed transaction d9ad30a963638a6efe405b608e1746b55092cb877e620d7135fe083becadbc51

Your environment

lnd version 0.11.0-beta commit=v0.11.0-beta
Bitcoin Core Daemon version v0.18.0
Linux rock64 4.4.132-1075-rockchip-ayufan-ga83beded8524 #1 SMP Thu Jul 26 08:22:22 UTC 2018 aarch64 GNU/Linux

Full log available here (password protected, send me a slack message and I'll send you the password)

lnd.log.80.zip

P1 bug commitments p2p

Source

MrManPew

Most helpful comment

Is there an answer to this question above?

Once a htlc is locked into your commitment transaction, the nodes in the channel need to be online to settle the htlc (if the preimage is revealed) or to time it out if the preimage is not revealed by the timeout block.

There are a few reasons why this could happen:

If your node is not reachable, your peer may not be able to connect to you to settle back after restart (simple enough to debug on your own), could be the case if you're having issues with ToR
If your peer is offline a lot (check the output for ListChannels to see their uptime percentage uptime/lifetime), then your node would have gone to chain to claim the amount
-> shameless Faraday shill here, the cli insights command will give you this info + more
Theoretically, a node could also maliciously not release the htlc but that would require running a forked evil implementation, would end up costing them if they opened the channel, and if you opened the channel, they still gain nothing (you just pay some fees)

It's most likely that your node isn't reachable, or you have a peer who has bad uptime percentage. Generally, it's desirable to peer with nodes that have good uptime so that this doesn't happen. Unfortunately, it's difficult to know whether a peer is going to stay online before you actually open a channel with them. The protocol has a disabled flag which nodes send out when their channel peers go dark (which can act as a proxy for uptime if you monitor it over time). This is one of the things we track in the BOS scores, so that could be a good place to get some info before connecting (although it is not the only data point, more info in the "Lightning Metrics" section here).

More generally, if you have channels open with peers who have just gone dead (offline for a long time), we highly recommend that you close the channel out because those nodes will not be around to help out with static channel backups if you do need to recover from a lost channeldb.

carlaKC on 16 Oct 2020

❤2

All 65 comments

same thing happened to me, had a couple of force closings for no reason
lnd 0.11.0-beta, neutrino, linux x64

enorrmann on 13 Sep 2020

Unless we've identified a new spurious force close vector. I'd check that you didn't have an HTLC which has expired. If not, then although we've fixed a number of spurious force close vectors, _both sides_ need to be updated to have them disappear completely.

Roasbeef on 15 Sep 2020

Unless we've identified a new spurious force close vector. I'd check that you didn't have an HTLC which has expired

Not sure how to check it? I've uploaded the full log on those days.

both sides need to be updated to have them disappear completely.

Luckily he is on github. @Horndev can you verify please what was your ZapRead node lnd version around 2020-09-02 ?
Thank you

MrManPew on 15 Sep 2020

happened again with another node, I have some logging information here
https://rayo.host/logs/force_close.log
I'm running 0.11Beta.. and the other peer is @Blockdaemon, I'm not sure which version are they on

enorrmann on 15 Sep 2020

and another one
https://rayo.host/logs/force_close_2.log

enorrmann on 15 Sep 2020

another one
https://rayo.host/logs/force_close_3.log

enorrmann on 15 Sep 2020

As mentioned above, if no HTLCs were present on the commitment transaction, then it may be due to the other node having an older version with bugs that could cause it to send an invalid commitment. In each of those statements, I'd look further back in the logs to see if the peer sent an invalid commitment earlier in the exchange.

Roasbeef on 17 Sep 2020

If you can get the version of the peer, this would help us. Also if there's a specific "invalid commitment" log message, that would aid us.

Crypt-iQ on 24 Sep 2020

2 days ago I opened this channels
lncli openchannel --node_key 03a5886df676f3b3216a4520156157b8d653e262b520281d8d325c24fd8b456b9c --sat_per_byte 3 --local_amt 3000000
lncli openchannel --node_key 02004c625d622245606a1ea2c1c69cfb4516b703b47945a3647713c05fe4aaeb1c --sat_per_byte 3 --local_amt 6000000
lncli openchannel --node_key 0395033b252c6f40e3756984162d68174e2bd8060a129c0d3462a9370471c6d28f --sat_per_byte 3 --local_amt 8000000
lncli openchannel --node_key 03e50492eab4107a773141bb419e107bda3de3d55652e6e1a41225f06a0bbf2d56 --sat_per_byte 3 --local_amt 7000000

today I found all of them were force closed from my side
no "invalid commitment" log message found
Edit: node names are
yalls-clearnet
WalletOfSatoshi.com
BitMEXResearch

enorrmann on 25 Sep 2020

Can you try to pinpoint the error messages, there should be something like link failed. The thing I'm after is what message was sent across. As you are a neutrino node, force closes with older nodes is more likely to happen. If any of the other counterparties are not on the 0.11 branch, then force closes can happen like laolu mentioned up above

Crypt-iQ on 25 Sep 2020

found it
https://rayo.host/logs/link_failed.log

enorrmann on 25 Sep 2020

Thanks, is there a way to open it to a paste-bin like site if things aren't too sensitive?

Crypt-iQ on 25 Sep 2020

https://pastebin.com/BLhbEC44
do you need the full log ?

enorrmann on 25 Sep 2020

Two interesting messages:

2020-09-25 04:51:17.080 [ERR] HSWC: ChannelLink(646845:1072:0): failing link: unable to handle upstream add HTLC: ID 27 on HTLC add does not match expected next ID 26 with error: invalid update
2020-09-25 04:51:20.760 [WRN] HSWC: ChannelLink(646845:1072:0): error when syncing channel states: first message sent to sync should be ChannelReestablish, instead received: *lnwire.Error

First error should've been fixed in 0.11 if they upgraded too. Not sure why the other occurs

Ping @cfromknecht

Crypt-iQ on 25 Sep 2020

Another "local force-close", with runam0k nodl:

Peer Public Key: 02f8f981a3d6cb6536fc12ea2abdcfd20f7490e28197514aafc05a7a1f08d3de09
Channel Point: c5e508504fda9c200d458bb68c8e814615fdf805a44a8bb3c5fa69ffb7f59ce5
Closing Transaction Hash: 22429d9eb955db66c638a4e8a23b0a41cfc4862dc4d713d7b0d6f478e3fe4083

Full log:
https://privatebin.net/?6fa87ce4beca6a74#C8QqFN1YY3zP985v3HQLbe6rv79LQyGyHNsSigycerNz

MrManPew on 25 Sep 2020

So you need debug level logs on - and you keep disconnecting with a tor node so it could be that this is triggering those issues fixed in 0.11. It makes sense that a tor node would cause reliability issues.

Crypt-iQ on 25 Sep 2020

Hi @Crypt-iQ how can I run with debug mode?
About the disconnects, is it related to this:
https://github.com/lightningnetwork/lnd/issues/4575

Still waiting for a response from @Roasbeef about #4575

MrManPew on 25 Sep 2020

Hi @Crypt-iQ how can I run with debug mode?

just edit lnd.conf
debuglevel=debug or finer detail
see https://github.com/lightningnetwork/lnd/blob/master/sample-lnd.conf

enorrmann on 26 Sep 2020

👍2

today I got another one... force closing from my side
https://pastebin.com/FtzewS93
channel point ea3e68dcba3367a4d5b59da9f6366c42a87d3023422ff79925d1659682587f43:0

enorrmann on 28 Sep 2020

First error should've been fixed in 0.11 if they upgraded too. Not sure why the other occurs

The second there can happen due to slight differences between implementations w.r.t what order they expect certain messages in.

2020-09-25 04:51:17.065 [INF] HSWC: ChannelLink(646845:1072:0): received re-establishment message from remote side
2020-09-25 04:51:17.080 [ERR] HSWC: ChannelLink(646845:1072:0): failing link: unable to handle upstream add HTLC: ID 27 on HTLC add does not match expected next ID 26 with error: invalid update

Note sure which implementation this is, but we've seen in the past that certain implementations don't re-transmit HTLCs in order of increasing HTLC ID, which can at times trigger this issue.

@enorrmann on that latest one, there were no other logs before that force close attempt, nothing on the p2p layer of maybe someone triggering a DLP scenario?

Roasbeef on 29 Sep 2020

Edit: node names are

This is really useful info, thanks! So from here, we should be able to check out the node announcements themselves, then check the feature bits to see if we can place them in an lnd version bucket from there.

Roasbeef on 29 Sep 2020

Can you both resend logs with debug enabled if you can? Can do over slack, name is "eugene". Or publicly here.

Crypt-iQ on 29 Sep 2020

Hi @Crypt-iQ , the node is now running with debung mode, but I need to wait for a new forceclose to have the log files that includes debugstate, correct ?

MrManPew on 30 Sep 2020

@MrManPew yes

Crypt-iQ on 30 Sep 2020

I got two more force close, but I don't have the log files as only 3 logs are saved and now that I am in debug mode, the logs already past the time of the close 🤦
I changed the settings to save more than 3 log files... But now we need to wait again. Those force-close are expensive...

MrManPew on 6 Oct 2020

@MrManPew after doing debug mode for all the logs, if you set lncli debuglevel --level=PEER=info.

Roasbeef on 6 Oct 2020

@Roasbeef
If I set lncli debuglevel --level=PEER=info then what? I think you did not finish the sentence.
This is my lnd.conf:

# RaspiBolt LND Mainnet: lnd configuration
# /home/bitcoin/.lnd/lnd.conf
[Application Options]
debuglevel=debug
maxpendingchannels=5
color=#68F442
listen=localhost
nat=false
maxlogfiles=50
maxlogfilesize=20
#sync-freelist=1
rpclisten=0.0.0.0:10009
tlsextraip=192.168.1.0/24


[Bitcoin]
bitcoin.active=1
bitcoin.mainnet=1
bitcoin.node=bitcoind

[autopilot]
autopilot.active=0
autopilot.maxchannels=5
autopilot.allocation=0.6


[Tor]
tor.active=true
tor.v3=true

MrManPew on 7 Oct 2020

@Roasbeef @Crypt-iQ
Another one, with LN.SIDESHIFT.AI

2020-10-08 20:01:51.993 [DBG] CNCT: ChannelArbitrator(3114234b7b95278049b6790037b3e7d74d56a9cd13956d9fce32b05adc7ea140:0): go to chain for outgoing htlc 4811bd19193e4a29f5fcd025ab5e4d95b11f5bce0d1be89942bede0e3bec74c8: timeout=651859, blocks_until_expiry=0, broadcast_delta=0
2020-10-08 20:01:52.423 [INF] CNCT: ChannelArbitrator(3114234b7b95278049b6790037b3e7d74d56a9cd13956d9fce32b05adc7ea140:0): force closing chan
2020-10-08 20:01:59.410 [DBG] LNWL: ChannelPoint(3114234b7b95278049b6790037b3e7d74d56a9cd13956d9fce32b05adc7ea140:0): starting local commitment:

Full log attached
lnd.log.597_pass.zip

Password sent via slack.

MrManPew on 8 Oct 2020

👍1

@MrManPew that force close isn't abnormal, given that lnd went on-chain in order to claim an outgoing HTLC.

Roasbeef on 8 Oct 2020

But why did my node decided to do it ? I did not ask it to close the channel?

MrManPew on 8 Oct 2020

If your node didn't go on-chain, then it may have had to forfeit the amount delta of that HTLC. This is how HTLCs work: if you extend one to a party and they never claim it off-chain, if you want the funds back, then you need to go on-chain to claim them.

Roasbeef on 8 Oct 2020

Not sure I get it, but this is LN.SIDESHIFT.AI fault for not returning the HTLC back when a payment failed? Is it a connectivity problem?
Any suggestions?

MrManPew on 8 Oct 2020

@Roasbeef @Crypt-iQ
Another one, now with fixedfloat.com
BTW:

admin@rock64:~$ bitcoind --version
Bitcoin Core Daemon version v0.18.0

Could be the same problem, as I see ~sort of the same log:

2020-10-09 13:47:47.633 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): checking commit chain actions at height=651962, in_htlc_count=0, out_htlc_count=1
 lnd.log.623
2020-10-09 13:58:32.867 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): new block (height=651963) examining active HTLC's
 lnd.log.623
2020-10-09 13:58:32.871 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): checking commit chain actions at height=651963, in_htlc_count=0, out_htlc_count=1
 lnd.log.623
2020-10-09 14:41:41.276 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): new block (height=651964) examining active HTLC's
 lnd.log.624
2020-10-09 14:41:41.285 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): checking commit chain actions at height=651964, in_htlc_count=0, out_htlc_count=1
 lnd.log.624
2020-10-09 15:13:45.445 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): new block (height=651965) examining active HTLC's
 lnd.log.624
2020-10-09 15:13:45.449 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): checking commit chain actions at height=651965, in_htlc_count=0, out_htlc_count=1
 lnd.log.624
2020-10-09 15:13:57.348 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): new block (height=651966) examining active HTLC's
 lnd.log.624
2020-10-09 15:13:57.355 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): checking commit chain actions at height=651966, in_htlc_count=0, out_htlc_count=1
 lnd.log.624
2020-10-09 15:13:57.358 [DBG] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): go to chain for outgoing htlc 0620f0086e877919b190ef87d6b67f38bdca87ca7043781f688364c070f86327: timeout=651966, blocks_until_expiry=0, broadcast_delta=0
 lnd.log.624
2020-10-09 15:13:57.986 [INF] CNCT: ChannelArbitrator(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1): force closing chan

Not sure it is related, but the situation escalated the moment I increased the logging to debug mode

zip password sent by slack.
logss1.zip

Thanks

MrManPew on 10 Oct 2020

@Roasbeef , @Crypt-iQ I got another force close, as far as I understand, now out_htlc_count=0. So not clear from the logs why there is a force-close

Nodename: LNBIG.com [lnd-13]
Channel Point: cc73a92ce2ec37df18f8cb47333026e1d466e66d9ea9dee736d2b2ddbbb8e1dd:0

2020-10-11 04:03:10.206 [DBG] CNCT: ChannelArbitrator(cc73a92ce2ec37df18f8cb47333026e1d466e66d9ea9dee736d2b2ddbbb8e1dd:0): new block (height=652193) examining active HTLC's
2020-10-11 04:03:10.215 [DBG] CNCT: ChannelArbitrator(cc73a92ce2ec37df18f8cb47333026e1d466e66d9ea9dee736d2b2ddbbb8e1dd:0): checking commit chain actions at height=652193, in_htlc_count=0, out_htlc_count=0
2020-10-11 04:03:10.525 [INF] HSWC: Garbage collected 2 shared secret hashes at height=652193
2020-10-11 04:03:10.546 [DBG] PEER: Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=605108527822340096, mflags=00000001, cflags=00000000, update_time=2020-10-11 02:20:29 +0000 UTC) from 037f990e61acee8a7697966afd29dd88f3b1f8a7b14d625c4f8742bd952003a590@185.5.53.91:9735
2020-10-11 04:03:10.547 [DBG] PEER: Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=620141050870497280, mflags=00000001, cflags=00000001, update_time=2020-10-11 03:42:10 +0000 UTC) from 02b686ccf655ece9aec77d4d80f19bb9193f7ce224ab7c8bbe72feb3cdd7187e01@127.0.0.1:35544
2020-10-11 04:03:10.600 [INF] CNCT: ChannelArbitrator(cc73a92ce2ec37df18f8cb47333026e1d466e66d9ea9dee736d2b2ddbbb8e1dd:0): force closing chan

password send on slack
logg2.zip

Thanks

MrManPew on 12 Oct 2020

In both of those instances, you went on-chain to resolve HTLCs. Nothing out of the ordinary.

Roasbeef on 13 Oct 2020

Just to chime in and say that we at Strike are also experiencing this issue. We'll try to come up with logs and help debug it. cc @mrfelton

rockstardev on 13 Oct 2020

Thanks for the new reports all! Just to note again, we're only interested in force closures that _aren't_ HTLC related go-to chain events. When sending or scanning for logs, the main sub-system to look at is LNWL (can show invalid sigs, or w/e), HSWC (the switch), and CNCT (the thing that decides go on-chain).

So far none of the logs above (that we could decrypt) have been actionable yet on our part.

Roasbeef on 14 Oct 2020

Not sure I get it, but this is LN.SIDESHIFT.AI fault for not returning the HTLC back when a payment failed? Is it a connectivity problem?
Any suggestions?

Is there an answer to this question above? Didn't see one here. Should I stop connecting with nodes that do this? Is it me? Is running on tor causing missed payments with connectivity problems? Is this malice from the sender that is routing through me? Seems like the answer is "totally normal" with no answer as to how to minimize this from occurring.

AnthonyRonning on 15 Oct 2020

Is there an answer to this question above?

There are a few reasons why this could happen:

If your node is not reachable, your peer may not be able to connect to you to settle back after restart (simple enough to debug on your own), could be the case if you're having issues with ToR
If your peer is offline a lot (check the output for ListChannels to see their uptime percentage uptime/lifetime), then your node would have gone to chain to claim the amount
-> shameless Faraday shill here, the cli insights command will give you this info + more
Theoretically, a node could also maliciously not release the htlc but that would require running a forked evil implementation, would end up costing them if they opened the channel, and if you opened the channel, they still gain nothing (you just pay some fees)

carlaKC on 16 Oct 2020

❤2

Another actionable step would be to update policy on your public channels. These force closes do cost on-chain fees, so it's worth adjusting your policies beyond the default values to reflect the chance that you may face these costs:

Set base_fee_rate and fee_rate to non-default values: you are providing a routing service which comes with costs, price your liquidity accordingly (you can also look at the output of DescribeGraph to see what other nodes are doing)
Set min_htlc_msat to control the value of the smallest htlc you are willing to route. With the knowledge that you may go to chain to claim the value of a htlc, setting this value higher means that you will only go on chain for larger amounts (with the tradeoff that you may route less because you reject small payments).

Of course, if you don't want to route you can always --rejecthltcs for existing public channels, or setup private channels.

We're all still figuring it out, and force closes will happen, but it's really about choosing the tradeoffs that work for you at the end of the day. IMO, it can be quite fun trying to figure out the best way to setup a routing node, but if you don't want that exposure, you also have that option.

carlaKC on 16 Oct 2020

Hi @carlaKC thank you for the detailed explanation. Not sure it fits my situation exactly because:

My node is reachable 24/7 in a dedicated Rock64 connected with a cable (BOS score top 5% of the network, RCN ISP)
The peers that I got the force close with are well known and stable nodes (fixedfloat, LNBIG.com [lnd-13], LN.SIDESHIFT.AI, zapread.com).

And most importantly, I changed the logging to debug, so you can see that I have ping/pong to those nodes. So I don't understand exactly how your explanation fits the situation.

Thank you

MrManPew on 16 Oct 2020

@MrManPew, I was more trying to answer the question "how to minimize this from occurring" above, so my suggestions are more general advice (which I thought may be userful to other people who find this issue) than a specific investigation of your force close. Should have made that clearer!

carlaKC on 18 Oct 2020

👍1

We just had another channel from OpenNode force closed. Here are some relevant logs:

2020-10-19 08:42:16.094 [INF] CNCT: ChannelArbitrator(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): trigger userTrigger moving from state StateCommitmentBroadcasted to StateCommitmentBroadcasted
2020-10-19 08:42:16.094 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): Restoring 0 local updates that the peer should sign
2020-10-19 08:42:16.093 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): Restoring 0 dangling remote updates
2020-10-19 08:42:16.091 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): starting remote commitment: (*lnwallet.commitment)(0xc006ee2300)({
2020-10-19 08:42:16.089 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): starting local commitment: (*lnwallet.commitment)(0xc006ee2180)({
2020-10-19 08:42:16.053 [INF] LNWL: Inserting unconfirmed transaction 92226e338c4caf7592497dc5144adff32133479c1a35be674a6e22fc2aac0d67
2020-10-19 08:42:16.052 [INF] CNCT: Broadcasting force close transaction 92226e338c4caf7592497dc5144adff32133479c1a35be674a6e22fc2aac0d67, ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): (*wire.MsgTx)(0xc0060d5600)({
2020-10-19 08:42:16.046 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): Restoring 0 local updates that the peer should sign
2020-10-19 08:42:16.045 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): Restoring 0 dangling remote updates
2020-10-19 08:42:16.043 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): starting remote commitment: (*lnwallet.commitment)(0xc004f68840)({
2020-10-19 08:42:16.040 [DBG] LNWL: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): starting local commitment: (*lnwallet.commitment)(0xc004f686c0)({
2020-10-19 08:42:16.038 [INF] HSWC: Removing channel link with ChannelID(1f86d2b734d90799b952efd8e7ccaf4f6a0294086f66a70d9e95303da914be8a)
2020-10-19 08:42:16.035 [INF] CNCT: ChannelArbitrator(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): force closing chan
2020-10-19 08:42:16.024 [DBG] CNCT: ChannelArbitrator(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): checking commit chain actions at height=653399, in_htlc_count=0, out_htlc_count=1
2020-10-19 08:42:16.023 [DBG] CNCT: ChannelArbitrator(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): new block (height=653399) examining active HTLC's
2020-10-19 08:42:16.019 [INF] CNCT: Attempting to force close ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0)
2020-10-19 08:42:16.019 [WRN] PEER: Force closing link(649686:2138:0)
2020-10-19 08:42:16.019 [INF] HSWC: ChannelLink(649686:2138:0): stopping
2020-10-19 08:42:16.019 [INF] HSWC: Removing channel link with ChannelID(1f86d2b734d90799b952efd8e7ccaf4f6a0294086f66a70d9e95303da914be8a)
2020-10-19 08:42:16.018 [INF] HSWC: ChannelLink(649686:2138:0): exited
2020-10-19 08:42:16.018 [ERR] HSWC: ChannelLink(649686:2138:0): link failed, exiting htlcManager
2020-10-19 08:42:16.018 [ERR] HSWC: ChannelLink(649686:2138:0): failing link: ChannelPoint(8abe14a93d30959e0da7666f0894026a4fafcce7d8ef52b99907d934b7d2861f:0): unable to accept new commitment: rejected commitment: commit_height=6668, invalid_htlc_sig=30440220528973a546e23b5a8804f8a2d56de89507d077d588b61676079e74d079be3f160220301ca20341679828462c289a1106badd6dcdac4e0892cd387501478c62524d77, commit_tx=02000000011f86d2b734d90799b952efd8e7ccaf4f6a0294086f66a70d9e95303da914be8a0000000000e5b888800435fc030000000000160014c451993f9df7450dcfa030c8d32e06759662d322239e2100000000002200203aaf3923de92118bc563d71f2026d59abd619837388f3c7083235e22199607faafdeab000000000022002055aa9714863a1bb2b135a7e8b1c5e4e1a36424ba3c3c7d2da944cf84a43271a8afdeab000000000022002055aa9714863a1bb2b135a7e8b1c5e4e1a36424ba3c3c7d2da944cf84a43271a861b1cc20, sig_hash=c52bf9f265e4a90b9564d4ec4ec04b06b46880dc8ebf691d785eed85ca82a677 with error: invalid commitment
2020-10-19 08:42:15.958 [DBG] HSWC: ChannelLink(649686:2138:0): removing Add packet (Chan ID=650048:2105:1, HTLC ID=1042) from mailbox
2020-10-19 08:42:15.898 [DBG] HSWC: ChannelLink(649686:2138:0): queueing keystone of ADD open circuit: (Chan ID=650048:2105:1, HTLC ID=1042)->(Chan ID=649686:2138:0, HTLC ID=1387)
2020-10-19 08:42:15.886 [DBG] HSWC: ChannelLink(650048:2105:1): forwarding 1 packets to switch
2020-10-19 08:42:15.122 [DBG] HSWC: Sent 0 satoshis and received 0 satoshis in the last 10 seconds (2.600000 tx/sec)
2020-10-19 08:42:14.477 [DBG] HSWC: ChannelLink(650048:2105:1): removing Fail/Settle packet (Chan ID=650048:2105:1, HTLC ID=1041) from mailbox
2020-10-19 08:42:14.460 [DBG] HSWC: ChannelLink(650048:2105:1): queueing removal of FAIL closed circuit: (Chan ID=650048:2105:1, HTLC ID=1041)->(Chan ID=652102:572:0, HTLC ID=2482)

Any insight in the the specific reason this was force closed? Anything else I can provide to help?

mrfelton on 20 Oct 2020

Any insight in the the specific reason this was force closed? Anything else I can provide to help?

Have you been noticing any connection issues - your logs, unlike some of the other ones, actually have an invalid commitment log line. There is one remaining class of force close that we don't yet handle - it's tracked on the spec level (https://github.com/lightningnetwork/lightning-rfc/issues/794) and that could be what you're experiencing.

Crypt-iQ on 20 Oct 2020

What kind of connection issues @Crypt-iQ ? Our nodes are connected 24/7. I have noticed that some of the nodes that we are connected to randomly show as offline when I know that they are not actually offline (since I can confirm that our other nodes are still connected to the peer that shows as offline, and if I issue a lncli disconnect/connect it reestablishes the connection to the peer and shows as online again.

mrfelton on 20 Oct 2020

Did you notice this after issuing a disconnect/connect command?

Crypt-iQ on 20 Oct 2020

No, and the node that I had to disconnect/reconnect was a different one (Bitrefill). We have several channels with OpenNode and have not noticed any specific issues with them prior to this force closure.

mrfelton on 20 Oct 2020

No, and the node that I had to disconnect/reconnect was a different one (Bitrefill). We have several channels with OpenNode and have not noticed any specific issues with them prior to this force closure.

Do you know what version OpenNode is running?

Crypt-iQ on 20 Oct 2020

Apparently they just updated from 0.7.x to to v0.11.x yesterday @Crypt-iQ

mrfelton on 20 Oct 2020

Apparently they just updated from 0.7.x to to v0.11.x yesterday @Crypt-iQ

Do you know (from your logs maybe?) whether the force close occurred before or after the upgrade?

Crypt-iQ on 20 Oct 2020

Two more force-close
Node names:
@CoinGate
@BitMEXResearch

In the case of @BitMEXResearch
out_htlc_count>0 so I assume it suppose to force close, right?
Do you want me to keep reporting it? Or should I stop?

2020-10-20 02:31:08.769 [DBG] CNCT: ChannelArbitrator(5508a3cb1bd3658bfd3b4a1b4863210e8af661f650b880dc44ac74ec7af7b375:0): checking commit chain actions at height=653506, in_htlc_count=0, out_htlc_count=2
 lnd.log.905
2020-10-20 02:31:08.774 [DBG] CNCT: ChannelArbitrator(5508a3cb1bd3658bfd3b4a1b4863210e8af661f650b880dc44ac74ec7af7b375:0): go to chain for outgoing htlc 12c242d9196a39238f262f0ab4bdd396b2c87650047739a23cbc9449858b827f: timeout=653506, blocks_until_expiry=0, broadcast_delta=0
 lnd.log.905
2020-10-20 02:31:09.451 [INF] CNCT: ChannelArbitrator(5508a3cb1bd3658bfd3b4a1b4863210e8af661f650b880dc44ac74ec7af7b375:0): force closing chan

In the case of @CoinGate , It catually seems that I owed them an htlc (we owe them a commitment), so I did not return it and this is why the force-closed the channel. No idea why my node did not return it.

2020-10-19 04:03:19.874 [DBG] CNCT: ChannelArbitrator(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): checking commit chain actions at height=653376, in_htlc_count=2, out_htlc_count=0
2020-10-19 04:05:08.324 [DBG] CHFT: Channel 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0 recording event: peer_offline
2020-10-19 04:05:09.860 [DBG] CHFT: Channel 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0 recording event: peer_online
2020-10-19 04:05:10.244 [DBG] LNWL: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): sync: remote believes our tail height is 3434, while we have 3435, we owe them a revocation
2020-10-19 04:05:10.245 [DBG] LNWL: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): sync: remote's next commit height is 3436, while we believe it is 3436, we owe them a commitment
2020-10-19 04:05:11.796 [ERR] HSWC: ChannelLink(584107:1286:0): failing link: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): received error from peer: chan_id=94d89be7009f2ad541f92d22b0fd357f2025d16813f2f66386bb6e6088dc7b0b, err=invalid commitment with error: remote error
2020-10-19 04:19:49.523 [DBG] NTFN: Found spend of outpoint=0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0, script=0 cd5be724c762ad4f4c889fd4999410b01b5c1db657773c73230406b91ea40b68: spend_tx=9ac829b5ffe4ebb777f67c45f2b1806bc310627cdf6cd24d5c4cec08df697ad2, block_height=653377
2020-10-19 04:19:51.088 [DBG] NTFN: Found spend of outpoint=0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0, script=0 cd5be724c762ad4f4c889fd4999410b01b5c1db657773c73230406b91ea40b68: spend_tx=9ac829b5ffe4ebb777f67c45f2b1806bc310627cdf6cd24d5c4cec08df697ad2, block_height=653377
2020-10-19 04:19:51.088 [DBG] NTFN: Spend request outpoint=0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0, script=0 cd5be724c762ad4f4c889fd4999410b01b5c1db657773c73230406b91ea40b68 spent at tip=653377
2020-10-19 04:19:51.970 [INF] NTFN: Dispatching confirmed spend notification for outpoint=0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0, script=0 cd5be724c762ad4f4c889fd4999410b01b5c1db657773c73230406b91ea40b68 at current height=653377: 9ac829b5ffe4ebb777f67c45f2b1806bc310627cdf6cd24d5c4cec08df697ad2[0] spending 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0 at height=653377
2020-10-19 04:19:51.973 [DBG] CNCT: ChannelArbitrator(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): new block (height=653377) examining active HTLC's
2020-10-19 04:19:51.979 [DBG] CNCT: ChannelArbitrator(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): checking commit chain actions at height=653377, in_htlc_count=2, out_htlc_count=0
2020-10-19 04:19:51.988 [DBG] CNCT: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): local_commit_type=0, local_commit=(*channeldb.ChannelCommitment)(0x400082ebf0)({
    PreviousOutPoint: (wire.OutPoint) 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0,
2020-10-19 04:19:51.995 [DBG] CNCT: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): remote_commit_type=0, remote_commit=(*channeldb.ChannelCommitment)(0x400082ec70)({
    PreviousOutPoint: (wire.OutPoint) 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0,
2020-10-19 04:19:51.999 [DBG] CNCT: ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): remote_pending_commit_type=0, remote_pending_commit=(channeldb.ChannelCommitment) {
    PreviousOutPoint: (wire.OutPoint) 0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0,
2020-10-19 04:19:52.008 [WRN] CNCT: Unprompted commitment broadcast for ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0) 
2020-10-19 04:19:52.013 [INF] CNCT: Unilateral close of ChannelPoint(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0) detected
2020-10-19 04:19:52.019 [INF] CNCT: ChannelArbitrator(0b7bdc88606ebb8663f6f21368d125207f35fdb0222df941d52a9f00e79bd894:0): remote party has closed channel out on-chain

Tell me if you are interested in the full logs.

MrManPew on 20 Oct 2020

Apparently they just updated from 0.7.x to to v0.11.x yesterday @Crypt-iQ

Do you know (from your logs maybe?) whether the force close occurred before or after the upgrade?

They performed the upgrade at around 22:45 PST. The channel closure happened at 01:42 PST. So, seems the channel was force closed whist their node was running the older version.

mrfelton on 20 Oct 2020

@MrManPew for the coingate channel this is tracked as a spec issue

@mrfelton This should be normal as the older version of the software inconsistently handled some commitment tx data.

If either of you see any force closures with both channel parties running v0.11, then I think we can look into that more concretely.

Crypt-iQ on 21 Oct 2020

Just had three more channels with Fold node simultaneously force closed:

2020-10-22 06:43:23.834 [DBG] CNCT: ChannelArbitrator(5e9eac0744e00bb7b62c5aad5b64047b6a9ead5676d7908b4551bac19f743683:0): checking commit chain actions at height=653793, in_htlc_count=0, out_htlc_count=0
2020-10-22 06:43:23.834 [DBG] CNCT: ChannelArbitrator(84ec882c4afbbe0490d44071bb889cd479a8c9563da8f7df1e5fa5409a38ba7f:0): checking commit chain actions at height=653793, in_htlc_count=0, out_htlc_count=0
2020-10-22 06:43:23.834 [DBG] CNCT: ChannelArbitrator(d829cae5f3a2658de40738200efc4041eb44e3f4ab35748ff121fd7b2df24890:0): checking commit chain actions at height=653793, in_htlc_count=0, out_htlc_count=0
2020-10-22 06:43:23.834 [DBG] CNCT: ChannelArbitrator(7b9e4476fddf8f4fbc0f1ffad157cde4b23fcbe86eacbb2c4eb27d0f351af2be:0): checking commit chain actions at height=653793, in_htlc_count=0, out_htlc_count=0
2020-10-22 06:43:23.835 [INF] CNCT: ChannelArbitrator(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): force closing chan
2020-10-22 06:43:23.835 [INF] CNCT: ChannelArbitrator(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): force closing chan
2020-10-22 06:43:23.838 [INF] HSWC: Garbage collected 10 shared secret hashes at height=653793
2020-10-22 06:43:23.838 [INF] HSWC: Removing channel link with ChannelID(d40b77e9e41ffe6bd7eea5d8f14d0f9460645b4022377e07fcd116ddd05c533f)
2020-10-22 06:43:23.840 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): starting local commitment: (*lnwallet.commitment)(0xc0051b8300)({
2020-10-22 06:43:23.843 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): starting remote commitment: (*lnwallet.commitment)(0xc0051b8480)({
2020-10-22 06:43:23.846 [INF] HSWC: Removing channel link with ChannelID(39d75cc2d2d192adff56def4beea62047ea994998e1e458a34504ad4aac2a48e)
2020-10-22 06:43:23.845 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): pending remote commitment: (*lnwallet.commitment)(0xc003aee3c0)({
2020-10-22 06:43:23.848 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): starting local commitment: (*lnwallet.commitment)(0xc003a12900)({
2020-10-22 06:43:23.850 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): Restoring 0 dangling remote updates
2020-10-22 06:43:23.850 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): Restoring 0 local updates that the peer should sign
2020-10-22 06:43:23.850 [INF] CNCT: ChannelArbitrator(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): force closing chan
2020-10-22 06:43:23.851 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): starting remote commitment: (*lnwallet.commitment)(0xc0033f7380)({
2020-10-22 06:43:23.852 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): pending remote commitment: (*lnwallet.commitment)(0xc0045cd200)({
2020-10-22 06:43:23.852 [INF] HSWC: Removing channel link with ChannelID(03cf6441e8fd5b432e65de2ce6f8a551b71de906e53ff0a4e08affc846aadeb9)
2020-10-22 06:43:23.853 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): Restoring 0 dangling remote updates
2020-10-22 06:43:23.853 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): Restoring 0 local updates that the peer should sign
2020-10-22 06:43:23.854 [INF] CNCT: Broadcasting force close transaction 679ccd2c3464212f25268ca8a01e3ee90bcef0ff5efc6b80e7b85c167cf9209a, ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): (*wire.MsgTx)(0xc000822940)({
2020-10-22 06:43:23.855 [INF] LNWL: Inserting unconfirmed transaction 679ccd2c3464212f25268ca8a01e3ee90bcef0ff5efc6b80e7b85c167cf9209a
2020-10-22 06:43:23.855 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): starting local commitment: (*lnwallet.commitment)(0xc0051b8540)({
2020-10-22 06:43:23.857 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): starting remote commitment: (*lnwallet.commitment)(0xc003f2a6c0)({
2020-10-22 06:43:23.858 [INF] CNCT: Broadcasting force close transaction 5a24bf384d9c0dc805510772c9aac633000401842cf7735fedb293385820d4c3, ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): (*wire.MsgTx)(0xc004ec3340)({
2020-10-22 06:43:23.858 [INF] LNWL: Inserting unconfirmed transaction 5a24bf384d9c0dc805510772c9aac633000401842cf7735fedb293385820d4c3
2020-10-22 06:43:23.858 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): pending remote commitment: (*lnwallet.commitment)(0xc003f2a900)({
2020-10-22 06:43:23.860 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): Restoring 0 dangling remote updates
2020-10-22 06:43:23.860 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): Restoring 0 local updates that the peer should sign
2020-10-22 06:43:23.866 [INF] CNCT: Broadcasting force close transaction 519511b702e65dd42f4b46ac6cb8f2716a9ef10e09cf60a03fdb23f3150eca50, ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): (*wire.MsgTx)(0xc005680f40)({
2020-10-22 06:43:23.867 [INF] LNWL: Inserting unconfirmed transaction 519511b702e65dd42f4b46ac6cb8f2716a9ef10e09cf60a03fdb23f3150eca50
2020-10-22 06:43:23.941 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): starting local commitment: (*lnwallet.commitment)(0xc00473c000)({
2020-10-22 06:43:23.941 [DBG] LNWL: ChannelPoint(3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1): starting local commitment: (*lnwallet.commitment)(0xc0049c7680)({
2020-10-22 06:43:23.943 [DBG] LNWL: ChannelPoint(8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0): starting remote commitment: (*lnwallet.commitment)(0xc003f2a000)({
2020-10-22 06:43:23.944 [DBG] LNWL: ChannelPoint(b9deaa46c8ff8ae0a4f03fe506e91db751a5f8e62cde652e435bfde84164cf03:0): starting local commitment: (*lnwallet.commitment)(0xc004b26300)({

mrfelton on 22 Oct 2020

Just to add to that too - we are also experiencing connectivity issues with the Fold node. It randomly starts showing as offline when in fact I know it is online. For example, right now I have the following channels with Fold:

7x pending force closing
1x online
1x offline

How can one of the channels be showing as offline whist the other shows as online, given that they are both to the same peer?

Running the following makes the offline one start showing online again:

lncli disconnect 02816caed43171d3c9854e3b0ab2cf0c42be086ff1bd4005acc2a5f7db70d83774
lncli connect 02816caed43171d3c9854e3b0ab2cf0c42be086ff1bd4005acc2a5f7db70d83774@35.238.153.25:9735

I'm detailing it here since this seems to be a common thread with the nodes that keep force closing on us but let me know if I should I create a separate issue for the disconnect/reconnect issue.

mrfelton on 22 Oct 2020

Thanks @mrfelton ! Fold was one I was having the forced closed issue with myself. Do we know what version they are on?

AnthonyRonning on 22 Oct 2020

Could you please create a separate issue for the connect/disconnect issue so this one is just force closes @mrfelton ? Version for fold would help as well, [PEER] & [HSWC] logs are probably mostly what is needed for diagnosis.

Crypt-iQ on 22 Oct 2020

Thanks @mrfelton ! Fold was one I was having the forced closed issue with myself. Do we know what version they are on?

Fold is on version 0.11.0-beta.

tdickman on 22 Oct 2020

@tdickman did Fold upgrade before or after these force closes?

Crypt-iQ on 22 Oct 2020

They have been running this node version for a while. Here are the full logs from around the time of the closures.

lnd-logs.zip

mrfelton on 22 Oct 2020

@mrfelton and I have been DM-ing back and forth. There are 4 channels that have been force closed between us recently:

3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1
3096b5bbf7a31c2bd9b262572cd4e8b169e6ac78fb77a420f6d8575e109f4db3:0
8ea4c2aad44a50348a451e8e9994a97e0462eabef4de56ffad92d1d2c25cd739:0
88f8307d2c8c9e15a4d2181dc9db2c10a2ae26d5f94e98d831c5ef3db0c04d20:0

None of these appear in our channels list (which is weird). Here is a filtered view of our logs, searching for any references to the first channel: https://paste.ubuntu.com/p/B2ZC4K6Twz/

tdickman on 22 Oct 2020

Here is our data on that same channel:

        {
            "channel": {
                "remote_node_pub": "02816caed43171d3c9854e3b0ab2cf0c42be086ff1bd4005acc2a5f7db70d83774",
                "channel_point": "3e535cd0dd16d1fc077e3722405b6460940f4df1d8a5eed76bfe1fe4e9770bd4:1",
                "capacity": "15000000",
                "local_balance": "5032983",
                "remote_balance": "0",
                "local_chan_reserve_sat": "0",
                "remote_chan_reserve_sat": "0",
                "initiator": "INITIATOR_LOCAL",
                "commitment_type": "STATIC_REMOTE_KEY"
            },
            "closing_txid": "679ccd2c3464212f25268ca8a01e3ee90bcef0ff5efc6b80e7b85c167cf9209a",
            "limbo_balance": "5032983",
            "maturity_height": 655597,
            "blocks_til_maturity": 1754,
            "recovered_balance": "0",
            "pending_htlcs": [
            ],
            "anchor": "LIMBO"
        },

mrfelton on 22 Oct 2020

We had an unexpected unilateral channel close between 2 nodes we control, both running 0.11.0. We have not found "expire" in our logs. Are there some logs we can provide?
This was the commitment error message:
Oct 21 21:13:22 donnernode lnd[24389]: 2020-10-21 21:13:22.428 [ERR] HSWC: ChannelLink(652714:1118:1): failing link: ChannelPoint(d7f0b27fe98a68640250c71414cbf598a85898ca5d970992d6115f999a410dc9:1): unable to accept new commitment: rejected commitment: commit_height=3189, invalid_commit_sig=3045022100e47d73be443dd4fb11e81a7d4720572b03dca9ff33dbeba7f6e8f8f97bed6e0202206ffa41247f2b575e4f5be5ac8fa78d611e7137833c4311ab532fa1473a0c1f11, commit_tx=0200000001c90d419a995f11d69209975dca9858a898f5cb1414c7500264688ae97fb2f0d70100000000b6d3a58002be3d1b0000000000160014ca59ef805ca3acabbf3992a66a2dd59486503f43e7be300000000000220020a292f4e51422e95a4fef0b61d84f0a54f1bb9c86cea3911ae0d8ad71d5edb4c91be2cf20, sig_hash=77fcb455787523de2045d4fab9c2c5771c5b3b4d56c2809040be8add152a5c5f with error: invalid commitment

sputn1ck on 23 Oct 2020

Another force-close from my side, now with @RiverFinancial , I assume that they are running latest version
in_htlc_count=0, out_htlc_count=0

full log, debug mode (password is the same as before, see slack)

2020-10-22 15:31:48.864 [DBG] CNCT: ChannelArbitrator(2ffd7fc2c769ffac18b04f81a01e8419331ee084ca471cf4aecaa2da800e4631:0): new block (height=653846) examining active HTLC's
2020-10-22 15:31:48.864 [DBG] CNCT: ChannelArbitrator(2ffd7fc2c769ffac18b04f81a01e8419331ee084ca471cf4aecaa2da800e4631:0): checking commit chain actions at height=653846, in_htlc_count=0, out_htlc_count=0
2020-10-22 15:31:49.326 [DBG] DISC: New block: height=653846, hash=0000000000000000000867f160899f5ccbf5e93e050195a0500d3e1bdc80993b
2020-10-22 15:31:49.326 [DBG] PEER: Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=678047930287587328, mflags=00000001, cflags=00000001, update_time=2020-10-22 15:03:21 +0000 UTC) from 0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782@213.174.156.86:9735
2020-10-22 15:31:49.360 [INF] CNCT: ChannelArbitrator(2ffd7fc2c769ffac18b04f81a01e8419331ee084ca471cf4aecaa2da800e4631:0): force closing chan

lndlog.zip

MrManPew on 24 Oct 2020

Experienced a force close in the following situation:

Channel flooded with HTLCs in jamming experiment
Endless payment loop after attempting to pay an invoice through this channel
Failed to reconnect; rejected commitment:

[ERR] HSWC: ChannelLink(657759:561:0): failing link: ChannelPoint(c37bec006b18df172698a84739ca47128935e0a8666fecd1a843e49b01db207c:0): received error from peer: chan_id=7c20db019be443a8d1ec6f66a8e035891247ca3947a8982617df186b00ec7bc3, err=rejected commitment: commit_height=455, invalid_commit_sig=3044022076fd65191eb6305b723fa6012be378413b6326e2786c38db58b4c02e1f3999d202207605ca31de8b4c5b1d9cd20dc1581dfa2383e0b4e06c8ad4f718ab5c434d8cf5, commit_tx=02000000017c20db019be443a8d1ec6f66a8e035891247ca3947a8982617df186b00ec7bc300000000008a792e8002210d0000000000002200201031cf10a1efef261edd3d0a1a6a953b27bc25bd7150bb2b07afdc69805e02157213000000000000160014de650929042bef58b71783ae1a44834a902a8f2d542ca720, sig_hash=4e0fb804c74376020e4c44a60969b9206eb0aaa9a89b76017d60f23ad5cf63e5 with error: remote error