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
This commit is contained in:
Ken Sedgwick 2024-04-25 16:42:54 -07:00 committed by Rusty Russell
parent c3280676e8
commit e3c600b0c8
12 changed files with 674 additions and 622 deletions

View file

@ -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": {

View file

@ -161,6 +161,7 @@ message ListpeersRequest {
DEBUG = 1;
INFO = 2;
UNUSUAL = 3;
TRACE = 4;
}
optional bytes id = 1;
optional ListpeersLevel level = 2;
@ -190,6 +191,7 @@ message ListpeersPeersLog {
DEBUG = 4;
IO_IN = 5;
IO_OUT = 6;
TRACE = 7;
}
ListpeersPeersLogType item_type = 1;
optional uint32 num_skipped = 2;
@ -1829,6 +1831,7 @@ message GetlogRequest {
INFO = 2;
DEBUG = 3;
IO = 4;
TRACE = 5;
}
optional GetlogLevel level = 1;
}
@ -1850,6 +1853,7 @@ message GetlogLog {
DEBUG = 4;
IO_IN = 5;
IO_OUT = 6;
TRACE = 7;
}
GetlogLogType item_type = 1;
optional uint32 num_skipped = 2;

16
cln-rpc/src/model.rs generated
View file

@ -260,6 +260,8 @@ pub mod requests {
INFO = 2,
#[serde(rename = "unusual")]
UNUSUAL = 3,
#[serde(rename = "trace")]
TRACE = 4,
}
impl TryFrom<i32> for ListpeersLevel {
@ -270,6 +272,7 @@ pub mod requests {
1 => Ok(ListpeersLevel::DEBUG),
2 => Ok(ListpeersLevel::INFO),
3 => Ok(ListpeersLevel::UNUSUAL),
4 => Ok(ListpeersLevel::TRACE),
o => Err(anyhow::anyhow!("Unknown variant {} for enum ListpeersLevel", o)),
}
}
@ -279,6 +282,7 @@ pub mod requests {
fn to_string(&self) -> String {
match self {
ListpeersLevel::IO => "IO",
ListpeersLevel::TRACE => "TRACE",
ListpeersLevel::DEBUG => "DEBUG",
ListpeersLevel::INFO => "INFO",
ListpeersLevel::UNUSUAL => "UNUSUAL",
@ -2051,6 +2055,8 @@ pub mod requests {
DEBUG = 3,
#[serde(rename = "io")]
IO = 4,
#[serde(rename = "trace")]
TRACE = 5,
}
impl TryFrom<i32> for GetlogLevel {
@ -2062,6 +2068,7 @@ pub mod requests {
2 => Ok(GetlogLevel::INFO),
3 => Ok(GetlogLevel::DEBUG),
4 => Ok(GetlogLevel::IO),
5 => Ok(GetlogLevel::TRACE),
o => Err(anyhow::anyhow!("Unknown variant {} for enum GetlogLevel", o)),
}
}
@ -2074,6 +2081,7 @@ pub mod requests {
GetlogLevel::UNUSUAL => "UNUSUAL",
GetlogLevel::INFO => "INFO",
GetlogLevel::DEBUG => "DEBUG",
GetlogLevel::TRACE => "TRACE",
GetlogLevel::IO => "IO",
}.to_string()
}
@ -3235,6 +3243,8 @@ pub mod responses {
IO_IN = 5,
#[serde(rename = "IO_OUT")]
IO_OUT = 6,
#[serde(rename = "TRACE")]
TRACE = 7,
}
impl TryFrom<i32> for ListpeersPeersLogType {
@ -3248,6 +3258,7 @@ pub mod responses {
4 => Ok(ListpeersPeersLogType::DEBUG),
5 => Ok(ListpeersPeersLogType::IO_IN),
6 => Ok(ListpeersPeersLogType::IO_OUT),
7 => Ok(ListpeersPeersLogType::TRACE),
o => Err(anyhow::anyhow!("Unknown variant {} for enum ListpeersPeersLogType", o)),
}
}
@ -3261,6 +3272,7 @@ pub mod responses {
ListpeersPeersLogType::UNUSUAL => "UNUSUAL",
ListpeersPeersLogType::INFO => "INFO",
ListpeersPeersLogType::DEBUG => "DEBUG",
ListpeersPeersLogType::TRACE => "TRACE",
ListpeersPeersLogType::IO_IN => "IO_IN",
ListpeersPeersLogType::IO_OUT => "IO_OUT",
}.to_string()
@ -6321,6 +6333,8 @@ pub mod responses {
IO_IN = 5,
#[serde(rename = "IO_OUT")]
IO_OUT = 6,
#[serde(rename = "TRACE")]
TRACE = 7,
}
impl TryFrom<i32> for GetlogLogType {
@ -6334,6 +6348,7 @@ pub mod responses {
4 => Ok(GetlogLogType::DEBUG),
5 => Ok(GetlogLogType::IO_IN),
6 => Ok(GetlogLogType::IO_OUT),
7 => Ok(GetlogLogType::TRACE),
o => Err(anyhow::anyhow!("Unknown variant {} for enum GetlogLogType", o)),
}
}
@ -6347,6 +6362,7 @@ pub mod responses {
GetlogLogType::UNUSUAL => "UNUSUAL",
GetlogLogType::INFO => "INFO",
GetlogLogType::DEBUG => "DEBUG",
GetlogLogType::TRACE => "TRACE",
GetlogLogType::IO_IN => "IO_IN",
GetlogLogType::IO_OUT => "IO_OUT",
}.to_string()

View file

@ -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, ...) \

View file

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

View file

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

View file

@ -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"
]
}
}

File diff suppressed because one or more lines are too long

View file

@ -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"
]
}
}

View file

@ -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"
]
}
}

View file

@ -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");

View file

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