Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

pytest: more flake fixes #7810

Merged
merged 15 commits into from
Nov 17, 2024

Conversation

rustyrussell
Copy link
Contributor

@rustyrussell rustyrussell commented Nov 13, 2024

Changelog-None

@rustyrussell rustyrussell changed the title pytest: don't try exposesecret test under valgrind. pytest: more flake fixes Nov 13, 2024
@rustyrussell rustyrussell force-pushed the guilt/fix-flakes7 branch 3 times, most recently from e7695e6 to 8f3f776 Compare November 14, 2024 22:43
There's a known issue with hsm passwords and valgrind:

```
        write_all(master_fd, (password + '\n').encode("utf-8"))
>       l1.daemon.wait_for_log("Server started with public key")

tests/test_plugin.py:4526: 
...
                        if self.is_in_log(r):
                            print("({} was previously in logs!)".format(r))
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile('Server started with public key')]" in logs.
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
```
**BROKEN** plugin-spenderp: Lost connection to the RPC socket.
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
valgrind slowed things down so the HTLC was resolved, so we didn't use
an anchor.  Make that case consistent.

```
    def test_onchain_unwatch(node_factory, bitcoind, chainparams):
        """Onchaind should not watch random spends"""
        # We track channel balances, to verify that accounting is ok.
        coin_mvt_plugin = os.path.join(os.getcwd(), 'tests/plugins/coin_movements.py')
        l1, l2 = node_factory.line_graph(2, opts={'plugin': coin_mvt_plugin})
        channel_id = first_channel_id(l1, l2)
    
        l1.pay(l2, 200000000)
    
        l1.rpc.dev_fail(l2.info['id'])
        l1.daemon.wait_for_log('Failing due to dev-fail command')
        l1.wait_for_channel_onchain(l2.info['id'])
    
        # Make sure we see anchor too
>       l1.bitcoin.generate_block(1, wait_for_mempool=2)

tests/test_closing.py:1769: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
contrib/pyln-testing/pyln/testing/utils.py:477: in generate_block
    wait_for(lambda: len(self.rpc.getrawmempool()) >= wait_for_mempool)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

success = <function BitcoinD.generate_block.<locals>.<lambda> at 0x7f23f909c310>
timeout = 180

    def wait_for(success, timeout=TIMEOUT):
        start_time = time.time()
        interval = 0.25
        while not success():
            time_left = start_time + timeout - time.time()
            if time_left <= 0:
>               raise ValueError("Timeout while waiting for {}".format(success))
E               ValueError: Timeout while waiting for <function BitcoinD.generate_block.<locals>.<lambda> at 0x7f23f909c310>
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
…ules.

Because it wasn't in ALL_OBJS.  Copy the Makefile pattern!

```
Submodule 'src/secp256k1' (https://github.com/ElementsProject/secp256k1-zkp.git) registered for path 'external/libwally-core/src/secp256k1'
Cloning into '/home/runner/work/lightning/lightning/external/libwally-core/src/secp256k1'...
cc tests/plugins/channeld_fakenet.c
In file included from ./bitcoin/script.h:4,
                 from tests/plugins/channeld_fakenet.c:14:
./bitcoin/signature.h:6:10: fatal error: secp256k1.h: No such file or directory
    6 | #include <secp256k1.h>
      |          ^~~~~~~~~~~~~
compilation terminated.
make: *** [Makefile:301: tests/plugins/channeld_fakenet.o] Error 1
make: *** Waiting for unfinished jobs....
Submodule path 'external/libwally-core/src/secp256k1': checked out
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Seems like it's using an old version of pyln-client, which had the bug
of referring to long_desc:

```
def test_local_dir_install(node_factory):
        """Test search and install from local directory source."""
        n = get_reckless_node(node_factory)
        n.start()
        r = reckless([f"--network={NETWORK}", "-v", "source", "add",
                      "tests/data/recklessrepo/lightningd/testplugpass"],
                     dir=n.lightning_dir)
        assert r.returncode == 0
        r = reckless([f"--network={NETWORK}", "-v", "install", "testplugpass"], dir=n.lightning_dir)
        assert r.returncode == 0
>       assert 'testplugpass enabled' in r.stdout
E       assert 'testplugpass enabled' in '[2024-11-14 06:47:12,999] DEBUG: Searching for testplugpass\nfound testplugpass in source: tests/data/recklessrepo/lightningd/testplugpass\n[2024-11-14 06:47:13,031] DEBUG: entry: testplugpass.py\n[2024-11-14 06:47:13,031] DEBUG: Retrieving testplugpass from tests/data/recklessrepo/lightningd/testplugpass\n[2024-11-14 06:47:13,032] DEBUG: Install requested from InstInfo(testplugpass, tests/data/recklessrepo/lightningd/testplugpass, None, testplugpass.py, requirements.txt, None).\n[2024-11-14 06:47:13,032] DEBUG: copying local directory contents from tests/data/recklessrepo/lightningd/testplugpass\n[2024-11-14 06:47:13,038] DEBUG: cloned_src: InstInfo(testplugpass, /tmp/reckless-0721411112afw6ng7/clone, None, testplugpass.py, requirements.txt, testplugpass)\n[2024-11-14 06:47:13,038] DEBUG: using installer python3venv\n[2024-11-14 06:47:13,038] DEBUG: creating /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass\n[2024-11-14 06:47:13,038] DEBUG: creating /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/source\n[2024-11-14 06:47:13,038] DEBUG: copying /tmp/reckless-0721411112afw6ng7/clone/testplugpass tree to /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/source/testplugpass\n[2024-11-14 06:47:13,039] DEBUG: linking source /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/source/testplugpass/testplugpass.py to /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/testplugpass.py\n[2024-11-14 06:47:13,039] DEBUG: InstInfo(testplugpass, /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass, None, testplugpass.py, requirements.txt, source/testplugpass)\n[2024-11-14 06:47:20,508] DEBUG: configuring a python virtual environment (pip) in /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/.venv\n[2024-11-14 06:47:20,508] DEBUG: virtual environment created in /tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/.venv.\nCollecting pyln-client\n  Using cached pyln_client-24.8.2-py3-none-any.whl (35 kB)\nCollecting pyln-proto>=23\n  Using cached pyln_proto-24.8.2-py3-none-any.whl (31 kB)\nCollecting pyln-bolt7>=1.0\n  Using cached pyln_bolt7-1.0.246-py3-none-any.whl (18 kB)\nCollecting base58<3.0.0,>=2.1.1\n  Using cached base58-2.1.1-py3-none-any.whl (5.6 kB)\nCollecting cryptography<43,>=42\n  Using cached cryptography-42.0.8-cp37-abi3-manylinux_2_28_x86_64.whl (3.9 MB)\nCollecting bitstring<5.0.0,>=4.1.0\n  Using cached bitstring-4.2.3-py3-none-any.whl (71 kB)\nCollecting coincurve<21,>=20\n  Using cached coincurve-20.0.0-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (1.2 MB)\nCollecting PySocks<2,>=1\n  Using cached PySocks-1.7.1-py3-none-any.whl (16 kB)\nCollecting bitarray<3.0.0,>=2.9.0\n  Using cached bitarray-2.9.3-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (288 kB)\nCollecting cffi>=1.3.0\n  Using cached cffi-1.17.1-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (446 kB)\nCollecting asn1crypto\n  Using cached asn1crypto-1.5.1-py2.py3-none-any.whl (105 kB)\nCollecting pycparser\n  Using cached pycparser-2.22-py3-none-any.whl (117 kB)\nInstalling collected packages: bitarray, asn1crypto, PySocks, pyln-bolt7, pycparser, bitstring, base58, cffi, cryptography, coincurve, pyln-proto, pyln-client\nSuccessfully installed PySocks-1.7.1 asn1crypto-1.5.1 base58-2.1.1 bitarray-2.9.3 bitstring-4.2.3 cffi-1.17.1 coincurve-20.0.0 cryptography-42.0.8 pycparser-2.22 pyln-bolt7-1.0.246 pyln-client-24.8.2 pyln-proto-24.8.2\ndependencies installed successfully\n[2024-11-14 06:47:37,424] DEBUG: virtual environment for cloned plugin: .venv\n[2024-11-14 06:47:37,746] DEBUG: plugin testing error:\n[2024-11-14 06:47:37,746] DEBUG:   Traceback (most recent call last):\n[2024-11-14 06:47:37,746] DEBUG:     File "/tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/testplugpass.py", line 9, in <module>\n[2024-11-14 06:47:37,746] DEBUG:       runpy.run_module("testplugpass", {}, "__main__")\n[2024-11-14 06:47:37,746] DEBUG:     File "/opt/hostedtoolcache/Python/3.8.18/x64/lib/python3.8/runpy.py", line 210, in run_module\n[2024-11-14 06:47:37,746] DEBUG:       return _run_code(code, {}, init_globals, run_name, mod_spec)\n[2024-11-14 06:47:37,746] DEBUG:     File "/opt/hostedtoolcache/Python/3.8.18/x64/lib/python3.8/runpy.py", line 87, in _run_code\n[2024-11-14 06:47:37,746] DEBUG:       exec(code, run_globals)\n[2024-11-14 06:47:37,746] DEBUG:     File "/tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/source/testplugpass/testplugpass.py", line 25, in <module>\n[2024-11-14 06:47:37,746] DEBUG:       plugin.run()\n[2024-11-14 06:47:37,746] DEBUG:     File "/tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/.venv/lib/python3.8/site-packages/pyln/client/plugin.py", line 877, in run\n[2024-11-14 06:47:37,747] DEBUG:       return self.print_usage()\n[2024-11-14 06:47:37,747] DEBUG:     File "/tmp/ltests-chy6ayqu/test_local_dir_install_2/lightning-1/reckless/testplugpass/.venv/lib/python3.8/site-packages/pyln/client/plugin.py", line 831, in print_usage\n[2024-11-14 06:47:37,747] DEBUG:       doc = method.long_desc if method.long_desc is not None else "No documentation found"\n[2024-11-14 06:47:37,747] DEBUG:   AttributeError: \'Method\' object has no attribute \'long_desc\'\n[2024-11-14 06:47:37,747] ERROR: plugin testing failed\n[2024-11-14 06:47:37,937] WARNING: testplugpass: installation aborted\n'
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
```
2024-11-14T23:50:43.8609029Z test_real_data failed (1 runs remaining out of 2).
2024-11-14T23:50:43.8609157Z 	<class 'Failed'>
2024-11-14T23:50:43.8609244Z 	Timeout >1200.0s
...
2024-11-14T23:50:43.8629292Z test_real_biases failed (1 runs remaining out of 2).
2024-11-14T23:50:43.8629407Z 	<class 'Failed'>
2024-11-14T23:50:43.8629494Z 	Timeout >1200.0s
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
```
        # reply_channel_range == 264
>       assert msgs == ['0108'
                        # blockhash
                        + genesis_blockhash
                        # first_blocknum, number_of_blocks, complete
                        + format(0, '08x') + format(1000000, '08x') + '01'
                        # encoded_short_ids
                        + format(len(encoded) // 2, '04x')
                        + encoded]
E       AssertionError: assert ['010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006900000100000000680000010000'] == ['010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006800000100000000690000010000']
E         At index 0 diff: '010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006900000100000000680000010000' != '010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006800000100000000690000010000'
E         Full diff:
E         - ['010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006800000100000000690000010000']
E         ?                                                                                                    ^               ^
E         + ['010806226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f00000000000f42400100110000006900000100000000680000010000']
E         ?                                                                                                    ^               ^
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
```
>       wss = BindWebSecureSocket('localhost', wss_port)

tests/test_connection.py:4584: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
tests/test_connection.py:4570: in __init__
    self.ws.connect("wss://" + hostname + ":" + str(port))
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/websocket/_core.py:256: in connect
    self.sock, addrs = connect(
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/websocket/_http.py:145: in connect
    sock = _open_socket(addrinfo_list, options.sockopt, options.timeout)
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/websocket/_http.py:232: in _open_socket
    raise err
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

addrinfo_list = [(<AddressFamily.AF_INET6: 10>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('::1', 45521, 0, 0)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 45521))]
sockopt = [], timeout = None

    def _open_socket(addrinfo_list, sockopt, timeout):
        err = None
        for addrinfo in addrinfo_list:
            family, socktype, proto = addrinfo[:3]
            sock = socket.socket(family, socktype, proto)
            sock.settimeout(timeout)
            for opts in DEFAULT_SOCKET_OPTION:
                sock.setsockopt(*opts)
            for opts in sockopt:
                sock.setsockopt(*opts)
    
            address = addrinfo[4]
            err = None
            while not err:
                try:
>                   sock.connect(address)
E                   ConnectionRefusedError: [Errno 111] Connection refused
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
…own.

```
lightningd-1 2024-11-15T04:06:47.660Z UNUSUAL lightningd: JSON-RPC shutdown
lightningd-1 2024-11-15T04:06:47.665Z DEBUG   lightningd: io_break: start_json_stream
lightningd-1 2024-11-15T04:06:47.666Z DEBUG   lightningd: io_loop_with_timers: main
lightningd-1 2024-11-15T04:06:47.672Z DEBUG   connectd: REPLY WIRE_CONNECTD_START_SHUTDOWN_REPLY with 0 fds
lightningd-1 2024-11-15T04:06:47.674Z DEBUG   lightningd: io_break: connectd_start_shutdown_reply
lightningd-1 2024-11-15T04:06:47.680Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Status closed, but not exited. Killing
lightningd-1 2024-11-15T04:06:47.715Z **BROKEN** lightningd: FATAL SIGNAL 11 (version e627dbf-modded)
------------------------------- Valgrind errors --------------------------------
Valgrind error file: valgrind-errors.43310
==43310== Invalid read of size 8
==43310==    at 0x1B5717: subd_send_msg (subd.c:842)
==43310==    by 0x17563A: onchain_tx_depth (onchain_control.c:177)
==43310==    by 0x175E92: replay_block (onchain_control.c:391)
==43310==    by 0x12E30C: getrawblockbyheight_callback (bitcoind.c:506)
==43310==    by 0x1A5AC0: plugin_response_handle (plugin.c:663)
==43310==    by 0x1A5D3C: plugin_read_json_one (plugin.c:775)
==43310==    by 0x1A5F79: plugin_read_json (plugin.c:826)
==43310==    by 0x38F320: next_plan (io.c:60)
==43310==    by 0x38FF76: do_plan (io.c:422)
==43310==    by 0x38FFDD: io_ready (io.c:439)
==43310==    by 0x392411: io_loop (poll.c:455)
==43310==    by 0x1AB630: shutdown_plugins (plugin.c:2588)
==43310==  Address 0x58 is not stack'd, malloc'd or (recently) free'd
==43310== 
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Since wait_for_onchaind_tx doesn't actually wait for the call to bitcoind to
return, we have a race in checking if the txid is in the mempool.  Fix this
by making wait_for_onchaind_tx actually wait for the response (except for delayed txs!).

```
2024-11-15T07:15:22.0836959Z     def test_htlc_in_timeout(node_factory, bitcoind, executor):
2024-11-15T07:15:22.0837722Z         """Test that we drop onchain if the peer doesn't accept fulfilled HTLC"""
2024-11-15T07:15:22.0838208Z     
2024-11-15T07:15:22.0838585Z         # HTLC 1->2, 1 fails after 2 has sent committed the fulfill
2024-11-15T07:15:22.0839137Z         disconnects = ['-WIRE_REVOKE_AND_ACK*2']
2024-11-15T07:15:22.0839741Z         # Feerates identical so we don't get gratuitous commit to update them
2024-11-15T07:15:22.0840304Z         l1 = node_factory.get_node(disconnect=disconnects,
2024-11-15T07:15:22.0840839Z                                    options={'dev-no-reconnect': None},
2024-11-15T07:15:22.0841285Z                                    feerates=(7500, 7500, 7500, 7500))
2024-11-15T07:15:22.0841673Z         l2 = node_factory.get_node()
2024-11-15T07:15:22.0842278Z         # Give it some sats for anchor spend!
2024-11-15T07:15:22.0842679Z         l2.fundwallet(25000, mine_block=False)
2024-11-15T07:15:22.0843013Z     
2024-11-15T07:15:22.0843342Z         l1.rpc.connect(l2.info['id'], 'localhost', l2.port)
2024-11-15T07:15:22.0843753Z         chanid, _ = l1.fundchannel(l2, 10**6)
2024-11-15T07:15:22.0844058Z     
2024-11-15T07:15:22.0844291Z         sync_blockheight(bitcoind, [l1, l2])
2024-11-15T07:15:22.0844606Z     
2024-11-15T07:15:22.0844958Z         amt = 200000000
2024-11-15T07:15:22.0845713Z         inv = l2.rpc.invoice(amt, 'test_htlc_in_timeout', 'desc')['bolt11']
2024-11-15T07:15:22.0846612Z         assert only_one(l2.rpc.listinvoices('test_htlc_in_timeout')['invoices'])['status'] == 'unpaid'
2024-11-15T07:15:22.0847141Z     
2024-11-15T07:15:22.0847430Z         executor.submit(l1.dev_pay, inv, dev_use_shadow=False)
2024-11-15T07:15:22.0847805Z     
2024-11-15T07:15:22.0848041Z         # l1 will disconnect and not reconnect.
2024-11-15T07:15:22.0848660Z         l1.daemon.wait_for_log('dev_disconnect: -WIRE_REVOKE_AND_ACK')
2024-11-15T07:15:22.0850393Z     
2024-11-15T07:15:22.0851297Z         # Deadline HTLC expiry minus 1/2 cltv-expiry delta (rounded up) (== cltv - 3).  cltv is 5+1.
2024-11-15T07:15:22.0852146Z         # shadow route can add extra blocks!
2024-11-15T07:15:22.0852622Z         status = only_one(l1.rpc.call('paystatus')['pay'])
2024-11-15T07:15:22.0853044Z         if 'shadow' in status:
2024-11-15T07:15:22.0853861Z             shadowlen = 6 * status['shadow'].count('Added 6 cltv delay for shadow')
2024-11-15T07:15:22.0854325Z         else:
2024-11-15T07:15:22.0854547Z             shadowlen = 0
2024-11-15T07:15:22.0854845Z         bitcoind.generate_block(2 + shadowlen)
2024-11-15T07:15:22.0855292Z         assert not l2.daemon.is_in_log('hit deadline')
2024-11-15T07:15:22.0855669Z         bitcoind.generate_block(1)
2024-11-15T07:15:22.0855950Z     
2024-11-15T07:15:22.0856406Z         l2.daemon.wait_for_log('Fulfilled HTLC 0 SENT_REMOVE_COMMIT cltv .* hit deadline')
2024-11-15T07:15:22.0856997Z         l2.daemon.wait_for_log('sendrawtx exit 0')
2024-11-15T07:15:22.0857360Z         l2.bitcoin.generate_block(1)
2024-11-15T07:15:22.0857741Z         l2.daemon.wait_for_log(' to ONCHAIN')
2024-11-15T07:15:22.0858137Z         l1.daemon.wait_for_log(' to ONCHAIN')
2024-11-15T07:15:22.0858644Z     
2024-11-15T07:15:22.0859068Z         # L2 will collect HTLC (iff no shadow route)
2024-11-15T07:15:22.0859741Z         _, txid, blocks = l2.wait_for_onchaind_tx('OUR_HTLC_SUCCESS_TX',
2024-11-15T07:15:22.0860287Z                                                   'OUR_UNILATERAL/THEIR_HTLC')
2024-11-15T07:15:22.0860662Z         assert blocks == 0
2024-11-15T07:15:22.0860908Z     
2024-11-15T07:15:22.0861262Z         # If we try to reuse the same output as we used for the anchor spend, then
2024-11-15T07:15:22.0861951Z         # bitcoind can reject it.  In that case we'll try again after we get change
2024-11-15T07:15:22.0862433Z         # from anchor spend.
2024-11-15T07:15:22.0862768Z         if txid not in bitcoind.rpc.getrawmempool():
2024-11-15T07:15:22.0863354Z             bitcoind.generate_block(1)
2024-11-15T07:15:22.0863735Z >           bitcoind.generate_block(1, wait_for_mempool=1)
2024-11-15T07:15:22.0864019Z 
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Looking at the logs (and comparing a successful run), it seems the connect happens before
the connect_stream is ready, so we miss it:

```
________________________ test_grpc_connect_notification ________________________
[gw7] linux -- Python 3.8.18 /home/runner/.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/bin/python

node_factory = <pyln.testing.utils.NodeFactory object at 0x7fb08bb969d0>

    def test_grpc_connect_notification(node_factory):
        l1, l2 = node_factory.get_nodes(2)
    
        # Test the connect notification
        connect_stream = l1.grpc.SubscribeConnect(clnpb.StreamConnectRequest())
        l2.connect(l1)
    
>       for connect_event in connect_stream:

tests/test_cln_rs.py:425: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/grpc/_channel.py:543: in __next__
    return self._next()
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/grpc/_channel.py:960: in _next
    _common.wait(self._state.condition.wait, _response_ready)
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/grpc/_common.py:156: in wait
    _wait_once(wait_fn, MAXIMUM_WAIT_TIMEOUT, spin_cb)
../../../.cache/pypoetry/virtualenvs/cln-meta-project-AqJ9wMix-py3.8/lib/python3.8/site-packages/grpc/_common.py:116: in _wait_once
    wait_fn(timeout=timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <Condition(<unlocked _thread.RLock object owner=0 count=0 at 0x7fb089730f00>, 0)>
timeout = 0.1

    def wait(self, timeout=None):
        """Wait until notified or until a timeout occurs.
    
        If the calling thread has not acquired the lock when this method is
        called, a RuntimeError is raised.
    
        This method releases the underlying lock, and then blocks until it is
        awakened by a notify() or notify_all() call for the same condition
        variable in another thread, or until the optional timeout occurs. Once
        awakened or timed out, it re-acquires the lock and returns.
    
        When the timeout argument is present and not None, it should be a
        floating point number specifying a timeout for the operation in seconds
        (or fractions thereof).
    
        When the underlying lock is an RLock, it is not released using its
        release() method, since this may not actually unlock the lock when it
        was acquired multiple times recursively. Instead, an internal interface
        of the RLock class is used, which really unlocks it even when it has
        been recursively acquired several times. Another internal interface is
        then used to restore the recursion level when the lock is reacquired.
    
        """
        if not self._is_owned():
            raise RuntimeError("cannot wait on un-acquired lock")
        waiter = _allocate_lock()
        waiter.acquire()
        self._waiters.append(waiter)
        saved_state = self._release_save()
        gotit = False
        try:    # restore state no matter what (e.g., KeyboardInterrupt)
            if timeout is None:
                waiter.acquire()
                gotit = True
            else:
                if timeout > 0:
>                   gotit = waiter.acquire(True, timeout)
E                   Failed: Timeout >1200.0s
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Couldn't figure out why hsmtool.proc.wait(WAIT_TIMEOUT) returns 1?
hsmtool doesn't ever seem to exit status 1!

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Fails when l3 doesn't know address for l1, to connect to it:

```
2024-11-16T04:45:42.2243366Z lightningd-3 2024-11-16T04:35:10.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: peer_in WIRE_ONION_MESSAGE
2024-11-16T04:45:42.2244342Z lightningd-3 2024-11-16T04:35:10.582Z DEBUG   lightningd: Got onionmsg reply_path
2024-11-16T04:45:42.2245398Z lightningd-3 2024-11-16T04:35:10.582Z DEBUG   plugin-offers: Note: disallowing deprecated onion_message_recv.blinding
2024-11-16T04:45:42.2246408Z lightningd-3 2024-11-16T04:35:10.586Z UNUSUAL plugin-offers: No incoming channel for 5msat, so no blinded path
2024-11-16T04:45:42.2247289Z lightningd-3 2024-11-16T04:35:10.605Z DEBUG   hsmd: Client: Received message 25 from client
2024-11-16T04:45:42.2248372Z lightningd-3 2024-11-16T04:35:10.606Z DEBUG   plugin-offers: connecting directly to 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518
2024-11-16T04:45:42.2249451Z lightningd-3 2024-11-16T04:35:10.606Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2024-11-16T04:45:42.2250743Z lightningd-3 2024-11-16T04:35:10.607Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: Failed connected out: Unable to connect, no address known for peer
```

This is because the test which was supposed to wait for addresses is
wrong: it passes when l3 knows nothing!  (`all([])` == `True`)

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
…e positives.

```
**BROKEN** lightningd: MEMLEAK: 0x5557327d1428
**BROKEN** lightningd:   label=lightningd/onchain_control.c:352:struct replay_tx
**BROKEN** lightningd:   alloc:
**BROKEN** lightningd:     /home/runner/work/lightning/lightning/ccan/ccan/tal/tal.c:488 (tal_alloc_)
**BROKEN** lightningd:     /home/runner/work/lightning/lightning/lightningd/onchain_control.c:352 (replay_watch_tx)
**BROKEN** lightningd:     /home/runner/work/lightning/lightning/lightningd/onchain_control.c:1816 (onchaind_funding_spent)
**BROKEN** lightningd:     /home/runner/work/lightning/lightning/lightningd/onchain_control.c:1860 (onchaind_replay_channels)
**BROKEN** lightningd:     /home/runner/work/lightning/lightning/lightningd/lightningd.c:1407 (main)
**BROKEN** lightningd:   parents:
**BROKEN** lightningd:     lightningd/onchain_control.c:1856:struct replay_tx_hash
**BROKEN** lightningd:     lightningd/lightningd.c:112:struct lightningd
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Looks like a build race, where we use it before it's finished:

```
msggen cln-rpc/src/model.rs
error: this file contains an unclosed delimiter
    --> cln-grpc/src/server.rs:3661:7
     |
84   | {
     | - unclosed delimiter
...
3661 |     }
     |      ^
```
...

```
make: *** [plugins/Makefile:298: target/release/cln-grpc] Error 101
make: *** Waiting for unfinished jobs....
```

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
@rustyrussell rustyrussell merged commit 374db23 into ElementsProject:master Nov 17, 2024
39 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant