From 6daf4c91aa2066c918d2a08c2f363b7a59bb2c5a Mon Sep 17 00:00:00 2001 From: Ken Sedgwick Date: Thu, 25 Apr 2024 16:42:54 -0700 Subject: [PATCH] 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 ([#7279]) Related Issues: https://github.com/ElementsProject/lightning/issues/6927 https://github.com/chrisguida/smaug/issues/34 https://github.com/ZmnSCPxj/clboss/issues/194 --- common/status.h | 4 ++++ common/status_levels.c | 1 + common/status_levels.h | 2 ++ contrib/msggen/msggen/schema.json | 5 ++++- doc/schemas/lightning-getlog.json | 5 ++++- lightningd/log.c | 9 ++++++++- lightningd/log.h | 2 ++ 7 files changed, 25 insertions(+), 3 deletions(-) diff --git a/common/status.h b/common/status.h index e4ca3f924d17..ee2d174afa1b 100644 --- a/common/status.h +++ b/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, ...) \ diff --git a/common/status_levels.c b/common/status_levels.c index 8746ec8d9a80..8eb826e208d4 100644 --- a/common/status_levels.c +++ b/common/status_levels.c @@ -5,6 +5,7 @@ static const char *ll_names[] = { "io", "io", + "trace", "debug", "info", "unusual", diff --git a/common/status_levels.h b/common/status_levels.h index 32d3338c9b40..79f7bc57313a 100644 --- a/common/status_levels.h +++ b/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. */ diff --git a/contrib/msggen/msggen/schema.json b/contrib/msggen/msggen/schema.json index 2b26022f87fe..61323dffda79 100644 --- a/contrib/msggen/msggen/schema.json +++ b/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" ] } } diff --git a/doc/schemas/lightning-getlog.json b/doc/schemas/lightning-getlog.json index e179cfe75fc7..018c14303e8f 100644 --- a/doc/schemas/lightning-getlog.json +++ b/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" ] } } diff --git a/lightningd/log.c b/lightningd/log.c index 316890115fde..6173239bc5ef 100644 --- a/lightningd/log.c +++ b/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"); diff --git a/lightningd/log.h b/lightningd/log.h index 3812788bc9aa..e73fdce94183 100644 --- a/lightningd/log.h +++ b/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__)