Lnd: LND hangs at 'CNCT: ChannelArbitrator(b4f9....a9335:1): force closing chan'

[grunch]

Background

My LND node just stop working properly and restarted, when I unlock the wallet it restarts again and go back to locked wallet state

Your environment

• lnd version 0.4.2-beta commit=f0f5e11b826e020c11c37343bcbaf9725627378b
• Linux wepa 4.15.0-29-generic #31-Ubuntu SMP Tue Jul 17 15:39:52 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
• Bitcoin Core Daemon version v0.16.0

Steps to reproduce

just starting the node
lnd.conf file (I recently commented the autopilot)

[Application Options]
debuglevel=info
maxpendingchannels=5
alias=alias
color=#2c5f85
restlisten=localhost:8080
restlisten=192.168.0.21:8080
rpclisten=localhost:10009
rpclisten=192.168.0.21:10009
tlsextradomain=extradomain.xyz

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

#[autopilot]
#autopilot.active=1
#autopilot.maxchannels=5
#autopilot.allocation=0.6

Expected behaviour

It should starts normally

Actual behaviour

It stops
log file

2018-08-21 15:50:04.026 [INF] LNWL: Opened wallet
2018-08-21 15:50:04.256 [INF] LTND: Primary chain is set to: bitcoin
2018-08-21 15:50:04.257 [INF] LTND: Initializing bitcoind backed fee estimator
2018-08-21 15:50:04.263 [INF] LNWL: Started listening for blocks via ZMQ on tcp://127.0.0.1:29000
2018-08-21 15:50:06.589 [INF] LNWL: The wallet has been unlocked without a time limit
2018-08-21 15:50:06.589 [INF] LTND: LightningWallet opened
2018-08-21 15:50:06.669 [INF] HSWC: Restoring in-memory circuit state from disk
2018-08-21 15:50:06.986 [INF] LNWL: Started rescan from block 00000000000000000029825d1789f267b4e7f1d77e018a25d0d2b32b1a03c3d7 (height 537835) for 524 addresses
2018-08-21 15:50:07.021 [INF] LNWL: Starting rescan from block 00000000000000000029825d1789f267b4e7f1d77e018a25d0d2b32b1a03c3d7
2018-08-21 15:50:07.038 [INF] LNWL: Rescan finished at 537835 (00000000000000000029825d1789f267b4e7f1d77e018a25d0d2b32b1a03c3d7)
2018-08-21 15:50:07.039 [INF] LNWL: Catching up block hashes to height 537835, this might take a while
2018-08-21 15:50:07.075 [INF] LNWL: Done catching up block hashes
2018-08-21 15:50:07.075 [INF] LNWL: Finished rescan for 524 addresses (synced to block 00000000000000000029825d1789f267b4e7f1d77e018a25d0d2b32b1a03c3d7, height 537835)
2018-08-21 15:50:07.257 [INF] HSWC: Payment circuits loaded: num_pending=511, num_open=18
2018-08-21 15:50:07.351 [INF] HSWC: Trimming open circuits for chan_id=532664:117:0, start_htlc_id=0
2018-08-21 15:50:07.351 [INF] HSWC: Trimming open circuits for chan_id=532193:820:1, start_htlc_id=0
2018-08-21 15:50:07.351 [INF] HSWC: Trimming open circuits for chan_id=516006:1767:1, start_htlc_id=52
----- more trimming open circuits logs ---------
2018-08-21 15:50:07.479 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-08-21 15:50:07.480 [INF] RPCS: RPC server listening on 192.168.0.21:10009
2018-08-21 15:50:07.480 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-08-21 15:50:07.480 [INF] RPCS: gRPC proxy started at 192.168.0.21:8080
2018-08-21 15:50:07.488 [INF] LTND: Waiting for chain backend to finish sync, start_height=537835
2018-08-21 15:50:07.497 [INF] LTND: Chain backend is fully synced (end_height=537835)!
2018-08-21 15:50:07.500 [INF] LNWL: Started listening for blocks via ZMQ on tcp://127.0.0.1:29000
2018-08-21 15:50:07.549 [INF] HSWC: Starting HTLC Switch
2018-08-21 15:50:07.549 [INF] NTFN: New block epoch subscription
2018-08-21 15:50:07.549 [INF] NTFN: New block epoch subscription
2018-08-21 15:50:08.611 [INF] NTFN: New block epoch subscription
2018-08-21 15:50:09.006 [INF] CNCT: Creating ChannelArbitrators for 20 active channels
2018-08-21 15:50:09.007 [INF] NTFN: New block epoch subscription
2018-08-21 15:50:09.007 [INF] NTFN: New block epoch subscription
----- more New block epoch subscription logs -------------
2018-08-21 15:50:09.094 [INF] CNCT: Creating ChannelArbitrators for 1 closing channels
2018-08-21 15:50:09.094 [INF] NTFN: New block epoch subscription
2018-08-21 15:50:09.094 [INF] NTFN: New spend subscription: utxo=9036d25491b051ab71fb2cba3020b3fe1fa01517afce82d461db0a02f21500a1:0
2018-08-21 15:50:09.193 [INF] NTFN: New spend subscription: utxo=cb16c481a96d801a9fe23f6a5ba3dcd6c60a476bc54ac4d371d940a70de0cc1d:0
2018-08-21 15:50:09.193 [INF] CNCT: Close observer for ChannelPoint(9036d25491b051ab71fb2cba3020b3fe1fa01517afce82d461db0a02f21500a1:0) active
2018-08-21 15:50:09.263 [INF] NTFN: New spend subscription: utxo=64e90866ea054e892366f11fc5a56b2cfc15f62dd4734e64507d6d3a3595dd23:1
2018-08-21 15:50:09.263 [INF] CNCT: Close observer for ChannelPoint(cb16c481a96d801a9fe23f6a5ba3dcd6c60a476bc54ac4d371d940a70de0cc1d:0) active
------ more  CNCT: Close observer ----------------
2018-08-21 15:50:10.682 [INF] NTFN: New spend subscription: utxo=1f75b62f5930bb81960dd1c06bc2522d09c6ba8fbb6405b25777762e20f9ace0:0
2018-08-21 15:50:10.682 [INF] CNCT: Close observer for ChannelPoint(18871533aec34e712053d661f7266c1f13f35f0e4b3bc8eda66cfe62ee747011:0) active
2018-08-21 15:50:10.697 [INF] CNCT: ChannelArbitrator(b4f9a9335cd2e5fb5216c2ed5156614a001c8f5c76d3b4d095552e497691e4c8:1): starting state=StateBroadcastCommit
2018-08-21 15:50:10.698 [INF] CNCT: Close observer for ChannelPoint(1f75b62f5930bb81960dd1c06bc2522d09c6ba8fbb6405b25777762e20f9ace0:0) active
2018-08-21 15:50:10.701 [INF] CNCT: ChannelArbitrator(b4f9a9335cd2e5fb5216c2ed5156614a001c8f5c76d3b4d095552e497691e4c8:1): force closing chan

Stops there, on the same ChannelArbitrator line

[grunch]

I have more info about this, the log file doesn't show the complete crash, I ran it directly (I was running it by systemd script before) and I get this

2018-08-22 19:53:25.950 [INF] CNCT: ChannelArbitrator(b4f9a9335cd2e5fb5216c2ed5156614a001c8f5c76d3b4d095552e497691e4c8:1): force closing chan
2018-08-22 19:53:25.960 [INF] LTND: Shutdown complete
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x4e3d60]

goroutine 1 [running]:
github.com/lightningnetwork/lnd/contractcourt.(*ChannelArbitrator).stateStep(0x11967900, 0x8359e, 0x0, 0x114e06c0, 0x3, 0x3, 0x11a5e0c0)
    /home/admin/go/src/github.com/lightningnetwork/lnd/contractcourt/channel_arbitrator.go:445 +0xd0
github.com/lightningnetwork/lnd/contractcourt.(*ChannelArbitrator).advanceState(0x11967900, 0x8359e, 0x83500, 0x0, 0x0, 0x2, 0x4de630, 0x0)
    /home/admin/go/src/github.com/lightningnetwork/lnd/contractcourt/channel_arbitrator.go:653 +0x138
github.com/lightningnetwork/lnd/contractcourt.(*ChannelArbitrator).Start(0x11967900, 0x0, 0x0)
    /home/admin/go/src/github.com/lightningnetwork/lnd/contractcourt/channel_arbitrator.go:250 +0x274
github.com/lightningnetwork/lnd/contractcourt.(*ChainArbitrator).Start(0x1156a1e0, 0x0, 0x0)
    /home/admin/go/src/github.com/lightningnetwork/lnd/contractcourt/chain_arbitrator.go:429 +0x69c
main.(*server).Start(0x1143a2d0, 0x9a38e7, 0x2e)
    /home/admin/go/src/github.com/lightningnetwork/lnd/server.go:923 +0xf0
main.lndMain(0x0, 0x0)
    /home/admin/go/src/github.com/lightningnetwork/lnd/lnd.go:419 +0xf00
main.main()
    /home/admin/go/src/github.com/lightningnetwork/lnd/lnd.go:451 +0x14

[cfromknecht]

unfortunately this state is going to be hard to recover from, there are number of fixes that just landed in master that resolve this issue, see #1696. do you know if the transaction that closed the channel was yours or the remote party's?

[halseth]

From the trace it looks like the channel
1) Force close was initiated, channel arbitrator commits to StateBroadcastCommit
2) StateBroadcastCommit is executed, and the force closing transaction in broadcasted
3) The ChanArb fails committing to the next state (the commit itself fails, or sometime before that time, a hunch is an error returned from the backend when broadcasting).
4) The closing transaction confirms, and the channel is marked closed in the database (this was before the recent changes in #1696).
5) On restart we create a restricted channel arbitrator, since the channel is pending close.
6) Since StateBroadcastCommit was the last state committed to, it will try to replay this state.
7) It crashes when it tries to get the ForceCloseSummary, since this is not defined for restricted channel arbitrators.

[halseth]

Fix could be to always go to StateContractClosed on localForceClose and remoteForceClose trigger when in StateBroadcastCommit.

[grunch]

Thanks guys, but I'm not sure how to do all the StateContractClosed and stuff, could you be more specific how I can solve this issue?

Thanks

[grunch]

this is the current channel state, I can't have my lnd working, I have 3 days and still is not closed, what can I do?

{
    "total_limbo_balance": "0",
    "pending_open_channels": [
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
        {
            "channel": {
                "remote_node_pub": "0394396e6e8cf8d9f91de4269dfd2e8416b93b91cae6139057c7283b463e4bfa31",
                "channel_point": "b4f9a9335cd2e5fb5216c2ed5156614a001c8f5c76d3b4d095552e497691e4c8:1",
                "capacity": "140000",
                "local_balance": "4843",
                "remote_balance": "0"
            },
            "closing_txid": "0723413d80094528915b5cb91f74696039502560f563f82a6b2eee134e58e9fc",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        }
    ],
    "waiting_close_channels": [
    ]
}

[halseth]

@grunch Try running the patch in https://github.com/lightningnetwork/lnd/pull/1774, should get you up running again :)

[grunch]

Hi @halseth, thank you, I finally make it work through a patch @roasbeef sent me last night, we can now close this issue

[halseth]

Nice! We'll keep this open until the actual fix is merged. Thanks for the report! 😀

[dlogemann]

Had the same problem, fix from #1774 works for me as well - thanks!