lnd: LND is constantly hanging on "LTND: Waiting for chain backend to finish sync, start_height="

Background

Describe your issue here.

Your environment

• version of lnd - 0.5.0-beta commit=v0.5.1-beta-rc1
• which operating system (uname -a on *Nix) - CentOS 6.*
• version of btcd, bitcoind, or other backend - bitcoind v0.17.0.1
• any other relevant environment details

Steps to reproduce

After normal working of LND i decided stop & start. I made graceful shutdown and after i cannot run node again. I many times stopped bitcoind, lnd - everytime same last log in LND:

LTND: Waiting for chain backend to finish sync, start_height=

In this time the lnd process cunsumes 50-100% cpu.

Expected behaviour

Norman starting. I have same compiled lnds daemons with same OS & bitcoind with lnd version. There are everything OK. There are same configs. For example normal behaviour:

2018-11-17 09:37:17.399 [INF] LTND: Primary chain is set to: bitcoin
2018-11-17 09:37:17.411 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on tcp://127.0.0.1:28332
2018-11-17 09:37:17.411 [INF] LTND: Initializing bitcoind backed fee estimator
2018-11-17 09:37:17.411 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on tcp://127.0.0.1:28333
2018-11-17 09:37:19.002 [INF] LNWL: The wallet has been unlocked without a time limit
2018-11-17 09:37:19.005 [INF] LTND: LightningWallet opened
2018-11-17 09:37:19.052 [INF] HSWC: Restoring in-memory circuit state from disk
2018-11-17 09:37:19.082 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
...
2018-11-17 09:37:19.166 [INF] HSWC: Trimming open circuits for chan_id=550338:1779:0, start_htlc_id=0
2018-11-17 09:37:19.316 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-11-17 09:37:19.316 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-11-17 09:37:19.318 [INF] LTND: Waiting for chain backend to finish sync, start_height=550422
2018-11-17 09:37:19.340 [INF] LNWL: Started rescan from block 0000000000000000000ebf43216644b72c87769086cae234b20e12e0cbca15a4 (height 550422) for 662 addresses
2018-11-17 09:37:19.348 [INF] LNWL: Starting rescan from block 0000000000000000000ebf43216644b72c87769086cae234b20e12e0cbca15a4
2018-11-17 09:37:19.351 [INF] LNWL: Rescan finished at 550422 (0000000000000000000ebf43216644b72c87769086cae234b20e12e0cbca15a4)

Actual behaviour

The last log line same is: LTND: Waiting for chain backend to finish sync, start_height=NNNN where is NNNN - current last block of bitcoin network and bitcoind

2018-11-17 13:22:51.720 [INF] LTND: Version: 0.5.0-beta commit=v0.5.1-beta-rc1, build=production, logging=default
2018-11-17 13:22:51.720 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2018-11-17 13:22:51.720 [INF] CHDB: Checking for schema update: latest_version=6, db_version=6
2018-11-17 13:22:51.754 [INF] RPCS: password gRPC proxy started at 127.0.0.1:8080
2018-11-17 13:22:51.754 [INF] RPCS: password RPC server listening on 127.0.0.1:10009
2018-11-17 13:22:51.754 [INF] LTND: Waiting for wallet encryption password. Use `lncli create` to create a wallet, `lncli unlock` to unlock an existing wallet, or `lncli changepassword` to change the password of an existing wallet and unlock it.
2018-11-17 13:23:09.572 [INF] LNWL: Opened wallet
2018-11-17 13:23:09.699 [INF] LTND: Primary chain is set to: bitcoin
2018-11-17 13:23:09.711 [INF] LTND: Initializing bitcoind backed fee estimator
2018-11-17 13:23:09.711 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on tcp://127.0.0.1:28332
2018-11-17 13:23:09.711 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on tcp://127.0.0.1:28333
2018-11-17 13:23:11.353 [INF] LNWL: The wallet has been unlocked without a time limit
2018-11-17 13:23:11.356 [INF] LTND: LightningWallet opened
2018-11-17 13:23:11.395 [INF] HSWC: Restoring in-memory circuit state from disk
2018-11-17 13:23:11.407 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2018-11-17 13:23:11.487 [INF] HSWC: Trimming open circuits for chan_id=550343:866:0, start_htlc_id=0
2018-11-17 13:23:11.487 [INF] HSWC: Trimming open circuits for chan_id=550343:867:0, start_htlc_id=0
2018-11-17 13:23:11.487 [INF] HSWC: Trimming open circuits for chan_id=550338:1772:0, start_htlc_id=0
...
2018-11-17 13:23:11.490 [INF] HSWC: Trimming open circuits for chan_id=550341:613:0, start_htlc_id=0
2018-11-17 13:23:11.490 [INF] HSWC: Trimming open circuits for chan_id=550343:871:0, start_htlc_id=0
2018-11-17 13:23:11.490 [INF] HSWC: Trimming open circuits for chan_id=550346:263:0, start_htlc_id=0
2018-11-17 13:23:11.490 [INF] HSWC: Trimming open circuits for chan_id=550338:1652:0, start_htlc_id=0
2018-11-17 13:23:11.515 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-11-17 13:23:11.515 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-11-17 13:23:11.517 [INF] LTND: Waiting for chain backend to finish sync, start_height=550441

I wait hours… Nothing. I stop and start again lnd (graceful shuttdown) - same problem. I stop lnd + bitcoind and run its again - same problem. I stop lnd and wait 1-2 hours and start again - same problem.

In this time the top shows to me like this: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3489 bitcoin 20 0 3238m 68m 11m S 105.5 0.1 15:36.09 lnd

My LND config is:

[Application Options]
rpclisten=localhost:10009
restlisten=localhost:8080
debuglevel=info
debughtlc=false
autopilot.active=1
autopilot.maxchannels=1024
#autopilot.maxchansize=9000000
autopilot.allocation=1.0

# You need configure router for port forwarding
externalip=MY_IP:9735
listen=MY_IP:9735
alias=MY_ALIAS

datadir=/home/bitcoin/.lnd/data-mainnet/
adminmacaroonpath=/home/bitcoin/.lnd/admin-mainnet.macaroon
readonlymacaroonpath=/home/bitcoin/.lnd/readonly-mainnet.macaroon
invoicemacaroonpath=/home/bitcoin/.lnd/invoice-mainnet.macaroon

[Bitcoin]
bitcoin.mainnet=1
bitcoin.active=1
bitcoin.node=bitcoind
bitcoin.feerate=100
bitcoin.basefee=1000

[Bitcoind]
bitcoind.rpcuser=lnd
bitcoind.rpcpass=MY_PASS_HERE
bitcoind.zmqpubrawblock=tcp://127.0.0.1:28332
bitcoind.zmqpubrawtx=tcp://127.0.0.1:28333

The bitcoind config is:

txindex=1
server=1
daemon=1

pid=/home/bitcoin/.mainnet-bitcoind.pid

# Will beother upnp support - through 'upnpc' utility
upnp=0

# ZMQ for lnd...
zmqpubrawblock=tcp://127.0.0.1:28332
zmqpubrawtx=tcp://127.0.0.1:28333

# Auth key for lnd
rpcauth=lnd:MY_KEY_HERE

# You need configure router for port forwarding
externalip=MY_IP_HERE

mainnet-lncli getinfo shows to me now:

{
"identity_pubkey": "MY_NODE_ID",
"alias": "MY_ALIAS",
"num_pending_channels": 0,
"num_active_channels": 0,
"num_peers": 0,
"block_height": 550444,
"block_hash": "0000000000000000000c56c6fc713489787ab6c53e572484d71516c3865f16b8",
"synced_to_chain": false,
"testnet": false,
"chains": [
    "bitcoin"
],
"uris": [
    "MY_NODE_ID@MY_IP:9735"
],
"best_header_timestamp": "0",
"version": "0.5.0-beta commit=v0.5.1-beta-rc1",
"num_inactive_channels": 59
}

P.S. I do regular incremental backups each minute by rsync to other machine so i have all binary files before last normal working. So I have a option to copy all the files, but I want to understand the problem.