lnd crash, panic: page 1072 already freed

[plasm0r]

Background

lnd is crashing during startup:

Attempting automatic RPC configuration to bitcoind
Automatically obtained bitcoind's RPC credentials
2018-04-17 22:19:08.109 [INF] LTND: Version 0.4.1-beta commit=
2018-04-17 22:19:08.110 [INF] LTND: Active chain: Bitcoin (network=testnet)
2018-04-17 22:19:08.112 [INF] CHDB: Checking for schema update: latest_version=0, db_version=0
2018-04-17 22:19:08.119 [INF] RPCS: password RPC server listening on 127.0.0.1:10009
2018-04-17 22:19:08.120 [INF] RPCS: password gRPC proxy started at 127.0.0.1:8080
2018-04-17 22:19:08.121 [INF] LTND: Waiting for wallet encryption password. Use lncli create to create wallet, or lncli unlock to unlock already created wallet.
2018-04-17 22:19:20.759 [INF] LNWL: Opened wallet
2018-04-17 22:19:21.159 [INF] LTND: Primary chain is set to: bitcoin
2018-04-17 22:19:21.159 [INF] LTND: Initializing bitcoind backed fee estimator
2018-04-17 22:19:27.366 [INF] LNWL: Opened wallet
2018-04-17 22:19:27.371 [INF] LNWL: Started listening for blocks via ZMQ on tcp://127.0.0.1:29000
2018-04-17 22:19:33.627 [INF] LNWL: The wallet has been unlocked without a time limit
2018-04-17 22:19:33.628 [INF] LTND: LightningWallet opened
2018-04-17 22:19:33.657 [INF] HSWC: Restoring in-memory circuit state from disk
2018-04-17 22:19:33.658 [INF] HSWC: Payment circuits loaded: num_pending=6, num_open=6
2018-04-17 22:19:33.693 [INF] HSWC: Trimming open circuits for chan_id=1293038:78:0, start_htlc_id=0
2018-04-17 22:19:33.693 [INF] HSWC: Trimming open circuits for chan_id=1293043:62:1, start_htlc_id=0
2018-04-17 22:19:33.693 [INF] HSWC: Trimming open circuits for chan_id=1293054:445:0, start_htlc_id=0
panic: page 1072 already freed

goroutine 1 [running]:
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*freelist).free(0x122500a0, 0x85fb, 0x0, 0x7518b000)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/freelist.go:143 +0x4ac
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0x11e99040, 0x1224b710, 0xacfe28)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:363 +0x1e0
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0x11e99000, 0x0, 0x0)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:350 +0x90
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0x11e98fc0, 0x120e32e4, 0x5)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:350 +0x90
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Bucket).spill(0x1200aac0, 0x1200aa00, 0x120e3538)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/bucket.go:568 +0x37c
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Bucket).spill(0x11ebc50c, 0xbeadc529, 0x5b68e6d)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/bucket.go:535 +0x2d4
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Tx).Commit(0x11ebc500, 0x0, 0x0)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/tx.go:160 +0xb8
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*DB).Update(0x11f78000, 0x120e3630, 0x0, 0x0)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/db.go:675 +0xd0
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).SetSourceNode(0x11e0c638, 0x120903f0, 0x46, 0x46)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/channeldb/graph.go:314 +0x5c
main.newServer(0x11f30978, 0x1, 0x1, 0x11f76050, 0x12084000, 0x122fd140, 0x0, 0x8, 0x12084000)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/server.go:320 +0xe10
main.lndMain(0x0, 0x0)
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/lnd.go:303 +0x8b8
main.main()
/Users/roasbeef/gocode/src/github.com/lightningnetwork/lnd/lnd.go:623 +0x24

Your environment

• lnd 0.4.1-beta (lnd-linux-arm-v0.4.1-beta.tar.gz)
• Linux 4.14.30-v7+ invoice: improve "wrong network" error message #1102 SMP Mon Mar 26 16:45:49 BST 2018 armv7l GNU/Linux (Rapbian Stretch Lite)
• Bitcoin Core Daemon version v0.16.0 (bitcoin-0.16.0-arm-linux-gnueabihf.tar.gz)
• I recently copied my existing .lnd folder to a new hardrive.

Steps to reproduce

lnd is crashing during startup. It happens every time I try to start it.

Expected behaviour

lnd should startup without error

Actual behaviour

lnd crashes with a stack trace.

[Roasbeef]

I recently copied my existing .lnd folder to a new hardrive.

Did you copy the directory while lnd was running?

[plasm0r]

No, it was shutdown, along with bitcoind. I copied both the .bitcoin and .lnd folders over to the new drive. bitcoind started without problems. Lnd did a lot of initial syncing/catching up and then it crashed. Upon restart I keep getting the same results.

I could delete everything and start over, unless there is something you would like me to check further?

[Roasbeef]

If you re-compile lnd with the -race flag, does it report anything?

go build -v -race

[plasm0r]

I tried that, but it's not supported on my platform:

go build: -race and -msan are only supported on linux/amd64, freebsd/amd64, darwin/amd64 and windows/amd64

I built from the latest source and tried again, I still get the same crash.

Anything else I can try for you?

[plasm0r]

Somthing that i forgot to mention is that I was using an external USB drive that was powered by the raspberry PI. This wasn't working too well and I would occasionally get voltage drops. So I switched to a USB drive that was separately powered. I wonder if database corruption could have occurred during those voltage drops.

I was searching and came across this which made me think that boltdb/bolt#348
It's an older issue but it made me think that those voltage drops I was getting could have corrupted the database.

[Roasbeef]

Hmm, yeah according to that issue, the bug was fixed. But seems it has popped up elsewhere. FWIW, now use coreos/bbolt instead of boltdb/bolt as the latter is no longer actively maintained.

Looking at coreos/bbolt I've found this: etcd-io/bbolt#72

• Which points to there being a race somewhere in the code, which is why I asked if you could run with the race condition detector on.

[plasm0r]

Ok, i have a copy of the database that caused the problem. I will try and recompile on my x64 Linux VM with that race flag set as it's not available when compiling a Go app on an Arm platform like the Raspberry PI.

[halseth]

Similar: lightninglabs/neutrino#48

[plasm0r]

Hi

I recompiled on my x64 Linux VM and ran LND with the bad database copied from my Raspberry PI and I'm getting the same error (see below) with no additional information that I can see. Is there something I could have missed? I did notice that with that race flag set, LND took much longer to start and used a lot more of the CPU. Anything else you want me to try?

2018-04-27 18:50:02.266 [INF] LTND: Version 0.4.1-beta commit=
2018-04-27 18:50:02.281 [INF] LTND: Active chain: Bitcoin (network=testnet)
2018-04-27 18:50:02.963 [INF] CHDB: Checking for schema update: latest_version=0, db_version=0
2018-04-27 18:50:03.503 [INF] RPCS: password RPC server listening on 127.0.0.1:10009
2018-04-27 18:50:03.507 [INF] RPCS: password gRPC proxy started at 127.0.0.1:8080
2018-04-27 18:50:03.507 [INF] LTND: Waiting for wallet encryption password. Use lncli create to create wallet, or lncli unlock to unlock already created wallet.
2018-04-27 18:50:50.521 [INF] LNWL: Opened wallet
2018-04-27 18:50:50.695 [INF] LTND: Primary chain is set to: bitcoin
2018-04-27 18:50:50.968 [INF] LTND: Initializing btcd backed fee estimator
2018-04-27 18:51:14.645 [INF] LNWL: Opened wallet
2018-04-27 18:51:40.597 [INF] LNWL: The wallet has been unlocked without a time limit
2018-04-27 18:51:40.598 [INF] LTND: LightningWallet opened
2018-04-27 18:51:41.357 [INF] LNWL: Started rescan from block 00000000eb8c3cd4de7697ad36294b4afa72e3e514935f326d67c94fa6d2d95f (height 1293900) for 36 addresses
2018-04-27 18:51:42.192 [INF] HSWC: Restoring in-memory circuit state from disk
2018-04-27 18:51:42.234 [INF] HSWC: Payment circuits loaded: num_pending=6, num_open=6
2018-04-27 18:51:42.511 [INF] HSWC: Trimming open circuits for chan_id=1293038:78:0, start_htlc_id=0
2018-04-27 18:51:42.512 [INF] HSWC: Trimming open circuits for chan_id=1293043:62:1, start_htlc_id=0
2018-04-27 18:51:42.512 [INF] HSWC: Trimming open circuits for chan_id=1293054:445:0, start_htlc_id=0
panic: page 1072 already freed

goroutine 1 [running]:
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*freelist).free(0xc42021fa70, 0x8605, 0x7fae22430000)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/freelist.go:143 +0x796
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0xc4205ac540, 0xc420592a60, 0x15b8fe0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:363 +0x962
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0xc4205ac4d0, 0x0, 0x0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:350 +0x190
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*node).spill(0xc4205ac460, 0xc4206ec4c0, 0x5)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/node.go:350 +0x190
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Bucket).spill(0xc4201960c0, 0xc4202b0300, 0xc4206ec940)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/bucket.go:568 +0x699
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Bucket).spill(0xc42025c0f8, 0x1875e8a14c, 0x1b25e00)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/bucket.go:535 +0x52a
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Tx).Commit(0xc42025c0e0, 0x0, 0x0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/tx.go:160 +0x191
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*DB).Update(0xc42027c780, 0xc4206ecba0, 0x0, 0x0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/db.go:675 +0x125
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).SetSourceNode(0xc4202b4008, 0xc420330000, 0x46, 0x46)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/channeldb/graph.go:314 +0xe5
main.newServer(0xc420280300, 0x1, 0x1, 0xc420236740, 0xc42017a1b0, 0xc42021f1a0, 0x8, 0x8, 0x0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/server.go:320 +0x1f0e
main.lndMain(0x0, 0x0)
/home/admin/gocode/src/github.com/lightningnetwork/lnd/lnd.go:320 +0x11c5
main.main()
/home/admin/gocode/src/github.com/lightningnetwork/lnd/lnd.go:636 +0x34