test: Wait for both veracks in add_p2p_connection #18247

maflcko · 2020-03-02T19:14:18Z

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

jonatack

Concept ACK with a question on implementation.

test/functional/p2p_leak.py

jonatack · 2020-03-06T12:14:04Z

test/functional/test_framework/test_node.py

            p2p_conn.wait_for_verack()
+            # Force the node to fully process our verack as well
+            p2p_conn.sync_with_ping()


It looks like this change would affect quite a few other functional tests that don't pass wait_for_verack=False. Is it a good idea to change it here rather than in p2p_blocksonly?

Yes, whenever we add a p2p connection in the tests we want the least amount of surprise and want to assume that the connection has been fully established when the function returns.

Only in adversarial tests do we need to make sure that the connection is not (or only partially) established. Do you see any other test that needs a partial connection?

There are some tests that now have a redundant sync_with_ping() immediately following an add_p2p_connection(), e.g. in p2p_invalid_messages.py::143

and others that have a single operation between the two calls and which are probably being needlessly synced twice (or perhaps should not be synced until after the single operation), e.g. in 3 places in p2p_dos_header_tree.py

I think this is fine, at worst slows down the test by a few milliseconds.

There are some tests that now have a redundant sync_with_ping() immediately following an add_p2p_connection(), e.g. in p2p_invalid_messages.py::143

I fixed this instance in the latest commit, but couldn't find any other instances.

and others that have a single operation between the two calls and which are probably being needlessly synced twice (or perhaps should not be synced until after the single operation), e.g. in 3 places in p2p_dos_header_tree.py

Why are they needlessly being synced? First they need to wait until the connection is fully established, then they need to wait until the message they sent is fully processed. This is a common pattern in our tests, see send_and_ping.

I went ahead and replaced the two-line calls there with the more widely used one-line send_and_ping

Why are they needlessly being synced?

Unless I am confused, these cases seem to be synced one additional time after this change:

Before: add connection / send / sync

After: add connection including sync by default / send / sync

Help me understand if that's not the case?

Ok fine, in this case the sync is redundant, but I can't see a way to distinguish the redundant case from the non-redundant one. Even if we could, the cost of a few milliseconds is probably not worth it to optimize this, right?

Force pushed with additional doc to explain my reasoning

I agree; thanks for the doc

maflcko · 2020-03-31T12:53:57Z

Would be nice to move forward with this. I am seeing about one ci failure each day because of this bug.

Also replace the two-line (send_message + sync_with_ping) with the one-line send_and_ping

jonatack · 2020-03-31T21:18:49Z

ACK faf1d04

Verified that p2p_leaks and p2p_timeouts needed these changes and looked at other tests.

…nection 4670006 test: remove redundant sync_with_ping after add_p2p_connection (Jon Atack) Pull request description: Now that #18247 is merged, these calls are redundant. ACKs for top commit: vasild: utACK 4670006 Tree-SHA512: bdbfe8bcf9dbdde0a8115e3a62bfe359910798d7a3010d920ffca07049cb5f97bf8fb9b6f70079b0607105192b61a6d665774e59a2b678597b47ad6237595ad5

…p2p_connection 4670006 test: remove redundant sync_with_ping after add_p2p_connection (Jon Atack) Pull request description: Now that bitcoin#18247 is merged, these calls are redundant. ACKs for top commit: vasild: utACK 4670006 Tree-SHA512: bdbfe8bcf9dbdde0a8115e3a62bfe359910798d7a3010d920ffca07049cb5f97bf8fb9b6f70079b0607105192b61a6d665774e59a2b678597b47ad6237595ad5

Summary: Partial backport of Core [[bitcoin/bitcoin#18247 | PR18247]] Depends on D6431 Test Plan: ninja check-all Reviewers: #bitcoin_abc, jasonbcox, deadalnix Reviewed By: #bitcoin_abc, jasonbcox, deadalnix Subscribers: deadalnix, jasonbcox Differential Revision: https://reviews.bitcoinabc.org/D6384

…connection Summary: Also replace the two-line (send_message + sync_with_ping) with the one-line send_and_ping bitcoin/bitcoin@faf1d04 --- Depends on D6384 Concludes backport of Core [[bitcoin/bitcoin#18247 | PR18247]] Test Plan: ./test/functional/test_runner.py Reviewers: #bitcoin_abc, deadalnix, jasonbcox Reviewed By: #bitcoin_abc, deadalnix, jasonbcox Differential Revision: https://reviews.bitcoinabc.org/D6432

…p2p_connection 4670006 test: remove redundant sync_with_ping after add_p2p_connection (Jon Atack) Pull request description: Now that bitcoin#18247 is merged, these calls are redundant. ACKs for top commit: vasild: utACK 4670006 Tree-SHA512: bdbfe8bcf9dbdde0a8115e3a62bfe359910798d7a3010d920ffca07049cb5f97bf8fb9b6f70079b0607105192b61a6d665774e59a2b678597b47ad6237595ad5

fanquake added the Tests label Mar 2, 2020

maflcko force-pushed the 2003-qaMininodeVerackRace branch from fac8203 to fa58623 Compare March 2, 2020 21:41

jonatack reviewed Mar 6, 2020

View reviewed changes

maflcko added this to the 0.20.0 milestone Mar 31, 2020

MarcoFalke added 2 commits March 31, 2020 17:03

test: Wait for both veracks in add_p2p_connection

fa90647

test: Remove redundant sync_with_ping after add_p2p_connection

faf1d04

Also replace the two-line (send_message + sync_with_ping) with the one-line send_and_ping

maflcko force-pushed the 2003-qaMininodeVerackRace branch from fa5d339 to faf1d04 Compare March 31, 2020 21:04

maflcko merged commit 67a7246 into bitcoin:master Apr 1, 2020

maflcko deleted the 2003-qaMininodeVerackRace branch April 1, 2020 02:56

This was referenced Apr 1, 2020

test: remove redundant sync_with_ping after add_p2p_connection #18496

Merged

test: enable opening partial p2p connections where useful #18498

Closed

MarkLTZ mentioned this pull request Apr 4, 2020

Bitcoin PR tracking litecoinz-core/litecoinz#14

Closed

bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: Wait for both veracks in add_p2p_connection #18247

test: Wait for both veracks in add_p2p_connection #18247

maflcko commented Mar 2, 2020

jonatack left a comment

jonatack Mar 6, 2020

maflcko Mar 6, 2020

jonatack Mar 31, 2020

maflcko Mar 31, 2020

jonatack Mar 31, 2020 •

edited

Loading

maflcko Mar 31, 2020

maflcko Mar 31, 2020

jonatack Mar 31, 2020

maflcko commented Mar 31, 2020

jonatack commented Mar 31, 2020

test: Wait for both veracks in add_p2p_connection #18247

test: Wait for both veracks in add_p2p_connection #18247

Conversation

maflcko commented Mar 2, 2020

jonatack left a comment

Choose a reason for hiding this comment

jonatack Mar 6, 2020

Choose a reason for hiding this comment

maflcko Mar 6, 2020

Choose a reason for hiding this comment

jonatack Mar 31, 2020

Choose a reason for hiding this comment

maflcko Mar 31, 2020

Choose a reason for hiding this comment

jonatack Mar 31, 2020 • edited Loading

Choose a reason for hiding this comment

maflcko Mar 31, 2020

Choose a reason for hiding this comment

maflcko Mar 31, 2020

Choose a reason for hiding this comment

jonatack Mar 31, 2020

Choose a reason for hiding this comment

maflcko commented Mar 31, 2020

jonatack commented Mar 31, 2020

jonatack Mar 31, 2020 •

edited

Loading