← Watch feed
pytest: don't rely on sleep to ensure wait commands have been submitted.
Public commit record
95/100 · Strong
What the developer wrote
Authored by Rusty Russell
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 <rusty@rustcorp.com.au>
✓ Specific, descriptive subject✓ Names a concrete action or component✓ Provides detailed explanatory context✓ Explains rationale or failure mode✓ Mentions testing or verification
What changed, and why it matters
This commit fixes flaky automated tests, not the Core Lightning server itself. The tests were using a one-second sleep to guess that a background 'wait' command had been submitted, but sometimes the command wasn't ready in time and the test would fail. The patch adds a log line when a wait command is registered and changes the tests to wait for that log line instead of sleeping. There is no security fix here.
Recommended action
No security action needed. Treat as a normal test reliability improvement.
Security signals we found
No strong security signals were identified.
Evidence from the diff
The change is a test-hardening patch. In lightningd/wait.c a trace log is emitted when json_wait() appends a waiter to cmd->ld->wait_commands. Multiple pytest files replace time.sleep(N) calls with daemon.wait_for_log() / wait_for_logs() checks for the new ‘waiting on
Changed components
tests/test_coinmoves.pytests/test_connection.pytests/test_invoices.pytests/test_misc.pytests/test_pay.pylightningd/wait.c (log_trace only)Inspect captured patch +28 / −20
diff --git a/lightningd/wait.c b/lightningd/wait.c
index b9390a74..1e074df0 100644
--- a/lightningd/wait.c
+++ b/lightningd/wait.c
@@ -5,6 +5,7 @@
#include <common/json_command.h>
#include <common/overflows.h>
#include <db/exec.h>
+#include <inttypes.h>
#include <lightningd/jsonrpc.h>
#include <lightningd/lightningd.h>
#include <lightningd/wait.h>
@@ -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 b3679fbb..bc7ee41d 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 92603ea7..6bfe59e4 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 37e6695b..29c35fc4 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 18c7384b..b1aa0379 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 c921b907..06b82812 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)
Risk score
Our methodology →Why this scored 15/100
Human-validated context
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
No validated notes yet.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.