Merge #19272: net, test: invalid p2p messages and test framework improvements

56010f9256 test: hoist p2p values to test framework constants (Jon Atack)
75447f0893 test: improve msg sends and p2p disconnections in p2p_invalid_messages (Jon Atack)
57960192a5 test: refactor test_large_inv() into 3 tests with common method (Jon Atack)
e2b21d8a59 test: add p2p_invalid_messages logging (Jon Atack)
9fa494dc09 net: update misbehavior logging for oversized messages (Jon Atack)

Pull request description:

  ...seen while reviewing #19264, #19252, #19304 and #19107:

  in `net_processing.cpp`
  - make the debug logging for oversized message size misbehavior the same for `addr`, `getdata`, `headers` and `inv` messages

  in `p2p_invalid_messages`
  - add missing logging
  - improve assertions/message sends, move cleanup disconnections outside the assertion scopes
  - split a slowish 3-part test into 3 order-independent tests
  - add a few p2p constants to the test framework

ACKs for top commit:
  troygiorshev:
    reACK 56010f9256
  MarcoFalke:
    ACK 56010f9256 🎛

Tree-SHA512: db67b70278f8d4c318907e105af54b54eb3afd15500f9aa0c98034f6fd4bd1cf9ad1663037bd9b237ff4890f3059b37291a6498d8d6ae2cc38efb9f045f73310

src/net_processing.cpp

@@ -2454,7 +2454,7 @@ void ProcessMessage(
         if (vAddr.size() > 1000)
         {
             LOCK(cs_main);
-            Misbehaving(pfrom.GetId(), 20, strprintf("message addr size() = %u", vAddr.size()));
+            Misbehaving(pfrom.GetId(), 20, strprintf("addr message size = %u", vAddr.size()));
             return;
         }
 
@@ -2530,7 +2530,7 @@ void ProcessMessage(
         if (vInv.size() > MAX_INV_SZ)
         {
             LOCK(cs_main);
-            Misbehaving(pfrom.GetId(), 20, strprintf("message inv size() = %u", vInv.size()));
+            Misbehaving(pfrom.GetId(), 20, strprintf("inv message size = %u", vInv.size()));
             return;
         }
 
@@ -2596,7 +2596,7 @@ void ProcessMessage(
         if (vInv.size() > MAX_INV_SZ)
         {
             LOCK(cs_main);
-            Misbehaving(pfrom.GetId(), 20, strprintf("message getdata size() = %u", vInv.size()));
+            Misbehaving(pfrom.GetId(), 20, strprintf("getdata message size = %u", vInv.size()));
             return;
         }
 

test/functional/p2p_addr_relay.py

@@ -49,9 +49,9 @@ class AddrTest(BitcoinTestFramework):
         addr_source = self.nodes[0].add_p2p_connection(P2PInterface())
         msg = msg_addr()
 
-        self.log.info('Send too large addr message')
+        self.log.info('Send too-large addr message')
         msg.addrs = ADDRS * 101
-        with self.nodes[0].assert_debug_log(['message addr size() = 1010']):
+        with self.nodes[0].assert_debug_log(['addr message size = 1010']):
             addr_source.send_and_ping(msg)
 
         self.log.info('Check that addr message content is relayed and added to addrman')

test/functional/p2p_invalid_messages.py

@@ -7,6 +7,9 @@
 from test_framework.messages import (
     CBlockHeader,
     CInv,
+    MAX_HEADERS_RESULTS,
+    MAX_INV_SIZE,
+    MAX_PROTOCOL_MESSAGE_LENGTH,
     msg_getdata,
     msg_headers,
     msg_inv,
@@ -24,8 +27,7 @@ from test_framework.util import (
     wait_until,
 )
 
-MSG_LIMIT = 4 * 1000 * 1000  # 4MB, per MAX_PROTOCOL_MESSAGE_LENGTH
-VALID_DATA_LIMIT = MSG_LIMIT - 5  # Account for the 5-byte length prefix
+VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5  # Account for the 5-byte length prefix
 
 class msg_unrecognized:
     """Nonsensical message. Modeled after similar types in test_framework.messages."""
@@ -53,11 +55,13 @@ class InvalidMessagesTest(BitcoinTestFramework):
         self.test_checksum()
         self.test_size()
         self.test_msgtype()
-        self.test_large_inv()
+        self.test_oversized_inv_msg()
+        self.test_oversized_getdata_msg()
+        self.test_oversized_headers_msg()
         self.test_resource_exhaustion()
 
     def test_buffer(self):
-        self.log.info("Test message with header split across two buffers, should be received")
+        self.log.info("Test message with header split across two buffers is received")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         # Create valid message
         msg = conn.build_message(msg_ping(nonce=12345))
@@ -76,6 +80,7 @@ class InvalidMessagesTest(BitcoinTestFramework):
         self.nodes[0].disconnect_p2ps()
 
     def test_magic_bytes(self):
+        self.log.info("Test message with invalid magic bytes disconnects peer")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         with self.nodes[0].assert_debug_log(['PROCESSMESSAGE: INVALID MESSAGESTART badmsg']):
             msg = conn.build_message(msg_unrecognized(str_data="d"))
@@ -83,9 +88,10 @@ class InvalidMessagesTest(BitcoinTestFramework):
             msg = b'\xff' * 4 + msg[4:]
             conn.send_raw_message(msg)
             conn.wait_for_disconnect(timeout=1)
-            self.nodes[0].disconnect_p2ps()
+        self.nodes[0].disconnect_p2ps()
 
     def test_checksum(self):
+        self.log.info("Test message with invalid checksum logs an error")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         with self.nodes[0].assert_debug_log(['CHECKSUM ERROR (badmsg, 2 bytes), expected 78df0a04 was ffffffff']):
             msg = conn.build_message(msg_unrecognized(str_data="d"))
@@ -93,21 +99,22 @@ class InvalidMessagesTest(BitcoinTestFramework):
             cut_len = 4 + 12 + 4
             # modify checksum
             msg = msg[:cut_len] + b'\xff' * 4 + msg[cut_len + 4:]
-            self.nodes[0].p2p.send_raw_message(msg)
+            conn.send_raw_message(msg)
             conn.sync_with_ping(timeout=1)
-            self.nodes[0].disconnect_p2ps()
+        self.nodes[0].disconnect_p2ps()
 
     def test_size(self):
+        self.log.info("Test message with oversized payload disconnects peer")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         with self.nodes[0].assert_debug_log(['']):
-            # Create a message with oversized payload
             msg = msg_unrecognized(str_data="d" * (VALID_DATA_LIMIT + 1))
             msg = conn.build_message(msg)
-            self.nodes[0].p2p.send_raw_message(msg)
+            conn.send_raw_message(msg)
             conn.wait_for_disconnect(timeout=1)
-            self.nodes[0].disconnect_p2ps()
+        self.nodes[0].disconnect_p2ps()
 
     def test_msgtype(self):
+        self.log.info("Test message with invalid message type logs an error")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         with self.nodes[0].assert_debug_log(['PROCESSMESSAGE: ERRORS IN HEADER']):
             msg = msg_unrecognized(str_data="d")
@@ -115,44 +122,52 @@ class InvalidMessagesTest(BitcoinTestFramework):
             msg = conn.build_message(msg)
             # Modify msgtype
             msg = msg[:7] + b'\x00' + msg[7 + 1:]
-            self.nodes[0].p2p.send_raw_message(msg)
+            conn.send_raw_message(msg)
             conn.sync_with_ping(timeout=1)
-            self.nodes[0].disconnect_p2ps()
-
-    def test_large_inv(self):
-        conn = self.nodes[0].add_p2p_connection(P2PInterface())
-        with self.nodes[0].assert_debug_log(['Misbehaving', '(0 -> 20): message inv size() = 50001']):
-            msg = msg_inv([CInv(MSG_TX, 1)] * 50001)
-            conn.send_and_ping(msg)
-        with self.nodes[0].assert_debug_log(['Misbehaving', '(20 -> 40): message getdata size() = 50001']):
-            msg = msg_getdata([CInv(MSG_TX, 1)] * 50001)
-            conn.send_and_ping(msg)
-        with self.nodes[0].assert_debug_log(['Misbehaving', '(40 -> 60): headers message size = 2001']):
-            msg = msg_headers([CBlockHeader()] * 2001)
-            conn.send_and_ping(msg)
         self.nodes[0].disconnect_p2ps()
 
+    def test_oversized_msg(self, msg, size):
+        msg_type = msg.msgtype.decode('ascii')
+        self.log.info("Test {} message of size {} is logged as misbehaving".format(msg_type, size))
+        with self.nodes[0].assert_debug_log(['Misbehaving', '{} message size = {}'.format(msg_type, size)]):
+            self.nodes[0].add_p2p_connection(P2PInterface()).send_and_ping(msg)
+        self.nodes[0].disconnect_p2ps()
+
+    def test_oversized_inv_msg(self):
+        size = MAX_INV_SIZE + 1
+        self.test_oversized_msg(msg_inv([CInv(MSG_TX, 1)] * size), size)
+
+    def test_oversized_getdata_msg(self):
+        size = MAX_INV_SIZE + 1
+        self.test_oversized_msg(msg_getdata([CInv(MSG_TX, 1)] * size), size)
+
+    def test_oversized_headers_msg(self):
+        size = MAX_HEADERS_RESULTS + 1
+        self.test_oversized_msg(msg_headers([CBlockHeader()] * size), size)
+
     def test_resource_exhaustion(self):
+        self.log.info("Test node stays up despite many large junk messages")
         conn = self.nodes[0].add_p2p_connection(P2PDataStore())
         conn2 = self.nodes[0].add_p2p_connection(P2PDataStore())
         msg_at_size = msg_unrecognized(str_data="b" * VALID_DATA_LIMIT)
-        assert len(msg_at_size.serialize()) == MSG_LIMIT
+        assert len(msg_at_size.serialize()) == MAX_PROTOCOL_MESSAGE_LENGTH
 
-        self.log.info("Sending a bunch of large, junk messages to test memory exhaustion. May take a bit...")
-
-        # Run a bunch of times to test for memory exhaustion.
+        self.log.info("(a) Send 80 messages, each of maximum valid data size (4MB)")
         for _ in range(80):
             conn.send_message(msg_at_size)
 
         # Check that, even though the node is being hammered by nonsense from one
         # connection, it can still service other peers in a timely way.
+        self.log.info("(b) Check node still services peers in a timely way")
         for _ in range(20):
             conn2.sync_with_ping(timeout=2)
 
-        # Peer 1, despite being served up a bunch of nonsense, should still be connected.
-        self.log.info("Waiting for node to drop junk messages.")
+        self.log.info("(c) Wait for node to drop junk messages, while remaining connected")
         conn.sync_with_ping(timeout=400)
+
+        # Despite being served up a bunch of nonsense, the peers should still be connected.
         assert conn.is_connected
+        assert conn2.is_connected
         self.nodes[0].disconnect_p2ps()
 
 

test/functional/test_framework/messages.py

@@ -45,6 +45,10 @@ MAX_MONEY = 21000000 * COIN
 
 BIP125_SEQUENCE_NUMBER = 0xfffffffd  # Sequence number that is BIP 125 opt-in and BIP 68-opt-out
 
+MAX_PROTOCOL_MESSAGE_LENGTH = 4000000  # Maximum length of incoming protocol messages
+MAX_HEADERS_RESULTS = 2000  # Number of headers sent in one getheaders result
+MAX_INV_SIZE = 50000  # Maximum number of entries in an 'inv' protocol message
+
 NODE_NETWORK = (1 << 0)
 NODE_GETUTXO = (1 << 1)
 NODE_BLOOM = (1 << 2)

test/functional/test_framework/mininode.py

@@ -26,6 +26,7 @@ import threading
 
 from test_framework.messages import (
     CBlockHeader,
+    MAX_HEADERS_RESULTS,
     MIN_VERSION_SUPPORTED,
     msg_addr,
     msg_block,
@@ -553,7 +554,6 @@ class P2PDataStore(P2PInterface):
             return
 
         headers_list = [self.block_store[self.last_block_hash]]
-        maxheaders = 2000
         while headers_list[-1].sha256 not in locator.vHave:
             # Walk back through the block store, adding headers to headers_list
             # as we go.
@@ -569,7 +569,7 @@ class P2PDataStore(P2PInterface):
                 break
 
         # Truncate the list if there are too many headers
-        headers_list = headers_list[:-maxheaders - 1:-1]
+        headers_list = headers_list[:-MAX_HEADERS_RESULTS - 1:-1]
         response = msg_headers(headers_list)
 
         if response is not None: