From f6f1844e15c6573eec6757b83a9ba3a0a41d0f22 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Fri, 8 Jul 2022 19:23:11 +0930 Subject: [PATCH] options: let log-level subsystem filter also cover nodeid. That's useful for "tell me everything about this node" debugging. Signed-off-by: Rusty Russell Fixes: #5348 Changelog-Added: lightningd: `log-level=debug:` supported to get debug-level logs for everything about a peer. --- doc/lightningd-config.5.md | 6 ++++-- lightningd/log.c | 16 +++++++++------- lightningd/log.h | 2 +- lightningd/subd.c | 2 +- lightningd/test/run-find_my_abspath.c | 2 +- lightningd/test/run-shuffle_fds.c | 2 +- tests/test_misc.py | 8 ++++++++ 7 files changed, 25 insertions(+), 13 deletions(-) diff --git a/doc/lightningd-config.5.md b/doc/lightningd-config.5.md index 6049178b5..94060f956 100644 --- a/doc/lightningd-config.5.md +++ b/doc/lightningd-config.5.md @@ -124,7 +124,7 @@ Specify pid file to write to. **log-level**=*LEVEL*\[:*SUBSYSTEM*\] What log level to print out: options are io, debug, info, unusual, broken. If *SUBSYSTEM* is supplied, this sets the logging level -for any subsystem containing that string. This option may be specified multiple times. +for any subsystem (or *nodeid*) containing that string. This option may be specified multiple times. Subsystems include: * *lightningd*: The main lightning daemon @@ -148,7 +148,9 @@ internal integer id assigned for the lifetime of the channel: So, **log-level=debug:plugin** would set debug level logging on all plugins and the plugin manager. **log-level=io:chan#55** would set -IO logging on channel number 55 (or 550, for that matter). +IO logging on channel number 55 (or 550, for that matter). +**log-level=debug:024b9a1fa8** would set debug logging for that channel +(or any node id containing that string). **log-prefix**=*PREFIX* Prefix for log lines: this can be customized if you want to merge logs diff --git a/lightningd/log.c b/lightningd/log.c index ddbcb7267..d86fcbb24 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -291,13 +291,15 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem) } static enum log_level filter_level(struct log_book *lr, - const struct log_prefix *lp) + const struct log_prefix *lp, + const struct node_id *node_id) { struct print_filter *i; + const char *node_id_str = node_id ? node_id_to_hexstr(tmpctx, node_id) : ""; assert(lr->default_print_level != NULL); list_for_each(&lr->print_filters, i, list) { - if (strstr(lp->prefix, i->prefix)) + if (strstr(lp->prefix, i->prefix) || strstr(node_id_str, i->prefix)) return i->level; } return *lr->default_print_level; @@ -331,14 +333,14 @@ const char *log_prefix(const struct log *log) return log->prefix->prefix; } -enum log_level log_print_level(struct log *log) +enum log_level log_print_level(struct log *log, const struct node_id *node_id) { if (!log->print_level) { /* Not set globally yet? Print UNUSUAL / BROKEN messages only */ if (!log->lr->default_print_level) return LOG_UNUSUAL; log->print_level = tal(log, enum log_level); - *log->print_level = filter_level(log->lr, log->prefix); + *log->print_level = filter_level(log->lr, log->prefix, node_id); } return *log->print_level; } @@ -400,7 +402,7 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level, static void maybe_print(struct log *log, const struct log_entry *l) { - if (l->level >= log_print_level(log)) + if (l->level >= log_print_level(log, l->nc ? &l->nc->node_id : NULL)) log_to_files(log->prefix->prefix, l->level, l->nc ? &l->nc->node_id : NULL, &l->time, l->log, @@ -450,7 +452,7 @@ void log_io(struct log *log, enum log_level dir, assert(dir == LOG_IO_IN || dir == LOG_IO_OUT); /* Print first, in case we need to truncate. */ - if (l->level >= log_print_level(log)) + if (l->level >= log_print_level(log, node_id)) log_to_files(log->prefix->prefix, l->level, l->nc ? &l->nc->node_id : NULL, &l->time, str, @@ -758,7 +760,7 @@ void logging_options_parsed(struct log_book *lr) for (size_t i = 0; i < lr->num_entries; i++) { const struct log_entry *l = &lr->log[i]; - if (l->level >= filter_level(lr, l->prefix)) + if (l->level >= filter_level(lr, l->prefix, NULL)) log_to_files(l->prefix->prefix, l->level, l->nc ? &l->nc->node_id : NULL, &l->time, l->log, diff --git a/lightningd/log.h b/lightningd/log.h index 95dc2ada2..a0ebd7cc7 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -44,7 +44,7 @@ void logv(struct log *log, enum log_level level, const struct node_id *node_id, bool call_notifier, const char *fmt, va_list ap); const char *log_prefix(const struct log *log); -enum log_level log_print_level(struct log *log); +enum log_level log_print_level(struct log *log, const struct node_id *node_id); void opt_register_logging(struct lightningd *ld); diff --git a/lightningd/subd.c b/lightningd/subd.c index a959eb1d7..4ee11c1c2 100644 --- a/lightningd/subd.c +++ b/lightningd/subd.c @@ -742,7 +742,7 @@ static struct subd *new_subd(const tal_t *ctx, &msg_fd, /* We only turn on subdaemon io logging if we're going * to print it: too stressful otherwise! */ - log_print_level(sd->log) < LOG_DBG, + log_print_level(sd->log, node_id) < LOG_DBG, ap); if (sd->pid == (pid_t)-1) { log_unusual(ld->log, "subd %s failed: %s", diff --git a/lightningd/test/run-find_my_abspath.c b/lightningd/test/run-find_my_abspath.c index a8805bce7..0a25f7c14 100644 --- a/lightningd/test/run-find_my_abspath.c +++ b/lightningd/test/run-find_my_abspath.c @@ -147,7 +147,7 @@ void log_backtrace_print(const char *fmt UNNEEDED, ...) const char *log_prefix(const struct log *log UNNEEDED) { fprintf(stderr, "log_prefix called!\n"); abort(); } /* Generated stub for log_print_level */ -enum log_level log_print_level(struct log *log UNNEEDED) +enum log_level log_print_level(struct log *log UNNEEDED, const struct node_id *node_id UNNEEDED) { fprintf(stderr, "log_print_level called!\n"); abort(); } /* Generated stub for log_status_msg */ bool log_status_msg(struct log *log UNNEEDED, diff --git a/lightningd/test/run-shuffle_fds.c b/lightningd/test/run-shuffle_fds.c index f26907cb6..0981f69a3 100644 --- a/lightningd/test/run-shuffle_fds.c +++ b/lightningd/test/run-shuffle_fds.c @@ -96,7 +96,7 @@ void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, const char *log_prefix(const struct log *log UNNEEDED) { fprintf(stderr, "log_prefix called!\n"); abort(); } /* Generated stub for log_print_level */ -enum log_level log_print_level(struct log *log UNNEEDED) +enum log_level log_print_level(struct log *log UNNEEDED, const struct node_id *node_id UNNEEDED) { fprintf(stderr, "log_print_level called!\n"); abort(); } /* Generated stub for log_status_msg */ bool log_status_msg(struct log *log UNNEEDED, diff --git a/tests/test_misc.py b/tests/test_misc.py index b93579447..79d74b255 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -2435,6 +2435,14 @@ def test_getlog(node_factory): assert [l for l in logs if l['type'] == 'SKIPPED'] == [] +def test_log_filter(node_factory): + """Test the log-level option with subsystem filters""" + # This actually suppresses debug! + l1, l2 = node_factory.line_graph(2, opts=[{'log-level': ['debug', 'broken:022d223620']}, {}]) + + assert not l1.daemon.is_in_log(r'-chan#[0-9]*:') + + def test_force_feerates(node_factory): l1 = node_factory.get_node(options={'force-feerates': 1111}) assert l1.rpc.listconfigs()['force-feerates'] == '1111'