From 53423e8a55846f405a9d36900616bc1b7137656f Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Mon, 18 Feb 2019 13:14:29 +1030 Subject: [PATCH] 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 --- lightningd/json_stream.c | 14 +++++++++++++- lightningd/json_stream.h | 5 ++++- lightningd/jsonrpc.c | 10 +++++----- lightningd/jsonrpc.h | 6 +++--- lightningd/plugin.c | 9 ++++++--- lightningd/plugin_hook.c | 3 ++- lightningd/test/run-jsonrpc.c | 4 ++-- 7 files changed, 35 insertions(+), 16 deletions(-) diff --git a/lightningd/json_stream.c b/lightningd/json_stream.c index b90723d91..a26f77bae 100644 --- a/lightningd/json_stream.c +++ b/lightningd/json_stream.c @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -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); diff --git a/lightningd/json_stream.h b/lightningd/json_stream.h index 3e7e4f494..f160e0ce7 100644 --- a/lightningd/json_stream.h +++ b/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. diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index 3cce8a3c4..bcddf8477 100644 --- a/lightningd/jsonrpc.c +++ b/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 diff --git a/lightningd/jsonrpc.h b/lightningd/jsonrpc.h index 55d3dbf66..76a09a16c 100644 --- a/lightningd/jsonrpc.h +++ b/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); diff --git a/lightningd/plugin.c b/lightningd/plugin.c index affb27507..4c9258bd4 100644 --- a/lightningd/plugin.c +++ b/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"); diff --git a/lightningd/plugin_hook.c b/lightningd/plugin_hook.c index cefea2365..0a5975386 100644 --- a/lightningd/plugin_hook.c +++ b/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; diff --git a/lightningd/test/run-jsonrpc.c b/lightningd/test/run-jsonrpc.c index 28a7141d9..6ebe3e8e4 100644 --- a/lightningd/test/run-jsonrpc.c +++ b/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;