Ensure Safe LND Shutdown on Quit

[cfromknecht]

Description

In testing I found the the child LND process appears to be killed when closing the application, e.g. clicking the red button on Mac OS. Ideally shutting down would call StopDaemon to mitigate the chance of corrupting the disk state or leaving us in an inconsistent state that we can't recover from

Steps to reproduce the behavior

Open application and press quit. I haven't tried Cmd+Q, but would guess the behavior would be similar. The bug should be exhibited irrespective of any application state after the daemon is started.

Expected behavior

LND stopping all of the subsystems and cleaning up resources

Example shutdown logs when Ctrl+C'ing LND:

^C2018-08-22 18:39:46.239 [INF] LTND: Received SIGINT (Ctrl+C).
2018-08-22 18:39:46.239 [INF] LTND: Shutting down...
2018-08-22 18:39:46.239 [INF] LTND: Gracefully shutting down.
2018-08-22 18:39:46.239 [INF] ATPL: Autopilot Agent stopping
2018-08-22 18:39:46.240 [INF] CRTR: Channel Router shutting down
2018-08-22 18:39:46.240 [INF] CRTR: FilteredChainView stopping
2018-08-22 18:39:46.240 [WRN] FNDG: ChainNotifier shutting down, cannot complete funding flow for ChannelPoint(b8b971a17d5146ce4d8a4aa531e9aa59d0520ff899999ba5a5f146922f761daa:1)
2018-08-22 18:39:46.240 [INF] HSWC: Block epoch canceled, decaying hash log shutting down
2018-08-22 18:39:46.240 [ERR] CRTR: Error encountered during rescan: <nil>
2018-08-22 18:39:46.240 [INF] HSWC: HTLC Switch shutting down
2018-08-22 18:39:46.240 [ERR] FNDG: waiting for funding confirmation failed
2018-08-22 18:39:46.241 [INF] UTXN: UTXO nursery shutting down
2018-08-22 18:39:46.241 [INF] BRAR: Breach arbiter shutting down
2018-08-22 18:39:46.241 [INF] DISC: Authenticated Gossiper is stopping
2018-08-22 18:39:46.241 [INF] CNCT: Stopping ChainArbitrator
2018-08-22 18:39:46.241 [INF] FNDG: Funding manager shutting down
2018-08-22 18:39:46.241 [INF] SRVR: Disconnecting from 178.128.224.168:9735
2018-08-22 18:39:46.241 [INF] PEER: unable to read message from 178.128.224.168:9735: read tcp 10.2.3.93:56961->178.128.224.168:9735: use of closed network connection
2018-08-22 18:39:46.241 [INF] SRVR: Disconnecting from 85.195.232.197:9735
2018-08-22 18:39:46.241 [INF] PEER: unable to read message from 85.195.232.197:9735: read tcp 10.2.3.93:56988->85.195.232.197:9735: use of closed network connection
2018-08-22 18:39:46.242 [INF] SRVR: Disconnecting from 92.53.100.122:9735
2018-08-22 18:39:46.242 [INF] PEER: unable to read message from 92.53.100.122:9735: read tcp 10.2.3.93:56968->92.53.100.122:9735: use of closed network connection
2018-08-22 18:39:46.242 [INF] SRVR: Disconnecting from 70.122.6.171:9735
2018-08-22 18:39:46.242 [INF] PEER: unable to read message from 70.122.6.171:9735: read tcp 10.2.3.93:57019->70.122.6.171:9735: use of closed network connection
2018-08-22 18:39:46.242 [INF] BTCN: Lost peer 127.0.0.1:18333 (outbound)
2018-08-22 18:39:46.242 [INF] BTCN: Syncing to block height 1405559 from peer 104.155.159.141:18333
2018-08-22 18:39:46.242 [INF] BTCN: Fetching set of headers from tip (height=1405559) from peer 104.155.159.141:18333
2018-08-22 18:39:46.243 [INF] BTCN: Lost peer 104.155.159.141:18333 (outbound)
2018-08-22 18:39:46.243 [WRN] BTCN: No sync peer candidates available
2018-08-22 18:39:46.293 [INF] BTCN: Block manager shutting down
2018-08-22 18:39:47.132 [INF] BTCN: Verified 1 filter header in the last 41.54s (height 1405559, 2018-08-22 18:39:02 -0700 PDT)
2018-08-22 18:39:47.132 [INF] BTCN: Address manager shutting down
2018-08-22 18:39:47.155 [INF] LTND: Shutdown complete

Actual behavior

The log messages seem sympotatic of the child process being killed instead of shutdown

Logs from terminal where the app was started:

[20:21:13.611] [info] lnd: 2018-08-22 20:21:13.584 [INF] BTCN: Verified 1 filter header in the last 14.54s (height 1405977, 2018-08-22 20:20:58 -0700 PDT)
2018-08-22 20:21:13.585 [INF] NTFN: New block: height=1405977, sha=0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20
2018-08-22 20:21:13.585 [INF] UTXN: Attempting to graduate height=1405977: num_kids=0, num_babies=0
2018-08-22 20:21:13.590 [INF] CRTR: Pruning channel graph using block 0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20 (height=1405977)
2018-08-22 20:21:13.592 [INF] CRTR: Block 0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20 (height=1405977) closed 0 channels

[20:21:29.511] [info] lnd: 2018-08-22 20:21:29.485 [INF] DISC: Broadcasting batch of 1 new announcements

k[20:21:35.508] [error] Caught Main Process Error:
[20:21:35.509] [error] Caught Main Process Error:

Raw logs from daemon log file:

2018-08-22 20:20:59.483 [INF] DISC: Broadcasting batch of 3 new announcements
2018-08-22 20:21:13.460 [INF] BTCN: Processed 1 block in the last 14.49s (height 1405977, 2018-08-22 20:20:58 -0700 PDT)
2018-08-22 20:21:13.465 [INF] BTCN: Attempting to fetch set of un-checkpointed filters at height=1405977, hash=0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20
2018-08-22 20:21:13.584 [INF] BTCN: Verified 1 filter header in the last 14.54s (height 1405977, 2018-08-22 20:20:58 -0700 PDT)
2018-08-22 20:21:13.585 [INF] NTFN: New block: height=1405977, sha=0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20
2018-08-22 20:21:13.585 [INF] UTXN: Attempting to graduate height=1405977: num_kids=0, num_babies=0
2018-08-22 20:21:13.590 [INF] CRTR: Pruning channel graph using block 0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20 (height=1405977)
2018-08-22 20:21:13.592 [INF] CRTR: Block 0000000000000180ba046ca86aa5d54cf48f1d5a9fe3ff187f5d494b3a568b20 (height=1405977) closed 0 channels
2018-08-22 20:21:29.485 [INF] DISC: Broadcasting batch of 1 new announcements
<EOF>

[tanx]

Good catch. Looks like electron doesn't wait for process.kill() to complete:

lightning-app/public/electron.js

Lines 198 to 201 in 3e21de1

	app.on('quit', () => {
	lndProcess && lndProcess.kill();
	btcdProcess && btcdProcess.kill();
	});

[cfromknecht]

If for some reason the shutdown gets blocked, do you think it’d be worth “killing and forgetting” after some timeout?

[tanx]

If for some reason the shutdown gets blocked, do you think it’d be worth “killing and forgetting” after some timeout?

That could be a solution. We just have to see which hooks electron provides here. Cmd+Q currently triggers the quit event. Perhaps there is a hook that fires before quit that is appropriate for cleanup and that makes electron wait before finally quitting.

I messed around with this a little over the weekend and there is a before-quit event in which I prevented the default and tried to kill LND safely - lndProcess.kill('SIGINT').

Unfortunately, I didn't get consistent results. Will keep trying. There's also an added issue of these events not triggering on Windows...

Just to clarify - what I tried was something along the lines:

app.on('before-quit', () => {
  if (lndProcess) {
    lndProcess.on('close', (code, signal) => {
      console.log(`
        child process terminated due to receipt of signal ${signal}
      `);
      app.quit();
    });
    lndProcess.kill('SIGINT');
    event.preventDefault();
  }
});

[tanx]

@ERKarl cool. Thanks for the insight.

I messed around with this a little over the weekend and there is a before-quit event in which I prevented the default and tried to kill LND safely - lndProcess.kill('SIGINT').

Unfortunately, I didn't get consistent results. Will keep trying. There's also an added issue of these events not triggering on Windows...

From reading the electron docs on before-quit it seems like the windows issue only applies when quitting due to system restart or user logout. I'm ok with ignoring these edge cases for now if we can get safe lnd shutdown in most cases. Plus who uses Windows anyway 😬

Just to clarify - what I tried was something along the lines:

Have you tried with calling event.preventDefault() and just waiting for a few seconds e.g. await new Promise(resolve => setTimeout(resolve, LND_INIT_DELAY)) before calling app.quit()?

[cfromknecht]

+1 on sending SIGINT instead of StopDaemon, this triggers the shutdown logic more directly since it bypasses the rpcserver 👍

[valentinewallace]

@cfromknecht sounds good, will update PR 👍