From ef33dd29983cc97cced0cf040708683e23871ac8 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Fri, 27 Jul 2018 06:49:37 +0930 Subject: [PATCH] jsonrpc: reduce debug log spam for JSON commands. Just log the failed ones, not every connection and successful commands. Before (VALGRIND=0 -n10): 111 passed, 1 skipped in 175.78 seconds After: 111 passed, 1 skipped in 173.92 seconds 111 passed, 1 skipped in 164.16 seconds 111 passed, 1 skipped in 171.30 seconds 111 passed, 1 skipped in 180.05 seconds 111 passed, 1 skipped in 180.04 seconds Signed-off-by: Rusty Russell --- lightningd/jsonrpc.c | 20 ++++++++++---------- lightningd/jsonrpc.h | 2 ++ 2 files changed, 12 insertions(+), 10 deletions(-) diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index a89516554..cecc8d1cc 100644 --- a/lightningd/jsonrpc.c +++ b/lightningd/jsonrpc.c @@ -360,7 +360,6 @@ void command_success(struct command *cmd, struct json_result *result) } assert(cmd_in_jcon(jcon, cmd)); connection_complete_ok(jcon, cmd, cmd->id, result); - log_debug(jcon->log, "Success"); } static void command_fail_v(struct command *cmd, @@ -373,14 +372,18 @@ static void command_fail_v(struct command *cmd, if (!jcon) { log_debug(cmd->ld->log, - "Command failed after jcon close"); + "%s: Command failed after jcon close", + cmd->json_cmd->name); tal_free(cmd); return; } error = tal_vfmt(cmd, fmt, ap); - log_debug(jcon->log, "Failing: %s", error); + /* cmd->json_cmd can be NULL, if we're failing for command not found! */ + log_debug(jcon->log, "Failing %s: %s", + cmd->json_cmd ? cmd->json_cmd->name : "invalid cmd", + error); assert(cmd_in_jcon(jcon, cmd)); connection_complete_error(jcon, cmd, cmd->id, error, code, data); @@ -422,7 +425,6 @@ static void json_command_malformed(struct json_connection *jcon, static void parse_request(struct json_connection *jcon, const jsmntok_t tok[]) { const jsmntok_t *method, *id, *params; - const struct json_command *cmd; struct command *c; if (tok[0].type != JSMN_OBJECT) { @@ -469,15 +471,15 @@ static void parse_request(struct json_connection *jcon, const jsmntok_t tok[]) return; } - cmd = find_cmd(jcon->buffer, method); - if (!cmd) { + c->json_cmd = find_cmd(jcon->buffer, method); + if (!c->json_cmd) { command_fail(c, JSONRPC2_METHOD_NOT_FOUND, "Unknown command '%.*s'", method->end - method->start, jcon->buffer + method->start); return; } - if (cmd->deprecated && !deprecated_apis) { + if (c->json_cmd->deprecated && !deprecated_apis) { command_fail(c, JSONRPC2_METHOD_NOT_FOUND, "Command '%.*s' is deprecated", method->end - method->start, @@ -486,7 +488,7 @@ static void parse_request(struct json_connection *jcon, const jsmntok_t tok[]) } db_begin_transaction(jcon->ld->wallet->db); - cmd->dispatch(c, jcon->buffer, params); + c->json_cmd->dispatch(c, jcon->buffer, params); db_commit_transaction(jcon->ld->wallet->db); /* If they didn't complete it, they must call command_still_pending */ @@ -603,8 +605,6 @@ static struct io_plan *jcon_connected(struct io_conn *conn, static struct io_plan *incoming_jcon_connected(struct io_conn *conn, struct lightningd *ld) { - log_debug(ld->log, "Connected json input"); - /* Lifetime of JSON conn is limited to fd connect time. */ return jcon_connected(notleak(conn), ld); } diff --git a/lightningd/jsonrpc.h b/lightningd/jsonrpc.h index 01ece3c3b..eaf12ec40 100644 --- a/lightningd/jsonrpc.h +++ b/lightningd/jsonrpc.h @@ -19,6 +19,8 @@ struct command { struct lightningd *ld; /* The 'id' which we need to include in the response. */ const char *id; + /* What command we're running (for logging) */ + const struct json_command *json_cmd; /* The connection, or NULL if it closed. */ struct json_connection *jcon; /* Have we been marked by command_still_pending? For debugging... */