logging: switch to a simple ringbuffer.
What changed, and why it matters
This commit rewrites Core Lightning's internal log storage from a dynamically pruned array into a fixed 16 MB ring buffer. It is a refactoring/cleanup change: the old pruning logic is removed, the log size is now hard-capped, and the 'SKIPPED' entries in the getlog RPC are eliminated. There is no direct security fix described by the author, and the diff does not show an obvious exploitable vulnerability. The main security-relevant side effect is that crash logs and the getlog output now contain only the most recent 16 MB of messages, which could slightly reduce forensic information after an incident.
Treat as a normal code-quality/refactoring commit. Review the new ring-buffer helpers for correct wrap-around handling and ensure the 16 MB cap is acceptable for operational forensics. No urgent security action is indicated by the supplied materials.
Security signals we found
Refactoring of internal logging storage
Removal of probabilistic log pruning
Introduction of fixed-size 16 MB ring buffer
New wrap-around buffer read/write helpers
Change to getlog RPC output format (no more SKIPPED entries)
No vendor claim of security relevance
Evidence from the diff
The patch replaces the previous log_book implementation (a resizable array of struct log_entry with probabilistic pruning to stay under a 10 MB memory budget) with a 16 MB byte ring buffer. Log records are now stored as a packed struct log_hdr followed by msglen bytes and iolen bytes. New helper functions (ringbuf_span, copy_from, copy_to, get_log_entry, del_front_log, add_entry, cap_header) manage wrap-around and in-place reads. The public API changes: new_log_book no longer takes a max_mem argument; the ‘skipped’ counter and SKIPPED JSON entries are removed; log_to_files and log_each_line_ now pass explicit string/IO lengths; json_add_log uses json_add_stringn and json_add_hex instead of tal-counted arrays. Tests are updated to verify ring-buffer wrap-around rather than pruning behavior. No memory-safety bug, overflow, or authentication bypass is evident in the diff, though the ring buffer logic is new code that handles wrap-around and truncation.
Changed components
lightningd/log.clightningd/log.hlightningd/lightningd.clightningd/test/run-log-pruning.clightningd/test/run-log_filter.ctests/test_misc.pywallet/test/run-wallet.clightningd/test/run-find_my_abspath.cInspect captured patch +317 / −297
diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c
index aff78fc8..504a5adb 100644
--- a/lightningd/lightningd.c
+++ b/lightningd/lightningd.c
@@ -213,11 +213,11 @@ static struct lightningd *new_lightningd(const tal_t *ctx)
* who talk to us about long-closed channels. */
ld->closed_channels = new_htable(ld, closed_channel_map);
- /*~ We have a multi-entry log-book infrastructure: we define a 10MB log
- * book to hold all the entries (and trims as necessary), and multiple
+ /*~ We have a multi-entry log-book infrastructure: we define a 16MB log
+ * book to hold all the entries in a circular buffer, and multiple
* log objects which each can write into it, each with a unique
* prefix. */
- ld->log_book = new_log_book(ld, 10*1024*1024);
+ ld->log_book = new_log_book(ld);
/*~ Note the tal context arg (by convention, the first argument to any
* allocation function): ld->log will be implicitly freed when ld
* is. */
diff --git a/lightningd/log.c b/lightningd/log.c
index 8b7a9f20..a3a2b838 100644
--- a/lightningd/log.c
+++ b/lightningd/log.c
@@ -1,4 +1,5 @@
#include "config.h"
+#include <ccan/cast/cast.h>
#include <ccan/err/err.h>
#include <ccan/io/io.h>
#include <ccan/read_write_all/read_write_all.h>
@@ -28,15 +29,13 @@ struct log_prefix {
const char *prefix;
};
-struct log_entry {
+struct log_hdr {
struct timeabs time;
enum log_level level;
- unsigned int skipped;
struct node_id_cache *nc;
struct log_prefix *prefix;
- char *log;
- /* Iff LOG_IO */
- const u8 *io;
+ size_t msglen, iolen;
+ /* Followed by msglen then iolen bytes! */
};
struct print_filter {
@@ -52,12 +51,15 @@ struct log_file {
FILE *f;
};
+#define RING_BITS 24
struct log_book {
- size_t mem_used;
- size_t max_mem;
- size_t num_entries;
struct list_head print_filters;
+ /* Ring buffer: 16MB should be enough for anyone! */
+ char ringbuf[1 << RING_BITS];
+ /* These free-run, so use modulus */
+ size_t ringbuf_start, ringbuf_end;
+
/* Non-null once it's been initialized */
enum log_level *default_print_level;
struct timeabs init_time;
@@ -69,7 +71,6 @@ struct log_book {
struct log_file **log_files;
bool print_timestamps;
- struct log_entry *log;
/* Prefix this to every entry as you output */
const char *prefix;
@@ -105,12 +106,118 @@ static struct log_prefix *log_prefix_new(const tal_t *ctx,
return lp;
}
+static void ringbuf_span(const struct log_book *log,
+ size_t start, size_t len,
+ void **buf1, size_t *buf1len,
+ void **buf2, size_t *buf2len)
+{
+ size_t size = sizeof(log->ringbuf);
+ size_t off = start % size;
+ size_t first = size - off;
+
+ assert(len <= size);
+
+ if (first > len)
+ first = len;
+
+ *buf1 = (void *)(log->ringbuf + off);
+ *buf1len = first;
+
+ if (first == len) {
+ *buf2 = NULL;
+ *buf2len = 0;
+ } else {
+ *buf2 = (void *)log->ringbuf;
+ *buf2len = len - first;
+ }
+}
+
+/* buf1/buf1len & buf2/buf2len -> dest/destlen */
+static size_t copy_from(void *dest, size_t destlen,
+ const void *buf1, size_t buf1len,
+ const void *buf2, size_t buf2len)
+{
+ assert(destlen == buf1len + buf2len);
+ if (buf1len)
+ memcpy(dest, buf1, buf1len);
+ if (buf2len)
+ memcpy((char *)dest + buf1len, buf2, buf2len);
+ return destlen;
+}
+
+/* dest/destlen -> buf1/buf1len & buf2/buf2len */
+static size_t copy_to(void *buf1, size_t buf1len,
+ void *buf2, size_t buf2len,
+ const void *dest, size_t destlen)
+{
+ assert(destlen == buf1len + buf2len);
+ if (buf1len)
+ memcpy(buf1, dest, buf1len);
+ if (buf2len)
+ memcpy(buf2, (char *)dest + buf1len, buf2len);
+ return destlen;
+}
+
+static size_t ringbuf_used(const struct log_book *log)
+{
+ return log->ringbuf_end - log->ringbuf_start;
+}
+
+static size_t ringbuf_avail(const struct log_book *log)
+{
+ return sizeof(log->ringbuf) - ringbuf_used(log);
+}
+
static void log_prefix_drop(struct log_prefix *lp)
{
if (--lp->refcnt == 0)
tal_free(lp);
}
+/* Returns in-place, but copies if it has to. Updates *off. */
+static bool get_log_entry(const tal_t *ctx,
+ const struct log_book *log,
+ struct log_hdr *hdr,
+ const char **msg,
+ const u8 **io,
+ size_t *off)
+{
+ void *buf1, *buf2;
+ size_t buf1len, buf2len;
+
+ if (ringbuf_used(log) < *off + sizeof(*hdr))
+ return false;
+
+ ringbuf_span(log, log->ringbuf_start + *off, sizeof(*hdr),
+ &buf1, &buf1len, &buf2, &buf2len);
+ *off += copy_from(hdr, sizeof(*hdr), buf1, buf1len, buf2, buf2len);
+ ringbuf_span(log, log->ringbuf_start + *off, hdr->msglen,
+ &buf1, &buf1len, &buf2, &buf2len);
+ if (buf2len != 0) {
+ char *bytes = tal_arr(ctx, char, buf1len + buf2len);
+ *off += copy_from(bytes, tal_bytelen(bytes), buf1, buf1len, buf2, buf2len);
+ *msg = bytes;
+ } else {
+ *msg = buf1;
+ *off += buf1len;
+ }
+ ringbuf_span(log, log->ringbuf_start + *off, hdr->iolen,
+ &buf1, &buf1len, &buf2, &buf2len);
+ if (buf2len != 0) {
+ u8 *bytes = tal_arr(ctx, u8, buf1len + buf2len);
+ *off += copy_from(bytes, tal_bytelen(bytes), buf1, buf1len, buf2, buf2len);
+ *io = bytes;
+ } else {
+ if (buf1len == 0)
+ *io = NULL;
+ else {
+ *io = buf1;
+ *off += buf1len;
+ }
+ }
+ return true;
+}
+
static struct log_prefix *log_prefix_get(struct log_prefix *lp)
{
assert(lp->refcnt);
@@ -139,6 +246,62 @@ HTABLE_DEFINE_NODUPS_TYPE(struct node_id_cache,
node_cache_id, node_id_hash, node_id_cache_eq,
node_id_map);
+static void del_front_log(struct log_book *log)
+{
+ struct log_hdr hdr;
+ void *buf1, *buf2;
+ size_t buf1len, buf2len;
+
+ ringbuf_span(log, log->ringbuf_start, sizeof(hdr),
+ &buf1, &buf1len, &buf2, &buf2len);
+ copy_from(&hdr, sizeof(hdr), buf1, buf1len, buf2, buf2len);
+ assert(ringbuf_used(log) >= sizeof(hdr) + hdr.msglen + hdr.iolen);
+ log->ringbuf_start += sizeof(hdr) + hdr.msglen + hdr.iolen;
+
+ if (hdr.nc && --hdr.nc->count == 0)
+ tal_free(hdr.nc);
+ log_prefix_drop(hdr.prefix);
+}
+
+/* We truncate genuinely giant messages */
+static char *cap_header(const tal_t *ctx, struct log_hdr *hdr, const char *msg)
+{
+ 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",
+ hdr->msglen, (int)max, msg);
+ hdr->msglen = strlen(msg);
+ }
+ 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->iolen = max;
+ }
+ return cast_const(char *, msg);
+}
+
+static void add_entry(struct log_book *log,
+ const struct log_hdr *hdr,
+ const char *msg,
+ const u8 *io)
+{
+ void *buf1, *buf2;
+ size_t buf1len, buf2len;
+ size_t needed = sizeof(*hdr) + hdr->msglen + hdr->iolen;
+ assert(needed < sizeof(log->ringbuf));
+
+ while (ringbuf_avail(log) < needed)
+ del_front_log(log);
+
+ ringbuf_span(log, log->ringbuf_end, sizeof(*hdr), &buf1, &buf1len, &buf2, &buf2len);
+ log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, hdr, sizeof(*hdr));
+ ringbuf_span(log, log->ringbuf_end, hdr->msglen, &buf1, &buf1len, &buf2, &buf2len);
+ log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, msg, hdr->msglen);
+ ringbuf_span(log, log->ringbuf_end, hdr->iolen, &buf1, &buf1len, &buf2, &buf2len);
+ log->ringbuf_end += copy_to(buf1, buf1len, buf2, buf2len, io, hdr->iolen);
+}
+
static const char *level_prefix(enum log_level level)
{
switch (level) {
@@ -216,9 +379,8 @@ static void log_to_files(const char *log_prefix,
/* Filters to apply, if non-NULL */
const struct list_head *print_filters,
const struct timeabs *time,
- const char *str,
- const u8 *io,
- size_t io_len,
+ const char *str, size_t str_len,
+ const u8 *io, size_t io_len,
bool print_timestamps,
const enum log_level *default_print_level,
struct log_file **log_files)
@@ -231,7 +393,7 @@ static void log_to_files(const char *log_prefix,
+ strlen(level_prefix(level))
+ sizeof(nodestr)
+ strlen(entry_prefix)
- + strlen(str)];
+ + str_len];
bool filtered;
if (print_timestamps) {
@@ -250,26 +412,26 @@ static void log_to_files(const char *log_prefix,
const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
char *hex = tal_hexstr(NULL, io, io_len);
if (!node_id)
- entry = tal_fmt(tmpctx, "%s%s%s: %s%s %s\n",
- log_prefix, tstamp, entry_prefix, str, dir, hex);
+ entry = tal_fmt(tmpctx, "%s%s%s: %.*s%s %s\n",
+ log_prefix, tstamp, entry_prefix, (int)str_len, str, dir, hex);
else
- entry = tal_fmt(tmpctx, "%s%s%s-%s: %s%s %s\n",
+ entry = tal_fmt(tmpctx, "%s%s%s-%s: %.*s%s %s\n",
log_prefix, tstamp,
nodestr,
- entry_prefix, str, dir, hex);
+ entry_prefix, (int)str_len, str, dir, hex);
tal_free(hex);
} else {
size_t len;
entry = buf;
if (!node_id)
len = snprintf(buf, sizeof(buf),
- "%s%s%s %s: %s\n",
- log_prefix, tstamp, level_prefix(level), entry_prefix, str);
+ "%s%s%s %s: %.*s\n",
+ log_prefix, tstamp, level_prefix(level), entry_prefix, (int)str_len, str);
else
- len = snprintf(buf, sizeof(buf), "%s%s%s %s-%s: %s\n",
+ len = snprintf(buf, sizeof(buf), "%s%s%s %s-%s: %.*s\n",
log_prefix, tstamp, level_prefix(level),
nodestr,
- entry_prefix, str);
+ entry_prefix, (int)str_len, str);
assert(len < sizeof(buf));
}
@@ -316,101 +478,17 @@ static void log_to_files(const char *log_prefix,
}
}
-static size_t mem_used(const struct log_entry *e)
-{
- return sizeof(*e) + strlen(e->log) + 1 + tal_count(e->io);
-}
-
-/* Threshold (of 1000) to delete */
-static u32 delete_threshold(enum log_level level)
-{
- switch (level) {
- /* Delete 90% of log_io */
- case LOG_IO_OUT:
- case LOG_IO_IN:
- return 900;
- /* 50% of LOG_TRACE */
- case LOG_TRACE:
- return 750;
- /* 50% of LOG_DBG */
- case LOG_DBG:
- return 500;
- /* 25% of LOG_INFORM */
- case LOG_INFORM:
- return 250;
- /* 5% of LOG_UNUSUAL / LOG_BROKEN */
- case LOG_UNUSUAL:
- case LOG_BROKEN:
- return 50;
- }
- abort();
-}
-
-/* Delete a log entry: returns how many now deleted */
-static size_t delete_entry(struct log_book *log, struct log_entry *i)
-{
- log->mem_used -= mem_used(i);
- log->num_entries--;
- if (i->nc && --i->nc->count == 0)
- tal_free(i->nc);
- free(i->log);
- log_prefix_drop(i->prefix);
- tal_free(i->io);
-
- return 1 + i->skipped;
-}
-
-static size_t prune_log(struct log_book *log)
-{
- size_t skipped = 0, deleted = 0, count = 0, dst = 0, max, tail;
-
- /* Never delete the last 10% (and definitely not last one!). */
- tail = log->num_entries / 10 + 1;
- max = log->num_entries - tail;
-
- for (count = 0; count < max; count++) {
- struct log_entry *i = &log->log[count];
-
- if (pseudorand(1000) > delete_threshold(i->level)) {
- i->skipped += skipped;
- skipped = 0;
- /* Move down if necesary. */
- log->log[dst++] = *i;
- continue;
- }
-
- skipped += delete_entry(log, i);
- deleted++;
- }
-
- /* Any skipped at tail go on the next entry */
- log->log[count].skipped += skipped;
-
- /* Move down the last 10% */
- memmove(log->log + dst, log->log + count, tail * sizeof(*log->log));
- return deleted;
-}
-
static void destroy_log_book(struct log_book *log)
{
- size_t num = log->num_entries;
-
- for (size_t i = 0; i < num; i++)
- delete_entry(log, &log->log[i]);
-
- assert(log->num_entries == 0);
- assert(log->mem_used == 0);
+ while (ringbuf_used(log) > 0)
+ del_front_log(log);
}
-struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
+struct log_book *new_log_book(struct lightningd *ld)
{
struct log_book *log_book = tal_linkable(tal(NULL, struct log_book));
- /* Give a reasonable size for memory limit! */
- assert(max_mem > sizeof(struct logger) * 2);
- log_book->mem_used = 0;
- log_book->num_entries = 0;
- log_book->max_mem = max_mem;
+ log_book->ringbuf_start = log_book->ringbuf_end = 0;
log_book->log_files = NULL;
log_book->default_print_level = NULL;
/* We have to allocate this, since we tal_free it on resetting */
@@ -421,7 +499,6 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
log_book->ld = ld;
log_book->cache = tal(log_book, struct node_id_map);
node_id_map_init(log_book->cache);
- log_book->log = tal_arr(log_book, struct log_entry, 128);
log_book->print_timestamps = true;
tal_add_destructor(log_book, destroy_log_book);
@@ -512,41 +589,50 @@ bool log_has_trace_logging(const struct logger *log)
return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_DBG;
}
-/* This may move entry! */
-static void add_entry(struct logger *log, struct log_entry **l)
-{
- log->log_book->mem_used += mem_used(*l);
- log->log_book->num_entries++;
-
- if (log->log_book->mem_used > log->log_book->max_mem) {
- size_t old_mem = log->log_book->mem_used, deleted;
- deleted = prune_log(log->log_book);
- /* Will have moved, but will be last entry. */
- *l = &log->log_book->log[log->log_book->num_entries-1];
- log_debug(log, "Log pruned %zu entries (mem %zu -> %zu)",
- deleted, old_mem, log->log_book->mem_used);
- }
-}
-
static void destroy_node_id_cache(struct node_id_cache *nc, struct log_book *log_book)
{
node_id_map_del(log_book->cache, nc);
}
-static struct log_entry *new_log_entry(struct logger *log, enum log_level level,
- const struct node_id *node_id)
+static void maybe_print(struct logger *log,
+ const struct log_hdr *l,
+ const char *logmsg,
+ const u8 *iomsg)
{
- struct log_entry *l;
+ 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, logmsg, strlen(logmsg),
+ iomsg, l->iolen,
+ log->log_book->print_timestamps,
+ log->log_book->default_print_level,
+ log->log_book->log_files);
+}
- if (log->log_book->num_entries == tal_count(log->log_book->log))
- tal_resize(&log->log_book->log, tal_count(log->log_book->log) * 2);
+static void maybe_notify_log(struct logger *log,
+ const struct log_hdr *l,
+ const char *logmsg)
+{
+ if (l->level >= log->print_level)
+ notify_log(log->log_book->ld,
+ l->level,
+ l->time,
+ l->prefix->prefix,
+ logmsg);
+}
- l = &log->log_book->log[log->log_book->num_entries];
+static void init_log_hdr(const struct logger *log,
+ struct log_hdr *l,
+ enum log_level level,
+ const struct node_id *node_id,
+ size_t msglen, size_t iolen)
+{
l->time = clock_time();
l->level = level;
- l->skipped = 0;
l->prefix = log_prefix_get(log->prefix);
- l->io = NULL;
+ l->msglen = msglen;
+ l->iolen = iolen;
if (!node_id)
node_id = log->default_node_id;
if (node_id) {
@@ -562,32 +648,6 @@ static struct log_entry *new_log_entry(struct logger *log, enum log_level level,
l->nc->count++;
} else
l->nc = NULL;
-
- return l;
-}
-
-static void maybe_print(struct logger *log, const struct log_entry *l)
-{
- 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, l->log,
- l->io, tal_bytelen(l->io),
- log->log_book->print_timestamps,
- log->log_book->default_print_level,
- log->log_book->log_files);
-}
-
-static void maybe_notify_log(struct logger *log,
- const struct log_entry *l)
-{
- if (l->level >= log->print_level)
- notify_log(log->log_book->ld,
- l->level,
- l->time,
- l->prefix->prefix,
- l->log);
}
void logv(struct logger *log, enum log_level level,
@@ -596,31 +656,36 @@ void logv(struct logger *log, enum log_level level,
const char *fmt, va_list ap)
{
int save_errno = errno;
- struct log_entry *l = new_log_entry(log, level, node_id);
+ struct log_hdr l;
+ size_t log_len;
+ char *logmsg;
/* This is WARN_UNUSED_RESULT, because everyone should somehow deal
* with OOM, even though nobody does. */
- if (vasprintf(&l->log, fmt, ap) == -1)
+ if (vasprintf(&logmsg, fmt, ap) == -1)
abort();
- size_t log_len = strlen(l->log);
+ log_len = strlen(logmsg);
/* Sanitize any non-printable characters, and replace with '?' */
for (size_t i=0; i<log_len; i++)
- if (l->log[i] < ' ' || l->log[i] >= 0x7f)
- l->log[i] = '?';
+ if (logmsg[i] < ' ' || logmsg[i] >= 0x7f)
+ logmsg[i] = '?';
- maybe_print(log, l);
- maybe_notify_log(log, l);
+ init_log_hdr(log, &l, level, node_id, log_len, 0);
+ maybe_print(log, &l, logmsg, NULL);
+ maybe_notify_log(log, &l, logmsg);
- add_entry(log, &l);
+ logmsg = cap_header(tmpctx, &l, logmsg);
+ add_entry(log->log_book, &l, logmsg, NULL);
if (call_notifier)
notify_warning(log->log_book->ld,
- l->level,
- l->time,
- l->prefix->prefix,
- l->log);
+ l.level,
+ l.time,
+ l.prefix->prefix,
+ logmsg);
+ free(logmsg);
errno = save_errno;
}
@@ -631,37 +696,24 @@ void log_io(struct logger *log, enum log_level dir,
const void *data TAKES, size_t len)
{
int save_errno = errno;
- struct log_entry *l = new_log_entry(log, dir, node_id);
+ struct log_hdr l;
assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);
- /* Print first, in case we need to truncate. */
- 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,
+ init_log_hdr(log, &l, dir, node_id, strlen(str), 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,
+ &l.time, str, strlen(str),
data, len,
log->log_book->print_timestamps,
log->log_book->default_print_level,
log->log_book->log_files);
- /* Save a tal header, by using raw malloc. */
- l->log = strdup(str);
- if (taken(str))
- tal_free(str);
-
- /* Don't immediately fill buffer with giant IOs */
- if (len > log->log_book->max_mem / 64) {
- l->skipped++;
- len = log->log_book->max_mem / 64;
- }
-
- /* FIXME: We could save 4 pointers by using a raw allow, but saving
- * the length. */
- l->io = tal_dup_arr(log->log_book, u8, data, len, 0);
-
- add_entry(log, &l);
+ str = cap_header(tmpctx, &l, str);
+ add_entry(log->log_book, &l, str, data);
errno = save_errno;
}
@@ -680,31 +732,34 @@ void log_(struct logger *log, enum log_level level,
#define log_each_line(log_book, func, arg) \
log_each_line_((log_book), \
typesafe_cb_preargs(void, void *, (func), (arg), \
- unsigned int, \
struct timerel, \
enum log_level, \
const struct node_id *, \
const char *, \
- const char *, \
- const u8 *), (arg))
+ const char *, size_t, \
+ const u8 *, size_t), (arg))
static void log_each_line_(const struct log_book *log_book,
- void (*func)(unsigned int skipped,
- struct timerel time,
+ void (*func)(struct timerel time,
enum log_level level,
const struct node_id *node_id,
const char *prefix,
const char *log,
+ size_t loglen,
const u8 *io,
+ size_t iolen,
void *arg),
void *arg)
{
- for (size_t i = 0; i < log_book->num_entries; i++) {
- const struct log_entry *l = &log_book->log[i];
+ size_t off = 0;
+ const char *msg;
+ const u8 *io;
+ struct log_hdr l;
- func(l->skipped, time_between(l->time, log_book->init_time),
- l->level, l->nc ? &l->nc->node_id : NULL,
- l->prefix->prefix, l->log, l->io, arg);
+ while (get_log_entry(tmpctx, log_book, &l, &msg, &io, &off)) {
+ func(time_between(l.time, log_book->init_time),
+ l.level, l.nc ? &l.nc->node_id : NULL,
+ l.prefix->prefix, msg, l.msglen, io, l.iolen, arg);
}
}
@@ -713,23 +768,18 @@ struct log_data {
const char *prefix;
};
-static void log_one_line(unsigned int skipped,
- struct timerel diff,
+static void log_one_line(struct timerel diff,
enum log_level level,
const struct node_id *node_id,
const char *prefix,
const char *log,
+ size_t loglen,
const u8 *io,
+ size_t iolen,
struct log_data *data)
{
char buf[101];
- if (skipped) {
- snprintf(buf, sizeof(buf), "%s... %u skipped...", data->prefix, skipped);
- write_all(data->fd, buf, strlen(buf));
- data->prefix = "\n";
- }
-
snprintf(buf, sizeof(buf), "%s+%lu.%09u %s%s: ",
data->prefix,
(unsigned long)diff.ts.tv_sec,
@@ -745,13 +795,13 @@ static void log_one_line(unsigned int skipped,
: "**INVALID**");
write_all(data->fd, buf, strlen(buf));
- write_all(data->fd, log, strlen(log));
+ write_all(data->fd, log, loglen);
if (level == LOG_IO_IN || level == LOG_IO_OUT) {
- size_t off, used, len = tal_count(io);
+ size_t off, used;
/* No allocations, may be in signal handler. */
- for (off = 0; off < len; off += used) {
- used = len - off;
+ for (off = 0; off < iolen; off += used) {
+ used = iolen - off;
if (hex_str_size(used) > sizeof(buf))
used = hex_data_size(sizeof(buf));
hex_encode(io + off, used, buf, hex_str_size(used));
@@ -968,6 +1018,10 @@ void opt_register_logging(struct lightningd *ld)
void logging_options_parsed(struct log_book *log_book)
{
struct logger *log;
+ size_t off;
+ const char *msg;
+ const u8 *io;
+ struct log_hdr l;
/* If they didn't set an explicit level, set to info */
if (!log_book->default_print_level) {
@@ -984,15 +1038,14 @@ void logging_options_parsed(struct log_book *log_book)
}
/* Catch up, since before we were only printing BROKEN msgs */
- for (size_t i = 0; i < log_book->num_entries; i++) {
- const struct log_entry *l = &log_book->log[i];
-
- if (l->level >= print_level(log_book, l->prefix, l->nc ? &l->nc->node_id : NULL, NULL))
- log_to_files(log_book->prefix, l->prefix->prefix, l->level,
- l->nc ? &l->nc->node_id : NULL,
+ off = 0;
+ while (get_log_entry(tmpctx, log_book, &l, &msg, &io, &off)) {
+ if (l.level >= print_level(log_book, l.prefix, l.nc ? &l.nc->node_id : NULL, NULL))
+ log_to_files(log_book->prefix, l.prefix->prefix, l.level,
+ l.nc ? &l.nc->node_id : NULL,
&log_book->print_filters,
- &l->time, l->log,
- l->io, tal_bytelen(l->io),
+ &l.time, msg, l.msglen,
+ io, l.iolen,
log_book->print_timestamps,
log_book->default_print_level,
log_book->log_files);
@@ -1018,13 +1071,8 @@ static void log_dump_to_file(int fd, const struct log_book *log_book)
struct log_data data;
time_t start;
- if (log_book->num_entries == 0) {
- write_all(fd, "0 bytes:\n\n", strlen("0 bytes:\n\n"));
- return;
- }
-
start = log_book->init_time.ts.tv_sec;
- len = snprintf(buf, sizeof(buf), "%zu bytes, %s", log_book->mem_used, ctime(&start));
+ len = snprintf(buf, sizeof(buf), "%zu bytes, %s", ringbuf_used(log_book), ctime(&start));
write_all(fd, buf, len);
/* ctime includes \n... WTF? */
@@ -1094,45 +1142,29 @@ void fatal(const char *fmt, ...)
struct log_info {
enum log_level level;
struct json_stream *response;
- unsigned int num_skipped;
/* If non-null, only show messages about this peer */
const struct node_id *node_id;
};
-static void add_skipped(struct log_info *info)
-{
- if (info->num_skipped) {
- json_object_start(info->response, NULL);
- json_add_string(info->response, "type", "SKIPPED");
- json_add_num(info->response, "num_skipped", info->num_skipped);
- json_object_end(info->response);
- info->num_skipped = 0;
- }
-}
-
-static void log_to_json(unsigned int skipped,
- struct timerel diff,
+static void log_to_json(struct timerel diff,
enum log_level level,
const struct node_id *node_id,
const char *prefix,
const char *log,
+ size_t loglen,
const u8 *io,
+ size_t iolen,
struct log_info *info)
{
- info->num_skipped += skipped;
-
if (info->node_id) {
if (!node_id || !node_id_eq(node_id, info->node_id))
return;
}
if (level < info->level) {
- info->num_skipped++;
return;
}
- add_skipped(info);
-
json_object_start(info->response, NULL);
json_add_string(info->response, "type",
level == LOG_BROKEN ? "BROKEN"
@@ -1147,9 +1179,9 @@ static void log_to_json(unsigned int skipped,
if (node_id)
json_add_node_id(info->response, "node_id", node_id);
json_add_string(info->response, "source", prefix);
- json_add_string(info->response, "log", log);
+ json_add_stringn(info->response, "log", log, loglen);
if (io)
- json_add_hex_talarr(info->response, "data", io);
+ json_add_hex(info->response, "data", io, iolen);
json_object_end(info->response);
}
@@ -1163,12 +1195,10 @@ void json_add_log(struct json_stream *response,
info.level = minlevel;
info.response = response;
- info.num_skipped = 0;
info.node_id = node_id;
json_array_start(info.response, "log");
log_each_line(log_book, log_to_json, &info);
- add_skipped(&info);
json_array_end(info.response);
}
@@ -1205,8 +1235,8 @@ static struct command_result *json_getlog(struct command *cmd,
/* Suppress logging for this stream, to not bloat io logs */
json_stream_log_suppress_for_cmd(response, cmd);
json_add_timestr(response, "created_at", log_book->init_time.ts);
- json_add_num(response, "bytes_used", (unsigned int)log_book->mem_used);
- json_add_num(response, "bytes_max", (unsigned int)log_book->max_mem);
+ json_add_num(response, "bytes_used", (unsigned int)ringbuf_used(log_book));
+ json_add_num(response, "bytes_max", sizeof(log_book->ringbuf));
json_add_log(response, log_book, NULL, *minlevel);
return command_success(cmd, response);
}
diff --git a/lightningd/log.h b/lightningd/log.h
index a05c7762..5a84ef7b 100644
--- a/lightningd/log.h
+++ b/lightningd/log.h
@@ -13,7 +13,7 @@ struct timerel;
/* We can have a single log book, with multiple loggers writing to it: it's freed
* by the last struct logger itself. */
-struct log_book *new_log_book(struct lightningd *ld, size_t max_mem);
+struct log_book *new_log_book(struct lightningd *ld);
/* With different entry points */
struct logger *new_logger(const tal_t *ctx, struct log_book *record,
diff --git a/lightningd/test/run-find_my_abspath.c b/lightningd/test/run-find_my_abspath.c
index 80c2a42c..37ff3c1a 100644
--- a/lightningd/test/run-find_my_abspath.c
+++ b/lightningd/test/run-find_my_abspath.c
@@ -145,7 +145,7 @@ bool log_status_msg(struct logger *log UNNEEDED,
const u8 *msg UNNEEDED)
{ fprintf(stderr, "log_status_msg called!\n"); abort(); }
/* Generated stub for new_log_book */
-struct log_book *new_log_book(struct lightningd *ld UNNEEDED, size_t max_mem UNNEEDED)
+struct log_book *new_log_book(struct lightningd *ld UNNEEDED)
{ fprintf(stderr, "new_log_book called!\n"); abort(); }
/* Generated stub for new_logger */
struct logger *new_logger(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED,
diff --git a/lightningd/test/run-log-pruning.c b/lightningd/test/run-log-pruning.c
index 02fcc9a0..87a2bdb1 100644
--- a/lightningd/test/run-log-pruning.c
+++ b/lightningd/test/run-log-pruning.c
@@ -75,47 +75,39 @@ int main(int argc, char *argv[])
{
struct log_book *lb;
struct logger *l;
+ size_t prev_avail = -1ULL, num = 0, off, i;
+ const u8 *io;
+ const char *msg;
+ struct log_hdr lhdr;
common_setup(argv[0]);
- lb = new_log_book(NULL,
- (sizeof(struct log_entry) + sizeof("test XXXXXX"))
- *100);
+ lb = new_log_book(NULL);
l = new_logger(lb, lb, NULL, "test %s", "prefix");
assert(streq(log_prefix(l), "test prefix"));
- for (size_t i = 0; i < 100; i++)
- log_debug(l, "test %06zi", i);
-
- assert(lb->num_entries == 100);
- for (size_t i = 0; i < 100; i++) {
- assert(lb->log[i].level == LOG_DBG);
- assert(lb->log[i].skipped == 0);
- assert(lb->log[i].nc == NULL);
- assert(lb->log[i].prefix->refcnt == 101);
- assert(streq(lb->log[i].prefix->prefix, "test prefix"));
- assert(streq(lb->log[i].log, tal_fmt(lb, "test %06zi", i)));
- assert(lb->log[i].io == NULL);
+ /* Push one off the end. */
+ while (ringbuf_avail(lb) < prev_avail) {
+ prev_avail = ringbuf_avail(lb);
+ log_debug(l, "test %06zi", num++);
}
- log_debug(l, "final test message");
- assert(lb->num_entries < 100);
- assert(lb->num_entries > 11);
-
- /* last 10% must be preserved exactly (with final and pruning
- * msg appended) */
- for (size_t i = 91; i < 100; i++) {
- size_t pos = lb->num_entries - 2 - (100 - i);
- assert(streq(lb->log[pos].log, tal_fmt(lb, "test %06zi", i)));
+ assert(ringbuf_used(lb) <= sizeof(lb->ringbuf));
+ assert(ringbuf_avail(lb) < sizeof(struct log_hdr) + strlen("test 000000"));
+
+ off = 0;
+ i = 1;
+ while (get_log_entry(tmpctx, lb, &lhdr, &msg, &io, &off)) {
+ assert(lhdr.level == LOG_DBG);
+ assert(lhdr.nc == NULL);
+ assert(streq(lhdr.prefix->prefix, "test prefix"));
+ assert(lhdr.msglen == strlen("test 000000"));
+ assert(lhdr.iolen == 0);
+ assert(strncmp(msg, tal_fmt(lb, "test %06zi", i++), lhdr.msglen) == 0);
+ assert(lhdr.prefix->refcnt == num);
+ assert(io == NULL);
}
- assert(streq(lb->log[lb->num_entries - 2].log, "final test message"));
-
- /* Sum should still reflect 102 total messages */
- size_t total = 0;
- for (size_t i = 0; i < lb->num_entries; i++)
- total += 1 + lb->log[i].skipped;
- assert(total == 102);
/* Freeing (last) log frees logbook */
tal_free(l);
diff --git a/lightningd/test/run-log_filter.c b/lightningd/test/run-log_filter.c
index c700eae8..a6da5a6b 100644
--- a/lightningd/test/run-log_filter.c
+++ b/lightningd/test/run-log_filter.c
@@ -113,7 +113,7 @@ int main(int argc, char *argv[])
ld = tal(tmpctx, struct lightningd);
ld->logfiles = NULL;
- lb = ld->log_book = new_log_book(ld, 1024*1024);
+ lb = ld->log_book = new_log_book(ld);
ld->log = new_logger(ld, lb, NULL, "dummy");
assert(arg_log_to_file("-", ld) == NULL);
diff --git a/tests/test_misc.py b/tests/test_misc.py
index b1aa0379..8777059f 100644
--- a/tests/test_misc.py
+++ b/tests/test_misc.py
@@ -3769,13 +3769,11 @@ def test_getlog(node_factory):
"""Test the getlog command"""
l1 = node_factory.get_node(options={'log-level': 'io'})
- # Default will skip some entries
logs = l1.rpc.getlog()['log']
- assert [l for l in logs if l['type'] == 'SKIPPED'] != []
+ assert [l for l in logs if l['type'] not in ("BROKEN", "UNUSUAL", "INFO")] == []
- # This should not
logs = l1.rpc.getlog(level='io')['log']
- assert [l for l in logs if l['type'] == 'SKIPPED'] == []
+ assert [l for l in logs if l['type'] not in ("BROKEN", "UNUSUAL", "INFO", "DEBUG", "TRACE", "IO_IN", "IO_OUT")] == []
def test_log_filter(node_factory):
diff --git a/wallet/test/run-wallet.c b/wallet/test/run-wallet.c
index 86962e52..21d3299b 100644
--- a/wallet/test/run-wallet.c
+++ b/wallet/test/run-wallet.c
@@ -850,7 +850,7 @@ struct logger *new_logger(const tal_t *ctx UNNEEDED, struct log_book *record UNN
return NULL;
}
-struct log_book *new_log_book(struct lightningd *ld UNNEEDED, size_t max_mem UNNEEDED)
+struct log_book *new_log_book(struct lightningd *ld UNNEEDED)
{
return NULL;
}
Why this scored 19/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.