lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.73k stars 2.09k forks source link

lnd.service shutting down after unlocking wallet successfully #1938

Closed ad2003 closed 6 years ago

ad2003 commented 6 years ago

Background

I updated from 0.4.2 to 0.5.0-beta commit=3b2c807288b1b7f40d609533c1e96a510ac5fa6d. Everything just worked fine for around 24hours. But then the wallet was locked. I restarted everything manually, waited for bitcoind to start completely, started lnd manually but when I try to unlock my wallet I am getting the following log:

-- Logs begin at Thu 2016-11-03 18:16:43 CET. -- Sep 19 11:40:15 raspberrypi lnd[2093]: Attempting automatic RPC configuration to bitcoind Sep 19 11:40:15 raspberrypi lnd[2093]: Automatically obtained bitcoind's RPC cre dentials Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.684 [INF] LTND: Versi on 0.5.0-beta commit=3b2c807288b1b7f40d609533c1e96a510ac5fa6d Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.684 [INF] LTND: Activ e chain: Bitcoin (network=mainnet) Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.688 [INF] CHDB: Check ing for schema update: latest_version=6, db_version=6 Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.697 [INF] RPCS: passw ord RPC server listening on 127.0.0.1:10009 Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.698 [INF] RPCS: passw ord gRPC proxy started at 127.0.0.1:8080 Sep 19 11:40:15 raspberrypi lnd[2093]: 2018-09-19 11:40:15.698 [INF] LTND: Waiti ng for wallet encryption password. Use lncli create to create a wallet, lncli unlock to unlock an existing wallet, or lncli changepassword to change the p assword of an existing wallet and unlock it. Sep 19 13:14:31 raspberrypi lnd[2093]: 2018-09-19 13:14:31.633 [INF] LNWL: Opene d wallet Sep 19 13:14:32 raspberrypi lnd[2093]: 2018-09-19 13:14:32.929 [INF] LTND: Prima ry chain is set to: bitcoin Sep 19 13:14:41 raspberrypi lnd[2093]: 2018-09-19 13:14:41.333 [INF] LTND: Initializing bitcoind backed fee estimator Sep 19 13:14:41 raspberrypi lnd[2093]: 2018-09-19 13:14:41.334 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on tcp://127.0.0.1:28334 Sep 19 13:14:41 raspberrypi lnd[2093]: 2018-09-19 13:14:41.333 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on tcp://127.0.0.1:28332 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.439 [INF] LNWL: The wallet has been unlocked without a time limit Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.439 [INF] LTND: LightningWallet opened Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.525 [INF] HSWC: Restoring in-memory circuit state from disk Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.541 [INF] HSWC: Payment circuits loaded: num_pending=1, num_open=0 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.664 [INF] HSWC: Trimming open circuits for chan_id=533772:868:1, start_htlc_id=50 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.665 [INF] HSWC: Trimming open circuits for chan_id=533764:1592:0, start_htlc_id=25 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.665 [INF] HSWC: Trimming open circuits for chan_id=533660:1938:0, start_htlc_id=42 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.665 [INF] HSWC: Trimming open circuits for chan_id=537675:1291:0, start_htlc_id=0 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.666 [INF] HSWC: Trimming open circuits for chan_id=541586:1513:1, start_htlc_id=0 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.756 [INF] RPCS: RPC server listening on 127.0.0.1:10009 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.775 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.784 [INF] LTND: Waiting for chain backend to finish sync, start_height=542077 Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.950 [INF] LNWL: Started rescan from block 0000000000000000001573bb4bda3b94bf30c78a216befda7dc14183a23bb1f9 (height 542072) for 98 addresses Sep 19 13:14:52 raspberrypi lnd[2093]: 2018-09-19 13:14:52.956 [INF] LNWL: Starting rescan from block 0000000000000000001573bb4bda3b94bf30c78a216befda7dc14183a23bb1f9 Sep 19 13:15:07 raspberrypi lnd[2093]: 2018-09-19 13:15:07.886 [INF] LNWL: Rescan finished at 542072 (0000000000000000001573bb4bda3b94bf30c78a216befda7dc14183a23bb1f9) Sep 19 13:15:07 raspberrypi lnd[2093]: 2018-09-19 13:15:07.892 [INF] LNWL: Catching up block hashes to height 542072, this might take a while Sep 19 13:15:07 raspberrypi lnd[2093]: 2018-09-19 13:15:07.905 [INF] LNWL: Done catching up block hashes Sep 19 13:15:07 raspberrypi lnd[2093]: 2018-09-19 13:15:07.905 [INF] LNWL: Finished rescan for 98 addresses (synced to block 0000000000000000001573bb4bda3b94bf30c78a216befda7dc14183a23bb1f9, height 542072) Sep 19 13:15:08 raspberrypi lnd[2093]: 2018-09-19 13:15:08.756 [INF] LTND: Chain backend is fully synced (end_height=542077)! Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.327 [INF] HSWC: Starting HTLC Switch Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.327 [INF] NTFN: New block epoch subscription Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.327 [INF] NTFN: New block epoch subscription Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.531 [INF] NTFN: New block epoch subscription Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.602 [INF] UTXN: Processing outputs from missed blocks. Starting with blockHeight=542072, to current blockHeight=542077 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.602 [INF] UTXN: Attempting to graduate height=542073: num_kids=0, num_babies=0 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.645 [INF] UTXN: Attempting to graduate height=542074: num_kids=0, num_babies=0 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.690 [INF] UTXN: Attempting to graduate height=542075: num_kids=0, num_babies=0 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.724 [INF] UTXN: Attempting to graduate height=542076: num_kids=0, num_babies=0 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.764 [INF] UTXN: Attempting to graduate height=542077: num_kids=0, num_babies=0 Sep 19 13:15:09 raspberrypi lnd[2093]: 2018-09-19 13:15:09.799 [INF] UTXN: UTXO Nursery is now fully synced Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.070 [INF] CNCT: Creating ChannelArbitrators for 5 active channels Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.078 [INF] NTFN: New block epoch subscription Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.078 [INF] NTFN: New block epoch subscription Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.079 [INF] NTFN: New block epoch subscription Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.080 [INF] NTFN: New block epoch subscription Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.137 [INF] NTFN: New spend subscription: utxo=94344af8e0a1eaddef4b2ec1fa99045feb626584e25228b03bae3e9854ccf130:1 Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.137 [INF] NTFN: New spend subscription: utxo=c6ea46089fba93fe68f53e23a4303e7a44b743cabdf10fc990968c89fbfb1ccd:0 Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.137 [INF] NTFN: New spend subscription: utxo=7234c55ebe34990172604d61dd8bad64edd5caa11c888a661810b8990bd52179:1 Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.138 [INF] NTFN: New spend subscription: utxo=5c17817c2b8ac5194b53f88d735040fc1a904fe7c6d16b16ae79f606a47789f7:0 Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.138 [INF] NTFN: New spend subscription: utxo=d83b7addaf32eb600725f10adcfa8d0c0279054257b7829d238687f60caaef5e:0 Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.145 [INF] CNCT: Close observer for ChannelPoint(c6ea46089fba93fe68f53e23a4303e7a44b743cabdf10fc990968c89fbfb1ccd:0) active Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.151 [INF] CNCT: Close observer for ChannelPoint(d83b7addaf32eb600725f10adcfa8d0c0279054257b7829d238687f60caaef5e:0) active Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.156 [INF] CNCT: Close observer for ChannelPoint(7234c55ebe34990172604d61dd8bad64edd5caa11c888a661810b8990bd52179:1) active Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.162 [INF] CNCT: Close observer for ChannelPoint(5c17817c2b8ac5194b53f88d735040fc1a904fe7c6d16b16ae79f606a47789f7:0) active Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.166 [INF] CNCT: Close observer for ChannelPoint(94344af8e0a1eaddef4b2ec1fa99045feb626584e25228b03bae3e9854ccf130:1) active Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.166 [INF] CNCT: ChannelArbitrator(7234c55ebe34990172604d61dd8bad64edd5caa11c888a661810b8990bd52179:1): starting state=StateDefault Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.212 [INF] CNCT: ChannelArbitrator(d83b7addaf32eb600725f10adcfa8d0c0279054257b7829d238687f60caaef5e:0): starting state=StateDefault Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.308 [INF] CNCT: ChannelArbitrator(c6ea46089fba93fe68f53e23a4303e7a44b743cabdf10fc990968c89fbfb1ccd:0): starting state=StateDefault Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.320 [INF] CNCT: ChannelArbitrator(5c17817c2b8ac5194b53f88d735040fc1a904fe7c6d16b16ae79f606a47789f7:0): starting state=StateDefault Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.334 [INF] CNCT: ChannelArbitrator(94344af8e0a1eaddef4b2ec1fa99045feb626584e25228b03bae3e9854ccf130:1): starting state=StateDefault Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.403 [INF] DISC: Authenticated Gossiper is starting Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.403 [INF] BRAR: Starting contract observer, watching for breaches. Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.403 [INF] NTFN: New block epoch subscription Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.991 [INF] CRTR: FilteredChainView starting Sep 19 13:15:10 raspberrypi lnd[2093]: 2018-09-19 13:15:10.992 [ERR] SRVR: unable to send message to 031dd05b132fcca906701d2544aa23d60bace06e86e326575ba2c53071a2fc11c5, peer is not connected Sep 19 13:15:11 raspberrypi lnd[2093]: 2018-09-19 13:15:11.015 [ERR] DISC: unable to send AnnounceSignatures message to peer(031dd05b132fcca906701d2544aa23d60bace06e86e326575ba2c53071a2fc11c5): peer is not connected. Will retry when online. Sep 19 13:15:11 raspberrypi lnd[2093]: 2018-09-19 13:15:11.904 [ERR] SRVR: unable to start server: edge not found Sep 19 13:15:11 raspberrypi systemd[1]: lnd.service: Main process exited, code=exited, status=1/FAILURE Sep 19 13:15:11 raspberrypi systemd[1]: lnd.service: Unit entered failed state. Sep 19 13:15:11 raspberrypi systemd[1]: lnd.service: Failed with result 'exit-code'.

Your environment

Steps to reproduce

Everythings starts fine, wallet unlocks successfully but locks after some time.

Expected behaviourH

It should work as before.

Actual behaviour

Tell us what happens instead

wpaulino commented 6 years ago

Spent some time looking into this with the user on slack. Turns out the edge not being found is 395a1b980cc6d77c9f13c7291a3c5ccb5653181ab218d0b0f7517d2d34938d17:1, which is not relevant to the user.

Currently, the server fails to start because we're unable to fetch the channel view of the graph when starting the router. This fails due to not finding the edge info for the channel above. Not sure how things got into this state however, as the edge seems to have been added successfully to the database from looking at the logs.

2018-09-17 20:50:39.300 [INF] CRTR: New channel discovered! Link connects 037584aa529af342287a0f91427df19f497925b93f9e1a73c48af2fe5cd16a1542 and 03b9bbc899b028a4c29b3fe17a7b382d64e3a8fc768f9ea91bdd8c4bc6ab4c7589 with ChannelPoint(395a1b980cc6d77c9f13c7291a3c5ccb5653181ab218d0b0f7517d2d34938d17:1): chan_id=595742887755513857, capacity=0.00103549 BTC

After providing them with a patch to start up, they ran into the following crash:

panic: runtime error: slice bounds out of range

goroutine 1 [running]:
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*leafPageElement).value(...)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/page.go:126
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Cursor).keyValue(0x12377c18, 0x12af1480, 0x396ed8df, 0x8e516e8f, 0x41914c8f, 0x35de5d4b, 0x3542e2ba, 0xff5090cd)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/cursor.go:354 +0x190
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Cursor).next(0x12377c18, 0x9a1a14, 0x9, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/cursor.go:248 +0xdc
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Cursor).Next(0x12377c18, 0x24, 0x24, 0x70b16424, 0x8, 0x8, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/cursor.go:75 +0x64
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*Bucket).ForEach(0x125947e0, 0x12377c4c, 0xa, 0xa)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/bucket.go:387 +0xa8
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).ChannelView.func1(0x12067380, 0xb0e890, 0x12067380)
        /home/pi/go/src/github.com/lightningnetwork/lnd/channeldb/graph.go:2626 +0xf8
github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt.(*DB).View(0x1210a000, 0x12377c90, 0x0, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/vendor/github.com/coreos/bbolt/db.go:699 +0x80
github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).ChannelView(0x123be188, 0x123be878, 0x1, 0x1, 0x0, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/channeldb/graph.go:2606 +0x50
github.com/lightningnetwork/lnd/routing.(*ChannelRouter).Start(0x11f98280, 0x0, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/routing/router.go:378 +0x2f0
main.(*server).Start(0x12158380, 0x9cb1b2, 0x2e)
        /home/pi/go/src/github.com/lightningnetwork/lnd/server.go:954 +0x150
main.lndMain(0x0, 0x0)
        /home/pi/go/src/github.com/lightningnetwork/lnd/lnd.go:423 +0xf00
main.main()
        /home/pi/go/src/github.com/lightningnetwork/lnd/lnd.go:455 +0x14

This seems to point towards a database corruption, which would also explain why we were unable to find the edge above even though it was successfully added.

halseth commented 6 years ago

rip rPi 😢