logging: add TRACE log level and move some DEBUG logging to it

.msggen.json

@@ -105,6 +105,7 @@
             "debug": 3,
             "info": 2,
             "io": 4,
+            "trace": 5,
             "unusual": 1
         },
         "GetlogLogType": {
@@ -114,6 +115,7 @@
             "IO_IN": 5,
             "IO_OUT": 6,
             "SKIPPED": 0,
+            "TRACE": 7,
             "UNUSUAL": 2
         },
         "GetrouteRouteStyle": {
@@ -287,6 +289,7 @@
             "debug": 1,
             "info": 2,
             "io": 0,
+            "trace": 4,
             "unusual": 3
         },
         "ListpeersPeersChannelsHtlcsDirection": {
@@ -327,6 +330,7 @@
             "IO_IN": 5,
             "IO_OUT": 6,
             "SKIPPED": 0,
+            "TRACE": 7,
             "UNUSUAL": 2
         },
         "ListsendpaysIndex": {

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. */

common/trace.c

@@ -99,7 +99,7 @@ static void trace_inject_traceparent(void)
 static void trace_init(void) {
 	if (active_spans)
 		return;
-	active_spans = malloc(sizeof(struct span) * MAX_ACTIVE_SPANS);
+	active_spans = calloc(MAX_ACTIVE_SPANS, sizeof(struct span));
 
 	current = NULL;
 	trace_inject_traceparent();

contrib/msggen/msggen/schema.json

@@ -11825,6 +11825,7 @@
             "unusual",
             "info",
             "debug",
+            "trace",
             "io"
           ],
           "description": [
@@ -11877,6 +11878,7 @@
                   "UNUSUAL",
                   "INFO",
                   "DEBUG",
+                  "TRACE",
                   "IO_IN",
                   "IO_OUT"
                 ]
@@ -11919,7 +11921,8 @@
                         "BROKEN",
                         "UNUSUAL",
                         "INFO",
-                        "DEBUG"
+                        "DEBUG",
+                        "TRACE"
                       ]
                     }
                   }
@@ -20883,6 +20886,7 @@
           ],
           "enum": [
             "io",
+            "trace",
             "debug",
             "info",
             "unusual"
@@ -20945,6 +20949,7 @@
                         "UNUSUAL",
                         "INFO",
                         "DEBUG",
+                        "TRACE",
                         "IO_IN",
                         "IO_OUT"
                       ]
@@ -20986,7 +20991,8 @@
                               "BROKEN",
                               "UNUSUAL",
                               "INFO",
-                              "DEBUG"
+                              "DEBUG",
+                              "TRACE"
                             ]
                           }
                         }

doc/lightning-cli.1.md

@@ -68,7 +68,7 @@ field without parsing JSON.
 * **--notifications**/**-N**=*LEVEL*
 
   If *LEVEL* is 'none', then never print out notifications.  Otherwise,
-print out notifications of *LEVEL* or above (one of `io`, `debug`,
+print out notifications of *LEVEL* or above (one of `io`, `trace`, `debug`,
 `info` (the default), `unusual` or `broken`: they are prefixed with `#
 `.  (Note: currently not supported with `--commando`).
 

doc/lightningd-config.5.md

@@ -170,7 +170,7 @@ binary.
 
 * **log-level**=*LEVEL*\[:*SUBSYSTEM*\]\[:*PATH*\]
 
-  What log level to print out: options are io, debug, info, unusual,
+  What log level to print out: options are io, trace, debug, info, unusual,
 broken.  If *SUBSYSTEM* is supplied, this sets the logging level
 for any subsystem (or *nodeid*) containing that string. If *PATH* is supplied, it means this log-level filter is only applied to that `log-file`, which is useful for creating logs to capture a specific subsystem.  This option may be specified multiple times.
 Subsystems include:

doc/schemas/lightning-getlog.json

@@ -17,6 +17,7 @@
           "unusual",
           "info",
           "debug",
+          "trace",
           "io"
         ],
         "description": [
@@ -69,6 +70,7 @@
                 "UNUSUAL",
                 "INFO",
                 "DEBUG",
+                "TRACE",
                 "IO_IN",
                 "IO_OUT"
               ]
@@ -111,7 +113,8 @@
                       "BROKEN",
                       "UNUSUAL",
                       "INFO",
-                      "DEBUG"
+                      "DEBUG",
+                      "TRACE"
                     ]
                   }
                 }

doc/schemas/lightning-listpeers.json

@@ -31,6 +31,7 @@
         ],
         "enum": [
           "io",
+          "trace",
           "debug",
           "info",
           "unusual"
@@ -93,6 +94,7 @@
                       "UNUSUAL",
                       "INFO",
                       "DEBUG",
+                      "TRACE",
                       "IO_IN",
                       "IO_OUT"
                     ]
@@ -134,7 +136,8 @@
                             "BROKEN",
                             "UNUSUAL",
                             "INFO",
-                            "DEBUG"
+                            "DEBUG",
+                            "TRACE"
                           ]
                         }
                       }

gossipd/gossipd.c

@@ -204,7 +204,7 @@ static void handle_recv_gossip(struct daemon *daemon, const u8 *outermsg)
 		return;
 	}
 
-	status_peer_debug(&source, "handle_recv_gossip: %s", peer_wire_name(fromwire_peektype(msg)));
+	status_peer_trace(&source, "handle_recv_gossip: %s", peer_wire_name(fromwire_peektype(msg)));
 	/* These are messages relayed from peer */
 	switch ((enum peer_wire)fromwire_peektype(msg)) {
 	case WIRE_CHANNEL_ANNOUNCEMENT:

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__)