lightningd: don't crash when truncating large log messages

lightningd/log.c

@@ -264,18 +264,26 @@ 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;
 	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);
+		if (taken(msg))
+			tal_free(msg);
+		msg = take(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);
+		if (taken(msg))
+			tal_free(msg);
+		msg = take(new);
+		hdr->msglen = tal_count(msg) - 1;
 		hdr->iolen = max;
 	}
 	return cast_const(char *, msg);
@@ -660,12 +668,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 +680,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 +689,9 @@ void logv(struct logger *log, enum log_level level,
 			       l.time,
 			       l.prefix->prefix,
 			       logmsg);
-	free(logmsg);
 
+	if (taken(logmsg))
+		tal_free(logmsg);
 	errno = save_errno;
 }
 
@@ -700,20 +705,25 @@ 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);
 	add_entry(log->log_book, &l, str, data);
+	if (taken(str))
+		tal_free(str);
+	if (taken(data))
+		tal_free(data);
 	errno = save_errno;
 }
 

tests/test_misc.py

@@ -5143,3 +5143,18 @@ 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
+
+
+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")