log: separate levels for IO directions, allow msg + io data.

We currently don't handle LOG_IO properly, and we turn it into a string
before handing it to the ->print function, which makes it ugly for
the case where we're using copy_to_parent_log, and also means in
that case we lose *what peer* the IO is coming from.

Now, we handle the io as a separate arg, which is much neater.

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

common/status.c

@@ -75,13 +75,13 @@ static void status_send_with_hdr(u16 type, const void *p, size_t len)
 	}
 }
 
-void status_io(enum side sender, const u8 *p)
+void status_io(enum log_level iodir, const u8 *p)
 {
-	u16 type = STATUS_LOG_MIN + LOG_IO;
+	u16 type = STATUS_LOG_MIN + iodir;
 	u8 *msg = tal_arr(NULL, u8, 0);
 
+	assert(iodir == LOG_IO_IN || iodir == LOG_IO_OUT);
 	towire_u16(&msg, type);
-	towire_bool(&msg, sender == REMOTE);
 	towire(&msg, p, tal_len(p));
 	if (too_large(tal_len(msg), type))
 		tal_resize(&msg, 65535);

common/status.h

@@ -27,7 +27,7 @@ void status_fmt(enum log_level level, const char *fmt, ...)
 /* vprintf-style */
 void status_vfmt(enum log_level level, const char *fmt, va_list ap);
 
-void status_io(enum side sender, const u8 *msg);
+void status_io(enum log_level iodir, const u8 *p);
 
 /* Helpers */
 #define status_debug(...)			\

common/status_levels.h

@@ -4,7 +4,8 @@
 
 enum log_level {
 	/* Logging all IO. */
-	LOG_IO,
+	LOG_IO_OUT,
+	LOG_IO_IN,
 	/* Gory details which are mainly good for debugging. */
 	LOG_DBG,
 	/* Information about what's going in. */

lightningd/jsonrpc.c

@@ -634,7 +634,7 @@ static struct io_plan *write_json(struct io_conn *conn,
 	jcon->outbuf = tal_steal(jcon, out->json);
 	tal_free(out);
 
-	log_io(jcon->log, false, jcon->outbuf, strlen(jcon->outbuf));
+	log_io(jcon->log, LOG_IO_OUT, "", jcon->outbuf, strlen(jcon->outbuf));
 	return io_write(conn,
 			jcon->outbuf, strlen(jcon->outbuf), write_json, jcon);
 }
@@ -645,7 +645,8 @@ static struct io_plan *read_json(struct io_conn *conn,
 	jsmntok_t *toks;
 	bool valid;
 
-	log_io(jcon->log, true, jcon->buffer + jcon->used, jcon->len_read);
+	log_io(jcon->log, LOG_IO_IN, "",
+	       jcon->buffer + jcon->used, jcon->len_read);
 
 	/* Resize larger if we're full. */
 	jcon->used += jcon->len_read;

lightningd/log.c

@@ -29,6 +29,8 @@ struct log_entry {
 	unsigned int skipped;
 	const char *prefix;
 	char *log;
+	/* Iff LOG_IO */
+	const u8 *io;
 };
 
 struct log_book {
@@ -38,7 +40,7 @@ struct log_book {
 		      enum log_level level,
 		      bool continued,
 		      const struct timeabs *time,
-		      const char *str, void *arg);
+		      const char *str, const u8 *io, void *arg);
 	void *print_arg;
 	enum log_level print_level;
 	struct timeabs init_time;
@@ -56,13 +58,21 @@ static void log_to_file(const char *prefix,
 			bool continued,
 			const struct timeabs *time,
 			const char *str,
+			const u8 *io,
 			FILE *logf)
 {
 	char iso8601_msec_fmt[sizeof("YYYY-mm-ddTHH:MM:SS.%03dZ")];
 	strftime(iso8601_msec_fmt, sizeof(iso8601_msec_fmt), "%FT%T.%%03dZ", gmtime(&time->ts.tv_sec));
 	char iso8601_s[sizeof("YYYY-mm-ddTHH:MM:SS.nnnZ")];
 	snprintf(iso8601_s, sizeof(iso8601_s), iso8601_msec_fmt, (int) time->ts.tv_nsec / 1000000);
-	if (!continued) {
+
+	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
+		const char *dir = level == LOG_IO_IN ? "[IN]" : "[OUT]";
+		char *hex = tal_hex(NULL, io);
+		fprintf(logf, "%s %s%s%s %s\n",
+			iso8601_s, prefix, str, dir, hex);
+		tal_free(hex);
+	} else 	if (!continued) {
 		fprintf(logf, "%s %s %s\n", iso8601_s, prefix, str);
 	} else {
 		fprintf(logf, "%s %s \t%s\n", iso8601_s, prefix, str);
@@ -74,17 +84,15 @@ static void log_to_stdout(const char *prefix,
 			  enum log_level level,
 			  bool continued,
 			  const struct timeabs *time,
-			  const char *str, void *unused UNUSED)
+			  const char *str,
+			  const u8 *io, void *unused UNUSED)
 {
-	log_to_file(prefix, level, continued, time, str, stdout);
+	log_to_file(prefix, level, continued, time, str, io, stdout);
 }
 
-static size_t log_bufsize(const struct log_entry *e)
+static size_t mem_used(const struct log_entry *e)
 {
-	if (e->level == LOG_IO)
-		return tal_count(e->log);
-	else
-		return strlen(e->log) + 1;
+	return sizeof(*e) + strlen(e->log) + 1 + tal_len(e->io);
 }
 
 static size_t prune_log(struct log_book *log)
@@ -96,7 +104,7 @@ static size_t prune_log(struct log_book *log)
 	tail = list_tail(&log->log, struct log_entry, list);
 
 	list_for_each_safe(&log->log, i, next, list) {
-		/* 50% chance of deleting debug, 25% inform, 12.5% unusual. */
+		/* 50% chance of deleting IO_IN, 25% IO_OUT, 12.5% DEBUG... */
 		if (i == tail || !pseudorand(2 << i->level)) {
 			i->skipped += skipped;
 			skipped = 0;
@@ -104,7 +112,7 @@ static size_t prune_log(struct log_book *log)
 		}
 
 		list_del_from(&log->log, &i->list);
-		log->mem_used -= sizeof(*i) + log_bufsize(i);
+		log->mem_used -= mem_used(i);
 		tal_free(i);
 		skipped++;
 		deleted++;
@@ -174,7 +182,7 @@ void set_log_outfn_(struct log_book *lr,
 				  enum log_level level,
 				  bool continued,
 				  const struct timeabs *time,
-				  const char *str, void *arg),
+				  const char *str, const u8 *io, void *arg),
 		    void *arg)
 {
 	lr->print = print;
@@ -203,7 +211,7 @@ const struct timeabs *log_init_time(const struct log_book *lr)
 
 static void add_entry(struct log *log, struct log_entry *l)
 {
-	log->lr->mem_used += sizeof(*l) + log_bufsize(l);
+	log->lr->mem_used += mem_used(l);
 	list_add_tail(&log->lr->log, &l->list);
 
 	if (log->lr->mem_used > log->lr->max_mem) {
@@ -228,44 +236,45 @@ static struct log_entry *new_log_entry(struct log *log, enum log_level level)
 	l->level = level;
 	l->skipped = 0;
 	l->prefix = log->prefix;
+	l->io = NULL;
 
 	return l;
 }
 
+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,
+			       &l->time, l->log + offset,
+			       l->io, log->lr->print_arg);
+}
+
 void logv(struct log *log, enum log_level level, const char *fmt, va_list ap)
 {
 	int save_errno = errno;
 	struct log_entry *l = new_log_entry(log, level);
 
 	l->log = tal_vfmt(l, fmt, ap);
-
-	if (level >= log->lr->print_level)
-		log->lr->print(log->prefix, level, false, &l->time, l->log,
-			       log->lr->print_arg);
+	maybe_print(log, l, 0);
 
 	add_entry(log, l);
 	errno = save_errno;
 }
 
-void log_io(struct log *log, bool in, const void *data, size_t len)
+void log_io(struct log *log, enum log_level dir,
+	    const char *str TAKES,
+	    const void *data TAKES, size_t len)
 {
 	int save_errno = errno;
-	struct log_entry *l = new_log_entry(log, LOG_IO);
+	struct log_entry *l = new_log_entry(log, dir);
 
-	l->log = tal_arr(l, char, 1 + len);
-	l->log[0] = in;
-	memcpy(l->log + 1, data, len);
+	assert(dir == LOG_IO_IN || dir == LOG_IO_OUT);
 
-	if (LOG_IO >= log->lr->print_level) {
-		const char *dir = in ? "[IN]" : "[OUT]";
-		char *hex = tal_arr(l, char, strlen(dir) + hex_str_size(len));
-		strcpy(hex, dir);
-		hex_encode(data, len, hex + strlen(dir), hex_str_size(len));
-		log->lr->print(log->prefix, LOG_IO, false, &l->time, l->log,
-			       log->lr->print_arg);
-		tal_free(hex);
-	}
+	l->log = tal_strdup(l, str);
+	l->io = tal_dup_arr(l, u8, data, len, 0);
 
+	maybe_print(log, l, 0);
 	add_entry(log, l);
 	errno = save_errno;
 }
@@ -276,15 +285,13 @@ void logv_add(struct log *log, const char *fmt, va_list ap)
 	size_t oldlen = strlen(l->log);
 
 	/* Remove from list, so it doesn't get pruned. */
-	log->lr->mem_used -= sizeof(*l) + oldlen + 1;
+	log->lr->mem_used -= mem_used(l);
 	list_del_from(&log->lr->log, &l->list);
 
 	tal_append_vfmt(&l->log, fmt, ap);
 	add_entry(log, l);
 
-	if (l->level >= log->lr->print_level)
-		log->lr->print(log->prefix, l->level, true, &l->time, l->log + oldlen,
-			       log->lr->print_arg);
+	maybe_print(log, l, oldlen);
 }
 
 void log_(struct log *log, enum log_level level, const char *fmt, ...)
@@ -311,6 +318,7 @@ void log_each_line_(const struct log_book *lr,
 				 enum log_level level,
 				 const char *prefix,
 				 const char *log,
+				 const u8 *io,
 				 void *arg),
 		    void *arg)
 {
@@ -318,7 +326,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, arg);
+		     i->level, i->prefix, i->log, i->io, arg);
 	}
 }
 
@@ -332,6 +340,7 @@ static void log_one_line(unsigned int skipped,
 			 enum log_level level,
 			 const char *prefix,
 			 const char *log,
+			 const u8 *io,
 			 struct log_data *data)
 {
 	char buf[101];
@@ -347,7 +356,8 @@ static void log_one_line(unsigned int skipped,
 		(unsigned long)diff.ts.tv_sec,
 		(unsigned)diff.ts.tv_nsec,
 		prefix,
-		level == LOG_IO ? (log[0] ? "IO-IN" : "IO-OUT")
+		level == LOG_IO_IN ? "IO_IN"
+		: level == LOG_IO_OUT ? "IO_OUT"
 		: level == LOG_DBG ? "DEBUG"
 		: level == LOG_INFORM ? "INFO"
 		: level == LOG_UNUSUAL ? "UNUSUAL"
@@ -355,19 +365,18 @@ static void log_one_line(unsigned int skipped,
 		: "**INVALID**");
 
 	write_all(data->fd, buf, strlen(buf));
-	if (level == LOG_IO) {
-		size_t off, used, len = tal_count(log)-1;
+	write_all(data->fd, log, strlen(log));
+	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
+		size_t off, used, len = tal_count(io);
 
 		/* No allocations, may be in signal handler. */
 		for (off = 0; off < len; off += used) {
 			used = len - off;
 			if (hex_str_size(used) > sizeof(buf))
 				used = hex_data_size(sizeof(buf));
-			hex_encode(log + 1 + off, used, buf, hex_str_size(used));
+			hex_encode(io + off, used, buf, hex_str_size(used));
 			write_all(data->fd, buf, strlen(buf));
 		}
-	} else {
-		write_all(data->fd, log, strlen(log));
 	}
 
 	data->prefix = "\n";
@@ -377,7 +386,7 @@ static struct {
 	const char *name;
 	enum log_level level;
 } log_levels[] = {
-	{ "IO", LOG_IO },
+	{ "IO", LOG_IO_OUT },
 	{ "DEBUG", LOG_DBG },
 	{ "INFO", LOG_INFORM },
 	{ "UNUSUAL", LOG_UNUSUAL },
@@ -599,6 +608,7 @@ static void log_to_json(unsigned int skipped,
 			enum log_level level,
 			const char *prefix,
 			const char *log,
+			const u8 *io,
 			struct log_info *info)
 {
 	info->num_skipped += skipped;
@@ -616,20 +626,14 @@ static void log_to_json(unsigned int skipped,
 			: level == LOG_UNUSUAL ? "UNUSUAL"
 			: level == LOG_INFORM ? "INFO"
 			: level == LOG_DBG ? "DEBUG"
-			: level == LOG_IO ? "IO"
+			: level == LOG_IO_IN ? "IO_IN"
+			: level == LOG_IO_OUT ? "IO_OUT"
 			: "UNKNOWN");
 	json_add_time(info->response, "time", diff.ts);
 	json_add_string(info->response, "source", prefix);
-	if (level == LOG_IO) {
-		assert(tal_count(log) > 0);
-		if (log[0])
-			json_add_string(info->response, "direction", "IN");
-		else
-			json_add_string(info->response, "direction", "OUT");
-
-		json_add_hex(info->response, "data", log+1, tal_count(log)-1);
-	} else
-		json_add_string(info->response, "log", log);
+	json_add_string(info->response, "log", log);
+	if (io)
+		json_add_hex(info->response, "data", io, tal_count(io));
 
 	json_object_end(info->response);
 }
@@ -664,7 +668,7 @@ static void json_getlog(struct command *cmd,
 	if (!level)
 		minlevel = LOG_INFORM;
 	else if (json_tok_streq(buffer, level, "io"))
-		minlevel = LOG_IO;
+		minlevel = LOG_IO_OUT;
 	else if (json_tok_streq(buffer, level, "debug"))
 		minlevel = LOG_DBG;
 	else if (json_tok_streq(buffer, level, "info"))

lightningd/log.h

@@ -25,7 +25,8 @@ struct log *new_log(const tal_t *ctx, struct log_book *record, const char *fmt,
 #define log_unusual(log, ...) log_((log), LOG_UNUSUAL, __VA_ARGS__)
 #define log_broken(log, ...) log_((log), LOG_BROKEN, __VA_ARGS__)
 
-void log_io(struct log *log, bool in, const void *data, size_t len);
+void log_io(struct log *log, enum log_level dir, const char *comment,
+	    const void *data, size_t len);
 
 void log_(struct log *log, enum log_level level, const char *fmt, ...)
 	PRINTF_FMT(3,4);
@@ -44,14 +45,18 @@ const char *log_prefix(const struct log *log);
 					   enum log_level,		\
 					   bool,			\
 					   const struct timeabs *,	\
-					   const char *), (arg))
+					   const char *,		\
+					   const u8 *), (arg))
 
+/* If level == LOG_IO_IN/LOG_IO_OUT, then io contains data */
 void set_log_outfn_(struct log_book *lr,
 		    void (*print)(const char *prefix,
 				  enum log_level level,
 				  bool continued,
 				  const struct timeabs *time,
-				  const char *str, void *arg),
+				  const char *str,
+				  const u8 *io,
+				  void *arg),
 		    void *arg);
 
 size_t log_max_mem(const struct log_book *lr);
@@ -65,7 +70,8 @@ const struct timeabs *log_init_time(const struct log_book *lr);
 					   struct timerel,		\
 					   enum log_level,		\
 					   const char *,		\
-					   const char *), (arg))
+					   const char *,		\
+					   const u8 *), (arg))
 
 void log_each_line_(const struct log_book *lr,
 		    void (*func)(unsigned int skipped,
@@ -73,6 +79,7 @@ void log_each_line_(const struct log_book *lr,
 				 enum log_level level,
 				 const char *prefix,
 				 const char *log,
+				 const u8 *io,
 				 void *arg),
 		    void *arg);
 

lightningd/log_status.c

@@ -11,10 +11,8 @@ bool log_status_msg(struct log *log, const u8 *msg)
 		return false;
 
 	level = type - STATUS_LOG_MIN;
-	if (level == LOG_IO) {
-		/* First byte is direction */
-		bool dir = fromwire_bool(&msg, &max);
-		log_io(log, dir, msg, max);
+	if (level == LOG_IO_IN || level == LOG_IO_OUT) {
+		log_io(log, level, "", msg, max);
 	} else {
 		int i;
 		/* Truncate if unprintable */

lightningd/peer_control.c

@@ -699,9 +699,12 @@ static void copy_to_parent_log(const char *prefix,
 			       bool continued,
 			       const struct timeabs *time,
 			       const char *str,
+			       const u8 *io,
 			       struct peer *peer)
 {
-	if (continued)
+	if (level == LOG_IO_IN || level == LOG_IO_OUT)
+		log_io(peer->ld->log, level, prefix, io, tal_len(io));
+	else if (continued)
 		log_add(peer->ld->log, "%s ... %s", prefix, str);
 	else
 		log_(peer->ld->log, level, "%s %s", prefix, str);