Log categories

channeld/test/run-commit_tx.c

@@ -27,7 +27,9 @@ size_t bigsize_get(const u8 *p UNNEEDED, size_t max UNNEEDED, bigsize_t *val UNN
 size_t bigsize_put(u8 buf[BIGSIZE_MAX_LEN] UNNEEDED, bigsize_t v UNNEEDED)
 { fprintf(stderr, "bigsize_put called!\n"); abort(); }
 /* Generated stub for status_fmt */
-void status_fmt(enum log_level level UNNEEDED, const char *fmt UNNEEDED, ...)
+void status_fmt(enum log_level level UNNEEDED,
+		const struct node_id *peer UNNEEDED,
+		const char *fmt UNNEEDED, ...)
 
 { fprintf(stderr, "status_fmt called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */

channeld/test/run-full_channel.c

@@ -32,7 +32,9 @@ void status_failed(enum status_failreason code UNNEEDED,
 { fprintf(stderr, "status_failed called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
-void status_fmt(enum log_level level UNUSED, const char *fmt, ...)
+void status_fmt(enum log_level level UNUSED,
+		const struct node_id *node_id,
+		const char *fmt, ...)
 {
 	va_list ap;
 

common/crypto_sync.c

@@ -22,7 +22,7 @@ void sync_crypto_write(struct per_peer_state *pps, const void *msg TAKES)
 #endif
 	u8 *enc;
 
-	status_peer_io(LOG_IO_OUT, msg);
+	status_peer_io(LOG_IO_OUT, NULL, msg);
 	enc = cryptomsg_encrypt_msg(NULL, &pps->cs, msg);
 
 #if DEVELOPER
@@ -124,7 +124,7 @@ u8 *sync_crypto_read(const tal_t *ctx, struct per_peer_state *pps)
 	if (!dec)
 		peer_failed_connection_lost();
 	else
-		status_peer_io(LOG_IO_IN, dec);
+		status_peer_io(LOG_IO_IN, NULL, dec);
 
 	return dec;
 }

common/status.c

@@ -18,7 +18,7 @@
 static int status_fd = -1;
 static struct daemon_conn *status_conn;
 volatile bool logging_io = false;
-static bool was_logging_io = false;
+static bool was_logging_io;
 
 /* If we're more than this many msgs deep, don't add debug messages. */
 #define TRACE_QUEUE_LIMIT 20
@@ -33,6 +33,9 @@ static void setup_logging_sighandler(void)
 {
 	struct sigaction act;
 
+	/* Could have been set to true by --log-io arg. */
+	was_logging_io = logging_io;
+
 	memset(&act, 0, sizeof(act));
 	act.sa_handler = got_sigusr1;
 	act.sa_flags = SA_RESTART;
@@ -55,10 +58,6 @@ void status_setup_sync(int fd)
 	assert(!status_conn);
 	status_fd = fd;
 	setup_logging_sighandler();
-#if DEVELOPER
-	logging_io = (getenv("LIGHTNINGD_DEV_LOG_IO") != NULL);
-	report_logging_io("LIGHTNINGD_DEV_LOG_IO");
-#endif
 }
 
 static void destroy_daemon_conn(struct daemon_conn *dc UNUSED)
@@ -75,10 +74,6 @@ void status_setup_async(struct daemon_conn *master)
 	tal_add_destructor(master, destroy_daemon_conn);
 
 	setup_logging_sighandler();
-#if DEVELOPER
-	logging_io = (getenv("LIGHTNINGD_DEV_LOG_IO") != NULL);
-	report_logging_io("LIGHTNINGD_DEV_LOG_IO");
-#endif
 }
 
 void status_send(const u8 *msg TAKES)
@@ -93,39 +88,49 @@ void status_send(const u8 *msg TAKES)
 	}
 }
 
-static void status_io_full(enum log_level iodir, const char *who, const u8 *p)
+static void status_io_full(enum log_level iodir,
+			   const struct node_id *peer,
+			   const char *who, const u8 *p)
 {
-	status_send(take(towire_status_io(NULL, iodir, who, p)));
+	status_send(take(towire_status_io(NULL, iodir, peer, who, p)));
 }
 
-static void status_peer_io_short(enum log_level iodir, const u8 *p)
+static void status_peer_io_short(enum log_level iodir,
+				 const struct node_id *peer,
+				 const u8 *p)
 {
-	status_debug("%s %s",
-		     iodir == LOG_IO_OUT ? "peer_out" : "peer_in",
-		     wire_type_name(fromwire_peektype(p)));
+	status_peer_debug(peer, "%s %s",
+			  iodir == LOG_IO_OUT ? "peer_out" : "peer_in",
+			  wire_type_name(fromwire_peektype(p)));
 }
 
-void status_peer_io(enum log_level iodir, const u8 *p)
+void status_peer_io(enum log_level iodir,
+		    const struct node_id *peer,
+		    const u8 *p)
 {
 	report_logging_io("SIGUSR1");
 	if (logging_io)
-		status_io_full(iodir, "", p);
+		status_io_full(iodir, NULL, "", p);
 	/* We get a huge amount of gossip; don't log it */
 	else if (!is_msg_for_gossipd(p))
-		status_peer_io_short(iodir, p);
+		status_peer_io_short(iodir, peer, p);
 }
 
-void status_io(enum log_level iodir, const char *who,
+void status_io(enum log_level iodir,
+	       const struct node_id *peer,
+	       const char *who,
 	       const void *data, size_t len)
 {
 	report_logging_io("SIGUSR1");
 	if (!logging_io)
 		return;
 	/* Horribly inefficient, but so is logging IO generally. */
-	status_io_full(iodir, who, tal_dup_arr(tmpctx, u8, data, len, 0));
+	status_io_full(iodir, peer, who, tal_dup_arr(tmpctx, u8, data, len, 0));
 }
 
-void status_vfmt(enum log_level level, const char *fmt, va_list ap)
+void status_vfmt(enum log_level level,
+		 const struct node_id *peer,
+		 const char *fmt, va_list ap)
 {
 	char *str;
 
@@ -146,16 +151,18 @@ void status_vfmt(enum log_level level, const char *fmt, va_list ap)
 		}
 	}
 	str = tal_vfmt(NULL, fmt, ap);
-	status_send(take(towire_status_log(NULL, level, str)));
+	status_send(take(towire_status_log(NULL, level, peer, str)));
 	tal_free(str);
 }
 
-void status_fmt(enum log_level level, const char *fmt, ...)
+void status_fmt(enum log_level level,
+		const struct node_id *peer,
+		const char *fmt, ...)
 {
 	va_list ap;
 
 	va_start(ap, fmt);
-	status_vfmt(level, fmt, ap);
+	status_vfmt(level, peer, fmt, ap);
 	va_end(ap);
 }
 

common/status.h

@@ -11,34 +11,55 @@
 
 struct channel_id;
 struct daemon_conn;
+struct node_id;
 struct per_peer_state;
 
 /* Simple status reporting API. */
 void status_setup_sync(int fd);
 void status_setup_async(struct daemon_conn *master);
 
 /* Send a printf-style debugging trace. */
-void status_fmt(enum log_level level, const char *fmt, ...)
-	PRINTF_FMT(2,3);
+void status_fmt(enum log_level level,
+		const struct node_id *peer,
+		const char *fmt, ...)
+	PRINTF_FMT(3,4);
 
 /* vprintf-style */
-void status_vfmt(enum log_level level, const char *fmt, va_list ap);
+void status_vfmt(enum log_level level,
+		 const struct node_id *peer,
+		 const char *fmt, va_list ap);
 
 /* Usually we only log the packet names, not contents. */
 extern volatile bool logging_io;
-void status_peer_io(enum log_level iodir, const u8 *p);
-void status_io(enum log_level iodir, const char *who,
+
+/* This logs a debug summary if IO logging not enabled. */
+void status_peer_io(enum log_level iodir,
+		    const struct node_id *peer,
+		    const u8 *p);
+void status_io(enum log_level iodir,
+	       const struct node_id *peer,
+	       const char *who,
 	       const void *data, size_t len);
 
 /* Helpers */
 #define status_debug(...)			\
-	status_fmt(LOG_DBG, __VA_ARGS__)
+	status_fmt(LOG_DBG, NULL, __VA_ARGS__)
 #define status_info(...)			\
-	status_fmt(LOG_INFORM, __VA_ARGS__)
+	status_fmt(LOG_INFORM, NULL, __VA_ARGS__)
 #define status_unusual(...)			\
-	status_fmt(LOG_UNUSUAL, __VA_ARGS__)
+	status_fmt(LOG_UNUSUAL, NULL, __VA_ARGS__)
 #define status_broken( ...)			\
-	status_fmt(LOG_BROKEN, __VA_ARGS__)
+	status_fmt(LOG_BROKEN, NULL, __VA_ARGS__)
+
+/* For daemons which handle multiple peers */
+#define status_peer_debug(peer, ...)			\
+	status_fmt(LOG_DBG, (peer), __VA_ARGS__)
+#define status_peer_info(peer, ...)			\
+	status_fmt(LOG_INFORM, (peer), __VA_ARGS__)
+#define status_peer_unusual(peer, ...)			\
+	status_fmt(LOG_UNUSUAL, (peer), __VA_ARGS__)
+#define status_peer_broken(peer, ...)			\
+	status_fmt(LOG_BROKEN, (peer), __VA_ARGS__)
 
 /* Send a failure status code with printf-style msg, and exit. */
 void status_failed(enum status_failreason code,

common/status_wire.csv

@@ -3,10 +3,12 @@
 
 msgtype,status_log,0xFFF0
 msgdata,status_log,level,enum log_level,
+msgdata,status_log,peer,?node_id,
 msgdata,status_log,entry,wirestring,
 
 msgtype,status_io,0xFFF1
 msgdata,status_io,iodir,enum log_level,
+msgdata,status_io,peer,?node_id,
 msgdata,status_io,who,wirestring,
 msgdata,status_io,len,u16,
 msgdata,status_io,data,u8,len

common/subdaemon.c

@@ -16,7 +16,7 @@ static void status_backtrace_print(const char *fmt, ...)
 	va_list ap;
 
 	va_start(ap, fmt);
-	status_vfmt(LOG_BROKEN, fmt, ap);
+	status_vfmt(LOG_BROKEN, NULL, fmt, ap);
 	va_end(ap);
 }
 

common/test/run-cryptomsg.c

@@ -32,7 +32,9 @@ const void *fromwire_fail(const u8 **cursor UNNEEDED, size_t *max UNNEEDED)
 { fprintf(stderr, "fromwire_fail called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
-void status_fmt(enum log_level level UNUSED, const char *fmt, ...)
+void status_fmt(enum log_level level UNUSED,
+		const struct node_id *node_id UNUSED,
+		const char *fmt, ...)
 {
 	va_list ap;
 

connectd/connectd.c

@@ -354,8 +354,7 @@ static struct io_plan *retry_peer_connected(struct io_conn *conn,
 	struct io_plan *plan;
 
 	/*~ As you can see, we've had issues with this code before :( */
-	status_debug("peer %s: processing now old peer gone",
-		     type_to_string(tmpctx, struct node_id, &pr->id));
+	status_peer_debug(&pr->id, "processing now old peer gone");
 
 	/*~ Usually the pattern is to return this directly, but we have to free
 	 * our temporary structure. */
@@ -377,8 +376,7 @@ static struct io_plan *peer_reconnected(struct io_conn *conn,
 	u8 *msg;
 	struct peer_reconnected *pr;
 
-	status_debug("peer %s: reconnect",
-		     type_to_string(tmpctx, struct node_id, id));
+	status_peer_debug(id, "reconnect");
 
 	/* Tell master to kill it: will send peer_disconnect */
 	msg = towire_connect_reconnected(NULL, id);
@@ -470,8 +468,7 @@ static struct io_plan *handshake_in_success(struct io_conn *conn,
 {
 	struct node_id id;
 	node_id_from_pubkey(&id, id_key);
-	status_debug("Connect IN from %s",
-		     type_to_string(tmpctx, struct node_id, &id));
+	status_peer_debug(&id, "Connect IN");
 	return peer_exchange_initmsg(conn, daemon, cs, &id, addr);
 }
 
@@ -531,8 +528,7 @@ static struct io_plan *handshake_out_success(struct io_conn *conn,
 
 	node_id_from_pubkey(&id, key);
 	connect->connstate = "Exchanging init messages";
-	status_debug("Connect OUT to %s",
-		     type_to_string(tmpctx, struct node_id, &id));
+	status_peer_debug(&id, "Connect OUT");
 	return peer_exchange_initmsg(conn, connect->daemon, cs, &id, addr);
 }
 
@@ -549,8 +545,7 @@ struct io_plan *connection_out(struct io_conn *conn, struct connecting *connect)
 	}
 
 	/* FIXME: Timeout */
-	status_debug("Connected out for %s",
-		     type_to_string(tmpctx, struct node_id, &connect->id));
+	status_peer_debug(&connect->id, "Connected out, starting crypto");
 
 	connect->connstate = "Cryptographic handshake";
 	return initiator_handshake(conn, &connect->daemon->mykey, &outkey,
@@ -602,9 +597,7 @@ static void connect_failed(struct daemon *daemon,
 					       addrhint);
 	daemon_conn_send(daemon->master, take(msg));
 
-	status_debug("Failed connected out for %s: %s",
-		     type_to_string(tmpctx, struct node_id, id),
-		     err);
+	status_peer_debug(id, "Failed connected out: %s", err);
 }
 
 /*~ This is the destructor for the (unsuccessful) connection.  We accumulate
@@ -1279,21 +1272,21 @@ static void add_seed_addrs(struct wireaddr_internal **addrs,
 	const char **hostnames = seednames(tmpctx, id);
 
 	for (size_t i = 0; i < tal_count(hostnames); i++) {
-		status_debug("Resolving %s", hostnames[i]);
+		status_peer_debug(id, "Resolving %s", hostnames[i]);
 		new_addrs = wireaddr_from_hostname(tmpctx, hostnames[i], DEFAULT_PORT,
 		                                   NULL, broken_reply, NULL);
 		if (new_addrs) {
 			for (size_t j = 0; j < tal_count(new_addrs); j++) {
 				struct wireaddr_internal a;
 				a.itype = ADDR_INTERNAL_WIREADDR;
 				a.u.wireaddr = new_addrs[j];
-				status_debug("Resolved %s to %s", hostnames[i],
-				             type_to_string(tmpctx, struct wireaddr,
-				                            &a.u.wireaddr));
+				status_peer_debug(id, "Resolved %s to %s", hostnames[i],
+						  type_to_string(tmpctx, struct wireaddr,
+								 &a.u.wireaddr));
 				tal_arr_expand(addrs, a);
 			}
 		} else
-			status_debug("Could not resolve %s", hostnames[i]);
+			status_peer_debug(id, "Could not resolve %s", hostnames[i]);
 	}
 }
 

connectd/peer_exchange_initmsg.c

@@ -39,7 +39,7 @@ static struct io_plan *peer_init_received(struct io_conn *conn,
 	if (!msg)
 		return io_close(conn);
 
-	status_peer_io(LOG_IO_IN, msg);
+	status_peer_io(LOG_IO_IN, &peer->id, msg);
 
 	/* BOLT #1:
 	 *
@@ -51,9 +51,9 @@ static struct io_plan *peer_init_received(struct io_conn *conn,
 		return read_init(conn, peer);
 
 	if (!fromwire_init(tmpctx, msg, &globalfeatures, &features)) {
-		status_debug("peer %s bad fromwire_init '%s', closing",
-			     type_to_string(tmpctx, struct node_id, &peer->id),
-			     tal_hex(tmpctx, msg));
+		status_peer_debug(&peer->id,
+				  "bad fromwire_init '%s', closing",
+				  tal_hex(tmpctx, msg));
 		return io_close(conn);
 	}
 
@@ -168,7 +168,7 @@ struct io_plan *peer_exchange_initmsg(struct io_conn *conn,
 				/* Features so nice, we send it twice! */
 				get_offered_features(tmpctx),
 				get_offered_features(tmpctx));
-	status_peer_io(LOG_IO_OUT, peer->msg);
+	status_peer_io(LOG_IO_OUT, &peer->id, peer->msg);
 	peer->msg = cryptomsg_encrypt_msg(peer, &peer->cs, take(peer->msg));
 
 	next = read_init;

connectd/test/run-initiator-success.c

@@ -54,7 +54,9 @@ static struct io_plan *test_read(struct io_conn *conn,
 				 struct handshake *h);
 
 #define SUPERVERBOSE status_debug
-void status_fmt(enum log_level level UNUSED, const char *fmt, ...)
+void status_fmt(enum log_level level UNUSED,
+		const struct node_id *node_id,
+		const char *fmt, ...)
 {
 	va_list ap;