lightningd: extend log-level to support filter per-file.

Fixes: #5392
Changelog-Added: config: `log-level` can be specified on a per-logfile basis.

doc/lightningd-config.5.md

@@ -155,11 +155,11 @@ binary.
 
   Specify pid file to write to.
 
-* **log-level**=*LEVEL*\[:*SUBSYSTEM*\]
+* **log-level**=*LEVEL*\[:*SUBSYSTEM*\]\[:*PATH*\]
 
   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 (or *nodeid*) containing that string. This option may be specified multiple times.
+for any subsystem (or *nodeid*) containing that string. If *PATH* is supplied, it means this log-level filter is only applied to that `log-file`, which is useful for creating logs to capture a specific subsystem.  This option may be specified multiple times.
 Subsystems include:
 
   * *lightningd*: The main lightning daemon
@@ -195,8 +195,7 @@ Subsystems include:
   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).
-**log-level=debug:024b9a1fa8** would set debug logging for that channel
+**log-level=debug:024b9a1fa8:/tmp/024b9a1fa8.debug.log** would set debug logging for that channel only on the **log-file=/tmp/024b9a1fa8.debug.log** (or any node id containing that string).
-(or any node id containing that string).
 
 * **log-prefix**=*PREFIX*
 

lightningd/log.c

@@ -639,6 +639,18 @@ static void log_one_line(unsigned int skipped,
 	data->prefix = "\n";
 }
 
+static struct log_file *find_log_file(struct log_book *log_book,
+				      const char *fname)
+{
+	assert(tal_count(log_book->log_files)
+	       == tal_count(log_book->ld->logfiles));
+	for (size_t i = 0; i < tal_count(log_book->log_files); i++) {
+		if (streq(log_book->ld->logfiles[i], fname))
+			return log_book->log_files[i];
+	}
+	return NULL;
+}
+
 char *opt_log_level(const char *arg, struct log_book *log_book)
 {
 	enum log_level level;
@@ -652,7 +664,21 @@ char *opt_log_level(const char *arg, struct log_book *log_book)
 		struct print_filter *f = tal(log_book, struct print_filter);
 		f->prefix = arg + len + 1;
 		f->level = level;
-		list_add_tail(&log_book->print_filters, &f->list);
+
+		/* :<filename> */
+		len = strcspn(f->prefix, ":");
+		if (f->prefix[len]) {
+			struct log_file *lf;
+			lf = find_log_file(log_book, f->prefix + len + 1);
+			if (!lf)
+				return tal_fmt(tmpctx,
+					       "unknown log file %s",
+					       f->prefix + len + 1);
+			f->prefix = tal_strndup(f, f->prefix, len);
+			list_add_tail(&lf->print_filters, &f->list);
+		} else {
+			list_add_tail(&log_book->print_filters, &f->list);
+		}
 	} else {
 		tal_free(log_book->default_print_level);
 		log_book->default_print_level = tal(log_book, enum log_level);

lightningd/test/run-log_filter.c

@@ -0,0 +1,250 @@
+#include "config.h"
+#include <common/node_id.c>
+#include <common/setup.h>
+#include <common/status_levels.c>
+#include <stdio.h>
+
+#define fwrite test_fwrite
+static size_t test_fwrite(const void *ptr, size_t size, size_t nmemb,
+			  FILE *stream);
+#include "../log.c"
+
+/* AUTOGENERATED MOCKS START */
+/* Generated stub for command_fail */
+struct command_result *command_fail(struct command *cmd UNNEEDED, enum jsonrpc_errcode code UNNEEDED,
+				    const char *fmt UNNEEDED, ...)
+
+{ fprintf(stderr, "command_fail called!\n"); abort(); }
+/* Generated stub for command_param_failed */
+struct command_result *command_param_failed(void)
+
+{ fprintf(stderr, "command_param_failed called!\n"); abort(); }
+/* Generated stub for command_success */
+struct command_result *command_success(struct command *cmd UNNEEDED,
+				       struct json_stream *response)
+
+{ fprintf(stderr, "command_success called!\n"); abort(); }
+/* Generated stub for fromwire_bigsize */
+bigsize_t fromwire_bigsize(const u8 **cursor UNNEEDED, size_t *max UNNEEDED)
+{ fprintf(stderr, "fromwire_bigsize called!\n"); abort(); }
+/* Generated stub for fromwire_channel_id */
+bool fromwire_channel_id(const u8 **cursor UNNEEDED, size_t *max UNNEEDED,
+			 struct channel_id *channel_id UNNEEDED)
+{ fprintf(stderr, "fromwire_channel_id called!\n"); abort(); }
+/* Generated stub for json_add_hex_talarr */
+void json_add_hex_talarr(struct json_stream *result UNNEEDED,
+			 const char *fieldname UNNEEDED,
+			 const tal_t *data UNNEEDED)
+{ fprintf(stderr, "json_add_hex_talarr called!\n"); abort(); }
+/* Generated stub for json_add_node_id */
+void json_add_node_id(struct json_stream *response UNNEEDED,
+				const char *fieldname UNNEEDED,
+				const struct node_id *id UNNEEDED)
+{ fprintf(stderr, "json_add_node_id called!\n"); abort(); }
+/* Generated stub for json_add_num */
+void json_add_num(struct json_stream *result UNNEEDED, const char *fieldname UNNEEDED,
+		  unsigned int value UNNEEDED)
+{ fprintf(stderr, "json_add_num called!\n"); abort(); }
+/* Generated stub for json_add_str_fmt */
+void json_add_str_fmt(struct json_stream *js UNNEEDED,
+		      const char *fieldname UNNEEDED,
+		      const char *fmt UNNEEDED, ...)
+{ fprintf(stderr, "json_add_str_fmt called!\n"); abort(); }
+/* Generated stub for json_add_string */
+void json_add_string(struct json_stream *js UNNEEDED,
+		     const char *fieldname UNNEEDED,
+		     const char *str TAKES UNNEEDED)
+{ fprintf(stderr, "json_add_string called!\n"); abort(); }
+/* Generated stub for json_add_time */
+void json_add_time(struct json_stream *result UNNEEDED, const char *fieldname UNNEEDED,
+			  struct timespec ts UNNEEDED)
+{ fprintf(stderr, "json_add_time called!\n"); abort(); }
+/* Generated stub for json_array_end */
+void json_array_end(struct json_stream *js UNNEEDED)
+{ fprintf(stderr, "json_array_end called!\n"); abort(); }
+/* Generated stub for json_array_start */
+void json_array_start(struct json_stream *js UNNEEDED, const char *fieldname UNNEEDED)
+{ fprintf(stderr, "json_array_start called!\n"); abort(); }
+/* Generated stub for json_object_end */
+void json_object_end(struct json_stream *js UNNEEDED)
+{ fprintf(stderr, "json_object_end called!\n"); abort(); }
+/* Generated stub for json_object_start */
+void json_object_start(struct json_stream *ks UNNEEDED, const char *fieldname UNNEEDED)
+{ fprintf(stderr, "json_object_start called!\n"); abort(); }
+/* Generated stub for json_stream_log_suppress_for_cmd */
+void json_stream_log_suppress_for_cmd(struct json_stream *js UNNEEDED,
+					    const struct command *cmd UNNEEDED)
+{ fprintf(stderr, "json_stream_log_suppress_for_cmd called!\n"); abort(); }
+/* Generated stub for json_stream_success */
+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)
+{ fprintf(stderr, "notify_warning called!\n"); abort(); }
+/* Generated stub for param */
+bool param(struct command *cmd UNNEEDED, const char *buffer UNNEEDED,
+	   const jsmntok_t params[] UNNEEDED, ...)
+{ fprintf(stderr, "param called!\n"); abort(); }
+/* Generated stub for towire_bigsize */
+void towire_bigsize(u8 **pptr UNNEEDED, const bigsize_t val UNNEEDED)
+{ fprintf(stderr, "towire_bigsize called!\n"); abort(); }
+/* Generated stub for towire_channel_id */
+void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id UNNEEDED)
+{ fprintf(stderr, "towire_channel_id called!\n"); abort(); }
+/* AUTOGENERATED MOCKS END */
+
+static size_t num_written;
+static size_t test_fwrite(const void *ptr, size_t size, size_t nmemb,
+			  FILE *stream)
+{
+	num_written++;
+	return nmemb;
+}
+
+static size_t try_log(struct log_book *lb, const char *prefix,
+		      const struct node_id *node_id,
+		      enum log_level level)
+{
+	struct logger *log = new_logger(NULL, lb, node_id, "%s", prefix);
+
+	num_written = 0;
+	log_(log, level, NULL, false, "test_log");
+	tal_free(log);
+	return num_written;
+}
+
+int main(int argc, char *argv[])
+{
+	struct log_book *lb;
+	struct node_id node_id;
+	struct lightningd *ld;
+	char tmpfiletemplate[] = "/tmp/run-log_filter.XXXXXX";
+
+	common_setup(argv[0]);
+
+	assert(node_id_from_hexstr("0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518",
+				   strlen("0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518"), &node_id));
+
+	ld = tal(tmpctx, struct lightningd);
+	ld->logfiles = NULL;
+	lb = ld->log_book = new_log_book(ld, 1024*1024);
+	ld->log = new_logger(ld, lb, NULL, "dummy");
+	assert(arg_log_to_file("-", ld) == NULL);
+
+	assert(mkstemp(tmpfiletemplate) >= 0);
+	assert(arg_log_to_file(tmpfiletemplate, ld) == NULL);
+
+	/* Log level default. */
+	assert(opt_log_level("BROKEN", lb) == NULL);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0);
+
+	/* Now use debug as default */
+	assert(opt_log_level("debug", lb) == NULL);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0);
+
+	/* Log level exception for prefix */
+	assert(opt_log_level("broken:prefix2", lb) == NULL);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0);
+
+	assert(try_log(lb, "prefix2", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix2", NULL, LOG_INFORM) == 0);
+	assert(try_log(lb, "prefix2", NULL, LOG_DBG) == 0);
+	assert(try_log(lb, "prefix2", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix2", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix2", &node_id, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix2", &node_id, LOG_INFORM) == 0);
+	assert(try_log(lb, "prefix2", &node_id, LOG_DBG) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0);
+
+	/* Log level exception for nodeid: that only does broken! */
+	assert(opt_log_level("broken:0266e4598", lb) == NULL);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0);
+
+	/* File exceptions: log stdout prefix to stdout */
+	assert(opt_log_level("io:stdout1:-", lb) == NULL);
+	assert(try_log(lb, "stdout1", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_IO_OUT) == 1);
+	assert(try_log(lb, "stdout1", NULL, LOG_IO_IN) == 1);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+
+	/* File exceptions: log stdout2 prefix to stdout */
+	assert(opt_log_level("broken:stdout2:-", lb) == NULL);
+	assert(try_log(lb, "stdout2", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "stdout2", NULL, LOG_INFORM) == 1);
+	assert(try_log(lb, "stdout2", NULL, LOG_DBG) == 1);
+	assert(try_log(lb, "stdout2", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "stdout2", NULL, LOG_IO_IN) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0);
+
+	/* File exception: tmpfile logs everything */
+	assert(opt_log_level(tal_fmt(tmpctx, "io::%s", tmpfiletemplate), lb) == NULL);
+	assert(try_log(lb, "stdout1", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_IO_OUT) == 2);
+	assert(try_log(lb, "stdout1", NULL, LOG_IO_IN) == 2);
+	assert(try_log(lb, "stdout2", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "stdout2", NULL, LOG_INFORM) == 1);
+	assert(try_log(lb, "stdout2", NULL, LOG_DBG) == 1);
+	assert(try_log(lb, "stdout2", NULL, LOG_IO_OUT) == 1);
+	assert(try_log(lb, "stdout2", NULL, LOG_IO_IN) == 1);
+	assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 1);
+	assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 1);
+
+	/* Close output file, avoid upsetting valgrind */
+	fclose(ld->log_book->log_files[1]->f);
+
+	/* Freeing (last) log frees logbook */
+	tal_free(ld->log);
+	common_shutdown();
+}

tests/test_misc.py

@@ -2988,9 +2988,30 @@ def test_getlog(node_factory):
 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']}, {}])
+    l1 = node_factory.get_node(options={'log-level': ['debug', 'broken:022d223620']})
+    l2 = node_factory.get_node(start=False)
 
+    log1 = os.path.join(l2.daemon.lightning_dir, "log")
+    log2 = os.path.join(l2.daemon.lightning_dir, "log2")
+    # We need to set log file before we set options on it.
+    l2.daemon.early_opts += [f'--log-file={l}' for l in [log2] + l2.daemon.opts['log-file']]
+    del l2.daemon.opts['log-file']
+    l2.daemon.opts['log-level'] = ["broken",  # broken messages go everywhere
+                                   f"debug::{log1}",  # debug to normal log
+                                   "debug::-",  # debug to stdout
+                                   f'io:0266e4598d1d3:{log2}']
+    l2.start()
+    node_factory.join_nodes([l1, l2])
+
+    # No debug messages in l1's log
     assert not l1.daemon.is_in_log(r'-chan#[0-9]*:')
+    # FIXME: the connectd messages should also be matched!
+    # assert not l1.daemon.is_in_log(l2.info['id'])
+
+    # Every message in log2 must be about l1...
+    with open(log2, "r") as f:
+        lines = f.readlines()
+    assert all([' {}-'.format(l1.info['id']) in l for l in lines])
 
 
 def test_force_feerates(node_factory):