From c7c304b9dbdff735d79984589b1416de1cf19082 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 8 Dec 2025 12:20:12 +1030 Subject: [PATCH 1/5] gossmap: don't log every time we don't like a cupdate. This happens for about 300 channels, from every process that loads the gossmap. It's not very useful to flood the logs, so just log a summary. To be fair, on my node, this is only the 11th most common message, so we will revisit the others too: ``` 1589311 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-connectd: peer_out WIRE_WARNING 139993 DEBUG lightningd: fixup_scan: block 786151 with 1203 txs 55388 DEBUG plugin-bcli: Log pruned 1001 entries (mem 10508118 -> 10298662) 33000 DEBUG gossipd: Unreasonable timestamp in 0102000a38ec41f9137a5a560dac6effbde059c12cb727344821cbdd4ef46964a4791a0f67cd997499a6062fc8b4284bf1b47a91541fd0e65129505f02e4d08542b16fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000d9d56000ba40001690fe262010100900000000000000001000003e8000001f30000000000989680 23515 DEBUG hsmd: Client: Received message 14 from client 22269 DEBUG 024b9a1fa8e006f1e3937f65f66c408e6da8e1ca728ea43222a7381df1cc449605-hsmd: Got WIRE_HSMD_ECDH_REQ 14409 DEBUG gossipd: Enqueueing update for announce 0102002f7e4b4deb19947c67292e70cb22f7fac837fa9ee6269393f3c513d0431d52672e7387625856c19299cfd584e1a3f39e0f98df13c99090df9f4d5cca8446776fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000e216b0008050001692e1c390101009000000000000003e800000000000013880000004526945a00 12534 DEBUG gossipd: Previously-rejected announce for 514127x248x1 ===> 12092 DEBUG connectd: Bad cupdate for 641641x1164x1/1, ignoring (delta=80, fee=1073742199/58) 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Got it! 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: ... , awaiting 1120 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Sending master 1020 ``` Signed-off-by: Rusty Russell --- common/gossmap.c | 44 +++++++++++++++++++++++--------------------- 1 file changed, 23 insertions(+), 21 deletions(-) diff --git a/common/gossmap.c b/common/gossmap.c index 948ed0b9c4c1..9d52569d5384 100644 --- a/common/gossmap.c +++ b/common/gossmap.c @@ -503,16 +503,14 @@ static struct gossmap_chan *add_channel(struct gossmap *map, return chan; } -/* Does not set hc->nodeidx! */ -static void fill_from_update(struct gossmap *map, +/* Does not set hc->nodeidx! + * Returns false if it doesn't fit in our representation: this happens + * on the real network, as people set absurd fees + */ +static bool fill_from_update(struct gossmap *map, struct short_channel_id_dir *scidd, struct half_chan *hc, - u64 cupdate_off, - void (*logcb)(void *cbarg, - enum log_level level, - const char *fmt, - ...), - void *cbarg) + u64 cupdate_off) { /* Note that first two bytes are message type */ const u64 scid_off = cupdate_off + 2 + (64 + 32); @@ -543,18 +541,15 @@ static void fill_from_update(struct gossmap *map, hc->proportional_fee = proportional_fee; hc->delay = delay; - /* Check they fit: we turn off if not, log (at debug, it happens!). */ + /* Check they fit: we turn off if not. */ if (hc->base_fee != base_fee || hc->proportional_fee != proportional_fee || hc->delay != delay) { hc->htlc_max = 0; hc->enabled = false; - if (logcb) - logcb(cbarg, LOG_DBG, - "Bad cupdate for %s, ignoring (delta=%u, fee=%u/%u)", - fmt_short_channel_id_dir(tmpctx, scidd), - delay, base_fee, proportional_fee); + return false; } + return true; } /* BOLT #7: @@ -572,23 +567,24 @@ static void fill_from_update(struct gossmap *map, * * [`u32`:`fee_proportional_millionths`] * * [`u64`:`htlc_maximum_msat`] */ -static void update_channel(struct gossmap *map, u64 cupdate_off) +static bool update_channel(struct gossmap *map, u64 cupdate_off) { struct short_channel_id_dir scidd; struct gossmap_chan *chan; struct half_chan hc; + bool ret; - fill_from_update(map, &scidd, &hc, cupdate_off, - map->logcb, map->cbarg); + ret = fill_from_update(map, &scidd, &hc, cupdate_off); chan = gossmap_find_chan(map, &scidd.scid); /* This can happen if channel gets deleted! */ if (!chan) - return; + return ret; /* Preserve this */ hc.nodeidx = chan->half[scidd.dir].nodeidx; chan->half[scidd.dir] = hc; chan->cupdate_off[scidd.dir] = cupdate_off; + return ret; } static void remove_channel_by_deletemsg(struct gossmap *map, u64 del_off) @@ -677,7 +673,7 @@ static bool csum_matches(const struct gossmap *map, /* Returns false only if must_be_clean is true. */ static bool map_catchup(struct gossmap *map, bool must_be_clean, bool *changed) { - size_t reclen; + size_t reclen, num_bad_cupdates = 0; *changed = false; @@ -749,7 +745,7 @@ static bool map_catchup(struct gossmap *map, bool must_be_clean, bool *changed) if (redundant && must_be_clean) return false; } else if (type == WIRE_CHANNEL_UPDATE) - update_channel(map, off); + num_bad_cupdates += update_channel(map, off); else if (type == WIRE_GOSSIP_STORE_DELETE_CHAN) remove_channel_by_deletemsg(map, off); else if (type == WIRE_NODE_ANNOUNCEMENT) @@ -775,6 +771,12 @@ static bool map_catchup(struct gossmap *map, bool must_be_clean, bool *changed) *changed = true; } + if (num_bad_cupdates != 0) + map->logcb(map->cbarg, + LOG_DBG, + "Got %zu bad cupdates, ignoring them (expected on mainnet)", + num_bad_cupdates); + return true; } @@ -1168,7 +1170,7 @@ void gossmap_apply_localmods(struct gossmap *map, off = insert_local_space(&map->local_updates, tal_bytelen(cupdatemsg)); memcpy(map->local_updates + off, cupdatemsg, tal_bytelen(cupdatemsg)); chan->cupdate_off[h] = map->map_size + tal_bytelen(map->local_announces) + off; - fill_from_update(map, &scidd, &chan->half[h], chan->cupdate_off[h], NULL, NULL); + fill_from_update(map, &scidd, &chan->half[h], chan->cupdate_off[h]); /* We wrote the right update, correct? */ assert(short_channel_id_eq(scidd.scid, mod->scid)); From 396a189a9f2dbaf72d4f6a47b9bb8f025c9e8778 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 8 Dec 2025 12:31:42 +1030 Subject: [PATCH 2/5] connectd: don't be That Node when someone is gossipping crap. As seen in my logs, we complain about nodes a *lot* (Hi old CLN!). ``` ===>1589311 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-connectd: peer_out WIRE_WARNING 139993 DEBUG lightningd: fixup_scan: block 786151 with 1203 txs 55388 DEBUG plugin-bcli: Log pruned 1001 entries (mem 10508118 -> 10298662) 33000 DEBUG gossipd: Unreasonable timestamp in 0102000a38ec41f9137a5a560dac6effbde059c12cb727344821cbdd4ef46964a4791a0f67cd997499a6062fc8b4284bf1b47a91541fd0e65129505f02e4d08542b16fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000d9d56000ba40001690fe262010100900000000000000001000003e8000001f30000000000989680 23515 DEBUG hsmd: Client: Received message 14 from client 22269 DEBUG 024b9a1fa8e006f1e3937f65f66c408e6da8e1ca728ea43222a7381df1cc449605-hsmd: Got WIRE_HSMD_ECDH_REQ 14409 DEBUG gossipd: Enqueueing update for announce 0102002f7e4b4deb19947c67292e70cb22f7fac837fa9ee6269393f3c513d0431d52672e7387625856c19299cfd584e1a3f39e0f98df13c99090df9f4d5cca8446776fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000e216b0008050001692e1c390101009000000000000003e800000000000013880000004526945a00 12534 DEBUG gossipd: Previously-rejected announce for 514127x248x1 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Got it! 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: ... , awaiting 1120 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Sending master 1020 ``` Signed-off-by: Rusty Russell --- gossipd/gossmap_manage.c | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/gossipd/gossmap_manage.c b/gossipd/gossmap_manage.c index 3227465da5ae..84ae20264b80 100644 --- a/gossipd/gossmap_manage.c +++ b/gossipd/gossmap_manage.c @@ -703,9 +703,16 @@ void gossmap_manage_handle_get_txout_reply(struct gossmap_manage *gm, const u8 * * - MUST ignore the message. */ if (tal_count(outscript) == 0) { - peer_warning(gm, pca->source_peer, - "channel_announcement: no unspent txout %s", - fmt_short_channel_id(tmpctx, scid)); + /* Don't flood them: this happens with pre-25.12 CLN + * nodes, which lost their marbles about some old + * UTXOs. */ + static struct timemono prev; + if (time_greater(timemono_since(prev), time_from_sec(1))) { + peer_warning(gm, pca->source_peer, + "channel_announcement: no unspent txout %s", + fmt_short_channel_id(tmpctx, scid)); + prev = time_mono(); + } goto bad; } From 60fba4241362f6f79df5526d06c56207aae6f8c2 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Tue, 9 Dec 2025 12:12:26 +1030 Subject: [PATCH 3/5] lightningd: move log_prefix and log_entry struct definitions into log.c. They're only exposed because of the notifications, but they are better off with explicit parameters anyway. Signed-off-by: Rusty Russell --- lightningd/log.c | 30 ++++++++++++++++++-- lightningd/log.h | 18 ------------ lightningd/notification.c | 46 ++++++++++++++++++++----------- lightningd/notification.h | 12 ++++++-- lightningd/test/run-log-pruning.c | 12 ++++++-- lightningd/test/run-log_filter.c | 12 ++++++-- 6 files changed, 88 insertions(+), 42 deletions(-) diff --git a/lightningd/log.c b/lightningd/log.c index 8e12a6a13511..8b7a9f20e5e9 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -21,6 +21,24 @@ /* Once we're up and running, this is set up. */ struct logger *crashlog; +/* Reference counted log_prefix. Log entries keep a pointer, and they + * can outlast the log entry point which created them. */ +struct log_prefix { + size_t refcnt; + const char *prefix; +}; + +struct log_entry { + 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; +}; + struct print_filter { /* In list log_book->print_filters / log_file->print_filters */ struct list_node list; @@ -565,7 +583,11 @@ 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); + notify_log(log->log_book->ld, + l->level, + l->time, + l->prefix->prefix, + l->log); } void logv(struct logger *log, enum log_level level, @@ -594,7 +616,11 @@ void logv(struct logger *log, enum log_level level, add_entry(log, &l); if (call_notifier) - notify_warning(log->log_book->ld, l); + notify_warning(log->log_book->ld, + l->level, + l->time, + l->prefix->prefix, + l->log); errno = save_errno; } diff --git a/lightningd/log.h b/lightningd/log.h index c9b5277a3031..a05c77621b31 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -75,24 +75,6 @@ struct command_result *param_loglevel(struct command *cmd, const jsmntok_t *tok, enum log_level **level); -/* Reference counted log_prefix. Log entries keep a pointer, and they - * can outlast the log entry point which created them. */ -struct log_prefix { - size_t refcnt; - const char *prefix; -}; - -struct log_entry { - 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; -}; - /* For options.c's listconfig */ char *opt_log_level(const char *arg, struct log_book *log_book); void json_add_opt_log_levels(struct json_stream *response, struct log_book *log_book); diff --git a/lightningd/notification.c b/lightningd/notification.c index b2adb64eb72c..755a606b17cd 100644 --- a/lightningd/notification.c +++ b/lightningd/notification.c @@ -100,31 +100,38 @@ void notify_disconnect(struct lightningd *ld, const struct node_id *nodeid) /*'warning' is based on LOG_UNUSUAL/LOG_BROKEN level log *(in plugin module, they're 'warn'/'error' level). */ static void warning_notification_serialize(struct json_stream *stream, - struct log_entry *l) + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg) { /* Choose "BROKEN"/"UNUSUAL" to keep consistent with the habit * of plugin. But this may confuses the users who want to 'getlog' * with the level indicated by notifications. It is the duty of a * plugin to eliminate this misunderstanding. */ json_add_string(stream, "level", - l->level == LOG_BROKEN ? "error" + level == LOG_BROKEN ? "error" : "warn"); /* unsuaul/broken event is rare, plugin pay more attentions on * the absolute time, like when channels failed. */ - json_add_timestr(stream, "time", l->time.ts); - json_add_timeiso(stream, "timestamp", l->time); - json_add_string(stream, "source", l->prefix->prefix); - json_add_string(stream, "log", l->log); + json_add_timestr(stream, "time", time.ts); + json_add_timeiso(stream, "timestamp", time); + json_add_string(stream, "source", source); + json_add_string(stream, "log", logmsg); } REGISTER_NOTIFICATION(warning); -void notify_warning(struct lightningd *ld, struct log_entry *l) +void notify_warning(struct lightningd *ld, + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg) { struct jsonrpc_notification *n = notify_start(ld, "warning"); if (!n) return; - warning_notification_serialize(n->stream, l); + warning_notification_serialize(n->stream, level, time, source, logmsg); notify_send(ld, n); } @@ -631,26 +638,33 @@ bool notify_deprecated_oneshot(struct lightningd *ld, REGISTER_NOTIFICATION(deprecated_oneshot); static void log_notification_serialize(struct json_stream *stream, - const struct log_entry *l) + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg) { - json_add_string(stream, "level", log_level_name(l->level)); - json_add_timestr(stream, "time", l->time.ts); - json_add_timeiso(stream, "timestamp", l->time); - json_add_string(stream, "source", l->prefix->prefix); - json_add_string(stream, "log", l->log); + json_add_string(stream, "level", log_level_name(level)); + json_add_timestr(stream, "time", time.ts); + json_add_timeiso(stream, "timestamp", time); + json_add_string(stream, "source", source); + json_add_string(stream, "log", logmsg); } REGISTER_NOTIFICATION(log); -void notify_log(struct lightningd *ld, const struct log_entry *l) +void notify_log(struct lightningd *ld, + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg) { struct jsonrpc_notification *n; n = notify_start(ld, "log"); if (!n) return; - log_notification_serialize(n->stream, l); + log_notification_serialize(n->stream, level, time, source, logmsg); notify_send(ld, n); } diff --git a/lightningd/notification.h b/lightningd/notification.h index 91454a550ceb..7e4c94111695 100644 --- a/lightningd/notification.h +++ b/lightningd/notification.h @@ -27,7 +27,11 @@ void notify_connect(struct lightningd *ld, const struct wireaddr_internal *addr); void notify_disconnect(struct lightningd *ld, const struct node_id *nodeid); -void notify_warning(struct lightningd *ld, struct log_entry *l); +void notify_warning(struct lightningd *ld, + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg); void notify_custommsg(struct lightningd *ld, const struct node_id *peer_id, @@ -120,7 +124,11 @@ bool notify_deprecated_oneshot(struct lightningd *ld, /* Tell this plugin to shutdown: returns true if it was subscribed. */ bool notify_plugin_shutdown(struct lightningd *ld, struct plugin *p); /* Inform the plugin when a log line is emitted */ -void notify_log(struct lightningd *ld, const struct log_entry *l); +void notify_log(struct lightningd *ld, + enum log_level level, + struct timeabs time, + const char *source, + const char *logmsg); void notify_plugin_started(struct lightningd *ld, struct plugin *plugin); void notify_plugin_stopped(struct lightningd *ld, struct plugin *plugin); diff --git a/lightningd/test/run-log-pruning.c b/lightningd/test/run-log-pruning.c index 893c7071b34c..02fcc9a0e5d9 100644 --- a/lightningd/test/run-log-pruning.c +++ b/lightningd/test/run-log-pruning.c @@ -56,10 +56,18 @@ void json_stream_log_suppress_for_cmd(struct json_stream *js UNNEEDED, struct json_stream *json_stream_success(struct command *cmd UNNEEDED) { fprintf(stderr, "json_stream_success called!\n"); abort(); } /* Generated stub for notify_log */ -void notify_log(struct lightningd *ld UNNEEDED, const struct log_entry *l UNNEEDED) +void notify_log(struct lightningd *ld UNNEEDED, + enum log_level level UNNEEDED, + struct timeabs time UNNEEDED, + const char *source UNNEEDED, + const char *logmsg UNNEEDED) { fprintf(stderr, "notify_log called!\n"); abort(); } /* Generated stub for notify_warning */ -void notify_warning(struct lightningd *ld UNNEEDED, struct log_entry *l UNNEEDED) +void notify_warning(struct lightningd *ld UNNEEDED, + enum log_level level UNNEEDED, + struct timeabs time UNNEEDED, + const char *source UNNEEDED, + const char *logmsg UNNEEDED) { fprintf(stderr, "notify_warning called!\n"); abort(); } /* AUTOGENERATED MOCKS END */ diff --git a/lightningd/test/run-log_filter.c b/lightningd/test/run-log_filter.c index b125865439f9..c700eae822cc 100644 --- a/lightningd/test/run-log_filter.c +++ b/lightningd/test/run-log_filter.c @@ -11,7 +11,11 @@ static size_t test_fwrite(const void *ptr, size_t size, size_t nmemb, #include "../log.c" -void notify_log(struct lightningd *ld UNNEEDED, const struct log_entry *l UNNEEDED) +void notify_log(struct lightningd *ld UNNEEDED, + enum log_level level UNNEEDED, + struct timeabs time UNNEEDED, + const char *source UNNEEDED, + const char *logmsg UNNEEDED) { } /* AUTOGENERATED MOCKS START */ @@ -67,7 +71,11 @@ void json_stream_log_suppress_for_cmd(struct json_stream *js UNNEEDED, struct json_stream *json_stream_success(struct command *cmd UNNEEDED) { fprintf(stderr, "json_stream_success called!\n"); abort(); } /* Generated stub for notify_warning */ -void notify_warning(struct lightningd *ld UNNEEDED, struct log_entry *l UNNEEDED) +void notify_warning(struct lightningd *ld UNNEEDED, + enum log_level level UNNEEDED, + struct timeabs time UNNEEDED, + const char *source UNNEEDED, + const char *logmsg UNNEEDED) { fprintf(stderr, "notify_warning called!\n"); abort(); } /* AUTOGENERATED MOCKS END */ From 0fcaf199dcad51074c5b77a3197960b565a589bb Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Tue, 9 Dec 2025 12:13:14 +1030 Subject: [PATCH 4/5] getlog: fix schema. getlog() only gets recent logs, not all of them (since it prunes, and soon will be a ringbuffer). And "data" is actually an optional field, not required. Signed-off-by: Rusty Russell --- contrib/msggen/msggen/schema.json | 5 ++--- doc/schemas/getlog.json | 5 ++--- 2 files changed, 4 insertions(+), 6 deletions(-) diff --git a/contrib/msggen/msggen/schema.json b/contrib/msggen/msggen/schema.json index 8b2e1abc6e7a..4f55ece74539 100644 --- a/contrib/msggen/msggen/schema.json +++ b/contrib/msggen/msggen/schema.json @@ -15010,7 +15010,7 @@ "$schema": "../rpc-schema-draft.json", "type": "object", "rpc": "getlog", - "title": "Command to show logs.", + "title": "Command to show recent logs.", "description": [ "The **getlog** the RPC command to show logs, with optional log *level*." ], @@ -15184,8 +15184,7 @@ "required": [ "time", "source", - "log", - "data" + "log" ], "properties": { "type": {}, diff --git a/doc/schemas/getlog.json b/doc/schemas/getlog.json index 7a81024091ce..db262e48ee23 100644 --- a/doc/schemas/getlog.json +++ b/doc/schemas/getlog.json @@ -2,7 +2,7 @@ "$schema": "../rpc-schema-draft.json", "type": "object", "rpc": "getlog", - "title": "Command to show logs.", + "title": "Command to show recent logs.", "description": [ "The **getlog** the RPC command to show logs, with optional log *level*." ], @@ -176,8 +176,7 @@ "required": [ "time", "source", - "log", - "data" + "log" ], "properties": { "type": {}, From fad257ee2b3a178849f9d23b0e94f0da63a485b5 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Tue, 9 Dec 2025 13:07:35 +1030 Subject: [PATCH 5/5] logging: switch to a simple ringbuffer. We keep a history of logs internally, so we can drop them to disk on a crash. This "black box recorder" was some of the first code I wrote for CLN, but I can't remember the last time we use a crash log to diagnose a problem. We attempt to prune it to keep it under 10MB, but the complexity and cost is rarely worth it: simplify it to use a ringbuffer. Changelog-Changed: lightningd: logging is now more efficient internally (no more pruning, simple ringbuffer). ``` 139993 DEBUG lightningd: fixup_scan: block 786151 with 1203 txs ===> 55388 DEBUG plugin-bcli: Log pruned 1001 entries (mem 10508118 -> 10298662) 33000 DEBUG gossipd: Unreasonable timestamp in 0102000a38ec41f9137a5a560dac6effbde059c12cb727344821cbdd4ef46964a4791a0f67cd997499a6062fc8b4284bf1b47a91541fd0e65129505f02e4d08542b16fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000d9d56000ba40001690fe262010100900000000000000001000003e8000001f30000000000989680 23515 DEBUG hsmd: Client: Received message 14 from client 22269 DEBUG 024b9a1fa8e006f1e3937f65f66c408e6da8e1ca728ea43222a7381df1cc449605-hsmd: Got WIRE_HSMD_ECDH_REQ 14409 DEBUG gossipd: Enqueueing update for announce 0102002f7e4b4deb19947c67292e70cb22f7fac837fa9ee6269393f3c513d0431d52672e7387625856c19299cfd584e1a3f39e0f98df13c99090df9f4d5cca8446776fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d61900000000000e216b0008050001692e1c390101009000000000000003e800000000000013880000004526945a00 12534 DEBUG gossipd: Previously-rejected announce for 514127x248x1 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Got it! 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: ... , awaiting 1120 10761 DEBUG 02e01367e1d7818a7e9a0e8a52badd5c32615e07568dbe0497b6a47f9bef89d6af-channeld-chan#70770: Sending master 1020 ``` Signed-off-by: Rusty Russell --- lightningd/lightningd.c | 6 +- lightningd/log.c | 540 ++++++++++++++------------ lightningd/log.h | 2 +- lightningd/test/run-find_my_abspath.c | 2 +- lightningd/test/run-log-pruning.c | 54 ++- lightningd/test/run-log_filter.c | 2 +- tests/test_misc.py | 6 +- wallet/test/run-wallet.c | 2 +- 8 files changed, 317 insertions(+), 297 deletions(-) diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index e3eff22d5d7b..6722d31309ac 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 8b7a9f20e5e9..a3a2b8384327 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -1,4 +1,5 @@ #include "config.h" +#include #include #include #include @@ -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; ilog[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 a05c77621b31..5a84ef7bea0a 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 80c2a42c60bc..37ff3c1a13ff 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 02fcc9a0e5d9..78c15d08c84d 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(streq(msg, tal_fmt(lb, "test %06zi", i++))); + 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 c700eae822cc..a6da5a6b898d 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 e17d4935fc9c..2255c66cefb5 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -3747,13 +3747,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", "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 69b141472b76..1437854b63f7 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; }