connectd: add --dev-max-wake-delay-ms

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;

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;
  };

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,

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

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

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;

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 */

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,

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