lightningd: fix up log filtering for generic daemons (e.g. connectd).

Without this, only per-peer daemons were filtered correctly.  For generic
daemons, we need to filter with the actual nodeid they use (if any).

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: config: `log-level` filters now apply correctly to messages from `connectd`.
This commit is contained in:
Rusty Russell 2023-07-19 14:26:22 +09:30
parent 4a7b1b457e
commit e5d0d6958c
2 changed files with 84 additions and 24 deletions

View file

@ -74,6 +74,9 @@ struct logger {
/* Print log message at >= this level */
enum log_level print_level;
/* For non-trivial setups, we might need to test filters again
* when actually producing output. */
bool need_refiltering;
};
static struct log_prefix *log_prefix_new(const tal_t *ctx,
@ -154,10 +157,45 @@ static bool filter_level(const struct list_head *print_filters,
return false;
}
/* What's the lowest filtering which could possibly apply? */
static void lowest_filter(const struct list_head *print_filters,
const char *prefix,
const struct node_id *node_id,
enum log_level *level)
{
struct print_filter *i;
const char *node_id_str;
if (node_id)
node_id_str = node_id_to_hexstr(tmpctx, node_id);
else
node_id_str = NULL;
list_for_each(print_filters, i, list) {
bool match;
if (strstr(prefix, i->prefix))
match = true;
else if (node_id_str) {
match = (strstr(node_id_str, i->prefix) != NULL);
} else {
/* Could this possibly match a node_id? */
match = strstarts(i->prefix, "02") || strstarts(i->prefix, "03");
}
if (match && i->level < *level) {
*level = i->level;
}
}
}
static void log_to_files(const char *log_prefix,
const char *entry_prefix,
enum log_level level,
/* The node_id to log under. */
const struct node_id *node_id,
/* Filters to apply, if non-NULL */
const struct list_head *print_filters,
const struct timeabs *time,
const char *str,
const u8 *io,
@ -203,6 +241,17 @@ static void log_to_files(const char *log_prefix,
entry_prefix, str);
}
/* In complex configurations, we tell loggers to overshare: then we
* need to filter here to see if we really want it. */
if (print_filters) {
enum log_level filter;
if (filter_level(print_filters,
entry_prefix, nodestr, &filter)) {
if (level < filter)
return;
}
}
/* Default if nothing set is stdout */
if (!log_files) {
fwrite(entry, strlen(entry), 1, stdout);
@ -336,32 +385,34 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
return log_book;
}
/* What's the minimum level to print for this log book? */
/* What's the minimum level to print this prefix and node_id for this
* log book? Saves us marshalling long print lines in most cases. */
static enum log_level print_level(struct log_book *log_book,
const struct log_prefix *lp,
const struct node_id *node_id)
const struct node_id *node_id,
bool *need_refiltering)
{
enum log_level level;
const char *node_id_str = node_id ? node_id_to_hexstr(tmpctx, node_id) : "";
enum log_level level = *log_book->default_print_level;
bool have_filters = false;
assert(log_book->default_print_level != NULL);
if (!filter_level(&log_book->print_filters, lp->prefix,
node_id_str, &level)) {
level = *log_book->default_print_level;
}
lowest_filter(&log_book->print_filters, lp->prefix, node_id, &level);
if (!list_empty(&log_book->print_filters))
have_filters = true;
/* We need to look into per-file filters as well: might give a
* lower filter! */
for (size_t i = 0; i < tal_count(log_book->log_files); i++) {
enum log_level sublevel;
if (filter_level(&log_book->log_files[i]->print_filters,
lp->prefix, node_id_str, &sublevel)) {
if (sublevel < level) {
level = sublevel;
}
}
lowest_filter(&log_book->log_files[i]->print_filters,
lp->prefix, node_id, &level);
if (!list_empty(&log_book->log_files[i]->print_filters))
have_filters = true;
}
/* Almost any complex array of filters can mean we want to re-check
* when logging. */
if (need_refiltering)
*need_refiltering = have_filters;
return level;
}
@ -389,10 +440,15 @@ new_logger(const tal_t *ctx, struct log_book *log_book,
default_node_id);
/* Still initializing? Print UNUSUAL / BROKEN messages only */
if (!log->log_book->default_print_level)
if (!log->log_book->default_print_level) {
log->print_level = LOG_UNUSUAL;
else
log->print_level = print_level(log->log_book, log->prefix, default_node_id);
log->need_refiltering = false;
} else {
log->print_level = print_level(log->log_book,
log->prefix,
default_node_id,
&log->need_refiltering);
}
list_add(&log->log_book->loggers, &log->list);
tal_add_destructor(log, destroy_logger);
return log;
@ -405,7 +461,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) < LOG_DBG;
return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_DBG;
}
/* This may move entry! */
@ -467,6 +523,7 @@ static void maybe_print(struct logger *log, const struct log_entry *l)
if (l->level >= log->print_level)
log_to_files(log->log_book->prefix, log->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL,
log->need_refiltering ? &log->log_book->print_filters : NULL,
&l->time, l->log,
l->io, tal_bytelen(l->io),
log->log_book->print_timestamps,
@ -518,6 +575,7 @@ void log_io(struct logger *log, enum log_level dir,
if (l->level >= log->print_level)
log_to_files(log->log_book->prefix, log->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL,
log->need_refiltering ? &log->log_book->print_filters : NULL,
&l->time, str,
data, len,
log->log_book->print_timestamps,
@ -857,16 +915,18 @@ void logging_options_parsed(struct log_book *log_book)
list_for_each(&log_book->loggers, log, list) {
log->print_level = print_level(log_book,
log->prefix,
log->default_node_id);
log->default_node_id,
&log->need_refiltering);
}
/* Catch up, since before we were only printing BROKEN msgs */
for (size_t i = 0; i < log_book->num_entries; i++) {
const struct log_entry *l = &log_book->log[i];
if (l->level >= print_level(log_book, l->prefix, l->nc ? &l->nc->node_id : NULL))
if (l->level >= print_level(log_book, l->prefix, l->nc ? &l->nc->node_id : NULL, NULL))
log_to_files(log_book->prefix, l->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL,
&log_book->print_filters,
&l->time, l->log,
l->io, tal_bytelen(l->io),
log_book->print_timestamps,

View file

@ -3005,8 +3005,8 @@ def test_log_filter(node_factory):
# No debug messages in l1's log
assert not l1.daemon.is_in_log(r'-chan#[0-9]*:')
# FIXME: the connectd messages should also be matched!
# assert not l1.daemon.is_in_log(l2.info['id'])
# No mention of l2 at all (except spenderp mentions it)
assert not l1.daemon.is_in_log(l2.info['id'] + '-')
# Every message in log2 must be about l1...
with open(log2, "r") as f: