From 4ed37405521ecf99a0011620b30d67165c47a574 Mon Sep 17 00:00:00 2001 From: Matt Whitlock Date: Sun, 19 Jul 2026 02:35:26 -0400 Subject: [PATCH 1/6] lightningd: don't crash when truncating large log messages It's not okay to call free() on the pointer to a truncated log message that was allocated by tal_fmt() in cap_header(). Let's call tal_free() instead, and rather than calling vasprintf() to malloc the log message in the first place, let's call tal_vfmt(). Also, since we're now always using a tallocated string for the log message, let's have cap_header() take ownership of it and either free it if it truncated the message (and is returning a different pointer to the truncated message) or else return the taken original pointer without freeing it. Also, log_io()'s str and data parameters are marked TAKES, but the function was not actually taking them, so fix that up too. Also, don't call strlen() on a string returned by tal_fmt(). The returned pointer is guaranteed to have tal_count() == strlen() + 1, so there's no sense in scanning through the string to find its length. Changelog-None --- lightningd/log.c | 33 +++++++++++++++++++-------------- 1 file changed, 19 insertions(+), 14 deletions(-) diff --git a/lightningd/log.c b/lightningd/log.c index a3a2b8384327..554c34c9cdd2 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -264,20 +264,23 @@ static void del_front_log(struct log_book *log) } /* We truncate genuinely giant messages */ -static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg) +static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg TAKES) { const size_t max = sizeof(((struct log_book *)0)->ringbuf) / 64; + const char *origmsg = msg; if (hdr->msglen > max) { msg = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", hdr->msglen, (int)max, msg); - hdr->msglen = strlen(msg); + hdr->msglen = tal_count(msg) - 1; } if (hdr->iolen > max) { msg = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s", hdr->iolen, (int)hdr->msglen, msg); - hdr->msglen = strlen(msg); + hdr->msglen = tal_count(msg) - 1; hdr->iolen = max; } + if (taken(origmsg) && msg != origmsg) + tal_free(origmsg); return cast_const(char *, msg); } @@ -660,12 +663,8 @@ void logv(struct logger *log, enum log_level level, size_t log_len; char *logmsg; - /* This is WARN_UNUSED_RESULT, because everyone should somehow deal - * with OOM, even though nobody does. */ - if (vasprintf(&logmsg, fmt, ap) == -1) - abort(); - - log_len = strlen(logmsg); + logmsg = tal_vfmt(tmpctx, fmt, ap); + log_len = tal_count(logmsg) - 1; /* Sanitize any non-printable characters, and replace with '?' */ for (size_t i=0; ilog_book, &l, logmsg, NULL); if (call_notifier) @@ -685,8 +684,8 @@ void logv(struct logger *log, enum log_level level, l.time, l.prefix->prefix, logmsg); - free(logmsg); + tal_free(logmsg); errno = save_errno; } @@ -700,20 +699,26 @@ void log_io(struct logger *log, enum log_level dir, assert(dir == LOG_IO_IN || dir == LOG_IO_OUT); - init_log_hdr(log, &l, dir, node_id, strlen(str), len); + size_t str_len = strlen(str); + init_log_hdr(log, &l, dir, node_id, str_len, len); if (l.level >= log->print_level) log_to_files(log->log_book->prefix, log->prefix->prefix, l.level, l.nc ? &l.nc->node_id : NULL, log->need_refiltering ? &log->log_book->print_filters : NULL, - &l.time, str, strlen(str), + &l.time, str, str_len, data, len, log->log_book->print_timestamps, log->log_book->default_print_level, log->log_book->log_files); - str = cap_header(tmpctx, &l, str); + bool str_taken = is_taken(str); + str = cap_header(tmpctx, &l, str/*TAKES*/); add_entry(log->log_book, &l, str, data); + if (str_taken) + tal_free(str); + if (taken(data)) + tal_free(data); errno = save_errno; } From f3a9f3853d11c29cf8d12dfc20be7c70884575f1 Mon Sep 17 00:00:00 2001 From: Matt Whitlock Date: Tue, 21 Jul 2026 16:23:22 -0400 Subject: [PATCH 2/6] alternative take logic This relies on it being okay to return a pointer that is take(). --- lightningd/log.c | 27 ++++++++++++++++++--------- 1 file changed, 18 insertions(+), 9 deletions(-) diff --git a/lightningd/log.c b/lightningd/log.c index 554c34c9cdd2..dbfe97eb2c51 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -267,20 +267,29 @@ static void del_front_log(struct log_book *log) static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg TAKES) { const size_t max = sizeof(((struct log_book *)0)->ringbuf) / 64; - const char *origmsg = msg; if (hdr->msglen > max) { - msg = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", + char *new; + new = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", hdr->msglen, (int)max, msg); + if (taken(msg)) { + tal_free(msg); + take(new); + } + msg = new; hdr->msglen = tal_count(msg) - 1; } if (hdr->iolen > max) { - msg = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s", + char *new; + new = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s", hdr->iolen, (int)hdr->msglen, msg); + if (taken(msg)) { + tal_free(msg); + take(new); + } + msg = new; hdr->msglen = tal_count(msg) - 1; hdr->iolen = max; } - if (taken(origmsg) && msg != origmsg) - tal_free(origmsg); return cast_const(char *, msg); } @@ -685,7 +694,8 @@ void logv(struct logger *log, enum log_level level, l.prefix->prefix, logmsg); - tal_free(logmsg); + if (taken(logmsg)) + tal_free(logmsg); errno = save_errno; } @@ -712,10 +722,9 @@ void log_io(struct logger *log, enum log_level dir, log->log_book->default_print_level, log->log_book->log_files); - bool str_taken = is_taken(str); - str = cap_header(tmpctx, &l, str/*TAKES*/); + str = cap_header(tmpctx, &l, str); add_entry(log->log_book, &l, str, data); - if (str_taken) + if (taken(str)) tal_free(str); if (taken(data)) tal_free(data); From 30f80d20ac6e3ed29004b56102a1a7a77b560d2b Mon Sep 17 00:00:00 2001 From: Matt Whitlock Date: Tue, 21 Jul 2026 16:30:34 -0400 Subject: [PATCH 3/6] take(new), take two --- lightningd/log.c | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/lightningd/log.c b/lightningd/log.c index dbfe97eb2c51..a6c667072f8a 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -271,22 +271,18 @@ static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg T char *new; new = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", hdr->msglen, (int)max, msg); - if (taken(msg)) { + if (taken(msg)) tal_free(msg); - take(new); - } - msg = new; + msg = take(new); hdr->msglen = tal_count(msg) - 1; } if (hdr->iolen > max) { char *new; new = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s", hdr->iolen, (int)hdr->msglen, msg); - if (taken(msg)) { + if (taken(msg)) tal_free(msg); - take(new); - } - msg = new; + msg = take(new); hdr->msglen = tal_count(msg) - 1; hdr->iolen = max; } From 6a5aee9a12f46481f1b6328ed5ba88a7566d1436 Mon Sep 17 00:00:00 2001 From: Lagrang3 Date: Mon, 15 Jun 2026 09:21:46 +0100 Subject: [PATCH 4/6] lightningd: test for very long log entries Changelog-None Signed-off-by: Lagrang3 --- tests/test_misc.py | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/tests/test_misc.py b/tests/test_misc.py index bbfbd80c384f..0aeaf21ec649 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -5143,3 +5143,19 @@ def test_filter_with_invalid_json(node_factory): stdout=subprocess.PIPE) assert 'filter: Expected object: invalid token' in out.stdout.decode('utf-8') assert out.returncode == 1 + + +@pytest.mark.xfail(strict=True) +def test_long_logs(node_factory): + """A plugin that creates a very long log entry. Lightningd should truncate + the output and not crash.""" + + def setup(plugin): + @plugin.method("produce-log") + def prod_log(plugin): + """Produce a silly and very long log message.""" + plugin.log("X" * 300000) + return {} + + l1 = node_factory.get_node(inline_plugin=setup) + l1.rpc.call("produce-log") From 772d0afab6faba192237a87b0100f81ac37d3381 Mon Sep 17 00:00:00 2001 From: Lagrang3 Date: Mon, 15 Jun 2026 09:52:24 +0100 Subject: [PATCH 5/6] squash! lightningd: don't crash when truncating large log messages We were using vasprintf to generate the log line and then using free to deallocate the string. However, in the case of a very long log line a new pointer was created with tal_fmt and then tried to use free on it. This was introduced in commit: 4d8f923a9a1468b8987dbb48e8fc988747f8c62f ``` free(): invalid pointer lightningd: FATAL SIGNAL 6 (version v26.06-21-gebc5dc2) 0x563dab20be43 send_backtrace common/daemon.c:38 0x563dab20becd crashdump common/daemon.c:83 0x7f0cf0c96def ??? ./signal/../sysdeps/unix/sysv/linux/x86_64/libc_sigaction.c:0 0x7f0cf0ceb95c __pthread_kill_implementation ./nptl/pthread_kill.c:44 0x7f0cf0c96cc1 __GI_raise ../sysdeps/posix/raise.c:26 0x7f0cf0c7f4ab __GI_abort ./stdlib/abort.c:77 0x7f0cf0c80290 __libc_message_impl ../sysdeps/posix/libc_fatal.c:134 0x7f0cf0cf5464 malloc_printerr ./malloc/malloc.c:5832 0x7f0cf0cfa41b _int_free_check ./malloc/malloc.c:4560 0x7f0cf0cfa41b _int_free ./malloc/malloc.c:4692 0x7f0cf0cfa41b __GI___libc_free ./malloc/malloc.c:3476 0x563dab19be60 logv lightningd/log.c:688 0x563dab19c0bc log_ lightningd/log.c:728 0x563dab1c1047 plugin_log_handle lightningd/plugin.c:530 0x563dab1c5801 plugin_notification_handle lightningd/plugin.c:609 0x563dab1c5a9a plugin_read_json lightningd/plugin.c:753 0x563dab2388a5 next_plan ccan/ccan/io/io.c:60 0x563dab238c83 do_plan ccan/ccan/io/io.c:422 0x563dab238d3c io_ready ccan/ccan/io/io.c:439 0x563dab239e5b io_loop ccan/ccan/io/poll.c:470 0x563dab194399 io_loop_with_timers lightningd/io_loop_with_timers.c:22 0x563dab199c29 main lightningd/lightningd.c:1480 0x7f0cf0c80ca7 __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 0x7f0cf0c80d64 __libc_start_main_impl ../csu/libc-start.c:360 0x563dab169020 ??? _start+0x20:0 0xffffffffffffffff ??? ???:0 ``` Changelog-None Signed-off-by: Lagrang3 --- tests/test_misc.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/test_misc.py b/tests/test_misc.py index 0aeaf21ec649..5ed6792c6e4e 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -5145,7 +5145,6 @@ def test_filter_with_invalid_json(node_factory): assert out.returncode == 1 -@pytest.mark.xfail(strict=True) def test_long_logs(node_factory): """A plugin that creates a very long log entry. Lightningd should truncate the output and not crash.""" From 715c53fdd1814ae9c8fefaa02bdc3bf13043e1d9 Mon Sep 17 00:00:00 2001 From: Matt Whitlock Date: Wed, 22 Jul 2026 15:58:04 -0400 Subject: [PATCH 6/6] cap_header() always tal_strdup()s msg This is less efficient at runtime but adheres to established practices. Suggested-by: Lagrang3 See: https://github.com/ElementsProject/lightning/pull/9331#discussion_r3628600315 --- lightningd/jsonrpc.c | 2 +- lightningd/log.c | 20 ++++++++------------ 2 files changed, 9 insertions(+), 13 deletions(-) diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index 6d9e83aa605e..1c5d0b994e2a 100644 --- a/lightningd/jsonrpc.c +++ b/lightningd/jsonrpc.c @@ -707,7 +707,7 @@ void json_stream_log_suppress_for_cmd(struct json_stream *js, { const char *nm = cmd->json_cmd->name; const char *s = tal_fmt(tmpctx, "Suppressing logging of %s command", nm); - log_io(cmd->jcon->log, LOG_IO_OUT, NULL, s, NULL, 0); + log_io(cmd->jcon->log, LOG_IO_OUT, NULL, take(s), NULL, 0); /* Really shouldn't be used for anything else */ assert(streq(nm, "getlog")); diff --git a/lightningd/log.c b/lightningd/log.c index a6c667072f8a..4e2656eedc8c 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -267,22 +267,21 @@ static void del_front_log(struct log_book *log) static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg TAKES) { const size_t max = sizeof(((struct log_book *)0)->ringbuf) / 64; + msg = tal_strdup(ctx, msg); if (hdr->msglen > max) { char *new; new = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", hdr->msglen, (int)max, msg); - if (taken(msg)) - tal_free(msg); - msg = take(new); + tal_free(msg); + msg = new; hdr->msglen = tal_count(msg) - 1; } if (hdr->iolen > max) { char *new; new = tal_fmt(ctx, "[TRUNCATED IO from %zu bytes]: %.*s", hdr->iolen, (int)hdr->msglen, msg); - if (taken(msg)) - tal_free(msg); - msg = take(new); + tal_free(msg); + msg = new; hdr->msglen = tal_count(msg) - 1; hdr->iolen = max; } @@ -690,8 +689,7 @@ void logv(struct logger *log, enum log_level level, l.prefix->prefix, logmsg); - if (taken(logmsg)) - tal_free(logmsg); + tal_free(logmsg); errno = save_errno; } @@ -720,10 +718,8 @@ void log_io(struct logger *log, enum log_level dir, str = cap_header(tmpctx, &l, str); add_entry(log->log_book, &l, str, data); - if (taken(str)) - tal_free(str); - if (taken(data)) - tal_free(data); + tal_free(str); + tal_free_if_taken(data); errno = save_errno; }