diff --git a/doc/lightningd-config.5.md b/doc/lightningd-config.5.md index 97c06a0fb..ee6d455aa 100644 --- a/doc/lightningd-config.5.md +++ b/doc/lightningd-config.5.md @@ -155,11 +155,11 @@ binary. Specify pid file to write to. -* **log-level**=*LEVEL*\[:*SUBSYSTEM*\] +* **log-level**=*LEVEL*\[:*SUBSYSTEM*\]\[:*PATH*\] What log level to print out: options are io, debug, info, unusual, broken. If *SUBSYSTEM* is supplied, this sets the logging level -for any subsystem (or *nodeid*) containing that string. This option may be specified multiple times. +for any subsystem (or *nodeid*) containing that string. If *PATH* is supplied, it means this log-level filter is only applied to that `log-file`, which is useful for creating logs to capture a specific subsystem. This option may be specified multiple times. Subsystems include: * *lightningd*: The main lightning daemon @@ -195,8 +195,7 @@ Subsystems include: So, **log-level=debug:plugin** would set debug level logging on all plugins and the plugin manager. **log-level=io:chan#55** would set IO logging on channel number 55 (or 550, for that matter). -**log-level=debug:024b9a1fa8** would set debug logging for that channel -(or any node id containing that string). +**log-level=debug:024b9a1fa8:/tmp/024b9a1fa8.debug.log** would set debug logging for that channel only on the **log-file=/tmp/024b9a1fa8.debug.log** (or any node id containing that string). * **log-prefix**=*PREFIX* diff --git a/lightningd/log.c b/lightningd/log.c index e813ed119..cc23e40b9 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -639,6 +639,18 @@ static void log_one_line(unsigned int skipped, data->prefix = "\n"; } +static struct log_file *find_log_file(struct log_book *log_book, + const char *fname) +{ + assert(tal_count(log_book->log_files) + == tal_count(log_book->ld->logfiles)); + for (size_t i = 0; i < tal_count(log_book->log_files); i++) { + if (streq(log_book->ld->logfiles[i], fname)) + return log_book->log_files[i]; + } + return NULL; +} + char *opt_log_level(const char *arg, struct log_book *log_book) { enum log_level level; @@ -652,7 +664,21 @@ char *opt_log_level(const char *arg, struct log_book *log_book) struct print_filter *f = tal(log_book, struct print_filter); f->prefix = arg + len + 1; f->level = level; - list_add_tail(&log_book->print_filters, &f->list); + + /* : */ + len = strcspn(f->prefix, ":"); + if (f->prefix[len]) { + struct log_file *lf; + lf = find_log_file(log_book, f->prefix + len + 1); + if (!lf) + return tal_fmt(tmpctx, + "unknown log file %s", + f->prefix + len + 1); + f->prefix = tal_strndup(f, f->prefix, len); + list_add_tail(&lf->print_filters, &f->list); + } else { + list_add_tail(&log_book->print_filters, &f->list); + } } else { tal_free(log_book->default_print_level); log_book->default_print_level = tal(log_book, enum log_level); diff --git a/lightningd/test/run-log_filter.c b/lightningd/test/run-log_filter.c new file mode 100644 index 000000000..be53d73a0 --- /dev/null +++ b/lightningd/test/run-log_filter.c @@ -0,0 +1,250 @@ +#include "config.h" +#include +#include +#include +#include + +#define fwrite test_fwrite +static size_t test_fwrite(const void *ptr, size_t size, size_t nmemb, + FILE *stream); +#include "../log.c" + +/* AUTOGENERATED MOCKS START */ +/* Generated stub for command_fail */ +struct command_result *command_fail(struct command *cmd UNNEEDED, enum jsonrpc_errcode code UNNEEDED, + const char *fmt UNNEEDED, ...) + +{ fprintf(stderr, "command_fail called!\n"); abort(); } +/* Generated stub for command_param_failed */ +struct command_result *command_param_failed(void) + +{ fprintf(stderr, "command_param_failed called!\n"); abort(); } +/* Generated stub for command_success */ +struct command_result *command_success(struct command *cmd UNNEEDED, + struct json_stream *response) + +{ fprintf(stderr, "command_success called!\n"); abort(); } +/* Generated stub for fromwire_bigsize */ +bigsize_t fromwire_bigsize(const u8 **cursor UNNEEDED, size_t *max UNNEEDED) +{ fprintf(stderr, "fromwire_bigsize called!\n"); abort(); } +/* Generated stub for fromwire_channel_id */ +bool fromwire_channel_id(const u8 **cursor UNNEEDED, size_t *max UNNEEDED, + struct channel_id *channel_id UNNEEDED) +{ fprintf(stderr, "fromwire_channel_id called!\n"); abort(); } +/* Generated stub for json_add_hex_talarr */ +void json_add_hex_talarr(struct json_stream *result UNNEEDED, + const char *fieldname UNNEEDED, + const tal_t *data UNNEEDED) +{ fprintf(stderr, "json_add_hex_talarr called!\n"); abort(); } +/* Generated stub for json_add_node_id */ +void json_add_node_id(struct json_stream *response UNNEEDED, + const char *fieldname UNNEEDED, + const struct node_id *id UNNEEDED) +{ fprintf(stderr, "json_add_node_id called!\n"); abort(); } +/* Generated stub for json_add_num */ +void json_add_num(struct json_stream *result UNNEEDED, const char *fieldname UNNEEDED, + unsigned int value UNNEEDED) +{ fprintf(stderr, "json_add_num called!\n"); abort(); } +/* Generated stub for json_add_str_fmt */ +void json_add_str_fmt(struct json_stream *js UNNEEDED, + const char *fieldname UNNEEDED, + const char *fmt UNNEEDED, ...) +{ fprintf(stderr, "json_add_str_fmt called!\n"); abort(); } +/* Generated stub for json_add_string */ +void json_add_string(struct json_stream *js UNNEEDED, + const char *fieldname UNNEEDED, + const char *str TAKES UNNEEDED) +{ fprintf(stderr, "json_add_string called!\n"); abort(); } +/* Generated stub for json_add_time */ +void json_add_time(struct json_stream *result UNNEEDED, const char *fieldname UNNEEDED, + struct timespec ts UNNEEDED) +{ fprintf(stderr, "json_add_time called!\n"); abort(); } +/* Generated stub for json_array_end */ +void json_array_end(struct json_stream *js UNNEEDED) +{ fprintf(stderr, "json_array_end called!\n"); abort(); } +/* Generated stub for json_array_start */ +void json_array_start(struct json_stream *js UNNEEDED, const char *fieldname UNNEEDED) +{ fprintf(stderr, "json_array_start called!\n"); abort(); } +/* Generated stub for json_object_end */ +void json_object_end(struct json_stream *js UNNEEDED) +{ fprintf(stderr, "json_object_end called!\n"); abort(); } +/* Generated stub for json_object_start */ +void json_object_start(struct json_stream *ks UNNEEDED, const char *fieldname UNNEEDED) +{ fprintf(stderr, "json_object_start called!\n"); abort(); } +/* Generated stub for json_stream_log_suppress_for_cmd */ +void json_stream_log_suppress_for_cmd(struct json_stream *js UNNEEDED, + const struct command *cmd UNNEEDED) +{ fprintf(stderr, "json_stream_log_suppress_for_cmd called!\n"); abort(); } +/* Generated stub for json_stream_success */ +struct json_stream *json_stream_success(struct command *cmd UNNEEDED) +{ fprintf(stderr, "json_stream_success called!\n"); abort(); } +/* Generated stub for notify_warning */ +void notify_warning(struct lightningd *ld UNNEEDED, struct log_entry *l UNNEEDED) +{ fprintf(stderr, "notify_warning called!\n"); abort(); } +/* Generated stub for param */ +bool param(struct command *cmd UNNEEDED, const char *buffer UNNEEDED, + const jsmntok_t params[] UNNEEDED, ...) +{ fprintf(stderr, "param called!\n"); abort(); } +/* Generated stub for towire_bigsize */ +void towire_bigsize(u8 **pptr UNNEEDED, const bigsize_t val UNNEEDED) +{ fprintf(stderr, "towire_bigsize called!\n"); abort(); } +/* Generated stub for towire_channel_id */ +void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id UNNEEDED) +{ fprintf(stderr, "towire_channel_id called!\n"); abort(); } +/* AUTOGENERATED MOCKS END */ + +static size_t num_written; +static size_t test_fwrite(const void *ptr, size_t size, size_t nmemb, + FILE *stream) +{ + num_written++; + return nmemb; +} + +static size_t try_log(struct log_book *lb, const char *prefix, + const struct node_id *node_id, + enum log_level level) +{ + struct logger *log = new_logger(NULL, lb, node_id, "%s", prefix); + + num_written = 0; + log_(log, level, NULL, false, "test_log"); + tal_free(log); + return num_written; +} + +int main(int argc, char *argv[]) +{ + struct log_book *lb; + struct node_id node_id; + struct lightningd *ld; + char tmpfiletemplate[] = "/tmp/run-log_filter.XXXXXX"; + + common_setup(argv[0]); + + assert(node_id_from_hexstr("0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518", + strlen("0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518"), &node_id)); + + ld = tal(tmpctx, struct lightningd); + ld->logfiles = NULL; + lb = ld->log_book = new_log_book(ld, 1024*1024); + ld->log = new_logger(ld, lb, NULL, "dummy"); + assert(arg_log_to_file("-", ld) == NULL); + + assert(mkstemp(tmpfiletemplate) >= 0); + assert(arg_log_to_file(tmpfiletemplate, ld) == NULL); + + /* Log level default. */ + assert(opt_log_level("BROKEN", lb) == NULL); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 0); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0); + + /* Now use debug as default */ + assert(opt_log_level("debug", lb) == NULL); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0); + + /* Log level exception for prefix */ + assert(opt_log_level("broken:prefix2", lb) == NULL); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0); + + assert(try_log(lb, "prefix2", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix2", NULL, LOG_INFORM) == 0); + assert(try_log(lb, "prefix2", NULL, LOG_DBG) == 0); + assert(try_log(lb, "prefix2", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix2", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix2", &node_id, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix2", &node_id, LOG_INFORM) == 0); + assert(try_log(lb, "prefix2", &node_id, LOG_DBG) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0); + + /* Log level exception for nodeid: that only does broken! */ + assert(opt_log_level("broken:0266e4598", lb) == NULL); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", &node_id, LOG_INFORM) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_DBG) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", &node_id, LOG_IO_IN) == 0); + + /* File exceptions: log stdout prefix to stdout */ + assert(opt_log_level("io:stdout1:-", lb) == NULL); + assert(try_log(lb, "stdout1", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_DBG) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_IO_OUT) == 1); + assert(try_log(lb, "stdout1", NULL, LOG_IO_IN) == 1); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + + /* File exceptions: log stdout2 prefix to stdout */ + assert(opt_log_level("broken:stdout2:-", lb) == NULL); + assert(try_log(lb, "stdout2", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "stdout2", NULL, LOG_INFORM) == 1); + assert(try_log(lb, "stdout2", NULL, LOG_DBG) == 1); + assert(try_log(lb, "stdout2", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "stdout2", NULL, LOG_IO_IN) == 0); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 0); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 0); + + /* File exception: tmpfile logs everything */ + assert(opt_log_level(tal_fmt(tmpctx, "io::%s", tmpfiletemplate), lb) == NULL); + assert(try_log(lb, "stdout1", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_DBG) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_IO_OUT) == 2); + assert(try_log(lb, "stdout1", NULL, LOG_IO_IN) == 2); + assert(try_log(lb, "stdout2", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "stdout2", NULL, LOG_INFORM) == 1); + assert(try_log(lb, "stdout2", NULL, LOG_DBG) == 1); + assert(try_log(lb, "stdout2", NULL, LOG_IO_OUT) == 1); + assert(try_log(lb, "stdout2", NULL, LOG_IO_IN) == 1); + assert(try_log(lb, "prefix", NULL, LOG_BROKEN) == 2); + assert(try_log(lb, "prefix", NULL, LOG_INFORM) == 2); + assert(try_log(lb, "prefix", NULL, LOG_DBG) == 2); + assert(try_log(lb, "prefix", NULL, LOG_IO_OUT) == 1); + assert(try_log(lb, "prefix", NULL, LOG_IO_IN) == 1); + + /* Close output file, avoid upsetting valgrind */ + fclose(ld->log_book->log_files[1]->f); + + /* Freeing (last) log frees logbook */ + tal_free(ld->log); + common_shutdown(); +} diff --git a/tests/test_misc.py b/tests/test_misc.py index 1e9554d87..04af4099a 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -2988,9 +2988,30 @@ def test_getlog(node_factory): def test_log_filter(node_factory): """Test the log-level option with subsystem filters""" # This actually suppresses debug! - l1, l2 = node_factory.line_graph(2, opts=[{'log-level': ['debug', 'broken:022d223620']}, {}]) + l1 = node_factory.get_node(options={'log-level': ['debug', 'broken:022d223620']}) + l2 = node_factory.get_node(start=False) + log1 = os.path.join(l2.daemon.lightning_dir, "log") + log2 = os.path.join(l2.daemon.lightning_dir, "log2") + # We need to set log file before we set options on it. + l2.daemon.early_opts += [f'--log-file={l}' for l in [log2] + l2.daemon.opts['log-file']] + del l2.daemon.opts['log-file'] + l2.daemon.opts['log-level'] = ["broken", # broken messages go everywhere + f"debug::{log1}", # debug to normal log + "debug::-", # debug to stdout + f'io:0266e4598d1d3:{log2}'] + l2.start() + node_factory.join_nodes([l1, l2]) + + # 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']) + + # Every message in log2 must be about l1... + with open(log2, "r") as f: + lines = f.readlines() + assert all([' {}-'.format(l1.info['id']) in l for l in lines]) def test_force_feerates(node_factory):