Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
C-Otto opened this issue Apr 30, 2024 · 11 comments · May be fixed by #8770
Open

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

C-Otto opened this issue Apr 30, 2024 · 11 comments · May be fixed by #8770
Labels
beginner Issues suitable for new developers bug Unintended code behaviour good first issue Issues suitable for first time contributors to LND logging Related to the logging / debug output functionality missing reproduction P4 low prio
Milestone
v0.18.1

Comments

@C-Otto
Copy link
Contributor

C-Otto commented Apr 30, 2024 •
edited

See #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
@C-Otto C-Otto added bug Unintended code behaviour needs triage labels Apr 30, 2024
@saubyk saubyk added good first issue Issues suitable for first time contributors to LND beginner Issues suitable for new developers logging Related to the logging / debug output functionality P3 might get fixed, nice to have and removed needs triage labels Apr 30, 2024
@Chinwendu20
Copy link
Contributor

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

image

@Chinwendu20
Copy link
Contributor

Seems like there is a new line there already?

lnd/lnd.go

Line 142 in ab83343

ltndLog.Info("Shutdown complete\n")

@C-Otto
Copy link
Contributor Author

C-Otto commented Apr 30, 2024

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
Copy link

MPins commented May 4, 2024

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
Copy link
Collaborator

saubyk commented May 4, 2024

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

@saubyk saubyk closed this as completed May 4, 2024
@C-Otto
Copy link
Contributor Author

C-Otto commented May 4, 2024 •
edited

@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
Copy link
Contributor Author

C-Otto commented May 4, 2024

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
Copy link
Contributor

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
Copy link
Contributor Author

C-Otto commented May 4, 2024 •
edited

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

In my lnd.service: StandardOutput=null

@saubyk saubyk reopened this May 4, 2024
@saubyk saubyk added P4 low prio and removed P3 might get fixed, nice to have labels May 5, 2024
@MPins
Copy link

MPins commented May 17, 2024

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 MPins linked a pull request May 20, 2024 that will close this issue
Open
8 tasks
@MPins
Copy link

MPins commented May 20, 2024

The log of last test before the PR

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

The log of test after the PR changes

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

@saubyk saubyk added this to the v0.18.1 milestone May 21, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
beginner Issues suitable for new developers bug Unintended code behaviour good first issue Issues suitable for first time contributors to LND logging Related to the logging / debug output functionality missing reproduction P4 low prio
Projects
None yet
Milestone
v0.18.1
Development

Successfully merging a pull request may close this issue.

Fixing newline on "Shutdown complete" log message modified: lnd.go MPins/lnd
4 participants
@C-Otto @saubyk @Chinwendu20 @MPins