lightningd: have logging include an optional node_id for each entry.

A log can have a default node_id, which can be overridden on a per-entry
basis.  This changes the format of logging, so some tests need rework.

Signed-off-by: Rusty Russell <[email protected]>

contrib/pyln-testing/pyln/testing/utils.py

@@ -732,9 +732,13 @@ def fund_channel(self, l2, amount, wait_for_active=True):
                                      'to CHANNELD_NORMAL'])
         return scid
 
-    def subd_pid(self, subd):
+    def subd_pid(self, subd, peerid=None):
         """Get the process id of the given subdaemon, eg channeld or gossipd"""
-        ex = re.compile(r'lightning_{}.*: pid ([0-9]*),'.format(subd))
+        if peerid:
+            ex = re.compile(r'{}-.*lightning_{}.*: pid ([0-9]*),'
+                            .format(peerid, subd))
+        else:
+            ex = re.compile('lightning_{}-.*: pid ([0-9]*),'.format(subd))
         # Make sure we get latest one if it's restarted!
         for l in reversed(self.daemon.logs):
             group = ex.search(l)
@@ -1024,7 +1028,7 @@ def line_graph(self, num_nodes, fundchannel=True, fundamount=10**6, wait_for_ann
         # getpeers.
         if not fundchannel:
             for src, dst in connections:
-                dst.daemon.wait_for_log('openingd-{} chan #[0-9]*: Handed peer, entering loop'.format(src.info['id']))
+                dst.daemon.wait_for_log(r'{}-.*lightning_openingd-chan #[0-9]*: Handed peer, entering loop'.format(src.info['id']))
             return nodes
 
         # If we got here, we want to fund channels

lightningd/channel.c

@@ -209,14 +209,11 @@ struct channel *new_channel(struct peer *peer, u64 dbid,
 
 	if (!log) {
 		/* FIXME: update log prefix when we get scid */
-		/* FIXME: Use minimal unique pubkey prefix for logs! */
-		const char *idname = type_to_string(peer,
-						    struct node_id,
-						    &peer->id);
 		channel->log = new_log(channel,
-				       peer->log_book, "%s chan #%"PRIu64":",
-				       idname, dbid);
-		tal_free(idname);
+				       peer->log_book,
+				       &channel->peer->id,
+				       "chan #%"PRIu64":",
+				       dbid);
 	} else
 		channel->log = tal_steal(channel, log);
 	channel->channel_flags = channel_flags;

lightningd/json_stream.c

@@ -209,7 +209,7 @@ static struct io_plan *json_stream_output_write(struct io_conn *conn,
 
 	js->reader = conn;
 	if (js->log)
-		log_io(js->log, LOG_IO_OUT, "", p, js->len_read);
+		log_io(js->log, LOG_IO_OUT, NULL, "", p, js->len_read);
 	return io_write(conn,
 			p, js->len_read,
 			json_stream_output_write, js);

lightningd/jsonrpc.c

@@ -531,7 +531,7 @@ void json_stream_log_suppress_for_cmd(struct json_stream *js,
 {
 	const char *nm = cmd->json_cmd->name;
 	const char *s = tal_fmt(tmpctx, "Suppressing logging of %s command", nm);
-	log_io(cmd->jcon->log, LOG_IO_OUT, s, NULL, 0);
+	log_io(cmd->jcon->log, LOG_IO_OUT, NULL, s, NULL, 0);
 	json_stream_log_suppress(js, strdup(nm));
 
 }
@@ -828,7 +828,7 @@ static struct io_plan *read_json(struct io_conn *conn,
 	bool valid;
 
 	if (jcon->len_read)
-		log_io(jcon->log, LOG_IO_IN, "",
+		log_io(jcon->log, LOG_IO_IN, NULL, "",
 		       jcon->buffer + jcon->used, jcon->len_read);
 
 	/* Resize larger if we're full. */
@@ -903,7 +903,7 @@ static struct io_plan *jcon_connected(struct io_conn *conn,
 	list_head_init(&jcon->commands);
 
 	/* We want to log on destruction, so we free this in destructor. */
-	jcon->log = new_log(ld->log_book, ld->log_book, "%sjcon fd %i:",
+	jcon->log = new_log(ld->log_book, ld->log_book, NULL, "%sjcon fd %i:",
 			    log_prefix(ld->log), io_conn_fd(conn));
 
 	tal_add_destructor(jcon, destroy_jcon);
@@ -1011,7 +1011,7 @@ void jsonrpc_setup(struct lightningd *ld)
 	ld->jsonrpc = tal(ld, struct jsonrpc);
 	strmap_init(&ld->jsonrpc->usagemap);
 	ld->jsonrpc->commands = tal_arr(ld->jsonrpc, struct json_command *, 0);
-	ld->jsonrpc->log = new_log(ld->jsonrpc, ld->log_book, "jsonrpc");
+	ld->jsonrpc->log = new_log(ld->jsonrpc, ld->log_book, NULL, "jsonrpc");
 	for (size_t i=0; i<num_cmdlist; i++) {
 		if (!jsonrpc_command_add_perm(ld, ld->jsonrpc, commands[i]))
 			fatal("Cannot add duplicate command %s",

lightningd/lightningd.c

@@ -169,7 +169,8 @@ static struct lightningd *new_lightningd(const tal_t *ctx)
 	/*~ Note the tal context arg (by convention, the first argument to any
 	 * allocation function): ld->log will be implicitly freed when ld
 	 * is. */
-	ld->log = new_log(ld, ld->log_book, "lightningd(%u):", (int)getpid());
+	ld->log = new_log(ld, ld->log_book, NULL,
+			  "lightningd(%u):", (int)getpid());
 	ld->logfile = NULL;
 
 	/*~ We explicitly set these to NULL: if they're still NULL after option

lightningd/log.c

@@ -52,6 +52,7 @@ static const char *level_prefix(enum log_level level)
 
 static void log_to_file(const char *prefix,
 			enum log_level level,
+			const struct node_id *node_id,
 			bool continued,
 			const struct timeabs *time,
 			const char *str,
@@ -67,11 +68,24 @@ static void log_to_file(const char *prefix,
 	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
 		const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
 		char *hex = tal_hexstr(NULL, io, io_len);
-		fprintf(logf, "%s %s%s%s %s\n",
-			iso8601_s, prefix, str, dir, hex);
+		if (!node_id)
+			fprintf(logf, "%s %s%s%s %s\n",
+				iso8601_s, prefix, str, dir, hex);
+		else
+			fprintf(logf, "%s %s-%s%s%s %s\n",
+				iso8601_s,
+				node_id_to_hexstr(tmpctx, node_id),
+				prefix, str, dir, hex);
 		tal_free(hex);
 	} else if (!continued) {
-		fprintf(logf, "%s %s %s %s\n", iso8601_s, level_prefix(level), prefix, str);
+		if (!node_id)
+			fprintf(logf, "%s %s %s %s\n",
+				iso8601_s, level_prefix(level), prefix, str);
+		else
+			fprintf(logf, "%s %s %s-%s %s\n",
+				iso8601_s, level_prefix(level),
+				node_id_to_hexstr(tmpctx, node_id),
+				prefix, str);
 	} else {
 		fprintf(logf, "%s %s \t%s\n", iso8601_s, prefix, str);
 	}
@@ -80,13 +94,14 @@ static void log_to_file(const char *prefix,
 
 static void log_to_stdout(const char *prefix,
 			  enum log_level level,
+			  const struct node_id *node_id,
 			  bool continued,
 			  const struct timeabs *time,
 			  const char *str,
 			  const u8 *io, size_t io_len,
 			  void *unused UNUSED)
 {
-	log_to_file(prefix, level, continued, time, str, io, io_len, stdout);
+	log_to_file(prefix, level, node_id, continued, time, str, io, io_len, stdout);
 }
 
 static size_t mem_used(const struct log_entry *e)
@@ -141,7 +156,9 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem,
 
 /* With different entry points */
 struct log *
-new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...)
+new_log(const tal_t *ctx, struct log_book *record,
+	const struct node_id *default_node_id,
+	const char *fmt, ...)
 {
 	struct log *log = tal(ctx, struct log);
 	va_list ap;
@@ -152,6 +169,11 @@ new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...)
 	/* FIXME: Refcount this! */
 	log->prefix = notleak(tal_vfmt(log->lr, fmt, ap));
 	va_end(ap);
+	if (default_node_id)
+		log->default_node_id = tal_dup(log, struct node_id,
+					       default_node_id);
+	else
+		log->default_node_id = NULL;
 
 	return log;
 }
@@ -180,6 +202,7 @@ void set_log_prefix(struct log *log, const char *prefix)
 void set_log_outfn_(struct log_book *lr,
 		    void (*print)(const char *prefix,
 				  enum log_level level,
+				  const struct node_id *node,
 				  bool continued,
 				  const struct timeabs *time,
 				  const char *str,
@@ -224,7 +247,8 @@ static void add_entry(struct log *log, struct log_entry *l)
 	}
 }
 
-static struct log_entry *new_log_entry(struct log *log, enum log_level level)
+static struct log_entry *new_log_entry(struct log *log, enum log_level level,
+				       const struct node_id *node_id)
 {
 	struct log_entry *l = tal(log->lr, struct log_entry);
 
@@ -233,6 +257,12 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level)
 	l->skipped = 0;
 	l->prefix = log->prefix;
 	l->io = NULL;
+	if (!node_id)
+		node_id = log->default_node_id;
+	if (node_id)
+		l->node_id = tal_dup(l, struct node_id, node_id);
+	else
+		l->node_id = NULL;
 
 	return l;
 }
@@ -241,16 +271,18 @@ static void maybe_print(const struct log *log, const struct log_entry *l,
 			size_t offset)
 {
 	if (l->level >= log->lr->print_level)
-		log->lr->print(log->prefix, l->level, offset != 0,
+		log->lr->print(log->prefix, l->level, l->node_id, offset != 0,
 			       &l->time, l->log + offset,
 			       l->io, tal_bytelen(l->io), log->lr->print_arg);
 }
 
-void logv(struct log *log, enum log_level level, bool call_notifier,
-			const char *fmt, va_list ap)
+void logv(struct log *log, enum log_level level,
+	  const struct node_id *node_id,
+	  bool call_notifier,
+	  const char *fmt, va_list ap)
 {
 	int save_errno = errno;
-	struct log_entry *l = new_log_entry(log, level);
+	struct log_entry *l = new_log_entry(log, level, node_id);
 
 	l->log = tal_vfmt(l, fmt, ap);
 
@@ -272,17 +304,18 @@ void logv(struct log *log, enum log_level level, bool call_notifier,
 }
 
 void log_io(struct log *log, enum log_level dir,
+	    const struct node_id *node_id,
 	    const char *str TAKES,
 	    const void *data TAKES, size_t len)
 {
 	int save_errno = errno;
-	struct log_entry *l = new_log_entry(log, dir);
+	struct log_entry *l = new_log_entry(log, dir, node_id);
 
 	assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);
 
 	/* Print first, in case we need to truncate. */
 	if (l->level >= log->lr->print_level)
-		log->lr->print(log->prefix, l->level, false,
+		log->lr->print(log->prefix, l->level, l->node_id, false,
 			       &l->time, str,
 			       data, len, log->lr->print_arg);
 
@@ -320,13 +353,15 @@ void logv_add(struct log *log, const char *fmt, va_list ap)
 	maybe_print(log, l, oldlen);
 }
 
-void log_(struct log *log, enum log_level level, bool call_notifier,
-			const char *fmt, ...)
+void log_(struct log *log, enum log_level level,
+	  const struct node_id *node_id,
+	  bool call_notifier,
+	  const char *fmt, ...)
 {
 	va_list ap;
 
 	va_start(ap, fmt);
-	logv(log, level, call_notifier, fmt, ap);
+	logv(log, level, node_id, call_notifier, fmt, ap);
 	va_end(ap);
 }
 
@@ -343,6 +378,7 @@ void log_each_line_(const struct log_book *lr,
 		    void (*func)(unsigned int skipped,
 				 struct timerel time,
 				 enum log_level level,
+				 const struct node_id *node_id,
 				 const char *prefix,
 				 const char *log,
 				 const u8 *io,
@@ -353,7 +389,7 @@ void log_each_line_(const struct log_book *lr,
 
 	list_for_each(&lr->log, i, list) {
 		func(i->skipped, time_between(i->time, lr->init_time),
-		     i->level, i->prefix, i->log, i->io, arg);
+		     i->level, i->node_id, i->prefix, i->log, i->io, arg);
 	}
 }
 
@@ -365,6 +401,7 @@ struct log_data {
 static void log_one_line(unsigned int skipped,
 			 struct timerel diff,
 			 enum log_level level,
+			 const struct node_id *node_id,
 			 const char *prefix,
 			 const char *log,
 			 const u8 *io,
@@ -561,7 +598,7 @@ void log_backtrace_print(const char *fmt, ...)
 		return;
 
 	va_start(ap, fmt);
-	logv(crashlog, LOG_BROKEN, false, fmt, ap);
+	logv(crashlog, LOG_BROKEN, NULL, false, fmt, ap);
 	va_end(ap);
 }
 
@@ -634,7 +671,7 @@ void fatal(const char *fmt, ...)
 		exit(1);
 
 	va_start(ap, fmt);
-	logv(crashlog, LOG_BROKEN, true, fmt, ap);
+	logv(crashlog, LOG_BROKEN, NULL, true, fmt, ap);
 	va_end(ap);
 	abort();
 }
@@ -659,6 +696,7 @@ static void add_skipped(struct log_info *info)
 static void log_to_json(unsigned int skipped,
 			struct timerel diff,
 			enum log_level level,
+			const struct node_id *node_id,
 			const char *prefix,
 			const char *log,
 			const u8 *io,
@@ -683,6 +721,8 @@ static void log_to_json(unsigned int skipped,
 			: level == LOG_IO_OUT ? "IO_OUT"
 			: "UNKNOWN");
 	json_add_time(info->response, "time", diff.ts);
+	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);
 	if (io)