Skip to content

pytest: fix flakes in test_splicing_rbf, test_reconnect_signed, test_htlc_no_force_close #8402

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 4 commits into from
Jul 11, 2025
Merged

pytest: fix flakes in test_splicing_rbf, test_reconnect_signed, test_htlc_no_force_close #8402

merged 4 commits into from
Jul 11, 2025

Conversation

@rustyrussell
Copy link
Contributor

@rustyrussell rustyrussell commented Jul 9, 2025 •
edited
Loading

FIRST FLAKE

We get a unilateral close if the blocks come too fast:

>       l2.daemon.wait_for_log(r'CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')

tests/test_splicing.py:96:
...
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile('CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')]" in logs.

Here:

lightningd-2 2025-07-08T12:08:30.430Z DEBUG   lightningd: Adding block 114: 542499dfc63bc94c0ba0a3d81bdaff07ab73ba9aebddd4c2ae4b2e0c1e8bd15f
...
lightningd-2 2025-07-08T12:08:30.459Z UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Peer permanent failure in CHANNELD_AWAITING_SPLICE: Fulfilled HTLC 1 RCVD_REMOVE_REVOCATION cltv11 4 hit deadline (reason=protocol)
lightningd-2 2025-07-08T12:08:30.469Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#1: Status closed, but not exited. Killing
lightningd-2 2025-07-08T12:08:30.475Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_AWAITING_SPLICE to AWAITING_UNILATERAL

SECOND FLAKE

>       l1.rpc.fundchannel(l2.info['id'], CHANNEL_SIZE)

tests/test_connection.py:667:
...
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: fundchannel, payload: {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'amount': 50000, 'announce': True}, error: {'code': -1, 'message': 'Disconnected', 'data': {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'method': 'openchannel_update'}}

What happens here is complicated.

  1. dualopend never processes the WIRE_COMMITMENT_SIGNED message, meaning it doesn't consider it worth
    trying to reconnect.
  2. Normally, on disconnect, we give subds time to process packets and then notice the disconnect.
  3. But, if we can another connection, we terminate the (old) subds immediately.
  4. When lightningd transitions the channel from DUALOPEND_OPEN_INIT to DUALOPEND_OPEN_COMMIT_READY,
    it tells connectd this peer is important.
  5. Normally, this causes a reconnect one second after hangup.
  6. However, if we've already disconnected, it makes connectd reconnect immediately. This causes
    the test flake, if dualopend hasn't processed the message, and thus changed the state to
    DUALOPEND_OPEN_COMMITTED: we don't reconnect and instead fail the fundchannel() call.

Changelog-None

@rustyrussell
pytest: fix flake in test_splicing_rbf
bd99c2c 
We get a unilateral close if the blocks come too fast:

```
>       l2.daemon.wait_for_log(r'CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')

tests/test_splicing.py:96:
...
>                   raise TimeoutError('Unable to find "{}" in logs.'.format(exs))
E                   TimeoutError: Unable to find "[re.compile('CHANNELD_AWAITING_SPLICE to CHANNELD_NORMAL')]" in logs.
```

Here:

```
lightningd-2 2025-07-08T12:08:30.430Z DEBUG   lightningd: Adding block 114: 542499dfc63bc94c0ba0a3d81bdaff07ab73ba9aebddd4c2ae4b2e0c1e8bd15f
...
lightningd-2 2025-07-08T12:08:30.459Z UNUSUAL 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Peer permanent failure in CHANNELD_AWAITING_SPLICE: Fulfilled HTLC 1 RCVD_REMOVE_REVOCATION cltv11 4 hit deadline (reason=protocol)
lightningd-2 2025-07-08T12:08:30.469Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-channeld-chan#1: Status closed, but not exited. Killing
lightningd-2 2025-07-08T12:08:30.475Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from CHANNELD_AWAITING_SPLICE to AWAITING_UNILATERAL
```

Signed-off-by: Rusty Russell <[email protected]>
@rustyrussell rustyrussell added this to the v25.09 milestone Jul 9, 2025
@rustyrussell rustyrussell requested review from ddustin and sangbida July 9, 2025 02:05
@rustyrussell rustyrussell changed the title pytest: fix flake in test_splicing_rbf pytest: fix flakes in test_splicing_rbf and test_reconnect_signed Jul 9, 2025
@rustyrussell
pytest: really fix flake in test_reconnect_signed
19ae86f 
```
>       l1.rpc.fundchannel(l2.info['id'], CHANNEL_SIZE)

tests/test_connection.py:667:
...
>           raise RpcError(method, payload, resp['error'])
E           pyln.client.lightning.RpcError: RPC call failed: method: fundchannel, payload: {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'amount': 50000, 'announce': True}, error: {'code': -1, 'message': 'Disconnected', 'data': {'id': '022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59', 'method': 'openchannel_update'}}
```

What happens here is complicated.

1. dualopend never processes the WIRE_COMMITMENT_SIGNED message, meaning it doesn't consider it worth
   trying to reconnect.
2. Normally, on disconnect, we give subds time to process packets and then notice the disconnect.
3. But, if we can another connection, we terminate the (old) subds immediately.
4. When lightningd transitions the channel from DUALOPEND_OPEN_INIT to DUALOPEND_OPEN_COMMIT_READY,
   it tells connectd this peer is important.
5. Normally, this causes a reconnect one second after hangup.
6. However, if we've already disconnected, it makes connectd reconnect immediately.  This causes
   the test flake, if dualopend hasn't processed the message, and thus changed the state to
   DUALOPEND_OPEN_COMMITTED: we don't reconnect and instead fail the fundchannel() call.

Signed-off-by: Rusty Russell <[email protected]>
ddustin
ddustin approved these changes Jul 9, 2025
View reviewed changes
Copy link
Collaborator

@ddustin ddustin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The splicing test update LGTM, ack 19ae86f 👍

tests/test_splicing.py
l1.rpc.pay(inv['bolt11'])

# Make sure l1 doesn't unilateral close if HTLC hasn't completely settled before deadline.
wait_for(lambda: only_one(l1.rpc.listpeerchannels()['channels'])['htlcs'] == [])
Copy link
Collaborator

@ddustin ddustin Jul 9, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah cool didn't know we had a way to do this 👍

@rustyrussell rustyrussell changed the title pytest: fix flakes in test_splicing_rbf and test_reconnect_signed pytest: fix flakes in test_splicing_rbf, test_reconnect_signed, test_htlc_no_force_close Jul 10, 2025
@rustyrussell rustyrussell enabled auto-merge (rebase) July 10, 2025 06:46
@rustyrussell
pytest: avoid bad gossip flake in test_htlc_no_force_close
a828622 
l3 closes with l2 unilaterally, but l2 sends l1 the channel_announce after
that, when it has never seen it before.  The solution is to wait until
l1 has seen the channel before we start the rest of the test:

```
E           ValueError:
E           Node errors:
E            - lightningd-2: had warning messages
E            - lightningd-1: had bad gossip messages
...
lightningd-2 2025-07-09T07:55:59.778Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_in WIRE_WARNING
lightningd-2 2025-07-09T07:55:59.778Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: Received WIRE_WARNING: WARNING: channel_announcement: no unspent txout 103x1x0
lightningd-1 2025-07-09T07:55:59.781Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-channeld-chan#1: billboard: Channel ready for use.
lightningd-1 2025-07-09T07:55:59.782Z TRACE   gossipd: channel_announcement: got reply for 103x1x0...
lightningd-1 2025-07-09T07:55:59.782Z TRACE   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-gossipd: Bad gossip order: channel_announcement: no unspent txout 103x1x0
```

Signed-off-by: Rusty Russell <[email protected]>
@rustyrussell
pytest: add debug print to diagnose flake in test_peer_anchor_push
2a61a9c 
Sometimes the feerate is 5 too high.  But without seeing the actual txs it's
looking at, it's hard to know why.

```
actual_feerate = 13005.66942869603, expected_feerate = 13000

    def check_feerate(nodes, actual_feerate, expected_feerate):
        # Feerate can't be lower.
        assert actual_feerate > expected_feerate - 2
        if actual_feerate >= expected_feerate + 2:
            if any([did_short_sig(n) for n in nodes]):
                return
        # Use assert as it shows the actual values on failure
>       assert actual_feerate < expected_feerate + 2
E       AssertionError
```

Signed-off-by: Rusty Russell <[email protected]>
@rustyrussell rustyrussell merged commit 725c417 into ElementsProject:master Jul 11, 2025
76 of 79 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@ddustin ddustin ddustin approved these changes

@sangbida sangbida Awaiting requested review from sangbida

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

v25.09

Development

Successfully merging this pull request may close these issues.

2 participants

@rustyrussell @ddustin