plugin_log_handle: accommodate multi-line messages

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 https://github.com/ElementsProject/lightning/issues/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.

Changelog-Changed: Plugins: log messages containing \n are now split into multiple log lines, for neatness, and " is no longer turned into \".
This commit is contained in:
Boris Nagaev
2024-02-08 21:24:53 +01:00
committed by Rusty Russell
parent 833b8d11d3
commit 23997b2e1d

View File

@@ -3,6 +3,7 @@
#include <ccan/ccan/tal/grab_file/grab_file.h>
#include <ccan/crc32c/crc32c.h>
#include <ccan/io/io.h>
#include <ccan/json_escape/json_escape.h>
#include <ccan/mem/mem.h>
#include <ccan/opt/opt.h>
#include <ccan/pipecmd/pipecmd.h>
@@ -512,9 +513,50 @@ static const char *plugin_log_handle(struct plugin *plugin,
}
call_notifier = (level == LOG_BROKEN || level == LOG_UNUSUAL)? true : false;
/* FIXME: Let plugin specify node_id? */
log_(plugin->log, level, NULL, call_notifier, "%.*s", msgtok->end - msgtok->start,
plugin->buffer + msgtok->start);
/* Unescape log message. */
tal_t *ctx = tal(NULL, char);
const char *log_escaped = plugin->buffer + msgtok->start;
const size_t log_escaped_len = msgtok->end - msgtok->start;
struct json_escape *esc = json_escape_string_(ctx, log_escaped, log_escaped_len);
const char *log_msg = json_escape_unescape(ctx, esc);
/* Find last line. */
const char *log_msg2 = log_msg;
const char *last_msg;
while (true) {
const char *msg_end = strchr(log_msg2, '\n');
if (!msg_end) {
break;
}
int msg_len = msg_end - log_msg2;
if (msg_len > 0) {
last_msg = log_msg2;
}
log_msg2 = msg_end + 1;
}
/* Split to lines and log them separately. */
while (true) {
const char *msg_end = strchr(log_msg, '\n');
if (!msg_end) {
break;
}
int msg_len = msg_end - log_msg;
if (msg_len > 0) {
/* Call notifier only for the last message to avoid Python errors. */
bool call_notifier2 = call_notifier;
if (log_msg != last_msg) {
call_notifier2 = false;
}
/* FIXME: Let plugin specify node_id? */
log_(plugin->log, level, NULL, call_notifier2, "%.*s", msg_len, log_msg);
}
log_msg = msg_end + 1;
}
tal_free(ctx);
return NULL;
}