test: Wait for both veracks in add_p2p_connection #18247

pull MarcoFalke wants to merge 2 commits into bitcoin:master from MarcoFalke:2003-qaMininodeVerackRace changing 5 files +33 −9
  1. MarcoFalke commented at 7:14 PM on March 2, 2020: member

    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
  2. fanquake added the label Tests on Mar 2, 2020
  3. MarcoFalke force-pushed on Mar 2, 2020
  4. in test/functional/p2p_leak.py:104 in fa586230eb outdated 
      97 | @@ -96,7 +98,11 @@ def set_test_params(self):
  98 |      def run_test(self):
  99 |          no_version_bannode = self.nodes[0].add_p2p_connection(CNodeNoVersionBan(), send_version=False, wait_for_verack=False)
 100 |          no_version_idlenode = self.nodes[0].add_p2p_connection(CNodeNoVersionIdle(), send_version=False, wait_for_verack=False)
 101 | -        no_verack_idlenode = self.nodes[0].add_p2p_connection(CNodeNoVerackIdle())
 102 | +        no_verack_idlenode = self.nodes[0].add_p2p_connection(CNodeNoVerackIdle(), wait_for_verack=False)
 103 | +
 104 | +        # Wait until we got the verack in response to the version. Though, don't wait for the other node to receive the
 105 | +        # verack, since we never sent one
    jonatack commented at 12:09 PM on March 6, 2020:

    non-blocking suggestion (line wrap and content) here and p2p_timeouts.py::50:

            # Wait until we get the verack in response to the version. Do not wait
        # for the other node to receive the verack, since we never sent one.
    MarcoFalke commented at 2:21 PM on March 6, 2020:

    Most terminal sizes are 120 by default, also most review tools as well as GitHub web. So my personal preference is 120. I think I will leave it as is for now.

  5. in test/functional/test_framework/test_node.py:483 in fa586230eb outdated 
     467 | @@ -468,7 +468,10 @@ def add_p2p_connection(self, p2p_conn, *, wait_for_verack=True, **kwargs):
 468 |          p2p_conn.peer_connect(**kwargs, net=self.chain)()
 469 |          self.p2ps.append(p2p_conn)
 470 |          if wait_for_verack:
 471 | +            # Wait for the node to send us the version and verack
 472 |              p2p_conn.wait_for_verack()
 473 | +            # Force the node to fully process our verack as well
 474 | +            p2p_conn.sync_with_ping()
    jonatack commented at 12:14 PM on March 6, 2020:

    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?

    MarcoFalke commented at 2:24 PM on March 6, 2020:

    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?

    jonatack commented at 7:01 PM on March 31, 2020:

    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

    MarcoFalke commented at 7:33 PM on March 31, 2020:

    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

    jonatack commented at 7:51 PM on March 31, 2020:

    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?

    MarcoFalke commented at 9:04 PM on March 31, 2020:

    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?

    MarcoFalke commented at 9:05 PM on March 31, 2020:

    Force pushed with additional doc to explain my reasoning

    jonatack commented at 9:15 PM on March 31, 2020:

    I agree; thanks for the doc

  6. jonatack commented at 12:15 PM on March 6, 2020: member

    Concept ACK with a question on implementation.

  7. laanwj added this to the "Blockers" column in a project
  8. MarcoFalke added this to the milestone 0.20.0 on Mar 31, 2020
  9. MarcoFalke commented at 12:53 PM on March 31, 2020: member

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

  10. test: Wait for both veracks in add_p2p_connection fa90647045
  11. test: Remove redundant sync_with_ping after add_p2p_connection
    Also replace the two-line (send_message + sync_with_ping) with the one-line send_and_ping
    faf1d04731
  12. MarcoFalke force-pushed on Mar 31, 2020
  13. jonatack commented at 9:18 PM on March 31, 2020: member

    ACK faf1d04

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

  14. MarcoFalke merged this on Apr 1, 2020
  15. MarcoFalke closed this on Apr 1, 2020
  16. MarcoFalke deleted the branch on Apr 1, 2020
  17. fanquake removed this from the "Blockers" column in a project
  18. MarcoFalke referenced this in commit 94fd4a56ed on Apr 4, 2020
  19. sidhujag referenced this in commit 6cdbaa1ba2 on Apr 8, 2020
  20. deadalnix referenced this in commit adcc233047 on Jun 8, 2020
  21. deadalnix referenced this in commit 9df59f0e69 on Jun 8, 2020
  22. PastaPastaPasta referenced this in commit c6ea4b2f2d on Jun 27, 2021
  23. PastaPastaPasta referenced this in commit 648d0a066c on Jun 28, 2021
  24. PastaPastaPasta referenced this in commit dd5dbac823 on Jun 29, 2021
  25. PastaPastaPasta referenced this in commit 5efbc4085b on Jul 1, 2021
  26. PastaPastaPasta referenced this in commit 13242fe82c on Jul 1, 2021
  27. PastaPastaPasta referenced this in commit 786b20681d on Sep 17, 2021
  28. DrahtBot locked this on Feb 15, 2022
Contributors
MarcoFalkejonatack
Labels
Tests

Milestone
0.20.0

Linked (view graph)
#18496 test: remove redundant sync_with_ping after add_p2p_connection#18498 test: enable opening partial p2p connections where useful
github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-14 21:14 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me