[backport#19272] net, test: invalid p2p messages and test framework i…

…mprovements

Summary:
56010f92564a94b0ca6c008c0e6f74a19fad4a2a test: hoist p2p values to test framework constants (Jon Atack)
75447f0893f9ad9bf83d182b301d139430d8de1c test: improve msg sends and p2p disconnections in p2p_invalid_messages (Jon Atack)
57960192a5362ff1a7b996995332535f4c2a25c3 test: refactor test_large_inv() into 3 tests with common method (Jon Atack)
e2b21d8a597c536a8617408d43958bfe9f98a442 test: add p2p_invalid_messages logging (Jon Atack)
9fa494dc0969c61d5ef33708a08923cca19ce091 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

---

Backport of [[bitcoin/bitcoin#19272 | core#19272]]

Test Plan:
  ninja all check check-functional

Reviewers: #bitcoin_abc, PiRK

Reviewed By: #bitcoin_abc, PiRK

Differential Revision: https://reviews.bitcoinabc.org/D9530

src/net_processing.cpp

@@ -3079,8 +3079,7 @@ void PeerManager::ProcessMessage(const Config &config, CNode &pfrom,
         vRecv >> vInv;
         if (vInv.size() > MAX_INV_SZ) {
             Misbehaving(pfrom, 20,
-                        strprintf("oversized-inv: message inv size() = %u",
-                                  vInv.size()));
+                        strprintf("inv message size = %u", vInv.size()));
             return;
         }
 
@@ -3166,8 +3165,7 @@ void PeerManager::ProcessMessage(const Config &config, CNode &pfrom,
         vRecv >> vInv;
         if (vInv.size() > MAX_INV_SZ) {
             Misbehaving(pfrom, 20,
-                        strprintf("too-many-inv: message getdata size() = %u",
-                                  vInv.size()));
+                        strprintf("getdata message size = %u", vInv.size()));
             return;
         }
 

test/functional/p2p_addr_relay.py

@@ -48,7 +48,7 @@ def run_test(self):
         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(['addr message size = 1010']):
             addr_source.send_and_ping(msg)

test/functional/p2p_invalid_messages.py

@@ -9,6 +9,9 @@
 from test_framework.messages import (
     CBlockHeader,
     CInv,
+    MAX_HEADERS_RESULTS,
+    MAX_INV_SIZE,
+    MAX_PROTOCOL_MESSAGE_LENGTH,
     msg_avahello,
     msg_avapoll,
     msg_avaresponse,
@@ -30,8 +33,8 @@
     wait_until,
 )
 
-MSG_LIMIT = 2 * 1024 * 1024  # 2MB, per MAX_PROTOCOL_MESSAGE_LENGTH
-VALID_DATA_LIMIT = MSG_LIMIT - 5  # Account for the 5-byte length prefix
+# Account for the 5-byte length prefix
+VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5
 
 
 class msg_unrecognized:
@@ -69,13 +72,15 @@ def run_test(self):
         self.test_addrv2_no_addresses()
         self.test_addrv2_too_long_address()
         self.test_addrv2_unrecognized_network()
-        self.test_large_inv()
+        self.test_oversized_inv_msg()
+        self.test_oversized_getdata_msg()
+        self.test_oversized_headers_msg()
         self.test_unsolicited_ava_messages()
         self.test_resource_exhaustion()
 
     def test_buffer(self):
         self.log.info(
-            "Test message with header split across two buffers, should be received")
+            "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))
@@ -96,46 +101,49 @@ def test_buffer(self):
         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"))
             # modify magic bytes
             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"))
             # Checksum is after start bytes (4B), message type (12B), len (4B)
             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.wait_for_disconnect()
-            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")
             msg.msgtype = b'\xff' * 12
             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()
 
@@ -242,19 +250,27 @@ def test_addrv2_unrecognized_network(self):
                              # port
                              '208d'))
 
-    def test_large_inv(self):
-        conn = self.nodes[0].add_p2p_connection(P2PInterface())
-        with self.nodes[0].assert_debug_log(['Misbehaving', '(0 -> 20): oversized-inv: 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): too-many-inv: 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): too-many-headers: headers message size = 2001']):
-            msg = msg_headers([CBlockHeader()] * 2001)
-            conn.send_and_ping(msg)
+    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_unsolicited_ava_messages(self):
         """Node 0 has avalanche disabled by default. If a node does not
         advertise the avalanche service flag, it does not expect to receive
@@ -276,28 +292,31 @@ def test_unsolicited_ava_messages(self):
         self.nodes[0].disconnect_p2ps()
 
     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.
+            "(a) Send 80 messages, each of maximum valid data size (2MB)")
         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

@@ -51,6 +51,11 @@
 COIN = 100000000
 MAX_MONEY = 21000000 * COIN
 
+# Maximum length of incoming protocol messages
+MAX_PROTOCOL_MESSAGE_LENGTH = 2 * 1024 * 1024
+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 @@
 
 from test_framework.messages import (
     CBlockHeader,
+    MAX_HEADERS_RESULTS,
     MIN_VERSION_SUPPORTED,
     msg_addr,
     msg_addrv2,
@@ -646,7 +647,6 @@ def on_getheaders(self, message):
             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.
@@ -664,7 +664,7 @@ def on_getheaders(self, message):
                 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: