…seen while reviewing #19264, #19252, #19304 and #19107:
in net_processing.cpp
addr, getdata, headers and inv messagesin p2p_invalid_messages
112- with self.nodes[0].assert_debug_log(['Misbehaving', 'peer=4 (40 -> 60): headers message size = 2001']):
113- msg = msg_headers([CBlockHeader()] * 2001)
114- conn.send_and_ping(msg)
115+ def test_oversized(self, msg_type, msg, size):
116+ self.log.info("Test {} message of size {} is logged as misbehaving".format(msg_type, size))
117+ with self.nodes[0].assert_debug_log(['Misbehaving', msg_type, str(size)]):
net_processing.cpp the debug logging for misbehaving from headers message size was a bit different from the equivalent misbehavior logging for inv, getdata, and addr message sizes. Fixed. If we don’t want to touch it, we can also have each test pass in their own debug log message to test for.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
Reviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.
145 for _ in range(80):
146 conn.send_message(msg_at_size)
147
148 # Check that, even though the node is being hammered by nonsense from one
149 # connection, it can still service other peers in a timely way.
150+ self.log.info("(b) Check node still services peer in a timely way")
Maybe this should specify “other peers”? As it stands someone may miss the difference between conn and conn2.
0 self.log.info("(b) Check node still services other peers in a timely way")
disconnect_p2ps() call in test_oversized_msg().
test_checksum, test_size, and test_msgtype) self.nodes[0].p2p with conn, all of the subtest disconnect_p2ps can also be removed. The only reason they need it now is to clear p2ps.
disconnect_p2ps calls at the end of each subtest. Ideally the subtest finishes by leaving the node and fixture in as close a state to they were in originally. See #19304 (review)
@jnewbery good point…
Ideally the subtest finishes by leaving the node and fixture in as close a state to they were in originally
In terms of state, I’m thinking state = (1) the test_node.p2ps array and (2) the connections between the node and its peers.
(1) I think it’s ok if the array has an extra entry if we’re not using the .p2p property? Would you agree? If not, then yeah, we need to put disconnect_p2ps() back 😄 .
(2) For connections: Definitely agree that subtests should disconnect peers to clean up after themselves. Either node.disconnect_p2ps or peer.peer_disconnect Some of the subtests call wait_for_disconnect which makes sure that they are disconnected from the peer’s POV (no peer._transport). With #19252,disconnect_p2ps waits for node’s POV (not in node.getpeerinfo()).
I’m not sure if disconnected from peer’s POV == disconnected from the node’s POV. If they’re effectively the same, I’d say it’s unnecessary to call disconnect_p2ps after wait_for_disconnect.
I might be overthinking this haha, I dug into this when I thought superfluous disconnect_p2ps would cause performance problems 😅 .
AFAICT the tests are order-independent with this PR, and I checked that this passes when rebased to current master:
0+from test_framework.util import assert_equal
1
2+ def assert_no_connected_peers(self):
3+ assert_equal(self.nodes[0].num_connected_mininodes(), 0)
4+
5 def run_test(self):
6 self.test_magic_bytes()
7+ self.assert_no_connected_peers()
8 self.test_checksum()
9+ self.assert_no_connected_peers()
10 self.test_size()
11+ self.assert_no_connected_peers()
12 self.test_msgtype()
13+ self.assert_no_connected_peers()
14 self.test_oversized_inv_msg()
15+ self.assert_no_connected_peers()
16 self.test_oversized_getdata_msg()
17+ self.assert_no_connected_peers()
18 self.test_oversized_headers_msg()
19+ self.assert_no_connected_peers()
20 self.test_resource_exhaustion()
21+ self.assert_no_connected_peers()
I generally use the conflicts list of DrahtBot to see which pr has the most reviews and is the most ready to merge and then get them in one by one if they have received their ACKs.
Will take another look here. One sec
42@@ -39,19 +43,22 @@ def __repr__(self):
43 class InvalidMessagesTest(BitcoinTestFramework):
44 def set_test_params(self):
45 self.num_nodes = 1
46- self.setup_clean_chain = True
47+ self.setup_clean_chain = False
There is no new chain generated in this test:
0$ git grep generate 'test/functional/p2p_invalid_messages.py'
1$
21@@ -19,7 +22,8 @@
22 from test_framework.test_framework import BitcoinTestFramework
23
24 MSG_LIMIT = 4 * 1000 * 1000 # 4MB, per MAX_PROTOCOL_MESSAGE_LENGTH
0MSG_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH
Rebased for merged #19304, reverted the chain setting, and removed a line left over from the last change (thanks Marco).
0-MSG_LIMIT = 4 * 1000 * 1000 # 4MB, per MAX_PROTOCOL_MESSAGE_LENGTH
1VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5 # Account for the 5-byte length prefix
2
3- self.setup_clean_chain = False
4+ self.setup_clean_chain = True
3244@@ -3245,7 +3245,7 @@ bool ProcessMessage(CNode& pfrom, const std::string& msg_type, CDataStream& vRec
3245 unsigned int nCount = ReadCompactSize(vRecv);
3246 if (nCount > MAX_HEADERS_RESULTS) {
3247 LOCK(cs_main);
3248- Misbehaving(pfrom.GetId(), 20, strprintf("headers message size = %u", nCount));
3249+ Misbehaving(pfrom.GetId(), 20, strprintf("message headers size() = %u", nCount));
inv, getdata, and addr oversized messages misbehavior logging should be changed instead? Or are they all good as-is (in which case the headers one remains different, and each specific one can be passed into the test_oversized_msg() assertion function from the caller.)
IMO they should all be changed to <type> message size = %u. <type> message because that sounds better to my ear, and size as opposed to size() because we’re talking about the value of the function, not the function itself.
That said, I’ll ACK anything that’s consistent among these 4 logs.
173+ assert len(msg_at_size.serialize()) == MAX_PROTOCOL_MESSAGE_LENGTH
174
175- self.log.info("Sending a bunch of large, junk messages to test memory exhaustion. May take a bit...")
176-
177- # Run a bunch of times to test for memory exhaustion.
178+ self.log.info("(a) Send 80 messages of max data size 4MB to test for memory exhaustion")
26@@ -24,8 +27,8 @@
27 wait_until,
28 )
29
30-MSG_LIMIT = 4 * 1000 * 1000 # 4MB, per MAX_PROTOCOL_MESSAGE_LENGTH
31-VALID_DATA_LIMIT = MSG_LIMIT - 5 # Account for the 5-byte length prefix
32+VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5 # Account for the 5-byte length prefix
33+DISCONNECTING = 'disconnecting peer='
reACK ca658361c7e6a137d1ee8be8a005b35ad0426fa3
Reviewed and stepped through each test. Verified that none of these changes caused linting errors.
134- msg = msg_getdata([CInv(MSG_TX, 1)] * 50001)
135- conn.send_and_ping(msg)
136- with self.nodes[0].assert_debug_log(['Misbehaving', '(40 -> 60): headers message size = 2001']):
137- msg = msg_headers([CBlockHeader()] * 2001)
138- conn.send_and_ping(msg)
139+ def test_oversized_msg(self, msg_type, msg, size):
in commit cb71adbf9338c8a3f8348c936d4c1caa1086a33f:
no need to pass the message type, since the message already knows its own type:
0diff --git a/test/functional/p2p_invalid_messages.py b/test/functional/p2p_invalid_messages.py
1index f1ef5c6414..ad918bf3bb 100755
2--- a/test/functional/p2p_invalid_messages.py
3+++ b/test/functional/p2p_invalid_messages.py
4@@ -124,7 +124,8 @@ class InvalidMessagesTest(BitcoinTestFramework):
5 conn.sync_with_ping(timeout=1)
6 self.nodes[0].disconnect_p2ps()
7
8- def test_oversized_msg(self, msg_type, msg, size):
9+ def test_oversized_msg(self, _, msg, size):
10+ msg_type = msg.msgtype.decode('ascii')
11 self.log.info("Test {} message of size {} is logged as misbehaving".format(msg_type, size))
12 with self.nodes[0].assert_debug_log(['Misbehaving', '{} message size = {}'.format(msg_type, size)]):
13 self.nodes[0].add_p2p_connection(P2PInterface()).send_and_ping(msg)
79@@ -80,49 +80,49 @@ def test_buffer(self):
80 def test_magic_bytes(self):
81 self.log.info("Test message with invalid magic bytes disconnects peer")
82 conn = self.nodes[0].add_p2p_connection(P2PDataStore())
83- with self.nodes[0].assert_debug_log(['PROCESSMESSAGE: INVALID MESSAGESTART badmsg']):
84+ with self.nodes[0].assert_debug_log('PROCESSMESSAGE: INVALID MESSAGESTART badmsg'):
in commit 058dbcec567eb5b6fa780f0adbbd70b421621c38
This must stay an array. Otherwise it will assert nothing.
Thanks, done. I should have verified the method. Am in the long-standing habit of accepting either a string or an array in framework APIs I make, e.g.
0 def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
1+ if type(expected_msgs) == str:
2+ expected_msgs = [expected_msgs]
3+ if type(unexpected_msgs) == str:
4+ unexpected_msgs = [unexpected_msgs]
5 if unexpected_msgs is None:
6 unexpected_msgs = []
: List[str], but for some reason it didn’t complain when I passed a string. Maybe mypy was broken on my machine?
so that oversized ADDR, GETDATA, HEADERS and INV messages print
the same consistent debug logs.
- call disconnect_p2ps() outside of the assert_debug_log scopes
- send messages directly from the p2p conn rather than via nodes[0].p2p
- add an assertion
git range-diff 8ef15e8 98af0f0 56010f9
26@@ -24,8 +27,7 @@
27 wait_until,
28 )
29
30-MSG_LIMIT = 4 * 1000 * 1000 # 4MB, per MAX_PROTOCOL_MESSAGE_LENGTH
31-VALID_DATA_LIMIT = MSG_LIMIT - 5 # Account for the 5-byte length prefix
32+VALID_DATA_LIMIT = MAX_PROTOCOL_MESSAGE_LENGTH - 5 # Account for the 5-byte length prefix
ser_string() in messages.py. But is it something that the node also recognizes? It doesn’t seem to be part of the p2p protocol.
We set VALID_DATA_LIMIT so that the length of the serialised msg_unrecognized message built with it will equal MAX_PROTOCOL_MESSAGE_LENGTH. This is verified at line 153; you can also add the following assertion at line 111
0 msg = msg_unrecognized(str_data="d" * (VALID_DATA_LIMIT + 1))
1+ assert_equal(len(msg.serialize()), MAX_PROTOCOL_MESSAGE_LENGTH + 1)
or try changing the offset from 5 to 4 or 6.
I’ve added this assertion and some other ones while testing @troygiorshev’s net message headers refactoring and may propose the changes if they look worthwhile to me after a few days’ time.
174-
175- self.log.info("Sending a bunch of large, junk messages to test memory exhaustion. May take a bit...")
176+ assert len(msg_at_size.serialize()) == MAX_PROTOCOL_MESSAGE_LENGTH
177
178- # Run a bunch of times to test for memory exhaustion.
179+ self.log.info("(a) Send 80 messages, each of maximum valid data size (4MB)")
“junk messages” is stated in the log immediately beforehand:
02020-06-25 ... TestFramework (INFO): Test node stays up despite many large junk messages
12020-06-25 ... TestFramework (INFO): (a) Send 80 messages, each of maximum valid data size (4MB)
22020-06-25 ... TestFramework (INFO): (b) Check node still services peers in a timely way
32020-06-25 ... TestFramework (INFO): (c) Wait for node to drop junk messages, while remaining connected
ACK 56010f9256 🎛
Signature:
0-----BEGIN PGP SIGNED MESSAGE-----
1Hash: SHA512
2
3ACK 56010f9256 🎛
4-----BEGIN PGP SIGNATURE-----
5
6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
7pUicWwv+KIsi9o22/6uZbUTRM0UsyIPesQTV0ZcUzpXX8Sz27WY/psDv60xlD3+W
8eUGgldLLYL1EBH8wWRbyMWsQ4WFQJILWXl6+8Cr2b8Lv9N1NhJ/z+u+FLfHHMlXt
9dRxOMXXsytLgH8g3eW8f7zWbH0RaHtre+gcBiYqWAEbzq4i8D8h4lEO8ggA5c9TC
10iGgj4ACk04YvOXDTOOgfF4DJQXIn3CuHrh7y55zo5X7+hZp43YEDRaVtKnggLTiM
11dXZ3r3p+6i4Wqn2uFiZuw06rJN6PtSPEcBa8T3dmGVHixzPlXV5W3aILjU9TUGSV
12tMoysA6J0N/RPZVEL0pucUOjrJPB3l6ULSEnl4anjC9rvURvaWJogqwJ5Fa/73Tq
13OAFMkcO5iZod95zCDr6Alt34VI7nsJ//rej6/qpkeOSNc6vhQFbuSPaj5QNo/2Sc
14BF2ySsHCMluT0JrkGY8EYvMUJka5cO7D894tRvaudfhn6wWT2mNc/E+95LTsGflG
15EWs3YKPd
16=Yt/T
17-----END PGP SIGNATURE-----
Timestamp of file with hash 937d2e5bea5f5ff38ae343e4664be89319c7ac06458b75aca1a579bbd3abbcd1 -