status: suppress status_trace/status_debug messages if queue too long.

We can be spammy, which is good for tests, but bad for our simple message queue.
This avoids breaking our tests but also avoid the worst case (1M entries and counting!)
for gossip status messages in the case where we're syncing a large peer.

Signed-off-by: Rusty Russell <[email protected]>

common/daemon_conn.c

@@ -146,3 +146,8 @@ void daemon_conn_wake(struct daemon_conn *dc)
 {
 	msg_wake(dc->out);
 }
+
+size_t daemon_conn_queue_length(const struct daemon_conn *dc)
+{
+	return msg_queue_length(dc->out);
+}

common/daemon_conn.h

@@ -56,4 +56,10 @@ struct io_plan *daemon_conn_read_next(struct io_conn *conn,
  * daemon_conn_sync_flush - Flush connection by sending all messages now..
  */
 bool daemon_conn_sync_flush(struct daemon_conn *dc);
+
+/**
+ * daemon_conn_queue_length - Get number of message in outgoing queue.
+ */
+size_t daemon_conn_queue_length(const struct daemon_conn *dc);
+
 #endif /* LIGHTNING_COMMON_DAEMON_CONN_H */

common/msg_queue.c

@@ -22,6 +22,11 @@ static void do_enqueue(struct msg_queue *q, const u8 *add TAKES)
 	io_wake(q);
 }
 
+size_t msg_queue_length(const struct msg_queue *q)
+{
+	return tal_count(q->q);
+}
+
 void msg_enqueue(struct msg_queue *q, const u8 *add)
 {
 	assert(fromwire_peektype(add) != MSG_PASS_FD);

common/msg_queue.h

@@ -15,6 +15,9 @@ struct msg_queue *msg_queue_new(const tal_t *ctx);
 /* If add is taken(), freed after sending.  msg_wake() implied. */
 void msg_enqueue(struct msg_queue *q, const u8 *add TAKES);
 
+/* Get current queue length */
+size_t msg_queue_length(const struct msg_queue *q);
+
 /* Fd is closed after sending.  msg_wake() implied. */
 void msg_enqueue_fd(struct msg_queue *q, int fd);
 

common/status.c

@@ -20,6 +20,10 @@ static struct daemon_conn *status_conn;
 volatile bool logging_io = false;
 static bool was_logging_io = false;
 
+/* 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;
@@ -118,6 +122,22 @@ void status_vfmt(enum log_level level, const char *fmt, va_list ap)
 {
 	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 && 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_debug("...[%zu debug messages suppressed]...", n);
+		} else if (traces_suppressed || qlen > TRACE_QUEUE_LIMIT) {
+			traces_suppressed++;
+			return;
+		}
+	}
 	str = tal_vfmt(NULL, fmt, ap);
 	status_send(take(towire_status_log(NULL, level, str)));
 	tal_free(str);