From e433d4ddc16b5f02272205c64a8e2c3f7a9de82f Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Sun, 17 Nov 2019 22:11:33 +1030 Subject: [PATCH] lightningd: have logging include an optional node_id for each entry. A log can have a default node_id, which can be overridden on a per-entry basis. This changes the format of logging, so some tests need rework. Signed-off-by: Rusty Russell --- contrib/pyln-testing/pyln/testing/utils.py | 10 ++- lightningd/channel.c | 11 ++- lightningd/json_stream.c | 2 +- lightningd/jsonrpc.c | 8 +-- lightningd/lightningd.c | 3 +- lightningd/log.c | 76 ++++++++++++++++----- lightningd/log.h | 43 +++++++++--- lightningd/log_status.c | 8 ++- lightningd/log_status.h | 4 +- lightningd/opening_control.c | 7 +- lightningd/peer_control.c | 5 +- lightningd/plugin.c | 9 +-- lightningd/subd.c | 11 +-- lightningd/test/run-find_my_abspath.c | 13 +++- lightningd/test/run-invoice-select-inchan.c | 14 +++- lightningd/test/run-jsonrpc.c | 13 +++- tests/test_closing.py | 2 +- tests/test_connection.py | 2 +- tests/test_gossip.py | 6 +- tests/test_misc.py | 4 +- tests/test_plugin.py | 3 +- wallet/test/run-db.c | 2 +- wallet/test/run-wallet.c | 9 ++- 23 files changed, 178 insertions(+), 87 deletions(-) diff --git a/contrib/pyln-testing/pyln/testing/utils.py b/contrib/pyln-testing/pyln/testing/utils.py index a87d9c48ad8d..2cd8edf48b32 100644 --- a/contrib/pyln-testing/pyln/testing/utils.py +++ b/contrib/pyln-testing/pyln/testing/utils.py @@ -732,9 +732,13 @@ def fund_channel(self, l2, amount, wait_for_active=True): 'to CHANNELD_NORMAL']) return scid - def subd_pid(self, subd): + def subd_pid(self, subd, peerid=None): """Get the process id of the given subdaemon, eg channeld or gossipd""" - ex = re.compile(r'lightning_{}.*: pid ([0-9]*),'.format(subd)) + if peerid: + ex = re.compile(r'{}-.*lightning_{}.*: pid ([0-9]*),' + .format(peerid, subd)) + else: + ex = re.compile('lightning_{}-.*: pid ([0-9]*),'.format(subd)) # Make sure we get latest one if it's restarted! for l in reversed(self.daemon.logs): group = ex.search(l) @@ -1024,7 +1028,7 @@ def line_graph(self, num_nodes, fundchannel=True, fundamount=10**6, wait_for_ann # getpeers. if not fundchannel: for src, dst in connections: - dst.daemon.wait_for_log('openingd-{} chan #[0-9]*: Handed peer, entering loop'.format(src.info['id'])) + dst.daemon.wait_for_log(r'{}-.*lightning_openingd-chan #[0-9]*: Handed peer, entering loop'.format(src.info['id'])) return nodes # If we got here, we want to fund channels diff --git a/lightningd/channel.c b/lightningd/channel.c index 0e59e2d86aa7..f8821818fa1e 100644 --- a/lightningd/channel.c +++ b/lightningd/channel.c @@ -209,14 +209,11 @@ struct channel *new_channel(struct peer *peer, u64 dbid, if (!log) { /* FIXME: update log prefix when we get scid */ - /* FIXME: Use minimal unique pubkey prefix for logs! */ - const char *idname = type_to_string(peer, - struct node_id, - &peer->id); channel->log = new_log(channel, - peer->log_book, "%s chan #%"PRIu64":", - idname, dbid); - tal_free(idname); + peer->log_book, + &channel->peer->id, + "chan #%"PRIu64":", + dbid); } else channel->log = tal_steal(channel, log); channel->channel_flags = channel_flags; diff --git a/lightningd/json_stream.c b/lightningd/json_stream.c index cda1a3e88ff7..b21632d26724 100644 --- a/lightningd/json_stream.c +++ b/lightningd/json_stream.c @@ -209,7 +209,7 @@ static struct io_plan *json_stream_output_write(struct io_conn *conn, js->reader = conn; if (js->log) - log_io(js->log, LOG_IO_OUT, "", p, js->len_read); + log_io(js->log, LOG_IO_OUT, NULL, "", p, js->len_read); return io_write(conn, p, js->len_read, json_stream_output_write, js); diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index 82c445f3e17e..89f60483af96 100644 --- a/lightningd/jsonrpc.c +++ b/lightningd/jsonrpc.c @@ -531,7 +531,7 @@ void json_stream_log_suppress_for_cmd(struct json_stream *js, { const char *nm = cmd->json_cmd->name; const char *s = tal_fmt(tmpctx, "Suppressing logging of %s command", nm); - log_io(cmd->jcon->log, LOG_IO_OUT, s, NULL, 0); + log_io(cmd->jcon->log, LOG_IO_OUT, NULL, s, NULL, 0); json_stream_log_suppress(js, strdup(nm)); } @@ -828,7 +828,7 @@ static struct io_plan *read_json(struct io_conn *conn, bool valid; if (jcon->len_read) - log_io(jcon->log, LOG_IO_IN, "", + log_io(jcon->log, LOG_IO_IN, NULL, "", jcon->buffer + jcon->used, jcon->len_read); /* Resize larger if we're full. */ @@ -903,7 +903,7 @@ static struct io_plan *jcon_connected(struct io_conn *conn, list_head_init(&jcon->commands); /* We want to log on destruction, so we free this in destructor. */ - jcon->log = new_log(ld->log_book, ld->log_book, "%sjcon fd %i:", + jcon->log = new_log(ld->log_book, ld->log_book, NULL, "%sjcon fd %i:", log_prefix(ld->log), io_conn_fd(conn)); tal_add_destructor(jcon, destroy_jcon); @@ -1011,7 +1011,7 @@ void jsonrpc_setup(struct lightningd *ld) ld->jsonrpc = tal(ld, struct jsonrpc); strmap_init(&ld->jsonrpc->usagemap); ld->jsonrpc->commands = tal_arr(ld->jsonrpc, struct json_command *, 0); - ld->jsonrpc->log = new_log(ld->jsonrpc, ld->log_book, "jsonrpc"); + ld->jsonrpc->log = new_log(ld->jsonrpc, ld->log_book, NULL, "jsonrpc"); for (size_t i=0; ijsonrpc, commands[i])) fatal("Cannot add duplicate command %s", diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index 06a67194ebec..82b04c010cb3 100644 --- a/lightningd/lightningd.c +++ b/lightningd/lightningd.c @@ -169,7 +169,8 @@ static struct lightningd *new_lightningd(const tal_t *ctx) /*~ Note the tal context arg (by convention, the first argument to any * allocation function): ld->log will be implicitly freed when ld * is. */ - ld->log = new_log(ld, ld->log_book, "lightningd(%u):", (int)getpid()); + ld->log = new_log(ld, ld->log_book, NULL, + "lightningd(%u):", (int)getpid()); ld->logfile = NULL; /*~ We explicitly set these to NULL: if they're still NULL after option diff --git a/lightningd/log.c b/lightningd/log.c index 618cf15df43d..a5114f90393f 100644 --- a/lightningd/log.c +++ b/lightningd/log.c @@ -52,6 +52,7 @@ static const char *level_prefix(enum log_level level) static void log_to_file(const char *prefix, enum log_level level, + const struct node_id *node_id, bool continued, const struct timeabs *time, const char *str, @@ -67,11 +68,24 @@ static void log_to_file(const char *prefix, if (level == LOG_IO_IN || level == LOG_IO_OUT) { const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]"; char *hex = tal_hexstr(NULL, io, io_len); - fprintf(logf, "%s %s%s%s %s\n", - iso8601_s, prefix, str, dir, hex); + if (!node_id) + fprintf(logf, "%s %s%s%s %s\n", + iso8601_s, prefix, str, dir, hex); + else + fprintf(logf, "%s %s-%s%s%s %s\n", + iso8601_s, + node_id_to_hexstr(tmpctx, node_id), + prefix, str, dir, hex); tal_free(hex); } else if (!continued) { - fprintf(logf, "%s %s %s %s\n", iso8601_s, level_prefix(level), prefix, str); + if (!node_id) + fprintf(logf, "%s %s %s %s\n", + iso8601_s, level_prefix(level), prefix, str); + else + fprintf(logf, "%s %s %s-%s %s\n", + iso8601_s, level_prefix(level), + node_id_to_hexstr(tmpctx, node_id), + prefix, str); } else { fprintf(logf, "%s %s \t%s\n", iso8601_s, prefix, str); } @@ -80,13 +94,14 @@ static void log_to_file(const char *prefix, static void log_to_stdout(const char *prefix, enum log_level level, + const struct node_id *node_id, bool continued, const struct timeabs *time, const char *str, const u8 *io, size_t io_len, void *unused UNUSED) { - log_to_file(prefix, level, continued, time, str, io, io_len, stdout); + log_to_file(prefix, level, node_id, continued, time, str, io, io_len, stdout); } static size_t mem_used(const struct log_entry *e) @@ -141,7 +156,9 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem, /* With different entry points */ struct log * -new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...) +new_log(const tal_t *ctx, struct log_book *record, + const struct node_id *default_node_id, + const char *fmt, ...) { struct log *log = tal(ctx, struct log); va_list ap; @@ -152,6 +169,11 @@ new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...) /* FIXME: Refcount this! */ log->prefix = notleak(tal_vfmt(log->lr, fmt, ap)); va_end(ap); + if (default_node_id) + log->default_node_id = tal_dup(log, struct node_id, + default_node_id); + else + log->default_node_id = NULL; return log; } @@ -180,6 +202,7 @@ void set_log_prefix(struct log *log, const char *prefix) void set_log_outfn_(struct log_book *lr, void (*print)(const char *prefix, enum log_level level, + const struct node_id *node, bool continued, const struct timeabs *time, const char *str, @@ -224,7 +247,8 @@ static void add_entry(struct log *log, struct log_entry *l) } } -static struct log_entry *new_log_entry(struct log *log, enum log_level level) +static struct log_entry *new_log_entry(struct log *log, enum log_level level, + const struct node_id *node_id) { struct log_entry *l = tal(log->lr, struct log_entry); @@ -233,6 +257,12 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level) l->skipped = 0; l->prefix = log->prefix; l->io = NULL; + if (!node_id) + node_id = log->default_node_id; + if (node_id) + l->node_id = tal_dup(l, struct node_id, node_id); + else + l->node_id = NULL; return l; } @@ -241,16 +271,18 @@ static void maybe_print(const struct log *log, const struct log_entry *l, size_t offset) { if (l->level >= log->lr->print_level) - log->lr->print(log->prefix, l->level, offset != 0, + log->lr->print(log->prefix, l->level, l->node_id, offset != 0, &l->time, l->log + offset, l->io, tal_bytelen(l->io), log->lr->print_arg); } -void logv(struct log *log, enum log_level level, bool call_notifier, - const char *fmt, va_list ap) +void logv(struct log *log, enum log_level level, + const struct node_id *node_id, + bool call_notifier, + const char *fmt, va_list ap) { int save_errno = errno; - struct log_entry *l = new_log_entry(log, level); + struct log_entry *l = new_log_entry(log, level, node_id); l->log = tal_vfmt(l, fmt, ap); @@ -272,17 +304,18 @@ void logv(struct log *log, enum log_level level, bool call_notifier, } void log_io(struct log *log, enum log_level dir, + const struct node_id *node_id, const char *str TAKES, const void *data TAKES, size_t len) { int save_errno = errno; - struct log_entry *l = new_log_entry(log, dir); + struct log_entry *l = new_log_entry(log, dir, node_id); assert(dir == LOG_IO_IN || dir == LOG_IO_OUT); /* Print first, in case we need to truncate. */ if (l->level >= log->lr->print_level) - log->lr->print(log->prefix, l->level, false, + log->lr->print(log->prefix, l->level, l->node_id, false, &l->time, str, data, len, log->lr->print_arg); @@ -320,13 +353,15 @@ void logv_add(struct log *log, const char *fmt, va_list ap) maybe_print(log, l, oldlen); } -void log_(struct log *log, enum log_level level, bool call_notifier, - const char *fmt, ...) +void log_(struct log *log, enum log_level level, + const struct node_id *node_id, + bool call_notifier, + const char *fmt, ...) { va_list ap; va_start(ap, fmt); - logv(log, level, call_notifier, fmt, ap); + logv(log, level, node_id, call_notifier, fmt, ap); va_end(ap); } @@ -343,6 +378,7 @@ void log_each_line_(const struct log_book *lr, void (*func)(unsigned int skipped, struct timerel time, enum log_level level, + const struct node_id *node_id, const char *prefix, const char *log, const u8 *io, @@ -353,7 +389,7 @@ void log_each_line_(const struct log_book *lr, list_for_each(&lr->log, i, list) { func(i->skipped, time_between(i->time, lr->init_time), - i->level, i->prefix, i->log, i->io, arg); + i->level, i->node_id, i->prefix, i->log, i->io, arg); } } @@ -365,6 +401,7 @@ struct log_data { static void log_one_line(unsigned int skipped, struct timerel diff, enum log_level level, + const struct node_id *node_id, const char *prefix, const char *log, const u8 *io, @@ -561,7 +598,7 @@ void log_backtrace_print(const char *fmt, ...) return; va_start(ap, fmt); - logv(crashlog, LOG_BROKEN, false, fmt, ap); + logv(crashlog, LOG_BROKEN, NULL, false, fmt, ap); va_end(ap); } @@ -634,7 +671,7 @@ void fatal(const char *fmt, ...) exit(1); va_start(ap, fmt); - logv(crashlog, LOG_BROKEN, true, fmt, ap); + logv(crashlog, LOG_BROKEN, NULL, true, fmt, ap); va_end(ap); abort(); } @@ -659,6 +696,7 @@ static void add_skipped(struct log_info *info) static void log_to_json(unsigned int skipped, struct timerel diff, enum log_level level, + const struct node_id *node_id, const char *prefix, const char *log, const u8 *io, @@ -683,6 +721,8 @@ static void log_to_json(unsigned int skipped, : level == LOG_IO_OUT ? "IO_OUT" : "UNKNOWN"); json_add_time(info->response, "time", diff.ts); + if (node_id) + json_add_node_id(info->response, "node_id", node_id); json_add_string(info->response, "source", prefix); json_add_string(info->response, "log", log); if (io) diff --git a/lightningd/log.h b/lightningd/log.h index 8b501d8dfa14..2ae418e160fc 100644 --- a/lightningd/log.h +++ b/lightningd/log.h @@ -13,6 +13,7 @@ struct command; struct json_stream; struct lightningd; +struct node_id; struct timerel; struct log_entry { @@ -20,6 +21,7 @@ struct log_entry { struct timeabs time; enum log_level level; unsigned int skipped; + struct node_id *node_id; const char *prefix; char *log; /* Iff LOG_IO */ @@ -31,6 +33,7 @@ struct log_book { size_t max_mem; void (*print)(const char *prefix, enum log_level level, + const struct node_id *node_id, bool continued, const struct timeabs *time, const char *str, @@ -50,6 +53,7 @@ struct log_book { struct log { struct log_book *lr; + const struct node_id *default_node_id; const char *prefix; }; @@ -59,20 +63,33 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem, enum log_level printlevel); /* With different entry points */ -struct log *new_log(const tal_t *ctx, struct log_book *record, const char *fmt, ...) PRINTF_FMT(3,4); - -#define log_debug(log, ...) log_((log), LOG_DBG, false, __VA_ARGS__) -#define log_info(log, ...) log_((log), LOG_INFORM, false, __VA_ARGS__) -#define log_unusual(log, ...) log_((log), LOG_UNUSUAL, true, __VA_ARGS__) -#define log_broken(log, ...) log_((log), LOG_BROKEN, true, __VA_ARGS__) - -void log_io(struct log *log, enum log_level dir, const char *comment, +struct log *new_log(const tal_t *ctx, struct log_book *record, + const struct node_id *default_node_id, + const char *fmt, ...) PRINTF_FMT(4,5); + +#define log_debug(log, ...) log_((log), LOG_DBG, NULL, false, __VA_ARGS__) +#define log_info(log, ...) log_((log), LOG_INFORM, NULL, false, __VA_ARGS__) +#define log_unusual(log, ...) log_((log), LOG_UNUSUAL, NULL, true, __VA_ARGS__) +#define log_broken(log, ...) log_((log), LOG_BROKEN, NULL, true, __VA_ARGS__) + +#define log_peer_debug(log, nodeid, ...) log_((log), LOG_DBG, nodeid, false, __VA_ARGS__) +#define log_peer_info(log, nodeid, ...) log_((log), LOG_INFORM, nodeid, false, __VA_ARGS__) +#define log_peer_unusual(log, nodeid, ...) log_((log), LOG_UNUSUAL, nodeid, true, __VA_ARGS__) +#define log_peer_broken(log, nodeid, ...) log_((log), LOG_BROKEN, nodeid, true, __VA_ARGS__) + +void log_io(struct log *log, enum log_level dir, + const struct node_id *node_id, + const char *comment, const void *data, size_t len); -void log_(struct log *log, enum log_level level, bool call_notifier, const char *fmt, ...) - PRINTF_FMT(4,5); +void log_(struct log *log, enum log_level level, + const struct node_id *node_id, + bool call_notifier, + const char *fmt, ...) + PRINTF_FMT(5,6); void log_add(struct log *log, const char *fmt, ...) PRINTF_FMT(2,3); -void logv(struct log *log, enum log_level level, bool call_notifier, const char *fmt, va_list ap); +void logv(struct log *log, enum log_level level, const struct node_id *node_id, + bool call_notifier, const char *fmt, va_list ap); void logv_add(struct log *log, const char *fmt, va_list ap); enum log_level get_log_level(struct log_book *lr); @@ -86,6 +103,7 @@ struct log_book *get_log_book(const struct log *log); typesafe_cb_preargs(void, void *, (print), (arg),\ const char *, \ enum log_level, \ + const struct node_id *, \ bool, \ const struct timeabs *, \ const char *, \ @@ -95,6 +113,7 @@ struct log_book *get_log_book(const struct log *log); void set_log_outfn_(struct log_book *lr, void (*print)(const char *prefix, enum log_level level, + const struct node_id *node_id, bool continued, const struct timeabs *time, const char *str, @@ -112,6 +131,7 @@ const struct timeabs *log_init_time(const struct log_book *lr); unsigned int, \ struct timerel, \ enum log_level, \ + const struct node_id *, \ const char *, \ const char *, \ const u8 *), (arg)) @@ -120,6 +140,7 @@ void log_each_line_(const struct log_book *lr, void (*func)(unsigned int skipped, struct timerel time, enum log_level level, + const struct node_id *node_id, const char *prefix, const char *log, const u8 *io, diff --git a/lightningd/log_status.c b/lightningd/log_status.c index 2af7d46f65b8..fca390421dc8 100644 --- a/lightningd/log_status.c +++ b/lightningd/log_status.c @@ -1,7 +1,9 @@ #include #include -bool log_status_msg(struct log *log, const u8 *msg) +bool log_status_msg(struct log *log, + const struct node_id *node_id, + const u8 *msg) { char *entry, *who; u8 *data; @@ -12,12 +14,12 @@ bool log_status_msg(struct log *log, const u8 *msg) if (level != LOG_IO_IN && level != LOG_IO_OUT) { call_notifier = (level == LOG_BROKEN || level == LOG_UNUSUAL)? true : false; - log_(log, level, call_notifier, "%s", entry); + log_(log, level, node_id, call_notifier, "%s", entry); return true; } } else if (fromwire_status_io(msg, msg, &level, &who, &data)) { if (level == LOG_IO_IN || level == LOG_IO_OUT) { - log_io(log, level, who, data, tal_count(data)); + log_io(log, level, node_id, who, data, tal_count(data)); return true; } } diff --git a/lightningd/log_status.h b/lightningd/log_status.h index fc8dd824a203..9a5b70d65a1c 100644 --- a/lightningd/log_status.h +++ b/lightningd/log_status.h @@ -5,6 +5,8 @@ #include /* Returns true (and writes it to log) if it's a status_log message. */ -bool log_status_msg(struct log *log, const u8 *msg); +bool log_status_msg(struct log *log, + const struct node_id *node_id, + const u8 *msg); #endif /* LIGHTNING_LIGHTNINGD_LOG_STATUS_H */ diff --git a/lightningd/opening_control.c b/lightningd/opening_control.c index ec3548ea38ee..bc3000dac75c 100644 --- a/lightningd/opening_control.c +++ b/lightningd/opening_control.c @@ -621,7 +621,6 @@ new_uncommitted_channel(struct peer *peer) { struct lightningd *ld = peer->ld; struct uncommitted_channel *uc = tal(ld, struct uncommitted_channel); - const char *idname; uc->peer = peer; assert(!peer->uncommitted_channel); @@ -629,10 +628,8 @@ new_uncommitted_channel(struct peer *peer) uc->transient_billboard = NULL; uc->dbid = wallet_get_channel_dbid(ld->wallet); - idname = type_to_string(uc, struct node_id, &uc->peer->id); - uc->log = new_log(uc, uc->peer->log_book, "%s chan #%"PRIu64":", - idname, uc->dbid); - tal_free(idname); + uc->log = new_log(uc, uc->peer->log_book, &uc->peer->id, + "chan #%"PRIu64":", uc->dbid); uc->fc = NULL; uc->our_config.id = 0; diff --git a/lightningd/peer_control.c b/lightningd/peer_control.c index 03bee4cef6c1..af841df5b725 100644 --- a/lightningd/peer_control.c +++ b/lightningd/peer_control.c @@ -75,6 +75,7 @@ static void destroy_peer(struct peer *peer) /* We copy per-peer entries above --log-level into the main log. */ static void copy_to_parent_log(const char *prefix, enum log_level level, + const struct node_id *node_id, bool continued, const struct timeabs *time UNUSED, const char *str, @@ -82,11 +83,11 @@ static void copy_to_parent_log(const char *prefix, struct log *parent_log) { if (level == LOG_IO_IN || level == LOG_IO_OUT) - log_io(parent_log, level, prefix, io, io_len); + log_io(parent_log, level, node_id, prefix, io, io_len); else if (continued) log_add(parent_log, "%s ... %s", prefix, str); else - log_(parent_log, level, false, "%s %s", prefix, str); + log_(parent_log, level, node_id, false, "%s %s", prefix, str); } static void peer_update_features(struct peer *peer, const u8 *features TAKES) diff --git a/lightningd/plugin.c b/lightningd/plugin.c index 3db32f744ab8..55fc5f538f17 100644 --- a/lightningd/plugin.c +++ b/lightningd/plugin.c @@ -37,7 +37,7 @@ struct plugins *plugins_new(const tal_t *ctx, struct log_book *log_book, p = tal(ctx, struct plugins); list_head_init(&p->plugins); p->log_book = log_book; - p->log = new_log(p, log_book, "plugin-manager"); + p->log = new_log(p, log_book, NULL, "plugin-manager"); p->ld = ld; p->startup = true; uintmap_init(&p->pending_requests); @@ -91,7 +91,7 @@ struct plugin *plugin_register(struct plugins *plugins, const char* path TAKES) p->used = 0; p->subscriptions = NULL; - p->log = new_log(p, plugins->log_book, "plugin-%s", + p->log = new_log(p, plugins->log_book, NULL, "plugin-%s", path_basename(tmpctx, p->cmd)); p->methods = tal_arr(p, const char *, 0); list_head_init(&p->plugin_opts); @@ -194,7 +194,8 @@ static void plugin_log_handle(struct plugin *plugin, const jsmntok_t *paramstok) } call_notifier = (level == LOG_BROKEN || level == LOG_UNUSUAL)? true : false; - log_(plugin->log, level, call_notifier, "%.*s", msgtok->end - msgtok->start, + /* FIXME: Let plugin specify node_id? */ + log_(plugin->log, level, NULL, call_notifier, "%.*s", msgtok->end - msgtok->start, plugin->buffer + msgtok->start); } @@ -357,7 +358,7 @@ static struct io_plan *plugin_read_json(struct io_conn *conn UNUSED, { bool success; - log_io(plugin->log, LOG_IO_IN, "", + log_io(plugin->log, LOG_IO_IN, NULL, "", plugin->buffer + plugin->used, plugin->len_read); plugin->used += plugin->len_read; diff --git a/lightningd/subd.c b/lightningd/subd.c index e23510814bd7..2a2fe08a368b 100644 --- a/lightningd/subd.c +++ b/lightningd/subd.c @@ -432,7 +432,7 @@ static struct io_plan *sd_msg_read(struct io_conn *conn, struct subd *sd) switch ((enum status)type) { case WIRE_STATUS_LOG: case WIRE_STATUS_IO: - if (!log_status_msg(sd->log, sd->msg_in)) + if (!log_status_msg(sd->log, sd->node_id, sd->msg_in)) goto malformed; goto next; case WIRE_STATUS_FAIL: @@ -639,10 +639,11 @@ static struct subd *new_subd(struct lightningd *ld, } sd->ld = ld; if (base_log) { - sd->log = new_log(sd, get_log_book(base_log), "%s-%s", name, - log_prefix(base_log)); + sd->log = new_log(sd, get_log_book(base_log), node_id, + "%s-%s", name, log_prefix(base_log)); } else { - sd->log = new_log(sd, ld->log_book, "%s(%u):", name, sd->pid); + sd->log = new_log(sd, ld->log_book, node_id, + "%s(%u):", name, sd->pid); } sd->name = name; @@ -668,7 +669,7 @@ static struct subd *new_subd(struct lightningd *ld, sd->conn = io_new_conn(ld, msg_fd, msg_setup, sd); tal_steal(sd->conn, sd); - log_debug(sd->log, "pid %u, msgfd %i", sd->pid, msg_fd); + log_peer_debug(sd->log, node_id, "pid %u, msgfd %i", sd->pid, msg_fd); /* Clear any old transient message. */ if (billboardcb) diff --git a/lightningd/test/run-find_my_abspath.c b/lightningd/test/run-find_my_abspath.c index 801c9077246b..c28ff44dac14 100644 --- a/lightningd/test/run-find_my_abspath.c +++ b/lightningd/test/run-find_my_abspath.c @@ -112,7 +112,10 @@ void jsonrpc_setup(struct lightningd *ld UNNEEDED) struct htlc_in_map *load_channels_from_wallet(struct lightningd *ld UNNEEDED) { fprintf(stderr, "load_channels_from_wallet called!\n"); abort(); } /* Generated stub for log_ */ -void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, bool call_notifier UNNEEDED, const char *fmt UNNEEDED, ...) +void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, + const struct node_id *node_id UNNEEDED, + bool call_notifier UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "log_ called!\n"); abort(); } /* Generated stub for log_backtrace_exit */ @@ -125,10 +128,14 @@ void log_backtrace_print(const char *fmt UNNEEDED, ...) const char *log_prefix(const struct log *log UNNEEDED) { fprintf(stderr, "log_prefix called!\n"); abort(); } /* Generated stub for log_status_msg */ -bool log_status_msg(struct log *log UNNEEDED, const u8 *msg UNNEEDED) +bool log_status_msg(struct log *log UNNEEDED, + const struct node_id *node_id UNNEEDED, + const u8 *msg UNNEEDED) { fprintf(stderr, "log_status_msg called!\n"); abort(); } /* Generated stub for new_log */ -struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, const char *fmt UNNEEDED, ...) +struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, + const struct node_id *default_node_id UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "new_log called!\n"); abort(); } /* Generated stub for new_log_book */ struct log_book *new_log_book(struct lightningd *ld UNNEEDED, size_t max_mem UNNEEDED, diff --git a/lightningd/test/run-invoice-select-inchan.c b/lightningd/test/run-invoice-select-inchan.c index bf67b32309c6..6cbe59b0589b 100644 --- a/lightningd/test/run-invoice-select-inchan.c +++ b/lightningd/test/run-invoice-select-inchan.c @@ -261,14 +261,19 @@ void kill_uncommitted_channel(struct uncommitted_channel *uc UNNEEDED, const char *why UNNEEDED) { fprintf(stderr, "kill_uncommitted_channel called!\n"); abort(); } /* Generated stub for log_ */ -void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, bool call_notifier UNNEEDED, const char *fmt UNNEEDED, ...) +void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, + const struct node_id *node_id UNNEEDED, + bool call_notifier UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "log_ called!\n"); abort(); } /* Generated stub for log_add */ void log_add(struct log *log UNNEEDED, const char *fmt UNNEEDED, ...) { fprintf(stderr, "log_add called!\n"); abort(); } /* Generated stub for log_io */ -void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, const char *comment UNNEEDED, +void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, + const struct node_id *node_id UNNEEDED, + const char *comment UNNEEDED, const void *data UNNEEDED, size_t len UNNEEDED) { fprintf(stderr, "log_io called!\n"); abort(); } /* Generated stub for new_bolt11 */ @@ -276,7 +281,9 @@ struct bolt11 *new_bolt11(const tal_t *ctx UNNEEDED, const struct amount_msat *msat TAKES UNNEEDED) { fprintf(stderr, "new_bolt11 called!\n"); abort(); } /* Generated stub for new_log */ -struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, const char *fmt UNNEEDED, ...) +struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, + const struct node_id *default_node_id UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "new_log called!\n"); abort(); } /* Generated stub for new_log_book */ struct log_book *new_log_book(struct lightningd *ld UNNEEDED, size_t max_mem UNNEEDED, @@ -428,6 +435,7 @@ void plugin_hook_call_(struct lightningd *ld UNNEEDED, const struct plugin_hook void set_log_outfn_(struct log_book *lr UNNEEDED, void (*print)(const char *prefix UNNEEDED, enum log_level level UNNEEDED, + const struct node_id *node_id UNNEEDED, bool continued UNNEEDED, const struct timeabs *time UNNEEDED, const char *str UNNEEDED, diff --git a/lightningd/test/run-jsonrpc.c b/lightningd/test/run-jsonrpc.c index b6874186b6a0..190669826c8b 100644 --- a/lightningd/test/run-jsonrpc.c +++ b/lightningd/test/run-jsonrpc.c @@ -43,11 +43,16 @@ bool json_to_txid(const char *buffer UNNEEDED, const jsmntok_t *tok UNNEEDED, struct bitcoin_txid *txid UNNEEDED) { fprintf(stderr, "json_to_txid called!\n"); abort(); } /* Generated stub for log_ */ -void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, bool call_notifier UNNEEDED, const char *fmt UNNEEDED, ...) +void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED, + const struct node_id *node_id UNNEEDED, + bool call_notifier UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "log_ called!\n"); abort(); } /* Generated stub for log_io */ -void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, const char *comment UNNEEDED, +void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, + const struct node_id *node_id UNNEEDED, + const char *comment UNNEEDED, const void *data UNNEEDED, size_t len UNNEEDED) { fprintf(stderr, "log_io called!\n"); abort(); } /* Generated stub for log_prefix */ @@ -57,7 +62,9 @@ const char *log_prefix(const struct log *log UNNEEDED) void memleak_remove_strmap_(struct htable *memtable UNNEEDED, const struct strmap *m UNNEEDED) { fprintf(stderr, "memleak_remove_strmap_ called!\n"); abort(); } /* Generated stub for new_log */ -struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, const char *fmt UNNEEDED, ...) +struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, + const struct node_id *default_node_id UNNEEDED, + const char *fmt UNNEEDED, ...) { fprintf(stderr, "new_log called!\n"); abort(); } /* Generated stub for new_reltimer_ */ struct oneshot *new_reltimer_(struct timers *timers UNNEEDED, diff --git a/tests/test_closing.py b/tests/test_closing.py index 695dda063588..fef5abf09b2f 100644 --- a/tests/test_closing.py +++ b/tests/test_closing.py @@ -1459,7 +1459,7 @@ def test_permfail_htlc_out(node_factory, bitcoind, executor): l2 = node_factory.get_node(disconnect=disconnects, feerates=(7500, 7500, 7500)) l1.rpc.connect(l2.info['id'], 'localhost', l2.port) - l2.daemon.wait_for_log('openingd-{} chan #1: Handed peer, entering loop'.format(l1.info['id'])) + l2.daemon.wait_for_log('openingd-chan #1: Handed peer, entering loop'.format(l1.info['id'])) l2.fund_channel(l1, 10**6) # This will fail at l2's end. diff --git a/tests/test_connection.py b/tests/test_connection.py index 6fdcb173e7c6..6c4833830258 100644 --- a/tests/test_connection.py +++ b/tests/test_connection.py @@ -373,7 +373,7 @@ def test_reconnect_openingd(node_factory): l1.bitcoin.generate_block(3) # Just to be sure, second openingd hand over to channeld. This log line is about channeld being started - l2.daemon.wait_for_log(r'lightning_channeld-[0-9a-f]{66} chan #[0-9]: pid [0-9]+, msgfd [0-9]+') + l2.daemon.wait_for_log(r'lightning_channeld-chan #[0-9]: pid [0-9]+, msgfd [0-9]+') @unittest.skipIf(not DEVELOPER, "needs DEVELOPER=1") diff --git a/tests/test_gossip.py b/tests/test_gossip.py index b3008efc8280..6eeac5e96a36 100644 --- a/tests/test_gossip.py +++ b/tests/test_gossip.py @@ -357,7 +357,7 @@ def test_gossip_weirdalias(node_factory, bitcoind): .format(normal_name)) l1.rpc.connect(l2.info['id'], 'localhost', l2.port) - l2.daemon.wait_for_log('openingd-{} chan #1: Handed peer, entering loop'.format(l1.info['id'])) + l2.daemon.wait_for_log('openingd-chan #1: Handed peer, entering loop') l2.fund_channel(l1, 10**6) bitcoind.generate_block(6) @@ -486,8 +486,8 @@ def test_gossip_no_empty_announcements(node_factory, bitcoind): # Turn on IO logging for openingd (make sure it's ready!) l1.daemon.wait_for_log('openingd-.*: Handed peer, entering loop') subprocess.run(['kill', '-USR1', l1.subd_pid('openingd')]) - l2.daemon.wait_for_log('openingd-{}.*: Handed peer, entering loop'.format(l3.info['id'])) - subprocess.run(['kill', '-USR1', l2.subd_pid('openingd-{}'.format(l3.info['id']))]) + l2.daemon.wait_for_log(r'{}-.*lightning_openingd-chan #.: Handed peer, entering loop'.format(l3.info['id'])) + subprocess.run(['kill', '-USR1', l2.subd_pid('openingd', l3.info['id'])]) # Make an announced-but-not-updated channel. l3.fund_channel(l4, 10**5) diff --git a/tests/test_misc.py b/tests/test_misc.py index b5a3b42f006b..eddd1a0c6749 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -1205,7 +1205,7 @@ def test_htlc_send_timeout(node_factory, bitcoind): timedout = False while not timedout: try: - l2.daemon.wait_for_log(r'channeld-{} chan #[0-9]*:\[IN\] '.format(l3.info['id']), timeout=30) + l2.daemon.wait_for_log(r'channeld-chan #[0-9]*:\[IN\] ', timeout=30) except TimeoutError: timedout = True @@ -1231,7 +1231,7 @@ def test_htlc_send_timeout(node_factory, bitcoind): assert not l2.daemon.is_in_log(r'channeld.*:\[IN\] 0013') assert not l2.daemon.is_in_log(r'channeld.*:\[OUT\] 0084') # L2 killed the channel with l3 because it was too slow. - l2.daemon.wait_for_log('channeld-{}.*Adding HTLC too slow: killing connection'.format(l3.info['id'])) + l2.daemon.wait_for_log('{}-.*lightning_channeld-.*Adding HTLC too slow: killing connection'.format(l3.info['id'])) def test_ipv4_and_ipv6(node_factory): diff --git a/tests/test_plugin.py b/tests/test_plugin.py index 5929c578ecdd..e92f1fbc9901 100644 --- a/tests/test_plugin.py +++ b/tests/test_plugin.py @@ -263,8 +263,7 @@ def test_plugin_connected_hook(node_factory): l1.daemon.wait_for_log(r"{} is in reject list".format(l3.info['id'])) # FIXME: this error occurs *after* connection, so we connect then drop. - l3.daemon.wait_for_log(r"lightning_openingd-{} chan #1: peer_in WIRE_ERROR" - .format(l1.info['id'])) + l3.daemon.wait_for_log(r"lightning_openingd-chan #1: peer_in WIRE_ERROR") l3.daemon.wait_for_log(r"You are in reject list") def check_disconnect(): diff --git a/wallet/test/run-db.c b/wallet/test/run-db.c index e2ff7a864df7..7c06b0a82e8a 100644 --- a/wallet/test/run-db.c +++ b/wallet/test/run-db.c @@ -3,7 +3,7 @@ static void db_test_fatal(const char *fmt, ...); #define db_fatal db_test_fatal -static void db_log_(struct log *log UNUSED, enum log_level level UNUSED, bool call_notifier UNUSED, const char *fmt UNUSED, ...) +static void db_log_(struct log *log UNUSED, enum log_level level UNUSED, const struct node_id *node_id UNUSED, bool call_notifier UNUSED, const char *fmt UNUSED, ...) { } #define log_ db_log_ diff --git a/wallet/test/run-wallet.c b/wallet/test/run-wallet.c index 9ac47d7d7b97..b08e2a676eeb 100644 --- a/wallet/test/run-wallet.c +++ b/wallet/test/run-wallet.c @@ -4,7 +4,7 @@ static void wallet_test_fatal(const char *fmt, ...); #define db_fatal wallet_test_fatal #include "test_utils.h" -static void db_log_(struct log *log UNUSED, enum log_level level UNUSED, bool call_notifier UNUSED, const char *fmt UNUSED, ...) +static void db_log_(struct log *log UNUSED, enum log_level level UNUSED, const struct node_id *node_id UNUSED, bool call_notifier UNUSED, const char *fmt UNUSED, ...) { } #define log_ db_log_ @@ -376,7 +376,9 @@ void kill_uncommitted_channel(struct uncommitted_channel *uc UNNEEDED, void log_add(struct log *log UNNEEDED, const char *fmt UNNEEDED, ...) { fprintf(stderr, "log_add called!\n"); abort(); } /* Generated stub for log_io */ -void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, const char *comment UNNEEDED, +void log_io(struct log *log UNNEEDED, enum log_level dir UNNEEDED, + const struct node_id *node_id UNNEEDED, + const char *comment UNNEEDED, const void *data UNNEEDED, size_t len UNNEEDED) { fprintf(stderr, "log_io called!\n"); abort(); } /* Generated stub for notify_connect */ @@ -703,7 +705,7 @@ enum log_level get_log_level(struct log_book *lr UNNEEDED) return LOG_DBG; } -struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, const char *fmt UNNEEDED, ...) +struct log *new_log(const tal_t *ctx UNNEEDED, struct log_book *record UNNEEDED, const struct node_id *default_node_id UNNEEDED, const char *fmt UNNEEDED, ...) { return NULL; } @@ -717,6 +719,7 @@ struct log_book *new_log_book(struct lightningd *ld UNNEEDED, size_t max_mem UNN void set_log_outfn_(struct log_book *lr UNNEEDED, void (*print)(const char *prefix UNNEEDED, enum log_level level UNNEEDED, + const struct node_id *node_id UNNEEDED, bool continued UNNEEDED, const struct timeabs *time UNNEEDED, const char *str UNNEEDED,