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

09205b33aa net: Clarify message header validation errors (W. J. van der Laan)
955eee7680 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 09205b33aa only change is log message fixup 🔂
  practicalswift:
    re-ACK 09205b33aa

Tree-SHA512: 8fe5326af135cfcf39ea953d9074a8c966b9b85a810b06a2c45b8a745cf115de4f321e72fc769709d6bbecfc5953aab83176db6735b04c0bc6796f59272cadce
pull/21890/head
MarcoFalke 4 years ago
commit 5925f1e652
No known key found for this signature in database
GPG Key ID: CE2B75697E69A548

@ -681,19 +681,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;
}
@ -746,7 +746,7 @@ 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<uint8_t>(hash.begin(), hash.begin() + CMessageHeader::CHECKSUM_SIZE)),
HexStr(hdr.pchChecksum),
@ -754,8 +754,8 @@ std::optional<CNetMessage> V1TransportDeserializer::GetMessage(const std::chrono
out_err_raw_size = msg->m_raw_message_size;
msg = std::nullopt;
} 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();
}

@ -37,7 +37,7 @@ VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5 # Account for the 5-byte len
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
@ -104,7 +104,7 @@ class InvalidMessagesTest(BitcoinTestFramework):
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:]
@ -115,7 +115,7 @@ class InvalidMessagesTest(BitcoinTestFramework):
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
@ -130,7 +130,7 @@ class InvalidMessagesTest(BitcoinTestFramework):
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(['HEADER ERROR - SIZE (badmsg, 4000001 bytes)']):
with self.nodes[0].assert_debug_log(['Header error: Size too large (badmsg, 4000001 bytes)']):
msg = msg_unrecognized(str_data="d" * (VALID_DATA_LIMIT + 1))
msg = conn.build_message(msg)
conn.send_raw_message(msg)
@ -140,7 +140,7 @@ class InvalidMessagesTest(BitcoinTestFramework):
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

Loading…
Cancel
Save