[bug]: lnd server stuck in process of starting even when running on regtest with only a few blocks that needs synchronization

DhananjayPurohit commented 1 month ago

Background

Getting RPC error:- [lncli] rpc error: code = Unknown desc = server is still in the process of starting

when attempting to connect to the neighboring node.

Your environment

version of lnd: using the image lightninglabs/lndinit:v0.1.3-beta-lnd-v0.14.2-beta
which operating system (uname -a on *Nix): Linux logging 5.15.0-102-generic #112-Ubuntu SMP Tue Mar 5 16:50:32 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
version of btcd, bitcoind, or other backend:- lncm/bitcoind:v22.0
any other relevant environment details

Steps to reproduce

Nodes are started using the following script::- https://gist.github.com/DhananjayPurohit/4a558a4923cff2820a722ce763cbe7d9

Commands executed after starting the nodes::- https://gist.github.com/DhananjayPurohit/6decffb90d85e80089c30475be370721

Expected behaviour

The node should successfully connect to the neighboring node.

Actual behaviour

LND logs:-

2024-07-30 14:22:34.351 LNDINIT: Version 0.1.3-beta commit=, debuglevel=debug
2024-07-30 14:22:37.826 [INF] LTND: Version: 0.14.2-beta commit=v0.14.2-beta, build=production, logging=default, debuglevel=info
2024-07-30 14:22:34.354 LNDINIT: Reading seed from file
2024-07-30 14:22:37.826 [INF] LTND: Active chain: Bitcoin (network=regtest)
2024-07-30 14:22:37.826 [INF] RPCS: Generating TLS certificates...
2024-07-30 14:22:37.827 [INF] RPCS: Done generating TLS certificates
2024-07-30 14:22:37.830 [INF] RPCS: RPC server listening on 0.0.0.0:10009
2024-07-30 14:22:37.834 [INF] RPCS: gRPC proxy started at 0.0.0.0:8080
2024-07-30 14:22:37.836 [INF] LTND: Opening the main database, this might take a few minutes...
2024-07-30 14:22:37.836 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2024-07-30 14:22:37.846 [INF] LTND: Creating local graph and channel state DB instances
2024-07-30 14:22:37.855 [INF] CHDB: Checking for schema update: latest_version=24, db_version=24
2024-07-30 14:22:37.856 [INF] LTND: Database(s) now open (time_to_open=[19](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:20).225015ms)!
2024-07-30 14:22:37.856 [INF] LTND: Attempting automatic wallet unlock with password provided in file
2024-07-30 14:22:38.968 [INF] LNWL: Opened wallet
[20](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:21)24-07-30 14:22:39.078 [INF] CHRE: Primary chain is set to: bitcoin
2024-07-30 14:22:39.098 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on 172.19.0.3:28332
2024-07-30 14:22:39.100 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on 172.19.0.3:28333
2024-07-30 14:22:40.268 [INF] LNWL: The wallet has been unlocked without a time limit
2024-07-30 14:22:40.329 [INF] CHRE: LightningWallet opened
2024-07-30 14:22:40.333 [INF] HSWC: Cleaning circuits from disk for closed channels
2024-07-30 14:22:40.333 [INF] HSWC: Finished cleaning: no closed channels found, no actions taken.
2024-07-30 14:22:40.333 [INF] HSWC: Restoring in-memory circuit state from disk
2024-07-30 14:22:40.333 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2024-07-30 14:22:40.336 [INF] SWPR: Migrating UTXO nursery finalized TXIDs
2024-07-30 14:22:40.337 [INF] LTND: Channel backup proxy channel notifier starting
2024-07-30 14:22:40.337 [INF] ATPL: Instantiating autopilot with active=false, max_channels=5, allocation=0.600000, min_chan_size=20000, max_chan_size=16777[21](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:22)5, private=false, min_confs=1, conf_target=3
2024-07-30 14:22:40.337 [INF] IRPC: Baking macaroons for invoices RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/invoices.macaroon
2024-07-30 14:[22](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:23):40.338 [INF] SGNR: Making macaroons for Signer RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/signer.macaroon
2024-07-30 14:22:40.338 [INF] WLKT: Baking macaroons for WalletKit RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/walletkit.macaroon
2024-07-30 14:22:40.339 [INF] NTFR: Baking macaroons for ChainNotifier RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/chainnotifier.macaroon
2024-07-30 14:22:40.340 [INF] RRPC: Making macaroons for Router RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/router.macaroon
2024-07-30 14:22:40.340 [INF] LTND: We're not running within systemd
2024-07-30 14:22:40.341 [INF] LNWL: Started rescan from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (height 0) for 0 addresses
2024-07-30 14:22:40.342 [INF] LTND: Waiting for chain backend to finish sync, start_height=0
2024-07-30 14:22:40.350 [INF] LNWL: Catching up block hashes to height 0, this might take a while
2024-07-30 14:22:40.350 [INF] LNWL: Done catching up block hashes
2024-07-30 14:22:40.350 [INF] LNWL: Finished rescan for 0 addresses (synced to block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, height 0)
2024-07-30 14:22:34.354 LNDINIT: Reading wallet password from file
2024-07-30 14:22:34.568 LNDINIT: Creating new wallet in /root/.lnd/data/chain/bitcoin/regtest
2024-07-30 14:22:37.718 LNDINIT: Wallet created successfully in /root/.lnd/data/chain/bitcoin/regtest
2024-07-30 14:22:34.407 LNDINIT: Version 0.1.3-beta commit=, debuglevel=debug
2024-07-30 14:22:34.407 LNDINIT: Reading seed from file
2024-07-30 14:22:37.911 [INF] LTND: Version: 0.14.2-beta commit=v0.14.2-beta, build=production, logging=default, debuglevel=info
2024-07-30 14:22:34.407 LNDINIT: Reading wallet password from file
2024-07-30 14:22:34.580 LNDINIT: Creating new wallet in /root/.lnd/data/chain/bitcoin/regtest
2024-07-30 14:22:37.789 LNDINIT: Wallet created successfully in /root/.lnd/data/chain/bitcoin/regtest
2024-07-30 14:22:37.911 [INF] LTND: Active chain: Bitcoin (network=regtest)
2024-07-30 14:22:37.911 [INF] RPCS: Generating TLS certificates...
2024-07-30 14:22:37.912 [INF] RPCS: Done generating TLS certificates
2024-07-30 14:22:37.912 [INF] RPCS: RPC server listening on 0.0.0.0:10009
2024-07-30 14:22:37.924 [INF] RPCS: gRPC proxy started at 0.0.0.0:8080
2024-07-30 14:22:37.924 [INF] LTND: Opening the main database, this might take a few minutes...
2024-07-30 14:22:37.924 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2024-07-30 14:22:37.944 [INF] LTND: Creating local graph and channel state DB instances
2024-07-30 14:22:37.950 [INF] CHDB: Checking for schema update: latest_version=24, db_version=24
2024-07-30 14:22:37.956 [INF] LTND: Database(s) now open (time_to_open=32.057591ms)!
2024-07-30 14:22:37.957 [INF] LTND: Attempting automatic wallet unlock with password provided in file
2024-07-30 14:22:39.058 [INF] LNWL: Opened wallet
2024-07-30 14:22:39.161 [INF] CHRE: Primary chain is set to: bitcoin
2024-07-30 14:22:39.180 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on 172.19.0.3:28332
2024-07-30 14:22:39.182 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on 172.19.0.3:28333
2024-07-30 14:22:40.369 [INF] LNWL: The wallet has been unlocked without a time limit
2024-07-30 14:22:40.419 [INF] CHRE: LightningWallet opened
2024-07-30 14:22:40.4[23](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:24) [INF] HSWC: Cleaning circuits from disk for closed channels
2024-07-30 14:22:40.423 [INF] HSWC: Finished cleaning: no closed channels found, no actions taken.
20[24](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:25)-07-30 14:22:40.424 [INF] HSWC: Restoring in-memory circuit state from disk
2024-07-30 14:22:40.424 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2024-07-30 14:22:40.4[26](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:27) [INF] SWPR: Migrating UTXO nursery finalized TXIDs
2024-07-30 14:22:40.427 [INF] LTND: Channel backup proxy channel notifier starting
2024-07-30 14:22:40.4[27](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:28) [INF] ATPL: Instantiating autopilot with active=false, max_channels=5, allocation=0.600000, min_chan_size=20000, max_chan_size=16777215, private=false, min_confs=1, conf_target=3
2024-07-30 14:22:40.427 [INF] SGNR: Making macaroons for Signer RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/signer.macaroon
2024-07-30 14:22:40.427 [INF] WLKT: Baking macaroons for WalletKit RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/walletkit.macaroon
2024-07-30 14:22:40.427 [INF] RRPC: Making macaroons for Router RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/router.macaroon
2024-07-30 14:22:40.4[28](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:29) [INF] NTFR: Baking macaroons for ChainNotifier RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/chainnotifier.macaroon
2024-07-30 14:22:40.428 [INF] IRPC: Baking macaroons for invoices RPC Server at: /root/.lnd/data/chain/bitcoin/regtest/invoices.macaroon
2024-07-30 14:22:40.4[29](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:30) [INF] LTND: We're not running within systemd
2024-07-30 14:22:40.431 [INF] LTND: Waiting for chain backend to finish sync, start_height=0
2024-07-[30](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:31) 14:22:40.435 [INF] LNWL: Started rescan from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (height 0) for 0 addresses
2024-07-30 14:22:40.438 [INF] LNWL: Catching up block hashes to height 0, this might take a while
2024-07-30 14:22:40.439 [INF] LNWL: Done catching up block hashes
2024-07-30 14:22:40.439 [INF] LNWL: Finished rescan for 0 addresses (synced to block 0f9188f13cb7b2c71f2a335e3a4fc[32](https://github.com/commerceblock/mercurylayer/actions/runs/10164054071/job/28108495940#step:8:33)8bf5beb436012afca590b1a11466e2206, height 0)
Pubkey: 0324665807bf4f9a18195bebbe614f75b3965a46f27395d3fc7324cd1859c60145
[lncli] rpc error: code = Unknown desc = server is still in the process of starting

guggero commented 1 month ago

Is your latest regtest block older than 2 hours? Then bitcoind (and because of that lnd as well) will think it's not up to date. Just mine a block and things should fully start up.

DhananjayPurohit commented 1 month ago

Have tried mining a few blocks to make it active but still getting the same RPC error when attempting to connect to the neighboring node.

yyforyongyu commented 1 month ago

2024-07-30 14:22:37.826 [INF] LTND: Version: 0.14.2-beta commit=v0.14.2-beta, build=production, logging=default, debuglevel=info

The version is quite old tho.

DhananjayPurohit commented 1 month ago

Yes, I'm using lndinit (lightninglabs/lndinit:v0.1.3-beta-lnd-v0.14.2-beta) to programmatically create a wallet for LND. There aren't any better versions available. https://hub.docker.com/r/lightninglabs/lndinit/tags?page=&page_size=&ordering=-last_updated&name=

guggero commented 1 month ago

You ordered by "oldest first"... It's a bit hard to search with the daily build. But if you go to the release page of lndinit and then look at the latest version there, you'll see it's v0.1.21-beta. If you filter by that, you'll see there's a new one available: https://hub.docker.com/r/lightninglabs/lndinit/tags?page=&page_size=&ordering=&name=v0.1.21-beta

DhananjayPurohit commented 1 month ago

Thanks, upgrading the lndinit version to lightninglabs/lndinit:v0.1.21-beta-lnd-v0.18.0-beta and changing the bitcoind config from

-zmqpubhashblock=tcp://0.0.0.0:28332 
-zmqpubhashtx=tcp://0.0.0.0:28333

to

-zmqpubrawblock=tcp://0.0.0.0:28332 
-zmqpubrawtx=tcp://0.0.0.0:28333

resolved the issue.

lightningnetwork / lnd