lightningd: don't timeout plugins if init is slow!

[rustyrussell]

This is a minimal fix: we wait until all plugins reply from init before continuing. Really large or busy nodes can have other things monopolize lightningd, then the timer goes off and we blame the plugin (which has responded, we just haven't read it yet!).

The real answer is to have some timeouts only advance when we're idle, or have them low-priority so we only activate them when we're idle (this doesn't apply to all timers: some are probably important!). But this is a minimal fix for -rc3.

Fixes: #5736

[vincenzopalazzo]

HACK a418a46

[cdecker]

Thanks Rusty, shepherding through ci and adding it to rc3 👍

[cdecker]

Added changelog entry from #5741

[cdecker]

I'll apply this as is since including it seems safer than not including it, but we have a timeout on valgrind-4:

    def test_important_plugin(node_factory):
        # Cache it here.
        pluginsdir = os.path.join(os.path.dirname(__file__), "plugins")
    
        n = node_factory.get_node(options={"important-plugin": os.path.join(pluginsdir, "nonexistent")},
                                  may_fail=True, expect_fail=True,
                                  allow_broken_log=True, start=False)
    
        n.daemon.start(wait_for_initialized=False, stderr_redir=True)
        # Will exit with failure code.
        assert n.daemon.wait() == 1
        assert n.daemon.is_in_stderr(r"Failed to register .*nonexistent: No such file or directory")
    
        # Check we exit if the important plugin dies.
        n.daemon.opts['important-plugin'] = os.path.join(pluginsdir, "fail_by_itself.py")
    
        n.daemon.start(wait_for_initialized=False)
        # Will exit with failure code.
>       assert n.daemon.wait() == 1

tests/test_plugin.py:2128: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
contrib/pyln-testing/pyln/testing/utils.py:657: in wait
    self.proc.wait(timeout)
/opt/hostedtoolcache/Python/3.7.15/x64/lib/python3.7/subprocess.py:1019: in wait
    return self._wait(timeout=timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <subprocess.Popen object at 0x7efd8b29f150>, timeout = 900

    def _wait(self, timeout):
        """Internal implementation of wait() on POSIX."""
        if self.returncode is not None:
            return self.returncode
    
        if timeout is not None:
            endtime = _time() + timeout
            # Enter a busy loop if we have a timeout.  This busy loop was
            # cribbed from Lib/threading.py in Thread.wait() at r71065.
            delay = 0.0005 # 500 us -> initial delay of 1 ms
            while True:
                if self._waitpid_lock.acquire(False):
                    try:
                        if self.returncode is not None:
                            break  # Another thread waited.
                        (pid, sts) = self._try_wait(os.WNOHANG)
                        assert pid == self.pid or pid == 0
                        if pid == self.pid:
                            self._handle_exitstatus(sts)
                            break
                    finally:
                        self._waitpid_lock.release()
                remaining = self._remaining_time(endtime)
                if remaining <= 0:
>                   raise TimeoutExpired(self.args, timeout)
E                   subprocess.TimeoutExpired: Command '['valgrind', '-q', '--trace-children=yes', '--trace-children-skip=*python*,*bitcoin-cli*,*elements-cli*,*cln-grpc', '--error-exitcode=7', '--log-file=/tmp/ltests-tj13wttf/test_important_plugin_1/lightning-1//valgrind-errors.%p', '--read-inline-info=no', '--suppressions=/home/runner/work/lightning/lightning/tests/valgrind-suppressions.txt', '--gen-suppressions=all', 'lightningd/lightningd', '--log-level=debug', '--cltv-delta=6', '--cltv-final=5', '--watchtime-blocks=5', '--rescan=1', '--disable-dns', '--lightning-dir=/tmp/ltests-tj13wttf/test_important_plugin_1/lightning-1/', '--addr=127.0.0.1:34521', '--allow-deprecated-apis=false', '--network=regtest', '--ignore-fee-limits=false', '--bitcoin-rpcuser=rpcuser', '--bitcoin-rpcpassword=rpcpass', '--bitcoin-datadir=/tmp/ltests-tj13wttf/test_important_plugin_1/lightning-1/', '--dev-fast-gossip', '--dev-bitcoind-poll=1', '--log-file=-', '--log-file=/tmp/ltests-tj13wttf/test_important_plugin_1/lightning-1/log', '--log-prefix=lightningd-1 ', '--dev-fail-on-subdaemon-fail', '--dev-no-version-checks', '--dev-no-plugin-checksum', '--dev-no-reconnect', '--important-plugin=/home/runner/work/lightning/lightning/tests/plugins/fail_by_itself.py', '--bitcoin-rpcport=60953']' timed out after 900 seconds

900 seconds feels way too long for it to be flaky, and the BROKEN error level is emitted early on, so we may end up waiting forever.