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

@@ -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}

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():

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 = [