lightningd: print last method we called if we abort processing loop.
What the developer wrote
Authored by Rusty Russell
lightningd: print last method we called if we abort processing loop.
We are seeing this in the CI logs, eg tests/test_connection.py::test_reconnect_sender_add1:
lightningd-1 2025-11-17T05:48:00.665Z DEBUG jsonrpc#84: Pausing parsing after 1 requests
followed by:
lightningd-1 2025-11-17T05:48:02.068Z **BROKEN** 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: wake delay for WIRE_CHANNEL_REESTABLISH: 8512msec
So, what is consuming lightningd for 8 or so seconds?
This message helped diagnose that the issue was dev-memleak: fixed in a different branch.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
What changed, and why it matters
This commit only adds extra debugging information to a log message. When the lightning daemon pauses processing JSON-RPC commands, it now records the name of the last command it handled and how long it spent. There is no security fix or behavior change.
No security action needed; treat as a normal diagnostic/logging improvement.
Security signals we found
No strong security signals were identified.
Evidence from the diff
The change modifies lightningd/jsonrpc.c so that parse_request() returns the command name via an out-parameter, and read_json() logs that name plus elapsed milliseconds when the parsing loop pauses after 100 commands or 250 ms. It is a diagnostic improvement to help identify slow RPC handling, not a vulnerability patch.
Changed components
lightningd/jsonrpc.cInspect captured patch +9 / −3
diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c
index 68b07124..27d7efb3 100644
--- a/lightningd/jsonrpc.c
+++ b/lightningd/jsonrpc.c
@@ -1006,7 +1006,8 @@ REGISTER_PLUGIN_HOOK_STRFILTER(rpc_command,
static struct command_result *
parse_request(struct json_connection *jcon,
const char *buffer,
- const jsmntok_t tok[])
+ const jsmntok_t tok[],
+ const char **methodname)
{
const jsmntok_t *method, *id, *params, *filter, *jsonrpc;
struct command *c;
@@ -1114,6 +1115,7 @@ parse_request(struct json_connection *jcon,
rpc_hook->custom_replace = NULL;
rpc_hook->custom_buffer = NULL;
+ *methodname = c->json_cmd->name;
trace_span_start("lightningd/jsonrpc", &c);
trace_span_tag(&c, "method", c->json_cmd->name);
/* They can filter by command name */
@@ -1183,6 +1185,7 @@ static struct io_plan *read_json(struct io_conn *conn,
const jsmntok_t *toks;
const char *buffer, *error;
size_t num_parsed = 0;
+ const char *last_method = NULL;
buffer = jsonrpc_newly_read(jcon->json_in, &len_read);
if (len_read)
@@ -1209,7 +1212,7 @@ again:
db_begin_transaction(jcon->ld->wallet->db);
in_transaction = true;
}
- parse_request(jcon, buffer, toks);
+ parse_request(jcon, buffer, toks, &last_method);
jsonrpc_io_parse_done(jcon->json_in);
/* Don't ever process for more than 100 commands or 250 msec
@@ -1218,7 +1221,10 @@ again:
|| time_greater(timemono_between(time_mono(), start_time),
time_from_msec(250))) {
db_commit_transaction(jcon->ld->wallet->db);
- log_debug(jcon->log, "Pausing parsing after %zu requests", num_parsed);
+ log_debug(jcon->log, "Pausing parsing after %zu requests and %"PRIu64"msec (last method=%s)",
+ num_parsed,
+ time_to_msec(timemono_between(time_mono(), start_time)),
+ last_method ? last_method : "NONE");
/* Call us back, as if we read nothing new */
return io_always(conn, read_json, jcon);
}
Why this scored 15/100
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.