Repository: bitcoin/bitcoin
File: test/functional/p2p_v2_misbehaving.py (Python)

Code before:
    def set_test_params(self):
        self.num_nodes = 1
        self.extra_args = [["-v2transport=1", "-peertimeout=3"]]

    def run_test(self):
        self.test_earlykeyresponse()
        self.test_v2disconnection()

    def test_earlykeyresponse(self):
        self.log.info('Sending ellswift bytes in parts to ensure that response from responder is received only when')
        self.log.info('ellswift bytes have a mismatch from the 16 bytes(network magic followed by "version\\x00\\x00\\x00\\x00\\x00")')
        node0 = self.nodes[0]
        self.log.info('Sending first 4 bytes of ellswift which match network magic')
        self.log.info('If a response is received, assertion failure would happen in our custom data_received() function')
        peer1 = node0.add_p2p_connection(MisbehavingV2Peer(TestType.EARLY_KEY_RESPONSE), wait_for_verack=False, send_version=False, supports_v2_p2p=True, wait_for_v2_handshake=False)
        peer1.send_raw_message(MAGIC_BYTES['regtest'])
        self.log.info('Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is')
        self.log.info('expected now, our custom data_received() function wouldn\'t result in assertion failure')
        peer1.v2_state.can_data_be_received = True
        peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
        with node0.assert_debug_log(['V2 handshake timeout peer=0']):
            peer1.wait_for_disconnect(timeout=5)
        self.log.info('successful disconnection since modified ellswift was sent as response')

    def test_v2disconnection(self):
        # test v2 disconnection scenarios
        node0 = self.nodes[0]
        expected_debug_message = [
            [],  # EARLY_KEY_RESPONSE
            ["V2 transport error: missing garbage terminator, peer=1"],  # EXCESS_GARBAGE
            ["V2 handshake timeout peer=2"],  # WRONG_GARBAGE_TERMINATOR
            ["V2 transport error: packet decryption failure"],  # WRONG_GARBAGE
            ["V2 transport error: packet decryption failure"],  # SEND_NO_AAD
            [],  # SEND_NON_EMPTY_VERSION_PACKET
        ]
        for test_type in TestType:
            if test_type == TestType.EARLY_KEY_RESPONSE:
                continue
            elif test_type == TestType.SEND_NON_EMPTY_VERSION_PACKET:
                node0.add_p2p_connection(MisbehavingV2Peer(test_type), wait_for_verack=True, send_version=True, supports_v2_p2p=True)
                self.log.info(f"No disconnection for {test_type.name}")
            else:
                with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=5):
                    peer = node0.add_p2p_connection(MisbehavingV2Peer(test_type), wait_for_verack=False, send_version=False, supports_v2_p2p=True, expect_success=False)
                    peer.wait_for_disconnect()
                self.log.info(f"Expected disconnection for {test_type.name}")


if __name__ == '__main__':
    EncryptedP2PMisbehaving().main()


Review comment (bug):
`3` is the peer timeout, so you'll have to change it to bump `2` here. Otherwise, the test will fail:


https://cirrus-ci.com/task/5359619151757312?logs=ci#L3935


```
 test  2024-07-17T05:25:54.632000Z TestFramework.p2p (DEBUG): Connected & Listening: 127.0.0.1:15680 
 node0 2024-07-17T05:25:54.634738Z (mocktime: 2024-07-17T05:25:54Z) [net] [net.cpp:3764] [CNode] [net] Added connection peer=0 
 node0 2024-07-17T05:25:54.634776Z (mocktime: 2024-07-17T05:25:54Z) [net] [net.cpp:1814] [CreateNodeFromAcceptedSocket] [net] connection from 127.0.0.1:35786 accepted 
 test  2024-07-17T05:25:54.637000Z TestFramework.p2p (DEBUG): sending 3973 bytes of garbage data 
 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is 
 test  2024-07-17T05:25:54.682000Z TestFramework (INFO): expected now, our custom data_received() function wouldn't result in assertion failure 
 node0 2024-07-17T05:25:54.683023Z (mocktime: 2024-07-17T05:25:54Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.686396Z (mocktime: 2024-07-17T05:25:54Z) [httpworker.0] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2024-07-17T05:25:54.686869Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.686921Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=getpeerinfo user=__cookie__ 
 node0 2024-07-17T05:25:54.687051Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_vRecv, net.cpp:630 started 
 node0 2024-07-17T05:25:54.687435Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.2] [logging/timer.h:58] [Log] [lock] Enter: lock contention cs_vRecv, net.cpp:630 completed (370μs) 
 test  2024-07-17T05:25:54.688000Z TestFramework.p2p (DEBUG): Closed connection to: 127.0.0.1:15680 
 node0 2024-07-17T05:25:54.688100Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276 
 node0 2024-07-17T05:25:54.688149Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__ 
 node0 2024-07-17T05:25:54.688344Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:1971] [InactivityCheck] [net] socket no message in first 3 seconds, 1 0 peer=0 
 node0 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0 
 node0 2024-07-17T05:25:54.688685Z (mocktime: 2024-07-17T05:25:58Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0 
 node0 2024-07-17T05:26:39.522126Z (mocktime: 2024-07-17T05:25:58Z) [scheduler] [net.cpp:2369] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers 
 test  2024-07-17T05:27:14.735000Z TestFramework (ERROR): Assertion failed 
                                   Traceback (most recent call last):
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 132, in main
                                       self.run_test()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 133, in run_test
                                       self.test_earlykeyresponse()
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/p2p_v2_misbehaving.py", line 153, in test_earlykeyresponse
                                       with node0.assert_debug_log(['V2 handshake timeout peer=0']):
                                     File "/usr/lib/python3.12/contextlib.py", line 144, in __exit__
                                       next(self.gen)
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 506, in assert_debug_log
                                       self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
                                     File "/ci_container_base/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 192, in _raise_assertion_error
                                       raise AssertionError(self._node_msg(msg))
                                   AssertionError: [node 0] Expected messages "['V2 handshake timeout peer=0']" does not partially match log:
                                    - 2024-07-17T05:25:54.688100Z (mocktime: 2024-07-17T05:25:57Z) [http] [httpserver.cpp:305] [http_request_cb] [http] Received a POST request for / from 127.0.0.1:59276
                                    - 2024-07-17T05:25:54.688149Z (mocktime: 2024-07-17T05:25:57Z) [httpworker.3] [rpc/request.cpp:232] [parse] [rpc] ThreadRPCServer method=setmocktime user=__cookie__
                                    - 2024-07-17T05:25:54.688344Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:1971] [InactivityCheck] [net] socket no message in first 3 seconds, 1 0 peer=0
                                    - 2024-07-17T05:25:54.688378Z (mocktime: 2024-07-17T05:25:58Z) [net] [net.cpp:554] [CloseSocketDisconnect] [net] disconnecting peer=0
                                    - 2024-07-17T05:25:54.688685Z (mocktime: 2024-07-17T05:25:58Z) [net] [net_processing.cpp:1771] [FinalizeNode] [net] Cleared nodestate for peer=0
                                    - 2024-07-17T05:26:39.522126Z (mocktime: 2024-07-17T05:25:58Z) [scheduler] [net.cpp:2369] [StartExtraBlockRelayPeers] [net] enabling extra block-relay-only peers

Code after:
class EncryptedP2PMisbehaving(BitcoinTestFramework):
    def set_test_params(self):
        self.num_nodes = 1
        self.extra_args = [["-v2transport=1", "-peertimeout=3"]]

    def run_test(self):
        self.test_earlykeyresponse()
        self.test_v2disconnection()

    def test_earlykeyresponse(self):
        self.log.info('Sending ellswift bytes in parts to ensure that response from responder is received only when')
        self.log.info('ellswift bytes have a mismatch from the 16 bytes(network magic followed by "version\\x00\\x00\\x00\\x00\\x00")')
        node0 = self.nodes[0]
        node0.setmocktime(int(time.time()))
        self.log.info('Sending first 4 bytes of ellswift which match network magic')
        self.log.info('If a response is received, assertion failure would happen in our custom data_received() function')
        peer1 = node0.add_p2p_connection(MisbehavingV2Peer(TestType.EARLY_KEY_RESPONSE), wait_for_verack=False, send_version=False, supports_v2_p2p=True, wait_for_v2_handshake=False)
        peer1.send_raw_message(MAGIC_BYTES['regtest'])
        self.log.info('Sending remaining ellswift and garbage which are different from V1_PREFIX. Since a response is')
        self.log.info('expected now, our custom data_received() function wouldn\'t result in assertion failure')
        peer1.v2_state.can_data_be_received = True
        self.wait_until(lambda: peer1.v2_state.ellswift_ours)
        peer1.send_raw_message(peer1.v2_state.ellswift_ours[4:] + peer1.v2_state.sent_garbage)
        node0.bumpmocktime(3)
        # Ensure that the bytes sent after 4 bytes network magic are actually received.
        self.wait_until(lambda: node0.getpeerinfo()[-1]["bytesrecv"] > 4)
        with node0.assert_debug_log(['V2 handshake timeout peer=0']):
            node0.bumpmocktime(1)  # `InactivityCheck()` triggers now
            peer1.wait_for_disconnect(timeout=1)
        self.log.info('successful disconnection since modified ellswift was sent as response')

    def test_v2disconnection(self):
        # test v2 disconnection scenarios
        node0 = self.nodes[0]
        expected_debug_message = [
            [],  # EARLY_KEY_RESPONSE
            ["V2 transport error: missing garbage terminator, peer=1"],  # EXCESS_GARBAGE
            ["V2 handshake timeout peer=3"],  # WRONG_GARBAGE_TERMINATOR
            ["V2 transport error: packet decryption failure"],  # WRONG_GARBAGE
            ["V2 transport error: packet decryption failure"],  # SEND_NO_AAD
            [],  # SEND_NON_EMPTY_VERSION_PACKET
        ]
        for test_type in TestType:
            if test_type == TestType.EARLY_KEY_RESPONSE:
                continue
            elif test_type == TestType.SEND_NON_EMPTY_VERSION_PACKET:
                node0.add_p2p_connection(MisbehavingV2Peer(test_type), wait_for_verack=True, send_version=True, supports_v2_p2p=True)
                self.log.info(f"No disconnection for {test_type.name}")
            else:
                with node0.assert_debug_log(expected_debug_message[test_type.value], timeout=5):
                    node0.setmocktime(int(time.time()))