From 56dde2cb7718377dc4b0487301cdf5eadc2d7e5f Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Sun, 26 Jun 2022 13:55:01 +0930 Subject: [PATCH] lightningd: multiple log-file options allow more than one log output. I've wanted this for a while: the ability to log to multiple places at once. Signed-off-by: Rusty Russell Changelog-Changed: lightningd: `log-file` option specified multiple times opens multiple log files. --- doc/lightningd-config.5.md | 6 +- lightningd/lightningd.c | 2 +- lightningd/lightningd.h | 2 +- lightningd/log.c | 140 +++++++++++++++++++++---------------- lightningd/options.c | 13 +++- tests/test_misc.py | 18 +++++ 6 files changed, 116 insertions(+), 65 deletions(-) diff --git a/doc/lightningd-config.5.md b/doc/lightningd-config.5.md index 5fc07bea9..31832958b 100644 --- a/doc/lightningd-config.5.md +++ b/doc/lightningd-config.5.md @@ -155,8 +155,10 @@ Prefix for log lines: this can be customized if you want to merge logs with multiple daemons. **log-file**=*PATH* -Log to this file instead of stdout. Sending lightningd(8) SIGHUP will -cause it to reopen this file (useful for log rotation). +Log to this file (instead of stdout). If you specify this more than once +you'll get more than one log file: **-** is used to mean stdout. Sending +lightningd(8) SIGHUP will cause it to reopen each file (useful for log +rotation). **log-timestamps**=*BOOL* Set this to false to turn off timestamp prefixes (they will still appear diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index b8e60b3ff..e9c993bd4 100644 --- a/lightningd/lightningd.c +++ b/lightningd/lightningd.c @@ -184,7 +184,7 @@ static struct lightningd *new_lightningd(const tal_t *ctx) * allocation function): ld->log will be implicitly freed when ld * is. */ ld->log = new_log(ld, ld->log_book, NULL, "lightningd"); - ld->logfile = NULL; + ld->logfiles = NULL; /*~ We explicitly set these to NULL: if they're still NULL after option * parsing, we know they're to be set to the defaults. */ diff --git a/lightningd/lightningd.h b/lightningd/lightningd.h index 5e3a1edb7..5440384b7 100644 --- a/lightningd/lightningd.h +++ b/lightningd/lightningd.h @@ -110,7 +110,7 @@ struct lightningd { struct log_book *log_book; /* Log for general stuff. */ struct log *log; - const char *logfile; + const char **logfiles; /* This is us. */ struct node_id id; diff --git a/lightningd/log.c b/lightningd/log.c index e578f9022..ddbcb7267 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -39,7 +39,9 @@ struct log_book { /* Non-null once it's been initialized */ enum log_level *default_print_level; struct timeabs init_time; - FILE *outf; + + /* Array of log files: one per ld->logfiles[] */ + FILE **outfiles; bool print_timestamps; struct log_entry *log; @@ -128,17 +130,18 @@ static const char *level_prefix(enum log_level level) abort(); } -static void log_to_file(const char *prefix, - enum log_level level, - const struct node_id *node_id, - const struct timeabs *time, - const char *str, - const u8 *io, - size_t io_len, - bool print_timestamps, - FILE *logf) +static void log_to_files(const char *prefix, + enum log_level level, + const struct node_id *node_id, + const struct timeabs *time, + const char *str, + const u8 *io, + size_t io_len, + bool print_timestamps, + FILE **outfiles) { char tstamp[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ ")]; + char *entry; if (print_timestamps) { char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ ")]; @@ -151,25 +154,34 @@ static void log_to_file(const char *prefix, const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]"; char *hex = tal_hexstr(NULL, io, io_len); if (!node_id) - fprintf(logf, "%s%s: %s%s %s\n", - tstamp, prefix, str, dir, hex); + entry = tal_fmt(tmpctx, "%s%s: %s%s %s\n", + tstamp, prefix, str, dir, hex); else - fprintf(logf, "%s%s-%s: %s%s %s\n", - tstamp, - node_id_to_hexstr(tmpctx, node_id), - prefix, str, dir, hex); + entry = tal_fmt(tmpctx, "%s%s-%s: %s%s %s\n", + tstamp, + node_id_to_hexstr(tmpctx, node_id), + prefix, str, dir, hex); tal_free(hex); } else { if (!node_id) - fprintf(logf, "%s%s %s: %s\n", - tstamp, level_prefix(level), prefix, str); + entry = tal_fmt(tmpctx, "%s%s %s: %s\n", + tstamp, level_prefix(level), prefix, str); else - fprintf(logf, "%s%s %s-%s: %s\n", - tstamp, level_prefix(level), - node_id_to_hexstr(tmpctx, node_id), - prefix, str); + entry = tal_fmt(tmpctx, "%s%s %s-%s: %s\n", + tstamp, level_prefix(level), + node_id_to_hexstr(tmpctx, node_id), + prefix, str); + } + + /* Default if nothing set is stdout */ + if (!outfiles) { + fwrite(entry, strlen(entry), 1, stdout); + fflush(stdout); + } + for (size_t i = 0; i < tal_count(outfiles); i++) { + fwrite(entry, strlen(entry), 1, outfiles[i]); + fflush(outfiles[i]); } - fflush(logf); } static size_t mem_used(const struct log_entry *e) @@ -264,7 +276,7 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem) lr->mem_used = 0; lr->num_entries = 0; lr->max_mem = max_mem; - lr->outf = stdout; + lr->outfiles = NULL; lr->default_print_level = NULL; list_head_init(&lr->print_filters); lr->init_time = time_now(); @@ -389,12 +401,12 @@ 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) { if (l->level >= log_print_level(log)) - log_to_file(log->prefix->prefix, l->level, - l->nc ? &l->nc->node_id : NULL, - &l->time, l->log, - l->io, tal_bytelen(l->io), - log->lr->print_timestamps, - log->lr->outf); + log_to_files(log->prefix->prefix, l->level, + l->nc ? &l->nc->node_id : NULL, + &l->time, l->log, + l->io, tal_bytelen(l->io), + log->lr->print_timestamps, + log->lr->outfiles); } void logv(struct log *log, enum log_level level, @@ -439,12 +451,12 @@ void log_io(struct log *log, enum log_level dir, /* Print first, in case we need to truncate. */ if (l->level >= log_print_level(log)) - log_to_file(log->prefix->prefix, l->level, - l->nc ? &l->nc->node_id : NULL, - &l->time, str, - data, len, - log->lr->print_timestamps, - log->lr->outf); + log_to_files(log->prefix->prefix, l->level, + l->nc ? &l->nc->node_id : NULL, + &l->time, str, + data, len, + log->lr->print_timestamps, + log->lr->outfiles); /* Save a tal header, by using raw malloc. */ l->log = strdup(str); @@ -608,7 +620,7 @@ static void show_log_level(char buf[OPT_SHOW_LEN], const struct log *log) static char *arg_log_prefix(const char *arg, struct log *log) { /* log->lr owns this, since it keeps a pointer to it. */ - tal_free(log->prefix); + log_prefix_drop(log->prefix); log->prefix = log_prefix_new(log->lr, arg); return NULL; } @@ -635,11 +647,14 @@ static struct io_plan *setup_read(struct io_conn *conn, struct lightningd *ld); static struct io_plan *rotate_log(struct io_conn *conn, struct lightningd *ld) { log_info(ld->log, "Ending log due to SIGHUP"); - fclose(ld->log->lr->outf); - - ld->log->lr->outf = fopen(ld->logfile, "a"); - if (!ld->log->lr->outf) - err(1, "failed to reopen log file %s", ld->logfile); + for (size_t i = 0; i < tal_count(ld->log->lr->outfiles); i++) { + if (streq(ld->logfiles[i], "-")) + continue; + fclose(ld->log->lr->outfiles[i]); + ld->log->lr->outfiles[i] = fopen(ld->logfiles[i], "a"); + if (!ld->log->lr->outfiles[i]) + err(1, "failed to reopen log file %s", ld->logfiles[i]); + } log_info(ld->log, "Started log due to SIGHUP"); return setup_read(conn, ld); @@ -688,22 +703,29 @@ static void setup_log_rotation(struct lightningd *ld) char *arg_log_to_file(const char *arg, struct lightningd *ld) { int size; + FILE *outf; - if (ld->logfile) { - fclose(ld->log->lr->outf); - ld->logfile = tal_free(ld->logfile); - } else + if (!ld->logfiles) { setup_log_rotation(ld); + ld->logfiles = tal_arr(ld, const char *, 0); + ld->log->lr->outfiles = tal_arr(ld->log->lr, FILE *, 0); + } - ld->logfile = tal_strdup(ld, arg); - ld->log->lr->outf = fopen(arg, "a"); - if (!ld->log->lr->outf) - return tal_fmt(NULL, "Failed to open: %s", strerror(errno)); + if (streq(arg, "-")) + outf = stdout; + else { + outf = fopen(arg, "a"); + if (!outf) + return tal_fmt(NULL, "Failed to open: %s", strerror(errno)); + } + + tal_arr_expand(&ld->logfiles, tal_strdup(ld->logfiles, arg)); + tal_arr_expand(&ld->log->lr->outfiles, outf); /* For convenience make a block of empty lines just like Bitcoin Core */ - size = ftell(ld->log->lr->outf); + size = ftell(outf); if (size > 0) - fprintf(ld->log->lr->outf, "\n\n\n\n"); + fprintf(outf, "\n\n\n\n"); log_debug(ld->log, "Opened log file %s", arg); return NULL; @@ -721,7 +743,7 @@ void opt_register_logging(struct lightningd *ld) ld->log, "log prefix"); opt_register_early_arg("--log-file=", arg_log_to_file, NULL, ld, - "log to file instead of stdout"); + "Also log to file (- for stdout)"); } void logging_options_parsed(struct log_book *lr) @@ -737,12 +759,12 @@ void logging_options_parsed(struct log_book *lr) const struct log_entry *l = &lr->log[i]; if (l->level >= filter_level(lr, l->prefix)) - log_to_file(l->prefix->prefix, l->level, - l->nc ? &l->nc->node_id : NULL, - &l->time, l->log, - l->io, tal_bytelen(l->io), - lr->print_timestamps, - lr->outf); + log_to_files(l->prefix->prefix, l->level, + l->nc ? &l->nc->node_id : NULL, + &l->time, l->log, + l->io, tal_bytelen(l->io), + lr->print_timestamps, + lr->outfiles); } } diff --git a/lightningd/options.c b/lightningd/options.c index 43be6bccc..e7e2b9cc4 100644 --- a/lightningd/options.c +++ b/lightningd/options.c @@ -880,7 +880,7 @@ static void check_config(struct lightningd *ld) if (ld->always_use_proxy && !ld->proxyaddr) fatal("--always-use-proxy needs --proxy"); - if (ld->daemon_parent_fd != -1 && !ld->logfile) + if (ld->daemon_parent_fd != -1 && !ld->logfiles) fatal("--daemon needs --log-file"); } @@ -1438,6 +1438,14 @@ static void json_add_opt_addrs(struct json_stream *response, } } +static void json_add_opt_log_to_files(struct json_stream *response, + const char *name0, + const char **logfiles) +{ + for (size_t i = 0; i < tal_count(logfiles); i++) + json_add_string(response, name0, logfiles[i]); +} + struct json_add_opt_alt_subdaemon_args { const char *name0; struct json_stream *response; @@ -1568,7 +1576,8 @@ static void add_config(struct lightningd *ld, } else if (opt->cb_arg == (void *)opt_set_alias) { answer = (const char *)ld->alias; } else if (opt->cb_arg == (void *)arg_log_to_file) { - answer = ld->logfile; + if (ld->logfiles) + json_add_opt_log_to_files(response, name0, ld->logfiles); } else if (opt->cb_arg == (void *)opt_add_addr) { json_add_opt_addrs(response, name0, ld->proposed_wireaddr, diff --git a/tests/test_misc.py b/tests/test_misc.py index fdbb525e6..3ddd751c7 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1475,6 +1475,24 @@ def test_logging(node_factory): wait_for(lambda: os.path.exists(logpath)) wait_for(check_new_log) + # Multiple log files + l2 = node_factory.get_node(options={'log-file': ['logfile1', 'logfile2']}, start=False) + logpath1 = os.path.join(l2.daemon.lightning_dir, TEST_NETWORK, 'logfile1') + logpath2 = os.path.join(l2.daemon.lightning_dir, TEST_NETWORK, 'logfile2') + l2.daemon.start(wait_for_initialized=False) + + wait_for(lambda: os.path.exists(logpath1)) + wait_for(lambda: os.path.exists(logpath2)) + wait_for(lambda: os.path.exists(os.path.join(l2.daemon.lightning_dir, TEST_NETWORK, "lightning-rpc"))) + lines = subprocess.check_output(['cli/lightning-cli', + '--network={}'.format(TEST_NETWORK), + '--lightning-dir={}' + .format(l2.daemon.lightning_dir), + '-H', + 'listconfigs']).decode('utf-8').splitlines() + assert 'log-file=logfile1' in lines + assert 'log-file=logfile2' in lines + @unittest.skipIf(VALGRIND, "Valgrind sometimes fails assert on injected SEGV")