lightningd: don't crash when truncating large log messages
What the developer wrote
Authored by Matt Whitlock
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.
Suggested-by: Lagrang3 <lagrang3@protonmail.com>
See: https://github.com/ElementsProject/lightning/pull/9331#discussion_r3628600315
Changelog-Fixed: log: don't crash when truncating large log messages
What changed, and why it matters
This commit fixes a crash bug in Core Lightning's logging code. When a log message was very long and got truncated, the program accidentally used the standard free() on memory that had been allocated by the project's own tal allocation system, causing a crash. The patch switches everything to use tal consistently, marks some function parameters as 'taken' so ownership is clear, and removes a failing-test marker because the bug is now fixed.
Upgrade to a release containing this commit. The bug is a remotely or plugin-triggerable denial-of-service crash; no immediate workaround is required beyond patching. Operators running nodes that load untrusted or verbose plugins should prioritize the update.
Security signals we found
Use-after-free / allocator mismatch: free() called on tal-allocated memory
Denial of service via large log message triggering truncation path crash
Memory ownership semantics corrected with TAKES annotations
Test previously expected to fail is now enabled, confirming the crash path
Evidence from the diff
The patch resolves a memory-management mismatch in lightningd/log.c. cap_header() previously returned a tal_fmt()-allocated string, but logv() later called free() on it. The fix makes cap_header() take ownership of its input (TAKES), always tal_strdup() it, tal_free() the original when truncation occurs, and use tal_count() instead of strlen(). logv() now allocates the formatted message with tal_vfmt() instead of vasprintf(), and log_io() actually takes ownership of its TAKES-marked str and data parameters. A previously xfail-marked test (test_long_logs) is re-enabled.
Changed components
lightningd/log.clightningd/jsonrpc.ctests/test_misc.pyInspect captured patch +22 / −18
diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c
index cf8f68a2..81bcb999 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 a3a2b838..4e2656ee 100644
--- a/lightningd/log.c
+++ b/lightningd/log.c
@@ -264,18 +264,25 @@ 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;
+ msg = tal_strdup(ctx, 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);
- hdr->msglen = strlen(msg);
+ tal_free(msg);
+ 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);
- hdr->msglen = strlen(msg);
+ tal_free(msg);
+ msg = new;
+ hdr->msglen = tal_count(msg) - 1;
hdr->iolen = max;
}
return cast_const(char *, msg);
@@ -660,12 +667,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; i<log_len; i++)
@@ -676,7 +679,7 @@ void logv(struct logger *log, enum log_level level,
maybe_print(log, &l, logmsg, NULL);
maybe_notify_log(log, &l, logmsg);
- logmsg = cap_header(tmpctx, &l, logmsg);
+ logmsg = cap_header(tmpctx, &l, take(logmsg));
add_entry(log->log_book, &l, logmsg, NULL);
if (call_notifier)
@@ -685,8 +688,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,13 +703,14 @@ 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,
@@ -714,6 +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);
+ tal_free(str);
+ tal_free_if_taken(data);
errno = save_errno;
}
diff --git a/tests/test_misc.py b/tests/test_misc.py
index b5f07c67..24704c4a 100644
--- a/tests/test_misc.py
+++ b/tests/test_misc.py
@@ -5407,7 +5407,6 @@ def test_tracing_socket(node_factory):
assert span["localEndpoint"] == {"serviceName": "lightningd"}
-@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."""
@@ -5421,4 +5420,3 @@ def test_long_logs(node_factory):
l1 = node_factory.get_node(inline_plugin=setup)
l1.rpc.call("produce-log")
-
Why this scored 60/100
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.