tests/test_plugin.py::test_sendpay_notifications_nowaiter failed twice on a dev box (2026-07-17 and 2026-07-21, different branches) with assert 0 == 1 on len(results['sendpay_success']). The root cause is a pyln-testing interaction, not the notifications themselves.
On a node with an inline plugin, the test process's python logging is forwarded into the node's log. wait_for_log() first logs Waiting for [pattern] - and since the pattern text is embedded verbatim in that announcement, the scanner then matches its own forwarded line. From the failing run:
lightningd-1 21:00:08.295Z DEBUG plugin-inline-plugin.py: root : Waiting for ['Received a sendpay_success'] in the logs
lightningd-1 21:00:08.299Z DEBUG plugin-inline-plugin.py: root : Found 're.compile('Received a sendpay_success')' in logs
lightningd-1 21:00:08.361Z DEBUG plugin-inline-plugin.py: root : Waiting for ['Received a sendpay_failure'] in the logs
lightningd-1 21:00:08.361Z DEBUG plugin-inline-plugin.py: root : Found 're.compile('Received a sendpay_failure')' in logs
lightningd-1 21:00:08.470Z INFO plugin-inline-plugin.py: Received a sendpay_failure: id=1, payment_hash=8444...
lightningd-1 21:00:08.489Z INFO plugin-inline-plugin.py: Received a sendpay_failure: id=2, payment_hash=7e21...
Found comes 1-4ms after Waiting, and no real Received a sendpay_success INFO line ever appears. With the wait reduced to a no-op, the test's l2.rpc.close() races payment 1; under load the payment loses, both payments fail (note the sendpay_failure for id=1), and success_list ends up empty. The 2026-07-17 failure shows the identical sequence.
Scope is wider than this one test: any wait_for_log() with a literal pattern, on any node with an inline plugin, silently becomes a no-op whenever the test-side logger emits at DEBUG (the announcement line only exists then). That can mask races in tests that currently pass, and explains why this reproduces on dev boxes running DEBUG logging while CI mostly gets lucky on the underlying race.
Possible fixes:
- have
TailableProc.wait_for_logs() log the patterns in a non-matchable form (e.g. truncated or otherwise mangled), or record the scan position before emitting the announcement and skip lines it produced itself; or
- stop forwarding test-process log records into the node log stream that
wait_for_log() scans on inline-plugin nodes.
Part of #9222.
tests/test_plugin.py::test_sendpay_notifications_nowaiterfailed twice on a dev box (2026-07-17 and 2026-07-21, different branches) withassert 0 == 1onlen(results['sendpay_success']). The root cause is a pyln-testing interaction, not the notifications themselves.On a node with an inline plugin, the test process's python logging is forwarded into the node's log.
wait_for_log()first logsWaiting for [pattern]- and since the pattern text is embedded verbatim in that announcement, the scanner then matches its own forwarded line. From the failing run:Found comes 1-4ms after Waiting, and no real
Received a sendpay_successINFO line ever appears. With the wait reduced to a no-op, the test'sl2.rpc.close()races payment 1; under load the payment loses, both payments fail (note the sendpay_failure for id=1), andsuccess_listends up empty. The 2026-07-17 failure shows the identical sequence.Scope is wider than this one test: any
wait_for_log()with a literal pattern, on any node with an inline plugin, silently becomes a no-op whenever the test-side logger emits at DEBUG (the announcement line only exists then). That can mask races in tests that currently pass, and explains why this reproduces on dev boxes running DEBUG logging while CI mostly gets lucky on the underlying race.Possible fixes:
TailableProc.wait_for_logs()log the patterns in a non-matchable form (e.g. truncated or otherwise mangled), or record the scan position before emitting the announcement and skip lines it produced itself; orwait_for_log()scans on inline-plugin nodes.Part of #9222.