test: Check that message sends successfully when header is split across two buffers

troygiorshev commented at 3:03 pm on June 17, 2020: contributor

This PR is a tweak of #19302. This sends a valid message.

Additionally, this test includes logging in the same vein as #19272.

fanquake added the label Tests on Jun 17, 2020

in test/functional/p2p_invalid_messages.py:66 in c5904c82e0 outdated

61+        before = self.nodes[0].getnettotals()['totalbytesrecv']
62+        conn.send_raw_message(msg[:cut_pos])
63+        middle = self.nodes[0].getnettotals()['totalbytesrecv']
64+        # If this assert fails, we've hit an unlikely race
65+        # where the test framework sent a message in between the two halves
66+        assert middle == before + cut_pos

jonatack commented at 3:10 pm on June 17, 2020:

use assert_equal

jonatack commented at 3:13 pm on June 17, 2020:

Why not test the debug log output as well, e.g. Incomplete headerReceived. I think this works; maybe it can be improved on:

 0-        msg = conn.build_message(msg_ping(nonce=12345))
 1-        cut_pos = 12    # Chosen at an arbitrary position within the header
 2-        # Send message in two pieces
 3-        before = self.nodes[0].getnettotals()['totalbytesrecv']
 4-        conn.send_raw_message(msg[:cut_pos])
 5-        middle = self.nodes[0].getnettotals()['totalbytesrecv']
 6-        # If this assert fails, we've hit an unlikely race
 7-        # where the test framework sent a message in between the two halves
 8-        assert middle == before + cut_pos
 9-        conn.send_raw_message(msg[cut_pos:])
10-        conn.sync_with_ping(timeout=1)
11+        with self.nodes[0].assert_debug_log(['Incomplete headerReceived']):
12+            msg = conn.build_message(msg_ping(nonce=12345))
13+            cut_pos = 12    # Chosen at an arbitrary position within the header
14+            # Send message in two pieces
15+            before = self.nodes[0].getnettotals()['totalbytesrecv']
16+            conn.send_raw_message(msg[:cut_pos])
17+            middle = self.nodes[0].getnettotals()['totalbytesrecv']
18+            # If this assert fails, we've hit an unlikely race
19+            # where the test framework sent a message in between the two halves
20+            assert middle == before + cut_pos
21+            conn.send_raw_message(msg[cut_pos:])
22+            conn.sync_with_ping(timeout=1)
23
24with self.nodes[0].assert_debug_log(['[net] Incomplete headerReceived']):

jnewbery commented at 3:34 pm on June 17, 2020:

Why not test the debug log output as well

I’d prefer not to do this. My view is that functional tests should be as black box as possible, and test the functionality rather than the implementation. Using the debug log to test that an event has happened should be used only when there’s no other way to test, since doing so binds the test to the exact implementation, and any changes to control flow or logging in the product mean that the tests need to be updated.

use assert_equal

:+1:

troygiorshev commented at 3:36 pm on June 17, 2020:

See below

jonatack commented at 4:01 pm on June 17, 2020:

Oh right, if it’s just sockets then agreed.

in test/functional/p2p_invalid_messages.py:59 in c5904c82e0 outdated

50         self.test_msgtype()
51         self.test_large_inv()
52         self.test_resource_exhaustion()
53 
54+    def test_buffer(self):
55+        self.log.info("Test message with header split across two buffers")

jonatack commented at 3:12 pm on June 17, 2020:

suggestion: perhaps describe the expected result

troygiorshev commented at 3:36 pm on June 17, 2020:

We don’t currently log that an incomplete header was received. IMO we shouldn’t, it’s just an implementation detail of sockets, it doesn’t really mean anything on any Bitcoin level. At the very least maybe changing bitcoind logging is out of scope for this PR?

troygiorshev commented at 3:43 pm on June 17, 2020:

In #19302 (review) you added LogPrintf("Incomplete header");

jnewbery commented at 3:44 pm on June 17, 2020:

@jonatack are you sure? I don’t see anywhere in the product code that logs “Incomplete headerReceived” (and would be surprised to, since this is purely an implementation detail)

troygiorshev commented at 3:44 pm on June 17, 2020:

The idea is to mention the expected result. The rest was an example, success, failure, disconnects peer, etc.

Ah I agree, I’ll make this a bit more descriptive

jonatack commented at 4:09 pm on June 17, 2020:

@jonatack are you sure? I don’t see anywhere in the product code that logs “Incomplete headerReceived” (and would be surprised to, since this is purely an implementation detail)

Weird. I think it was a non-consistent result. Sorry about that.

jonatack commented at 4:23 pm on June 17, 2020:

In #19302 (comment) you added LogPrintf("Incomplete header");

Hm, it’s possible I didn’t rebuild properly. It’s late here :) will finish review of your net headers refactoring tomorrow fresh and early

jonatack commented at 3:21 pm on June 17, 2020: member

Concept ACK

in test/functional/p2p_invalid_messages.py:130 in c5904c82e0 outdated

120-        with self.nodes[0].assert_debug_log(['Misbehaving', 'peer=4 (20 -> 40): message getdata size() = 50001']):
121+        with self.nodes[0].assert_debug_log(['Misbehaving', '(20 -> 40): message getdata size() = 50001']):
122             msg = msg_getdata([CInv(MSG_TX, 1)] * 50001)
123             conn.send_and_ping(msg)
124-        with self.nodes[0].assert_debug_log(['Misbehaving', 'peer=4 (40 -> 60): headers message size = 2001']):
125+        with self.nodes[0].assert_debug_log(['Misbehaving', '(40 -> 60): headers message size = 2001']):

jonatack commented at 3:36 pm on June 17, 2020:

If #19272 if merged first, these changes in test_large_inv() won’t be needed.

troygiorshev commented at 3:38 pm on June 17, 2020:

+1, I’m more than happy to rebase this one if #19272 goes in first

in test/functional/p2p_invalid_messages.py:20 in c5904c82e0 outdated

16@@ -17,6 +17,7 @@
17     P2PInterface,
18 )
19 from test_framework.test_framework import BitcoinTestFramework
20+from test_framework.messages import msg_ping

jnewbery commented at 3:38 pm on June 17, 2020:

Please join this with the import from test_framework.messages above.

in test/functional/p2p_invalid_messages.py:75 in c5904c82e0 outdated

63+        middle = self.nodes[0].getnettotals()['totalbytesrecv']
64+        # If this assert fails, we've hit an unlikely race
65+        # where the test framework sent a message in between the two halves
66+        assert middle == before + cut_pos
67+        conn.send_raw_message(msg[cut_pos:])
68+        conn.sync_with_ping(timeout=1)

jnewbery commented at 3:40 pm on June 17, 2020:

I suggest you disconnect the connection at the end of this subtest, so that the node and test fixture are the same state at the end of each subtest as at the start.

Ideally, it should be possible to permute subtests in any order and have the test pass. That prevents brittleness like the asserts on peer numbers that you’ve had to change in an unrelated subtest here.

MarcoFalke commented at 3:41 pm on June 17, 2020: member

ACK. Thanks for adding the test, will test after assert_equal nit is addressed

troygiorshev force-pushed on Jun 17, 2020

troygiorshev commented at 4:13 pm on June 17, 2020: contributor

Compare c5904c82e05cb4f5856cc55877f9fa268a9cd031 to 3cd538a1a6c64c8ab4b6f02be72f45d2c865b9f1. Changed to assert_equal and made log more descriptive. Disconnects peer at the end of the test, I’ll keep that discussion in #19272 and I’ll follow the status quo here.

Had to add a short sleep, as I was finding my RPC call occationally went before the first half of the message was received by the node.

in test/functional/p2p_invalid_messages.py:67 in 3cd538a1a6 outdated

62+        msg = conn.build_message(msg_ping(nonce=12345))
63+        cut_pos = 12    # Chosen at an arbitrary position within the header
64+        # Send message in two pieces
65+        before = int(self.nodes[0].getnettotals()['totalbytesrecv'])
66+        conn.send_raw_message(msg[:cut_pos])
67+        time.sleep(0.01) # Prevent the RPC call from going too early

MarcoFalke commented at 4:55 pm on June 17, 2020:

I don’t think a sleep will consistently avoid races. Any reason why a sync_with_ping (on a different connection) or a wait_until is not working?

glozow commented at 5:47 pm on June 17, 2020:

I think getnettotals returns information about all peers, so sync_with_ping would affect totalbytesrecv right? You could take that into account too, something like:

0pinger = node.add_p2p_connection()
1...
2conn.send_raw_message(msg[:cut_pos])
3pinger.sync_with_ping()
4...
5assert_equal(middle, before + cut_pos + PING_SIZE)

I don’t think this guarantees that conn’s message has been processed just because pinger’s ping has been though…?

glozow commented at 6:01 pm on June 17, 2020:

Actually, I think wait_until might be better:

0       wait_until(lambda: self.nodes[0].getnettotals()['totalbytesrecv'] == before + cut_pos)

Wishful thinking, it’d be nice if cut_pos is a size that couldn’t possibly be = another message (does this exist?). It will still fail if the node receives another message in between the halves, but can’t pass if it isn’t received.

troygiorshev commented at 6:31 pm on June 17, 2020:

Ok, I like wait_until better. More expressive at the very least. How do you like this?

0        # Prevent the RPC call from going too early
1        conn.wait_util(int(self.nodes[0].getnettotals()['totalbytesrecv']) != before)

MarcoFalke commented at 6:33 pm on June 17, 2020:

Should be fine. In case it fails the assert_equal(middle, before + cut_pos) should trigger

troygiorshev commented at 6:47 pm on June 17, 2020:

Ah we came up with almost the same thing! I thought of this #19304 (review). Regarding cut_pos, we actually have what you’re looking for. cut_pos = 12 and the size of the smallest message (any of the messages with no payload) is 24 😄

I’ll think about getpeerinfo vs getnettotals

troygiorshev commented at 6:53 pm on June 17, 2020:

I don’t think this guarantees that conn’s message has been processed just because pinger’s ping has been though…?

I’m pretty sure you’re right. However, we’re looking at a race in a test for a race inside a test at this point, so I’m going to prefer the simpler fix.

glozow commented at 6:55 pm on June 17, 2020:

TWINSIES 👯 (If I may, I think == before + cut_pos is stronger than >= before or != before)

we actually have what you’re looking for

Ooh!! Genius, should be in the comment.

troygiorshev commented at 7:06 pm on June 17, 2020:

== before + cut_pos is stronger, but I see three possible situations that I would rather be caught by different asserts. This is possible with != and the later assert_equal

Something terrible happens and the first half of the message is never processed. wait_until times out and throws an exception.
The node takes a while but eventually processes the first half of the message (and only that). wait_until tries getnettotals a few times and then we continue past, and the test passes.
The race occurs and the node processes more than just the first half of the message. The assert_equals fails and we see the exception there.

Choosing == before + cut_pos or >= before could make both 1. and 3. fail on the wait_until, which is just a little harder to debug.

in test/functional/p2p_invalid_messages.py:74 in 3cd538a1a6 outdated

67+        time.sleep(0.01) # Prevent the RPC call from going too early
68+        middle = int(self.nodes[0].getnettotals()['totalbytesrecv'])
69+        # If this assert fails, we've hit an unlikely race
70+        # where the test framework sent a message in between the two halves
71+        assert_equal(middle, before + cut_pos)
72+        conn.send_raw_message(msg[cut_pos:])

glozow commented at 5:51 pm on June 17, 2020:

Do you want to make an assertion about totalbytesrecv here too? Or is it unnecessary? Also, I know this just tests that the 2 halves are received so this might be out of scope, but do you expect a pong in return? Could be tested using conn.message_count?

troygiorshev commented at 6:50 pm on June 17, 2020:

We do expect a pong in return, but it doesn’t really matter in this test. I’ve just chosen ping because it’s really simple, any valid message would have worked.

glozow commented at 6:28 pm on June 17, 2020: member

Concept ACK, hi Troy 👋 😁 ! Came here because I made a suggestion that impacts this test in #19272 - oops. I definitely see the need to make sure all peers are disconnected since getnettotals aggregates information across all peers.

I wrote some suggestions that build off of Marco’s comment about races.

Side note: not sure if you already considered this, but if there’s no other peers, you can also use getpeerinfo to see information on pings received from conn only.

troygiorshev force-pushed on Jun 17, 2020

in test/functional/p2p_invalid_messages.py:7 in cac346ce9f outdated

2@@ -3,12 +3,16 @@
3 # Distributed under the MIT software license, see the accompanying
4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
5 """Test node responses to invalid network messages."""
6+
7+import time

MarcoFalke commented at 7:21 pm on June 17, 2020:

glozow commented at 7:22 pm on June 17, 2020:

MarcoFalke = faster than linter

troygiorshev commented at 7:22 pm on June 17, 2020:

glares at pylint

thx

troygiorshev commented at 7:21 pm on June 17, 2020: contributor

Implemented wait_until as discussed.

Test buffered valid message

A message can be broken across two buffers, with the split inside its
header.  Usually this will occur when sending many messages, such that
the first buffer fills.

This test uses the RPC to verify that the message is actually being
received in two pieces.

There is a very rare chance of a race condition where the test framework
sends a message in between the two halves of the message under test.  In
this case the peer will almost certainly disconnect and the test will
fail.  An assert has been added to help debugging that rare case.

80d4423f99

troygiorshev force-pushed on Jun 17, 2020

troygiorshev commented at 7:23 pm on June 17, 2020: contributor

And removed unused import.

in test/functional/p2p_invalid_messages.py:6 in 80d4423f99

2@@ -3,12 +3,14 @@
3 # Distributed under the MIT software license, see the accompanying
4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
5 """Test node responses to invalid network messages."""
6+

glozow commented at 7:26 pm on June 17, 2020:

nit: extra newline here?

troygiorshev commented at 9:30 pm on June 17, 2020:

Using PEP 257 as a basis, this could be argued either way. I like this better, and it’s consistent with the 7 or so other test files that I just checked.

MarcoFalke commented at 7:29 pm on June 17, 2020: member

tested ACK 80d4423f997e15780bfa3f91bf4b4bf656b8ea45 (added an assert(false) to observe deterministic coverage) 🌦

Signature:

 0-----BEGIN PGP SIGNED MESSAGE-----
 1Hash: SHA512
 2
 3tested ACK 80d4423f997e15780bfa3f91bf4b4bf656b8ea45 (added an assert(false) to observe deterministic coverage) 🌦
 4-----BEGIN PGP SIGNATURE-----
 5
 6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
 7pUg1fgwAr3kntpEQs2aiIVSBgAO5mxLPeIy/CfdZirlGL0VYvHOPl2BvcIwBOSXt
 8/mjQVNutfafKTcpxz5pvMMX934qEA0K49aX92hU2jt+q5q5zggMsBjd996Cwm6ww
 9J5+Zz3AJFWSU2CVHll0vHIjNolBBe+HnB5w8enUgdz8TPGf4mS1LWtS9uE36a0ja
10Uor7i7wdN46jV+c35KXfH8gxVNyEirHlDAdDfQkHZpjdFBoMmEK4yML3PflEqkpy
11CVoKNfVr7ziGfjUDAG2JNl7wSDSJtomvBRcBsSwP0h0lPBONjv6JntoLSjeTHaY2
12wzx/mwB2lXx1QWw3E/VU/H1ivNiwcI5uIt8EdiVNhficdOUwhEgVGhI6TREpn8W1
13DgriZXSNI0v9SDhWM8fWV7MBR6XElZC5m31pM4aqknD5+4gftrZxUiI7Hg4t4tVC
14Gz/G1FEAo2icWAgmodUbSp+ti87Y2HhPi+9rDdvuHgWG2BPFviGO55tbLta14tiO
15U7YBmVXz
16=QULl
17-----END PGP SIGNATURE-----

Timestamp of file with hash 1e2f468bf771db8cdab09da071ec81ccf7eb4d5341ad83699ce0369e01a45610 -

in test/functional/p2p_invalid_messages.py:64 in 80d4423f99

59+    def test_buffer(self):
60+        self.log.info("Test message with header split across two buffers, should be received")
61+        conn = self.nodes[0].add_p2p_connection(P2PDataStore())
62+        # Create valid message
63+        msg = conn.build_message(msg_ping(nonce=12345))
64+        cut_pos = 12    # Chosen at an arbitrary position within the header

glozow commented at 7:30 pm on June 17, 2020:

nit: I think the fact that cut_pos < smallest message size is pretty smart and non-arbitrary :)

0        cut_pos = 12    # Smaller than any other P2P message and thus easily distinguishable

jonatack commented at 5:33 am on June 18, 2020:

:+1:

in test/functional/p2p_invalid_messages.py:5 in 80d4423f99

2@@ -3,12 +3,14 @@
3 # Distributed under the MIT software license, see the accompanying
4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
5 """Test node responses to invalid network messages."""

glozow commented at 7:50 pm on June 17, 2020:

This sends a valid message.

Er… I’m very sorry if I’m being a pain in the ass, but why is this in p2p_invalid_messages?

jnewbery commented at 8:45 pm on June 17, 2020:

I’m very sorry if I’m being a pain in the ass, but why is this in p2p_invalid_messages?

You’re not. Because we couldn’t think of anywhere better to put it 🤷‍♂️

glozow commented at 7:51 pm on June 17, 2020: member

ACK https://github.com/bitcoin/bitcoin/commit/80d4423f997e15780bfa3f91bf4b4bf656b8ea45 👊

Looks good to me, nits if you touch again and happy to re-ACK if you do.

DrahtBot commented at 8:17 pm on June 17, 2020: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#19272 (test: p2p_invalid_messages and test framework improvements by jonatack)

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.

Coverage

Coverage	Change (pull 19304, 181023380aeabcf62a25f7a546b465626c5be3d4)	Reference (master, 35ed88f187c9bc7eedc3a1cf12193e0fbf222057)
Lines	+0.0249 %	90.7991 %
Functions	+0.0818 %	85.6072 %
Branches	+0.0126 %	51.9831 %

Updated at: 2020-06-17T20:17:17.128362.

practicalswift commented at 9:45 pm on June 17, 2020: contributor

Concept ACK: good to have this code path tested deterministically!

in test/functional/p2p_invalid_messages.py:51 in 80d4423f99

47@@ -42,13 +48,33 @@ def set_test_params(self):
48         self.setup_clean_chain = True
49 
50     def run_test(self):
51+        self.test_buffer()

jonatack commented at 5:32 am on June 18, 2020:

This would allow not changing test_large_inv():

0     def run_test(self):
1-        self.test_buffer()
2         self.test_magic_bytes()
3         self.test_checksum()
4         self.test_size()
5         self.test_msgtype()
6         self.test_large_inv()
7+        self.test_buffer()
8         self.test_resource_exhaustion()

MarcoFalke commented at 11:37 am on June 18, 2020: member

Going to merge this. I think it is more important to have this test than it is to find the exact right location for this test. I picked an invalid message in #19302 to accomodate the file name, but if it really turns out to be problematic, one could add a comment like

# This test can equivalently be done with an invalid or valid message, for simplicity it is done here with a valid message

MarcoFalke merged this on Jun 18, 2020

MarcoFalke closed this on Jun 18, 2020

MarcoFalke referenced this in commit 67881de0e3 on Jun 24, 2020

deadalnix referenced this in commit 7300d72911 on May 13, 2021

DrahtBot locked this on Feb 15, 2022

test: Check that message sends successfully when header is split across two buffers #19304

Conflicts

Coverage