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 <rusty@rustcorp.com.au>
Fixes: #5348
Changelog-Added: lightningd: `log-level=debug:<partial-nodeid>` supported to get debug-level logs for everything about a peer.

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

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,

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);
 

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",

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,

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,

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'