pyln-testing: don't let wait_for_log match its own forwarded announcement

[ksedgwic]

Fixes #9343.

An inline plugin's Plugin() lives in the test process, and Plugin() installs a PluginLogHandler on the root logger so 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. 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 - the wait silently becomes a no-op. That is what let test_sendpay_notifications_nowaiter race its channel close against the first payment (assert 0 == 1); any literal-pattern wait_for_log on 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.

[daywalker90]

=================================== FAILURES ===================================
_________________ test_inline_plugin_wait_for_log_no_selfmatch _________________
[gw0] linux -- Python 3.10.20 /home/runner/work/lightning/lightning/.venv/bin/python

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f8fe41b0fa0>

    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)

tests/test_plugin.py:1817: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
contrib/pyln-testing/pyln/testing/utils.py:1898: in get_node
    _inline_plugin(node, inline_plugin)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

node = <fixtures.LightningNode object at 0x7f8ffe6e3fd0>
setup_fn = <function test_inline_plugin_wait_for_log_no_selfmatch.<locals>.setup at 0x7f8fff4ca560>

    def _inline_plugin(node, setup_fn):
        """Set up an inline plugin serve thread for a not-yet-started node.
    
        Normally called via get_node(inline_plugin=setup_fn).  The plugin's cwd
        (set by lightningd) is node.daemon.lightning_dir/TEST_NETWORK/, which is
        where the shim looks for inline-plugin.sock.
    
        Example::
    
            def setup(plugin):
                @plugin.method('greet')
                def greet(name, plugin):
                    return {'message': f'hello {name}'}
    
            l1 = node_factory.get_node(inline_plugin=setup)
            assert l1.rpc.greet('world') == {'message': 'hello world'}
        """
        sock_path = os.path.join(node.daemon.lightning_dir, TEST_NETWORK, 'inline-plugin.sock')
        srv = socket.socket(socket.AF_UNIX)
>       srv.bind(sock_path)
E       OSError: AF_UNIX path too long

contrib/pyln-testing/pyln/testing/utils.py:2055: OSError
----------------------------- Captured stdout call -----------------------------
{'run_id': 338097548104253440, 'github_repository': 'ElementsProject/lightning', 'github_sha': '751601e833243e0791cdaee4ca3cf428123d3f8b', 'github_ref': 'refs/pull/9344/merge', 'github_ref_name': 'HEAD', 'github_run_id': 29874630952, 'github_head_ref': 'fix-inline-plugin-log-selfmatch', 'github_run_number': 17275, 'github_base_ref': 'master', 'github_run_attempt': '1', 'testname': 'test_inline_plugin_wait_for_log_no_selfmatch', 'start_time': 1784678189, 'end_time': 1784678189, 'outcome': 'fail'}
----- generated xml file: /home/runner/work/lightning/lightning/report.xml -----
============================= slowest 10 durations =============================
475.22s call     test_connection.py::test_networkevents
241.39s call     test_plugin.py::test_plugin_startdir_lol
240.74s call     test_gossip.py::test_gossip_pruning
204.50s call     test_gossip.py::test_gossip_force_broadcast_channel_msgs
149.41s call     test_gossip.py::test_gossip_query_channel_range
129.42s call     test_connection.py::test_last_stable_connection
129.14s call     test_currencyrate.py::test_bkpr_currencyrate_warns_for_old_events
122.48s call     test_plugin.py::test_plugin_command
120.75s call     test_plugin.py::test_plugin_slowinit
120.28s call     test_plugin.py::test_failing_plugins
=========================== short test summary info ============================
FAILED tests/test_plugin.py::test_inline_plugin_wait_for_log_no_selfmatch - OSError: AF_UNIX path too long

AF_UNIX path too long :/

[ksedgwic]

Force-pushed: rebased on current master and fixed the liquid CI failure above.

The test's long name pushed the inline-plugin.sock path past Linux's 108-byte AF_UNIX limit (the node directory embeds the test name, and liquid-regtest is 7 chars longer than regtest, which fit at 106). _inline_plugin() now falls back to binding through a directory fd alias under /proc/self/fd when the direct bind fails, the bind-side analogue of UnixSocket.connect's existing long-path workaround. Verified locally with the default short path and with TEST_DIR padded past the limit to force the fallback.

[daywalker90]

Ideally we want tests to work on macos as well. There the limit is 104 characters.

I asked the clanker and it thinks you can switch into the directory fist and then bind via file name. Directory switching is process wide and in get_nodes we start nodes in parallel. So need to guard with a lock.

# Module-level lock serializing the (chdir, bind) critical section across
# threads. get_nodes() runs get_node() concurrently via a thread pool, and
# os.chdir() is process-wide state, so two inline-plugin binds racing here
# could each end up binding in the wrong directory.
_inline_plugin_bind_lock = threading.Lock()


def _inline_plugin(node, setup_fn):
    """Set up an inline plugin serve thread for a not-yet-started node.

    Normally called via get_node(inline_plugin=setup_fn).  The plugin's cwd
    (set by lightningd) is node.daemon.lightning_dir/TEST_NETWORK/, which is
    where the shim looks for inline-plugin.sock.
    """
    sockdir = os.path.join(node.daemon.lightning_dir, TEST_NETWORK)
    sockname = 'inline-plugin.sock'
    sock_path = os.path.join(sockdir, sockname)

    # AF_UNIX enforces a hard cap on the bind path (108 bytes on Linux,
    # 104 on macOS/BSD), measured on the string passed to bind(), not the
    # resolved absolute path. CI checkout dirs can exceed that, so chdir
    # into the socket's directory and bind with the short relative name
    # instead. The lock protects the chdir from concurrent get_node() calls
    # (get_nodes() runs these in a thread pool).
    srv = socket.socket(socket.AF_UNIX)
    with _inline_plugin_bind_lock:
        old_cwd = os.getcwd()
        os.chdir(sockdir)
        try:
            srv.bind(sockname)
        finally:
            os.chdir(old_cwd)

    # ... rest of listen/accept/serve-thread setup, using sock_path
    # (the absolute path) wherever the socket needs to be referenced
    # afterward, e.g. for cleanup/unlink.

This is the clanker suggestion but i would consider the NodeFactory own lock around the _inline_plugin call at line 1898.

[ksedgwic]

Yes, chdir+lock would work, but the lock would also have to cover every concurrent relative-path use, not just the binds -- e.g. TailableProc.start()'s Popen resolves the relative lightningd/lightningd against the cwd at spawn time, in the other get_nodes() threads. And a future relative-path use that doesn't know about the lock would quietly reintroduce the race as a rare flake.

What about binding through a short symlink alias instead? mkdtemp a short dir, symlink it to the socket's directory, bind alias/inline-plugin.sock, drop the alias. No process-wide state to guard, and it works on macOS too -- it's the same trick UnixSocket.connect already uses on Darwin.

[daywalker90]

Ah yes. That could work!

[ksedgwic]

does this version work for MacOS?

[daywalker90]

I don't have a mac machine myself but can you add

tests/test_plugin.py::test_inline_plugin_wait_for_log_no_selfmatch

to macos.yaml so the CI macos runner can test it?

[ksedgwic]

done, rebased on master as well

[daywalker90]

Thank you so much!

[ksedgwic]

The macOS smoke run passed with the test added ... but other test flaked

[daywalker90]

I fear those are a result of #9298 which just got merged

[ksedgwic]

yeah, my clanker has a suggested fix for it

[ksedgwic]

BTW - I've been leaving the commit's separate for reviewability but would probably squash this if merged

[daywalker90]

Yeah, just squash and we can merge.

[ksedgwic]

squashed