lightningd/log: Improve logging to handle multi-line messages #7944

NishantBansal2003 · 2024-12-16T15:46:37Z

Changelog-Added: Improved logging format in lightningd/log to handle multi-line messages by unescaping '\n' and logging each line separately.

Important

24.11 FREEZE NOVEMBER 7TH: Non-bugfix PRs not ready by this date will wait for 25.02.

Fixes: #4912

Log-Output:

2024-12-16T16:19:09.470Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic                                             ─╯
2024-12-16T16:19:09.471Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic

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 -rpcclienttimeout=60 echo 'hello world'
2024-12-16T16:19:11.635Z **BROKEN** plugin-bcli: Could not connect to bitcoind using bitcoin-cli. Is bitcoind running?
2024-12-16T16:19:11.635Z **BROKEN** plugin-bcli: Make sure you have bitcoind running and that bitcoin-cli is able to connect to bitcoind.
2024-12-16T16:19:11.635Z **BROKEN** plugin-bcli: You can verify that your Bitcoin Core installation is ready for use by running:
2024-12-16T16:19:11.635Z **BROKEN** plugin-bcli:     $ bitcoin-cli -rpcclienttimeout=60 echo 'hello world'
2024-12-16T16:19:11.635Z INFO    plugin-bcli: Killing plugin: exited before we sent init
The Bitcoin backend died.

Checklist

Before submitting the PR, ensure the following tasks are completed. If an item is not applicable to your PR, please mark it as checked:

The changelog has been updated in the relevant commit(s) according to the guidelines.
Tests have been added or modified to reflect the changes.
Documentation has been reviewed and updated as needed.
Related issues have been listed and linked, including any that this PR closes.

rustyrussell

Nice work!

lightningd/log.c

NishantBansal2003 · 2024-12-17T11:43:12Z

Hey @rustyrussell , I made some modifications based on your feedback. Could you please check if everything is covered, or if I need to check anything further?

NishantBansal2003 · 2024-12-17T17:05:21Z

Hey @rustyrussell, I tried debugging this memory leak issue in CI but couldn't understand the root cause. Could you point me to some documentation that explains how Core Lightning handles memory leaks? Thanks!

rustyrussell

Looking much better!

rustyrussell · 2024-12-19T01:05:30Z

lightningd/log.c

+		struct log_entry *l = new_log_entry(log, level, node_id);

-	/* Split to lines and log them separately. */
-	for (size_t j = 0; lines[j]; j++) {
-		l->log = tal_strdup(log, lines[j]);
+		l->log = strdup(log_msg);
+		size_t log_len = strlen(l->log);

 		/* Sanitize any non-printable characters, and replace with '?'
 		 */
-		size_t line_len = strlen(l->log);
-		for (size_t i = 0; i < line_len; i++)
+		for (size_t i = 0; i < log_len; i++)
 			if (l->log[i] < ' ' || l->log[i] >= 0x7f)
 				l->log[i] = '?';

 		maybe_print(log, l);
 		maybe_notify_log(log, l);

 		add_entry(log, &l);
-	}

-	if (call_notifier)


Extract this common code into a new function, rather than calling twice. Say "add_one_log_entry(log, level, nodeid, string)", which does new_log_entry, strdup, sanitize, maybe_print, maybe_notify_log, add_entry.

Then you can make the code a bit more optimal, and avoid json_escape if there are no escapes:

/* Nothing to escape: simple copy */ if (!strchr(log_msg, '\\')) add_one_log_entry(log, level, nodeid, log_msg); /* If it's weird, unescaping can fail */ else if ((unescaped_log = json_escape_unescape(tmpctx, (struct json_escape *)log_msg)) == NULL) add_one_log_entry(log, level, nodeid, log_msg); else { char **lines = tal_strsplit(unescaped_log, unescaped_log, "\n", STR_EMPTY_OK); /* Split to lines and log them separately. */ for (size_t i = 0; lines[i]; i++) add_one_log_entry(log, level, nodeid, lines[i]); }

rustyrussell · 2024-12-19T01:07:19Z

lightningd/log.c

-	    log, json_escape_unescape(log, (struct json_escape *)log_msg), "\n",
-	    STR_NO_EMPTY);
+	const char *unescaped_log =
+	    json_escape_unescape(NULL, (struct json_escape *)log_msg);


This is the cause of your leak, BTW. Every tal allocation is off some other tal allocation (or NULL). There's a special throwaway one called tmpctx which automagically gets cleaned in the event loop. Since you used NULL here, and don't free it, it gets caught as a leak by our leak detection code (and it is!).

rustyrussell · 2024-12-19T01:07:54Z

lightningd/log.c

 	char *log_msg = NULL;

 	/* This is WARN_UNUSED_RESULT, because everyone should somehow deal
 	 * with OOM, even though nobody does. */
 	if (vasprintf(&log_msg, fmt, ap) == -1)
 		abort();

-	char **lines = tal_strsplit(
-	    log, json_escape_unescape(log, (struct json_escape *)log_msg), "\n",
-	    STR_NO_EMPTY);


STR_EMPTY_OK, since you want to log empty lines too I think?

Now the output will look something like:

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

I think that's right, TBH?

NishantBansal2003 · 2024-12-19T07:02:20Z

Hey @rustyrussell, thank you for helping me out with this PR—it means a lot to me. I learned something new while working on this.

One more thing: could you please let me know what configuration/tool the core-lightning codebase uses to format its C code? I noticed a lot of formatting changes happening on save.

rustyrussell

This is looking really good now. Since you're a new contributor I've really nit-picked it, so there are two more trivial changes.

Also, squish it into a single commit please, so I can apply it!

rustyrussell · 2024-12-20T03:32:00Z

lightningd/log.c

@@ -558,70 +558,60 @@ static void maybe_notify_log(struct logger *log,
 		notify_log(log->log_book->ld, l);
 }

+static void add_one_log_entry(struct logger *log, enum log_level level,
+			      const struct node_id *node_id, bool call_notifier,
+			      char *log_msg)


const char * - we always use const when we can (it's a C bug that it's not the default!)

rustyrussell · 2024-12-20T03:32:38Z

lightningd/log.c

+	size_t log_len = strlen(l->log);
+
+	/* Sanitize any non-printable characters, and replace with '?'
+	 */
+	for (size_t i = 0; i < log_len; i++)


Drop log_len, use log_msg[i] != '\0'?

rustyrussell · 2024-12-20T03:37:06Z

Hey @rustyrussell, thank you for helping me out with this PR—it means a lot to me. I learned something new while working on this.

One more thing: could you please let me know what configuration/tool the core-lightning codebase uses to format its C code? I noticed a lot of formatting changes happening on save.

I use emacs, so that just does it all for me :(

Changelog-Added: Improved logging format in `lightningd/log` to handle multi-line messages by unescaping '\n' and logging each line separately. Signed-off-by: Nishant Bansal <nishant.bansal.282003@gmail.com> lightningd/log: Improve log handling Changelog-Added: Improved log handling to save memory. Signed-off-by: Nishant Bansal <nishant.bansal.282003@gmail.com> lightningd/log: Refactor code for logging Changelog-Added: Refactored code for log handling. Signed-off-by: Nishant Bansal <nishant.bansal.282003@gmail.com>

NishantBansal2003 force-pushed the plugin-log branch from 70e99c1 to 62ed812 Compare December 16, 2024 16:12

rustyrussell approved these changes Dec 16, 2024

View reviewed changes

lightningd/log.c Outdated Show resolved Hide resolved

rustyrussell requested changes Dec 16, 2024

View reviewed changes

lightningd/log.c Outdated Show resolved Hide resolved

NishantBansal2003 requested a review from rustyrussell December 17, 2024 11:43

NishantBansal2003 force-pushed the plugin-log branch from c83501c to df4f617 Compare December 18, 2024 19:26

rustyrussell requested changes Dec 19, 2024

View reviewed changes

NishantBansal2003 requested a review from rustyrussell December 19, 2024 07:02

rustyrussell approved these changes Dec 20, 2024

View reviewed changes

NishantBansal2003 force-pushed the plugin-log branch from 499365f to abf30f5 Compare December 20, 2024 06:03

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

lightningd/log: Improve logging to handle multi-line messages #7944

lightningd/log: Improve logging to handle multi-line messages #7944

NishantBansal2003 commented Dec 16, 2024 •

edited

Loading

rustyrussell left a comment

NishantBansal2003 commented Dec 17, 2024

NishantBansal2003 commented Dec 17, 2024

rustyrussell left a comment

rustyrussell Dec 19, 2024

rustyrussell Dec 19, 2024

rustyrussell Dec 19, 2024

NishantBansal2003 Dec 19, 2024

rustyrussell Dec 20, 2024

NishantBansal2003 commented Dec 19, 2024 •

edited

Loading

rustyrussell left a comment

rustyrussell Dec 20, 2024

rustyrussell Dec 20, 2024

rustyrussell commented Dec 20, 2024

lightningd/log: Improve logging to handle multi-line messages #7944

Are you sure you want to change the base?

lightningd/log: Improve logging to handle multi-line messages #7944

Conversation

NishantBansal2003 commented Dec 16, 2024 • edited Loading

Checklist

rustyrussell left a comment

Choose a reason for hiding this comment

NishantBansal2003 commented Dec 17, 2024

NishantBansal2003 commented Dec 17, 2024

rustyrussell left a comment

Choose a reason for hiding this comment

rustyrussell Dec 19, 2024

Choose a reason for hiding this comment

rustyrussell Dec 19, 2024

Choose a reason for hiding this comment

rustyrussell Dec 19, 2024

Choose a reason for hiding this comment

NishantBansal2003 Dec 19, 2024

Choose a reason for hiding this comment

rustyrussell Dec 20, 2024

Choose a reason for hiding this comment

NishantBansal2003 commented Dec 19, 2024 • edited Loading

rustyrussell left a comment

Choose a reason for hiding this comment

rustyrussell Dec 20, 2024

Choose a reason for hiding this comment

rustyrussell Dec 20, 2024

Choose a reason for hiding this comment

rustyrussell commented Dec 20, 2024

NishantBansal2003 commented Dec 16, 2024 •

edited

Loading

NishantBansal2003 commented Dec 19, 2024 •

edited

Loading