From c01f3267d51a4d356b8720d4b80aeea93f4018fe Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 5 Feb 2018 14:39:28 +1030 Subject: [PATCH] common: only log io if they set --debug-subdaemon-io= or with SIGUSR1. Otherwise we just log the type of msg. Signed-off-by: Rusty Russell --- common/status.c | 39 +++++++++++++++++++++++++++++++++++++-- common/status.h | 2 ++ common/subdaemon.c | 12 +++++++----- lightningd/lightningd.c | 1 + lightningd/lightningd.h | 3 +++ lightningd/options.c | 3 +++ lightningd/subd.c | 26 ++++++++++++++++---------- 7 files changed, 69 insertions(+), 17 deletions(-) diff --git a/common/status.c b/common/status.c index bc6b61f2e..c748cce96 100644 --- a/common/status.c +++ b/common/status.c @@ -10,13 +10,31 @@ #include #include #include +#include #include -#include +#include #include 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; diff --git a/common/status.h b/common/status.h index f222e9c92..d9e62a3b6 100644 --- a/common/status.h +++ b/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 */ diff --git a/common/subdaemon.c b/common/subdaemon.c index 9f5f37703..a33c118be 100644 --- a/common/subdaemon.c +++ b/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 } diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index c24cbc665..1a84d961e 100644 --- a/lightningd/lightningd.c +++ b/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; } diff --git a/lightningd/lightningd.h b/lightningd/lightningd.h index 478477bce..d6d7d5275 100644 --- a/lightningd/lightningd.h +++ b/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; diff --git a/lightningd/options.c b/lightningd/options.c index 5279f4874..d26b46156 100644 --- a/lightningd/options.c +++ b/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 diff --git a/lightningd/subd.c b/lightningd/subd.c index bcdfcc587..bb075a41d 100644 --- a/lightningd/subd.c +++ b/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));