pyln-testing: don't let wait_for_log match its own forwarded announcement
What the developer wrote
Authored by Ken Sedgwick
pyln-testing: don't let wait_for_log match its own forwarded announcement
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).
The node directory embeds the test name, and this test's long name
pushes inline-plugin.sock past the AF_UNIX bind cap on some runs:
Linux's 108 bytes under liquid-regtest's longer network dir, and
Darwin's 104 with even the default path. Teach _inline_plugin() to
fall back to binding through a short symlink alias to the socket's
directory -- the same technique UnixSocket.connect already uses on
Darwin, aliasing the directory rather than the socket since bind
can't traverse a dangling final-component symlink. The socket file
still lands where the shim's cwd-relative connect expects it. The
test runs in the macOS smoke set too, so CI exercises the fallback on
the platform with the tighter cap.
Fixes: #9343
Changelog-None
What changed, and why it matters
This commit fixes a bug in Core Lightning's Python testing toolkit. When tests used an 'inline plugin' and ran with detailed (DEBUG) logging, the test helper wait_for_log() would accidentally see its own 'Waiting for...' message in the node's log and instantly match it, making the wait useless. This caused a real test failure (test_sendpay_notifications_nowaiter) because a payment raced ahead of channel setup. The patch filters out internal pyln log messages from being forwarded into the node log, so only the plugin author's own log lines go through. It also adds a workaround for long Unix socket paths on macOS/Linux so the new test can run. There is no direct security vulnerability here; it is a test-framework correctness fix that closes a small reliability hole in automated tests.
No immediate security action required. This is a testing-framework reliability fix. Reviewers should verify the filter correctly distinguishes pyln internal paths from plugin author paths and that the symlink fallback cleans up its temporary directory on all error paths.
Security signals we found
Test-framework self-match bug caused real test race and assertion failure
Log forwarding filter prevents internal machinery messages from polluting node logs
No privilege escalation, remote attack surface, or cryptographic weakness introduced
Fixes publicly referenced issue #9343
Evidence from the diff
The change is in contrib/pyln-testing/pyln/testing/utils.py and tests/test_plugin.py. _inline_plugin() now attaches a _NoPylnInternalsFilter to the PluginLogHandler so records whose pathname originates inside pyln packages are not forwarded to the lightningd log. This prevents wait_for_logs()’s ‘Waiting for [pattern]’ line, emitted by pyln-testing internals, from being written into the scanned log and matching itself. The patch also handles AF_UNIX path-too-long errors by binding through a short symlink alias to the socket’s directory. A regression test verifies that an author log line is still forwarded and a never-logged sentinel times out instead of self-matching. The GitHub Actions macOS workflow includes the new test.
Changed components
contrib/pyln-testing/pyln/testing/utils.pytests/test_plugin.py.github/workflows/macos.yamlInspect captured patch +79 / −1
diff --git a/.github/workflows/macos.yaml b/.github/workflows/macos.yaml
index 19af0e0c..9346bb35 100644
--- a/.github/workflows/macos.yaml
+++ b/.github/workflows/macos.yaml
@@ -62,5 +62,6 @@ jobs:
tests/test_misc.py::test_ipv4_and_ipv6
tests/test_connection.py::test_websocket
tests/test_connection.py::test_wss_proxy
+ tests/test_plugin.py::test_inline_plugin_wait_for_log_no_selfmatch
run: |
VALGRIND=0 uv run pytest $PYTEST_TESTS -n $(sysctl -n hw.ncpu) ${PYTEST_OPTS}
diff --git a/contrib/pyln-testing/pyln/testing/utils.py b/contrib/pyln-testing/pyln/testing/utils.py
index a2ab613d..55c327d3 100644
--- a/contrib/pyln-testing/pyln/testing/utils.py
+++ b/contrib/pyln-testing/pyln/testing/utils.py
@@ -12,6 +12,7 @@ from pyln.client import LightningRpc
from pyln.client import Millisatoshi
from pyln.client import NodeVersion
from pyln.client import Plugin
+from pyln.client.plugin import PluginLogHandler
import ephemeral_port_reserve # type: ignore
import tempfile
@@ -2050,6 +2051,26 @@ class NodeFactory(object):
return not unexpected_fail, err_msgs
+class _NoPylnInternalsFilter(logging.Filter):
+ """Drop log records generated inside the pyln packages themselves.
+
+ An inline plugin's Plugin() lives in the test process, so its
+ PluginLogHandler on the root logger would forward pyln's own machinery
+ logs into the node's log. wait_for_logs()'s 'Waiting for [pattern]'
+ announcement embeds the pattern verbatim, lands in the very log being
+ scanned, and matches itself, silently reducing the wait to a no-op.
+ Only records from outside pyln (i.e. the plugin author's own logging)
+ may be forwarded.
+ """
+ PYLN_DIRS = tuple(
+ os.path.dirname(os.path.abspath(f)) + os.sep
+ for f in (__file__,
+ sys.modules[PluginLogHandler.__module__].__file__))
+
+ def filter(self, record):
+ return not os.path.abspath(record.pathname).startswith(self.PYLN_DIRS)
+
+
def _inline_plugin(node, setup_fn):
"""Set up an inline plugin serve thread for a not-yet-started node.
@@ -2069,10 +2090,33 @@ def _inline_plugin(node, setup_fn):
"""
sock_path = os.path.join(node.daemon.lightning_dir, TEST_NETWORK, 'inline-plugin.sock')
srv = socket.socket(socket.AF_UNIX)
- srv.bind(sock_path)
+ try:
+ srv.bind(sock_path)
+ except OSError as e:
+ # AF_UNIX caps the bind path (108 bytes on Linux, 104 on macOS),
+ # and the node dir embeds the (possibly long) test name. Bind
+ # through a short symlink alias to the socket's directory -- the
+ # bind-side analogue of UnixSocket.connect's Darwin workaround
+ # (bind can't go through a dangling final-component symlink, so
+ # alias the directory rather than the socket). The socket file
+ # still lands at sock_path, where the shim's cwd-relative connect
+ # expects it.
+ if e.args[0] != "AF_UNIX path too long":
+ raise
+ alias_dir = tempfile.mkdtemp(prefix='pyln-sock-')
+ alias = os.path.join(alias_dir, 'd')
+ os.symlink(os.path.dirname(sock_path), alias)
+ try:
+ srv.bind(os.path.join(alias, os.path.basename(sock_path)))
+ finally:
+ os.unlink(alias)
+ os.rmdir(alias_dir)
srv.listen(1)
plugin = Plugin(autopatch=False)
+ for handler in logging.getLogger().handlers:
+ if isinstance(handler, PluginLogHandler) and handler.plugin is plugin:
+ handler.addFilter(_NoPylnInternalsFilter())
setup_fn(plugin)
def serve():
diff --git a/tests/test_plugin.py b/tests/test_plugin.py
index 911088b2..783470ac 100644
--- a/tests/test_plugin.py
+++ b/tests/test_plugin.py
@@ -20,6 +20,7 @@ from tests.test_wallet import HsmTool, write_all, WAIT_TIMEOUT
import ast
import copy
import json
+import logging
import os
import pytest
import random
@@ -1803,6 +1804,38 @@ def test_sendpay_notifications_nowaiter(node_factory):
assert len(results['sendpay_failure']) == 1
+def test_inline_plugin_wait_for_log_no_selfmatch(node_factory):
+ """On inline-plugin nodes the test process's logging is forwarded into
+ the node's log. wait_for_log()'s own 'Waiting for [pattern]'
+ announcement embeds the pattern, so with test logging at DEBUG it used
+ to land in the scanned log and match itself, reducing the wait to a
+ no-op (#9343). A pattern that never appears must genuinely time out.
+ """
+ def setup(plugin):
+ @plugin.method('inline_ping')
+ def inline_ping(plugin):
+ logging.info("AUTHOR_LOG_MARKER_9343")
+ return {'pong': True}
+
+ l1 = node_factory.get_node(inline_plugin=setup)
+
+ root = logging.getLogger()
+ old_level = root.level
+ root.setLevel(logging.DEBUG)
+ try:
+ # The plugin author's own logging must still be forwarded...
+ assert l1.rpc.call('inline_ping') == {'pong': True}
+ l1.daemon.wait_for_log('AUTHOR_LOG_MARKER_9343')
+ # ...but pyln's internal announcements must not be, so a pattern
+ # that never appears genuinely times out instead of matching the
+ # forwarded 'Waiting for [pattern]' line.
+ with pytest.raises(TimeoutError):
+ l1.daemon.wait_for_log('SELFMATCH_SENTINEL_NEVER_LOGGED',
+ timeout=5)
+ finally:
+ root.setLevel(old_level)
+
+
def test_rpc_command_hook(node_factory):
"""Test the `rpc_command` hook chain"""
plugin = [
Why this scored 21/100
Community notes
Notes can correct, qualify, or add evidence to the AI analysis. Every note shown here has been validated by a human moderator.
The AI analysis stands alone for now. Submit a note if you can add evidence or important context.