From 3be25d48d3a8bf519cb10838dc5bf7b8e5e22764 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 14 Jan 2026 13:18:11 +1030 Subject: [PATCH] pytest: don't rely on sleep to ensure wait commands have been submitted. Seems like sleep(1) isn't always enough. Give in and put a log message there, and use that: ``` waitfut = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='deleted', nextvalue=1) time.sleep(1) l2.rpc.delforward(scid12, 1, 'failed') waitres = waitfut.result(TIMEOUT) > assert waitres == {'subsystem': 'forwards', 'deleted': 1, 'forwards': {'in_channel': scid12, 'in_htlc_id': 1, 'status': 'failed'}} E AssertionError: assert {'subsystem': 'forwards', 'deleted': 1} == {'subsystem': 'forwards', 'deleted': 1, 'forwards': {'in_channel': '103x2x0', 'in_htlc_id': 1, 'status': 'failed'}} E E Common items: E {'deleted': 1, 'subsystem': 'forwards'} E Right contains 1 more item: E {'forwards': {'in_channel': '103x2x0', 'in_htlc_id': 1, 'status': 'failed'}} E E Full diff: E { E 'deleted': 1, E - 'forwards': { E - 'in_channel': '103x2x0', E - 'in_htlc_id': 1, E - 'status': 'failed', E - }, E 'subsystem': 'forwards', E } tests/test_misc.py:3599: AssertionError ``` Signed-off-by: Rusty Russell --- lightningd/wait.c | 5 +++++ tests/test_coinmoves.py | 2 ++ tests/test_connection.py | 4 ++-- tests/test_invoices.py | 16 ++++++++-------- tests/test_misc.py | 11 ++++++----- tests/test_pay.py | 10 +++++----- 6 files changed, 28 insertions(+), 20 deletions(-) diff --git a/lightningd/wait.c b/lightningd/wait.c index b9390a746..1e074df05 100644 --- a/lightningd/wait.c +++ b/lightningd/wait.c @@ -5,6 +5,7 @@ #include #include #include +#include #include #include #include @@ -277,6 +278,10 @@ static struct command_result *json_wait(struct command *cmd, waiter->cmd = cmd; list_add_tail(&cmd->ld->wait_commands, &waiter->list); + log_trace(cmd->ld->log, "waiting on %s %s %"PRIu64, + wait_subsystem_name(*waiter->subsystem), + wait_index_name(*waiter->index), + *waiter->nextval); return command_still_pending(cmd); } diff --git a/tests/test_coinmoves.py b/tests/test_coinmoves.py index b3679fbbd..bc7ee41d1 100644 --- a/tests/test_coinmoves.py +++ b/tests/test_coinmoves.py @@ -1938,6 +1938,7 @@ def test_wait(node_factory, bitcoind, executor): l1, l2 = node_factory.get_nodes(2) fut = executor.submit(l1.rpc.wait, subsystem='chainmoves', indexname='created', nextvalue=1) + l1.daemon.wait_for_log('waiting on chainmovesmoves created 1') addr = l1.rpc.newaddr('bech32')['bech32'] bitcoind.rpc.sendtoaddress(addr, 200000000 / 10**8) @@ -1956,6 +1957,7 @@ def test_wait(node_factory, bitcoind, executor): wait_for(lambda: all([c['state'] == 'CHANNELD_NORMAL' for c in l1.rpc.listpeerchannels(l2.info['id'])['channels']])) fut = executor.submit(l1.rpc.wait, subsystem='channelmoves', indexname='created', nextvalue=1) + l1.daemon.wait_for_log('waiting on channelmoves created 1') inv = l2.rpc.invoice('any', 'test_wait', 'test_wait') l1.rpc.xpay(inv['bolt11'], '1000000sat') diff --git a/tests/test_connection.py b/tests/test_connection.py index 92603ea73..6bfe59e44 100644 --- a/tests/test_connection.py +++ b/tests/test_connection.py @@ -4652,7 +4652,7 @@ def test_networkevents(node_factory, executor): # Finally, disconnect event. fut = executor.submit(l1.rpc.wait, 'networkevents', 'created', 3) - time.sleep(1) + l1.daemon.wait_for_log('waiting on networkevents created 3') l2.rpc.disconnect(l1.info['id']) after = time.time() @@ -4735,7 +4735,7 @@ def test_networkevents(node_factory, executor): assert failevents[-1]['connect_attempted'] is False fut = executor.submit(l1.rpc.wait, 'networkevents', 'deleted', 1) - time.sleep(1) + l1.daemon.wait_for_log('waiting on networkevents deleted 1') l1.rpc.delnetworkevent(8) assert l1.rpc.listnetworkevents(start=8) == {'networkevents': []} diff --git a/tests/test_invoices.py b/tests/test_invoices.py index 37e6695be..29c35fc41 100644 --- a/tests/test_invoices.py +++ b/tests/test_invoices.py @@ -668,7 +668,7 @@ def test_wait_invoices(node_factory, executor): # Now ask for 1. waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'created', 'nextvalue': 1}) - time.sleep(1) + l2.daemon.wait_for_log('waiting on invoices created 1') inv = l2.rpc.invoice(42, 'invlabel', 'invdesc') waitres = waitfut.result(TIMEOUT) @@ -691,7 +691,7 @@ def test_wait_invoices(node_factory, executor): 'updated': 0} waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'updated', 'nextvalue': 1}) - time.sleep(1) + l2.daemon.wait_for_log('waiting on invoices updated 1') l1.rpc.pay(inv['bolt11']) waitres = waitfut.result(TIMEOUT) assert waitres == {'subsystem': 'invoices', @@ -724,7 +724,7 @@ def test_wait_invoices(node_factory, executor): 'deleted': 0} waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'deleted', 'nextvalue': 1}) - time.sleep(1) + l2.daemon.wait_for_log('waiting on invoices deleted 1') l2.rpc.delinvoice('invlabel', 'paid') waitres = waitfut.result(TIMEOUT) @@ -741,7 +741,7 @@ def test_wait_invoices(node_factory, executor): # Now check autoclean works. waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'deleted', 'nextvalue': 2}) - time.sleep(2) + l2.daemon.wait_for_log('waiting on invoices deleted 2') l2.rpc.autoclean_once('expiredinvoices', 1) waitres = waitfut.result(TIMEOUT) @@ -753,7 +753,7 @@ def test_wait_invoices(node_factory, executor): # Creating a new on gives us 3, not another 2! waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'created', 'nextvalue': 3}) - time.sleep(1) + l2.daemon.wait_for_log('waiting on invoices created 3') inv = l2.rpc.invoice(42, 'invlabel2', 'invdesc2', deschashonly=True) waitres = waitfut.result(TIMEOUT) assert waitres == {'subsystem': 'invoices', @@ -766,7 +766,7 @@ def test_wait_invoices(node_factory, executor): # Deleting a description causes updated to fire! waitfut = executor.submit(l2.rpc.call, 'wait', {'subsystem': 'invoices', 'indexname': 'updated', 'nextvalue': 3}) - time.sleep(1) + l2.daemon.wait_for_log('waiting on invoices updated 3') l2.rpc.delinvoice('invlabel2', status='unpaid', desconly=True) waitres = waitfut.result(TIMEOUT) assert waitres == {'subsystem': 'invoices', @@ -819,7 +819,7 @@ def test_invoice_deschash(node_factory, chainparams): assert inv['description'] == b11['description_hash'] -def test_listinvoices_index(node_factory, executor): +def test_listinvoices_index(node_factory): l1, l2 = node_factory.line_graph(2) invs = {} @@ -863,7 +863,7 @@ def test_listinvoices_index(node_factory, executor): assert only_one(l2.rpc.listinvoices(index='updated', start=i, limit=1)['invoices'])['label'] == str(70 + 1 - i) -def test_unified_invoices(node_factory, executor, bitcoind): +def test_unified_invoices(node_factory, bitcoind): l1, l2 = node_factory.line_graph(2, opts={'invoices-onchain-fallback': None}) amount_sat = 1000 inv = l1.rpc.invoice(amount_sat * 1000, "inv1", "test_unified_invoices") diff --git a/tests/test_misc.py b/tests/test_misc.py index 18c7384b0..b1aa03796 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -3541,7 +3541,7 @@ def test_listforwards_wait(node_factory, executor): # Now ask for 1. waitcreate = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='created', nextvalue=1) waitupdate = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='updated', nextvalue=1) - time.sleep(1) + l2.daemon.wait_for_logs(['waiting on forwards created 1', 'waiting on forwards updated 1']) amt1 = 1000 inv1 = l3.rpc.invoice(amt1, 'inv1', 'desc') @@ -3571,6 +3571,7 @@ def test_listforwards_wait(node_factory, executor): waitcreate = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='created', nextvalue=2) waitupdate = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='updated', nextvalue=2) + l2.daemon.wait_for_logs(['waiting on forwards created 2', 'waiting on forwards updated 2']) time.sleep(1) with pytest.raises(RpcError, match="WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS"): @@ -3605,7 +3606,7 @@ def test_listforwards_wait(node_factory, executor): # Finally, check deletion. waitfut = executor.submit(l2.rpc.wait, subsystem='forwards', indexname='deleted', nextvalue=1) - time.sleep(1) + l2.daemon.wait_for_log('waiting on forwards deleted 1') l2.rpc.delforward(scid12, 1, 'failed') @@ -3629,7 +3630,7 @@ def test_listhtlcs_wait(node_factory, bitcoind, executor): # Now ask for 1. waitcreate = executor.submit(l2.rpc.wait, subsystem='htlcs', indexname='created', nextvalue=1) waitupdate = executor.submit(l2.rpc.wait, subsystem='htlcs', indexname='updated', nextvalue=1) - time.sleep(1) + l2.daemon.wait_for_logs(['waiting on htlcs created 1', 'waiting on htlcs updated 1']) amt1 = 1000 inv1 = l3.rpc.invoice(amt1, 'inv1', 'desc') @@ -3665,7 +3666,7 @@ def test_listhtlcs_wait(node_factory, bitcoind, executor): l3.rpc.delinvoice('inv2', 'unpaid') waitcreate = executor.submit(l2.rpc.wait, subsystem='htlcs', indexname='created', nextvalue=4) - time.sleep(1) + l2.daemon.wait_for_log('waiting on htlcs created 4') with pytest.raises(RpcError, match="WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS"): l1.rpc.pay(inv2['bolt11']) @@ -3685,7 +3686,7 @@ def test_listhtlcs_wait(node_factory, bitcoind, executor): l1.rpc.close(l2.info['id']) waitfut = executor.submit(l2.rpc.wait, subsystem='htlcs', indexname='deleted', nextvalue=1) - time.sleep(1) + l2.daemon.wait_for_log('waiting on htlcs deleted 1') bitcoind.generate_block(100, wait_for_mempool=1) diff --git a/tests/test_pay.py b/tests/test_pay.py index c921b907b..06b828125 100644 --- a/tests/test_pay.py +++ b/tests/test_pay.py @@ -735,8 +735,8 @@ def test_wait_sendpay(node_factory, executor): wait_created = executor.submit(l1.rpc.call, 'wait', {'subsystem': 'sendpays', 'indexname': 'created', 'nextvalue': 1}) wait_updated = executor.submit(l1.rpc.call, 'wait', {'subsystem': 'sendpays', 'indexname': 'updated', 'nextvalue': 1}) + l1.daemon.wait_for_logs(['waiting on sendpays created 1', 'waiting on sendpays updated 1']) - time.sleep(1) amt = 200000000 inv = l2.rpc.invoice(amt, 'testpayment2', 'desc') routestep = { @@ -5582,7 +5582,7 @@ def test_sendpays_wait(node_factory, executor): # Now ask for 1. waitfut = executor.submit(l1.rpc.wait, subsystem='sendpays', indexname='created', nextvalue=1) - time.sleep(1) + l1.daemon.wait_for_log('waiting on sendpays created 1') inv1 = l2.rpc.invoice(42, 'invlabel', 'invdesc') l1.rpc.pay(inv1['bolt11']) @@ -5610,7 +5610,7 @@ def test_sendpays_wait(node_factory, executor): inv2 = l2.rpc.invoice(42, 'invlabel2', 'invdesc2') waitfut = executor.submit(l1.rpc.wait, subsystem='sendpays', indexname='updated', nextvalue=2) - time.sleep(1) + l1.daemon.wait_for_log('waiting on sendpays updated 2') l1.rpc.pay(inv2['bolt11']) waitres = waitfut.result(TIMEOUT) assert waitres == {'subsystem': 'sendpays', @@ -5632,7 +5632,7 @@ def test_sendpays_wait(node_factory, executor): l2.rpc.delinvoice('invlabel3', 'unpaid') waitfut = executor.submit(l1.rpc.wait, subsystem='sendpays', indexname='updated', nextvalue=3) - time.sleep(1) + l1.daemon.wait_for_log('waiting on sendpays updated 3') with pytest.raises(RpcError, match="WIRE_INCORRECT_OR_UNKNOWN_PAYMENT_DETAILS"): l1.rpc.pay(inv3['bolt11']) @@ -5660,7 +5660,7 @@ def test_sendpays_wait(node_factory, executor): 'deleted': 0} waitfut = executor.submit(l1.rpc.wait, subsystem='sendpays', indexname='deleted', nextvalue=1) - time.sleep(1) + l1.daemon.wait_for_log('waiting on sendpays deleted 1') l1.rpc.delpay(inv3['payment_hash'], 'failed', 0, 1)