2017-02-14 14:34:20 +01:00
|
|
|
#!/usr/bin/env python3
|
2023-08-16 19:27:31 +02:00
|
|
|
# Copyright (c) 2016-2020 The Bitcoin Core developers
|
2017-02-14 14:34:20 +01:00
|
|
|
# Distributed under the MIT software license, see the accompanying
|
|
|
|
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
|
2019-01-07 10:55:35 +01:00
|
|
|
"""Test various net timeouts.
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2024-03-25 16:54:04 +01:00
|
|
|
- Create three peers:
|
2017-02-14 14:34:20 +01:00
|
|
|
|
|
|
|
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.
|
|
|
|
|
|
|
|
- Wait 1 second
|
|
|
|
- Assert that we're connected
|
|
|
|
- Send a ping to no_verack_node and no_version_node
|
2018-12-04 12:06:35 +01:00
|
|
|
- Wait 1 second
|
2017-02-14 14:34:20 +01:00
|
|
|
- Assert that we're still connected
|
|
|
|
- Send a ping to no_verack_node and no_version_node
|
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)
|
2017-02-14 14:34:20 +01:00
|
|
|
"""
|
|
|
|
|
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
|
2024-01-15 20:35:29 +01:00
|
|
|
from test_framework.p2p import P2PInterface
|
2017-02-14 14:34:20 +01:00
|
|
|
from test_framework.test_framework import BitcoinTestFramework
|
|
|
|
|
2024-03-25 16:54:04 +01:00
|
|
|
import time
|
|
|
|
|
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
|
|
|
|
2018-03-20 11:44:19 +01:00
|
|
|
class TestP2PConn(P2PInterface):
|
2020-04-05 13:12:45 +02:00
|
|
|
def on_version(self, message):
|
2017-02-14 14:34:20 +01:00
|
|
|
# Don't send a verack in response
|
2017-05-02 19:10:23 +02:00
|
|
|
pass
|
2017-02-14 14:34:20 +01:00
|
|
|
|
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
|
|
|
|
2017-02-14 14:34:20 +01:00
|
|
|
class TimeoutsTest(BitcoinTestFramework):
|
2017-09-01 18:47:13 +02:00
|
|
|
def set_test_params(self):
|
2017-02-14 14:34:20 +01:00
|
|
|
self.setup_clean_chain = True
|
|
|
|
self.num_nodes = 1
|
2018-12-04 12:06:35 +01:00
|
|
|
# set timeout to receive version/verack to 3 seconds
|
|
|
|
self.extra_args = [["-peertimeout=3"]]
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2024-03-25 16:54:04 +01:00
|
|
|
def mock_forward(self, delta):
|
|
|
|
self.mock_time += delta
|
|
|
|
self.nodes[0].setmocktime(self.mock_time)
|
|
|
|
|
2017-02-14 14:34:20 +01:00
|
|
|
def run_test(self):
|
2024-03-25 16:54:04 +01:00
|
|
|
self.mock_time = int(time.time())
|
|
|
|
self.mock_forward(0)
|
|
|
|
|
2021-12-20 09:13:17 +01:00
|
|
|
# Setup the p2p connections, making sure the connections are established before the mocktime is bumped
|
|
|
|
with self.nodes[0].assert_debug_log(['Added connection peer=0']):
|
|
|
|
no_verack_node = self.nodes[0].add_p2p_connection(TestP2PConn(), wait_for_verack=False)
|
|
|
|
with self.nodes[0].assert_debug_log(['Added connection peer=1']):
|
|
|
|
no_version_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
|
|
|
|
with self.nodes[0].assert_debug_log(['Added connection peer=2']):
|
|
|
|
no_send_node = self.nodes[0].add_p2p_connection(TestP2PConn(), send_version=False, wait_for_verack=False)
|
2017-02-14 14:34:20 +01:00
|
|
|
|
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()
|
|
|
|
|
2024-03-25 16:54:04 +01:00
|
|
|
self.mock_forward(1)
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2018-06-24 01:28:13 +02:00
|
|
|
assert no_verack_node.is_connected
|
|
|
|
assert no_version_node.is_connected
|
|
|
|
assert no_send_node.is_connected
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2020-12-12 12:31:26 +01:00
|
|
|
with self.nodes[0].assert_debug_log(['Unsupported message "ping" prior to verack from peer=0']):
|
|
|
|
no_verack_node.send_message(msg_ping())
|
|
|
|
with self.nodes[0].assert_debug_log(['non-version message before version handshake. Message "ping" from peer=1']):
|
|
|
|
no_version_node.send_message(msg_ping())
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2024-03-25 16:54:04 +01:00
|
|
|
self.mock_forward(1)
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
assert "version" in no_verack_node.last_message
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2018-06-24 01:28:13 +02:00
|
|
|
assert no_verack_node.is_connected
|
|
|
|
assert no_version_node.is_connected
|
|
|
|
assert no_send_node.is_connected
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
no_verack_node.send_message(msg_ping())
|
|
|
|
no_version_node.send_message(msg_ping())
|
2017-02-14 14:34:20 +01:00
|
|
|
|
2018-12-04 12:06:35 +01:00
|
|
|
expected_timeout_logs = [
|
2024-03-24 09:01:35 +01:00
|
|
|
"version handshake timeout peer=0",
|
|
|
|
"socket no message in first 3 seconds, 1 0 peer=1",
|
|
|
|
"socket no message in first 3 seconds, 0 0 peer=2",
|
2018-12-04 12:06:35 +01:00
|
|
|
]
|
|
|
|
|
|
|
|
with self.nodes[0].assert_debug_log(expected_msgs=expected_timeout_logs):
|
2024-03-25 16:54:04 +01:00
|
|
|
self.mock_forward(3)
|
|
|
|
no_verack_node.wait_for_disconnect(timeout=1)
|
|
|
|
no_version_node.wait_for_disconnect(timeout=1)
|
|
|
|
no_send_node.wait_for_disconnect(timeout=1)
|
2017-02-14 14:34:20 +01:00
|
|
|
|
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
|
|
|
|
2017-02-14 14:34:20 +01:00
|
|
|
if __name__ == '__main__':
|
|
|
|
TimeoutsTest().main()
|