Skip to content

tests: fix flaky test_simple_close_dust_output_omitted mempool race#9299

Merged
daywalker90 merged 1 commit into
ElementsProject:masterfrom
ksedgwic:fix-flaky-simple-close-dust-race
Jul 21, 2026
Merged

tests: fix flaky test_simple_close_dust_output_omitted mempool race#9299
daywalker90 merged 1 commit into
ElementsProject:masterfrom
ksedgwic:fix-flaky-simple-close-dust-race

Conversation

@ksedgwic

@ksedgwic ksedgwic commented Jul 9, 2026

Copy link
Copy Markdown
Collaborator

Observed on a CI run for #9286 (postgres full integration, 1 failed / 1012 passed):
https://github.com/ElementsProject/lightning/actions/runs/28971841260

The test snapshots getrawmempool() and then fetches each txid with
getrawtransaction(). Both peers broadcast conflicting closer txs; in
the dust scenario l2's tx pays only 400sat fee (its whole balance)
while l1's pays 3375sat, so l1's tx RBF-replaces l2's. When the
replacement lands between the snapshot and the fetch,
getrawtransaction() fails with error -5 (No such mempool or blockchain
transaction). The captured node logs show l2's tx replaced 14ms after
broadcast.

The fix retries the snapshot-and-check loop when a txid vanishes
mid-iteration; the single-output assertion still fails hard. Same
class of race as the test_simple_close_delay_broadcast fix in
5ae0705.

Changelog-None

The test snapshots getrawmempool() and then calls getrawtransaction()
on each txid.  In simple close both peers broadcast conflicting closer
txs: here l2's tx pays only 400sat fee (its entire 400sat balance goes
to fees since its own output is dust) while l1's pays 3375sat, so l1's
tx can RBF-replace l2's between the snapshot and the fetch.  The
getrawtransaction() call on the replaced txid then fails with error -5
(No such mempool or blockchain transaction).  A CI failure showed
exactly this ordering: l2 broadcast its closer tx, l1's higher-fee tx
replaced it 14ms later, and the test's per-txid fetch raced the
replacement.

Retry the whole snapshot-and-check loop when a txid vanishes
mid-iteration, keeping the single-output assertion hard.  This is the
same class of mempool race fixed for test_simple_close_delay_broadcast
in 5ae0705 ("tests: fix flaky test_simple_close_delay_broadcast
mempool race").

Changelog-None
@daywalker90
daywalker90 force-pushed the fix-flaky-simple-close-dust-race branch from 7cfc667 to 235c75e Compare July 20, 2026 14:14
@daywalker90
daywalker90 enabled auto-merge (rebase) July 20, 2026 14:14
@daywalker90
daywalker90 disabled auto-merge July 20, 2026 16:27
@daywalker90

Copy link
Copy Markdown
Collaborator

Hmm never seen this one before:

 def test_bookkeeper_custom_notifs(node_factory, chainparams):
        # FIXME: what happens if we send internal funds to 'external' wallet?
        plugin = os.path.join(
            os.path.dirname(__file__), "plugins", "bookkeeper_custom_coins.py"
        )
        l1, l2 = node_factory.line_graph(2, opts=[{'plugin': plugin}, {}])
    
        outpoint_in = 'aa' * 32 + ':0'
        spend_txid = 'bb' * 32
        amount = 180000000
        withdraw_amt = 55555000
        fee = 2000
    
        change_deposit = 'bb' * 32 + ':0'
        external_deposit = 'bb' * 32 + ':1'
        acct = "nifty's secret stash"
    
        l1.rpc.senddeposit(acct, False, outpoint_in, amount)
        l1.daemon.wait_for_log(r"Foreign chain event: deposit \(nifty's secret stash\) 180000000msat -0msat 1679955976 111 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:0")
        l1.rpc.sendspend(acct, outpoint_in, spend_txid, amount)
>       l1.daemon.wait_for_log(r"Foreign chain event: withdrawal \(nifty's secret stash\) 0msat -180000000msat 1679955976 111 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:0 bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb")

contrib/pyln-testing/pyln/testing/utils.py:420: TimeoutError
lightningd-1 2026-07-20T14:45:56.487Z DEBUG   lightningd: updating channel 15363781x3224765x44550 with inbound settings
lightningd-1 2026-07-20T14:45:57.482Z UNUSUAL plugin-bookkeeper_custom_coins.py: Plugin does not support check command for senddeposit (id "-c:check#33")
lightningd-1 2026-07-20T14:45:58.423Z TRACE   lightningd: waiting on chainmoves created 6
lightningd-1 2026-07-20T14:45:58.445Z TRACE   lightningd: waiting on chainmoves updated 1
lightningd-1 2026-07-20T14:45:58.446Z TRACE   lightningd: waiting on chainmoves deleted 1
lightningd-1 2026-07-20T14:45:58.543Z DEBUG   plugin-sql: Time to call listchainmoves: 0.435772322 seconds
lightningd-1 2026-07-20T14:45:58.543Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.435958924 seconds (last=5)
lightningd-1 2026-07-20T14:45:58.543Z DEBUG   plugin-sql: Time to refresh + create indices for chainmoves: 0.436089551 seconds
lightningd-1 2026-07-20T14:45:58.730Z DEBUG   plugin-sql: Time to call listchainmoves: 0.081761597 seconds
lightningd-1 2026-07-20T14:45:58.731Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.081816009 seconds (last=5)
lightningd-1 2026-07-20T14:45:58.927Z DEBUG   plugin-sql: Time to call listchainmoves: 0.078867972 seconds
lightningd-1 2026-07-20T14:45:58.928Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.078925329 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.126Z DEBUG   plugin-sql: Time to call listchainmoves: 0.073577592 seconds
lightningd-1 2026-07-20T14:45:59.126Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.073735991 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.314Z DEBUG   plugin-sql: Time to call listchainmoves: 0.079464862 seconds
lightningd-1 2026-07-20T14:45:59.315Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.079518784 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.537Z DEBUG   plugin-sql: Time to call listchainmoves: 0.066801360 seconds
lightningd-1 2026-07-20T14:45:59.537Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.066853909 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.727Z DEBUG   plugin-sql: Time to call listchainmoves: 0.079809993 seconds
lightningd-1 2026-07-20T14:45:59.728Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.079863574 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.915Z DEBUG   plugin-sql: Time to call listchainmoves: 0.068384217 seconds
lightningd-1 2026-07-20T14:45:59.916Z DEBUG   plugin-sql: Time to refresh chainmoves: 0.068437177 seconds (last=5)
lightningd-1 2026-07-20T14:45:59.978Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 2000000000msat -0msat chain_mvt 1784558747
lightningd-1 2026-07-20T14:45:59.978Z DEBUG   plugin-bookkeeper: coin_move 2 (withdrawal) 0msat -2000000000msat chain_mvt 1784558755
lightningd-1 2026-07-20T14:45:59.979Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 995073000msat -0msat chain_mvt 1784558755
lightningd-1 2026-07-20T14:45:59.979Z DEBUG   plugin-bookkeeper: coin_move 2 (channel_open) 1000000000msat -0msat chain_mvt 1784558756
lightningd-1 2026-07-20T14:45:59.979Z DEBUG   plugin-bookkeeper: Foreign chain event: deposit (nifty's secret stash) 180000000msat -0msat 1679955976 111 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:0 
lightningd-1 2026-07-20T14:45:59.979Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 180000000msat -0msat chain_mvt 1679955976
lightningd-1 2026-07-20T14:46:00.337Z DEBUG   jsonrpc#51: Pausing parsing after 6 requests and 268msec (last method=datastore)
lightningd-1 2026-07-20T14:46:00.383Z UNUSUAL plugin-bookkeeper_custom_coins.py: Plugin does not support check command for sendspend (id "-c:check#35")
lightningd-1 2026-07-20T14:46:00.825Z TRACE   lightningd: waiting on chainmoves created 7
lightningd-2 2026-07-20T14:46:16.068Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-1 2026-07-20T14:46:16.069Z DEBUG   033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-gossipd: seeker: chosen for periodic full sync
lightningd-1 2026-07-20T14:46:16.070Z DEBUG   033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-gossipd: seeker: starting gossip (EVERYTHING)
lightningd-1 2026-07-20T14:46:16.070Z DEBUG   033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2026-07-20T14:46:16.166Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-gossipd: seeker: chosen for periodic full sync
lightningd-2 2026-07-20T14:46:16.166Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-gossipd: seeker: starting gossip (EVERYTHING)
lightningd-1 2026-07-20T14:46:16.167Z DEBUG   033845802d25b4e074ccfd7cd8b339a41dc75bf9978a034800444b51d42b07799a-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2026-07-20T14:46:16.168Z DEBUG   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2026-07-20T14:47:19.120Z TRACE   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-lightningd: Ping latency: 4698388nsec
lightningd-2 2026-07-20T14:48:28.136Z TRACE   038194b5f32bdf0aa59812c86c4ef7ad2f294104fa027d1ace9b469bb6f88cf37b-lightningd: Ping latency: 6970505nsec
Time-out: can't find [re.compile("Foreign chain event: withdrawal \\(nifty's secret stash\\) 0msat -180000000msat 1679955976 111 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:0 bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb)] in logs
{'run_id': 337605709663936512, 'github_repository': 'ElementsProject/lightning', 'github_sha': '52d327948380c1b65a132b60013568e9806f78ff', 'github_ref': 'refs/pull/9299/merge', 'github_ref_name': 'HEAD', 'github_run_id': 29749758933, 'github_head_ref': 'fix-flaky-simple-close-dust-race', 'github_run_number': 17245, 'github_base_ref': 'master', 'github_run_attempt': '1', 'testname': 'test_bookkeeper_custom_notifs', 'start_time': 1784558687, 'end_time': 1784558940, 'outcome': 'fail'}

Not sure what is going on there.

@daywalker90
daywalker90 merged commit 406fc7a into ElementsProject:master Jul 21, 2026
87 of 89 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.

CI Flake test_simple_close_dust_output_omitted

2 participants