lightningd: don't crash when truncating large log messages by whitslack · Pull Request #9331 · ElementsProject/lightning

whitslack · 2026-07-19T06:40:27Z

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.

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. N/A
Tests have been added or modified to reflect the changes. N/A
Documentation has been reviewed and updated as needed. N/A
Related issues have been listed and linked, including any that this PR closes. None found
Important All PRs must consider how to reverse any persistent changes for tools/lightning-downgrade N/A

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

whitslack · 2026-07-19T06:49:38Z

@@ -685,8 +684,8 @@ void logv(struct logger *log, enum log_level level,
 			       l.time,
 			       l.prefix->prefix,
 			       logmsg);
-	free(logmsg);


This is where the crash was occurring. The crash happens if cap_header() tallocates and returns a new string to hold the truncated message. Then we'll be trying to free() a tal pointer. Boom.

cdecker

Excellent find @ksedgwic 🙏

Lagrang3 · 2026-07-21T12:48:28Z

 	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;


Why not use strlen(msg)?

strlen has to scan over the entire string, which we've already determined is "giant." tal_count is just an integer load at an offset from the given pointer.

Lagrang3 · 2026-07-21T13:45:43Z

+	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);


This is very hard to read and understand.
Since str is a TAKES argument it will be consumed already by cap_header if marked as take.
No further action is needed. After the line str = cap_header(...); you only need to worry about the
new pointer, that one is allocated with tmpctx therefore this is just fine.

Suggested change

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);

str = cap_header(tmpctx, &l, str/*TAKES*/);

add_entry(log->log_book, &l, str, data);

if (taken(data))

tal_free(data);

In your suggested change, no one frees the str returned by cap_header. Memory leak.

I suppose cap_header could return take(str) in the case that it took ownership of the passed str and does not truncate it, but I didn't know whether take is intended to be used on return values or only on arguments, and I think the assumption already should be that the caller of an allocating function takes ownership of the returned allocation (if one occurred).

We have the following four cases:

str passed to log_io was marked take, and cap_header does not truncate.

cap_header must not free str since it's returning it directly. (cap_header takes ownership of str and then hands ownership back to the caller.)

log_io owns str returned from cap_header and must free it.

str passed to log_io was not marked take, and cap_header does not truncate.

cap_header must not free str since the caller did not cede ownership.

log_io does not own str returned from cap_header and must not free it.

str passed to log_io was marked take, and cap_header does truncate.

cap_header must free str since it has taken ownership of it and is returning a different pointer.

log_io owns str returned from cap_header and must free it.

str passed to log_io was not marked take, and cap_header does truncate.

cap_header must not free str since the caller did not cede ownership.

log_io owns str returned from cap_header and must free it. (My code leaks in this case, although it is known that the leaked pointed was allocated from tmpctx.)

I'll make the obligatory snide comment again that all of this would be so much simpler if you folks would just use C++ like sane people.

Lagrang3 · 2026-07-21T14:38:39Z

+	if (taken(origmsg) && msg != origmsg)
+		tal_free(origmsg);


When the caller marks msg as take you don't consume the pointer if msg==origmsg.
This breaks the caller assumption that you will consume it and return a pointer allocated
in the given ctx.

I think this whole function should be left the way it is now.
There is a bunch of sloopy pointer reassignment without freeing but
it is because the caller knows that everything here is under the tmpctx.

But if we want to be pedantic I think the function should follow the take and tal allocation rules
(as for my understanding).

/* 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; + msg = tal_strdup(ctx, msg); // already consumes msg if (hdr->msglen > max) { msg = tal_fmt(ctx, "[TRUNCATED message from %zu bytes]: %.*s", hdr->msglen, (int)max, msg);

NAK. There is no sense in duplicating a string and then immediately freeing the original. You're just burning CPU cycles for no reason.

Incidentally, you can re-parent a tal pointer, but I think 30f80d2 has a cleaner answer.

Lagrang3 · 2026-07-21T14:45:39Z

Also this is a duplicate of PR #9215.

whitslack · 2026-07-21T19:47:46Z

Also this is a duplicate of PR #9215.

Indeed. I didn't see your PR. 😞

Lagrang3 · 2026-07-21T20:17:24Z

Also this is a duplicate of PR #9215.

Indeed. I didn't see your PR. 😞

No problem. I'll close mine.

I am glad that you took the opportunity to fix things around.
Let me also comment that it would be nice to adhere to the convention to paste in the commit message
the error or stack trace of the crash that the PR is fixing.
And add a test to prove there was a problem and now it is fixed.
Feel free to cherry pick mine if you wish.

This relies on it being okay to return a pointer that is take().

whitslack · 2026-07-21T20:27:52Z

It can alternatively be done as in f3a9f38, which results in more conventional if (taken(…)) tal_free(…); logic but relies on a code pattern about whose acceptability I was uncertain: return take(…);.

EDIT: If cap_header allocates, then the pointer it returns should be take, regardless of whether it took the passed pointer. 30f80d2

Lagrang3 · 2026-07-21T20:35:20Z

BTW. I am still wondering why Rusty used vasprintf instead of a tal allocator for the log message string.
7 years ago this commit b210c9d changed tal_vfmt for vasprintf.
I think this is worth investigating.

Changelog-None Signed-off-by: Lagrang3 <lagrang3@protonmail.com>

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: 4d8f923 ``` 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 <lagrang3@protonmail.com>

whitslack · 2026-07-21T20:40:00Z

Feel free to cherry pick mine if you wish.

Done. Obviously this resulting sequence of commits will need to be rearranged and partially squashed before being merged, but I left it exploded apart for now for easier review.

whitslack · 2026-07-21T20:43:03Z

BTW. I am still wondering why Rusty used vasprintf instead of a tal allocator for the log message string. 7 years ago this commit b210c9d changed tal_vfmt for vasprintf. I think this is worth investigating.

I expect it was because he was keeping the log message pointers around under the old logbook implementation. Now that the log message contents are simply copied into a ring buffer, the tal overhead of the original log message pointer does not matter, as that allocation is now short-lived.

whitslack commented Jul 19, 2026

View reviewed changes

cdecker previously approved these changes Jul 21, 2026

View reviewed changes

enaples mentioned this pull request Jul 21, 2026

Crash: lightningd aborts with FATAL SIGNAL 6 whenever any log message exceeds 256KB #9339

Open

Lagrang3 reviewed Jul 21, 2026

View reviewed changes

alternative take logic

f3a9f38

This relies on it being okay to return a pointer that is take().

whitslack dismissed cdecker’s stale review via f3a9f38 July 21, 2026 20:24

take(new), take two

30f80d2

Lagrang3 added 2 commits July 21, 2026 16:35

lightningd: test for very long log entries

6a5aee9

Changelog-None Signed-off-by: Lagrang3 <lagrang3@protonmail.com>

Uh oh!

Conversation

whitslack commented Jul 19, 2026

Checklist

Uh oh!

whitslack Jul 19, 2026

Choose a reason for hiding this comment

Uh oh!

cdecker left a comment

Choose a reason for hiding this comment

Uh oh!

Lagrang3 Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

whitslack Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

Lagrang3 Jul 21, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

whitslack Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

whitslack Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

Lagrang3 Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

whitslack Jul 21, 2026

Choose a reason for hiding this comment

Uh oh!

whitslack Jul 21, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Lagrang3 commented Jul 21, 2026

Uh oh!

whitslack commented Jul 21, 2026

Uh oh!

Lagrang3 commented Jul 21, 2026

Uh oh!

whitslack commented Jul 21, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Lagrang3 commented Jul 21, 2026

Uh oh!

whitslack commented Jul 21, 2026

Uh oh!

whitslack commented Jul 21, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Lagrang3 Jul 21, 2026 •

edited

Loading

whitslack Jul 21, 2026 •

edited

Loading

whitslack commented Jul 21, 2026 •

edited

Loading