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.

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

Enhance plugin_log_handle to accommodate multi-line messages #7013

Open
wants to merge 2 commits into
base: master
Choose a base branch
from

Conversation

starius
Copy link

@starius starius commented Jan 25, 2024

Previously, the code utilized JSON-encoded text to pass log messages to the log_() function, resulting in new lines being printed to the log as '\n'. This commit addresses this issue by unescaping and splitting the log message into lines, with each non-empty line being logged separately.

It is deemed acceptable to pass non-printable characters to log_() since they are replaced with "?" in the logv() function, invoked by log_(). Therefore, leaving lines JSON unescaped is permissible.

It's important to note that only the last log_() call may have call_notifier set to true. This adjustment is crucial to prevent Python tracebacks complaining about a broken pipe after lightningd exits.

Fixes: #4912

Tested:

./lightningd/lightningd  
2024-02-08T20:33:17.642Z INFO    lightningd: v23.11-257-g968d6d6-modded

Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?

Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.

You can verify that your Bitcoin Core installation is ready for use by running:

    $ bitcoin-cli echo 'hello world'
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: You can verify that your Bitcoin Core installation is ready for use by running:
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli:     $ bitcoin-cli echo 'hello world'
2024-02-08T20:33:18.227Z INFO    plugin-bcli: Killing plugin: exited before we sent init
The Bitcoin backend died.

@cdecker
Copy link
Member

cdecker commented Jan 26, 2024

I'm not convinced that this is actually what we want, as it breaks a very basic assumption we make when logging: one log line == one event. This patch spreads a single log ling across many lines, potentially interleaving them, and breaking the event apart.

It also breaks the assumption that each line starts with the preamble consisting of datetime and level. This means it is not filterable as nicely after the fact.

@starius
Copy link
Author

starius commented Jan 26, 2024

It can be limited only to messages, containing BROKEN or even to the message from #4912 only, because it is likely to be the last (or the only) in the log.

@cdecker What do you think?

@ecurrencyhodler
Copy link

@cdecker WDYT of that adjustment? Or should we just close out the issue instead?

@rustyrussell
Copy link
Contributor

Yes, you cannot allow \n inside logs. However, you can split one level higher and turn them into multiple log messages, for sure!

@cdecker cdecker marked this pull request as draft February 2, 2024 09:13
@cdecker
Copy link
Member

cdecker commented Feb 2, 2024

Converted to a draft.

@starius
Copy link
Author

starius commented Feb 2, 2024

@rustyrussell Thanks for clarifying this!

I'm working on this. Please expect an update in next few days!

There are only 3 options, not 4, in the list.
Previously, the code utilized JSON-encoded text to pass log messages to the
log_() function, resulting in new lines being printed to the log as '\n'. This
commit addresses this issue by unescaping and splitting the log message into
lines, with each non-empty line being logged separately.

It is deemed acceptable to pass non-printable characters to log_() since they
are replaced with "?" in the logv() function, invoked by log_(). Therefore,
leaving lines JSON unescaped is permissible.

It's important to note that only the last log_() call may have call_notifier
set to true. This adjustment is crucial to prevent Python tracebacks complaining
about a broken pipe after lightningd exits.

Fix ElementsProject#4912

For reference, the log of lightningd failing without a backend:

./lightningd/lightningd
2024-02-08T20:33:17.642Z INFO    lightningd: v23.11-257-g968d6d6-modded

Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?

Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.

You can verify that your Bitcoin Core installation is ready for use by running:

    $ bitcoin-cli echo 'hello world'
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli: You can verify that your Bitcoin Core installation is ready for use by running:
2024-02-08T20:33:18.227Z **BROKEN** plugin-bcli:     $ bitcoin-cli echo 'hello world'
2024-02-08T20:33:18.227Z INFO    plugin-bcli: Killing plugin: exited before we sent init
The Bitcoin backend died.
@starius starius force-pushed the issue-4912 branch 2 times, most recently from 0f5ec37 to 7debaf3 Compare February 8, 2024 20:39
@starius starius changed the title logv: replace "\n" with line break in the log Enhance plugin_log_handle to accommodate multi-line messages Feb 8, 2024
@starius
Copy link
Author

starius commented Feb 8, 2024

@rustyrussell @cdecker

I changed the approach: I split the message in plugin_log_handle function to several lines and log them independently.

Please take another look!

@starius starius marked this pull request as ready for review February 8, 2024 20:43
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

plugin-bcli returning "\n" instead of line break in the logfile
4 participants