rustyrussell · Jul 30, 2014 · Jul 30, 2014 · Jul 30, 2014 · Jul 30, 2014
diff --git a/hex.c b/hex.c
@@ -1,4 +1,5 @@
 #include "hex.h"
+#include <assert.h>
 #include <ccan/short_types/short_types.h>
 #include <stdio.h>
 
@@ -37,14 +38,40 @@ bool from_hex(const char *str, size_t slen, void *buf, size_t bufsize)
 	return slen == 0 && bufsize == 0;
 }
 
+static char hexchar(unsigned int val)
+{
+	if (val < 10)
+		return '0' + val;
+	if (val < 16)
+		return 'a' + val - 10;
+	abort();
+}
+
+size_t to_hex_direct(char *dest, size_t destlen,
+		     const void *buf, size_t bufsize)
+{
+	size_t used = 0;
+
+	/* Need room for nul terminator */
+	assert(destlen > 0);
+
+	while (destlen >= 3 && used < bufsize) {
+		unsigned int c = ((const unsigned char *)buf)[used];
+		*(dest++) = hexchar(c >> 4);
+		*(dest++) = hexchar(c & 0xF);
+		destlen -= 2;
+		used++;
+	}
+	*dest = '\0';
+
+	return used;
+}
+
 char *to_hex(const tal_t *ctx, const void *buf, size_t bufsize)
 {
-	const u8 *p = buf;
-	size_t i;
 	char *hex = tal_arr(ctx, char, bufsize * 2 + 1);
-
-	for (i = 0; i < bufsize; i++)
-		sprintf(hex + i*2, "%02x", p[i]);
+
+	to_hex_direct(hex, bufsize * 2 + 1, buf, bufsize);
 
 	return hex;
 }
diff --git a/hex.h b/hex.h
@@ -10,4 +10,8 @@ bool from_hex(const char *str, size_t slen, void *buf, size_t bufsize);
 /* Allocate hex string off ctx */
 char *to_hex(const tal_t *ctx, const void *buf, size_t bufsize);
 
+/* dest becomes nul terminated string, returns bufsize used. */
+size_t to_hex_direct(char *dest, size_t destlen,
+		     const void *buf, size_t bufsize);
+
 #endif /* PETTYCOIN_HEX_H */
diff --git a/jsonrpc.c b/jsonrpc.c
@@ -24,7 +24,13 @@ struct json_output {
 
 static void free_jcon(struct io_conn *conn, struct json_connection *jcon)
 {
-	log_info(jcon->state->log, "Closing json input (%s)", strerror(errno));
+	if (--jcon->num_conns != 0) {
+		/* Wake other side, in case it's a closed socket. */
+		io_wake(jcon);
+		return;
+	}
+
+	log_info(jcon->log, "Closing (%s)", strerror(errno));
 	tal_free(jcon);
 }
 
@@ -122,7 +128,7 @@ static char *parse_request(struct json_connection *jcon, const jsmntok_t tok[])
 	char *result, *error;
 
 	if (tok[0].type != JSMN_OBJECT) {
-		log_unusual(jcon->state->log, "Expected {} for json command");
+		log_unusual(jcon->log, "Expected {} for json command");
 		return NULL;
 	}
 
@@ -131,19 +137,18 @@ static char *parse_request(struct json_connection *jcon, const jsmntok_t tok[])
 	id = json_get_member(jcon->buffer, tok, "id");
 
 	if (!id || !method || !params) {
-		log_unusual(jcon->state->log, "json: No %s",
+		log_unusual(jcon->log, "json: No %s",
 			    !id ? "id" : (!method ? "method" : "params"));
 		return NULL;
 	}
 
 	if (id->type != JSMN_STRING && id->type != JSMN_PRIMITIVE) {
-		log_unusual(jcon->state->log,
-			    "Expected string/primitive for id");
+		log_unusual(jcon->log, "Expected string/primitive for id");
 		return NULL;
 	}
 
 	if (method->type != JSMN_STRING) {
-		log_unusual(jcon->state->log, "Expected string for method");
+		log_unusual(jcon->log, "Expected string for method");
 		return NULL;
 	}
 
@@ -160,8 +165,7 @@ static char *parse_request(struct json_connection *jcon, const jsmntok_t tok[])
 	}
 
 	if (params->type != JSMN_ARRAY && params->type != JSMN_OBJECT) {
-		log_unusual(jcon->state->log,
-			    "Expected array or object for params");
+		log_unusual(jcon->log, "Expected array or object for params");
 		return NULL;
 	}
 
@@ -199,16 +203,24 @@ static struct io_plan write_json(struct io_conn *conn,
 	out = list_pop(&jcon->output, struct json_output, list);
 	if (!out) {
 		if (jcon->stop) {
-			log_unusual(jcon->state->log, "JSON-RPC shutdown");
+			log_unusual(jcon->log, "JSON-RPC shutdown");
 			/* Return us to toplevel pettycoin.c */
 			return io_break(jcon->state, io_close());
 		}
+
+		/* Has reader closed? */
+		if (jcon->num_conns != 2)
+			return io_close();
+
+		/* Reader can go again now. */
+		io_wake(jcon);
 		return io_wait(jcon, write_json, jcon);
 	}
 
 	jcon->outbuf = tal_steal(jcon, out->json);
 	tal_free(out);
-
+
+	log_io(jcon->log, false, jcon->outbuf, strlen(jcon->outbuf));
 	return io_write(jcon->outbuf, strlen(jcon->outbuf), write_json, jcon);
 }
 
@@ -219,6 +231,12 @@ static struct io_plan read_json(struct io_conn *conn,
 	bool valid;
 	struct json_output *out;
 
+	log_io(jcon->log, true, jcon->buffer + jcon->used, jcon->len_read);
+
+	/* Has writer closed? */
+	if (jcon->num_conns != 2)
+		return io_close();
+
 	/* Resize larger if we're full. */
 	jcon->used += jcon->len_read;
 	if (jcon->used == tal_count(jcon->buffer))
@@ -247,14 +265,19 @@ static struct io_plan read_json(struct io_conn *conn,
 	if (!out->json)
 		return io_close();
 
-	/* Queue for writing, and wake writer. */
-	list_add_tail(&jcon->output, &out->list);
-	io_wake(jcon);
-
 	/* Remove first {}. */
 	memmove(jcon->buffer, jcon->buffer + toks[0].end,
 		tal_count(jcon->buffer) - toks[0].end);
 	jcon->used -= toks[0].end;
+	tal_free(toks);
+
+	/* Queue for writing, and wake writer. */
+	list_add_tail(&jcon->output, &out->list);
+	io_wake(jcon);
+
+	/* Wait for it to finish */
+	jcon->len_read = 0;
+	return io_wait(jcon, read_json, jcon);
 
 read_more:
 	tal_free(toks);
@@ -266,23 +289,29 @@ static struct io_plan read_json(struct io_conn *conn,
 static void init_rpc(int fd, struct state *state)
 {
 	struct json_connection *jcon;
-	struct io_conn *conn;
+	struct io_conn *reader, *writer;
+	char prefix[sizeof("jcon fd ") + STR_MAX_CHARS(int)];
 
 	jcon = tal(state, struct json_connection);
 	jcon->state = state;
 	jcon->used = 0;
 	jcon->len_read = 64;
 	jcon->buffer = tal_arr(jcon, char, jcon->len_read);
 	jcon->stop = false;
+	jcon->num_conns = 2;
+	sprintf(prefix, "jcon fd %i", fd);
+	jcon->log = new_log(jcon, state->log, prefix, state->log_level,
+			    1000000);
 	list_head_init(&jcon->output);
 
-	conn = io_new_conn(fd,
-			   io_read_partial(jcon->buffer, &jcon->len_read,
-					   read_json, jcon));
+	reader = io_new_conn(fd,
+			     io_read_partial(jcon->buffer, &jcon->len_read,
+					     read_json, jcon));
 	/* Leave writer idle. */
-	io_duplex(conn, io_wait(jcon, write_json, jcon));
+	writer = io_duplex(reader, io_wait(jcon, write_json, jcon));
 
-	io_set_finish(conn, free_jcon, jcon);
+	io_set_finish(reader, free_jcon, jcon);
+	io_set_finish(writer, free_jcon, jcon);
 }
 
 static void rpc_connected(int fd, struct state *state)

diff --git a/jsonrpc.h b/jsonrpc.h
@@ -8,6 +8,9 @@ struct json_connection {
 	/* The global state */
 	struct state *state;
 
+	/* Logging for this json connection. */
+	struct log *log;
+
 	/* The buffer (required to interpret tokens). */
 	char *buffer;
 
@@ -17,6 +20,9 @@ struct json_connection {
 	/* How much has just been filled. */
 	size_t len_read;
 
+	/* I/O conns. */
+	unsigned int num_conns;
+
 	/* We've been told to stop. */
 	bool stop;
 

diff --git a/log.c b/log.c
@@ -1,3 +1,4 @@
+#include "hex.h"
 #include "log.h"
 #include "pseudorand.h"
 #include <ccan/list/list.h>
@@ -103,6 +104,25 @@ void logv(struct log *log, enum log_level level, const char *fmt, va_list ap)
 	add_entry(log, l);
 }
 
+void log_io(struct log *log, bool in, const void *data, size_t len)
+{
+	struct log_entry *l = tal(log, struct log_entry);
+
+	l->time = time_now();
+	l->level = LOG_IO;
+	l->skipped = 0;
+	l->log = tal_arr(l, char, 1 + len);
+	l->log[0] = in;
+	memcpy(l->log + 1, data, len);
+
+	if (LOG_IO >= log->print) {
+		char *hex = to_hex(l, data, len);
+		printf("%s[%s] %s\n", log->prefix, in ? "IN" : "OUT", hex);
+		tal_free(hex);
+	}
+	add_entry(log, l);
+}
+
 static void do_log_add(struct log *log, const char *fmt, va_list ap)
 {
 	struct log_entry *l = list_tail(&log->log, struct log_entry, list);
@@ -173,18 +193,33 @@ void log_to_file(int fd, const struct log *log)
 			prefix = "\n";
 		}
 		diff = time_between(i->time, prev);
+
 		sprintf(buf, "%s+%lu.%09u %s: ",
 			prefix,
 			(unsigned long)diff.ts.tv_sec,
 			(unsigned)diff.ts.tv_nsec,
-			i->level == LOG_DBG ? "DEBUG"
+			i->level == LOG_IO ? (i->log[0] ? "IO-IN" : "IO-OUT")
+			: i->level == LOG_DBG ? "DEBUG"
 			: i->level == LOG_INFORM ? "INFO"
 			: i->level == LOG_UNUSUAL ? "UNUSUAL"
 			: i->level == LOG_BROKEN ? "BROKEN"
 			: "**INVALID**");
+
 		write_all(fd, buf, strlen(buf));
-		write_all(fd, i->log, strlen(i->log));
+		if (i->level == LOG_IO) {
+			size_t off, used, len = tal_count(i->log)-1;
+
+			/* No allocations, may be in signal handler. */
+			for (off = 0; off < len; off += used) {
+				used = to_hex_direct(buf, sizeof(buf),
+						     i->log + 1 + off,
+						     len - off);
+				write_all(fd, buf, strlen(buf));
+			}
+		} else {
+			write_all(fd, i->log, strlen(i->log));
+		}
 		prefix = "\n";
 	}
 	write_all(fd, "\n\n", strlen("\n\n"));
-}			
+}
diff --git a/log.h b/log.h
@@ -14,6 +14,8 @@
 #define GEN_LOG_MAX 16777216
 
 enum log_level {
+	/* Logging all IO. */
+	LOG_IO,
 	/* Gory details which are mainly good for debugging. */
 	LOG_DBG,
 	/* Information about what's going in. */
@@ -33,6 +35,8 @@ struct log *new_log(const tal_t *ctx,
 #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_(struct log *log, enum log_level level, const char *fmt, ...)
 	PRINTF_FMT(3,4);
 void log_add(struct log *log, const char *fmt, ...) PRINTF_FMT(2,3);

diff --git a/minimal_log.c b/minimal_log.c
@@ -43,3 +43,14 @@ void log_add_enum_(struct log *log, const char *enumname, unsigned int val)
 	log_add(log, "%s(%u) ", enumname, val);
 }
 
+void log_io(struct log *log, bool in, const void *data, size_t len)
+{
+}
+
+struct log *new_log(const tal_t *ctx,
+		    const struct log *parent,
+		    const char *prefix,
+		    enum log_level printlevel, size_t max_mem)
+{
+	return NULL;
+}