Log filtering by node id.

common/test/run-bolt12_decode.c

@@ -8,8 +8,6 @@
 #include <ccan/tal/path/path.h>
 #include <common/setup.h>
 
-bool deprecated_apis = false;
-
 /* AUTOGENERATED MOCKS START */
 /* Generated stub for amount_asset_is_main */
 bool amount_asset_is_main(struct amount_asset *asset UNNEEDED)

common/test/run-bolt12_merkle.c

@@ -13,8 +13,6 @@
 /* Definition of n1 from the spec */
 #include <wire/peer_wire.h>
 
-bool deprecated_apis = false;
-
 /* AUTOGENERATED MOCKS START */
 /* Generated stub for features_unsupported */
 int features_unsupported(const struct feature_set *our_features UNNEEDED,

common/test/run-bolt12_period.c

@@ -6,8 +6,6 @@
 #include <ccan/tal/path/path.h>
 #include <common/setup.h>
 
-bool deprecated_apis = false;
-
 /* AUTOGENERATED MOCKS START */
 /* Generated stub for amount_asset_is_main */
 bool amount_asset_is_main(struct amount_asset *asset UNNEEDED)

connectd/test/run-gossip_rcvd_filter.c

@@ -37,9 +37,6 @@ struct amount_asset amount_sat_to_asset(struct amount_sat *sat UNNEEDED, const u
 /* Generated stub for amount_tx_fee */
 struct amount_sat amount_tx_fee(u32 fee_per_kw UNNEEDED, size_t weight UNNEEDED)
 { fprintf(stderr, "amount_tx_fee called!\n"); abort(); }
-/* Generated stub for memleak_remove_htable */
-void memleak_remove_htable(struct htable *memtable UNNEEDED, const struct htable *ht UNNEEDED)
-{ fprintf(stderr, "memleak_remove_htable called!\n"); abort(); }
 /* Generated stub for towire */
 void towire(u8 **pptr UNNEEDED, const void *data UNNEEDED, size_t len UNNEEDED)
 { fprintf(stderr, "towire called!\n"); abort(); }

contrib/pyln-testing/pyln/testing/utils.py

@@ -581,6 +581,7 @@ def __init__(self, lightning_dir, bitcoindproxy, port=9735, random_hsm=False, no
         self.prefix = 'lightningd-%d' % (node_id)
         # Log to stdout so we see it in failure cases, and log file for TailableProc.
         self.opts['log-file'] = ['-', os.path.join(lightning_dir, "log")]
+        self.opts['log-prefix'] = self.prefix + ' '
         # In case you want specific ordering!
         self.early_opts = []
 

doc/lightningd-config.5.md

@@ -124,7 +124,7 @@ Specify pid file to write to.
  **log-level**=*LEVEL*\[:*SUBSYSTEM*\]
 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 containing that string. This option may be specified multiple times.
+for any subsystem (or *nodeid*) containing that string. This option may be specified multiple times.
 Subsystems include:
 
 * *lightningd*: The main lightning daemon
@@ -148,11 +148,14 @@ internal integer id assigned for the lifetime of the channel:
 
   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).
+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-prefix**=*PREFIX*
-Prefix for log lines: this can be customized if you want to merge logs
-with multiple daemons.
+Prefix for all log lines: this can be customized if you want to merge logs
+with multiple daemons.  Usually you want to include a space at the end of *PREFIX*,
+as the timestamp follows immediately.
 
  **log-file**=*PATH*
 Log to this file (instead of stdout).  If you specify this more than once

lightningd/channel.c

@@ -237,6 +237,7 @@ struct channel *new_unsaved_channel(struct peer *peer,
 	channel->shutdown_wrong_funding = NULL;
 	channel->closing_feerate_range = NULL;
 	channel->channel_update = NULL;
+	channel->alias[LOCAL] = channel->alias[REMOTE] = NULL;
 
 	/* Channel is connected! */
 	channel->connected = true;

lightningd/log.c

@@ -45,6 +45,8 @@ struct log_book {
 	bool print_timestamps;
 
 	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
 	 * (the log_book belongs to lightningd), a pointer to lightningd
@@ -130,7 +132,8 @@ static const char *level_prefix(enum log_level level)
 	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,
 			 const struct node_id *node_id,
 			 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]";
 		char *hex = tal_hexstr(NULL, io, io_len);
 		if (!node_id)
-			entry = tal_fmt(tmpctx, "%s%s: %s%s %s\n",
-					tstamp, prefix, str, dir, hex);
+			entry = tal_fmt(tmpctx, "%s%s%s: %s%s %s\n",
+					log_prefix, tstamp, entry_prefix, str, dir, hex);
 		else
-			entry = tal_fmt(tmpctx, "%s%s-%s: %s%s %s\n",
-					tstamp,
+			entry = tal_fmt(tmpctx, "%s%s%s-%s: %s%s %s\n",
+					log_prefix, tstamp,
 					node_id_to_hexstr(tmpctx, node_id),
-					prefix, str, dir, hex);
+					entry_prefix, str, dir, hex);
 		tal_free(hex);
 	} else {
 		if (!node_id)
-			entry = tal_fmt(tmpctx, "%s%s %s: %s\n",
-					tstamp, level_prefix(level), prefix, str);
+			entry = tal_fmt(tmpctx, "%s%s%s %s: %s\n",
+					log_prefix, tstamp, level_prefix(level), entry_prefix, str);
 		else
-			entry = tal_fmt(tmpctx, "%s%s %s-%s: %s\n",
-					tstamp, level_prefix(level),
+			entry = tal_fmt(tmpctx, "%s%s%s %s-%s: %s\n",
+					log_prefix, tstamp, level_prefix(level),
 					node_id_to_hexstr(tmpctx, node_id),
-					prefix, str);
+					entry_prefix, str);
 	}
 
 	/* 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->outfiles = 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);
 	lr->init_time = time_now();
 	lr->ld = ld;
@@ -291,13 +296,15 @@ struct log_book *new_log_book(struct lightningd *ld, size_t max_mem)
 }
 
 static enum log_level filter_level(struct log_book *lr,
-				   const struct log_prefix *lp)
+				   const struct log_prefix *lp,
+				   const struct node_id *node_id)
 {
 	struct print_filter *i;
+	const char *node_id_str = node_id ? node_id_to_hexstr(tmpctx, node_id) : "";
 
 	assert(lr->default_print_level != NULL);
 	list_for_each(&lr->print_filters, i, list) {
-		if (strstr(lp->prefix, i->prefix))
+		if (strstr(lp->prefix, i->prefix) || strstr(node_id_str, i->prefix))
 			return i->level;
 	}
 	return *lr->default_print_level;
@@ -331,14 +338,14 @@ const char *log_prefix(const struct log *log)
 	return log->prefix->prefix;
 }
 
-enum log_level log_print_level(struct log *log)
+enum log_level log_print_level(struct log *log, const struct node_id *node_id)
 {
 	if (!log->print_level) {
 		/* Not set globally yet?  Print UNUSUAL / BROKEN messages only */
 		if (!log->lr->default_print_level)
 			return LOG_UNUSUAL;
 		log->print_level = tal(log, enum log_level);
-		*log->print_level = filter_level(log->lr, log->prefix);
+		*log->print_level = filter_level(log->lr, log->prefix, node_id);
 	}
 	return *log->print_level;
 }
@@ -400,8 +407,8 @@ 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_files(log->prefix->prefix, l->level,
+	if (l->level >= log_print_level(log, l->nc ? &l->nc->node_id : NULL))
+		log_to_files(log->lr->prefix, log->prefix->prefix, l->level,
 			     l->nc ? &l->nc->node_id : NULL,
 			     &l->time, l->log,
 			     l->io, tal_bytelen(l->io),
@@ -450,8 +457,8 @@ void log_io(struct log *log, enum log_level dir,
 	assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);
 
 	/* Print first, in case we need to truncate. */
-	if (l->level >= log_print_level(log))
-		log_to_files(log->prefix->prefix, l->level,
+	if (l->level >= log_print_level(log, node_id))
+		log_to_files(log->lr->prefix, log->prefix->prefix, l->level,
 			     l->nc ? &l->nc->node_id : NULL,
 			     &l->time, str,
 			     data, len,
@@ -617,17 +624,16 @@ static void show_log_level(char buf[OPT_SHOW_LEN], const struct log *log)
 	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. */
-	log_prefix_drop(log->prefix);
-	log->prefix = log_prefix_new(log->lr, arg);
+	tal_free(log_book->prefix);
+	log_book->prefix = tal_strdup(log_book, arg);
 	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';
 }
 
@@ -740,7 +746,7 @@ void opt_register_logging(struct lightningd *ld)
 			       opt_set_bool_arg, opt_show_bool, &ld->log->lr->print_timestamps,
 			       "prefix log messages with timestamp");
 	opt_register_early_arg("--log-prefix", arg_log_prefix, show_log_prefix,
-			       ld->log,
+			       ld->log_book,
 			       "log prefix");
 	opt_register_early_arg("--log-file=<file>", arg_log_to_file, NULL, ld,
 			       "Also log to file (- for stdout)");
@@ -758,8 +764,8 @@ void logging_options_parsed(struct log_book *lr)
 	for (size_t i = 0; i < lr->num_entries; i++) {
 		const struct log_entry *l = &lr->log[i];
 
-		if (l->level >= filter_level(lr, l->prefix))
-			log_to_files(l->prefix->prefix, l->level,
+		if (l->level >= filter_level(lr, l->prefix, NULL))
+			log_to_files(lr->prefix, l->prefix->prefix, l->level,
 				     l->nc ? &l->nc->node_id : NULL,
 				     &l->time, l->log,
 				     l->io, tal_bytelen(l->io),

lightningd/log.h

@@ -44,7 +44,7 @@ void logv(struct log *log, enum log_level level, const struct node_id *node_id,
 	  bool call_notifier, const char *fmt, va_list ap);
 
 const char *log_prefix(const struct log *log);
-enum log_level log_print_level(struct log *log);
+enum log_level log_print_level(struct log *log, const struct node_id *node_id);
 
 void opt_register_logging(struct lightningd *ld);
 

lightningd/opening_control.c

@@ -570,6 +570,12 @@ static void openingd_failed(struct subd *openingd, const u8 *msg,
 {
 	char *desc;
 
+	/* Since we're detaching from uc, we'll be unreferenced until
+	 * our imminent exit (as will our parent, openingd->conn). */
+	notleak(openingd);
+	/* openingd->conn is set to NULL temporarily for this call, so: */
+	notleak(tal_parent(openingd));
+
 	if (!fromwire_openingd_failed(msg, msg, &desc)) {
 		log_broken(uc->log,
 			   "bad OPENINGD_FAILED %s",
@@ -683,8 +689,6 @@ openchannel_hook_final(struct openchannel_hook_payload *payload STEALS)
 	} else
 		upfront_shutdown_script_wallet_index = NULL;
 
-	/* In case peer goes away right now, mark openingd notleak() */
-	notleak(openingd);
 	subd_send_msg(openingd,
 		      take(towire_openingd_got_offer_reply(NULL, errmsg,
 							   our_upfront_shutdown_script,

lightningd/options.c

@@ -1556,7 +1556,7 @@ static void add_config(struct lightningd *ld,
 			strcpy(buf + OPT_SHOW_LEN - 1, "...");
 
 			if (streq(buf, "true") || streq(buf, "false")
-			    || strspn(buf, "0123456789.") == strlen(buf)) {
+			    || (!streq(buf, "") && strspn(buf, "0123456789.") == strlen(buf))) {
 				/* Let pure numbers and true/false through as
 				 * literals. */
 				json_add_literal(response, name0,

lightningd/subd.c

@@ -742,7 +742,7 @@ static struct subd *new_subd(const tal_t *ctx,
 		       &msg_fd,
 		       /* We only turn on subdaemon io logging if we're going
 			* to print it: too stressful otherwise! */
-		       log_print_level(sd->log) < LOG_DBG,
+		       log_print_level(sd->log, node_id) < LOG_DBG,
 		       ap);
 	if (sd->pid == (pid_t)-1) {
 		log_unusual(ld->log, "subd %s failed: %s",

lightningd/test/run-find_my_abspath.c

@@ -147,7 +147,7 @@ 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_print_level */
-enum log_level log_print_level(struct log *log UNNEEDED)
+enum log_level log_print_level(struct log *log UNNEEDED, const struct node_id *node_id UNNEEDED)
 { fprintf(stderr, "log_print_level called!\n"); abort(); }
 /* Generated stub for log_status_msg */
 bool log_status_msg(struct log *log UNNEEDED,

lightningd/test/run-invoice-select-inchan.c

@@ -7,8 +7,6 @@
 #include <common/setup.h>
 #include <stdio.h>
 
-bool deprecated_apis = false;
-
 /* AUTOGENERATED MOCKS START */
 /* Generated stub for any_channel_by_scid */
 struct channel *any_channel_by_scid(struct lightningd *ld UNNEEDED,
@@ -163,6 +161,8 @@ void db_commit_transaction(struct db *db UNNEEDED)
 /* Generated stub for delete_channel */
 void delete_channel(struct channel *channel STEALS UNNEEDED)
 { fprintf(stderr, "delete_channel called!\n"); abort(); }
+/* Generated stub for deprecated_apis */
+bool deprecated_apis;
 /* Generated stub for encode_scriptpubkey_to_addr */
 char *encode_scriptpubkey_to_addr(const tal_t *ctx UNNEEDED,
 				  const struct chainparams *chainparams UNNEEDED,

lightningd/test/run-jsonrpc.c

@@ -12,6 +12,8 @@ void db_begin_transaction_(struct db *db UNNEEDED, const char *location UNNEEDED
 /* Generated stub for db_commit_transaction */
 void db_commit_transaction(struct db *db UNNEEDED)
 { fprintf(stderr, "db_commit_transaction called!\n"); abort(); }
+/* Generated stub for deprecated_apis */
+bool deprecated_apis;
 /* Generated stub for fatal */
 void   fatal(const char *fmt UNNEEDED, ...)
 { fprintf(stderr, "fatal called!\n"); abort(); }
@@ -123,8 +125,6 @@ void towire_node_id(u8 **pptr UNNEEDED, const struct node_id *id UNNEEDED)
 { fprintf(stderr, "towire_node_id called!\n"); abort(); }
 /* AUTOGENERATED MOCKS END */
 
-bool deprecated_apis;
-
 static int test_json_filter(void)
 {
 	struct json_stream *result = new_json_stream(NULL, NULL, NULL);

lightningd/test/run-shuffle_fds.c

@@ -96,7 +96,7 @@ void log_(struct log *log UNNEEDED, enum log_level level UNNEEDED,
 const char *log_prefix(const struct log *log UNNEEDED)
 { fprintf(stderr, "log_prefix called!\n"); abort(); }
 /* Generated stub for log_print_level */
-enum log_level log_print_level(struct log *log UNNEEDED)
+enum log_level log_print_level(struct log *log UNNEEDED, const struct node_id *node_id UNNEEDED)
 { fprintf(stderr, "log_print_level called!\n"); abort(); }
 /* Generated stub for log_status_msg */
 bool log_status_msg(struct log *log UNNEEDED,

tests/test_closing.py

@@ -3214,11 +3214,14 @@ def test_option_upfront_shutdown_script(node_factory, bitcoind, executor):
     l1.rpc.connect(l2.info['id'], 'localhost', l2.port)
     l1.fundchannel(l2, 1000000, False)
 
-    l2.rpc.close(l1.info['id'], unilateraltimeout=5)
+    fut = executor.submit(l2.rpc.close, l1.info['id'])
 
     # l2 will send warning unilaterally when it dislikes shutdown script.
     l1.daemon.wait_for_log(r'WARNING.*scriptpubkey .* is not as agreed upfront \(00143d43d226bcc27019ade52d7a3dc52a7ac1be28b8\)')
 
+    l2.rpc.close(l1.info['id'], unilateraltimeout=1)
+    fut.result(TIMEOUT)
+
     bitcoind.generate_block(1, wait_for_mempool=1)
     wait_for(lambda: [c['state'] for c in only_one(l1.rpc.listpeers()['peers'])['channels']] == ['ONCHAIN', 'ONCHAIN'])
     wait_for(lambda: [c['state'] for c in only_one(l2.rpc.listpeers()['peers'])['channels']] == ['ONCHAIN', 'ONCHAIN'])