Merge bitcoin#21872: net: Sanitize message type for logging

09205b3 net: Clarify message header validation errors (W. J. van der Laan)
955eee7 net: Sanitize message type for logging (W. J. van der Laan)

Pull request description:

  - Use `SanitizeString` when logging message errors to make sure that the message type is sanitized. I have checked all logging in `net.cpp`.

  - For the `MESSAGESTART` error don't inspect and log header details at all: receiving invalid start bytes makes it likely that the packet isn't even formatted as valid P2P message. Logging the four unexpected start bytes (as hex) should be enough.

  - Update `p2p_invalid_messages.py` test to check this.

  - Improve error messages in a second commit.

  Issue reported by gmaxwell.

ACKs for top commit:
  MarcoFalke:
    re-ACK 09205b3 only change is log message fixup 🔂
  practicalswift:
    re-ACK 09205b3

Tree-SHA512: 8fe5326af135cfcf39ea953d9074a8c966b9b85a810b06a2c45b8a745cf115de4f321e72fc769709d6bbecfc5953aab83176db6735b04c0bc6796f59272cadce

src/net.cpp

@@ -768,19 +768,19 @@ int V1TransportDeserializer::readHeader(Span<const uint8_t> msg_bytes)
         hdrbuf >> hdr;
     }
     catch (const std::exception&) {
-        LogPrint(BCLog::NET, "HEADER ERROR - UNABLE TO DESERIALIZE, peer=%d\n", m_node_id);
+        LogPrint(BCLog::NET, "Header error: Unable to deserialize, peer=%d\n", m_node_id);
         return -1;
     }
 
     // Check start string, network magic
     if (memcmp(hdr.pchMessageStart, m_chain_params.MessageStart(), CMessageHeader::MESSAGE_START_SIZE) != 0) {
-        LogPrint(BCLog::NET, "HEADER ERROR - MESSAGESTART (%s, %u bytes), received %s, peer=%d\n", hdr.GetCommand(), hdr.nMessageSize, HexStr(hdr.pchMessageStart), m_node_id);
+        LogPrint(BCLog::NET, "Header error: Wrong MessageStart %s received, peer=%d\n", HexStr(hdr.pchMessageStart), m_node_id);
         return -1;
     }
 
     // reject messages larger than MAX_SIZE or MAX_PROTOCOL_MESSAGE_LENGTH
     if (hdr.nMessageSize > MAX_SIZE || hdr.nMessageSize > MAX_PROTOCOL_MESSAGE_LENGTH) {
-        LogPrint(BCLog::NET, "HEADER ERROR - SIZE (%s, %u bytes), peer=%d\n", hdr.GetCommand(), hdr.nMessageSize, m_node_id);
+        LogPrint(BCLog::NET, "Header error: Size too large (%s, %u bytes), peer=%d\n", SanitizeString(hdr.GetCommand()), hdr.nMessageSize, m_node_id);
         return -1;
     }
 
@@ -833,16 +833,16 @@ std::optional<CNetMessage> V1TransportDeserializer::GetMessage(const std::chrono
 
     // Check checksum and header command string
     if (memcmp(hash.begin(), hdr.pchChecksum, CMessageHeader::CHECKSUM_SIZE) != 0) {
-        LogPrint(BCLog::NET, "CHECKSUM ERROR (%s, %u bytes), expected %s was %s, peer=%d\n",
+        LogPrint(BCLog::NET, "Header error: Wrong checksum (%s, %u bytes), expected %s was %s, peer=%d\n",
                  SanitizeString(msg->m_command), msg->m_message_size,
                  HexStr(Span{hash}.first(CMessageHeader::CHECKSUM_SIZE)),
                  HexStr(hdr.pchChecksum),
                  m_node_id);
         out_err_raw_size = msg->m_raw_message_size;
         msg.reset();
     } else if (!hdr.IsCommandValid()) {
-        LogPrint(BCLog::NET, "HEADER ERROR - COMMAND (%s, %u bytes), peer=%d\n",
-                 hdr.GetCommand(), msg->m_message_size, m_node_id);
+        LogPrint(BCLog::NET, "Header error: Invalid message type (%s, %u bytes), peer=%d\n",
+                 SanitizeString(hdr.GetCommand()), msg->m_message_size, m_node_id);
         out_err_raw_size = msg->m_raw_message_size;
         msg.reset();
     }

test/functional/p2p_invalid_messages.py

@@ -30,7 +30,7 @@
 class msg_unrecognized:
     """Nonsensical message. Modeled after similar types in test_framework.messages."""
 
-    msgtype = b'badmsg'
+    msgtype = b'badmsg\x01'
 
     def __init__(self, *, str_data):
         self.str_data = str_data.encode() if not isinstance(str_data, bytes) else str_data
@@ -81,7 +81,7 @@ def test_buffer(self):
     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(['HEADER ERROR - MESSAGESTART (badmsg, 2 bytes), received ffffffff']):
+        with self.nodes[0].assert_debug_log(['Header error: Wrong MessageStart ffffffff received']):
             msg = conn.build_message(msg_unrecognized(str_data="d"))
             # modify magic bytes
             msg = b'\xff' * 4 + msg[4:]
@@ -92,7 +92,7 @@ def test_magic_bytes(self):
     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']):
+        with self.nodes[0].assert_debug_log(['Header error: Wrong checksum (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
@@ -117,7 +117,7 @@ def test_size(self):
     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(['HEADER ERROR - COMMAND']):
+        with self.nodes[0].assert_debug_log(['Header error: Invalid message type']):
             msg = msg_unrecognized(str_data="d")
             msg = conn.build_message(msg)
             # Modify msgtype