From 0f5ec37bb3ba37af92e531ebedf921bfd1e2feca Mon Sep 17 00:00:00 2001
From: Boris Nagaev <bnagaev@gmail.com>
Date: Thu, 8 Feb 2024 21:24:53 +0100
Subject: [PATCH] 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.
---
 lightningd/plugin.c | 48 ++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 45 insertions(+), 3 deletions(-)

diff --git a/lightningd/plugin.c b/lightningd/plugin.c
index 8ee9a1a103f4..bda2b6da2028 100644
--- a/lightningd/plugin.c
+++ b/lightningd/plugin.c
@@ -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>
@@ -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;
 }