common: only log io if they set --debug-subdaemon-io=<daemon> or with SIGUSR1.

Otherwise we just log the type of msg.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

common/status.c

@@ -10,13 +10,31 @@
 #include <common/status.h>
 #include <common/utils.h>
 #include <errno.h>
+#include <signal.h>
 #include <stdarg.h>
-#include <wire/wire.h>
+#include <wire/peer_wire.h>
 #include <wire/wire_sync.h>
 
 static int status_fd = -1;
 static struct daemon_conn *status_conn;
 const void *trc;
+volatile bool logging_io = false;
+
+static void got_sigusr1(int signal)
+{
+	logging_io = !logging_io;
+}
+
+static void setup_logging_sighandler(void)
+{
+	struct sigaction act;
+
+	memset(&act, 0, sizeof(act));
+	act.sa_handler = got_sigusr1;
+	act.sa_flags = SA_RESTART;
+
+	sigaction(SIGUSR1, &act, NULL);
+}
 
 void status_setup_sync(int fd)
 {
@@ -24,6 +42,7 @@ void status_setup_sync(int fd)
 	assert(!status_conn);
 	status_fd = fd;
 	trc = tal_tmpctx(NULL);
+	setup_logging_sighandler();
 }
 
 void status_setup_async(struct daemon_conn *master)
@@ -34,6 +53,7 @@ void status_setup_async(struct daemon_conn *master)
 
 	/* Don't use tmpctx here, otherwise debug_poll gets upset. */
 	trc = tal(NULL, char);
+	setup_logging_sighandler();
 }
 
 static bool too_large(size_t len, int type)
@@ -75,7 +95,7 @@ static void status_send_with_hdr(u16 type, const void *p, size_t len)
 	}
 }
 
-void status_io(enum log_level iodir, const u8 *p)
+static void status_io_full(enum log_level iodir, const u8 *p)
 {
 	u16 type = STATUS_LOG_MIN + iodir;
 	u8 *msg = tal_arr(NULL, u8, 0);
@@ -95,6 +115,21 @@ void status_io(enum log_level iodir, const u8 *p)
 	}
 }
 
+static void status_io_short(enum log_level iodir, const u8 *p)
+{
+	status_debug("%s %s",
+		     iodir == LOG_IO_OUT ? "peer_out" : "peer_in",
+		     wire_type_name(fromwire_peektype(p)));
+}
+
+void status_io(enum log_level iodir, const u8 *p)
+{
+	if (logging_io)
+		status_io_full(iodir, p);
+	else
+		status_io_short(iodir, p);
+}
+
 void status_vfmt(enum log_level level, const char *fmt, va_list ap)
 {
 	char *str;

common/status.h

@@ -27,6 +27,8 @@ void status_fmt(enum log_level level, const char *fmt, ...)
 /* vprintf-style */
 void status_vfmt(enum log_level level, const char *fmt, va_list ap);
 
+/* Usually we only log the packet names, not contents. */
+extern volatile bool logging_io;
 void status_io(enum log_level iodir, const u8 *p);
 
 /* Helpers */

common/subdaemon.c

@@ -71,14 +71,12 @@ void subdaemon_setup(int argc, char *argv[])
 	secp256k1_ctx = secp256k1_context_create(SECP256K1_CONTEXT_VERIFY
 						 | SECP256K1_CONTEXT_SIGN);
 
-#if DEVELOPER
 	for (int i = 1; i < argc; i++) {
-		if (strstarts(argv[i], "--dev-disconnect=")) {
-			dev_disconnect_init(atoi(argv[i]
-						 + strlen("--dev-disconnect=")));
-		}
+		if (streq(argv[i], "--log-io"))
+			logging_io = true;
 	}
 
+#if DEVELOPER
 	/* From debugger, set debugger_spin to 0. */
 	for (int i = 1; i < argc; i++) {
 		if (streq(argv[i], "--debugger")) {
@@ -87,6 +85,10 @@ void subdaemon_setup(int argc, char *argv[])
 			while (!debugger_connected)
 				usleep(10000);
 		}
+		if (strstarts(argv[i], "--dev-disconnect=")) {
+			dev_disconnect_init(atoi(argv[i]
+						 + strlen("--dev-disconnect=")));
+		}
 	}
 #endif
 }

lightningd/lightningd.c

@@ -67,6 +67,7 @@ static struct lightningd *new_lightningd(const tal_t *ctx,
 	ld->portnum = DEFAULT_PORT;
 	timers_init(&ld->timers, time_mono());
 	ld->topology = new_topology(ld, ld->log);
+	ld->debug_subdaemon_io = NULL;
 
 	return ld;
 }

lightningd/lightningd.h

@@ -138,6 +138,9 @@ struct lightningd {
 	/* Transaction filter matching what we're interested in */
 	struct txfilter *owned_txfilter;
 
+	/* May be useful for non-developers debugging in the field */
+	char *debug_subdaemon_io;
+
 #if DEVELOPER
 	/* If we want to debug a subdaemon. */
 	const char *dev_debug_subdaemon;

lightningd/options.c

@@ -277,6 +277,9 @@ static void config_register_opts(struct lightningd *ld)
 			 opt_set_bool_arg, opt_show_bool,
 			 &deprecated_apis,
 			 "Enable deprecated options, JSONRPC commands, fields, etc.");
+	opt_register_arg("--debug-subdaemon-io",
+			 opt_set_charp, NULL, &ld->debug_subdaemon_io,
+			 "Enable full peer IO logging in subdaemons ending in this string (can also send SIGUSR1 to toggle)");
 }
 
 #if DEVELOPER

lightningd/subd.c

@@ -130,7 +130,9 @@ static void close_taken_fds(va_list *ap)
 }
 
 /* We use sockets, not pipes, because fds are bidir. */
-static int subd(const char *dir, const char *name, const char *debug_subdaemon,
+static int subd(const char *dir, const char *name,
+		const char *debug_subdaemon,
+		const char *debug_subdaemon_io,
 		int *msgfd, int dev_disconnect_fd, va_list *ap)
 {
 	int childmsg[2], execfail[2];
@@ -154,8 +156,8 @@ static int subd(const char *dir, const char *name, const char *debug_subdaemon,
 	if (childpid == 0) {
 		int fdnum = 3, i;
 		long max;
-		const char *debug_arg[2] = { NULL, NULL };
-		const char *path;
+		size_t num_args;
+		char *args[] = { NULL, NULL, NULL, NULL, NULL };
 
 		close(childmsg[0]);
 		close(execfail[0]);
@@ -190,14 +192,17 @@ static int subd(const char *dir, const char *name, const char *debug_subdaemon,
 			if (i != dev_disconnect_fd)
 				close(i);
 
+		num_args = 0;
+		args[num_args++] = path_join(NULL, dir, name);
 #if DEVELOPER
 		if (dev_disconnect_fd != -1)
-			debug_arg[0] = tal_fmt(NULL, "--dev-disconnect=%i", dev_disconnect_fd);
+			args[num_args++] = tal_fmt(NULL, "--dev-disconnect=%i", dev_disconnect_fd);
 		if (debug_subdaemon && strends(name, debug_subdaemon))
-			debug_arg[debug_arg[0] ? 1 : 0] = "--debugger";
+			args[num_args++] = "--debugger";
 #endif
-		path = path_join(NULL, dir, name);
-		execl(path, path, debug_arg[0], debug_arg[1], NULL);
+		if (debug_subdaemon_io && strends(name, debug_subdaemon_io))
+			args[num_args++] = "--log-io";
+		execv(args[0], args);
 
 	child_errno_fail:
 		err = errno;
@@ -249,7 +254,8 @@ int subd_raw(struct lightningd *ld, const char *name)
 	disconnect_fd = ld->dev_disconnect_fd;
 #endif /* DEVELOPER */
 
-	pid = subd(ld->daemon_dir, name, debug_subd, &msg_fd, disconnect_fd,
+	pid = subd(ld->daemon_dir, name, debug_subd, ld->debug_subdaemon_io,
+		   &msg_fd, disconnect_fd,
 		   NULL);
 	if (pid == (pid_t)-1) {
 		log_unusual(ld->log, "subd %s failed: %s",
@@ -613,8 +619,8 @@ static struct subd *new_subd(struct lightningd *ld,
 	disconnect_fd = ld->dev_disconnect_fd;
 #endif /* DEVELOPER */
 
-	sd->pid = subd(ld->daemon_dir, name, debug_subd, &msg_fd, disconnect_fd,
-		       ap);
+	sd->pid = subd(ld->daemon_dir, name, debug_subd, ld->debug_subdaemon_io,
+		       &msg_fd, disconnect_fd, ap);
 	if (sd->pid == (pid_t)-1) {
 		log_unusual(ld->log, "subd %s failed: %s",
 			    name, strerror(errno));