log: truncate giant IO logging.

Adding a giant IO message simply causes it to be pruned immediately,
so truncate it if it's more than 1/64 the max size.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd/log.c

@@ -49,7 +49,9 @@ struct log_book {
 		      enum log_level level,
 		      bool continued,
 		      const struct timeabs *time,
-		      const char *str, const u8 *io, void *arg);
+		      const char *str,
+		      const u8 *io, size_t io_len,
+		      void *arg);
 	void *print_arg;
 	enum log_level print_level;
 	struct timeabs init_time;
@@ -68,6 +70,7 @@ static void log_to_file(const char *prefix,
 			const struct timeabs *time,
 			const char *str,
 			const u8 *io,
+			size_t io_len,
 			FILE *logf)
 {
 	char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ")];
@@ -77,7 +80,7 @@ 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_hex(NULL, io);
+		char *hex = tal_hexstr(NULL, io, io_len);
 		fprintf(logf, "%s %s%s%s %s\n",
 			iso8601_s, prefix, str, dir, hex);
 		tal_free(hex);
@@ -94,9 +97,10 @@ static void log_to_stdout(const char *prefix,
 			  bool continued,
 			  const struct timeabs *time,
 			  const char *str,
-			  const u8 *io, void *unused UNUSED)
+			  const u8 *io, size_t io_len,
+			  void *unused UNUSED)
 {
-	log_to_file(prefix, level, continued, time, str, io, stdout);
+	log_to_file(prefix, level, continued, time, str, io, io_len, stdout);
 }
 
 static size_t mem_used(const struct log_entry *e)
@@ -191,7 +195,9 @@ void set_log_outfn_(struct log_book *lr,
 				  enum log_level level,
 				  bool continued,
 				  const struct timeabs *time,
-				  const char *str, const u8 *io, void *arg),
+				  const char *str,
+				  const u8 *io, size_t io_len,
+				  void *arg),
 		    void *arg)
 {
 	lr->print = print;
@@ -250,7 +256,7 @@ static void maybe_print(const struct log *log, const struct log_entry *l,
 	if (l->level >= log->lr->print_level)
 		log->lr->print(log->prefix, l->level, offset != 0,
 			       &l->time, l->log + offset,
-			       l->io, log->lr->print_arg);
+			       l->io, tal_bytelen(l->io), log->lr->print_arg);
 }
 
 void logv(struct log *log, enum log_level level, const char *fmt, va_list ap)
@@ -282,10 +288,21 @@ 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->lr->print_level)
+		log->lr->print(log->prefix, l->level, false,
+			       &l->time, str,
+			       data, len, log->lr->print_arg);
+
 	l->log = tal_strdup(l, str);
+
+	/* Don't immediately fill buffer with giant IOs */
+	if (len > log->lr->max_mem / 64) {
+		l->skipped++;
+		len = log->lr->max_mem / 64;
+	}
 	l->io = tal_dup_arr(l, u8, data, len, 0);
 
-	maybe_print(log, l, 0);
 	add_entry(log, l);
 	errno = save_errno;
 }

lightningd/log.h

@@ -50,7 +50,7 @@ struct log_book *get_log_book(const struct log *log);
 					   bool,			\
 					   const struct timeabs *,	\
 					   const char *,		\
-					   const u8 *), (arg))
+					   const u8 *, size_t), (arg))
 
 /* If level == LOG_IO_IN/LOG_IO_OUT, then io contains data */
 void set_log_outfn_(struct log_book *lr,
@@ -59,7 +59,7 @@ void set_log_outfn_(struct log_book *lr,
 				  bool continued,
 				  const struct timeabs *time,
 				  const char *str,
-				  const u8 *io,
+				  const u8 *io, size_t io_len,
 				  void *arg),
 		    void *arg);
 

lightningd/peer_control.c

@@ -72,11 +72,11 @@ static void copy_to_parent_log(const char *prefix,
 			       bool continued,
 			       const struct timeabs *time UNUSED,
 			       const char *str,
-			       const u8 *io,
+			       const u8 *io, size_t io_len,
 			       struct log *parent_log)
 {
 	if (level == LOG_IO_IN || level == LOG_IO_OUT)
-		log_io(parent_log, level, prefix, io, tal_count(io));
+		log_io(parent_log, level, prefix, io, io_len);
 	else if (continued)
 		log_add(parent_log, "%s ... %s", prefix, str);
 	else

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

@@ -382,7 +382,7 @@ void set_log_outfn_(struct log_book *lr UNNEEDED,
 				  bool continued UNNEEDED,
 				  const struct timeabs *time UNNEEDED,
 				  const char *str UNNEEDED,
-				  const u8 *io UNNEEDED,
+				  const u8 *io UNNEEDED, size_t io_len UNNEEDED,
 				  void *arg) UNNEEDED,
 		    void *arg UNNEEDED)
 { fprintf(stderr, "set_log_outfn_ called!\n"); abort(); }

wallet/test/run-wallet.c

@@ -623,6 +623,7 @@ void set_log_outfn_(struct log_book *lr UNNEEDED,
 				  const struct timeabs *time UNNEEDED,
 				  const char *str UNNEEDED,
 				  const u8 *io UNNEEDED,
+				  size_t io_len UNNEEDED,
 				  void *arg) UNNEEDED,
 		    void *arg UNNEEDED)
 {