Skip to content

Commit

Permalink
plugin_log_handle: accommodate multi-line messages
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
starius committed Feb 8, 2024
1 parent fb015da commit 0f5ec37
Showing 1 changed file with 45 additions and 3 deletions.
48 changes: 45 additions & 3 deletions lightningd/plugin.c
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -501,9 +502,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;
}

Expand Down

0 comments on commit 0f5ec37

Please sign in to comment.