common: don't send trace messages by default, don't ratelimit at all.

We ratelimited DEBUG messages, but that can be annoying and cause us to miss things.
We demoted the worst offenders in the last release, to TRACE level.

Now, only log trace if it's wanted, and never suppress DEBUG.

Changelog-Changed: Logging: we no longer suppress DEBUG messages from subdaemons.
Signed-off-by: Rusty Russell <[email protected]>
Fixes: #7917

Author: rustyrussell

common/status.c

@@ -15,12 +15,9 @@
 static int status_fd = -1;
 static struct daemon_conn *status_conn;
 volatile bool logging_io = false;
+bool logging_trace = false;
 static bool was_logging_io;
 
-/* If we're more than this many msgs deep, don't add debug messages. */
-#define TRACE_QUEUE_LIMIT 20
-static size_t traces_suppressed;
-
 static void got_sigusr1(int signal UNUSED)
 {
 	logging_io = !logging_io;
@@ -149,22 +146,10 @@ void status_vfmt(enum log_level level,
 {
 	char *str;
 
-	/* We only suppress async debug msgs.  IO messages are even spammier
-	 * but they only occur when explicitly asked for */
-	if ((level == LOG_DBG || level == LOG_TRACE) && status_conn) {
-		size_t qlen = daemon_conn_queue_length(status_conn);
-
-		/* Once suppressing, we keep suppressing until we're empty */
-		if (traces_suppressed && qlen == 0) {
-			size_t n = traces_suppressed;
-			traces_suppressed = 0;
-			/* Careful: recursion! */
-			status_trace("...[%zu debug/trace messages suppressed]...", n);
-		} else if (traces_suppressed || qlen > TRACE_QUEUE_LIMIT) {
-			traces_suppressed++;
-			return;
-		}
-	}
+	/* These are spammy, so only log if requested (or IO logging)*/
+	if (level == LOG_TRACE && (!logging_trace && !logging_io))
+		return;
+
 	str = tal_vfmt(NULL, fmt, ap);
 	status_send(take(towire_status_log(NULL, level, peer, str)));
 	tal_free(str);

common/status.h

@@ -26,6 +26,8 @@ void status_vfmt(enum log_level level,
 
 /* Usually we only log the packet names, not contents. */
 extern volatile bool logging_io;
+/* Usually we don't bother with TRACE spam */
+extern bool logging_trace;
 
 /* This logs a debug summary if IO logging not enabled. */
 void status_peer_io(enum log_level iodir,

common/subdaemon.c

@@ -30,6 +30,8 @@ bool subdaemon_setup(int argc, char *argv[])
 	for (int i = 1; i < argc; i++) {
 		if (streq(argv[i], "--log-io"))
 			logging_io = true;
+		if (streq(argv[i], "--log-trace"))
+			logging_trace = true;
 	}
 
 	developer = daemon_developer_mode(argv);

connectd/test/run-netaddress.c

@@ -53,9 +53,6 @@ u8 *b32_decode(const tal_t *ctx UNNEEDED, const char *str UNNEEDED, size_t len U
 /* Generated stub for b32_encode */
 char *b32_encode(const tal_t *ctx UNNEEDED, const void *data UNNEEDED, size_t len UNNEEDED)
 { fprintf(stderr, "b32_encode called!\n"); abort(); }
-/* Generated stub for daemon_conn_queue_length */
-size_t daemon_conn_queue_length(const struct daemon_conn *dc UNNEEDED)
-{ fprintf(stderr, "daemon_conn_queue_length called!\n"); abort(); }
 /* Generated stub for daemon_conn_send */
 void daemon_conn_send(struct daemon_conn *dc UNNEEDED, const u8 *msg UNNEEDED)
 { fprintf(stderr, "daemon_conn_send called!\n"); abort(); }

lightningd/log.c

@@ -478,6 +478,11 @@ bool log_has_io_logging(const struct logger *log)
 	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_TRACE;
 }
 
+bool log_has_trace_logging(const struct logger *log)
+{
+	return print_level(log->log_book, log->prefix, log->default_node_id, NULL) < LOG_DBG;
+}
+
 /* This may move entry! */
 static void add_entry(struct logger *log, struct log_entry **l)
 {

lightningd/log.h

@@ -48,6 +48,8 @@ void logv(struct logger *logger, enum log_level level, const struct node_id *nod
 const char *log_prefix(const struct logger *logger);
 /* Is there any chance we do io-level logging for this node_id in log? */
 bool log_has_io_logging(const struct logger *log);
+/* How about trace logging? */
+bool log_has_trace_logging(const struct logger *log);
 
 void opt_register_logging(struct lightningd *ld);
 

lightningd/subd.c

@@ -205,6 +205,7 @@ static int subd(const char *path, const char *name,
 		bool debugging,
 		int *msgfd,
 		bool io_logging,
+		bool trace_logging,
 		bool developer,
 		va_list *ap)
 {
@@ -228,7 +229,7 @@ static int subd(const char *path, const char *name,
 
 	if (childpid == 0) {
 		size_t num_args;
-		char *args[] = { NULL, NULL, NULL, NULL, NULL };
+		char *args[] = { NULL, NULL, NULL, NULL, NULL, NULL };
 		int **fds = tal_arr(tmpctx, int *, 3);
 		int stdoutfd = STDOUT_FILENO, stderrfd = STDERR_FILENO;
 
@@ -259,6 +260,8 @@ static int subd(const char *path, const char *name,
 		args[num_args++] = tal_strdup(NULL, path);
 		if (io_logging)
 			args[num_args++] = "--log-io";
+		if (trace_logging)
+			args[num_args++] = "--log-trace";
 		if (debugging)
 			args[num_args++] = "--dev-debug-self";
 		if (developer)
@@ -742,9 +745,10 @@ static struct subd *new_subd(const tal_t *ctx,
 
 	sd->pid = subd(path, name, debugging(ld, name),
 		       &msg_fd,
-		       /* We only turn on subdaemon io logging if we're going
+		       /* We only turn on subdaemon io/trace logging if we're going
 			* to print it: too stressful otherwise! */
 		       log_has_io_logging(sd->log),
+		       log_has_trace_logging(sd->log),
 		       ld->developer,
 		       ap);
 	if (sd->pid == (pid_t)-1) {

lightningd/test/run-find_my_abspath.c

@@ -173,6 +173,9 @@ void log_backtrace_print(const char *fmt UNNEEDED, ...)
 /* Generated stub for log_has_io_logging */
 bool log_has_io_logging(const struct logger *log UNNEEDED)
 { fprintf(stderr, "log_has_io_logging called!\n"); abort(); }
+/* Generated stub for log_has_trace_logging */
+bool log_has_trace_logging(const struct logger *log UNNEEDED)
+{ fprintf(stderr, "log_has_trace_logging called!\n"); abort(); }
 /* Generated stub for log_prefix */
 const char *log_prefix(const struct logger *logger UNNEEDED)
 { fprintf(stderr, "log_prefix called!\n"); abort(); }

lightningd/test/run-shuffle_fds.c

@@ -86,6 +86,9 @@ void log_(struct logger *logger UNNEEDED, enum log_level level UNNEEDED,
 /* Generated stub for log_has_io_logging */
 bool log_has_io_logging(const struct logger *log UNNEEDED)
 { fprintf(stderr, "log_has_io_logging called!\n"); abort(); }
+/* Generated stub for log_has_trace_logging */
+bool log_has_trace_logging(const struct logger *log UNNEEDED)
+{ fprintf(stderr, "log_has_trace_logging called!\n"); abort(); }
 /* Generated stub for log_prefix */
 const char *log_prefix(const struct logger *logger UNNEEDED)
 { fprintf(stderr, "log_prefix called!\n"); abort(); }