Skip to content

Conversation

glozow
Copy link
Member

@glozow glozow commented Jun 11, 2020

Followup to #19083 which adds bloomfilter-related tests.

  1. Make test_node disconnect_p2ps wait until disconnection is complete to avoid race conditions (and not place the burden on tests) from MarcoFalke's comment. And clean up any redundant wait_untils in the functional tests.
  2. Clean up style + logging in p2p_filter.py and p2p_nobloomfilter_messages.py and jonatack's other comments

@DrahtBot
Copy link
Contributor

DrahtBot commented Jun 13, 2020

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

Conflicts

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.

@glozow glozow marked this pull request as ready for review June 13, 2020 17:08
@glozow glozow changed the title [wip] test: wait for disconnect in disconnect_p2ps + bloomfilter test followups test: wait for disconnect in disconnect_p2ps + bloomfilter test followups Jun 13, 2020
@glozow
Copy link
Member Author

glozow commented Jun 13, 2020

@jonatack addressed your comments on #19083 in afad631 if you have time to take a look :)

Copy link
Contributor

@jnewbery jnewbery left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code review ACK 628227f

A couple of small style suggestions inline. Feel free to take or ignore.

Copy link
Member

@jonatack jonatack left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested ACK with a couple of minor suggestions and a possible concern.

In f1dbb84 consider adding explanation (why, tradeoffs, etc.) for the change in the commit message (like the content of the comment mentioned in the PR description), so future us searching through git history won't have to look up the PR description and then find the linked comment on GitHub, which is only GitHub-specific metadata and not stored in git history.

In the afad631 consider not linking in the commit message to GitHub metadata, e.g. PRs, comments, @-usernames (I used to do it, but it can leave a messy trail).

Concern: possible slowdown in test run times of ~10% in tests with wait_for_disconnect. See details that follow.

test run times

in test_runner.py

BASE_SCRIPTS = [
    'feature_maxuploadtarget.py',
    'p2p_blockfilters.py',
    'p2p_blocksonly.py',
    'p2p_dos_header_tree.py',
    'p2p_invalid_locator.py',
    'p2p_invalid_messages.py',
    'p2p_leak.py',
    'p2p_nobloomfilter_messages.py',
    'p2p_node_network_limited.py',
    'p2p_sendheaders.py',
    'p2p_unrequested_blocks.py',
]

this branch

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 92 s
p2p_blockfilters.py           | ✓ Passed  | 98 s
p2p_blocksonly.py             | ✓ Passed  | 4 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 103 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 19 s
p2p_sendheaders.py            | ✓ Passed  | 16 s
p2p_unrequested_blocks.py     | ✓ Passed  | 10 s

ALL                           | ✓ Passed  | 357 s (accumulated)
Runtime: 110 s

feature_maxuploadtarget.py    | ✓ Passed  | 93 s
p2p_blockfilters.py           | ✓ Passed  | 92 s
p2p_blocksonly.py             | ✓ Passed  | 7 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 94 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 17 s
p2p_sendheaders.py            | ✓ Passed  | 18 s
p2p_unrequested_blocks.py     | ✓ Passed  | 8 s

ALL                           | ✓ Passed  | 343 s (accumulated)
Runtime: 100 s

feature_maxuploadtarget.py    | ✓ Passed  | 95 s
p2p_blockfilters.py           | ✓ Passed  | 102 s
p2p_blocksonly.py             | ✓ Passed  | 4 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 100 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 18 s
p2p_sendheaders.py            | ✓ Passed  | 18 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 361 s (accumulated)
Runtime: 104 s

feature_maxuploadtarget.py    | ✓ Passed  | 97 s
p2p_blockfilters.py           | ✓ Passed  | 96 s
p2p_blocksonly.py             | ✓ Passed  | 17 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 97 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 17 s
p2p_sendheaders.py            | ✓ Passed  | 18 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 365 s (accumulated)
Runtime: 103 s

feature_maxuploadtarget.py    | ✓ Passed  | 95 s
p2p_blockfilters.py           | ✓ Passed  | 97 s
p2p_blocksonly.py             | ✓ Passed  | 7 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 96 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 16 s
p2p_sendheaders.py            | ✓ Passed  | 17 s
p2p_unrequested_blocks.py     | ✓ Passed  | 10 s

ALL                           | ✓ Passed  | 353 s (accumulated)
Runtime: 103 s

master

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 94 s
p2p_blockfilters.py           | ✓ Passed  | 95 s
p2p_blocksonly.py             | ✓ Passed  | 16 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 80 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 16 s
p2p_sendheaders.py            | ✓ Passed  | 17 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 342 s (accumulated)
Runtime: 95 s

feature_maxuploadtarget.py    | ✓ Passed  | 96 s
p2p_blockfilters.py           | ✓ Passed  | 99 s
p2p_blocksonly.py             | ✓ Passed  | 7 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 84 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 17 s
p2p_sendheaders.py            | ✓ Passed  | 18 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 345 s (accumulated)
Runtime: 99 s

feature_maxuploadtarget.py    | ✓ Passed  | 93 s
p2p_blockfilters.py           | ✓ Passed  | 94 s
p2p_blocksonly.py             | ✓ Passed  | 7 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 79 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 16 s
p2p_sendheaders.py            | ✓ Passed  | 18 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 330 s (accumulated)
Runtime: 94 s

feature_maxuploadtarget.py    | ✓ Passed  | 94 s
p2p_blockfilters.py           | ✓ Passed  | 97 s
p2p_blocksonly.py             | ✓ Passed  | 15 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 80 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 2 s
p2p_node_network_limited.py   | ✓ Passed  | 17 s
p2p_sendheaders.py            | ✓ Passed  | 17 s
p2p_unrequested_blocks.py     | ✓ Passed  | 9 s

ALL                           | ✓ Passed  | 343 s (accumulated)
Runtime: 97 s

@jonatack
Copy link
Member

(The number of test run samples is too small, but it might be interesting to look further into it.)

@glozow
Copy link
Member Author

glozow commented Jun 15, 2020

Concern: possible slowdown in test run times of ~10% in tests with wait_for_disconnect.

Hm :/ that slowdown seems pretty significant. I've thought of 2 possible solutions:

  1. What about an optional argument wait_for_disconnect, then allowing tests to decide if waiting isn't necessary (similar to wait_for_verack in add_p2p_connection)?
  2. I've also noticed that disconnect_p2ps is pretty over-used.
    For example, looks like p2p_invalid_messages.py slowed down by 23 seconds, probably because it calls disconnect_p2ps 10+ times. But actually, that test (and many others) wouldn't need to wait or even call disconnect_p2ps if it just didn't use node.p2p. Here is a refactored p2p_invalid_messages.py without any disconnect_p2ps.

It's a common pattern to test using multiple mininodes, one at a time, and call disconnect_p2ps at the end to make sure they don't affect each other. In general, the p2p property is supposed to be a shortcut for node.p2ps[0] when tests only use 1 mininode.

Thus, I think it would be better to use conn = node.add_p2p_connection() and then use conn to refer to the mininode. We could take out a lot of unnecessary disconnect_p2ps to reduce the performance issue. But it would be a pretty big diff.

What I suggest, for this PR, is to add a default wait_for_disconnect=False and then make it True for all the tests that need to wait (i.e. the ones I'm already touching here, and I'll search through the tests to see if any others need it). Would that be a good idea?

@jonatack
Copy link
Member

@gzhao408 I've been reworking p2p_invalid_messages.py lately in #19272. I'll apply this patch to it and test avoiding disconnect_p2ps.

@glozow glozow force-pushed the test-disconnect-p2ps-wait branch from 628227f to 8386ad5 Compare June 15, 2020 21:45
@glozow
Copy link
Member Author

glozow commented Jun 15, 2020

Ok, I made waiting optional/default False which should theoretically make a good dent in the performance problems. Went through and added a couple wait_for_disconnect=Trues to where I think it's needed.
I accidentally left the PR link in the 81e8207 commit message, so I'll fix with next round of edits. Otherwise it's ready for another look :)

@maflcko
Copy link
Member

maflcko commented Jun 15, 2020

Maybe the node.p2p property should be removed if it is causing so much trouble and complexity. There should be no downside to removing it unless I am missing something. Moreover, writing conn = add_conn() everywhere (even in the case of only one peer) even seems preferable for consistency anyway. Also, it is making code more clear at negative cost in complexity, since a reviewer/author doesn't have to look up what the property does.

If a connection is used in multiple sub-tests, a member variable could be used like self.conn = add_conn().

@jnewbery
Copy link
Contributor

@jonatack your test runs seem extraordinarily slow. Are you running under bitcoind with some additional debug instrumentation?

Here are the same tests in my vm for comparison:

test run times

Master:

1/11 - p2p_dos_header_tree.py passed, Duration: 2 s
2/11 - p2p_blocksonly.py passed, Duration: 3 s
3/11 - p2p_invalid_locator.py passed, Duration: 2 s
4/11 - p2p_leak.py passed, Duration: 6 s
5/11 - p2p_blockfilters.py passed, Duration: 11 s
6/11 - p2p_nobloomfilter_messages.py passed, Duration: 1 s
7/11 - p2p_node_network_limited.py passed, Duration: 9 s
Remaining jobs: [feature_maxuploadtarget.py, p2p_invalid_messages.py, p2p_sendheaders.py, p2p_unrequested_blocks.py]
8/11 - p2p_unrequested_blocks.py passed, Duration: 4 s
Remaining jobs: [feature_maxuploadtarget.py, p2p_invalid_messages.py, p2p_sendheaders.py]
9/11 - p2p_sendheaders.py passed, Duration: 13 s
Remaining jobs: [feature_maxuploadtarget.py, p2p_invalid_messages.py]
10/11 - p2p_invalid_messages.py passed, Duration: 28 s
Remaining jobs: [feature_maxuploadtarget.py]
11/11 - feature_maxuploadtarget.py passed, Duration: 69 s                

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 69 s
p2p_blockfilters.py           | ✓ Passed  | 11 s
p2p_blocksonly.py             | ✓ Passed  | 3 s
p2p_dos_header_tree.py        | ✓ Passed  | 2 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 28 s
p2p_leak.py                   | ✓ Passed  | 6 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 1 s
p2p_node_network_limited.py   | ✓ Passed  | 9 s
p2p_sendheaders.py            | ✓ Passed  | 13 s
p2p_unrequested_blocks.py     | ✓ Passed  | 4 s

ALL                           | ✓ Passed  | 148 s (accumulated) 

This branch (with the default wait_for_disconnect set to True):

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 62 s
p2p_blockfilters.py           | ✓ Passed  | 13 s
p2p_blocksonly.py             | ✓ Passed  | 6 s
p2p_dos_header_tree.py        | ✓ Passed  | 3 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 27 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 1 s
p2p_node_network_limited.py   | ✓ Passed  | 9 s
p2p_sendheaders.py            | ✓ Passed  | 13 s
p2p_unrequested_blocks.py     | ✓ Passed  | 4 s

ALL                           | ✓ Passed  | 147 s (accumulated) 
Runtime: 62 s

so with a sample size of 1, there' no observable difference.

If your bitcoinds are generally slow, then disconnecting peers may be slow, but generally it should be pretty quick and not contribute to test times significantly.

I think this needs more testing, but if others are able to replicate my results, then I'd vote for not adding the wait_for_disconnect parameter and keeping this simple.

@jonatack
Copy link
Member

jonatack commented Jun 16, 2020

Isolated the issue 🤦 Rebasing this PR onto 49236be or current master, p2p_invalid_messages runs much faster, with or without this change. John's PR made a huge improvement in its run time.

re-ACK 628227f (without the extra param)

glozow added 3 commits June 16, 2020 08:23
-Use peer to refer to mininodes instead of node
because they are not bitcoind nodes.
-Use log.debug for logs that give helpful but
not super necessary information.
-Adhere to style guidelines (newlines, capitalization).
-Waiting is important to avoid race conditions,
especially if testing peer info through rpc later.
-Wait for mininodes to be disconnected only, even
though it's more complex, because we may still want
to be connected to test nodes.
-Use wait_for_disconnect instead of manual
wait after calling disconnect_p2ps.
@glozow glozow force-pushed the test-disconnect-p2ps-wait branch from 8386ad5 to 9a40cfc Compare June 16, 2020 15:56
@glozow
Copy link
Member Author

glozow commented Jun 16, 2020

Rebased and addressed comments. Got rid of wait_for_disconnect 🙂

My run times ¯\_(ツ)_/¯

Master:

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 66 s
p2p_blockfilters.py           | ✓ Passed  | 28 s
p2p_blocksonly.py             | ✓ Passed  | 9 s
p2p_dos_header_tree.py        | ✓ Passed  | 6 s
p2p_invalid_locator.py        | ✓ Passed  | 2 s
p2p_invalid_messages.py       | ✓ Passed  | 10 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 4 s
p2p_node_network_limited.py   | ✓ Passed  | 10 s
p2p_sendheaders.py            | ✓ Passed  | 17 s
p2p_unrequested_blocks.py     | ✓ Passed  | 5 s

ALL                           | ✓ Passed  | 164 s (accumulated) 
Runtime: 66 s

This branch:

TEST                          | STATUS    | DURATION

feature_maxuploadtarget.py    | ✓ Passed  | 67 s
p2p_blockfilters.py           | ✓ Passed  | 18 s
p2p_blocksonly.py             | ✓ Passed  | 9 s
p2p_dos_header_tree.py        | ✓ Passed  | 6 s
p2p_invalid_locator.py        | ✓ Passed  | 3 s
p2p_invalid_messages.py       | ✓ Passed  | 11 s
p2p_leak.py                   | ✓ Passed  | 7 s
p2p_nobloomfilter_messages.py | ✓ Passed  | 3 s
p2p_node_network_limited.py   | ✓ Passed  | 11 s
p2p_sendheaders.py            | ✓ Passed  | 15 s
p2p_unrequested_blocks.py     | ✓ Passed  | 5 s

ALL                           | ✓ Passed  | 155 s (accumulated) 
Runtime: 67 s

@jonatack
Copy link
Member

Code review ACK 9a40cfc from re-reviewing the diff and git range-diff 5cafb46 8386ad5 9a40cfc

@maflcko
Copy link
Member

maflcko commented Jun 17, 2020

ACK 9a40cfc 🐂

Show signature and timestamp

Signature:

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

ACK 9a40cfc558b3f7fa4fff1270f969582af17479a5 🐂
-----BEGIN PGP SIGNATURE-----

iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
pUi2dgv+OVPePBmXNQ90EcBVrvDet1CHNODyKbSS713qREEOfhwi9KN+2pU3eAcy
dLfsOWCEe1QSlT+OXDXmjYnQon7OI4U3+KMIiaPW3wV/jcPMkP6TcrwIRzlDYmt9
Kw81TTq6rjKByYnib5MNy4JP/tFBxcw822JxfkqV8lCwWyiPg6LANzP8fIg8kU9L
eb8bmDN1nzDrPEHdNrcWJG7byWNFIwCuScCZGXUlWnuDVj+HKU1n6vLN+v5O4Gj+
NHYKWvSMa/+rLfyh/d13/f92HYObTnrNuHG4/6Wk4hszXgA16SivFfwrTIeewGMG
0jcr49IcOAmMxnUiSLCEYba1f/weM4Kt0iDC6ryRoLyYsnEoQ3TJ8tEEQQCOKng1
y8VvvHeI3r4Y3A0ELUWNe3qVtySozLDo+zR3dop04iBUD/DIZBOlUNIqZLGYn9Xa
22FEWJbQF2EpTJX+vze9Wz9OfhnZTiVJRcqCoTCUcdBqPov9mES+xt0x0il7CsWv
FwlNXkKL
=60oC
-----END PGP SIGNATURE-----

Timestamp of file with hash 60c563acc039d017e59fc85afcc06dea3c4ec236d394ece2f361f3fc7252dfb6 -

@maflcko maflcko merged commit 38389dd into bitcoin:master Jun 17, 2020
maflcko pushed a commit that referenced this pull request Jun 24, 2020
…ovements

56010f9 test: hoist p2p values to test framework constants (Jon Atack)
75447f0 test: improve msg sends and p2p disconnections in p2p_invalid_messages (Jon Atack)
5796019 test: refactor test_large_inv() into 3 tests with common method (Jon Atack)
e2b21d8 test: add p2p_invalid_messages logging (Jon Atack)
9fa494d net: update misbehavior logging for oversized messages (Jon Atack)

Pull request description:

  ...seen while reviewing #19264, #19252, #19304 and #19107:

  in `net_processing.cpp`
  - make the debug logging for oversized message size misbehavior the same for `addr`, `getdata`, `headers` and `inv` messages

  in `p2p_invalid_messages`
  - add missing logging
  - improve assertions/message sends, move cleanup disconnections outside the assertion scopes
  - split a slowish 3-part test into 3 order-independent tests
  - add a few p2p constants to the test framework

ACKs for top commit:
  troygiorshev:
    reACK 56010f9
  MarcoFalke:
    ACK 56010f9 🎛

Tree-SHA512: db67b70278f8d4c318907e105af54b54eb3afd15500f9aa0c98034f6fd4bd1cf9ad1663037bd9b237ff4890f3059b37291a6498d8d6ae2cc38efb9f045f73310
@glozow glozow deleted the test-disconnect-p2ps-wait branch July 25, 2020 14:47
deadalnix pushed a commit to Bitcoin-ABC/bitcoin-abc that referenced this pull request May 13, 2021
…filter test followups

Summary:
9a40cfc558b3f7fa4fff1270f969582af17479a5 [refactor] use waiting inside disconnect_p2ps (gzhao408)
aeb9fb414e2d000830287d9dd3fed7fc2eb570d2 [test] wait for disconnect_p2ps to be reflected in getpeerinfo (gzhao408)
e81942d2e1288367e8da94adb2b2a88be99e4751 [test] logging and style followups for bloomfilter tests (gzhao408)

Pull request description:

  Followup to #19083 which adds bloomfilter-related tests.

  1. Make test_node `disconnect_p2ps` wait until disconnection is complete to avoid race conditions (and not place the burden on tests) from MarcoFalke's [comment](bitcoin/bitcoin#19083 (comment)). And clean up any redundant `wait_until`s in the functional tests.
  2. Clean up style + logging in p2p_filter.py and p2p_nobloomfilter_messages.py and jonatack's other [comments](bitcoin/bitcoin#19083 (review))

---

Backport of [[bitcoin/bitcoin#19252 | core#19252]]

Depends on D9512

Test Plan:
  ninja all check check-functional

Reviewers: #bitcoin_abc, PiRK

Reviewed By: #bitcoin_abc, PiRK

Differential Revision: https://reviews.bitcoinabc.org/D9513
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants