LND stuck in `the RPC server is in the process of starting up, but not yet ready to accept calls`

[fiatjaf]

Background

My RPC server never starts and it doesn't tell me why.

Your environment

• version of lnd: v0.14.2-beta, linux.amd64, downloaded from the GitHub Releases page
• which operating system (uname -a on *Nix): Linux 5.15.10-arch1-1 Fix name typo in README #1 SMP PREEMPT Fri, 17 Dec 2021 11:17:37 +0000 x86_64 GNU/Linux
• version of btcd, bitcoind, or other backend: Bitcoin Core v0.21.1

Steps to reproduce

Tell us how to reproduce this issue. Please provide stacktraces and links to code in question.

Expected behaviour

I should be able to execute calls.

Actual behaviour

I erased my previous regtest folder so I could start a new regtest chain and started bitcoind with the following command:

~> bitcoind -regtest -datadir=/home/fiatjaf/.bitcoin/ -zmqpubrawblock=tcp://127.0.0.1:18332 -zmqpubrawtx=tcp://127.0.0.1:18333 -rpcbind=127.0.0.1 -rpcuser=fiatjaf -rpcpassword=fiatjaf

Then I created a wallet on bitcoind with bitcoin-cli --regtest ... createwallet dev, created an address with getnewaddress and then generatetoaddress 1 <address> (just so the chain would have a block, I don't know if this is important).

And these are the full start command and logs from LND:

~> ./lnd --bitcoind.rpcpass=fiatjaf --bitcoind.rpcuser=fiatjaf --bitcoind.zmqpubrawblock=tcp://127.0.0.1:18332 --bitcoind.zmqpubrawtx=tcp://127.0.0.1:18333 --bitcoin.active --bitcoin.node=bitcoind --bitcoin.regtest --alias=dev --accept-keysend --rpclisten=0.0.0.0:10009
2022-03-10 13:31:54.061 [WRN] LTND: open /home/fiatjaf/.lnd/lnd.conf: no such file or directory
2022-03-10 13:31:54.061 [INF] LTND: Version: 0.14.2-beta commit=v0.14.2-beta, build=production, logging=default, debuglevel=info
2022-03-10 13:31:54.062 [INF] LTND: Active chain: Bitcoin (network=regtest)
2022-03-10 13:31:54.062 [INF] RPCS: RPC server listening on 0.0.0.0:10009
2022-03-10 13:31:54.063 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2022-03-10 13:31:54.063 [INF] LTND: Opening the main database, this might take a few minutes...
2022-03-10 13:31:54.063 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2022-03-10 13:31:54.063 [INF] LTND: Creating local graph and channel state DB instances
2022-03-10 13:31:54.070 [INF] CHDB: Checking for schema update: latest_version=24, db_version=24                                                                                  
2022-03-10 13:31:54.070 [INF] LTND: Database(s) now open (time_to_open=7.252101ms)!
2022-03-10 13:31:54.070 [INF] LTND: We're not running within systemd
2022-03-10 13:31:54.070 [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.

[at this point I run `./lncli unlock`]

2022-03-10 13:32:21.936 [INF] LNWL: Opened wallet
2022-03-10 13:32:22.012 [INF] CHRE: Primary chain is set to: bitcoin

[at this point I try to run `./lncli -n regtest getinfo`]

2022-03-10 13:33:26.620 [ERR] RPCS: [/lnrpc.Lightning/GetInfo]: the RPC server is in the process of starting up, but not yet ready to accept calls

What am I missing? I tried to search for LND guides on the internet and read a bunch of them, trying to see if I had missed some important setting, but didn't find the reason for this behavior.

[guggero]

I think you need to mine a block. If the last block is more than 2 hours old, bitcoind will declare itself as "not synced to chain" and so will lnd. And lnd will block starting fully until it thinks it is synced to the chain.

[fiatjaf]

I have mined a block already, just the minute I had started LND. But now I mined another one and nothing changed.

[guggero]

Hmm, weird. Can you use --debuglevel=trace to see where exactly it stops in the startup process?

[fiatjaf]

Another piece of info: Doing Ctrl+C causes LND to be stuck forever on Gracefully shutting down.

[fiatjaf]

Running with --debuglevel=trace gives no new information apparently:

~> ./lnd --bitcoind.rpcpass=fiatjaf --bitcoind.rpcuser=fiatjaf --bitcoind.zmqpubrawblock=tcp://127.0.0.1:18332 --bitcoind.zmqpubrawtx=tcp://127.0.0.1:18333 --bitcoin.active --bitcoin.node=bitcoind --bitcoin.regtest --alias=dev --accept-keysend --rpclisten=0.0.0.0:10009 --debuglevel=trace                
2022-03-10 14:23:16.980 [WRN] LTND: open /home/fiatjaf/.lnd/lnd.conf: no such file or directory     
2022-03-10 14:23:16.980 [INF] LTND: Version: 0.14.2-beta commit=v0.14.2-beta, build=production, logging=default, debuglevel=trace                                                   
2022-03-10 14:23:16.980 [INF] LTND: Active chain: Bitcoin (network=regtest)                                                                                                         
2022-03-10 14:23:16.981 [DBG] NTFR: ChainNotifier RPC server successfully register with root gRPC server                                                                            
2022-03-10 14:23:16.981 [DBG] VRPC: Versioner RPC server successfully registered with root gRPC server                                                                              
2022-03-10 14:23:16.981 [DBG] WLKT: WalletKit RPC server successfully registered with root gRPC server                                                                              
2022-03-10 14:23:16.981 [DBG] RRPC: Router RPC server successfully register with root gRPC server                                                                                   
2022-03-10 14:23:16.981 [DBG] ARPC: Autopilot RPC server successfully register with root gRPC server                                                                                
2022-03-10 14:23:16.981 [DBG] SGNR: Signer RPC server successfully register with root gRPC server                                                                                   
2022-03-10 14:23:16.981 [DBG] IRPC: Invoices RPC server successfully registered with root gRPC server                                                                               
2022-03-10 14:23:16.981 [INF] RPCS: RPC server listening on 0.0.0.0:10009                                                                                                           
2022-03-10 14:23:16.981 [DBG] NTFR: ChainNotifier REST server successfully registered with root REST server                                                                         
2022-03-10 14:23:16.981 [DBG] VRPC: Versioner REST server successfully registered with root REST server                                                                             
2022-03-10 14:23:16.982 [DBG] WLKT: WalletKit REST server successfully registered with root REST server                                                                             
2022-03-10 14:23:16.982 [DBG] RRPC: Router REST server successfully registered with root REST server                                                                                
2022-03-10 14:23:16.982 [DBG] ARPC: Autopilot REST server successfully registered with root REST server                                                                             
2022-03-10 14:23:16.982 [DBG] SGNR: Signer REST server successfully registered with root REST server                                                                                
2022-03-10 14:23:16.983 [DBG] IRPC: Invoices REST server successfully registered with root REST server                                                                              
2022-03-10 14:23:16.983 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080                                                                                                            
2022-03-10 14:23:16.983 [INF] LTND: Opening the main database, this might take a few minutes...                                                                                     
2022-03-10 14:23:16.983 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false                                                                                 
2022-03-10 14:23:16.983 [INF] LTND: Creating local graph and channel state DB instances                                                                                             
2022-03-10 14:23:16.988 [DBG] CHDB: Populating in-memory channel graph, this might take a while...                                                                                  
2022-03-10 14:23:16.988 [DBG] CHDB: Finished populating in-memory channel graph (took 54.713µs, num_node_features=0, num_nodes=0, num_channels=0)                                   
2022-03-10 14:23:16.988 [INF] CHDB: Checking for schema update: latest_version=24, db_version=24                                                                                    
2022-03-10 14:23:16.988 [INF] LTND: Database(s) now open (time_to_open=5.364517ms)!                                                                                                 
2022-03-10 14:23:16.988 [INF] LTND: We're not running within systemd                                                                                                                
2022-03-10 14:23:16.988 [INF] LTND: Waiting for wallet encryption password. Use `lncli cr                                                                                           
word` to change the password of an existing wallet and unlock it.                                                                                                                   
2022-03-10 14:23:23.568 [INF] LNWL: Opened wallet                                                                                                                                   
2022-03-10 14:23:23.628 [INF] CHRE: Primary chain is set to: bitcoin

[guggero]

The next line on my machine is Started listening for bitcoind block notifications via ZMQ on 127.0.0.1:28332.
So I assume something is up with ZMQ? Can you try using the same port (28332, not 1833x) for both queues? I think the 18332/18333 might have some overlap with the normal RPC port.

[fiatjaf]

That fixed it! Thank you very much.

This is an issue on Bitcoin Core, I would say. It shouldn't accept conflicting ports like that,

[n-e-t-d-i-v-e-r]

@guggero @fiatjaf got the same issue here. in which file do I have to change to which port? may you put me here the step by step fix you did @fiatjaf ?

Attempting automatic RPC configuration to bitcoind
Automatically obtained bitcoind's RPC credentials
2023-08-15 16:20:27.774 [INF] LTND: Version: 0.16.4-beta commit=v0.16.4-beta, build=production, logging=default, debuglevel=info
2023-08-15 16:20:27.775 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2023-08-15 16:20:27.783 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2023-08-15 16:20:27.795 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2023-08-15 16:20:27.795 [INF] LTND: Opening the main database, this might take a few minutes...
2023-08-15 16:20:27.795 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=true
2023-08-15 16:20:27.807 [INF] CHDB: Not compacting database file at /home/lnd/.lnd/data/graph/mainnet/channel.db, it was last compacted at 2023-08-15 15:42:32.492913312 +0200 CEST (37m55s ago), min age is set to 168h0m0s
2023-08-15 16:20:28.431 [INF] CHDB: Not compacting database file at /home/lnd/.lnd/data/chain/bitcoin/mainnet/macaroons.db, it was last compacted at 2023-08-15 15:42:32.525203231 +0200 CEST (37m55s ago), min age is set to 168h0m0s
2023-08-15 16:20:28.433 [INF] CHDB: Not compacting database file at /home/lnd/.lnd/data/graph/mainnet/sphinxreplay.db, it was last compacted at 2023-08-15 15:42:32.538639867 +0200 CEST (37m55s ago), min age is set to 168h0m0s
2023-08-15 16:20:28.435 [INF] CHDB: Not compacting database file at /home/lnd/.lnd/data/graph/mainnet/wtclient.db, it was last compacted at 2023-08-15 15:42:32.554996322 +0200 CEST (37m55s ago), min age is set to 168h0m0s
2023-08-15 16:20:28.435 [INF] LTND: Creating local graph and channel state DB instances
2023-08-15 16:20:28.913 [INF] CHDB: Checking for schema update: latest_version=29, db_version=29
2023-08-15 16:20:28.914 [INF] CHDB: Checking for optional update: prune_revocation_log=false, db_version=empty
2023-08-15 16:20:28.916 [INF] LTND: Database(s) now open (time_to_open=1.120164101s)!
2023-08-15 16:20:28.916 [INF] LTND: Attempting automatic wallet unlock with password provided in file
2023-08-15 16:20:31.262 [INF] LNWL: Opened wallet
2023-08-15 16:20:31.494 [INF] CHRE: Primary chain is set to: bitcoin
2023-08-15 16:20:32.340 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.360 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.376 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.392 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.406 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.422 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.438 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.451 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.467 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.482 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-08-15 16:20:32.497 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: the RPC server is in the process of starting up, but not yet ready to accept calls

2023-08-15 16:22:34.391 [ERR] LTND: Shutting down because error in main method: error creating wallet config: unable to set up wallet password listeners: shutting down
2023-08-15 16:22:34.392 [ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: wallet locked, unlock it to enable full RPC access
2023-08-15 16:22:34.403 [INF] LTND: Shutdown complete

[guggero]

Has the node not been running for a while?
Sometimes it just takes some time to start up, sync to the chain, update the graph and so on. I'd wait a bit more than just 2 minutes.
The [ERR] you see are just from another software trying to hit lnd while it's starting up.

[fiatjaf]

If I remember correctly my issue was that the ZMQ port was being specified wrongly.

[n-e-t-d-i-v-e-r]

Bitcoin-Node where up and running since seven days and lnd-node also since hours. Rsult is always the same.

Attempting automatic RPC configuration to bitcoind Automatically obtained bitcoind's RPC credentials 2023-08-15 16:20:27.774 [INF] LTND: Version: 0.16.4-beta commit=v0.16.4-beta, build=production, logging=default, debuglevel=info 2023-08-15 16:20:27.775 [INF] LTND: Active chain: Bitcoin (network=mainnet) 2023-08-15 16:20:27.783 [INF] RPCS: RPC server listening on 127.0.0.1:10009 2023-08-15 16:20:27.795 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080 2023-08-15 16:20:27.795 [INF] LTND: Opening the main database, this might take a few minutes... 2023-08-15 16:20:27.795 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=true

[ERR] RPCS: [/lnrpc.Lightning/SubscribeInvoices]: wallet locked, unlock it to enable full RPC access

[n-e-t-d-i-v-e-r]

but with systemctl status lnd i’ll get:

could this be the reason, why I can’t get remote-connection over zeus-, zap-wallet or LNbits to?

[guggero]

Why do the logs diverge? Are you running/starting lnd twice?

[guggero]

Can you just post a bit more of the log, maybe upload to pastebin or something like that? The very first one you posted the node was shut down, so that didn't say much.