search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.64k stars 2.07k forks source link

[bug]: Regression: Missing newline in "Shutdown complete" log message #8713

Open C-Otto opened 4 months ago

C-Otto commented 4 months ago

See https://github.com/lightningnetwork/lnd/issues/3801. This bug resurfaced with v0.17.3-beta or before:

This is the output (in lnd.log) with lncli stop (v0.17.3-beta) and then re-starting lnd (v0.18.0-beta.rc1).

2024-04-30 15:21:12.886 [INF] RPCS: Stopping SignRPC Sub-RPC Server
2024-04-30 15:21:12.899 [INF] LTND: Shutdown complete2024-04-30 15:21:19.087 [INF] LTND: REST API is disabled!
2024-04-30 15:21:19.089 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it
Chinwendu20 commented 4 months ago

I am trying to reproduce it, so I started lnd (with the norest flag) and issued the command, lncli --stop.

image

Chinwendu20 commented 4 months ago

Seems like there is a new line there already? https://github.com/lightningnetwork/lnd/blob/ab83343c8718e292c8e392949318678e93df3e56/lnd.go#L142

C-Otto commented 4 months ago

It's in the code and, if I understand the logging library correctly, that's not even necessary. However, I've seen the bug manifest itself several times, but not everytime I stop lnd.

MPins commented 4 months ago

I did reproduce the problem. Actually I tested from the version v0.17.2-beta to 0.18.0-beta.rc1. The only version that we have missing newline in "Shutdown complete" is the v0.17.3-beta, curiously since v.0.17.4-beta we have a blank line after "Shutdown complete". See the logs below.

Version: 0.17.2-beta ------------------------------------------------------------------------------------------------------------------------

2024-05-04 00:37:37.207 [INF] LTND: Shutting down... 2024-05-04 00:37:37.207 [INF] LTND: Gracefully shutting down. 2024-05-04 00:37:38.177 [INF] RPCS: Stopping RPC Server 2024-05-04 00:37:38.177 [INF] RPCS: Stopping RouterRPC Sub-RPC Server 2024-05-04 00:37:38.177 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server 2024-05-04 00:37:38.177 [INF] RPCS: Stopping NeutrinoKitRPC Sub-RPC Server 2024-05-04 00:37:38.177 [INF] RPCS: Stopping SignRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping VersionRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping ChainRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] RPCS: Stopping PeersRPC Sub-RPC Server 2024-05-04 00:37:38.178 [INF] LNWL: Stopped waiting for wallet sync due to error: wallet shutting down 2024-05-04 00:37:38.178 [INF] BTCN: Canceling block subscription: id=1 2024-05-04 00:37:38.228 [INF] BTCN: Block manager shutting down 2024-05-04 00:37:38.229 [INF] BTCN: Address manager shutting down 2024-05-04 00:37:38.231 [INF] LTND: Shutdown complete 2024-05-04 00:38:05.554 [WRN] LTND: open /root/.lnd/lnd.conf: no such file or directory 2024-05-04 00:38:05.554 [INF] LTND: Version: 0.17.2-beta commit=v0.17.2-beta, build=production, logging=default, debuglevel=info

Version: 0.17.3-beta ----------------------------------------------------------------------------------------------------------------------

2024-05-03 21:25:24.666 [INF] LTND: Shutting down... 2024-05-03 21:25:24.666 [INF] LTND: Gracefully shutting down. 2024-05-03 21:25:25.012 [INF] RPCS: Stopping RPC Server 2024-05-03 21:25:25.012 [INF] RPCS: Stopping NeutrinoKitRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping VersionRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping ChainRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping SignRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server 2024-05-03 21:25:25.013 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server 2024-05-03 21:25:25.014 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server 2024-05-03 21:25:25.014 [INF] RPCS: Stopping RouterRPC Sub-RPC Server 2024-05-03 21:25:25.014 [INF] RPCS: Stopping PeersRPC Sub-RPC Server 2024-05-03 21:25:25.014 [INF] LNWL: Stopped waiting for wallet sync due to error: wallet shutting down 2024-05-03 21:25:25.014 [INF] BTCN: Canceling block subscription: id=1 2024-05-03 21:25:25.064 [INF] BTCN: Block manager shutting down 2024-05-03 21:25:25.064 [INF] BTCN: Address manager shutting down 2024-05-03 21:25:25.066 [INF] LTND: Shutdown complete2024-05-03 21:25:37.426 [WRN] LTND: open /root/.lnd/lnd.conf: no such file or directory 2024-05-03 21:25:37.426 [INF] LTND: Version: 0.17.3-beta commit=v0.17.3-beta, build=production, logging=default, debuglevel=info

Version: v0.17.4-beta -----------------------------------------------------------------------------------------------------------------------

2024-05-03 21:17:23.715 [INF] LTND: Shutting down... 2024-05-03 21:17:23.715 [INF] LTND: Gracefully shutting down. 2024-05-03 21:17:24.377 [INF] RPCS: Stopping RPC Server 2024-05-03 21:17:24.377 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server 2024-05-03 21:17:24.377 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping RouterRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping ChainRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping NeutrinoKitRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping VersionRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping SignRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping PeersRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server 2024-05-03 21:17:24.378 [INF] LNWL: Stopped waiting for wallet sync due to error: wallet shutting down 2024-05-03 21:17:24.379 [INF] BTCN: Canceling block subscription: id=1 2024-05-03 21:17:24.429 [INF] BTCN: Block manager shutting down 2024-05-03 21:17:24.429 [INF] BTCN: Address manager shutting down 2024-05-03 21:17:24.431 [INF] LTND: Shutdown complete

2024-05-03 21:17:45.492 [WRN] LTND: open /root/.lnd/lnd.conf: no such file or directory 2024-05-03 21:17:45.492 [INF] LTND: Version: 0.17.4-beta commit=v0.17.4-beta, build=production, logging=default, debuglevel=info

Version: 0.17.5-beta ------------------------------------------------------------------------------------------------------------------------

2024-05-04 00:50:37.076 [INF] LTND: Shutting down... 2024-05-04 00:50:37.076 [INF] LTND: Gracefully shutting down. 2024-05-04 00:50:37.942 [INF] RPCS: Stopping RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping PeersRPC Sub-RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping SignRPC Sub-RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping VersionRPC Sub-RPC Server 2024-05-04 00:50:37.942 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] RPCS: Stopping RouterRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] RPCS: Stopping ChainRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] RPCS: Stopping NeutrinoKitRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server 2024-05-04 00:50:37.943 [INF] LNWL: Stopped waiting for wallet sync due to error: wallet shutting down 2024-05-04 00:50:37.943 [INF] BTCN: Canceling block subscription: id=1 2024-05-04 00:50:37.994 [INF] BTCN: Block manager shutting down 2024-05-04 00:50:37.994 [INF] BTCN: Address manager shutting down 2024-05-04 00:50:37.997 [INF] LTND: Shutdown complete

2024-05-04 00:50:44.836 [WRN] LTND: open /root/.lnd/lnd.conf: no such file or directory 2024-05-04 00:50:44.836 [INF] LTND: Version: 0.17.5-beta commit=v0.17.5-beta, build=production, logging=default, debuglevel=info

Version: 0.18.0-beta.rc1 ----------------------------------------------------------------------------------------------------------------------

2024-05-04 00:43:17.174 [INF] LTND: Shutting down... 2024-05-04 00:43:17.174 [INF] LTND: Gracefully shutting down. 2024-05-04 00:43:17.471 [INF] RPCS: Stopping RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping NeutrinoKitRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping VersionRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping RouterRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping PeersRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping ChainRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping SignRPC Sub-RPC Server 2024-05-04 00:43:17.471 [INF] RPCS: Stopping WalletKitRPC Sub-RPC Server 2024-05-04 00:43:17.472 [INF] RPCS: Stopping WatchtowerRPC Sub-RPC Server 2024-05-04 00:43:17.472 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server 2024-05-04 00:43:17.472 [INF] RPCS: Stopping InvoicesRPC Sub-RPC Server 2024-05-04 00:43:17.472 [INF] RPCS: Stopping WatchtowerClientRPC Sub-RPC Server 2024-05-04 00:43:17.472 [INF] LNWL: Stopped waiting for wallet sync due to error: wallet shutting down 2024-05-04 00:43:17.472 [INF] BTCN: Canceling block subscription: id=1 2024-05-04 00:43:17.522 [INF] BTCN: Block manager shutting down 2024-05-04 00:43:17.522 [INF] BTCN: Address manager shutting down 2024-05-04 00:43:17.524 [INF] LTND: Shutdown complete

2024-05-04 00:43:26.850 [WRN] LTND: open /root/.lnd/lnd.conf: no such file or directory 2024-05-04 00:43:26.851 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-04 00:43:26.851 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1-16-g399ea864d, build=production, logging=default, debuglevel=info

saubyk commented 4 months ago

So, this seems to be a non-issue in the releases after 17.3 Closing this issue now.

C-Otto commented 4 months ago

@saubyk Please reopen, I just reproduced the issue with v0.18.0-beta.rc1. Let me know what kind of information you need to debug this.

2024-04-30 15:21:19.089 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1, build=production, logging=default, debuglevel=info
[...]
2024-05-04 10:45:58.138 [INF] RPCS: Stopping AutopilotRPC Sub-RPC Server
2024-05-04 10:45:58.158 [INF] LTND: Shutdown complete2024-05-04 10:45:58.377 [INF] LTND: REST API is disabled!
2024-05-04 10:45:58.378 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1, build=production, logging=default, debuglevel=info
2024-05-04 10:45:58.378 [INF] LTND: Active chain: Bitcoin (network=mainnet)

I'm starting/stopping/restarting lnd via systemd:

Type=simple
PIDFile=/home/bitcoin/.lnd/lnd.pid
ExecStart=/home/bitcoin/bin/lnd
C-Otto commented 4 months ago

If I use lncli stop with systemd, I do not reliably get the "Shutdown complete" message:

2024-05-04 11:00:11.268 [INF] LTND: Received terminated
2024-05-04 11:00:11.268 [INF] LTND: Shutting down...
2024-05-04 11:00:11.268 [INF] LTND: Gracefully shutting down.
2024-05-04 11:01:11.715 [INF] LTND: REST API is disabled!
2024-05-04 11:01:11.717 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1, build=production, logging=default, debuglevel=info
2024-05-04 11:01:11.717 [INF] LTND: Active chain: Bitcoin (network=mainnet)
Chinwendu20 commented 4 months ago

How are you viewing the logs if you are using systemd. Is it through lnd.log file located in the lnd's data directory? Or journalctl -u ?

Can you check both and see if the logs appear the same way?

I am assuming your lnd is built to output logs in the file and stdout. Also that journalctl outputs the logs from stdout.

C-Otto commented 4 months ago

I'm using log files (lnd.log) only, no journalctl/syslog.

In my lnd.service: StandardOutput=null

MPins commented 4 months ago

I did the tests on previous comment using docker images and command "lncli stop" and the problem occurred only on version: 0.17.3-beta. I reproduced using "systemctl start lnd" and "systemctl stop lnd", them the bug exist since 0.17.3-beta until the current version.

See the logs below:

v0.17.2-beta (there is no problem) ---------------------------------------------------------------------------------------------------------------- 2024-05-17 16:15:15.807 [INF] LTND: Version: 0.17.2-beta commit=v0.17.2-beta, build=development, logging=default, debuglevel=info . . . 2024-05-17 16:16:17.234 [INF] LTND: Shutdown complete 2024-05-17 16:16:34.352 [INF] LTND: Version: 0.17.2-beta commit=v0.17.2-beta, build=development, logging=default, debuglevel=info

v0.17.3-beta ----------------------------------------------------------------------------------------------------------------------------------------------------- 2024-05-17 16:10:36.927 [INF] LTND: Version: 0.17.3-beta commit=v0.17.3-beta, build=development, logging=default, debuglevel=info . . . 2024-05-17 16:11:15.103 [INF] LTND: Shutdown complete2024-05-17 16:11:27.950 [INF] LTND: Version: 0.17.3-beta commit=v0.17.3-beta, build=development, logging=default, debuglevel=info 2024-05-17 16:11:27.951 [INF] LTND: Active chain: Bitcoin (network=testnet)

v0.17.4-beta ------------------------------------------------------------------------------------------------------------------------------------------------ 2024-05-17 16:01:36.186 [INF] LTND: Version: 0.17.4-beta commit=v0.17.4-beta, build=development, logging=default, debuglevel=info . . . 2024-05-17 16:02:26.142 [INF] LTND: Shutdown complete2024-05-17 16:02:42.429 [INF] LTND: Version: 0.17.4-beta commit=v0.17.4-beta, build=development, logging=default, debuglevel=info 2024-05-17 16:02:42.429 [INF] LTND: Active chain: Bitcoin (network=testnet)

v0.17.5-beta ------------------------------------------------------------------------------------------------------------------------------------------------- 2024-05-17 15:25:50.340 [INF] LTND: Version: 0.17.5-beta commit=v0.17.5-beta, build=development, logging=default, debuglevel=info . . . 2024-05-17 15:26:52.106 [INF] LTND: Shutdown complete2024-05-17 15:27:33.092 [INF] LTND: Version: 0.17.5-beta commit=v0.17.5-beta, build=development, logging=default, debuglevel=info 2024-05-17 15:27:33.092 [INF] LTND: Active chain: Bitcoin (network=testnet)

v0.18.0-beta.rc1 ------------------------------------------------------------------------------------------------------------------------------------------- 2024-05-15 20:38:07.950 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-15 20:38:07.950 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1-dirty, build=development, logging=default, debuglevel=info . . . 2024-05-15 20:39:13.205 [INF] LTND: Shutdown complete2024-05-15 20:39:36.520 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-15 20:39:36.521 [INF] LTND: Version: 0.18.0-beta.rc1 commit=v0.18.0-beta.rc1-dirty, build=development, logging=default, debuglevel=info

MPins commented 4 months ago

Original Flaw

2024-05-20 14:04:17.705 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-20 14:04:17.705 [INF] LTND: Version: 0.18.0-beta.rc2 commit=v0.18.0-beta.rc1-48-g2a8ca878f, build=development, logging=default, debuglevel=info . . . 2024-05-20 14:05:01.948 [INF] LTND: Shutdown complete2024-05-20 14:05:19.906 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-20 14:05:19.907 [INF] LTND: Version: 0.18.0-beta.rc2 commit=v0.18.0-beta.rc1-48-g2a8ca878f, build=development, logging=default, debuglevel=info

Test after PR#8770

2024-05-20 15:59:47.298 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-20 15:59:47.298 [INF] LTND: Version: 0.18.0-beta.rc2 commit=v0.18.0-beta.rc1-48-g2a8ca878f-dirty, build=development, logging=default, debuglevel=info . . . 2024-05-20 16:00:29.366 [INF] LTND: Shutdown complete 2024-05-20 16:00:29.366 [INF] LTND:
2024-05-20 16:00:47.594 [WRN] LTND: Config 'bitcoin.active' is deprecated, please remove it 2024-05-20 16:00:47.594 [INF] LTND: Version: 0.18.0-beta.rc2 commit=v0.18.0-beta.rc1-48-g2a8ca878f-dirty, build=development, logging=default, debuglevel=info

MPins commented 3 months ago

Hello @C-Otto ... this [PR] (https://github.com/lightningnetwork/lnd/pull/8770) "fixed" the missing newline. Actually it is a turnaround as the "\n" is not working properly in some situations!

C-Otto commented 3 months ago

Meaning?

MPins commented 3 months ago

Meaning?

As you opened the issue ... I thought that you might send your opinion on this tiny PR.

C-Otto commented 3 months ago

It doesn't look like a fix to me (I don't see a regression test, and I don't see the original flaw). But if it works, that's great!

MPins commented 3 months ago

It doesn't look like a fix to me (I don't see a regression test, and I don't see the original flaw). But if it works, that's great!

I just included the original flaw and the test showing that it is fixed after the PR#8770. You can see it on the first message of the PR.

Thanks.

C-Otto commented 3 months ago

I understood how the resulting log lines look like, but I still don't understand why the original code is wrong. I prefer understanding the consequences of changing code, which isn't the case here. As said, if it works, that's great.

MPins commented 3 months ago

I got it and agree with you. From my research there is no wrong code on LND, that’s why I did a workaround.

ellemouton commented 2 weeks ago

@MPins, would you mind testing to see if this issue is still present with https://github.com/lightningnetwork/lnd/pull/9083?

MPins commented 2 weeks ago

@MPins, would you mind testing to see if this issue is still present with #9083?

Sure ... I will do it tonight.

MPins commented 2 weeks ago

@ellemouton I did the test with the master branch and the issue persists as you can see below:

2024-09-10 19:57:51.099 [INF] LTND: Version: 0.18.0-beta commit=fn/v1.2.1-44-gcc9e2b783, build=development, logging=default, debuglevel=debug
.
.
.
2024-09-10 19:58:16.744 [INF] LTND: Shutdown complete2024-09-10 19:58:24.964 [INF] LTND: Version: 0.18.0-beta commit=fn/v1.2.1-44-gcc9e2b783, build=development, logging=default, debuglevel=debug
.
.
.
2024-09-10 19:58:47.655 [INF] LTND: Shutdown complete

Then I did the test and the issue is not present with https://github.com/lightningnetwork/lnd/pull/9083 as you can see below:

2024-09-10 19:45:45.341 [INF] LTND: Version: 0.18.0-beta commit=sqldb/v1.0.4-50-g9ca6dacb6, build=development, logging=default, debuglevel=debug
.
.
.
2024-09-10 19:47:03.174 [INF] LTND: Shutdown complete

2024-09-10 19:47:26.365 [INF] LTND: Version: 0.18.0-beta commit=sqldb/v1.0.4-50-g9ca6dacb6, build=development, logging=default, debuglevel=debug
.
.
.
2024-09-10 19:47:54.106 [INF] LTND: Shutdown complete
ellemouton commented 2 weeks ago

@MPins - awesome!!! thanks for testing 🎉