Intermittent issue in p2p_private_broadcast.py", line 399, in run_test with tx_originator.assert_debug_log(expected_msgs=[disconnect_msg]): AssertionError: [node 0] ['Disconnecting: does not support transaction relay (connected in vain)'] not found #35843

issue maflcko opened this issue on July 30, 2026
  1. maflcko commented at 7:24 AM on July 30, 2026: member

    https://github.com/bitcoin/bitcoin/actions/runs/30521443556/job/90802607558?pr=35842#step:9:8391:

    test  2026-07-30T07:16:30.579942Z TestFramework (INFO): Checking that a private broadcast destination signaling relay=false gets disconnected 
     node0 2026-07-30T07:16:30.580107Z [http] [httpserver.cpp:1025] [MaybeDispatchRequestsFromClient] [http] Received a POST request for / from 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.580143Z [http.00] [rpc/request.cpp:242] [parse] [rpc] ThreadRPCServer method=getblockchaininfo user=__cookie__ id=230 
     node0 2026-07-30T07:16:30.580204Z [http.00] [httpserver.cpp:616] [WriteReply] [http] HTTPResponse (status code: 200 size: 735) added to send buffer for client 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.580221Z [http.00] [httpserver.cpp:1185] [MaybeSendBytesFromBuffer] [http] Sent 735 bytes to client 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.580582Z [http] [httpserver.cpp:1025] [MaybeDispatchRequestsFromClient] [http] Received a POST request for / from 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.580611Z [http.01] [rpc/request.cpp:242] [parse] [rpc] ThreadRPCServer method=sendrawtransaction user=__cookie__ id=231 
     node0 2026-07-30T07:16:30.580753Z [http.01] [txmempool.cpp:441] [check] [mempool] Checking mempool with 2 transactions and 2 inputs 
     node0 2026-07-30T07:16:30.580848Z [http.01] [net_processing.cpp:2494] [InitiateTxBroadcastPrivate] [privatebroadcast] Requesting 3 new connections due to txid=a9c1c601558eeb36efb16b03a1830c1fec9c94bf50d11d0dfb20de928c1c6006, wtxid=7dd5b6dd06dd68d4d8dd6231104023b479c46106808849d6f25dc609d7748502 
     node0 2026-07-30T07:16:30.580864Z [http.01] [httpserver.cpp:616] [WriteReply] [http] HTTPResponse (status code: 200 size: 212) added to send buffer for client 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.580877Z [http.01] [httpserver.cpp:1185] [MaybeSendBytesFromBuffer] [http] Sent 212 bytes to client 127.0.0.1:45602 (id=0) 
     node0 2026-07-30T07:16:30.680027Z [privbcast] [addrman.cpp:767] [Select_] [addrman] Selected testonlyc377777777777777777777777777777777777777777q.b32.i2p:0 from new 
     node0 2026-07-30T07:16:30.680055Z [privbcast] [net.cpp:404] [ConnectNode] [net] trying v1 connection (private-broadcast) to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0, lastseen=0.0hrs 
     node0 2026-07-30T07:16:30.680069Z [privbcast] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating transient I2P SAM session e707c40180 with 127.0.0.1:1 
     node0 2026-07-30T07:16:30.680114Z [privbcast] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111) 
     node0 2026-07-30T07:16:30.680155Z [privbcast] [i2p.cpp:275] [Connect] [i2p] Error connecting to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0: Cannot connect to 127.0.0.1:1 
     node0 2026-07-30T07:16:30.680167Z [privbcast] [net.cpp:3364] [ThreadPrivateBroadcast] [privatebroadcast] Failed to connect to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0, will retry to a different address; remaining connections to open: 9 
     node0 2026-07-30T07:16:30.782460Z [privbcast] [addrman.cpp:767] [Select_] [addrman] Selected 130.0.0.1:8333 from tried 
     node0 2026-07-30T07:16:30.782480Z [privbcast] [net.cpp:3364] [ThreadPrivateBroadcast] [privatebroadcast] Failed to connect to 130.0.0.1:8333 through the proxy at 127.0.0.1:41007, will retry to a different address; remaining connections to open: 9 
     node0 2026-07-30T07:16:30.815151Z [opencon] [net.cpp:2953] [ThreadOpenConnections] [net] Making feeler connection to [50::1]:8333 
     node0 2026-07-30T07:16:30.815179Z [opencon] [net.cpp:404] [ConnectNode] [net] trying v1 connection (feeler) to [50::1]:8333, lastseen=0.0hrs 
     node0 2026-07-30T07:16:30.815188Z [opencon] [net.cpp:489] [ConnectNode] [proxy] Using proxy: 127.0.0.1:41007 to connect to [50::1]:8333 
     node0 2026-07-30T07:16:30.815245Z [opencon] [netbase.cpp:396] [Socks5] [net] SOCKS5 connecting 50::1 
     node0 2026-07-30T07:16:30.815504Z [opencon] [netbase.cpp:434] [Socks5] [proxy] SOCKS5 sending username/password authentication 
     node0 2026-07-30T07:16:30.815572Z [opencon] [netbase.cpp:514] [Socks5] [net] SOCKS5 connected 50::1 
     test  2026-07-30T07:16:30.815593Z TestFramework.socks5 (DEBUG): Proxy: Socks5Command(1,3,bytearray(b'50::1'),8333,bytearray(b'0e7d197df7c908e0-20'),bytearray(b'0e7d197df7c908e0-20')) 
     node0 2026-07-30T07:16:30.815595Z [opencon] [net.cpp:4112] [CNode] [net] Added connection peer=20 
     node0 2026-07-30T07:16:30.819588Z [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 570dd11089 with 127.0.0.1:1 
     node0 2026-07-30T07:16:30.819634Z [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111) 
     node0 2026-07-30T07:16:30.819663Z [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1 
     test  2026-07-30T07:16:30.821785Z TestFramework.p2p (DEBUG): Listening server on 127.0.0.1:41721 should be started 
     node0 2026-07-30T07:16:30.823560Z [msghand] [net.cpp:4180] [PushMessage] [net] sending version (114 bytes) peer=20 
     node0 2026-07-30T07:16:30.823594Z [msghand] [net_processing.cpp:1692] [PushNodeVersion] [net] send version message: version=70017, blocks=200, txrelay=0, peer=20 
     test  2026-07-30T07:16:30.872173Z TestFramework (DEBUG): Instructing the SOCKS5 proxy to redirect connection i=20 (private-broadcast) for [50::1]:8333 to 127.0.0.1:41721 (Python NoRelayP2PInterface) 
     test  2026-07-30T07:16:30.872270Z TestFramework.socks5 (DEBUG): Serving connection to [50::1]:8333, will redirect it to 127.0.0.1:41721 instead 
     test  2026-07-30T07:16:30.872561Z TestFramework.p2p (DEBUG): Connected: us=127.0.0.1:41721, them=127.0.0.1:57430 
     test  2026-07-30T07:16:30.872692Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:57430: msg_version(nVersion=70017 nServices=1033 nTime=Thu Jul 30 07:16:30 2026 addrTo=CAddress(nServices=9 net=IPv4 addr=0.0.0.1 port=8333) addrFrom=CAddress(nServices=1033 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x5938FA4F8DCAC12B strSubVer=/Satoshi:31.99.0(testnode0)/ nStartingHeight=200 relay=0) 
     test  2026-07-30T07:16:30.872746Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:57430: msg_version(nVersion=70017 nServices=9 nTime=Thu Jul 30 07:16:30 2026 addrTo=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) addrFrom=CAddress(nServices=1 net=IPv4 addr=0.0.0.0 port=0) nNonce=0x41FAEAEC489A927F strSubVer=/python-p2p-tester:0.0.3/ nStartingHeight=-1 relay=0) 
     test  2026-07-30T07:16:30.872786Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:57430: msg_wtxidrelay() 
     test  2026-07-30T07:16:30.872815Z TestFramework.p2p (DEBUG): Send message to 127.0.0.1:57430: msg_verack() 
     node0 2026-07-30T07:16:30.876367Z [msghand] [net_processing.cpp:3809] [ProcessMessage] [net] received: version (111 bytes) peer=20 
     node0 2026-07-30T07:16:30.876392Z [msghand] [net_processing.cpp:3928] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70017, blocks=-1, us=0.0.0.0:0, txrelay=0, peer=20 
     node0 2026-07-30T07:16:30.876397Z [msghand] [net.cpp:4180] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=20 
     node0 2026-07-30T07:16:30.876422Z [msghand] [net.cpp:4180] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=20 
     node0 2026-07-30T07:16:30.876435Z [msghand] [net.cpp:4180] [PushMessage] [net] sending verack (0 bytes) peer=20 
     node0 2026-07-30T07:16:30.876454Z [msghand] [addrman.cpp:657] [Good_] [addrman] Moved [50::1]:8333 to tried[171][20] 
     node0 2026-07-30T07:16:30.876459Z [msghand] [node/timeoffsets.cpp:31] [Add] [net] Added time offset +0s, total samples 11 
     node0 2026-07-30T07:16:30.876466Z [msghand] [net_processing.cpp:4043] [ProcessMessage] [net] feeler connection completed, disconnecting peer=20 
     node0 2026-07-30T07:16:30.876538Z [net] [net.cpp:567] [CloseSocketDisconnect] [net] Resetting socket for peer=20 
     node0 2026-07-30T07:16:30.876561Z [net] [net_processing.cpp:1848] [FinalizeNode] [net] Cleared nodestate for peer=20 
     test  2026-07-30T07:16:30.876661Z TestFramework.socks5 (DEBUG): Handler 20 removed 
     test  2026-07-30T07:16:30.876782Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:57430: msg_wtxidrelay() 
     test  2026-07-30T07:16:30.876829Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:57430: msg_sendaddrv2() 
     test  2026-07-30T07:16:30.876858Z TestFramework.p2p (DEBUG): Received message from 127.0.0.1:57430: msg_verack() 
     test  2026-07-30T07:16:30.876912Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:57430 
     test  2026-07-30T07:16:30.882827Z TestFramework (ERROR): Unexpected exception: 
                                       Traceback (most recent call last):
                                         File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 145, in main
                                           self.run_test()
                                         File "/home/runner/work/bitcoin/bitcoin/ci_build/test/functional/p2p_private_broadcast.py", line 399, in run_test
                                           with tx_originator.assert_debug_log(expected_msgs=[disconnect_msg]):
                                         File "/usr/lib/python3.12/contextlib.py", line 144, in __exit__
                                           next(self.gen)
                                         File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_node.py", line 627, in assert_debug_log
                                           self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} '
                                         File "/home/runner/work/bitcoin/bitcoin/test/functional/test_framework/test_node.py", line 228, in _raise_assertion_error
                                           raise AssertionError(self._node_msg(msg))
                                       AssertionError: [node 0] Expected message(s) ['Disconnecting: does not support transaction relay (connected in vain)'] not found in log:
                                        - 2026-07-30T07:16:30.580582Z [http] [httpserver.cpp:1025] [MaybeDispatchRequestsFromClient] [http] Received a POST request for / from 127.0.0.1:45602 (id=0)
                                        - 2026-07-30T07:16:30.580611Z [http.01] [rpc/request.cpp:242] [parse] [rpc] ThreadRPCServer method=sendrawtransaction user=__cookie__ id=231
                                        - 2026-07-30T07:16:30.580753Z [http.01] [txmempool.cpp:441] [check] [mempool] Checking mempool with 2 transactions and 2 inputs
                                        - 2026-07-30T07:16:30.580848Z [http.01] [net_processing.cpp:2494] [InitiateTxBroadcastPrivate] [privatebroadcast] Requesting 3 new connections due to txid=a9c1c601558eeb36efb16b03a1830c1fec9c94bf50d11d0dfb20de928c1c6006, wtxid=7dd5b6dd06dd68d4d8dd6231104023b479c46106808849d6f25dc609d7748502
                                        - 2026-07-30T07:16:30.580864Z [http.01] [httpserver.cpp:616] [WriteReply] [http] HTTPResponse (status code: 200 size: 212) added to send buffer for client 127.0.0.1:45602 (id=0)
                                        - 2026-07-30T07:16:30.580877Z [http.01] [httpserver.cpp:1185] [MaybeSendBytesFromBuffer] [http] Sent 212 bytes to client 127.0.0.1:45602 (id=0)
                                        - 2026-07-30T07:16:30.680027Z [privbcast] [addrman.cpp:767] [Select_] [addrman] Selected testonlyc377777777777777777777777777777777777777777q.b32.i2p:0 from new
                                        - 2026-07-30T07:16:30.680055Z [privbcast] [net.cpp:404] [ConnectNode] [net] trying v1 connection (private-broadcast) to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0, lastseen=0.0hrs
                                        - 2026-07-30T07:16:30.680069Z [privbcast] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating transient I2P SAM session e707c40180 with 127.0.0.1:1
                                        - 2026-07-30T07:16:30.680114Z [privbcast] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
                                        - 2026-07-30T07:16:30.680155Z [privbcast] [i2p.cpp:275] [Connect] [i2p] Error connecting to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0: Cannot connect to 127.0.0.1:1
                                        - 2026-07-30T07:16:30.680167Z [privbcast] [net.cpp:3364] [ThreadPrivateBroadcast] [privatebroadcast] Failed to connect to testonlyc377777777777777777777777777777777777777777q.b32.i2p:0, will retry to a different address; remaining connections to open: 9
                                        - 2026-07-30T07:16:30.782460Z [privbcast] [addrman.cpp:767] [Select_] [addrman] Selected 130.0.0.1:8333 from tried
                                        - 2026-07-30T07:16:30.782480Z [privbcast] [net.cpp:3364] [ThreadPrivateBroadcast] [privatebroadcast] Failed to connect to 130.0.0.1:8333 through the proxy at 127.0.0.1:41007, will retry to a different address; remaining connections to open: 9
                                        - 2026-07-30T07:16:30.815151Z [opencon] [net.cpp:2953] [ThreadOpenConnections] [net] Making feeler connection to [50::1]:8333
                                        - 2026-07-30T07:16:30.815179Z [opencon] [net.cpp:404] [ConnectNode] [net] trying v1 connection (feeler) to [50::1]:8333, lastseen=0.0hrs
                                        - 2026-07-30T07:16:30.815188Z [opencon] [net.cpp:489] [ConnectNode] [proxy] Using proxy: 127.0.0.1:41007 to connect to [50::1]:8333
                                        - 2026-07-30T07:16:30.815245Z [opencon] [netbase.cpp:396] [Socks5] [net] SOCKS5 connecting 50::1
                                        - 2026-07-30T07:16:30.815504Z [opencon] [netbase.cpp:434] [Socks5] [proxy] SOCKS5 sending username/password authentication
                                        - 2026-07-30T07:16:30.815572Z [opencon] [netbase.cpp:514] [Socks5] [net] SOCKS5 connected 50::1
                                        - 2026-07-30T07:16:30.815595Z [opencon] [net.cpp:4112] [CNode] [net] Added connection peer=20
                                        - 2026-07-30T07:16:30.819588Z [i2paccept] [i2p.cpp:418] [CreateIfNotCreatedAlready] [i2p] Creating persistent I2P SAM session 570dd11089 with 127.0.0.1:1
                                        - 2026-07-30T07:16:30.819634Z [i2paccept] [netbase.cpp:584] [LogConnectFailure] connect() to 127.0.0.1:1 failed after wait: Connection refused (111)
                                        - 2026-07-30T07:16:30.819663Z [i2paccept] [i2p.cpp:152] [Listen] [error] Couldn't listen: Cannot connect to 127.0.0.1:1
                                        - 2026-07-30T07:16:30.823560Z [msghand] [net.cpp:4180] [PushMessage] [net] sending version (114 bytes) peer=20
                                        - 2026-07-30T07:16:30.823594Z [msghand] [net_processing.cpp:1692] [PushNodeVersion] [net] send version message: version=70017, blocks=200, txrelay=0, peer=20
                                        - 2026-07-30T07:16:30.876367Z [msghand] [net_processing.cpp:3809] [ProcessMessage] [net] received: version (111 bytes) peer=20
                                        - 2026-07-30T07:16:30.876392Z [msghand] [net_processing.cpp:3928] [ProcessMessage] [net] receive version message: /python-p2p-tester:0.0.3/: version 70017, blocks=-1, us=0.0.0.0:0, txrelay=0, peer=20
                                        - 2026-07-30T07:16:30.876397Z [msghand] [net.cpp:4180] [PushMessage] [net] sending wtxidrelay (0 bytes) peer=20
                                        - 2026-07-30T07:16:30.876422Z [msghand] [net.cpp:4180] [PushMessage] [net] sending sendaddrv2 (0 bytes) peer=20
                                        - 2026-07-30T07:16:30.876435Z [msghand] [net.cpp:4180] [PushMessage] [net] sending verack (0 bytes) peer=20
                                        - 2026-07-30T07:16:30.876454Z [msghand] [addrman.cpp:657] [Good_] [addrman] Moved [50::1]:8333 to tried[171][20]
                                        - 2026-07-30T07:16:30.876459Z [msghand] [node/timeoffsets.cpp:31] [Add] [net] Added time offset +0s, total samples 11
                                        - 2026-07-30T07:16:30.876466Z [msghand] [net_processing.cpp:4043] [ProcessMessage] [net] feeler connection completed, disconnecting peer=20
                                        - 2026-07-30T07:16:30.876538Z [net] [net.cpp:567] [CloseSocketDisconnect] [net] Resetting socket for peer=20
                                        - 2026-07-30T07:16:30.876561Z [net] [net_processing.cpp:1848] [FinalizeNode] [net] Cleared nodestate for peer=20
    
  2. maflcko added the label CI failed on Jul 30, 2026
  3. fanquake commented at 7:54 AM on July 30, 2026: member
  4. fanquake added the label Private Broadcast on Jul 30, 2026
  5. 151henry151 commented at 12:43 AM on August 1, 2026: contributor

    My brief analysis found this potentially useful information:

    find_connection_type_in_debug_log() returns the first trying v. connection (...) to <addr>:<port> match in the whole log, so once addrman reuses an address the classification goes stale — here [50::1]:8333 was picked up by [opencon] Making feeler connection, got labelled private-broadcast from an earlier attempt to the same address, and the NoRelayP2PInterface was attached to a feeler, which the node then dropped with feeler connection completed, disconnecting peer=20 instead of the expected connected in vain message.

    Taking the last match (or, more robustly, scanning only lines appended since the previous classification) might fix it.

  6. maflcko commented at 7:21 AM on August 2, 2026: member

    so once addrman reuses an address

    Haven't looked here in detail, but is it possible to deterministically reproduce this issue somehow? E.g. with src/addrdb.cpp: bool deterministic = HasTestOption(args, "addrman"); // use a deterministic addrman only for tests

  7. 151henry151 commented at 4:07 PM on August 2, 2026: contributor

    Yes — I was able to reproduce this deterministically on every run (the CI hit still depends on feeler timing; this just removes that dependency).

    The test already uses -test=addrman, so I didn't need to add that; the lever was forcing a feeler to an address that had already been used for private-broadcast.

    From the log in the issue body:

    07:16:21.192308 [privbcast] trying v1 connection (private-broadcast) to [50::1]:8333
    07:16:30.815179 [opencon] trying v1 connection (feeler) to [50::1]:8333
    07:16:30.872173 TestFramework (DEBUG): Instructing the SOCKS5 proxy to redirect connection i=20 (private-broadcast) for [50::1]:8333 to 127.0.0.1:41721 (Python NoRelayP2PInterface)
    

    My reading is that find_connection_type_in_debug_log(), which decides which fake peer to attach, takes the first matching line for an address — so it picked up the 10-second-old private-broadcast line and the no-relay peer ended up on the feeler. The feeler disconnected immediately, the test's wait finished, and the expected "connected in vain" message never appeared, since no real private-broadcast peer was involved in that check. With -proxy set, private broadcast can also pick IPv4/IPv6, so it and feelers (and other automatic outbound) draw from the same clearnet pool, which makes this reuse fairly ordinary rather than a rare coincidence.

    The forced path: after a private-broadcast attempt to a clearnet address, wait for that address to disconnect (addconnection is a no-op while it's still connected), free an outbound slot by disconnecting a peer, then:

    node.addconnection("<that_address>", "feeler", False)
    

    That is enough to get the helper to mislabel the feeler as private-broadcast and attach the no-relay peer every time.

    Reading the last matching line instead fixed it locally and still produced the real "connected in vain" disconnect, though it isn't airtight if two attempts to the same address overlap (narrower window than today, but not closed). Matching the Nth proxy request to the Nth log line for that address would be exact, as would the per-connection SOCKS5 auth token, but the latter needs the token passed into the test helper and logged next to the connection type. I can open a PR for last-match or the Nth-request pairing.

    <details> <summary>Reproduction script (throwaway)</summary>

    #!/usr/bin/env python3
    """
    Throwaway local repro for bitcoin/bitcoin#35843.
    
    Invocation (attach a seed when sharing runs; the feeler is forced via
    addconnection so the failure mode does not depend on feeler timing):
    
      python3 test/functional/p2p_private_broadcast_repro_35843.py \\
          --configfile=build/test/config.ini --loglevel=INFO \\
          --randomseed=556164264432164378
    """
    
    import re
    import threading
    import time
    
    from test_framework.p2p import (
        P2PInterface,
        P2P_SERVICES,
        start_p2p_listener,
    )
    from test_framework.socks5 import (
        start_socks5_server,
    )
    from test_framework.test_framework import (
        BitcoinTestFramework,
    )
    from test_framework.netutil import (
        format_addr_port,
    )
    from test_framework.util import (
        assert_equal,
        tor_port,
    )
    from test_framework.wallet import (
        MiniWallet,
    )
    from test_framework.messages import (
        CAddress,
    )
    
    
    class NoRelayP2PInterface(P2PInterface):
        def peer_connect_send_version(self, services):
            super().peer_connect_send_version(services)
            self.on_connection_send_msg.relay = 0
    
    
    def connection_types_in_debug_log(debug_log_path, to_addr, to_port):
        """Return all connection types logged for to_addr:to_port, in order."""
        # Strip brackets from IPv6 for the regex (log may include them).
        addr = to_addr.strip("[]")
        pattern = re.compile(rf".*trying v. connection \((.+)\) to \[?{re.escape(addr)}\]?:{to_port},.*")
        types = []
        with open(debug_log_path, mode="r", encoding="utf-8") as debug_log:
            for line in debug_log:
                match = pattern.match(line)
                if match:
                    types.append(match.group(1))
        return types
    
    
    def find_connection_type_first(debug_log_path, to_addr, to_port):
        types = connection_types_in_debug_log(debug_log_path, to_addr, to_port)
        return types[0] if types else None
    
    
    def find_connection_type_last(debug_log_path, to_addr, to_port):
        types = connection_types_in_debug_log(debug_log_path, to_addr, to_port)
        return types[-1] if types else None
    
    
    class P2PPrivateBroadcastRepro35843(BitcoinTestFramework):
        def set_test_params(self):
            # Same as p2p_private_broadcast.py: autoconnect required (-connect=0 is
            # incompatible with -privatebroadcast). Outbound slots are freed before
            # forced feelers so addconnection can obtain a semaphore grant.
            self.disable_autoconnect = False
            self.num_nodes = 2
    
        def setup_nodes(self):
            self.destinations = []
            self.destinations_lock = threading.Lock()
            self.trigger_no_relay_peer = False
            self.no_relay_peer = None
            # When True, use last-match classification (proposed fix).
            self.use_last_match = False
    
            def find_connection_type_in_debug_log(to_addr, to_port):
                if self.use_last_match:
                    return find_connection_type_last(self.tx_originator_debug_log_path, to_addr, to_port)
                return find_connection_type_first(self.tx_originator_debug_log_path, to_addr, to_port)
    
            def destinations_factory(requested_to_addr, requested_to_port):
                conn_type = None
    
                def found_connection_in_debug_log():
                    nonlocal conn_type
                    conn_type = find_connection_type_in_debug_log(requested_to_addr, requested_to_port)
                    return conn_type is not None
    
                self.wait_until(found_connection_in_debug_log)
    
                with self.destinations_lock:
                    i = len(self.destinations)
                    if conn_type == "private-broadcast" and not any(
                        dest["conn_type"] == "private-broadcast" for dest in self.destinations
                    ):
                        actual_to_addr = "127.0.0.1"
                        actual_to_port = tor_port(1)
                        target_name = "nodes[1]"
                        listener = None
                    else:
                        if conn_type == "private-broadcast" and self.trigger_no_relay_peer:
                            listener = NoRelayP2PInterface()
                            target_name = "Python NoRelayP2PInterface"
                            self.trigger_no_relay_peer = False
                            self.no_relay_peer = listener
                        else:
                            listener = P2PInterface()
                            target_name = "Python P2PInterface"
                        listener.peer_connect_helper(
                            dstaddr="0.0.0.0", dstport=0, net=self.chain, timeout_factor=self.options.timeout_factor
                        )
                        listener.peer_connect_send_version(services=P2P_SERVICES)
                        actual_to_addr, actual_to_port = start_p2p_listener(self.network_thread, listener)
    
                    self.log.info(
                        f"SOCKS5 redirect i={i} classified={conn_type} for "
                        f"{format_addr_port(requested_to_addr, requested_to_port)} -> {target_name}"
                    )
                    self.destinations.append({
                        "requested_to": format_addr_port(requested_to_addr, requested_to_port),
                        "requested_addr": requested_to_addr,
                        "requested_port": requested_to_port,
                        "conn_type": conn_type,
                        "node": listener,
                        "target_name": target_name,
                    })
                    return {
                        "actual_to_addr": actual_to_addr,
                        "actual_to_port": actual_to_port,
                    }
    
            self.socks5_server = start_socks5_server(destinations_factory)
            self.extra_args = [
                [
                    "-cjdnsreachable",
                    "-v2transport=0",
                    "-test=addrman",
                    "-privatebroadcast",
                    f"-proxy={self.socks5_server.conf.addr[0]}:{self.socks5_server.conf.addr[1]}",
                    "-i2psam=127.0.0.1:1",
                ],
                [
                    "-connect=0",
                    f"-bind=127.0.0.1:{tor_port(1)}=onion",
                ],
            ]
            super().setup_nodes()
            # Available before any SOCKS5 classification (autoconnect may race run_test).
            self.tx_originator_debug_log_path = self.nodes[0].debug_log_path
    
        def setup_network(self):
            self.setup_nodes()
    
        def _find_clearnet_private_broadcast(self):
            with self.destinations_lock:
                for dest in self.destinations:
                    if dest["conn_type"] != "private-broadcast":
                        continue
                    addr = dest["requested_addr"]
                    # Onion / I2P are not useful for the forced-feeler path we want
                    # (addconnection feeler to a clearnet addr that PB already used).
                    if addr.endswith(".onion") or addr.endswith(".i2p"):
                        continue
                    return dest
            return None
    
        def wait_for_clearnet_private_broadcast(self, timeout=30):
            """Wait until a clearnet (IPv4/IPv6) private-broadcast destination exists."""
            deadline = time.time() + timeout
            while time.time() < deadline:
                dest = self._find_clearnet_private_broadcast()
                if dest is not None:
                    return dest
                time.sleep(0.05)
            return None
    
        def run_test(self):
            tx_originator = self.nodes[0]
    
            # Baseline: -test=addrman is already in extra_args.
            assert "-test=addrman" in self.extra_args[0]
            self.log.info("Baseline OK: -test=addrman is enabled")
    
            self.fill_node_addrman(
                node_index=0,
                address_types_to_add=[
                    CAddress.NET_IPV4,
                    CAddress.NET_IPV6,
                    CAddress.NET_TORV3,
                    CAddress.NET_I2P,
                ],
            )
    
            wallet = MiniWallet(tx_originator)
    
            # Trigger private broadcast until we observe a clearnet destination.
            # PickNetwork may choose onion/I2P first; keep submitting txs until we get IPv4/IPv6.
            pb_dest = None
            for _ in range(20):
                tx = wallet.create_self_transfer()
                tx_originator.sendrawtransaction(hexstring=tx["hex"], maxfeerate=0.1)
                pb_dest = self.wait_for_clearnet_private_broadcast()
                if pb_dest is not None:
                    break
                self.log.info("No clearnet private-broadcast yet; submitting another tx")
            assert pb_dest is not None, "failed to observe a clearnet private-broadcast destination"
            reuse_addr = pb_dest["requested_addr"]
            reuse_port = pb_dest["requested_port"]
            self.log.info(f"Collected clearnet private-broadcast addr: {format_addr_port(reuse_addr, reuse_port)}")
    
            addconn_addr = format_addr_port(reuse_addr, reuse_port)
            types_before = connection_types_in_debug_log(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            assert "private-broadcast" in types_before, types_before
            first_before = find_connection_type_first(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            assert_equal(first_before, "private-broadcast")
            self.log.info(f"Types before feeler for reused addr: {types_before}")
    
            # addconnection is a no-op while AlreadyConnectedToHost(pszDest); wait out
            # the prior private-broadcast peer first.
            if pb_dest["node"] is not None:
                self.log.info("Waiting for prior private-broadcast peer to disconnect")
                pb_dest["node"].wait_for_disconnect()
            self.wait_until(lambda: not self._connected_to(tx_originator, addconn_addr), timeout=60)
    
            # --- Step 2: force feeler; prove first vs last ---
            types_after, _ = self._force_feeler_and_wait_logged(
                tx_originator, reuse_addr, reuse_port, addconn_addr
            )
            first_after = find_connection_type_first(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            last_after = find_connection_type_last(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            self.log.info(f"Types after feeler: {types_after}")
            self.log.info(f"FIRST match={first_after} LAST match={last_after}")
            assert_equal(first_after, "private-broadcast")
            assert_equal(last_after, "feeler")
            self.log.info("Step 2 OK: first-match is stale private-broadcast; last-match is feeler")
    
            # --- Step 3: arm no-relay probe; feeler steals NoRelayP2PInterface ---
            self.wait_until(lambda: not self._connected_to(tx_originator, addconn_addr), timeout=60)
            with self.destinations_lock:
                self.no_relay_peer = None
                self.trigger_no_relay_peer = True
                destinations_before_step3 = len(self.destinations)
    
            self.log.info("Arming trigger_no_relay_peer and forcing another feeler")
            _, peer_id = self._force_feeler_and_wait_logged(
                tx_originator, reuse_addr, reuse_port, addconn_addr
            )
    
            self.wait_until(lambda: self.no_relay_peer is not None, timeout=60)
            peer = self.no_relay_peer
            assert isinstance(peer, NoRelayP2PInterface)
            peer.wait_until(lambda: peer.message_count["version"] == 1, check_connected=False)
            peer.wait_for_disconnect()
    
            disconnect_msg = "Disconnecting: does not support transaction relay (connected in vain)"
            if peer_id is None:
                peer_id = self._feeler_peer_id_from_completed_log(reuse_addr, reuse_port)
            assert peer_id is not None, "expected feeler peer id from getpeerinfo or feeler-completed log"
            feeler_done = f"feeler connection completed, disconnecting peer={peer_id}"
            with open(self.tx_originator_debug_log_path, encoding="utf-8") as f:
                log_text = f.read()
            assert feeler_done in log_text, f"missing {feeler_done!r} in debug log"
            with self.destinations_lock:
                stolen = [
                    d for d in self.destinations[destinations_before_step3:]
                    if d["target_name"] == "Python NoRelayP2PInterface"
                    and d["conn_type"] == "private-broadcast"
                    and d["requested_to"] == addconn_addr
                ]
            assert stolen, "expected NoRelayP2PInterface attached under stale private-broadcast classification"
            self.log.info(
                f"Step 3 OK: NoRelayP2PInterface attached to feeler for {addconn_addr} "
                f"(classified as {stolen[-1]['conn_type']})"
            )
            all_types = connection_types_in_debug_log(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            self.log.info(f"REPRO_ADDR={addconn_addr}")
            self.log.info(f"REPRO_TYPES={all_types}")
    
            # --- Step 4: last-match fix — feeler must NOT steal NoRelay ---
            self.wait_until(lambda: not self._connected_to(tx_originator, addconn_addr), timeout=60)
            self.use_last_match = True
            with self.destinations_lock:
                self.no_relay_peer = None
                self.trigger_no_relay_peer = True
                destinations_before = len(self.destinations)
    
            self.log.info("Step 4: last-match enabled; forcing feeler again (must NOT attach NoRelay)")
            self._force_feeler_and_wait_logged(tx_originator, reuse_addr, reuse_port, addconn_addr)
    
            def feeler_destination_seen():
                with self.destinations_lock:
                    for d in self.destinations[destinations_before:]:
                        if d["requested_to"] == addconn_addr and d["conn_type"] == "feeler":
                            return d
                return None
    
            self.wait_until(lambda: feeler_destination_seen() is not None, timeout=60)
            dest = feeler_destination_seen()
            assert_equal(dest["conn_type"], "feeler")
            assert_equal(dest["target_name"], "Python P2PInterface")
            with self.destinations_lock:
                misclassified = [
                    d for d in self.destinations[destinations_before:]
                    if d["requested_to"] == addconn_addr and d["conn_type"] == "private-broadcast"
                ]
            assert not misclassified, (
                f"expected no private-broadcast classification for forced feeler to {addconn_addr}, "
                f"got {misclassified}"
            )
            self.log.info("Step 4 OK: last-match classifies feeler correctly; NoRelay not stolen")
    
            # Real private-broadcast no-relay path still works with last-match.
            self.log.info("Step 4b: genuine private-broadcast no-relay disconnect still works")
            with self.destinations_lock:
                self.no_relay_peer = None
                self.trigger_no_relay_peer = True
            tx2 = wallet.create_self_transfer()
            with tx_originator.assert_debug_log(expected_msgs=[disconnect_msg]):
                tx_originator.sendrawtransaction(hexstring=tx2["hex"], maxfeerate=0.1)
                self.wait_until(lambda: self.no_relay_peer is not None, timeout=120)
                self.no_relay_peer.wait_until(
                    lambda: self.no_relay_peer.message_count["version"] == 1, check_connected=False
                )
                self.no_relay_peer.wait_for_disconnect()
            assert_equal(self.no_relay_peer.message_count, {"version": 1})
            self.log.info("Step 4b OK: connected-in-vain disconnect observed with last-match helper")
    
            self.socks5_server.stop()
            self.log.info("All repro steps passed")
    
        def _connected_to(self, node, addr_port):
            return any(p.get("addr") == addr_port for p in node.getpeerinfo())
    
        def _feeler_peer_id(self, node, addr_port):
            """Return peer id for a live feeler to addr_port via getpeerinfo."""
            for p in node.getpeerinfo():
                if p.get("addr") == addr_port and p.get("connection_type") == "feeler":
                    return p["id"]
            return None
    
        def _feeler_peer_id_from_completed_log(self, to_addr, to_port):
            """Peer id from the latest feeler-completed line after a feeler trying line to addr.
    
            Unlike matching the next 'Added connection peer=' (any thread), this only
            accepts feeler-specific completion lines.
            """
            addr = to_addr.strip("[]")
            trying = re.compile(
                rf".*trying v. connection \(feeler\) to \[?{re.escape(addr)}\]?:{to_port},.*"
            )
            completed = re.compile(r".*feeler connection completed, disconnecting peer=(\d+).*")
            peer_id = None
            pending = False
            with open(self.tx_originator_debug_log_path, encoding="utf-8") as debug_log:
                for line in debug_log:
                    if trying.match(line):
                        pending = True
                        continue
                    if pending:
                        match = completed.match(line)
                        if match:
                            peer_id = int(match.group(1))
                            pending = False
            return peer_id
    
        def _free_outbound_slots(self, node):
            """Disconnect automatic outbound peers so addconnection can take a semOutbound grant."""
            for p in node.getpeerinfo():
                if p.get("connection_type") in (
                    "outbound-full-relay",
                    "block-relay-only",
                    "feeler",
                    "addr-fetch",
                ):
                    try:
                        node.disconnectnode(address=p["addr"])
                    except Exception as e:
                        self.log.debug(f"disconnectnode({p.get('addr')}): {e}")
    
        def _force_feeler_and_wait_logged(self, node, reuse_addr, reuse_port, addconn_addr):
            """Force a feeler; return (types_for_addr, feeler_peer_id_or_None).
    
            Peer id is captured via getpeerinfo during the short-lived feeler window
            when possible (feelers often disconnect within milliseconds).
            """
            before = connection_types_in_debug_log(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            before_feelers = before.count("feeler")
            captured_id = None
            self.log.info(f"Forcing feeler via addconnection to {addconn_addr}")
            # Retry: AddConnection returns success even when OpenNetworkConnection
            # bails on AlreadyConnectedToHost / full outbound semaphore.
            def feeler_logged():
                nonlocal captured_id
                if captured_id is None:
                    captured_id = self._feeler_peer_id(node, addconn_addr)
                types = connection_types_in_debug_log(
                    self.tx_originator_debug_log_path, reuse_addr, reuse_port
                )
                if types.count("feeler") > before_feelers:
                    if captured_id is None:
                        captured_id = self._feeler_peer_id(node, addconn_addr)
                    return True
                self._free_outbound_slots(node)
                if not self._connected_to(node, addconn_addr):
                    try:
                        node.addconnection(addconn_addr, "feeler", False)
                    except Exception as e:
                        self.log.debug(f"addconnection retry: {e}")
                return False
    
            # Tight interval: feelers are often gone from getpeerinfo within ~5ms.
            self.wait_until(feeler_logged, timeout=120, check_interval=0.001)
            types = connection_types_in_debug_log(
                self.tx_originator_debug_log_path, reuse_addr, reuse_port
            )
            return types, captured_id
    
    
    if __name__ == "__main__":
        P2PPrivateBroadcastRepro35843(__file__).main()
    

    Run with:

    python3 test/functional/p2p_private_broadcast_repro_35843.py \
        --configfile=build/test/config.ini --loglevel=INFO \
        --randomseed=556164264432164378
    

    </details>

  8. andrewtoth commented at 5:31 PM on August 2, 2026: contributor

    Thanks @151henry151 I've confirmed your reproducer causes the issue and reading the last match fixes it. I would encourage you to open a PR with the fix. The Nth-request pairing that you suggest is more complex, and probably for little gain. But, up to you if you want to fix it that way as well.

  9. fanquake closed this on Aug 12, 2026

  10. fanquake referenced this in commit 2f72123f61 on Aug 12, 2026

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-08-21 05:51 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me