logging: add TRACE between DEBUG and IO

By moving super-noisy debugging logging to new TRACE level we can
make long-term logging at DEBUG possible w/o removing any logging.

Addresses ([ElementsProject#7279])

Related Issues:
ElementsProject#6927
chrisguida/smaug#34
ZmnSCPxj/clboss#194

common/status.h

@@ -37,6 +37,8 @@ void status_io(enum log_level iodir,
 	       const void *data, size_t len);
 
 /* Helpers */
+#define status_trace(...)			\
+	status_fmt(LOG_TRACE, NULL, __VA_ARGS__)
 #define status_debug(...)			\
 	status_fmt(LOG_DBG, NULL, __VA_ARGS__)
 #define status_info(...)			\
@@ -47,6 +49,8 @@ void status_io(enum log_level iodir,
 	status_fmt(LOG_BROKEN, NULL, __VA_ARGS__)
 
 /* For daemons which handle multiple peers */
+#define status_peer_trace(peer, ...)			\
+	status_fmt(LOG_TRACE, (peer), __VA_ARGS__)
 #define status_peer_debug(peer, ...)			\
 	status_fmt(LOG_DBG, (peer), __VA_ARGS__)
 #define status_peer_info(peer, ...)			\

common/status_levels.c

@@ -5,6 +5,7 @@
 static const char *ll_names[] = {
 	"io",
 	"io",
+	"trace",
 	"debug",
 	"info",
 	"unusual",

common/status_levels.h

@@ -7,6 +7,8 @@ enum log_level {
 	/* Logging all IO. */
 	LOG_IO_OUT,
 	LOG_IO_IN,
+	/* Extra-gory logging details for deep debugging */
+	LOG_TRACE,
 	/* Gory details which are mainly good for debugging. */
 	LOG_DBG,
 	/* Information about what's going in. */

lightningd/log.c

@@ -128,6 +128,8 @@ static const char *level_prefix(enum log_level level)
 	case LOG_IO_OUT:
 	case LOG_IO_IN:
 		return "IO     ";
+	case LOG_TRACE:
+		return "TRACE  ";
 	case LOG_DBG:
 		return "DEBUG  ";
 	case LOG_INFORM:
@@ -298,6 +300,9 @@ static u32 delete_threshold(enum log_level level)
 	case LOG_IO_OUT:
 	case LOG_IO_IN:
 		return 900;
+	/* 50% of LOG_TRACE */
+	case LOG_TRACE:
+		return 750;
 	/* 50% of LOG_DBG */
 	case LOG_DBG:
 		return 500;
@@ -470,7 +475,7 @@ const char *log_prefix(const struct logger *log)
 
 bool log_has_io_logging(const struct logger *log)
 {
-	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_DBG;
+	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_TRACE;
 }
 
 /* This may move entry! */
@@ -682,6 +687,7 @@ static void log_one_line(unsigned int skipped,
 		prefix,
 		level == LOG_IO_IN ? "IO_IN"
 		: level == LOG_IO_OUT ? "IO_OUT"
+		: level == LOG_TRACE ? "TRACE"
 		: level == LOG_DBG ? "DEBUG"
 		: level == LOG_INFORM ? "INFO"
 		: level == LOG_UNUSUAL ? "UNUSUAL"
@@ -1084,6 +1090,7 @@ static void log_to_json(unsigned int skipped,
 			: level == LOG_UNUSUAL ? "UNUSUAL"
 			: level == LOG_INFORM ? "INFO"
 			: level == LOG_DBG ? "DEBUG"
+			: level == LOG_TRACE ? "TRACE"
 			: level == LOG_IO_IN ? "IO_IN"
 			: level == LOG_IO_OUT ? "IO_OUT"
 			: "UNKNOWN");

lightningd/log.h

@@ -20,11 +20,13 @@ struct logger *new_logger(const tal_t *ctx, struct log_book *record,
 			  const struct node_id *default_node_id,
 			  const char *fmt, ...) PRINTF_FMT(4,5);
 
+#define log_trace(logger, ...) log_((logger), LOG_TRACE, NULL, false, __VA_ARGS__)
 #define log_debug(logger, ...) log_((logger), LOG_DBG, NULL, false, __VA_ARGS__)
 #define log_info(logger, ...) log_((logger), LOG_INFORM, NULL, false, __VA_ARGS__)
 #define log_unusual(logger, ...) log_((logger), LOG_UNUSUAL, NULL, true, __VA_ARGS__)
 #define log_broken(logger, ...) log_((logger), LOG_BROKEN, NULL, true, __VA_ARGS__)
 
+#define log_peer_trace(logger, nodeid, ...) log_((logger), LOG_TRACE, nodeid, false, __VA_ARGS__)
 #define log_peer_debug(logger, nodeid, ...) log_((logger), LOG_DBG, nodeid, false, __VA_ARGS__)
 #define log_peer_info(logger, nodeid, ...) log_((logger), LOG_INFORM, nodeid, false, __VA_ARGS__)
 #define log_peer_unusual(logger, nodeid, ...) log_((logger), LOG_UNUSUAL, nodeid, true, __VA_ARGS__)