CI Flake `test_funding_cancel_race`

[ddustin]

Server delay from receiving WIRE_OPEN_CHANNEL, activating connectd takes 11068msec which triggers BROKEN message for taking too long.

(CI Log)

Relevant portion of log:

lightningd-6 2026-06-30T18:07:40.211Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-connectd: Activating for message WIRE_OPEN_CHANNEL
lightningd-20 2026-06-30T18:07:40.925Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-18 2026-06-30T18:07:41.387Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-21 2026-06-30T18:07:41.668Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-8 2026-06-30T18:07:41.961Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-17 2026-06-30T18:07:41.978Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-15 2026-06-30T18:07:42.137Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-13 2026-06-30T18:07:42.294Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-14 2026-06-30T18:07:42.479Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-16 2026-06-30T18:07:42.695Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-19 2026-06-30T18:07:42.723Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-7 2026-06-30T18:07:42.940Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-11 2026-06-30T18:07:43.173Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-9 2026-06-30T18:07:43.484Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-10 2026-06-30T18:07:43.523Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-12 2026-06-30T18:07:43.988Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-20 2026-06-30T18:07:45.926Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-18 2026-06-30T18:07:46.388Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-21 2026-06-30T18:07:46.722Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-17 2026-06-30T18:07:46.982Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-8 2026-06-30T18:07:47.032Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-15 2026-06-30T18:07:47.276Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-13 2026-06-30T18:07:47.294Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-14 2026-06-30T18:07:47.690Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-16 2026-06-30T18:07:47.738Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-19 2026-06-30T18:07:47.740Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-7 2026-06-30T18:07:47.825Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-11 2026-06-30T18:07:48.178Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-9 2026-06-30T18:07:48.526Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-10 2026-06-30T18:07:48.573Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-12 2026-06-30T18:07:49.076Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-6 2026-06-30T18:07:50.978Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-openingd-chan#1: pid 49751, msgfd 91
lightningd-20 2026-06-30T18:07:51.170Z DEBUG   gossipd: seeker: no peers, waiting
lightningd-6 2026-06-30T18:07:51.225Z DEBUG   hsmd: Client: Received message 30 from client
lightningd-6 2026-06-30T18:07:51.277Z DEBUG   hsmd: Client: Received message 10 from client
lightningd-6 2026-06-30T18:07:51.278Z DEBUG   hsmd: new_client: 1
lightningd-6 2026-06-30T18:07:51.278Z **BROKEN** 038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-connectd: wake delay for WIRE_OPEN_CHANNEL: 11068msec

[Amperstrand]

Reproduced deterministically — the flake is not in the funding-cancel
logic but in a dev-only watchdog tripping on scheduler latency.

connectd's write_to_subd() empty-queue branch (multiplex.c:1335-1350)
measures the gap between handing a peer message to the subdaemon queue
and the subdaemon consuming it; past a hardcoded 5000 msec it emits
wake delay for %s BROKEN. That window includes lightningd-master's
time to spawn the subdaemon — in the CI run here
(tests/test_connection.py::test_funding_cancel_race spins up 100 nodes
on a fast runner) the window hit 11068 msec, well past the threshold.

On-demand repro without CI load: SIGSTOP the accepter's lightningd
master before the opener sends open_channel (connectd is a separate
process and stays alive; CLOCK_MONOTONIC keeps running), then SIGCONT —
the BROKEN fires with the frozen window and the framework's
broken-log check fails the run exactly as in CI. 3/3, control arm (no
SIGSTOP) clean.

The class is already acknowledged in-tree: dev_lightningd_is_slow
(connectd.c:2071) exists "so don't complain (and break CI!) if it's
slow" — but it is only settable by the memleak dev-RPC, not by
load-heavy tests.

I have a small branch making the threshold a developer option
(--dev-max-wake-delay-ms, default unchanged, wired through
connectd_init, with a test that freezes the accepter past the default
and expects a clean run with the option raised) — implemented and
validated locally — PR at #9481. Would you rather the measurement
excluded the initial subd-spawn wait? That needs a reliable "subd
ready" signal, which is why I went for the threshold first — happy to
do either. A one-line broken_log regex in the test itself also works
if you prefer keeping the diagnostic untouched.

deterministic repro results (master build, regtest pyln) — expand

run1/C2-repro REPRODUCED (pytest failed on broken log, as in CI)
run2/C2-repro REPRODUCED      run3/C2-repro REPRODUCED
run1..3/C1-control PASS (identical flow, no SIGSTOP)
post-fix cells: 9439/GREEN PASS, 9439/RED PASS (fails without the fix, as designed)
9268/option-b PASS, 9268/in-PR-test PASS

Fuller repro record (trigger recipe, all cells, control arm): https://gist.github.com/Amperstrand/b50c4d604f88016047e104dc65f866c6