lightningd: re-enable IO logging for JSON output.

Hex format is terrible, but sometimes it's the only way to tell WTF is
going on.

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

lightningd/json_stream.c

@@ -4,6 +4,7 @@
 #include <common/utils.h>
 #include <lightningd/json.h>
 #include <lightningd/json_stream.h>
+#include <lightningd/log.h>
 #include <stdarg.h>
 #include <stdio.h>
 
@@ -29,6 +30,9 @@ struct json_stream {
 	void *reader_arg;
 	size_t len_read;
 
+	/* Where to log I/O */
+	struct log *log;
+
 	/* Current command's output. */
 	MEMBUF(char) outbuf;
 };
@@ -43,7 +47,9 @@ static void *membuf_tal_realloc(struct membuf *mb,
 	return p;
 }
 
-struct json_stream *new_json_stream(const tal_t *ctx, struct command *writer)
+struct json_stream *new_json_stream(const tal_t *ctx,
+				    struct command *writer,
+				    struct log *log)
 {
 	struct json_stream *js = tal(ctx, struct json_stream);
 
@@ -56,6 +62,7 @@ struct json_stream *new_json_stream(const tal_t *ctx, struct command *writer)
 #endif
 	js->indent = 0;
 	js->empty = true;
+	js->log = log;
 	return js;
 }
 
@@ -109,6 +116,8 @@ static void js_written_some(struct json_stream *js)
 void json_stream_append_part(struct json_stream *js, const char *str, size_t len)
 {
 	mkroom(js, len);
+	if (js->log)
+		log_io(js->log, LOG_IO_OUT, "", str, len);
 	memcpy(membuf_add(&js->outbuf, len), str, len);
 	js_written_some(js);
 }
@@ -139,6 +148,9 @@ static void json_stream_append_vfmt(struct json_stream *js,
 		mkroom(js, fmtlen + 1);
 		vsprintf(membuf_space(&js->outbuf), fmt, ap2);
 	}
+	if (js->log)
+		log_io(js->log, LOG_IO_OUT, "",
+		       membuf_space(&js->outbuf), fmtlen);
 	membuf_added(&js->outbuf, fmtlen);
 	js_written_some(js);
 	va_end(ap2);

lightningd/json_stream.h

@@ -15,13 +15,16 @@
 struct command;
 struct io_conn;
 struct json_stream;
+struct log;
 
 /**
  * new_json_stream - create a new JSON stream.
  * @ctx: tal context for allocation.
  * @writer: object responsible for writing to this stream.
+ * @log: where to log the IO
  */
-struct json_stream *new_json_stream(const tal_t *ctx, struct command *writer);
+struct json_stream *new_json_stream(const tal_t *ctx, struct command *writer,
+				    struct log *log);
 
 /**
  * Duplicate an existing stream.

lightningd/jsonrpc.c

@@ -120,7 +120,7 @@ static struct json_stream *jcon_new_json_stream(const tal_t *ctx,
 						struct json_connection *jcon,
 						struct command *writer)
 {
-	struct json_stream *js = new_json_stream(ctx, writer);
+	struct json_stream *js = new_json_stream(ctx, writer, jcon->log);
 
 	/* Wake writer to start streaming, in case it's not already. */
 	io_wake(jcon);
@@ -499,7 +499,7 @@ struct json_stream *json_stream_raw_for_cmd(struct command *cmd)
 	if (cmd->jcon)
 		js = jcon_new_json_stream(cmd, cmd->jcon, cmd);
 	else
-		js = new_json_stream(cmd, cmd);
+		js = new_json_stream(cmd, cmd, NULL);
 
 	assert(!cmd->have_json_stream);
 	cmd->have_json_stream = true;
@@ -1068,7 +1068,7 @@ struct jsonrpc_notification *jsonrpc_notification_start(const tal_t *ctx, const
 {
 	struct jsonrpc_notification *n = tal(ctx, struct jsonrpc_notification);
 	n->method = tal_strdup(n, method);
-	n->stream = new_json_stream(n, NULL);
+	n->stream = new_json_stream(n, NULL, NULL);
 	json_object_start(n->stream, NULL);
 	json_add_string(n->stream, "jsonrpc", "2.0");
 	json_add_string(n->stream, "method", method);
@@ -1085,7 +1085,7 @@ void jsonrpc_notification_end(struct jsonrpc_notification *n)
 }
 
 struct jsonrpc_request *jsonrpc_request_start_(
-    const tal_t *ctx, const char *method,
+    const tal_t *ctx, const char *method, struct log *log,
     void (*response_cb)(const char *buffer, const jsmntok_t *toks,
 			const jsmntok_t *idtok, void *),
     void *response_cb_arg)
@@ -1096,7 +1096,7 @@ struct jsonrpc_request *jsonrpc_request_start_(
 	r->response_cb = response_cb;
 	r->response_cb_arg = response_cb_arg;
 	r->method = NULL;
-	r->stream = new_json_stream(r, NULL);
+	r->stream = new_json_stream(r, NULL, log);
 
 	/* If no method is specified we don't prefill the JSON-RPC
 	 * request with the header. This serves as an escape hatch to

lightningd/jsonrpc.h

@@ -189,9 +189,9 @@ struct jsonrpc_notification *jsonrpc_notification_start(const tal_t *ctx, const
  */
 void jsonrpc_notification_end(struct jsonrpc_notification *n);
 
-#define jsonrpc_request_start(ctx, method, response_cb, response_cb_arg)			\
+#define jsonrpc_request_start(ctx, method, log, response_cb, response_cb_arg) \
 	jsonrpc_request_start_(					\
-		(ctx), (method),					\
+		(ctx), (method), (log),					\
 	    typesafe_cb_preargs(void, void *, (response_cb), (response_cb_arg),	\
 				const char *buffer,		\
 				const jsmntok_t *toks,		\
@@ -199,7 +199,7 @@ void jsonrpc_notification_end(struct jsonrpc_notification *n);
 	    (response_cb_arg))
 
 struct jsonrpc_request *jsonrpc_request_start_(
-    const tal_t *ctx, const char *method,
+    const tal_t *ctx, const char *method, struct log *log,
     void (*response_cb)(const char *buffer, const jsmntok_t *toks,
 			const jsmntok_t *idtok, void *),
     void *response_cb_arg);

lightningd/plugin.c

@@ -616,7 +616,8 @@ static struct command_result *plugin_rpcmethod_dispatch(struct command *cmd,
 	idtok = json_get_member(buffer, toks, "id");
 	assert(idtok != NULL);
 
-	req = jsonrpc_request_start(plugin, NULL, plugin_rpcmethod_cb, cmd);
+	req = jsonrpc_request_start(plugin, NULL, plugin->log,
+				    plugin_rpcmethod_cb, cmd);
 	snprintf(id, ARRAY_SIZE(id), "%"PRIu64, req->id);
 
 	json_stream_forward_change_id(req->stream, buffer, toks, idtok, id);
@@ -928,7 +929,8 @@ void plugins_init(struct plugins *plugins, const char *dev_plugin_debug)
 		 * write-only on p->stdout */
 		io_new_conn(p, stdout, plugin_stdout_conn_init, p);
 		io_new_conn(p, stdin, plugin_stdin_conn_init, p);
-		req = jsonrpc_request_start(p, "getmanifest", plugin_manifest_cb, p);
+		req = jsonrpc_request_start(p, "getmanifest", p->log,
+					    plugin_manifest_cb, p);
 		jsonrpc_request_end(req);
 		plugin_request_send(p, req);
 
@@ -971,7 +973,8 @@ static void plugin_config(struct plugin *plugin)
 	const char *name;
 	struct jsonrpc_request *req;
 	struct lightningd *ld = plugin->plugins->ld;
-	req = jsonrpc_request_start(plugin, "init", plugin_config_cb, plugin);
+	req = jsonrpc_request_start(plugin, "init", plugin->log,
+				    plugin_config_cb, plugin);
 
 	/* Add .params.options */
 	json_object_start(req->stream, "options");

lightningd/plugin_hook.c

@@ -71,7 +71,8 @@ void plugin_hook_call_(struct lightningd *ld, const struct plugin_hook *hook,
 		 * currently have a list to store these. We might want
 		 * to eventually to inspect in-flight requests. */
 		ph_req = notleak(tal(hook->plugin, struct plugin_hook_request));
-		req = jsonrpc_request_start(NULL, hook->name,
+		/* FIXME: do IO logging for these! */
+		req = jsonrpc_request_start(NULL, hook->name, NULL,
 					    plugin_hook_callback, ph_req);
 		ph_req->hook = hook;
 		ph_req->cb_arg = cb_arg;

lightningd/test/run-jsonrpc.c

@@ -83,7 +83,7 @@ bool deprecated_apis;
 
 static int test_json_filter(void)
 {
-	struct json_stream *result = new_json_stream(NULL, NULL);
+	struct json_stream *result = new_json_stream(NULL, NULL, NULL);
 	jsmntok_t *toks;
 	const jsmntok_t *x;
 	bool valid;
@@ -129,7 +129,7 @@ static void test_json_escape(void)
 
 	for (i = 1; i < 256; i++) {
 		char badstr[2];
-		struct json_stream *result = new_json_stream(NULL, NULL);
+		struct json_stream *result = new_json_stream(NULL, NULL, NULL);
 		struct json_escaped *esc;
 
 		badstr[0] = i;