[bug]: No idea why lnd is stuck - could it be compacting for 18+ hours?

[bensig]

Background

lnd stuck for 18+ hours

Your environment

• version of lnd: lncli version 0.17.3-beta commit=v0.17.3-beta
• which operating system (uname -a on *Nix): Linux 4.19.0-26-amd64 #1 SMP Debian 4.19.304-1 (2024-01-09) x86_64 GNU/Linux
• version of btcd, bitcoind, or other backend Bitcoin Core RPC client version v26.0.0
• any other relevant environment details

Steps to reproduce

Just updated from 16 to 17.3 and restarted...
Bitcoin fully sync'd and I can create addresses and bitcoin txs just fine.

bitcoin-cli getblockcount
833658

Expected behaviour

Should have some idea of why it is not loading... all it says is that RPC services are not avail:

lncli getinfo 
[lncli] rpc error: code = Unknown desc = waiting to start, RPC services not available

Actual behaviour

log shows:

2024-03-07 00:00:08.534 [INF] CHDB: Compacting database file at /home/bitcoin/.lnd/data/graph/mainnet/channel.db
...
2024-03-07 18:51:05.068 [ERR] RPCS: [/lnrpc.Lightning/LookupInvoice]: waiting to start, RPC services not available
2024-03-07 18:51:06.768 [ERR] RPCS: [/lnrpc.Lightning/GetInfo]: waiting to start, RPC services not available

[hieblmi]

Thanks for flagging this issue. Indeed this takes a long time. Do you know how big the db was when you started the compaction? Have you ever compacted the db before?

[bensig]

db I believe is compacted automatically whenever the process is restarted.

Last restart appears to have happened on Jan 31:

2024-01-31T00:43:15Z

Unsure when that last occurred before this.

Here is my lnd/data/graph/mainnet dir (user redacted):

-rw-r--r-- 1 user user 1023M Mar  5 10:09 /home/user/.lnd/data/graph/mainnet/channel.db
-rw------- 1 user user     8 Jan 30 18:51 /home/user/.lnd/data/graph/mainnet/channel.db.last-compacted
-rw-r--r-- 1 user user  132M Mar  5 10:08 /home/user/.lnd/data/graph/mainnet/sphinxreplay.db
-rw------- 1 user user     8 Jan 30 18:51 /home/user/.lnd/data/graph/mainnet/sphinxreplay.db.last-compacted
-rw-r--r-- 1 user user   65M Mar  8 04:11 /home/user/.lnd/data/graph/mainnet/temp-dont-use.db
-rw-r--r-- 1 user user   33M Mar  5 10:08 /home/user/.lnd/data/graph/mainnet/wtclient.db
-rw------- 1 user user     8 Jan 30 18:51 /home/user/.lnd/data/graph/mainnet/wtclient.db.last-compacted

[bensig]

I have now tried to restart without compacting bbolt database to see if that helps - but it's seems to be stuck at "opening" for over an hour already. I'm really not sure about the diff between bbolt db and channel db and what could be causing this...

Changed lnd.conf to:

db.bolt.auto-compact=false

logs:

2024-03-08 03:48:17.282 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-08 03:48:17.282 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2024-03-08 04:48:26.182 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-08 04:48:26.182 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false

[hieblmi]

Did you recently experience any downtime or outages of your node?
You should do the following:

1. Stop lnd
2. Copy the channel.db file into a separate folder
3. In that separate folder, run chantools compactdb and check the result (see https://github.com/lightninglabs/chantools and https://github.com/lightninglabs/chantools/blob/master/doc/chantools_compactdb.md)

[C-Otto]

It might help (a lot) to run cat channel.db > /dev/null while lnd is starting/compacting. It seems your system only managed to write 65 MByte after 18 hours of compacting, you might want to check your disk (or storage backend) health.

[C-Otto]

The message "Opening the main database" should only appear once during startup. In your logs it is shown twice, with almost exactly one hour in between. Do you maybe re-start lnd automatically (if it doesn't start up completely within a timeout)?

[bensig]

It might help (a lot) to run cat channel.db > /dev/null while lnd is starting/compacting. It seems your system only managed to write 65 MByte after 18 hours of compacting, you might want to check your disk (or storage backend) health.

Disk health is good. This is running on a server cluster that is quite healthy.

running cat /home/user/.lnd/data/graph/mainnet/channel.db >> /dev/null does not seem to help.

Log keeps repeating - I assume this is lnd crashing and the service auto-restarting:

2024-03-08 06:57:12.929 [INF] LTND: Version: 0.17.3-beta commit=v0.17.3-beta, build=production, logging=default, debuglevel=info
2024-03-08 06:57:12.929 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2024-03-08 06:57:12.930 [INF] RPCS: RPC server listening on [::]:10009
2024-03-08 06:57:12.930 [INF] RPCS: RPC server listening on 0.0.0.0:10009
2024-03-08 06:57:12.935 [INF] RPCS: gRPC proxy started at [::]:10080
2024-03-08 06:57:12.935 [INF] RPCS: gRPC proxy started at 0.0.0.0:10080
2024-03-08 06:57:12.935 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-08 06:57:12.935 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
2024-03-08 06:57:24.181 [INF] LTND: Version: 0.17.3-beta commit=v0.17.3-beta, build=production, logging=default, debuglevel=info
2024-03-08 06:57:24.181 [INF] LTND: Active chain: Bitcoin (network=mainnet)
2024-03-08 06:57:24.182 [INF] RPCS: RPC server listening on [::]:10009
2024-03-08 06:57:24.182 [INF] RPCS: RPC server listening on 0.0.0.0:10009
2024-03-08 06:57:24.185 [INF] RPCS: gRPC proxy started at [::]:10080
2024-03-08 06:57:24.186 [INF] RPCS: gRPC proxy started at 0.0.0.0:10080
2024-03-08 06:57:24.186 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-08 06:57:24.186 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false

[C-Otto]

How do you start lnd? Maybe systemd is doing weird things?

[guggero]

Can you check the actual standard out of the daemon (and not just the log)? Do you see a panic/stack trace?

[bensig]

How do you start lnd? Maybe systemd is doing weird things?

Yeah I am using systemd services and docker...

[bensig]

Can you check the actual standard out of the daemon (and not just the log)? Do you see a panic/stack trace?

How do I do that exactly?

[bensig]

Can you check the actual standard out of the daemon (and not just the log)? Do you see a panic/stack trace?

How do I do that exactly?

When I run lnd I get:

2024-03-13 11:47:14.649 [INF] LTND: Opening the main database, this might take a few minutes...
2024-03-13 11:47:14.649 [INF] LTND: Opening bbolt database, sync_freelist=false, auto_compact=false
panic: freepages: failed to get all reachable pages (page 256270: multiple references (stack: [256270 255578 256270]))

goroutine 273 [running]:
go.etcd.io/bbolt.(*DB).freepages.func2()
go.etcd.io/bbolt@v1.3.7/db.go:1178 +0x8d
created by go.etcd.io/bbolt.(*DB).freepages in goroutine 1
go.etcd.io/bbolt@v1.3.7/db.go:1176 +0x1e5

[guggero]

Ugh, that looks like data corruption in the freepages. Did you attempt the steps in this comment? #8532 (comment)