status: add multiple levels of logging.

status_trace maps to status_debug.

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

channeld/test/run-full_channel.c

@@ -1,8 +1,3 @@
- #include <common/status.h>
- #include <stdio.h>
-#define status_trace(fmt , ...) \
-	printf(fmt "\n" , ## __VA_ARGS__)
-
 #include "../../common/key_derive.c"
 #include "../../common/keyset.c"
 #include "../../common/initial_channel.c"
@@ -17,6 +12,17 @@
 #include <ccan/str/hex/hex.h>
 #include <common/sphinx.h>
 #include <common/type_to_string.h>
+#include <stdio.h>
+
+void status_fmt(enum log_level level, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	vprintf(fmt, ap);
+	printf("\n");
+	va_end(ap);
+}
 
 const void *trc;
 

common/Makefile

@@ -42,7 +42,7 @@ COMMON_SRC :=					\
 	common/wire_error.c			\
 	common/withdraw_tx.c
 
-COMMON_HEADERS_NOGEN := $(COMMON_SRC:.c=.h) common/overflows.h common/htlc.h
+COMMON_HEADERS_NOGEN := $(COMMON_SRC:.c=.h) common/overflows.h common/htlc.h common/status_levels.h
 COMMON_HEADERS_GEN := common/gen_htlc_state_names.h
 
 COMMON_HEADERS := $(COMMON_HEADERS_GEN) $(COMMON_HEADERS_NOGEN)

common/status.c

@@ -75,12 +75,32 @@ static void status_send_with_hdr(u16 type, const void *p, size_t len)
 	}
 }
 
-void status_tracev(const char *fmt, va_list ap)
+void status_io(enum side sender, const u8 *p)
+{
+	u16 type = STATUS_LOG_MIN + LOG_IO;
+	u8 *msg = tal_arr(NULL, u8, 0);
+
+	towire_u16(&msg, type);
+	towire_bool(&msg, sender == REMOTE);
+	towire(&msg, p, tal_len(p));
+	if (too_large(tal_len(msg), type))
+		tal_resize(&msg, 65535);
+
+	if (status_fd >= 0) {
+		if (!wire_sync_write(status_fd, take(msg)))
+			err(1, "Writing out status %u len %zu",
+			    type, tal_len(p));
+	} else {
+		daemon_conn_send(status_conn, take(msg));
+	}
+}
+
+void status_vfmt(enum log_level level, const char *fmt, va_list ap)
 {
 	char *str;
 
 	str = tal_vfmt(NULL, fmt, ap);
-	status_send_with_hdr(STATUS_TRACE, str, strlen(str));
+	status_send_with_hdr(STATUS_LOG_MIN + level, str, strlen(str));
 	tal_free(str);
 
 	/* Free up any temporary children. */
@@ -90,12 +110,12 @@ void status_tracev(const char *fmt, va_list ap)
 	}
 }
 
-void status_trace(const char *fmt, ...)
+void status_fmt(enum log_level level, const char *fmt, ...)
 {
 	va_list ap;
 
 	va_start(ap, fmt);
-	status_tracev(fmt, ap);
+	status_vfmt(level, fmt, ap);
 	va_end(ap);
 }
 

common/status.h

@@ -3,7 +3,10 @@
 #include "config.h"
 #include <ccan/compiler/compiler.h>
 #include <ccan/short_types/short_types.h>
+#include <common/htlc.h> /* For enum side */
+#include <common/status_levels.h>
 #include <stdarg.h>
+#include <stdbool.h>
 #include <stdlib.h>
 
 struct daemon_conn;
@@ -15,44 +18,30 @@ void status_setup_async(struct daemon_conn *master);
 /* Convenient context, frees up after every status_update/failed */
 extern const void *trc;
 
-/* Special status code for tracing messages. */
-#define STATUS_TRACE 0x7FFF
-
-/* Failure codes always have high bit set. */
-#define STATUS_FAIL 0x8000
-
-/* These are always followed by an ASCII string. */
-enum status_fail {
-	/*
-	 * These errors shouldn't happen:
-	 */
-	/* Master daemon sent unknown/malformed command, or fd failed */
-	STATUS_FAIL_MASTER_IO = STATUS_FAIL,
-
-	/* Hsmd sent unknown/malformed command, or fd failed */
-	STATUS_FAIL_HSM_IO,
-
-	/* Gossipd sent unknown/malformed command, or fd failed */
-	STATUS_FAIL_GOSSIP_IO,
-
-	/* Other internal error. */
-	STATUS_FAIL_INTERNAL_ERROR,
-
-	/*
-	 * These errors happen when the other peer misbehaves:
-	 */
-	/* I/O failure (probably they closed the socket) */
-	STATUS_FAIL_PEER_IO,
-	/* Peer did something else wrong */
-	STATUS_FAIL_PEER_BAD
-};
-
 /* Send a message (frees the message). */
 void status_send_sync(const u8 *msg);
 /* Send a printf-style debugging trace. */
-void status_trace(const char *fmt, ...) PRINTF_FMT(1,2);
+void status_fmt(enum log_level level, const char *fmt, ...)
+	PRINTF_FMT(2,3);
+
 /* vprintf-style */
-void status_tracev(const char *fmt, va_list ap);
+void status_vfmt(enum log_level level, const char *fmt, va_list ap);
+
+void status_io(enum side sender, const u8 *msg);
+
+/* Helpers */
+#define status_debug(...)			\
+	status_fmt(LOG_DBG, __VA_ARGS__)
+#define status_info(...)			\
+	status_fmt(LOG_INFORM, __VA_ARGS__)
+#define status_unusual(...)			\
+	status_fmt(LOG_UNUSUAL, __VA_ARGS__)
+#define status_broken( ...)			\
+	status_fmt(LOG_BROKEN, __VA_ARGS__)
+
+/* FIXME: Transition */
+#define status_trace(...) status_debug(__VA_ARGS__)
+
 /* Send a failure status code with printf-style msg, and exit. */
 void status_failed(enum status_fail code, const char *fmt, ...) PRINTF_FMT(2,3) NORETURN;
 

common/status_levels.h

@@ -0,0 +1,52 @@
+#ifndef LIGHTNING_COMMON_STATUS_LEVELS_H
+#define LIGHTNING_COMMON_STATUS_LEVELS_H
+#include "config.h"
+
+enum log_level {
+	/* Logging all IO. */
+	LOG_IO,
+	/* Gory details which are mainly good for debugging. */
+	LOG_DBG,
+	/* Information about what's going in. */
+	LOG_INFORM,
+	/* That's strange... */
+	LOG_UNUSUAL,
+	/* That's really bad, we're broken. */
+	LOG_BROKEN
+};
+
+/* Special status code for tracing messages (subtract log_level). */
+#define STATUS_LOG_MIN (STATUS_LOG_MAX - LOG_BROKEN)
+#define STATUS_LOG_MAX (0x7FFF)
+
+/* Failure codes always have high bit set. */
+#define STATUS_FAIL 0x8000
+
+/* These are always followed by an ASCII string. */
+enum status_fail {
+	/*
+	 * These errors shouldn't happen:
+	 */
+	/* Master daemon sent unknown/malformed command, or fd failed */
+	STATUS_FAIL_MASTER_IO = STATUS_FAIL,
+
+	/* Hsmd sent unknown/malformed command, or fd failed */
+	STATUS_FAIL_HSM_IO,
+
+	/* Gossipd sent unknown/malformed command, or fd failed */
+	STATUS_FAIL_GOSSIP_IO,
+
+	/* Other internal error. */
+	STATUS_FAIL_INTERNAL_ERROR,
+
+	/*
+	 * These errors happen when the other peer misbehaves:
+	 */
+	/* I/O failure (probably they closed the socket) */
+	STATUS_FAIL_PEER_IO,
+
+	/* Peer did something else wrong */
+	STATUS_FAIL_PEER_BAD
+};
+
+#endif /* LIGHTNING_COMMON_STATUS_LEVELS_H */

gossipd/test/run-bench-find_route.c

@@ -7,13 +7,20 @@
 #include <common/pseudorand.h>
 #include <common/status.h>
 #include <common/type_to_string.h>
+#include <stdio.h>
 #include <sys/types.h>
 #include <sys/wait.h>
 #include <unistd.h>
 
-#include <stdio.h>
+void status_fmt(enum log_level level, const char *fmt, ...)
-#define status_trace(fmt, ...) \
+{
-	do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0)
+	va_list ap;
+
+	va_start(ap, fmt);
+	vprintf(fmt, ap);
+	printf("\n");
+	va_end(ap);
+}
 
 static bool in_bench = 0;
 

gossipd/test/run-find_route-specific.c

@@ -8,7 +8,7 @@
 #include <common/status.h>
 
 #include <stdio.h>
-#define status_trace(fmt, ...) \
+#define status_fmt(level, fmt, ...)					\
 	do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0)
 
 #include "../routing.c"

gossipd/test/run-find_route.c

@@ -1,16 +1,21 @@
-#include <common/status.h>
-
-#include <stdio.h>
-#define status_trace(fmt, ...) \
-	do { printf((fmt) ,##__VA_ARGS__); printf("\n"); } while(0)
-
 #include "../routing.c"
+#include <stdio.h>
 
 struct broadcast_state *new_broadcast_state(tal_t *ctx UNNEEDED)
 {
 	return NULL;
 }
 
+void status_fmt(enum log_level level, const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	vprintf(fmt, ap);
+	printf("\n");
+	va_end(ap);
+}
+
 /* AUTOGENERATED MOCKS START */
 /* Generated stub for fromwire_channel_announcement */
 bool fromwire_channel_announcement(const tal_t *ctx UNNEEDED, const void *p UNNEEDED, size_t *plen UNNEEDED, secp256k1_ecdsa_signature *node_signature_1 UNNEEDED, secp256k1_ecdsa_signature *node_signature_2 UNNEEDED, secp256k1_ecdsa_signature *bitcoin_signature_1 UNNEEDED, secp256k1_ecdsa_signature *bitcoin_signature_2 UNNEEDED, u8 **features UNNEEDED, struct bitcoin_blkid *chain_hash UNNEEDED, struct short_channel_id *short_channel_id UNNEEDED, struct pubkey *node_id_1 UNNEEDED, struct pubkey *node_id_2 UNNEEDED, struct pubkey *bitcoin_key_1 UNNEEDED, struct pubkey *bitcoin_key_2 UNNEEDED)

gossipd/test/run-initiator-success.c

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

gossipd/test/run-responder-success.c

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

lightningd/Makefile

@@ -55,6 +55,7 @@ LIGHTNINGD_SRC :=				\
 	lightningd/jsonrpc.c			\
 	lightningd/lightningd.c			\
 	lightningd/log.c			\
+	lightningd/log_status.c			\
 	lightningd/netaddress.c			\
 	lightningd/opt_time.c			\
 	lightningd/options.c			\

lightningd/hsm_control.c

@@ -11,6 +11,7 @@
 #include <inttypes.h>
 #include <lightningd/hsm_control.h>
 #include <lightningd/log.h>
+#include <lightningd/log_status.h>
 #include <string.h>
 #include <wally_bip32.h>
 #include <wire/wire_sync.h>
@@ -19,15 +20,13 @@ u8 *hsm_sync_read(const tal_t *ctx, struct lightningd *ld)
 {
 	for (;;) {
 		u8 *msg = wire_sync_read(ctx, ld->hsm_fd);
+
 		if (!msg)
 			fatal("Could not read from HSM: %s", strerror(errno));
-		if (fromwire_peektype(msg) != STATUS_TRACE)
+		if (log_status_msg(ld->log, msg))
+			tal_free(msg);
+		else
 			return msg;
-
-		log_debug(ld->log, "HSM TRACE: %.*s",
-			  (int)(tal_len(msg) - sizeof(be16)),
-			  (char *)msg + sizeof(be16));
-		tal_free(msg);
 	}
 }
 

lightningd/log.h

@@ -4,6 +4,7 @@
 #include <ccan/tal/tal.h>
 #include <ccan/time/time.h>
 #include <ccan/typesafe_cb/typesafe_cb.h>
+#include <common/status.h>
 #include <common/type_to_string.h>
 #include <stdarg.h>
 
@@ -11,19 +12,6 @@ struct lightningd;
 struct timerel;
 struct lightningd;
 
-enum log_level {
-	/* Logging all IO. */
-	LOG_IO,
-	/* Gory details which are mainly good for debugging. */
-	LOG_DBG,
-	/* Information about what's going in. */
-	LOG_INFORM,
-	/* That's strange... */
-	LOG_UNUSUAL,
-	/* That's really bad, we're broken. */
-	LOG_BROKEN
-};
-
 /* We can have a single log book, with multiple logs in it. */
 struct log_book *new_log_book(const tal_t *ctx,
 			      size_t max_mem,

lightningd/log_status.c

@@ -0,0 +1,28 @@
+#include <lightningd/log_status.h>
+#include <wire/wire.h>
+
+bool log_status_msg(struct log *log, const u8 *msg)
+{
+	size_t max = tal_len(msg);
+	int type = fromwire_u16(&msg, &max);
+	enum log_level level;
+
+	if (type < STATUS_LOG_MIN || type > STATUS_LOG_MAX)
+		return false;
+
+	level = type - STATUS_LOG_MIN;
+	if (level == LOG_IO) {
+		/* First byte is direction */
+		bool dir = fromwire_bool(&msg, &max);
+		log_io(log, dir, msg, max);
+	} else {
+		int i;
+		/* Truncate if unprintable */
+		for (i = 0; i < max; i++) {
+			if (!cisprint((char)msg[i]))
+				break;
+		}
+		log_(log, level, "%.*s%s", i, msg, i == max ? "" : "...");
+	}
+	return true;
+}

lightningd/log_status.h

@@ -0,0 +1,10 @@
+#ifndef LIGHTNING_LIGHTNINGD_LOG_STATUS_H
+#define LIGHTNING_LIGHTNINGD_LOG_STATUS_H
+#include "config.h"
+#include <common/status_levels.h>
+#include <lightningd/log.h>
+
+/* Returns true (and writes it to log) if it's a status_log message. */
+bool log_status_msg(struct log *log, const u8 *msg);
+
+#endif /* LIGHTNING_LIGHTNINGD_LOG_STATUS_H */

lightningd/subd.c

@@ -7,11 +7,11 @@
 #include <ccan/take/take.h>
 #include <ccan/tal/path/path.h>
 #include <ccan/tal/str/str.h>
-#include <common/status.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <lightningd/lightningd.h>
 #include <lightningd/log.h>
+#include <lightningd/log_status.h>
 #include <lightningd/peer_control.h>
 #include <lightningd/subd.h>
 #include <signal.h>
@@ -438,14 +438,10 @@ static struct io_plan *sd_msg_read(struct io_conn *conn, struct subd *sd)
 	tmpctx = tal_tmpctx(sd);
 	tal_steal(tmpctx, sd->msg_in);
 
-	if (type == STATUS_TRACE) {
+	if (log_status_msg(sd->log, sd->msg_in))
-		int str_len;
-		const char *str = string_from_msg(sd->msg_in, &str_len);
-		if (!str)
-			goto malformed;
-		log_debug(sd->log, "TRACE: %.*s", str_len, str);
 		goto next;
-	} else if (type & STATUS_FAIL) {
+
+	if (type & STATUS_FAIL) {
 		int str_len;
 		const char *str = string_from_msg(sd->msg_in, &str_len);
 		if (!str)

lightningd/test/run-cryptomsg.c

@@ -36,8 +36,15 @@ static void do_write(const void *buf, size_t len)
 #define io_write(conn, p, len, next, arg) \
 	(do_write((p), (len)), (next)((conn), (arg)), NULL)
 
-#define status_trace(fmt, ...) \
+void status_fmt(enum log_level level, const char *fmt, ...)
-	printf(fmt "\n", __VA_ARGS__)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	vprintf(fmt, ap);
+	printf("\n");
+	va_end(ap);
+}
 
 #if DEVELOPER
 /* AUTOGENERATED MOCKS START */