From 8614442aabf54f8b0b3639c6e4939a6e1db38ef5 Mon Sep 17 00:00:00 2001 From: Ken Sedgwick Date: Wed, 29 Jul 2026 10:29:54 -0700 Subject: [PATCH] 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 --- .github/workflows/macos.yaml | 1 + contrib/pyln-testing/pyln/testing/utils.py | 46 +++++++++++++++++++++- tests/test_plugin.py | 33 ++++++++++++++++ 3 files changed, 79 insertions(+), 1 deletion(-) diff --git a/.github/workflows/macos.yaml b/.github/workflows/macos.yaml index 19af0e0cc16e..9346bb357d26 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 a2ab613dbea2..55c327d3b9ec 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 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 @@ def killall(self, expected_successes): 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 greet(name, plugin): """ 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 ae74e1726aff..fe14f93f0893 100644 --- a/tests/test_plugin.py +++ b/tests/test_plugin.py @@ -20,6 +20,7 @@ import ast import copy import json +import logging import os import pytest import random @@ -1803,6 +1804,38 @@ def record_lookup(plugin): 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 = [