options: allow --log-level <level>:<prefix> for finegrained log control.

This allows finegrained logging control of particular subdaemons or
subsystems.

To do this, we defer setting the logging levels for each log object
until after early argument parsing (since e.g. "bitcoind" log object
is created early).

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-changed: Options: log-level can now specify different levels for different subsystems.

doc/lightningd-config.5

@@ -14,8 +14,8 @@ directory (if it exists), but that can be changed by the
 
 
 Configuration file options are processed first, then command line
-options: later options override earlier ones except \fIaddr\fR options which
+options: later options override earlier ones except \fIaddr\fR options 
-accumulate\.
+and \fIlog-level\fR with subsystems, which accumulate\.
 
 
 All these options are mirrored as commandline arguments to
@@ -119,30 +119,69 @@ Sets the working directory\. All files (except \fI--conf\fR and
 Specify pid file to write to\.
 
 
- \fBlog-level\fR=\fILEVEL\fR
+ \fBlog-level\fR=\fILEVEL\fR[:\fISUBSYSTEM\fR]
 What log level to print out: options are io, debug, info, unusual,
-broken\.
+broken\.  If \fISUBSYSTEM\fR is supplied, this sets the logging level
+for any subsystem containing that string\.  Subsystems include:
 
+.RS
+.IP \[bu]
+\fIlightningd\fR: The main lightning daemon
+.IP \[bu]
+\fIdatabase\fR: The database subsystem
+.IP \[bu]
+\fIwallet\fR: The wallet subsystem
+.IP \[bu]
+\fIgossipd\fR: The gossip daemon
+.IP \[bu]
+\fIplugin-manager\fR: The plugin subsystem
+.IP \[bu]
+\fIplugin-P\fR: Each plugin, P = plugin path without directory
+.IP \[bu]
+\fIhsmd\fR: The secret-holding daemon
+.IP \[bu]
+\fIgossipd\fR: The gossip daemon
+.IP \[bu]
+\fIconnectd\fR: The network connection daemon
+
+.RE
+
+The following subsystems exist for each channel, where N is an incrementing
+internal integer id assigned for the lifetime of the channel:
+
+.RS
+.IP \[bu]
+\fIopeningd-chan #N\fR: Each opening / idling daemon
+.IP \[bu]
+\fIchanneld-chan #N\fR: Each channel management daemon
+.IP \[bu]
+\fIclosingd-chan #N\fR: Each closing negotiation daemon
+.IP \[bu]
+\fIonchaind-chan #N\fR: Each onchain close handling daemon
+.IP \[bu]
 
- \fBlog-prefix\fR=\fIPREFIX\fR
+\fIjson #FD\fR: Each JSONRPC connection, FD = file descriptor number
+
+
+\fBlog-prefix\fR=\fIPREFIX\fR
 Prefix for log lines: this can be customized if you want to merge logs
 with multiple daemons\.
 
 
- \fBlog-file\fR=\fIPATH\fR
+\fBlog-file\fR=\fIPATH\fR
 Log to this file instead of stdout\. Sending \fBlightningd\fR(8) SIGHUP will
 cause it to reopen this file (useful for log rotation)\.
 
 
- \fBrpc-file\fR=\fIPATH\fR
+\fBrpc-file\fR=\fIPATH\fR
 Set JSON-RPC socket (or /dev/tty), such as for \fBlightning-cli\fR(1)\.
 
 
- \fBdaemon\fR
+\fBdaemon\fR
 Run in the background, suppress stdout and stderr\.
 
 
- \fBconf\fR=\fIPATH\fR
+\fBconf\fR=\fIPATH\fR
 Sets configuration file (default: \fBlightning-dir\fR/\fIconfig\fR )\. If this
 is a relative path, it is relative to the starting directory, not
 \fBlightning-dir\fR (unlike other paths)\. \fIPATH\fR must exist and be
@@ -150,17 +189,20 @@ readable (we allow missing files in the default case)\. Using this inside
 a configuration file is meaningless\.
 
 
- \fBwallet\fR=\fIDSN\fR
+\fBwallet\fR=\fIDSN\fR
 Identify the location of the wallet\. This is a fully qualified data source
 name, including a scheme such as \fBsqlite3\fR or \fBpostgres\fR followed by the
 connection parameters\.
 
 
- \fBencrypted-hsm\fR
+\fBencrypted-hsm\fR
 If set, you will be prompted to enter a password used to encrypt the \fBhsm_secret\fR\.
 Note that once you encrypt the \fBhsm_secret\fR this option will be mandatory for
 \fBlightningd\fR to start\.
 
+
+
+.RE
 .SH Lightning node customization options
 
  \fBalias\fR=\fIRRGGBB\fR

doc/lightningd-config.5.md

@@ -15,8 +15,8 @@ directory (if it exists), but that can be changed by the
 *--lightning-dir* or *--conf* options on the lightningd(8) command line.
 
 Configuration file options are processed first, then command line
-options: later options override earlier ones except *addr* options which
+options: later options override earlier ones except *addr* options 
-accumulate.
+and *log-level* with subsystems, which accumulate.
 
 All these options are mirrored as commandline arguments to
 lightningd(8), so *--foo* becomes simply *foo* in the configuration
@@ -103,9 +103,28 @@ Sets the working directory. All files (except *--conf* and
  **pid-file**=*PATH*
 Specify pid file to write to.
 
- **log-level**=*LEVEL*
+ **log-level**=*LEVEL*\[:*SUBSYSTEM*\]
 What log level to print out: options are io, debug, info, unusual,
-broken.
+broken.  If *SUBSYSTEM* is supplied, this sets the logging level
+for any subsystem containing that string.  Subsystems include:
+
+* *lightningd*: The main lightning daemon
+* *database*: The database subsystem
+* *wallet*: The wallet subsystem
+* *gossipd*: The gossip daemon
+* *plugin-manager*: The plugin subsystem
+* *plugin-P*: Each plugin, P = plugin path without directory
+* *hsmd*: The secret-holding daemon
+* *gossipd*: The gossip daemon
+* *connectd*: The network connection daemon
+
+The following subsystems exist for each channel, where N is an incrementing
+internal integer id assigned for the lifetime of the channel:
+* *openingd-chan #N*: Each opening / idling daemon
+* *channeld-chan #N*: Each channel management daemon
+* *closingd-chan #N*: Each closing negotiation daemon
+* *onchaind-chan #N*: Each onchain close handling daemon
+* *json #FD*: Each JSONRPC connection, FD = file descriptor number
 
  **log-prefix**=*PREFIX*
 Prefix for log lines: this can be customized if you want to merge logs

lightningd/lightningd.c

@@ -165,7 +165,7 @@ static struct lightningd *new_lightningd(const tal_t *ctx)
 	 * book to hold all the entries (and trims as necessary), and multiple
 	 * log objects which each can write into it, each with a unique
 	 * prefix. */
-	ld->log_book = new_log_book(ld, 100*1024*1024, LOG_INFORM);
+	ld->log_book = new_log_book(ld, 100*1024*1024);
 	/*~ Note the tal context arg (by convention, the first argument to any
 	 * allocation function): ld->log will be implicitly freed when ld
 	 * is. */

lightningd/log.c

@@ -29,13 +29,26 @@
 #include <sys/types.h>
 #include <unistd.h>
 
+/* What logging level to use if they didn't specify */
+#define DEFAULT_LOGLEVEL LOG_INFORM
+
 /* Once we're up and running, this is set up. */
 struct log *crashlog;
 
+struct print_filter {
+	struct list_node list;
+
+	const char *prefix;
+	enum log_level level;
+};
+
 struct log_book {
 	size_t mem_used;
 	size_t max_mem;
-	enum log_level print_level;
+	struct list_head print_filters;
+
+	/* Non-null once it's been initialized */
+	enum log_level *default_print_level;
 	struct timeabs init_time;
 	FILE *outf;
 
@@ -51,6 +64,9 @@ struct log {
 	struct log_book *lr;
 	const struct node_id *default_node_id;
 	const char *prefix;
+
+	/* Non-NULL once it's been initialized */
+	enum log_level *print_level;
 };
 
 static const char *level_prefix(enum log_level level)
@@ -145,8 +161,7 @@ static size_t prune_log(struct log_book *log)
 	return deleted;
 }
 
-struct log_book *new_log_book(struct lightningd *ld, size_t max_mem,
+struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
-			      enum log_level printlevel)
 {
 	struct log_book *lr = tal_linkable(tal(NULL, struct log_book));
 
@@ -155,7 +170,8 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem,
 	lr->mem_used = 0;
 	lr->max_mem = max_mem;
 	lr->outf = stdout;
-	lr->print_level = printlevel;
+	lr->default_print_level = NULL;
+	list_head_init(&lr->print_filters);
 	lr->init_time = time_now();
 	lr->ld = ld;
 	list_head_init(&lr->log);
@@ -163,6 +179,18 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem,
 	return lr;
 }
 
+static enum log_level filter_level(struct log_book *lr, const char *prefix)
+{
+	struct print_filter *i;
+
+	assert(lr->default_print_level != NULL);
+	list_for_each(&lr->print_filters, i, list) {
+		if (strstr(prefix, i->prefix))
+			return i->level;
+	}
+	return *lr->default_print_level;
+}
+
 /* With different entry points */
 struct log *
 new_log(const tal_t *ctx, struct log_book *record,
@@ -184,14 +212,28 @@ new_log(const tal_t *ctx, struct log_book *record,
 	else
 		log->default_node_id = NULL;
 
+	/* Initialized on first use */
+	log->print_level = NULL;
 	return log;
 }
 
-
 const char *log_prefix(const struct log *log)
 {
 	return log->prefix;
 }
+
+enum log_level log_print_level(struct log *log)
+{
+	if (!log->print_level) {
+		/* Not set globally yet?  Print BROKEN messages only */
+		if (!log->lr->default_print_level)
+			return LOG_BROKEN;
+		log->print_level = tal(log, enum log_level);
+		*log->print_level = filter_level(log->lr, log->prefix);
+	}
+	return *log->print_level;
+}
+
 static void add_entry(struct log *log, struct log_entry *l)
 {
 	log->lr->mem_used += mem_used(l);
@@ -225,10 +267,10 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level,
 	return l;
 }
 
-static void maybe_print(const struct log *log, const struct log_entry *l,
+static void maybe_print(struct log *log, const struct log_entry *l,
 			size_t offset)
 {
-	if (l->level >= log->lr->print_level)
+	if (l->level >= log_print_level(log))
 		log_to_file(log->prefix, l->level, l->node_id, offset != 0,
 			    &l->time, l->log + offset,
 			    l->io, tal_bytelen(l->io), log->lr->outf);
@@ -272,7 +314,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->lr->print_level)
+	if (l->level >= log_print_level(log))
 		log_to_file(log->prefix, l->level, l->node_id, false,
 			    &l->time, str,
 			    data, len, log->lr->outf);
@@ -415,7 +457,7 @@ static void log_one_line(unsigned int skipped,
 	data->prefix = "\n";
 }
 
-static struct {
+static const struct level {
 	const char *name;
 	enum log_level level;
 } log_levels[] = {
@@ -426,30 +468,69 @@ static struct {
 	{ "BROKEN", LOG_BROKEN }
 };
 
-static char *arg_log_level(const char *arg, struct log *log)
+static const struct level *str_to_level(const char *str, size_t len)
 {
-	size_t i;
+	for (size_t i = 0; i < ARRAY_SIZE(log_levels); i++) {
+		if (strlen(log_levels[i].name) != len)
+			continue;
+		if (strncasecmp(str, log_levels[i].name, len) != 0)
+			continue;
+		return &log_levels[i];
+	}
+	return NULL;
+}
 
-	for (i = 0; i < ARRAY_SIZE(log_levels); i++) {
+static const char *level_to_str(enum log_level level)
-		if (strcasecmp(arg, log_levels[i].name) == 0) {
+{
-			log->lr->print_level = log_levels[i].level;
+	for (size_t i = 0; i < ARRAY_SIZE(log_levels); i++) {
+		if (level == log_levels[i].level)
+			return log_levels[i].name;
+	}
 	return NULL;
+}
+
+char *opt_log_level(const char *arg, struct log *log)
+{
+	const struct level *level;
+	int len;
+
+	len = strcspn(arg, ":");
+	level = str_to_level(arg, len);
+	if (!level)
+		return tal_fmt(NULL, "unknown log level %.*s", len, arg);
+
+	if (arg[len]) {
+		struct print_filter *f = tal(log->lr, struct print_filter);
+		f->prefix = arg + len + 1;
+		f->level = level->level;
+		list_add_tail(&log->lr->print_filters, &f->list);
+	} else {
+		tal_free(log->lr->default_print_level);
+		log->lr->default_print_level = tal(log->lr, enum log_level);
+		*log->lr->default_print_level = level->level;
 	}
+	return NULL;
+}
+
+void json_add_opt_log_levels(struct json_stream *response, struct log *log)
+{
+	struct print_filter *i;
+
+	list_for_each(&log->lr->print_filters, i, list) {
+		json_add_member(response, "log-level", true, "%s:%s",
+				level_to_str(i->level), i->prefix);
 	}
-	return tal_fmt(NULL, "unknown log level");
 }
 
 static void show_log_level(char buf[OPT_SHOW_LEN], const struct log *log)
 {
-	size_t i;
+	enum log_level l;
 
-	for (i = 0; i < ARRAY_SIZE(log_levels); i++) {
+	if (log->lr->default_print_level)
-		if (log->lr->print_level == log_levels[i].level) {
+		l = *log->lr->default_print_level;
-			strncpy(buf, log_levels[i].name, OPT_SHOW_LEN-1);
+	else
-			return;
+		l = DEFAULT_LOGLEVEL;
-		}
+	strncpy(buf, level_to_str(l), OPT_SHOW_LEN-1);
-	}
-	abort();
 }
 
 static char *arg_log_prefix(const char *arg, struct log *log)
@@ -516,7 +597,6 @@ static void setup_log_rotation(struct lightningd *ld)
 
 char *arg_log_to_file(const char *arg, struct lightningd *ld)
 {
-	const struct log_entry *i;
 	int size;
 
 	if (ld->logfile) {
@@ -535,10 +615,6 @@ char *arg_log_to_file(const char *arg, struct lightningd *ld)
 	if (size > 0)
 		fprintf(ld->log->lr->outf, "\n\n\n\n");
 
-	/* Catch up */
-	list_for_each(&ld->log->lr->log, i, list)
-		maybe_print(ld->log, i, 0);
-
 	log_debug(ld->log, "Opened log file %s", arg);
 	return NULL;
 }
@@ -546,8 +622,8 @@ char *arg_log_to_file(const char *arg, struct lightningd *ld)
 void opt_register_logging(struct lightningd *ld)
 {
 	opt_register_early_arg("--log-level",
-			       arg_log_level, show_log_level, ld->log,
+			       opt_log_level, show_log_level, ld->log,
-			       "log level (io, debug, info, unusual, broken)");
+			       "log level (io, debug, info, unusual, broken) [:prefix]");
 	opt_register_early_arg("--log-prefix", arg_log_prefix, show_log_prefix,
 			       ld->log,
 			       "log prefix");
@@ -555,6 +631,25 @@ void opt_register_logging(struct lightningd *ld)
 			       "log to file instead of stdout");
 }
 
+void logging_options_parsed(struct log_book *lr)
+{
+	const struct log_entry *l;
+
+	/* If they didn't set an explicit level, set to info */
+	if (!lr->default_print_level) {
+		lr->default_print_level = tal(lr, enum log_level);
+		*lr->default_print_level = DEFAULT_LOGLEVEL;
+	}
+
+	/* Catch up, since before we were only printing BROKEN msgs */
+	list_for_each(&lr->log, l, list) {
+		if (l->level >= filter_level(lr, l->prefix))
+			log_to_file(l->prefix, l->level, l->node_id, false,
+				    &l->time, l->log,
+				    l->io, tal_bytelen(l->io), lr->outf);
+	}
+}
+
 void log_backtrace_print(const char *fmt, ...)
 {
 	va_list ap;

lightningd/log.h

@@ -18,8 +18,7 @@ struct timerel;
 
 /* We can have a single log book, with multiple logs in it: it's freed
  * by the last struct log itself. */
-struct log_book *new_log_book(struct lightningd *ld, size_t max_mem,
+struct log_book *new_log_book(struct lightningd *ld, size_t max_mem);
-			      enum log_level printlevel);
 
 /* With different entry points */
 struct log *new_log(const tal_t *ctx, struct log_book *record,
@@ -52,6 +51,7 @@ void logv(struct log *log, enum log_level level, const struct node_id *node_id,
 void logv_add(struct log *log, const char *fmt, va_list ap);
 
 const char *log_prefix(const struct log *log);
+enum log_level log_print_level(struct log *log);
 
 void opt_register_logging(struct lightningd *ld);
 
@@ -88,4 +88,8 @@ struct log_entry {
 	const u8 *io;
 };
 
+/* For options.c's listconfig */
+char *opt_log_level(const char *arg, struct log *log);
+void json_add_opt_log_levels(struct json_stream *response, struct log *log);
+void logging_options_parsed(struct log_book *lr);
 #endif /* LIGHTNING_LIGHTNINGD_LOG_H */

lightningd/options.c

@@ -1194,6 +1194,9 @@ void handle_early_opts(struct lightningd *ld, int argc, char *argv[])
 
 	/* Now we know what network we're on, initialize defaults. */
 	setup_default_config(ld);
+
+	/* Finalize the logging subsystem now. */
+	logging_options_parsed(ld->log_book);
 }
 
 void handle_opts(struct lightningd *ld, int argc, char *argv[])
@@ -1351,6 +1354,8 @@ static void add_config(struct lightningd *ld,
 				answer = fmt_wireaddr(name0, ld->proxyaddr);
 		} else if (opt->cb_arg == (void *)opt_add_plugin) {
 			json_add_opt_plugins(response, ld->plugins);
+		} else if (opt->cb_arg == (void *)opt_log_level) {
+			json_add_opt_log_levels(response, ld->log);
 		} else if (opt->cb_arg == (void *)opt_add_plugin_dir
 			   || opt->cb_arg == (void *)opt_disable_plugin
 			   || opt->cb_arg == (void *)plugin_opt_set) {

lightningd/test/run-find_my_abspath.c

@@ -135,8 +135,7 @@ struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED,
 		    const char *fmt UNNEEDED, ...)
 { fprintf(stderr, "new_log 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, size_t max_mem UNNEEDED)
-			      enum log_level printlevel UNNEEDED)
 { fprintf(stderr, "new_log_book called!\n"); abort(); }
 /* Generated stub for new_topology */
 struct chain_topology *new_topology(struct lightningd *ld UNNEEDED, struct log *log UNNEEDED)

lightningd/test/run-invoice-select-inchan.c

@@ -179,12 +179,6 @@ void json_add_log(struct json_stream *result UNNEEDED,
 		  const struct node_id *node_id UNNEEDED,
 		  enum log_level minlevel UNNEEDED)
 { fprintf(stderr, "json_add_log called!\n"); abort(); }
-/* Generated stub for json_add_member */
-void json_add_member(struct json_stream *js UNNEEDED,
-		     const char *fieldname UNNEEDED,
-		     bool quote UNNEEDED,
-		     const char *fmt UNNEEDED, ...)
-{ fprintf(stderr, "json_add_member called!\n"); abort(); }
 /* Generated stub for json_add_node_id */
 void json_add_node_id(struct json_stream *response UNNEEDED,
 				const char *fieldname UNNEEDED,

wallet/test/run-wallet.c

@@ -252,12 +252,6 @@ void json_add_log(struct json_stream *result UNNEEDED,
 		  const struct node_id *node_id UNNEEDED,
 		  enum log_level minlevel UNNEEDED)
 { fprintf(stderr, "json_add_log called!\n"); abort(); }
-/* Generated stub for json_add_member */
-void json_add_member(struct json_stream *js UNNEEDED,
-		     const char *fieldname UNNEEDED,
-		     bool quote UNNEEDED,
-		     const char *fmt UNNEEDED, ...)
-{ fprintf(stderr, "json_add_member called!\n"); abort(); }
 /* Generated stub for json_add_node_id */
 void json_add_node_id(struct json_stream *response UNNEEDED,
 				const char *fieldname UNNEEDED,
@@ -703,8 +697,7 @@ struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED,
 	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, size_t max_mem UNNEEDED)
-			      enum log_level printlevel UNNEEDED)
 {
 	return NULL;
 }