pyln-testing: don't let wait_for_log match its own forwarded announcement#9344
Open
ksedgwic wants to merge 1 commit into
Open
pyln-testing: don't let wait_for_log match its own forwarded announcement#9344ksedgwic wants to merge 1 commit into
ksedgwic wants to merge 1 commit into
Conversation
…ment An inline plugin's Plugin() object lives in the test process, and Plugin() installs a PluginLogHandler on the root logger so that a plugin author's `logging` calls reach lightningd. In the test process that handler also forwards pyln's own machinery logs into the node's log whenever the test-side logger emits at DEBUG. In particular wait_for_logs() announces 'Waiting for [pattern]' with the pattern embedded verbatim, so the announcement lands in the very log being scanned and matches itself, silently reducing the wait to a no-op. That let test_sendpay_notifications_nowaiter race its channel close against the first payment (both payments then fail and the success assertion sees an empty list); any literal-pattern wait_for_log on an inline-plugin node is similarly voided under DEBUG logging. Attach a filter to the inline plugin's log handler that only forwards records originating outside the pyln packages, so author logging still reaches the node log but pyln internals never do. The new test covers both directions: an author log line is found by wait_for_log, and a never-logged sentinel genuinely times out (it matched instantly via the forwarded announcement before this fix). Fixes: ElementsProject#9343 Changelog-None
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes #9343.
An inline plugin's
Plugin()lives in the test process, andPlugin()installs aPluginLogHandleron the root logger so a plugin author'sloggingcalls reach lightningd. In the test process that handler also forwards pyln's own machinery logs into the node's log whenever the test-side logger emits at DEBUG.wait_for_logs()announcesWaiting for [pattern]with the pattern embedded verbatim, so the announcement lands in the very log being scanned and matches itself - the wait silently becomes a no-op. That is what lettest_sendpay_notifications_nowaiterrace its channel close against the first payment (assert 0 == 1); any literal-patternwait_for_logon an inline-plugin node is similarly voided under DEBUG logging, which can mask races in tests that currently pass.The fix attaches a filter to the inline plugin's log handler that only forwards records originating outside the pyln packages: author logging still reaches the node log, pyln internals never do.
The new test proves both directions and reproduces the bug deterministically: before the fix it fails with
DID NOT RAISE TimeoutError(the sentinel wait matched its own announcement); after it, an author-logged marker is still found while the never-logged sentinel genuinely times out.