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")