Lnd: My node force-closed channel with bfx-lnd1, not sure why

[MrManPew]

Background

My node foce-closed channel with bfx-lnd0 so I opened a new one with bfx-lnd1 and my node also closed this channel.
I did not do anything to foce-close the channel.

Here are some of the logs:

2020-06-13 13:35:54.946 [INF] NTFN: New spend subscription: spend_id=43, outpoint=97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0, script=0 036081b2f5cd128d16f2b3d8a2b84c88d6d4a0cd8da6f210a70fe42f15704578, height_hint=634553
2020-06-13 13:35:54.947 [INF] NTFN: Dispatching historical spend rescan for outpoint=97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0, script=0 036081b2f5cd128d16f2b3d8a2b84c88d6d4a0cd8da6f210a70fe42f15704578, start=634553, end=634557
2020-06-13 13:35:59.113 [INF] CNCT: Close observer for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) active
2020-06-13 13:36:02.915 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): starting state=StateDefault, trigger=chainTrigger, triggerHeight=634558
2020-06-13 13:39:25.380 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-13 13:39:25.591 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 00:58:45.513 [INF] NANN: Announcing channel(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) disabled [detected]
2020-06-15 01:05:41.320 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 01:05:41.371 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 01:24:42.805 [INF] NANN: Announcing channel(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) enabled
2020-06-15 06:22:10.190 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 06:22:10.359 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 06:47:39.087 [INF] NTFN: New spend subscription: spend_id=33, outpoint=97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0, script=0 036081b2f5cd128d16f2b3d8a2b84c88d6d4a0cd8da6f210a70fe42f15704578, height_hint=634826
2020-06-15 06:47:39.088 [INF] NTFN: Dispatching historical spend rescan for outpoint=97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0, script=0 036081b2f5cd128d16f2b3d8a2b84c88d6d4a0cd8da6f210a70fe42f15704578, start=634826, end=634830
2020-06-15 06:47:40.140 [INF] CNCT: Close observer for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) active
2020-06-15 06:47:46.584 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): starting state=StateDefault, trigger=chainTrigger, triggerHeight=634830
2020-06-15 06:49:23.447 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 06:49:23.453 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-15 07:08:30.179 [INF] NANN: Announcing channel(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) disabled [detected]
2020-06-15 07:08:38.753 [INF] NANN: Announcing channel(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) enabled
2020-06-18 05:02:24.279 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-18 05:02:24.287 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-18 07:37:34.851 [INF] PEER: NodeKey(03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6) loading ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-18 07:37:34.940 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0)
2020-06-18 08:26:58.994 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): force closing chan
2020-06-18 08:27:00.393 [INF] CNCT: Broadcasting force close transaction 8c50b676a62297640067a6bab7b12ef4c3a198610e13f00e29b6a92ec00837a6, ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): (*wire.MsgTx)(0x40031b7280)({
   PreviousOutPoint: (wire.OutPoint) 97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0,
2020-06-18 08:27:02.114 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): trigger chainTrigger moving from state StateCommitmentBroadcasted to StateCommitmentBroadcasted
2020-06-18 08:36:02.981 [INF] NTFN: Dispatching confirmed spend notification for outpoint=97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0, script=0 036081b2f5cd128d16f2b3d8a2b84c88d6d4a0cd8da6f210a70fe42f15704578 at current height=635268: 8c50b676a62297640067a6bab7b12ef4c3a198610e13f00e29b6a92ec00837a6[0] spending 97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0 at height=635268
2020-06-18 08:36:03.001 [INF] CNCT: Local unilateral close of ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) detected
2020-06-18 08:36:03.102 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): local on-chain channel close
2020-06-18 08:36:05.414 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): trigger localCloseTrigger moving from state StateCommitmentBroadcasted to StateContractClosed
2020-06-18 08:36:05.687 [INF] UTXN: Incubating Channel(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) num-htlcs=1
2020-06-18 08:36:05.845 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): still awaiting contract resolution
2020-06-19 11:47:39.724 [INF] CNCT: *contractcourt.commitSweepResolver(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): Sweeping with witness type: CommitmentTimeLock
2020-06-19 11:47:39.726 [INF] CNCT: *contractcourt.commitSweepResolver(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): sweeping commit output
2020-06-19 14:31:00.335 [INF] CNCT: *contractcourt.commitSweepResolver(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): commit tx fully resolved by sweep tx: b6b0ec3eb12eee7f0f43f89f1d43d63724bae9cf69cff91a37854473a130b4f4
2020-06-19 14:31:00.597 [INF] UTXN: Removed channel 97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0 from nursery store
2020-06-19 14:31:00.664 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): a contract has been fully resolved!
2020-06-19 14:31:00.664 [INF] CNCT: ChannelArbitrator(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0): still awaiting contract resolution
2020-06-19 14:31:00.730 [INF] CNCT: ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) has been fully resolved on-chain at height=635422
2020-06-19 14:31:00.730 [INF] CNCT: Marking ChannelPoint(97face4492e046ac5734ddb92dcc41fcc6e82d89f59f8c9fa4d4d47f5ec8d49b:0) fully resolved

Your environment

0.10.1
Linux rock64 4.4.132-1075-rockchip-ayufan-ga83beded8524 #1 SMP Thu Jul 26 08:22:22 UTC 2018 aarch64 GNU/Linux
bitcoind

Thanks

[Roasbeef]

Were there unresolved HTLCs on the commitment transaction (indicating an HTLC timeout)? If not, then it may have been channel state de-sync, in which case we have a number of open PRs that should fix the issue such as: #4430.

[Crypt-iQ]

Even though we have fixes for the latter case, we'd still like logs (if that's okay) to determine why nodes are disconnecting and causing this de-sync. But only if an htlc didn't time out.

[MrManPew]

Were there unresolved HTLCs on the commitment transaction (indicating an HTLC timeout)? If not, then it may have been channel state de-sync, in which case we have a number of open PRs that should fix the issue such as: #4430.

@Roasbeef
Not sure how can I check this?

@Crypt-iQ I'll be haapy to send full log file, but I assume there is some private info in there, I'll like to send it privately - maybe I can send it by Slack? PM ? what is your slack username?

[Crypt-iQ]

@MrManPew I am "eugene" on the lnd slack

[MrManPew]

Great @Crypt-iQ , I've sent you the log on slack. Is it the same issue?

[Crypt-iQ]

Sorry, the logs only show the other peer disconnecting. I would need the opposite peer's logs to figure out why they're disconnecting.

[MrManPew]

The opposite side is https://ln.bitfinex.com/.
Maybe @bitfinexcom, @prdn, @mafintosh can help?

[MrManPew]

Another one @Crypt-iQ , now my node force-closed a channel with @acinq.
@t-bast could you help with finding out why we got disconnected ?
I've added the full log to lnd Slack.