From 2b0d2a4f8df1527729a5679e78bff425f480c760 Mon Sep 17 00:00:00 2001 From: Amperstrand Date: Sat, 5 Sep 2026 21:53:16 +0200 Subject: [PATCH] connectd: add --dev-max-wake-delay-ms The wake-delay watchdog (write_to_subd's empty-queue check) measures the gap between handing a peer message to the subdaemon queue and the subdaemon consuming it, which includes lightningd-master's time to spawn the subdaemon: under CI load that alone can exceed the hardcoded 5000 msec and fail runs with 'wake delay for WIRE_OPEN_CHANNEL' BROKEN (ElementsProject/lightning#9268) -- tests/test_connection.py:: test_funding_cancel_race spins up 100 nodes and hit a 11068 msec window. dev_lightningd_is_slow exists for the same class but is only settable by the memleak dev-RPC. Make the threshold a developer option (default unchanged at 5000) so load-heavy tests can raise it; wired through connectd_init. The regression test freezes the accepter's master past the default threshold and expects a clean run with the option raised. Changelog-Fixes: #9268 --- connectd/connectd.c | 4 +++- connectd/connectd.h | 1 + connectd/connectd_wire.csv | 1 + connectd/multiplex.c | 3 ++- lightningd/connect_control.c | 3 ++- lightningd/lightningd.c | 1 + lightningd/lightningd.h | 1 + lightningd/options.c | 6 ++++++ tests/test_connection.py | 25 +++++++++++++++++++++++++ 9 files changed, 42 insertions(+), 3 deletions(-) diff --git a/connectd/connectd.c b/connectd/connectd.c index cb95ef9b0cac..31b13c79c5fc 100644 --- a/connectd/connectd.c +++ b/connectd/connectd.c @@ -1717,7 +1717,8 @@ static void connect_init(struct daemon *daemon, const u8 *msg) &daemon->dev_no_reconnect, &daemon->dev_fast_reconnect, &dev_limit_connections_inflight, - &daemon->dev_keep_nagle)) { + &daemon->dev_keep_nagle, + &daemon->dev_max_wake_delay_ms)) { /* This is a helper which prints the type expected and the actual * message, then exits (it should never be called!). */ master_badmsg(WIRE_CONNECTD_INIT, msg); @@ -2552,6 +2553,7 @@ int main(int argc, char *argv[]) daemon->custom_msgs = NULL; daemon->dev_exhausted_fds = false; daemon->dev_lightningd_is_slow = false; + daemon->dev_max_wake_delay_ms = 5000; daemon->dev_keep_nagle = false; /* We generally allow 1MB per second per peer, except for dev testing */ daemon->gossip_stream_limit = 1000000; diff --git a/connectd/connectd.h b/connectd/connectd.h index 11665cc2440d..93cd4d840583 100644 --- a/connectd/connectd.h +++ b/connectd/connectd.h @@ -388,6 +388,7 @@ struct daemon { bool dev_fast_reconnect; /* Don't complain about lightningd being unresponsive. */ bool dev_lightningd_is_slow; + u64 dev_max_wake_delay_ms; /* Don't set TCP_NODELAY */ bool dev_keep_nagle; }; diff --git a/connectd/connectd_wire.csv b/connectd/connectd_wire.csv index c1361a597556..1505550f88a5 100644 --- a/connectd/connectd_wire.csv +++ b/connectd/connectd_wire.csv @@ -231,3 +231,4 @@ msgdata,connectd_onionmsg_forward_fail,path_key,pubkey, msgdata,connectd_onionmsg_forward_fail,outgoing_len,u16, msgdata,connectd_onionmsg_forward_fail,outgoing,u8,outgoing_len, msgdata,connectd_onionmsg_forward_fail,next_node,?sciddir_or_pubkey, +msgdata,connectd_init,dev_max_wake_delay_ms,u64, diff --git a/connectd/multiplex.c b/connectd/multiplex.c index 1051645f8cec..c1e92a05aef4 100644 --- a/connectd/multiplex.c +++ b/connectd/multiplex.c @@ -1342,7 +1342,8 @@ static struct io_plan *write_to_subd(struct io_conn *subd_conn, if (subd->peer->peer_in_lastmsg != -1) { u64 msec = time_to_msec(timemono_between(time_mono(), subd->peer->peer_in_lasttime)); - if (msec > 5000 && !subd->peer->daemon->dev_lightningd_is_slow) + if (msec > subd->peer->daemon->dev_max_wake_delay_ms + && !subd->peer->daemon->dev_lightningd_is_slow) status_peer_broken(&subd->peer->id, "wake delay for %s: %"PRIu64"msec", peer_wire_name(subd->peer->peer_in_lastmsg), diff --git a/lightningd/connect_control.c b/lightningd/connect_control.c index 9c8afa9676a9..d755cc0184c8 100644 --- a/lightningd/connect_control.c +++ b/lightningd/connect_control.c @@ -728,7 +728,8 @@ int connectd_init(struct lightningd *ld) !ld->reconnect, ld->dev_fast_reconnect, ld->dev_limit_connections_inflight, - ld->dev_keep_nagle); + ld->dev_keep_nagle, + ld->dev_max_wake_delay_ms); subd_req(ld->connectd, ld->connectd, take(msg), -1, 0, connect_init_done, NULL); diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index 44ed3fa66425..8db48b17d7fd 100644 --- a/lightningd/lightningd.c +++ b/lightningd/lightningd.c @@ -138,6 +138,7 @@ static struct lightningd *new_lightningd(const tal_t *ctx) ld->dev_force_tmp_channel_id = NULL; ld->dev_no_htlc_timeout = false; ld->dev_no_version_checks = false; + ld->dev_max_wake_delay_ms = 5000; ld->dev_max_funding_unconfirmed = 2016; ld->dev_low_prio_anchor_blocks = 2016; ld->dev_ignore_modern_onion = false; diff --git a/lightningd/lightningd.h b/lightningd/lightningd.h index 6d778c929e95..8536629e63cc 100644 --- a/lightningd/lightningd.h +++ b/lightningd/lightningd.h @@ -314,6 +314,7 @@ struct lightningd { bool dev_fast_gossip; bool dev_fast_gossip_prune; bool dev_throttle_gossip; + u64 dev_max_wake_delay_ms; bool dev_suppress_gossip; /* How long to aim for low-priority commitment closes */ diff --git a/lightningd/options.c b/lightningd/options.c index 42ee3a6e43f3..9f8e3b697f75 100644 --- a/lightningd/options.c +++ b/lightningd/options.c @@ -924,6 +924,12 @@ static void dev_register_opts(struct lightningd *ld) opt_set_bool, &ld->dev_throttle_gossip, "Throttle gossip right down, for testing"); + clnopt_witharg("--dev-max-wake-delay-ms", OPT_DEV|OPT_SHOWINT, + opt_set_u64, opt_show_u64, + &ld->dev_max_wake_delay_ms, + "Maximum msec a peer message may wait for its subdaemon " + "to wake before connectd logs BROKEN (default 5000); " + "raise for load-heavy tests (ElementsProject/lightning#9268)"); clnopt_noarg("--dev-limit-connections-inflight", OPT_DEV, opt_set_bool, &ld->dev_limit_connections_inflight, diff --git a/tests/test_connection.py b/tests/test_connection.py index 4b07bda708c9..6949cadb90ba 100644 --- a/tests/test_connection.py +++ b/tests/test_connection.py @@ -5136,3 +5136,28 @@ def test_open_channel_funding_above_max_supply(node_factory, bitcoind): funding_sat, push_msat) assert l1.rpc.getinfo()['id'] == l1.info['id'] + + +def test_dev_max_wake_delay(node_factory, executor, bitcoind): + """connectd's wake-delay watchdog measures master scheduling latency + too; under heavy CI load the subdaemon spawn alone can exceed the + 5s default (ElementsProject/lightning#9268). --dev-max-wake-delay-ms + lets load-heavy tests raise the threshold: the same freeze that + fires BROKEN by default passes cleanly with it raised.""" + l2 = node_factory.get_node(options={'dev-max-wake-delay-ms': 60000}) + l1 = node_factory.get_node() + addr = l1.rpc.newaddr('bech32')['bech32'] + bitcoind.rpc.sendtoaddress(addr, 200000 / 10**8) + bitcoind.generate_block(1) + wait_for(lambda: len(l1.rpc.listfunds()["outputs"]) != 0) + + l1.rpc.connect(l2.info['id'], 'localhost', l2.port) + # Freeze the accepter's master so openingd's spawn is delayed + # beyond the default threshold; the raised threshold must absorb it. + os.kill(l2.daemon.proc.pid, signal.SIGSTOP) + fut = executor.submit(l1.rpc.fundchannel_start, l2.info['id'], "100000sat") + time.sleep(7) + os.kill(l2.daemon.proc.pid, signal.SIGCONT) + fut.result(TIMEOUT) + time.sleep(5) + assert not l2.daemon.is_in_log(r"wake delay for WIRE_OPEN_CHANNEL")