mirrors/core-lightning
1
0
Fork 0
mirror of https://github.com/ElementsProject/lightning.git synced 2025-01-18 21:35:11 +01:00
Code Issues Projects Releases Wiki Activity

lightningd: make log-prefix actually prepend all log messages as expected.

Browse Source 
It actually only sets the prefix for the lightningd core log messages;
the other logs have their own prefix.

Make it a real, process-wide prefix which actually goes in front of the timestamp.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: options: `log-prefix` now correctly prefixes *all* log messages.
This commit is contained in:
Rusty Russell 2022-07-08 19:27:11 +09:30
parent ba4e9b64b5
commit 6aec374674
3 changed files with 35 additions and 30 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
doc/lightningd-config.5.md
View File

@ -153,8 +153,9 @@ IO logging on channel number 55 (or 550, for that matter).
(or any node id containing that string). (or any node id containing that string).
**log-prefix**=*PREFIX* **log-prefix**=*PREFIX*
Prefix for log lines: this can be customized if you want to merge logs Prefix for all log lines: this can be customized if you want to merge logs
with multiple daemons. with multiple daemons. Usually you want to include a space at the end of *PREFIX*,
as the timestamp follows immediately.
**log-file**=*PATH* **log-file**=*PATH*
Log to this file (instead of stdout). If you specify this more than once Log to this file (instead of stdout). If you specify this more than once

46
lightningd/log.c
View File

@ -45,6 +45,8 @@ struct log_book {
bool print_timestamps; bool print_timestamps;
struct log_entry *log; struct log_entry *log;
/* Prefix this to every entry as you output */
const char *prefix;
/* Although log_book will copy log entries to parent log_book /* Although log_book will copy log entries to parent log_book
* (the log_book belongs to lightningd), a pointer to lightningd * (the log_book belongs to lightningd), a pointer to lightningd
@ -130,7 +132,8 @@ static const char *level_prefix(enum log_level level)
abort(); abort();
} }
static void log_to_files(const char *prefix, static void log_to_files(const char *log_prefix,
const char *entry_prefix,
enum log_level level, enum log_level level,
const struct node_id *node_id, const struct node_id *node_id,
const struct timeabs *time, const struct timeabs *time,
@ -154,23 +157,23 @@ static void log_to_files(const char *prefix,
const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]"; const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
char *hex = tal_hexstr(NULL, io, io_len); char *hex = tal_hexstr(NULL, io, io_len);
if (!node_id) if (!node_id)
entry = tal_fmt(tmpctx, "%s%s: %s%s %s\n", entry = tal_fmt(tmpctx, "%s%s%s: %s%s %s\n",
tstamp, prefix, str, dir, hex); log_prefix, tstamp, entry_prefix, str, dir, hex);
else else
entry = tal_fmt(tmpctx, "%s%s-%s: %s%s %s\n", entry = tal_fmt(tmpctx, "%s%s%s-%s: %s%s %s\n",
tstamp, log_prefix, tstamp,
node_id_to_hexstr(tmpctx, node_id), node_id_to_hexstr(tmpctx, node_id),
prefix, str, dir, hex); entry_prefix, str, dir, hex);
tal_free(hex); tal_free(hex);
} else { } else {
if (!node_id) if (!node_id)
entry = tal_fmt(tmpctx, "%s%s %s: %s\n", entry = tal_fmt(tmpctx, "%s%s%s %s: %s\n",
tstamp, level_prefix(level), prefix, str); log_prefix, tstamp, level_prefix(level), entry_prefix, str);
else else
entry = tal_fmt(tmpctx, "%s%s %s-%s: %s\n", entry = tal_fmt(tmpctx, "%s%s%s %s-%s: %s\n",
tstamp, level_prefix(level), log_prefix, tstamp, level_prefix(level),
node_id_to_hexstr(tmpctx, node_id), node_id_to_hexstr(tmpctx, node_id),
prefix, str); entry_prefix, str);
} }
/* Default if nothing set is stdout */ /* Default if nothing set is stdout */
@ -278,6 +281,8 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
lr->max_mem = max_mem; lr->max_mem = max_mem;
lr->outfiles = NULL; lr->outfiles = NULL;
lr->default_print_level = NULL; lr->default_print_level = NULL;
/* We have to allocate this, since we tal_free it on resetting */
lr->prefix = tal_strdup(lr, "");
list_head_init(&lr->print_filters); list_head_init(&lr->print_filters);
lr->init_time = time_now(); lr->init_time = time_now();
lr->ld = ld; lr->ld = ld;
@ -403,7 +408,7 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level,
static void maybe_print(struct log *log, const struct log_entry *l) static void maybe_print(struct log *log, const struct log_entry *l)
{ {
if (l->level >= log_print_level(log, l->nc ? &l->nc->node_id : NULL)) if (l->level >= log_print_level(log, l->nc ? &l->nc->node_id : NULL))
log_to_files(log->prefix->prefix, l->level, log_to_files(log->lr->prefix, log->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL, l->nc ? &l->nc->node_id : NULL,
&l->time, l->log, &l->time, l->log,
l->io, tal_bytelen(l->io), l->io, tal_bytelen(l->io),
@ -453,7 +458,7 @@ void log_io(struct log *log, enum log_level dir,
/* Print first, in case we need to truncate. */ /* Print first, in case we need to truncate. */
if (l->level >= log_print_level(log, node_id)) if (l->level >= log_print_level(log, node_id))
log_to_files(log->prefix->prefix, l->level, log_to_files(log->lr->prefix, log->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL, l->nc ? &l->nc->node_id : NULL,
&l->time, str, &l->time, str,
data, len, data, len,
@ -619,17 +624,16 @@ static void show_log_level(char buf[OPT_SHOW_LEN], const struct log *log)
buf[OPT_SHOW_LEN - 1] = '\0'; buf[OPT_SHOW_LEN - 1] = '\0';
} }
static char *arg_log_prefix(const char *arg, struct log *log) static char *arg_log_prefix(const char *arg, struct log_book *log_book)
{ {
/* log->lr owns this, since it keeps a pointer to it. */ tal_free(log_book->prefix);
log_prefix_drop(log->prefix); log_book->prefix = tal_strdup(log_book, arg);
log->prefix = log_prefix_new(log->lr, arg);
return NULL; return NULL;
} }
static void show_log_prefix(char buf[OPT_SHOW_LEN], const struct log *log) static void show_log_prefix(char buf[OPT_SHOW_LEN], const struct log_book *log_book)
{ {
strncpy(buf, log->prefix->prefix, OPT_SHOW_LEN - 1); strncpy(buf, log_book->prefix, OPT_SHOW_LEN - 1);
buf[OPT_SHOW_LEN - 1] = '\0'; buf[OPT_SHOW_LEN - 1] = '\0';
} }
@ -742,7 +746,7 @@ void opt_register_logging(struct lightningd *ld)
opt_set_bool_arg, opt_show_bool, &ld->log->lr->print_timestamps, opt_set_bool_arg, opt_show_bool, &ld->log->lr->print_timestamps,
"prefix log messages with timestamp"); "prefix log messages with timestamp");
opt_register_early_arg("--log-prefix", arg_log_prefix, show_log_prefix, opt_register_early_arg("--log-prefix", arg_log_prefix, show_log_prefix,
ld->log, ld->log_book,
"log prefix"); "log prefix");
opt_register_early_arg("--log-file=<file>", arg_log_to_file, NULL, ld, opt_register_early_arg("--log-file=<file>", arg_log_to_file, NULL, ld,
"Also log to file (- for stdout)"); "Also log to file (- for stdout)");
@ -761,7 +765,7 @@ void logging_options_parsed(struct log_book *lr)
const struct log_entry *l = &lr->log[i]; const struct log_entry *l = &lr->log[i];
if (l->level >= filter_level(lr, l->prefix, NULL)) if (l->level >= filter_level(lr, l->prefix, NULL))
log_to_files(l->prefix->prefix, l->level, log_to_files(lr->prefix, l->prefix->prefix, l->level,
l->nc ? &l->nc->node_id : NULL, l->nc ? &l->nc->node_id : NULL,
&l->time, l->log, &l->time, l->log,
l->io, tal_bytelen(l->io), l->io, tal_bytelen(l->io),

14
tests/test_gossip.py
View File

@ -2102,20 +2102,20 @@ def test_addgossip(node_factory):
nann1 = l1.daemon.is_in_log(r"\[OUT\] 0101.*") nann1 = l1.daemon.is_in_log(r"\[OUT\] 0101.*")
nann2 = l2.daemon.is_in_log(r"\[OUT\] 0101.*") nann2 = l2.daemon.is_in_log(r"\[OUT\] 0101.*")
# Feed them to l3 (Each one starts with TIMESTAMP chanid-xxx: [OUT] ...) # Feed them to l3 (Each one starts with PREFIX TIMESTAMP chanid-xxx: [OUT] ...)
l3.rpc.addgossip(ann.split()[3]) l3.rpc.addgossip(ann.split()[4])
l3.rpc.addgossip(upd1.split()[3]) l3.rpc.addgossip(upd1.split()[4])
l3.rpc.addgossip(upd2.split()[3]) l3.rpc.addgossip(upd2.split()[4])
l3.rpc.addgossip(nann1.split()[3]) l3.rpc.addgossip(nann1.split()[4])
l3.rpc.addgossip(nann2.split()[3]) l3.rpc.addgossip(nann2.split()[4])
# In this case, it can actually have to wait, since it does scid lookup. # In this case, it can actually have to wait, since it does scid lookup.
wait_for(lambda: len(l3.rpc.listchannels()['channels']) == 2) wait_for(lambda: len(l3.rpc.listchannels()['channels']) == 2)
wait_for(lambda: len(l3.rpc.listnodes()['nodes']) == 2) wait_for(lambda: len(l3.rpc.listnodes()['nodes']) == 2)
# Now corrupt an update # Now corrupt an update
badupdate = upd1.split()[3] badupdate = upd1.split()[4]
if badupdate.endswith('f'): if badupdate.endswith('f'):
badupdate = badupdate[:-1] + 'e' badupdate = badupdate[:-1] + 'e'
else: else: