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 a3a2b8384327..4e2656eedc8c 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; ilog_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 bbfbd80c384f..5ed6792c6e4e 100644 --- a/tests/test_misc.py +++ b/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")