dash/test/functional/p2p_invalid_messages.py
MarcoFalke 60cfe097be
Merge #18247: test: Wait for both veracks in add_p2p_connection
faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke)
fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke)

Pull request description:

  This fixes the race in p2p_blocksonly

  E.g. https://travis-ci.org/MarcoFalke/bitcoin-core/jobs/657038844#L4500

  ```
   ...
   test  2020-03-01T20:58:28.825000Z TestFramework.mininode (DEBUG): Closed connection to: 127.0.0.1:11828
   node0 2020-03-01T20:58:28.825642Z [net] disconnecting peer=0
   node0 2020-03-01T20:58:28.825826Z [net] Cleared nodestate for peer=0
   node0 2020-03-01T20:58:28.875835Z [http] Received a POST request for / from 127.0.0.1:53448
   node0 2020-03-01T20:58:28.876067Z [httpworker.0] ThreadRPCServer method=getmempoolinfo user=__cookie__
   test  2020-03-01T20:58:28.877000Z TestFramework.mininode (DEBUG): Connecting to Bitcoin Node: 127.0.0.1:11828
   test  2020-03-01T20:58:28.878000Z TestFramework.mininode (DEBUG): Connected & Listening: 127.0.0.1:11828
   test  2020-03-01T20:58:28.878000Z TestFramework.mininode (DEBUG): Send message to 127.0.0.1:11828: msg_version(nVersion=70014 nServices=9 nTime=Sun Mar  1 20:58:28 2020 addrTo=CAddress(nServices=1 ip=127.0.0.1 port=11828) addrFrom=CAddress(nServices=1 ip=0.0.0.0 port=0) nNonce=0x164D5DEB952A4A0B strSubVer=b'/python-mininode-tester:0.0.3/' nStartingHeight=-1 nRelay=1)
   node0 2020-03-01T20:58:28.883808Z [net] Added connection peer=1
   node0 2020-03-01T20:58:28.883950Z [net] connection from 127.0.0.1:33798 accepted
   node0 2020-03-01T20:58:28.884300Z [msghand] received: version (116 bytes) peer=1
   node0 2020-03-01T20:58:28.884483Z [msghand] sending version (114 bytes) peer=1
   node0 2020-03-01T20:58:28.884700Z [msghand] send version message: version 70015, blocks=200, us=[::]:0, peer=1
   node0 2020-03-01T20:58:28.884765Z [msghand] sending verack (0 bytes) peer=1
   test  2020-03-01T20:58:28.885000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_version(nVersion=70015 nServices=1033 nTime=Sun Mar  1 20:58:28 2020 addrTo=CAddress(nServices=0 ip=0.0.0.0 port=0) addrFrom=CAddress(nServices=1033 ip=0.0.0.0 port=0) nNonce=0x4A0F2F4C549B3399 strSubVer=b'/Satoshi:0.19.99(testnode0)/' nStartingHeight=200 nRelay=0)
   test  2020-03-01T20:58:28.885000Z TestFramework.mininode (DEBUG): Send message to 127.0.0.1:11828: msg_verack()
   test  2020-03-01T20:58:28.885000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_verack()
   node0 2020-03-01T20:58:28.885004Z [msghand] receive version message: /python-mininode-tester:0.0.3/: version 70014, blocks=-1, us=127.0.0.1:11828, peer=1
   test  2020-03-01T20:58:28.886000Z TestFramework (INFO): Check that txs from rpc are not rejected and relayed to other peers
   node0 2020-03-01T20:58:28.886556Z [http] Received a POST request for / from 127.0.0.1:53448
   node0 2020-03-01T20:58:28.886783Z [httpworker.1] ThreadRPCServer method=getpeerinfo user=__cookie__
   node0 2020-03-01T20:58:28.889032Z [http] Received a POST request for / from 127.0.0.1:53448
   node0 2020-03-01T20:58:28.889294Z [httpworker.2] ThreadRPCServer method=testmempoolaccept user=__cookie__
   node0 2020-03-01T20:58:28.891655Z [http] Received a POST request for / from 127.0.0.1:53448
   node0 2020-03-01T20:58:28.891963Z [httpworker.3] ThreadRPCServer method=sendrawtransaction user=__cookie__
   node0 2020-03-01T20:58:28.893115Z [httpworker.3] Enqueuing TransactionAddedToMempool: txid=af34fc5ff9ea8babbd4083fbb79ffd2ad5aff1d6def803c07ca5aeed880bd60f wtxid=af34fc5ff9ea8babbd4083fbb79ffd2ad5aff1d6def803c07ca5aeed880bd60f
   node0 2020-03-01T20:58:28.893443Z [scheduler] TransactionAddedToMempool: txid=af34fc5ff9ea8babbd4083fbb79ffd2ad5aff1d6def803c07ca5aeed880bd60f wtxid=af34fc5ff9ea8babbd4083fbb79ffd2ad5aff1d6def803c07ca5aeed880bd60f
   node0 2020-03-01T20:58:28.894814Z [msghand] received: verack (0 bytes) peer=1
   node0 2020-03-01T20:58:28.894937Z [msghand] sending sendheaders (0 bytes) peer=1
   node0 2020-03-01T20:58:28.895087Z [msghand] sending sendcmpct (9 bytes) peer=1
   node0 2020-03-01T20:58:28.895235Z [msghand] sending sendcmpct (9 bytes) peer=1
   node0 2020-03-01T20:58:28.895430Z [msghand] sending ping (8 bytes) peer=1
   node0 2020-03-01T20:58:28.895896Z [msghand] initial getheaders (199) to peer=1 (startheight:-1)
   test  2020-03-01T20:58:28.896000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_sendheaders()
   node0 2020-03-01T20:58:28.896016Z [msghand] sending getheaders (645 bytes) peer=1
   node0 2020-03-01T20:58:28.896607Z [msghand] sending feefilter (8 bytes) peer=1
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_sendcmpct(announce=False, version=2)
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_sendcmpct(announce=False, version=1)
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_ping(nonce=f735096062d217b5)
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Send message to 127.0.0.1:11828: msg_pong(nonce=f735096062d217b5)
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_getheaders(locator=CBlockLocator(nVersion=70014 vHave=[48924041037103782797700918670732352379567180837453042168545380831411841797392, 28010422273815860773972769588722664110955084223364219183119416607410792753789, 5954376895683677137597080246740451260829355661937599865380797589540815086241, 14500403275336359851183244421245184901482464358719551678581030092830439955257, 17853919108052771837249729512111680264864054213441538187113939176285784834878, 28843166929059356839755035875664073555480989477... (msg truncated)
   test  2020-03-01T20:58:28.897000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11828: msg_feefilter(feerate=000003e8)
   node0 2020-03-01T20:58:28.898144Z [msghand] received: pong (8 bytes) peer=1
   node0 2020-03-01T20:59:28.338539Z [scheduler] Feeding 13446 bytes of dynamic environment data into RNG
   test  2020-03-01T20:59:28.908000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
                                             def test_function():
                                                 assert self.is_connected
                                                 if not self.last_message.get('tx'):
                                                     return False
                                                 return self.last_message['tx'].tx.rehash() == txid
                                     '''
   test  2020-03-01T20:59:28.908000Z TestFramework (ERROR): Assertion failed
                                     Traceback (most recent call last):
                                       File "/home/travis/build/MarcoFalke/bitcoin-core/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 112, in main
                                         self.run_test()
                                       File "/home/travis/build/MarcoFalke/bitcoin-core/build/bitcoin-x86_64-pc-linux-gnu/test/functional/p2p_blocksonly.py", line 57, in run_test
                                         self.nodes[0].p2p.wait_for_tx(txid)
                                       File "/home/travis/build/MarcoFalke/bitcoin-core/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/mininode.py", line 369, in wait_for_tx
                                         wait_until(test_function, timeout=timeout, lock=mininode_lock)
                                       File "/home/travis/build/MarcoFalke/bitcoin-core/build/bitcoin-x86_64-pc-linux-gnu/test/functional/test_framework/util.py", line 234, in wait_until
                                         raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
                                     AssertionError: Predicate ''''
                                             def test_function():
                                                 assert self.is_connected
                                                 if not self.last_message.get('tx'):
                                                     return False
                                                 return self.last_message['tx'].tx.rehash() == txid
                                     ''' not true after 60 seconds

ACKs for top commit:
  jonatack:
    ACK faf1d04

Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2022-09-08 00:02:35 +03:00

224 lines
8.4 KiB
Python
Executable File

#!/usr/bin/env python3
# Copyright (c) 2015-2019 The Bitcoin Core developers
# Distributed under the MIT software license, see the accompanying
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
"""Test node responses to invalid network messages."""
import asyncio
import struct
import sys
from test_framework import messages
from test_framework.mininode import P2PDataStore, NetworkThread
from test_framework.test_framework import BitcoinTestFramework
class msg_unrecognized:
"""Nonsensical message. Modeled after similar types in test_framework.messages."""
command = b'badmsg'
def __init__(self, *, str_data):
self.str_data = str_data.encode() if not isinstance(str_data, bytes) else str_data
def serialize(self):
return messages.ser_string(self.str_data)
def __repr__(self):
return "{}(data={})".format(self.command, self.str_data)
class InvalidMessagesTest(BitcoinTestFramework):
def set_test_params(self):
self.num_nodes = 1
self.setup_clean_chain = True
def run_test(self):
"""
. Test msg header
0. Send a bunch of large (3MB) messages of an unrecognized type. Check to see
that it isn't an effective DoS against the node.
1. Send an oversized (3MB+) message and check that we're disconnected.
2. Send a few messages with an incorrect data size in the header, ensure the
messages are ignored.
"""
self.test_magic_bytes()
self.test_checksum()
self.test_size()
self.test_command()
node = self.nodes[0]
self.node = node
node.add_p2p_connection(P2PDataStore())
conn2 = node.add_p2p_connection(P2PDataStore())
msg_limit = 3 * 1024 * 1024 # 3MB, per MAX_PROTOCOL_MESSAGE_LENGTH
valid_data_limit = msg_limit - 5 # Account for the 4-byte length prefix
#
# 0.
#
# Send as large a message as is valid, ensure we aren't disconnected but
# also can't exhaust resources.
#
msg_at_size = msg_unrecognized(str_data="b" * valid_data_limit)
assert len(msg_at_size.serialize()) == msg_limit
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.
for _ in range(80):
node.p2p.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.
for _ in range(20):
conn2.sync_with_ping(timeout=2)
# Peer 1, despite serving up a bunch of nonsense, should still be connected.
self.log.info("Waiting for node to drop junk messages.")
node.p2p.sync_with_ping(timeout=320)
assert node.p2p.is_connected
#
# 1.
#
# Send an oversized message, ensure we're disconnected.
#
# Under macOS this test is skipped due to an unexpected error code
# returned from the closing socket which python/asyncio does not
# yet know how to handle.
#
if sys.platform != 'darwin':
msg_over_size = msg_unrecognized(str_data="b" * (valid_data_limit + 1))
assert len(msg_over_size.serialize()) == (msg_limit + 1)
# An unknown message type (or *any* message type) over
# MAX_PROTOCOL_MESSAGE_LENGTH should result in a disconnect.
node.p2p.send_message(msg_over_size)
node.p2p.wait_for_disconnect(timeout=4)
node.disconnect_p2ps()
conn = node.add_p2p_connection(P2PDataStore())
conn.wait_for_verack()
else:
self.log.info("Skipping test p2p_invalid_messages/1 (oversized message) under macOS")
#
# 2.
#
# Send messages with an incorrect data size in the header.
#
actual_size = 100
msg = msg_unrecognized(str_data="b" * actual_size)
# TODO: handle larger-than cases. I haven't been able to pin down what behavior to expect.
for wrong_size in (2, 77, 78, 79):
self.log.info("Sending a message with incorrect size of {}".format(wrong_size))
# Unmodified message should submit okay.
node.p2p.send_and_ping(msg)
# A message lying about its data size results in a disconnect when the incorrect
# data size is less than the actual size.
#
# TODO: why does behavior change at 78 bytes?
#
node.p2p.send_raw_message(self._tweak_msg_data_size(msg, wrong_size))
# For some reason unknown to me, we sometimes have to push additional data to the
# peer in order for it to realize a disconnect.
try:
node.p2p.send_message(messages.msg_ping(nonce=123123))
except IOError:
pass
node.p2p.wait_for_disconnect(timeout=10)
node.disconnect_p2ps()
node.add_p2p_connection(P2PDataStore())
# Node is still up.
conn = node.add_p2p_connection(P2PDataStore())
def test_magic_bytes(self):
conn = self.nodes[0].add_p2p_connection(P2PDataStore())
async def swap_magic_bytes():
conn._on_data = lambda: None # Need to ignore all incoming messages from now, since they come with "invalid" magic bytes
conn.magic_bytes = b'\x00\x11\x22\x32'
# Call .result() to block until the atomic swap is complete, otherwise
# we might run into races later on
asyncio.run_coroutine_threadsafe(swap_magic_bytes(), NetworkThread.network_event_loop).result()
with self.nodes[0].assert_debug_log(['PROCESSMESSAGE: INVALID MESSAGESTART ping']):
conn.send_message(messages.msg_ping(nonce=0xff))
conn.wait_for_disconnect(timeout=1)
self.nodes[0].disconnect_p2ps()
def test_checksum(self):
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"))
cut_len = (
4 + # magic
12 + # command
4 #len
)
# modify checksum
msg = msg[:cut_len] + b'\xff' * 4 + msg[cut_len + 4:]
self.nodes[0].p2p.send_raw_message(msg)
conn.sync_with_ping(timeout=1)
self.nodes[0].disconnect_p2ps()
def test_size(self):
conn = self.nodes[0].add_p2p_connection(P2PDataStore())
with self.nodes[0].assert_debug_log(['']):
msg = conn.build_message(msg_unrecognized(str_data="d"))
cut_len = (
4 + # magic
12 # command
)
# modify len to MAX_SIZE + 1
msg = msg[:cut_len] + struct.pack("<I", 0x02000000 + 1) + msg[cut_len + 4:]
self.nodes[0].p2p.send_raw_message(msg)
conn.wait_for_disconnect(timeout=1)
self.nodes[0].disconnect_p2ps()
def test_command(self):
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.command = b'\xff' * 12
msg = conn.build_message(msg)
# Modify command
msg = msg[:7] + b'\x00' + msg[7 + 1:]
self.nodes[0].p2p.send_raw_message(msg)
conn.sync_with_ping(timeout=1)
self.nodes[0].disconnect_p2ps()
def _tweak_msg_data_size(self, message, wrong_size):
"""
Return a raw message based on another message but with an incorrect data size in
the message header.
"""
raw_msg = self.node.p2p.build_message(message)
bad_size_bytes = struct.pack("<I", wrong_size)
num_header_bytes_before_size = 4 + 12
# Replace the correct data size in the message with an incorrect one.
raw_msg_with_wrong_size = (
raw_msg[:num_header_bytes_before_size] +
bad_size_bytes +
raw_msg[(num_header_bytes_before_size + len(bad_size_bytes)):]
)
assert len(raw_msg) == len(raw_msg_with_wrong_size)
return raw_msg_with_wrong_size
if __name__ == '__main__':
InvalidMessagesTest().main()