Allow lnd to be stopped while starting

[stridentbean]

Background

Running a casa node right now and sometimes lncli stop OR docker stop doesn't shutdown lnd. From looking at the logs, it appears the shutdown command is being received, but it never shuts down. If I run docker stop lnd, after 10 minutes the default docker timeout will kill the container.

The best guess I have is that lnd isn't fully functional yet when I am trying to shut it down. So, lnd would receive the signal to shutdown, but is unable to actually do it. I think this because sometimes I have seen it shut down properly in about 30 seconds, which is slow, but expected for the pi.

Your environment

• lnd 0.7.0.
• Linux casa-node 4.14.70-v7+ Fixing some README typos #2 SMP Wed Sep 19 07:49:26 UTC 2018 armv7l GNU/Linux)
• Has affected both Bitcoind 0.18.0.
• Running on a raspberry pi 3 b+ in docker containers.
• Tor version 0.3.5.8.

Steps to reproduce

1. Spin up lnd on a raspberry pi in a docker container
2. Unlock lnd
3. Immediately run lncli stop from inside the container
4. Observe lnd continue to run and still actively listen for new rpc calls (ex lncli getinfo)

Logs from lnd

2019-08-13 22:51:46.294 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2019-08-13 22:51:46.295 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2019-08-13 22:51:46.313 [INF] LTND: Waiting for chain backend to finish sync, start_height=589992
2019-08-13 22:51:47.646 [INF] LNWL: Started rescan from block 00000000000000000006940febb02acde1b79268e8ff4d7c8622772cf22438e6 (height 589992) for 105 addresses
2019-08-13 22:51:47.682 [INF] LNWL: Catching up block hashes to height 589992, this might take a while
2019-08-13 22:51:47.736 [INF] LNWL: Done catching up block hashes
2019-08-13 22:51:47.737 [INF] LNWL: Finished rescan for 105 addresses (synced to block 00000000000000000006940febb02acde1b79268e8ff4d7c8622772cf22438e6, height 589992)
2019-08-13 22:51:48.340 [INF] LTND: Chain backend is fully synced (end_height=589992)!
2019-08-13 22:51:48.482 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:48.504 [INF] HSWC: Starting HTLC Switch
2019-08-13 22:51:48.505 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:48.505 [INF] LNWL: Inserting unconfirmed transaction 0557ef9b0ada0b74f2f0b9ffca57536d1afd948a936e2305b1170cb0ca0fbdb9
2019-08-13 22:51:48.670 [INF] LNWL: Removed invalid transaction: (*wire.MsgTx)(0x13fe06c0)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=1) {
  (*wire.TxIn)(0x392bd00)({
   PreviousOutPoint: (wire.OutPoint) 2fb69f7dc83042aafcc3198d2703849d1ebd9556bc60ea05da1bdfb1bd563573:0,
   SignatureScript: ([]uint8) {
   },
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=71) {
     00000000  30 44 02 20 4a 05 8f 4b  28 31 c7 90 67 14 aa 6f  |0D. J..K(1..g..o|
     00000010  56 18 89 c9 e2 b4 38 dc  6f 5d ea 9b 8b d9 49 47  |V.....8.o]....IG|
     00000020  ac 80 d5 a7 02 20 7f 2d  11 42 e4 66 f8 7e 7f 02  |..... .-.B.f.~..|
     00000030  a4 e7 01 0c bc 93 c4 d1  6a 3d 3c d3 00 ec 7a 2f  |........j=<...z/|
     00000040  d9 f3 79 cc d4 8b 01                              |..y....|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 15 05 a3 7a b9 e7 75  52 45 fe 4f 82 40 d8 2e  |....z..uRE.O.@..|
     00000010  ad 4e 3a c3 52 9b 75 4b  35 4d 2e ab 6e d0 05 12  |.N:.R.uK5M..n...|
     00000020  81                                                |.|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=1) {
  (*wire.TxOut)(0x13fe0700)({
   Value: (int64) 71597,
   PkScript: ([]uint8) (len=22 cap=22) {
    00000000  00 14 63 d9 3f 71 cd 10  bb 11 b4 dd cb 0d 56 f0  |..c.?q........V.|
    00000010  8a 5f e1 46 73 da                                 |._.Fs.|
   }
  })
 },
 LockTime: (uint32) 588757
})

2019-08-13 22:51:48.676 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:48.723 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:48.740 [INF] CNCT: Creating ChannelArbitrators for 1 closing channels
2019-08-13 22:51:48.741 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:48.770 [INF] CNCT: ChannelArbitrator(2c262f0ff0bc2aedbbd2cdea80fbd7696b8a8601e4e623b54791578285c1ed10:1): starting state=StateWaitingFullResolution
2019-08-13 22:51:48.775 [INF] CNCT: ChannelArbitrator(2c262f0ff0bc2aedbbd2cdea80fbd7696b8a8601e4e623b54791578285c1ed10:1): still awaiting contract resolution
2019-08-13 22:51:48.778 [INF] CNCT: ChannelArbitrator(2c262f0ff0bc2aedbbd2cdea80fbd7696b8a8601e4e623b54791578285c1ed10:1): relaunching 1 contract resolvers
2019-08-13 22:51:48.786 [INF] NTFN: New confirmation subscription: txid=2fb69f7dc83042aafcc3198d2703849d1ebd9556bc60ea05da1bdfb1bd563573, num_confs=1
2019-08-13 22:51:48.786 [INF] NTFN: New confirmation subscription: conf_id=1, txid=2fb69f7dc83042aafcc3198d2703849d1ebd9556bc60ea05da1bdfb1bd563573, height_hint=588252
2019-08-13 22:51:48.793 [INF] DISC: Authenticated Gossiper is starting
2019-08-13 22:51:48.793 [INF] BRAR: Starting contract observer, watching for breaches.
2019-08-13 22:51:48.793 [INF] NTFN: New block epoch subscription
2019-08-13 22:51:49.338 [INF] CRTR: FilteredChainView starting
2019-08-13 22:52:27.883 [INF] LTND: Received terminated
2019-08-13 22:52:27.971 [INF] LTND: Shutting down...
2019-08-13 22:52:27.971 [INF] LTND: Gracefully shutting down.
2019-08-13 22:53:54.027 [INF] CRTR: Filtering chain using 35790 channels active
2019-08-13 22:53:54.223 [INF] CRTR: Prune tip for Channel Graph: height=589215, hash=0000000000000000000298138d21e5fa81d0589dcdca29e39c3219fddd6c1e57
2019-08-13 22:53:54.257 [INF] CRTR: Syncing channel graph from height=589215 (hash=0000000000000000000298138d21e5fa81d0589dcdca29e39c3219fddd6c1e57) to height=589992 (hash=00000000000000000006940febb02acde1b79268e8ff4d7c8622772cf22438e6)
2019-08-13 22:54:00.650 [INF] CRTR: Block 000000000000000000043a935930653bc04b13a02773f4510e9542504516d9e9 (height=589216) closed 12 channels
2019-08-13 22:54:04.023 [INF] CHDB: Pruned unconnected node 02ef01a0a61aa6bc2730ce6d129338ea951658c94113ad9c901752c00c05d9a072 from channel graph
2019-08-13 22:54:04.024 [INF] CHDB: Pruned 1 unconnected nodes from the channel graph
2019-08-13 22:54:04.138 [INF] CRTR: Block 0000000000000000000ed9f360d4d87ce92b93b24b39359ebfe910f616aa0bfc (height=589217) closed 1 channels
2019-08-13 22:54:06.946 [INF] CRTR: Block 00000000000000000006c16db981bb9e2de9d735f6489196deec98c68a9ee704 (height=589218) closed 0 channels
2019-08-13 22:54:08.268 [INF] CRTR: Block 00000000000000000007956d028bb6de32b5cc027f10485af08eb115b664425e (height=589219) closed 0 channels
2019-08-13 22:54:09.732 [INF] CRTR: Block 00000000000000000005cf12fe5ff117fc1eec475bb8103692e17d97c0ebfeb5 (height=589220) closed 2 channels
2019-08-13 22:54:11.913 [INF] CRTR: Block 0000000000000000000bcf4a963b1e54169da28e188e3f0ef1a29627c5e12bfa (height=589221) closed 0 channels
2019-08-13 22:54:13.952 [INF] CRTR: Block 0000000000000000001b88b96707c0257a651a355d6fdee638c3ef82789e9424 (height=589222) closed 0 channels
2019-08-13 22:54:15.482 [INF] CRTR: Block 00000000000000000014ebe6ccf7e3cca4115cfcbad349a2bc678a70eddddbf6 (height=589223) closed 3 channels
2019-08-13 22:54:17.972 [INF] CRTR: Block 0000000000000000001411ae7e1ada6e1614007e8b2df6a6ec2f6cbdc0e66021 (height=589224) closed 0 channels
2019-08-13 22:54:20.030 [INF] CRTR: Block 00000000000000000016f22f07fd69bbbd27e810b5cfa697562d4d0939b116fa (height=589225) closed 0 channels
2019-08-13 22:54:23.433 [INF] CRTR: Block 0000000000000000000196c901c9bd005b6728d5ae8d6c43e7fb1e5afe0ced4d (height=589226) closed 0 channels
2019-08-13 22:54:24.700 [INF] CRTR: Block 0000000000000000000782d280ee7ab3b31a71f429ccfb4c705cfd902b0aa007 (height=589227) closed 1 channels
2019-08-13 22:54:26.362 [INF] CRTR: Block 00000000000000000004eeee7d953845734d3ba34efeef7341d98ef436b1318a (height=589228) closed 0 channels
2019-08-13 22:54:27.563 [INF] CRTR: Block 0000000000000000000c93bc23d9d1a10176a0c13bc3e669270aaf5e8a429cb2 (height=589229) closed 0 channels
2019-08-13 22:54:28.655 [INF] CRTR: Block 000000000000000000168363444d5a5798c844af31e293cf9c9fbbb4b36a0689 (height=589230) closed 0 channels
2019-08-13 22:54:29.866 [INF] CRTR: Block 000000000000000000119f540a08bac7d285171f68c9c32752988d79fbec7087 (height=589231) closed 0 channels
2019-08-13 22:54:31.176 [INF] CRTR: Block 00000000000000000014115deb70c1cf43fdd0b724f540a492b3f93334d7d0e5 (height=589232) closed 0 channels
2019-08-13 22:54:32.509 [INF] CRTR: Block 0000000000000000000d2a5ad51ff7ea224e323194ff370a99cc1ecaebb800df (height=589233) closed 0 channels
2019-08-13 22:54:33.691 [INF] CRTR: Block 000000000000000000125d8aaafae6a8f972d757272f80f8e774e5f40052359f (height=589234) closed 0 channels
2019-08-13 22:54:35.466 [INF] CRTR: Block 00000000000000000019e49e5d6262edfb745afd29c218db2559b3b7d99b1658 (height=589235) closed 5 channels
2019-08-13 22:54:39.253 [INF] CRTR: Block 000000000000000000141707eb165f372704e393ee0025e3025d03e19a4d66d4 (height=589236) closed 10 channels
2019-08-13 22:54:43.697 [INF] CRTR: Block 00000000000000000015cd9958a969ed755b81ee6b523ffa19439004df6d7abe (height=589237) closed 1 channels
2019-08-13 22:54:47.793 [INF] CRTR: Block 00000000000000000019bc94057e4a1bcf4a59b1254e178661827e06a035c51e (height=589238) closed 0 channels
2019-08-13 22:54:51.811 [INF] CHDB: Pruned unconnected node 022911a1d94385130dafa548edc54ab4e263e1b59f67299ad0cbe1f1be948dda38 from channel graph
2019-08-13 22:54:51.811 [INF] CHDB: Pruned 1 unconnected nodes from the channel graph
2019-08-13 22:54:51.910 [INF] CRTR: Block 0000000000000000000c54a5ad1ebb9a6bbedac133f00e64c89e2ecfd3ef2d10 (height=589239) closed 2 channels

I tried it again and waited for lnd to "boot up fully".

2019-08-13 23:16:09.437 [INF] CRTR: Graph pruning complete: 339 channels were closed since height 589552
2019-08-13 23:16:09.616 [INF] CRTR: Pruning channel graph using block 0000000000000000001759ba329cefad464a3831b2858935afbf747de2e619e4 (height=589993)
2019-08-13 23:16:09.841 [INF] CHBU: Starting chanbackup.SubSwapper
2019-08-13 23:16:09.892 [INF] CMGR: Server listening on [::]:9735
2019-08-13 23:16:10.299 [INF] CHBU: Updating backup file at /root/.lnd/data/scb/channels.backup

Then I send the stop command and it was shutdown within 30 seconds.

Expected behaviour

Lnd should shut down quickly

Actual behaviour

Lnd stays open until docker times out.

[Roasbeef]

Immediately run lncli stop from inside the container

This just seems like a race condition? The RPC server may not be up yet by the time you issue the call.

[stridentbean]

Okay, I'll define immediately loosely. If I really do the rpc call immediately, it will fail (connection refused). Here, the rpc call is successfully hitting lnd. You can also see

2019-08-13 22:52:27.971 [INF] LTND: Shutting down...
2019-08-13 22:52:27.971 [INF] LTND: Gracefully shutting down.

In the logs.

[Roasbeef]

In the case of your logs, it's catching up to the chain after it has been offline for some time, which is why (atm) that isn't halted immediately. Once it finishes catching up, then it should shut down.

[cfromknecht]

@stridentbean 0.7.1 has a partial solution to this, in that catching up blocks is significantly faster. instead of doing a db txn per block, we now do one db txn for all outstanding blocks thanks to #3251. I'd be interested to hear if it's as big of an issue on 0.7.1

The root of the issue tho I think the issue is as you say:

So, lnd would receive the signal to shutdown, but is unable to actually do it.

This shutdown signal isn't being processed while the server is starting. I think there are some ways we could work around this, shouldn't be too complicated.

[stridentbean]

@cfromknecht Testing 0.7.1 this morning does show significant improvement. When lnd is fully synced, shutdown takes ~15-20 seconds. When lnd is just unlocked then immediately shut down, it completes in ~120-150 seconds. While not ideal, it is substantially better than 0.7.0. It also means that we can guarantee a clean shutdown. Previously it just timed out after 10 minutes and then docker just killed lnd.

[stridentbean]

Also, to give a little more context. The reason this is coming up is that we want to use the change password rpc on lnd. But, as noted in #2529, we can only use changepassword if the wallet unlocker is active. It is only active after a restart. So, we are trying to restart lnd just before calling a changepassword.

Adding another data point, changepassword takes 30 seconds pretty consistently. Although, I haven't tested with a huge amount of channels yet. I'm not sure if that will affect it.

[Roasbeef]

changepassword takes 30 seconds pretty consistently

It needs to perform a series of scrypt operations, which allocate a lot of memory, and may be slow on hardware like a rasp pi.