lightningd: print UNUSUAL log message if a command is very slow.
What the developer wrote
Authored by Rusty Russell
lightningd: print UNUSUAL log message if a command is very slow.
We don't expect an internal command to take 5 seconds to service
without explicitly pausing: if it does, log at a higher level.
Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
What changed, and why it matters
This change simply adds a warning message to the log file when an internal command takes unusually long (more than 5 seconds). It does not fix a vulnerability, change permissions, or alter how commands are processed. It is a diagnostic/monitoring improvement.
No security action required. Treat as a normal observability/logging improvement.
Security signals we found
No strong security signals were identified.
Evidence from the diff
The commit modifies the JSON-RPC command parsing loop in lightningd/jsonrpc.c to log an UNUSUAL-level message once per run if processing a single batch of commands exceeds 5000 ms. It also updates a test to suppress the expected warning for a known-slow fundpsbt call. No functional behavior of command handling changes.
Changed components
lightningd/jsonrpc.ctests/test_plugin.pyInspect captured patch +13 / −5
diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c
index 27d7efb3..7240fdc9 100644
--- a/lightningd/jsonrpc.c
+++ b/lightningd/jsonrpc.c
@@ -1186,6 +1186,7 @@ static struct io_plan *read_json(struct io_conn *conn,
const char *buffer, *error;
size_t num_parsed = 0;
const char *last_method = NULL;
+ u64 msec;
buffer = jsonrpc_newly_read(jcon->json_in, &len_read);
if (len_read)
@@ -1217,14 +1218,20 @@ again:
/* Don't ever process for more than 100 commands or 250 msec
* without giving others a chance */
- if (num_parsed++ == 100
- || time_greater(timemono_between(time_mono(), start_time),
- time_from_msec(250))) {
+ msec = time_to_msec(timemono_between(time_mono(), start_time));
+ if (num_parsed++ == 100 || msec > 250) {
+ static bool printed_once = false;
db_commit_transaction(jcon->ld->wallet->db);
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)),
+ msec,
last_method ? last_method : "NONE");
+ if (msec > 5000 && last_method && !printed_once) {
+ log_unusual(jcon->log,
+ CI_UNEXPECTED "Request %s took %"PRIu64" milliseconds",
+ last_method, msec);
+ printed_once = true;
+ }
/* Call us back, as if we read nothing new */
return io_always(conn, read_json, jcon);
}
diff --git a/tests/test_plugin.py b/tests/test_plugin.py
index a036ecc2..3ca02c0a 100644
--- a/tests/test_plugin.py
+++ b/tests/test_plugin.py
@@ -1903,7 +1903,8 @@ def test_bitcoin_backend(node_factory, bitcoind):
def test_bitcoin_backend_gianttx(node_factory, bitcoind):
"""Test that a giant tx doesn't crash bcli"""
- l1 = node_factory.get_node(start=False)
+ # This complains about how long fundpsbt took.
+ l1 = node_factory.get_node(start=False, broken_log='Request fundpsbt took')
# With memleak we spend far too much time gathering backtraces.
if "LIGHTNINGD_DEV_MEMLEAK" in l1.daemon.env:
del l1.daemon.env["LIGHTNINGD_DEV_MEMLEAK"]
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.