CI Flake `test_graceful_htlc`

[ddustin]

test_graceful_htlc flaking on CI appears to have been introduced by PR #9111 (CI logs)

FAILED tests/test_misc.py::test_graceful_htlc - ValueError: Timeout while waiting for <function test_graceful_htlc.<locals>.<lambda> at 0x7f6419c567a0>

Let's get this test to stop flaking. Here are some relevant info from the failed CI run:

    def test_graceful_htlc(node_factory, executor):
        """graceful with an HTLC in flight notifies about expiry and completes after HTLC resolves"""
        l1, l2, l3 = node_factory.line_graph(3, wait_for_announce=True,
                                             opts=[{'may_reconnect': True,
                                                    'dev-no-reconnect': None},
                                                   {'may_reconnect': True,
                                                    'dev-no-reconnect': None},
                                                   {'plugin': os.path.join(os.getcwd(), 'tests/plugins/hold_invoice.py')}])
    
        inv = l3.rpc.invoice(10000, 'hold', 'hold invoice')
        route = l1.single_route(l3.info['id'], 10000)
        l1.rpc.sendpay(route, inv['payment_hash'], payment_secret=inv['payment_secret'])
        wait_for(lambda: len(only_one(l3.rpc.listpeerchannels()['channels'])['htlcs']) == 1)
    
        notifications = []
    
        def run_graceful():
            def capture(message, **kwargs):
                if message:
                    notifications.append(message)
            with l2.rpc.notify(capture):
                return l2.rpc.graceful()
    
        fut = executor.submit(run_graceful)
    
        # Wait until graceful has sent at least one HTLC expiry notification
        wait_for(lambda: len(notifications) == 1)
>       wait_for(lambda: notifications[0] == f'Next HTLC SENT_ADD_ACK_REVOCATION expires at block #118 (10 blocks from now) going to peer {l3.info["id"]} (connected)')

lightningd-1 2026-06-10T18:36:09.390Z UNUSUAL lightningd: JSON-RPC shutdown
lightningd-1 2026-06-10T18:36:09.835Z DEBUG   jsonrpc#81: Pausing parsing after 1 requests and 484msec (last method=stop)
lightningd-1 2026-06-10T18:36:09.920Z DEBUG   lightningd: io_break: start_json_stream
lightningd-1 2026-06-10T18:36:09.992Z DEBUG   lightningd: io_loop_with_timers: main
lightningd-1 2026-06-10T18:36:10.859Z DEBUG   connectd: REPLY WIRE_CONNECTD_START_SHUTDOWN_REPLY with 0 fds
lightningd-1 2026-06-10T18:36:10.866Z DEBUG   lightningd: io_break: connectd_start_shutdown_reply
lightningd-1 2026-06-10T18:36:11.667Z DEBUG   033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-channeld-chan#1: Status closed, but not exited. Killing
lightningd-1 2026-06-10T18:36:15.633Z INFO    033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (256)
lightningd-1 2026-06-10T18:36:15.960Z DEBUG   plugin-sql: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:15.978Z DEBUG   plugin-chanbackup: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.255Z DEBUG   plugin-funder: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.276Z DEBUG   plugin-cln-xpay: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.294Z DEBUG   plugin-exposesecret: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.311Z DEBUG   plugin-cln-askrene: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.323Z DEBUG   plugin-commando: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.565Z DEBUG   plugin-bookkeeper: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.794Z DEBUG   plugin-recover: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.885Z DEBUG   plugin-autoclean: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:16.952Z DEBUG   plugin-cln-renepay: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.010Z DEBUG   plugin-bcli: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.019Z DEBUG   plugin-txprepare: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.041Z DEBUG   plugin-topology: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.045Z DEBUG   plugin-pay: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.054Z DEBUG   plugin-recklessrpc: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.059Z DEBUG   plugin-offers: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.061Z DEBUG   plugin-spenderp: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.072Z DEBUG   plugin-cln-bwatch: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.083Z DEBUG   plugin-keysend: Killing plugin: exited during normal operation
lightningd-1 2026-06-10T18:36:17.088Z DEBUG   lightningd: io_break: destroy_plugin
lightningd-1 2026-06-10T18:36:17.111Z DEBUG   lightningd: Command returned result after jcon close
lightningd-1 2026-06-10T18:36:17.116Z DEBUG   connectd: Shutting down
lightningd-1 2026-06-10T18:36:17.323Z DEBUG   gossipd: Shutting down
lightningd-2 2026-06-10T18:36:17.349Z INFO    038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-channeld-chan#1: Peer connection lost
lightningd-2 2026-06-10T18:36:17.355Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-channeld-chan#1: Status closed, but not exited. Killing
lightningd-1 2026-06-10T18:36:17.714Z DEBUG   hsmd: Shutting down
lightningd-2 2026-06-10T18:36:18.030Z INFO    038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
lightningd-2 2026-06-10T18:36:18.094Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-lightningd: peer_disconnected
lightningd-2 2026-06-10T18:36:18.124Z DEBUG   lightningd: NOTIFY "-c:graceful#40" info Next HTLC SENT_ADD_ACK_REVOCATION expires at block #118 (10 blocks from now) going to peer 03cecbfdc68544cc596223b68ce0710c9e5d2c9cb317ee07822d95079acc703d31 (connected)

[ddustin]

Interestingly it appears lightning-1 is shutting down before lightning-2 gets the notification message it's waiting for.

[ddustin]

Ran into a seperate failure case while trying to recreate it locally:

...
        fut = executor.submit(run_graceful)

        # Wait until graceful has sent at least one HTLC expiry notification
        wait_for(lambda: len(notifications) == 1)
        wait_for(lambda: notifications[0] == f'Next HTLC SENT_ADD_ACK_REVOCATION expires at block #118 (10 blocks from now) going to peer {l3.info["id"]} (connected)')

        # This will tell us about htlcs and the peers (peers unordered)
        ret = l2.rpc.graceful(1)
        assert ret in ({'pending_htlc_expiries': [118, 124],
                        'pending_peers': [l1.info['id'], l3.info['id']]},
                       {'pending_htlc_expiries': [118, 124],
                        'pending_peers': [l3.info['id'], l1.info['id']]})

        # Close incoming connection, so incoming HTLC gets stuck.
        l1.rpc.disconnect(l2.info['id'], force=True)
        wait_for(lambda: notifications[-1] == f'Next HTLC SENT_ADD_ACK_REVOCATION expires at block #118 (10 blocks from now) going to peer {l3.info["id"]} (connected)')

        # Release the hold so the *outgoing* HTLC resolves
        open(os.path.join(l3.daemon.lightning_dir, TEST_NETWORK, "unhold"), "w").close()

        wait_for(lambda: notifications[-1] == f'Next HTLC SENT_REMOVE_HTLC expires at block #124 (16 blocks from now) coming from peer {l1.info["id"]} (disconnected)')

        ret = l2.rpc.graceful(1)
        assert ret == {'pending_htlc_expiries': [124]}

        # Reconnect and it will settle.
        l1.rpc.connect(l2.info['id'], 'localhost', l2.port)

>       assert fut.result(TIMEOUT) == {}
               ^^^^^^^^^^^^^^^^^^^

[daywalker90]

Unfortunately i just encountered another flake in this test: https://github.com/ElementsProject/lightning/actions/runs/28935417082/job/85846876583?pr=9288

# Wait until graceful has sent at least one HTLC expiry notification
        wait_for(lambda: len(notifications) >= inotif + 1)
    
        # Depending on on timing between the sendpay and `l2.rpc.graceful`, we may get
        # RCVD_ADD_REVOCATION or we may be too late to get that.
        if notifications[inotif] == f'Next HTLC RCVD_ADD_REVOCATION expires at block #118 (10 blocks from now) going to peer {l3.info["id"]} (connected)':
            # If we get RCVD_ADD_REVOCATION, ignore it and move onto the next notification
            inotif += 1
>           wait_for(lambda: len(notifications) >= inotif + 1)
FAILED tests/test_misc.py::test_graceful_htlc - ValueError: Timeout while waiting for <function test_graceful_htlc.<locals>.<lambda> at 0x7fec25fdc8b0>