dash/test/functional/p2p_timeouts.py

89 lines
3.0 KiB
Python
Raw Normal View History

#!/usr/bin/env python3
# Copyright (c) 2016-2020 The Bitcoin Core developers
# Distributed under the MIT software license, see the accompanying
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
Backports 0.15 pr2 (#2597) * Merge #9815: Trivial: use EXIT_ codes instead of magic numbers a87d02a use EXIT_ codes instead of magic numbers (Marko Bencun) * Merge #9801: Removed redundant parameter from mempool.PrioritiseTransaction eaea2bb Removed redundant parameter from mempool.PrioritiseTransaction (gubatron) * remove extra parameter (see 3a3745bb) in dash specific code * Merge #9819: Remove harmless read of unusued priority estimates bc8fd12 Remove harmless read of unusued priority estimates (Alex Morcos) * Merge #9766: Add --exclude option to rpc-tests.py c578408 Add exclude option to rpc-tests.py (John Newbery) * Merge #9577: Fix docstrings in qa tests 3f95a80 Fix docstrings in qa tests (John Newbery) * Merge #9823: qa: Set correct path for binaries in rpc tests 3333ad0 qa: Set correct path for binaries in rpc tests (MarcoFalke) * Merge #9833: Trivial: fix comments referencing AppInit2 ef9f495 Trivial: fix comments referencing AppInit2 (Marko Bencun) * Merge #9612: [trivial] Rephrase the definition of difficulty. dc222f8 Trivial: Rephrase the definition of difficulty in the code. (Karl-Johan Alm) * Merge #9847: Extra test vector for BIP32 30aedcb BIP32 extra test vector (Pieter Wuille) * Merge #9839: [qa] Make import-rescan.py watchonly check reliable 864890a [qa] Make import-rescan.py watchonly check reliable (Russell Yanofsky) Tree-SHA512: ea0e2b1d4fc8f35174c3d575fb751b428daf6ad3aa944fad4e3ddcc9195e4f17051473acabc54203b1d27cca64cf911b737ab92e986c40ef384410652e2dbea1 * Change back file params
2019-01-07 10:55:35 +01:00
"""Test various net timeouts.
- Create three dashd nodes:
no_verack_node - we never send a verack in response to their version
no_version_node - we never send a version (only a ping)
no_send_node - we never send any P2P message.
- Start all three nodes
- Wait 1 second
- Assert that we're connected
- Send a ping to no_verack_node and no_version_node
Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested. 48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia) 8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia) Pull request description: **Summary:** 1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting. 2. _Secondary_: Drastically speeds up `p2p_timeout.py` test. 3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test. **Rationale:** - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number. - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec. - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`. - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test. **Locally verified changes:** _With Proposed Change (4.7 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7 2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit 2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful real 0m4.743s ``` _Currently on master (62.8 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h 2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit 2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful real 1m2.836s ``` _Error message demonstrated for new argument `-peertimeout`:_ ``` $ ./bitcoind -peertimeout=-5 ... Error: peertimeout cannot be configured with a negative value. ``` Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a
2018-12-04 12:06:35 +01:00
- Wait 1 second
- Assert that we're still connected
- Send a ping to no_verack_node and no_version_node
Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested. 48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia) 8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia) Pull request description: **Summary:** 1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting. 2. _Secondary_: Drastically speeds up `p2p_timeout.py` test. 3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test. **Rationale:** - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number. - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec. - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`. - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test. **Locally verified changes:** _With Proposed Change (4.7 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7 2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit 2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful real 0m4.743s ``` _Currently on master (62.8 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h 2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit 2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful real 1m2.836s ``` _Error message demonstrated for new argument `-peertimeout`:_ ``` $ ./bitcoind -peertimeout=-5 ... Error: peertimeout cannot be configured with a negative value. ``` Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a
2018-12-04 12:06:35 +01:00
- Wait 2 seconds
- Assert that we're no longer connected (timeout to receive version/verack is 3 seconds)
"""
from time import sleep
Merge #13054: tests: Enable automatic detection of undefined names in Python tests scripts. Remove wildcard imports. 68400d8b96 tests: Use explicit imports (practicalswift) Pull request description: Enable automatic detection of undefined names in Python tests scripts. Remove wildcard imports. Wildcard imports make it unclear which names are present in the namespace, confusing both readers and many automated tools. An additional benefit of not using wildcard imports in tests scripts is that readers of a test script then can infer the rough testing scope just by looking at the imports. Before this commit: ``` $ contrib/devtools/lint-python.sh | head -10 ./test/functional/feature_rbf.py:8:1: F403 'from test_framework.util import *' used; unable to detect undefined names ./test/functional/feature_rbf.py:9:1: F403 'from test_framework.script import *' used; unable to detect undefined names ./test/functional/feature_rbf.py:10:1: F403 'from test_framework.mininode import *' used; unable to detect undefined names ./test/functional/feature_rbf.py:15:12: F405 bytes_to_hex_str may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:17:58: F405 CScript may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:25:13: F405 COIN may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:26:31: F405 satoshi_round may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:26:60: F405 COIN may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:30:41: F405 satoshi_round may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util ./test/functional/feature_rbf.py:30:68: F405 COIN may be undefined, or defined from star imports: test_framework.mininode, test_framework.script, test_framework.util $ ``` After this commit: ``` $ contrib/devtools/lint-python.sh | head -10 $ ``` Tree-SHA512: 3f826d39cffb6438388e5efcb20a9622ff8238247e882d68f7b38609877421b2a8e10e9229575f8eb6a8fa42dec4256986692e92922c86171f750a0e887438d9
2018-08-13 14:24:43 +02:00
from test_framework.messages import msg_ping
Merge #19760: test: Remove confusing mininode terminology d5800da5199527a366024bc80cad7fcca17d5c4a [test] Remove final references to mininode (John Newbery) 5e8df3312e47a73e747ee892face55ed9ababeea test: resort imports (John Newbery) 85165d4332b0f72d30e0c584b476249b542338e6 scripted-diff: Rename mininode to p2p (John Newbery) 9e2897d020b114a10c860f90c5405be029afddba scripted-diff: Rename mininode_lock to p2p_lock (John Newbery) Pull request description: New contributors are often confused by the terminology in the test framework, and what the difference between a _node_ and a _peer_ is. To summarize: - a 'node' is a bitcoind instance. This is the thing whose behavior is being tested. Each bitcoind node is managed by a python `TestNode` object which is used to start/stop the node, manage the node's data directory, read state about the node (eg process status, log file), and interact with the node over different interfaces. - one of the interfaces that we can use to interact with the node is the p2p interface. Each connection to a node using this interface is managed by a python `P2PInterface` or derived object (which is owned by the `TestNode` object). We can open zero, one or many p2p connections to each bitcoind node. The node sees these connections as 'peers'. For historic reasons, the word 'mininode' has been used to refer to those p2p interface objects that we use to connect to the bitcoind node (the code was originally taken from the 'mini-node' branch of https://github.com/jgarzik/pynode/tree/mini-node). However that name has proved to be confusing for new contributors, so rename the remaining references. ACKs for top commit: amitiuttarwar: ACK d5800da519 MarcoFalke: ACK d5800da5199527a366024bc80cad7fcca17d5c4a 🚞 Tree-SHA512: 2c46c2ac3c4278b6e3c647cfd8108428a41e80788fc4f0e386e5b0c47675bc687d94779496c09a3e5ea1319617295be10c422adeeff2d2bd68378e00e0eeb5de
2024-01-15 20:35:29 +01:00
from test_framework.p2p import P2PInterface
from test_framework.test_framework import BitcoinTestFramework
Merge #18247: test: Wait for both veracks in add_p2p_connection faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke) fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke) Pull request description: 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 ACKs for top commit: jonatack: ACK faf1d04 Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2020-04-01 05:08:30 +02:00
class TestP2PConn(P2PInterface):
def on_version(self, message):
# Don't send a verack in response
pass
Merge #18247: test: Wait for both veracks in add_p2p_connection faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke) fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke) Pull request description: 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 ACKs for top commit: jonatack: ACK faf1d04 Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2020-04-01 05:08:30 +02:00
class TimeoutsTest(BitcoinTestFramework):
def set_test_params(self):
self.setup_clean_chain = True
self.num_nodes = 1
Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested. 48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia) 8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia) Pull request description: **Summary:** 1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting. 2. _Secondary_: Drastically speeds up `p2p_timeout.py` test. 3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test. **Rationale:** - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number. - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec. - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`. - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test. **Locally verified changes:** _With Proposed Change (4.7 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7 2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit 2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful real 0m4.743s ``` _Currently on master (62.8 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h 2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit 2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful real 1m2.836s ``` _Error message demonstrated for new argument `-peertimeout`:_ ``` $ ./bitcoind -peertimeout=-5 ... Error: peertimeout cannot be configured with a negative value. ``` Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a
2018-12-04 12:06:35 +01:00
# set timeout to receive version/verack to 3 seconds
self.extra_args = [["-peertimeout=3"]]
def run_test(self):
# Setup the p2p connections
Merge #18247: test: Wait for both veracks in add_p2p_connection faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke) fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke) Pull request description: 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 ACKs for top commit: jonatack: ACK faf1d04 Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2020-04-01 05:08:30 +02:00
no_verack_node = self.nodes[0].add_p2p_connection(TestP2PConn(), wait_for_verack=False)
no_version_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
no_send_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
Merge #18247: test: Wait for both veracks in add_p2p_connection faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke) fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke) Pull request description: 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 ACKs for top commit: jonatack: ACK faf1d04 Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2020-04-01 05:08:30 +02:00
# Wait until we got the verack in response to the version. Though, don't wait for the other node to receive the
# verack, since we never sent one
no_verack_node.wait_for_verack()
sleep(1)
assert no_verack_node.is_connected
assert no_version_node.is_connected
assert no_send_node.is_connected
no_verack_node.send_message(msg_ping())
no_version_node.send_message(msg_ping())
Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested. 48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia) 8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia) Pull request description: **Summary:** 1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting. 2. _Secondary_: Drastically speeds up `p2p_timeout.py` test. 3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test. **Rationale:** - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number. - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec. - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`. - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test. **Locally verified changes:** _With Proposed Change (4.7 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7 2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit 2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful real 0m4.743s ``` _Currently on master (62.8 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h 2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit 2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful real 1m2.836s ``` _Error message demonstrated for new argument `-peertimeout`:_ ``` $ ./bitcoind -peertimeout=-5 ... Error: peertimeout cannot be configured with a negative value. ``` Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a
2018-12-04 12:06:35 +01:00
sleep(1)
assert "version" in no_verack_node.last_message
assert no_verack_node.is_connected
assert no_version_node.is_connected
assert no_send_node.is_connected
no_verack_node.send_message(msg_ping())
no_version_node.send_message(msg_ping())
Merge #14733: P2P: Make peer timeout configurable, speed up very slow test and ensure correct code path tested. 48b37db50 make peertimeout a debug argument, remove error message translation (Zain Iqbal Allarakhia) 8042bbfbf p2p: allow p2ptimeout to be configurable, speed up slow test (Zain Iqbal Allarakhia) Pull request description: **Summary:** 1. _Primary_: Adds a `debug_only=true` flag for peertimeout, defaults to 60 sec., the current hard-coded setting. 2. _Secondary_: Drastically speeds up `p2p_timeout.py` test. 3. _Secondary_: Tests that the correct code path is being tested by adding log assertions to the test. **Rationale:** - P2P timeout was hard-coded: make it explicitly specified and configurable, instead of a magic number. - Addresses #13518; `p2p_timeout.py` takes 4 sec. to run instead of 61 sec. - Makes `p2p_timeout.py` more explicit. Previously, we relied on a comment to inform us of the timeout amount being tested. Now it is specified directly in the test via passing in the new arg; `-peertimeout=3`. - Opens us up to testing more P2P scenarios; oftentimes slow tests are the reason we don't test. **Locally verified changes:** _With Proposed Change (4.7 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:04:19.077000Z TestFramework (INFO): Initializing test directory /tmp/testhja7g2n7 2018-11-19T00:04:23.479000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:04:23.683000Z TestFramework (INFO): Cleaning up /tmp/testhja7g2n7 on exit 2018-11-19T00:04:23.683000Z TestFramework (INFO): Tests successful real 0m4.743s ``` _Currently on master (62.8 sec.):_ ``` $ time ./test/functional/p2p_timeouts.py 2018-11-19T00:06:10.948000Z TestFramework (INFO): Initializing test directory /tmp/test6mo6k21h 2018-11-19T00:07:13.376000Z TestFramework (INFO): Stopping nodes 2018-11-19T00:07:13.631000Z TestFramework (INFO): Cleaning up /tmp/test6mo6k21h on exit 2018-11-19T00:07:13.631000Z TestFramework (INFO): Tests successful real 1m2.836s ``` _Error message demonstrated for new argument `-peertimeout`:_ ``` $ ./bitcoind -peertimeout=-5 ... Error: peertimeout cannot be configured with a negative value. ``` Tree-SHA512: ff7a244ebea54c4059407bf4fb86465714e6a79cef5d2bcaa22cfe831a81761aaf597ba4d5172fc2ec12266f54712216fc41b5d24849e5d9dab39ba6f09e3a2a
2018-12-04 12:06:35 +01:00
expected_timeout_logs = [
"version handshake timeout from 0",
"socket no message in first 3 seconds, 1 0 from 1",
"socket no message in first 3 seconds, 0 0 from 2",
]
with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):
sleep(3 + 1) # Sleep one second more than peertimeout
assert not no_verack_node.is_connected
assert not no_version_node.is_connected
assert not no_send_node.is_connected
Merge #18247: test: Wait for both veracks in add_p2p_connection faf1d047313e71658fb31f6b94fdd5d37705ab85 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke) fa9064704524a0fd1fa9ea73eea45b07316ac3d1 test: Wait for both veracks in add_p2p_connection (MarcoFalke) Pull request description: 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 ACKs for top commit: jonatack: ACK faf1d04 Tree-SHA512: 3b1a38a5c87d11c610eee0988f0c4af9bfcd978df9ac718ef611f663df2fd4a0eb04e077df5e940d15971bb2f22328fb6021cacccb6902f1e527f288ad2c4a2c
2020-04-01 05:08:30 +02:00
if __name__ == '__main__':
TimeoutsTest().main()