2017-08-15 23:34:07 +02:00
|
|
|
#!/usr/bin/env python3
|
|
|
|
# Copyright (c) 2017 The Bitcoin Core developers
|
|
|
|
# Distributed under the MIT software license, see the accompanying
|
|
|
|
# file COPYING or http://www.opensource.org/licenses/mit-license.php.
|
2019-09-23 21:36:47 +02:00
|
|
|
"""Class for dashd node under test"""
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2020-06-13 06:50:03 +02:00
|
|
|
import contextlib
|
2017-08-24 22:01:16 +02:00
|
|
|
import decimal
|
2017-08-15 23:34:07 +02:00
|
|
|
import errno
|
2021-04-08 22:29:01 +02:00
|
|
|
from enum import Enum
|
2017-08-15 23:34:07 +02:00
|
|
|
import http.client
|
2017-08-24 22:01:16 +02:00
|
|
|
import json
|
2017-08-15 23:34:07 +02:00
|
|
|
import logging
|
2020-07-22 19:18:11 +02:00
|
|
|
import os.path
|
2018-01-12 23:24:36 +01:00
|
|
|
import re
|
2017-08-15 23:34:07 +02:00
|
|
|
import subprocess
|
2018-03-22 10:18:33 +01:00
|
|
|
import tempfile
|
2017-08-15 23:34:07 +02:00
|
|
|
import time
|
2018-08-02 15:58:39 +02:00
|
|
|
import urllib.parse
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
import shlex
|
|
|
|
import sys
|
2018-09-17 20:00:41 +02:00
|
|
|
import collections
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
from .authproxy import JSONRPCException
|
2020-06-17 12:20:04 +02:00
|
|
|
from .messages import MY_SUBVERSION
|
2017-08-15 23:34:07 +02:00
|
|
|
from .util import (
|
2019-05-24 13:00:54 +02:00
|
|
|
MAX_NODES,
|
2018-03-07 14:51:58 +01:00
|
|
|
append_config,
|
2018-04-10 01:11:07 +02:00
|
|
|
delete_cookie_file,
|
2020-04-18 17:03:13 +02:00
|
|
|
get_auth_cookie,
|
2017-08-15 23:34:07 +02:00
|
|
|
get_rpc_proxy,
|
|
|
|
rpc_url,
|
2017-09-06 20:02:08 +02:00
|
|
|
wait_until,
|
2017-11-08 19:10:43 +01:00
|
|
|
p2p_port,
|
2021-01-22 15:58:07 +01:00
|
|
|
get_chain_folder,
|
2019-12-12 02:10:59 +01:00
|
|
|
EncodeDecimal,
|
2017-08-15 23:34:07 +02:00
|
|
|
)
|
|
|
|
|
2017-09-06 20:02:08 +02:00
|
|
|
BITCOIND_PROC_WAIT_TIMEOUT = 60
|
|
|
|
|
2018-03-30 17:39:50 +02:00
|
|
|
|
|
|
|
class FailedToStartError(Exception):
|
|
|
|
"""Raised when a node fails to start correctly."""
|
|
|
|
|
|
|
|
|
2021-04-08 22:29:01 +02:00
|
|
|
class ErrorMatch(Enum):
|
|
|
|
FULL_TEXT = 1
|
|
|
|
FULL_REGEX = 2
|
|
|
|
PARTIAL_REGEX = 3
|
|
|
|
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
class TestNode():
|
2019-09-23 21:36:47 +02:00
|
|
|
"""A class for representing a dashd node under test.
|
2017-08-15 23:34:07 +02:00
|
|
|
|
|
|
|
This class contains:
|
|
|
|
|
|
|
|
- state about the node (whether it's running, etc)
|
|
|
|
- a Python subprocess.Popen object representing the running process
|
|
|
|
- an RPC connection to the node
|
2017-11-08 19:10:43 +01:00
|
|
|
- one or more P2P connections to the node
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
To make things easier for the test writer, any unrecognised messages will
|
|
|
|
be dispatched to the RPC connection."""
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2020-05-19 02:00:24 +02:00
|
|
|
def __init__(self, i, datadir, extra_args_from_options, *, chain, rpchost, timewait, timeout_factor, bitcoind, bitcoin_cli, mocktime, coverage_dir, cwd, extra_conf=None, extra_args=None, use_cli=False, start_perf=False, use_valgrind=False):
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
"""
|
|
|
|
Kwargs:
|
|
|
|
start_perf (bool): If True, begin profiling the node with `perf` as soon as
|
|
|
|
the node starts.
|
|
|
|
"""
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
self.index = i
|
2018-03-22 11:04:37 +01:00
|
|
|
self.datadir = datadir
|
2021-01-22 15:58:07 +01:00
|
|
|
self.chain = chain
|
Merge #16248: Make whitebind/whitelist permissions more flexible
c5b404e8f1973afe071a07c63ba1038eefe13f0f Add functional tests for flexible whitebind/list (nicolas.dorier)
d541fa391844f658bd7035659b5b16695733dd56 Replace the use of fWhitelisted by permission checks (nicolas.dorier)
ecd5cf7ea4c3644a30092100ffc399e30e193275 Do not disconnect peer for asking mempool if it has NO_BAN permission (nicolas.dorier)
e5b26deaaa6842f7dd7c4537ede000f965ea0189 Make whitebind/whitelist permissions more flexible (nicolas.dorier)
Pull request description:
# Motivation
In 0.19, bloom filter will be disabled by default. I tried to make [a PR](https://github.com/bitcoin/bitcoin/pull/16176) to enable bloom filter for whitelisted peers regardless of `-peerbloomfilters`.
Bloom filter have non existent privacy and server can omit filter's matches. However, both problems are completely irrelevant when you connect to your own node. If you connect to your own node, bloom filters are the most bandwidth efficient way to synchronize your light client without the need of some middleware like Electrum.
It is also a superior alternative to BIP157 as it does not require to maintain an additional index and it would work well on pruned nodes.
When I attempted to allow bloom filters for whitelisted peer, my proposal has been NACKed in favor of [a more flexible approach](https://github.com/bitcoin/bitcoin/pull/16176#issuecomment-500762907) which should allow node operator to set fine grained permissions instead of a global `whitelisted` attribute.
Doing so will also make follow up idea very easy to implement in a backward compatible way.
# Implementation details
The PR propose a new format for `--white{list,bind}`. I added a way to specify permissions granted to inbound connection matching `white{list,bind}`.
The following permissions exists:
* ForceRelay
* Relay
* NoBan
* BloomFilter
* Mempool
Example:
* `-whitelist=bloomfilter@127.0.0.1/32`.
* `-whitebind=bloomfilter,relay,noban@127.0.0.1:10020`.
If no permissions are specified, `NoBan | Mempool` is assumed. (making this PR backward compatible)
When we receive an inbound connection, we calculate the effective permissions for this peer by fetching the permissions granted from `whitelist` and add to it the permissions granted from `whitebind`.
To keep backward compatibility, if no permissions are specified in `white{list,bind}` (e.g. `--whitelist=127.0.0.1`) then parameters `-whitelistforcerelay` and `-whiterelay` will add the permissions `ForceRelay` and `Relay` to the inbound node.
`-whitelistforcerelay` and `-whiterelay` are ignored if the permissions flags are explicitly set in `white{bind,list}`.
# Follow up idea
Based on this PR, other changes become quite easy to code in a trivially review-able, backward compatible way:
* Changing `connect` at rpc and config file level to understand the permissions flags.
* Changing the permissions of a peer at RPC level.
ACKs for top commit:
laanwj:
re-ACK c5b404e8f1973afe071a07c63ba1038eefe13f0f
Tree-SHA512: adfefb373d09e68cae401247c8fc64034e305694cdef104bdcdacb9f1704277bd53b18f52a2427a5cffdbc77bda410d221aed252bc2ece698ffbb9cf1b830577
2019-08-14 16:35:54 +02:00
|
|
|
self.bitcoinconf = os.path.join(self.datadir, "dash.conf")
|
2021-06-17 19:05:11 +02:00
|
|
|
self.stdout_dir = os.path.join(self.datadir, "stdout")
|
|
|
|
self.stderr_dir = os.path.join(self.datadir, "stderr")
|
2017-08-15 23:34:07 +02:00
|
|
|
self.rpchost = rpchost
|
2018-08-02 14:31:47 +02:00
|
|
|
self.rpc_timeout = timewait
|
2018-04-25 15:54:36 +02:00
|
|
|
self.binary = bitcoind
|
2017-08-15 23:34:07 +02:00
|
|
|
self.coverage_dir = coverage_dir
|
2019-02-19 16:12:07 +01:00
|
|
|
self.cwd = cwd
|
2020-04-17 07:52:06 +02:00
|
|
|
self.mocktime = mocktime
|
2018-12-13 12:57:41 +01:00
|
|
|
if extra_conf is not None:
|
2018-03-22 11:04:37 +01:00
|
|
|
append_config(datadir, extra_conf)
|
2018-03-07 14:51:58 +01:00
|
|
|
# Most callers will just need to add extra args to the standard list below.
|
|
|
|
# For those callers that need more flexibity, they can just set the args property directly.
|
2020-12-11 03:08:07 +01:00
|
|
|
# Note that common args are set in the config file (see initialize_datadir)
|
2017-08-15 23:34:07 +02:00
|
|
|
self.extra_args = extra_args
|
2020-04-16 11:23:49 +02:00
|
|
|
self.extra_args_from_options = extra_args_from_options
|
2021-11-08 18:20:39 +01:00
|
|
|
# Configuration for logging is set as command-line args rather than in the bitcoin.conf file.
|
|
|
|
# This means that starting a bitcoind using the temp dir to debug a failed test won't
|
|
|
|
# spam debug.log.
|
2018-04-17 17:07:19 +02:00
|
|
|
self.args = [
|
|
|
|
self.binary,
|
|
|
|
"-datadir=" + self.datadir,
|
|
|
|
"-logtimemicros",
|
2021-11-08 18:20:39 +01:00
|
|
|
"-logthreadnames",
|
2018-04-17 17:07:19 +02:00
|
|
|
"-debug",
|
|
|
|
"-debugexclude=libevent",
|
|
|
|
"-debugexclude=leveldb",
|
|
|
|
"-mocktime=" + str(mocktime),
|
2018-05-09 20:43:09 +02:00
|
|
|
"-uacomment=testnode%d" % i
|
2018-04-17 17:07:19 +02:00
|
|
|
]
|
Merge #17633: tests: Add option --valgrind to run the functional tests under Valgrind
5db506ba5943868cc2c845f717508739b7f05714 tests: Add option --valgrind to run nodes under valgrind in the functional tests (practicalswift)
Pull request description:
What is better than fixing bugs? Fixing entire bug classes of course! :)
Add option `--valgrind` to run the functional tests under Valgrind.
Regular functional testing under Valgrind would have caught many of the uninitialized reads we've seen historically.
Let's kill this bug class once and for all: let's never use an uninitialized value ever again. Or at least not one that would be triggered by running the functional tests! :)
My hope is that this addition will make it super-easy to run the functional tests under Valgrind and thus increase the probability of people making use of it :)
Hopefully `test/functional/test_runner.py --valgrind` will become a natural part of the pre-release QA process.
**Usage:**
```
$ test/functional/test_runner.py --help
…
--valgrind run nodes under the valgrind memory error detector:
expect at least a ~10x slowdown, valgrind 3.14 or
later required
```
**Live demo:**
First, let's re-introduce a memory bug by reverting the recent P2P uninitialized read bug fix from PR #17624 ("net: Fix an uninitialized read in ProcessMessage(…, "tx", …) when receiving a transaction we already have").
```
$ git diff
diff --git a/src/consensus/validation.h b/src/consensus/validation.h
index 3401eb64c..940adea33 100644
--- a/src/consensus/validation.h
+++ b/src/consensus/validation.h
@@ -114,7 +114,7 @@ inline ValidationState::~ValidationState() {};
class TxValidationState : public ValidationState {
private:
- TxValidationResult m_result = TxValidationResult::TX_RESULT_UNSET;
+ TxValidationResult m_result;
public:
bool Invalid(TxValidationResult result,
const std::string &reject_reason="",
```
Second, let's test as normal without Valgrind:
```
$ test/functional/p2p_segwit.py -l INFO
2019-11-28T09:30:42.810000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test__fc8q3qo
…
2019-11-28T09:31:57.187000Z TestFramework (INFO): Subtest: test_non_standard_witness_blinding (Segwit active = True)
…
2019-11-28T09:32:08.265000Z TestFramework (INFO): Tests successful
```
Third, let's test with `--valgrind` and see if the test fail (as we expect) when the unitialized value is used:
```
$ test/functional/p2p_segwit.py -l INFO --valgrind
2019-11-28T09:32:33.018000Z TestFramework (INFO): Initializing test directory /tmp/bitcoin_func_test_gtjecx2l
…
2019-11-28T09:40:36.702000Z TestFramework (INFO): Subtest: test_non_standard_witness_blinding (Segwit active = True)
2019-11-28T09:40:37.813000Z TestFramework (ERROR): Assertion failed
ConnectionRefusedError: [Errno 111] Connection refused
```
ACKs for top commit:
MarcoFalke:
ACK 5db506ba5943868cc2c845f717508739b7f05714
jonatack:
ACK 5db506ba5943868cc2c845f717508739b7f05714
Tree-SHA512: 2eaecacf4da166febad88b2a8ee6d7ac2bcd38d4c1892ca39516b6343e8f8c8814edf5eaf14c90f11a069a0389d24f0713076112ac284de987e72fc5f6cc3795
2019-12-10 19:30:05 +01:00
|
|
|
if use_valgrind:
|
|
|
|
default_suppressions_file = os.path.join(
|
|
|
|
os.path.dirname(os.path.realpath(__file__)),
|
|
|
|
"..", "..", "..", "contrib", "valgrind.supp")
|
|
|
|
suppressions_file = os.getenv("VALGRIND_SUPPRESSIONS_FILE",
|
|
|
|
default_suppressions_file)
|
|
|
|
self.args = ["valgrind", "--suppressions={}".format(suppressions_file),
|
|
|
|
"--gen-suppressions=all", "--exit-on-first-error=yes",
|
|
|
|
"--error-exitcode=1", "--quiet"] + self.args
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2018-04-25 15:54:36 +02:00
|
|
|
self.cli = TestNodeCLI(bitcoin_cli, self.datadir)
|
2018-01-12 23:24:36 +01:00
|
|
|
self.use_cli = use_cli
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
self.start_perf = start_perf
|
2017-08-24 22:01:16 +02:00
|
|
|
|
2019-09-23 21:43:21 +02:00
|
|
|
# Don't try auto backups (they fail a lot when running tests)
|
|
|
|
self.args.append("-createwalletbackups=0")
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
self.running = False
|
|
|
|
self.process = None
|
|
|
|
self.rpc_connected = False
|
|
|
|
self.rpc = None
|
|
|
|
self.url = None
|
|
|
|
self.log = logging.getLogger('TestFramework.node%d' % i)
|
2018-04-08 17:05:44 +02:00
|
|
|
self.cleanup_on_exit = True # Whether to kill the node when this object goes away
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
# Cache perf subprocesses here by their data output filename.
|
|
|
|
self.perf_subprocesses = {}
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
self.p2ps = []
|
2020-05-19 02:00:24 +02:00
|
|
|
self.timeout_factor = timeout_factor
|
2017-11-08 19:10:43 +01:00
|
|
|
|
2019-05-24 13:00:54 +02:00
|
|
|
AddressKeyPair = collections.namedtuple('AddressKeyPair', ['address', 'key'])
|
|
|
|
PRIV_KEYS = [
|
2018-09-13 23:45:32 +02:00
|
|
|
# address , privkey
|
2018-09-17 20:00:41 +02:00
|
|
|
AddressKeyPair('yYdShjQSptFKitYLksFEUSwHe4hnbar5rf', 'cMfbiEsnG5b8Gwm6vEgfWvZLuXZNC4zsN2y7Es3An9xHRWRjmwgR'),
|
|
|
|
AddressKeyPair('yfTFJgvq65UZsb9RBbpdYAAzsJoCGXqH2w', 'cStuFACUD1N6JjKQxNLUQ443qJUtSzLitKKEkA8x6utxTPZTLUtA'),
|
|
|
|
AddressKeyPair('yU3w4VDjKhHiZpWszkUZVnFTS56AfgdfPV', 'cQb5yh2sTiG7dsxxbXHhWSBLMByYT7jY49A1kC7zKhgL9WNHysWW'),
|
|
|
|
AddressKeyPair('yYhzix2R5LiYnDixsUnF8XwBYGYpyeTgB4', 'cW9Gu6uU4KoZJQcdyUvjULNRg4C8srPJw1adhgdTZMr9YQdKHtcn'),
|
|
|
|
AddressKeyPair('yiQ3qLx5L1BW9XA6JAG7hC8UQDktcBCeYG', 'cSq7gHVC1QPsswyX2pE5C38UnWZXfCLr7XnkjnDwuZ68NkWp183T'),
|
|
|
|
AddressKeyPair('yUL8h8mR7aNDRsU5zhcDbpp6YtA6ieUtK2', 'cTk7hiDKgxZX3JSb37vywdYYjjJows4DQjEaxBJDGF6LC6GXvPKo'),
|
|
|
|
AddressKeyPair('yfy21e12jn3A3uDicNehCq486o9fMwJKMc', 'cMuko9rLDbtxCFWuBSrFgBDRSMxsLWKpJKScRGNuWKbhuQsnsjKT'),
|
|
|
|
AddressKeyPair('yURgENB3b2YRMWnbhKF7iGs3KoaVRVXsJr', 'cQhdjTMh57MaHCDk9FsWGPtftRMBUuhaYAtouWnetcewmBuSrLSM'),
|
|
|
|
AddressKeyPair('yYC9AxBEUs3ZZxfcQvj2LUF5PVxxtqaEs7', 'cQFueiiP13mfytV3Svoe4o4Ux79fRJvwuSgHapXsnBwrHod57EeL'),
|
2019-05-24 13:00:54 +02:00
|
|
|
AddressKeyPair('yVs9jXGyLWLLFbpESnoppk7F8DtXcuCCTf', 'cN55daf1HotwBAgAKWVgDcoppmUNDtQSfb7XLutTLeAgVc3u8hik'),
|
|
|
|
AddressKeyPair('yV3eqNNshZJ4Pv6NCyYsbdJb1ERFFygFqf', 'cT7qK7g1wkYEMvKowd2ZrX1E5f6JQ7TM246UfqbCiyF7kZhorpX3'),
|
|
|
|
AddressKeyPair('yfE8gZCiFW9Uqu21v3JGibr3WVSPQWmY8n', 'cPiRWE8KMjTRxH1MWkPerhfoHFn5iHPWVK5aPqjW8NxmdwenFinJ'),
|
|
|
|
AddressKeyPair('yLLVXzya7GzmVkjQzsCG4iDpqYJyJFDSEV', 'cVLCocFyWxzyCwEknkWvDeWneTBsh9Jf3u4yiJCYjcy3gt8Jw1cM'),
|
|
|
|
AddressKeyPair('yLNNR3HeJxgR669oRePksYmCqHuPUG79mF', 'cQawC3oUgoToGDJBw1Ub2PpDmf44kVtcaVaTcHyzXMRKGwdn9UYW'),
|
|
|
|
AddressKeyPair('yLPKVwRTXME7Q3JfKAPJ4FHEaGdWgJuhpj', 'cVcFaWTbkCUZPFTHfDs8iHurPWns5QXc5rqcfkPMHUdmv17o8UYB'),
|
|
|
|
AddressKeyPair('yLPUundzTpvjU8KYVyM4Zmnr4REf3FFvhZ', 'cRVeRmRaYuEYP9HbCZFsf1ifYYZ4KQD9rttRoTNb9wjPzhvRwqMb'),
|
|
|
|
AddressKeyPair('yLRhHqau58AS1ALtnaowv1Pyztxi1Q6fXG', 'cNYFW52pJswYbfPR9fpiRpWHEQygg5tyMih2ASPsgMgPy9SUSSEV'),
|
|
|
|
AddressKeyPair('yLRwHeMkXwYrkDzC4q12vej243AyTeWiPm', 'cRqfZ3dAp8BJUcGhSv7ueCXNGbki1bpcXEKk5dEJN344H52GuHQY'),
|
|
|
|
AddressKeyPair('yLTMCXJhG1mpaWhbHcsr7zUt9wDWuQSPSk', 'cVWGbeCT5QcVGVTL5NuiLs9JfL8HFDb9PN5Gq2xudw6ZsDFeDy1V'),
|
|
|
|
AddressKeyPair('yLU9vxiAWUdiKKxn6EazLDFq9WXrK2T7RP', 'cVCzrzfxMhUMxV34UhTmdmntAqHvosAuNo2KUZsiHZSKLm73g35o'),
|
|
|
|
]
|
|
|
|
|
|
|
|
def get_deterministic_priv_key(self):
|
|
|
|
"""Return a deterministic priv key in base58, that only depends on the node's index"""
|
|
|
|
assert len(self.PRIV_KEYS) == MAX_NODES
|
|
|
|
return self.PRIV_KEYS[self.index]
|
2018-09-10 22:58:15 +02:00
|
|
|
|
2018-04-24 11:06:11 +02:00
|
|
|
def _node_msg(self, msg: str) -> str:
|
|
|
|
"""Return a modified msg that identifies this node by its index as a debugging aid."""
|
|
|
|
return "[node %d] %s" % (self.index, msg)
|
|
|
|
|
|
|
|
def _raise_assertion_error(self, msg: str):
|
|
|
|
"""Raise an AssertionError with msg modified to identify this node."""
|
|
|
|
raise AssertionError(self._node_msg(msg))
|
|
|
|
|
2018-04-08 17:05:44 +02:00
|
|
|
def __del__(self):
|
2020-06-11 10:39:04 +02:00
|
|
|
# Ensure that we don't leave any dashd processes lying around after
|
2018-04-08 17:05:44 +02:00
|
|
|
# the test ends
|
|
|
|
if self.process and self.cleanup_on_exit:
|
|
|
|
# Should only happen on test failure
|
|
|
|
# Avoid using logger, as that may have already been shutdown when
|
|
|
|
# this destructor is called.
|
2018-04-24 11:06:11 +02:00
|
|
|
print(self._node_msg("Cleaning up leftover process"))
|
2018-04-08 17:05:44 +02:00
|
|
|
self.process.kill()
|
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
def __getattr__(self, name):
|
2018-01-12 23:24:36 +01:00
|
|
|
"""Dispatches any unrecognised messages to the RPC connection or a CLI instance."""
|
|
|
|
if self.use_cli:
|
|
|
|
return getattr(self.cli, name)
|
|
|
|
else:
|
2018-04-24 11:06:11 +02:00
|
|
|
assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
|
2018-01-12 23:24:36 +01:00
|
|
|
return getattr(self.rpc, name)
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2019-02-19 16:12:07 +01:00
|
|
|
def start(self, extra_args=None, *, cwd=None, stdout=None, stderr=None, **kwargs):
|
2017-08-15 23:34:07 +02:00
|
|
|
"""Start the node."""
|
2017-09-01 18:47:13 +02:00
|
|
|
if extra_args is None:
|
|
|
|
extra_args = self.extra_args
|
2021-06-17 19:05:11 +02:00
|
|
|
|
|
|
|
# Add a new stdout and stderr file each time dashd is started
|
2017-09-01 18:47:13 +02:00
|
|
|
if stderr is None:
|
2021-06-17 19:05:11 +02:00
|
|
|
stderr = tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False)
|
|
|
|
if stdout is None:
|
|
|
|
stdout = tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False)
|
|
|
|
self.stderr = stderr
|
|
|
|
self.stdout = stdout
|
|
|
|
|
2019-02-19 16:12:07 +01:00
|
|
|
if cwd is None:
|
|
|
|
cwd = self.cwd
|
|
|
|
|
2020-04-16 11:23:49 +02:00
|
|
|
all_args = self.args + self.extra_args_from_options + extra_args
|
2020-04-17 07:52:06 +02:00
|
|
|
if self.mocktime != 0:
|
|
|
|
all_args = all_args + ["-mocktime=%d" % self.mocktime]
|
2021-06-17 19:05:11 +02:00
|
|
|
|
2018-04-10 01:11:07 +02:00
|
|
|
# Delete any existing cookie file -- if such a file exists (eg due to
|
2020-06-11 10:39:04 +02:00
|
|
|
# unclean shutdown), it will get overwritten anyway by dashd, and
|
2018-04-10 01:11:07 +02:00
|
|
|
# potentially interfere with our attempt to authenticate
|
2021-01-22 15:58:07 +01:00
|
|
|
delete_cookie_file(self.datadir, self.chain)
|
2021-06-17 19:05:11 +02:00
|
|
|
|
|
|
|
# add environment variable LIBC_FATAL_STDERR_=1 so that libc errors are written to stderr and not the terminal
|
|
|
|
subp_env = dict(os.environ, LIBC_FATAL_STDERR_="1")
|
|
|
|
|
2019-02-19 16:12:07 +01:00
|
|
|
self.process = subprocess.Popen(all_args, env=subp_env, stdout=stdout, stderr=stderr, cwd=cwd, **kwargs)
|
2021-06-17 19:05:11 +02:00
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
self.running = True
|
2019-09-23 21:36:47 +02:00
|
|
|
self.log.debug("dashd started, waiting for RPC to come up")
|
2017-08-15 23:34:07 +02:00
|
|
|
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
if self.start_perf:
|
|
|
|
self._start_perf()
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
def wait_for_rpc_connection(self):
|
2019-09-23 21:36:47 +02:00
|
|
|
"""Sets up an RPC connection to the dashd process. Returns False if unable to connect."""
|
2017-08-23 18:05:43 +02:00
|
|
|
# Poll at a rate of four times per second
|
|
|
|
poll_per_s = 4
|
|
|
|
for _ in range(poll_per_s * self.rpc_timeout):
|
2018-03-30 17:39:50 +02:00
|
|
|
if self.process.poll() is not None:
|
2018-04-24 11:06:11 +02:00
|
|
|
raise FailedToStartError(self._node_msg(
|
|
|
|
'dashd exited with status {} during initialization'.format(self.process.returncode)))
|
2017-08-15 23:34:07 +02:00
|
|
|
try:
|
2020-05-21 17:26:45 +02:00
|
|
|
rpc = get_rpc_proxy(
|
|
|
|
rpc_url(self.datadir, self.index, self.chain, self.rpchost),
|
|
|
|
self.index,
|
|
|
|
timeout=self.rpc_timeout // 2, # Shorter timeout to allow for one retry in case of ETIMEDOUT
|
|
|
|
coveragedir=self.coverage_dir,
|
|
|
|
)
|
2019-02-07 16:15:25 +01:00
|
|
|
rpc.getblockcount()
|
2017-08-15 23:34:07 +02:00
|
|
|
# If the call to getblockcount() succeeds then the RPC connection is up
|
2022-09-07 20:48:44 +02:00
|
|
|
wait_until(lambda: rpc.getmempoolinfo()['loaded'])
|
|
|
|
# Wait for the node to finish reindex, block import, and
|
|
|
|
# loading the mempool. Usually importing happens fast or
|
|
|
|
# even "immediate" when the node is started. However, there
|
|
|
|
# is no guarantee and sometimes ThreadImport might finish
|
|
|
|
# later. This is going to cause intermittent test failures,
|
|
|
|
# because generally the tests assume the node is fully
|
|
|
|
# ready after being started.
|
|
|
|
#
|
|
|
|
# For example, the node will reject block messages from p2p
|
|
|
|
# when it is still importing with the error "Unexpected
|
|
|
|
# block message received"
|
|
|
|
#
|
|
|
|
# The wait is done here to make tests as robust as possible
|
|
|
|
# and prevent racy tests and intermittent failures as much
|
|
|
|
# as possible. Some tests might not need this, but the
|
2020-05-19 02:00:24 +02:00
|
|
|
# overhead is trivial, and the added guarantees are worth
|
2022-09-07 20:48:44 +02:00
|
|
|
# the minimal performance cost.
|
2019-02-07 16:15:25 +01:00
|
|
|
self.log.debug("RPC successfully started")
|
|
|
|
if self.use_cli:
|
|
|
|
return
|
|
|
|
self.rpc = rpc
|
2017-08-15 23:34:07 +02:00
|
|
|
self.rpc_connected = True
|
|
|
|
self.url = self.rpc.url
|
|
|
|
return
|
|
|
|
except JSONRPCException as e: # Initialization phase
|
2019-10-17 11:59:21 +02:00
|
|
|
# -28 RPC in warmup
|
|
|
|
# -342 Service unavailable, RPC server started but is shutting down due to error
|
|
|
|
if e.error['code'] != -28 and e.error['code'] != -342:
|
2017-08-15 23:34:07 +02:00
|
|
|
raise # unknown JSON RPC exception
|
2020-04-09 16:21:13 +02:00
|
|
|
except ConnectionResetError:
|
|
|
|
# This might happen when the RPC server is in warmup, but shut down before the call to getblockcount
|
|
|
|
# succeeds. Try again to properly raise the FailedToStartError
|
|
|
|
pass
|
2020-04-19 12:10:04 +02:00
|
|
|
except OSError as e:
|
2020-05-21 17:26:45 +02:00
|
|
|
if e.errno == errno.ETIMEDOUT:
|
|
|
|
pass # Treat identical to ConnectionResetError
|
|
|
|
elif e.errno == errno.ECONNREFUSED:
|
|
|
|
pass # Port not yet open?
|
|
|
|
else:
|
2020-04-19 12:10:04 +02:00
|
|
|
raise # unknown OS error
|
2020-04-18 17:03:13 +02:00
|
|
|
except ValueError as e: # cookie file not found and no rpcuser or rpcpassword; dashd is still starting
|
2017-08-15 23:34:07 +02:00
|
|
|
if "No RPC credentials" not in str(e):
|
|
|
|
raise
|
2017-08-20 15:04:26 +02:00
|
|
|
time.sleep(1.0 / poll_per_s)
|
2020-04-18 18:56:55 +02:00
|
|
|
self._raise_assertion_error("Unable to connect to dashd after {}s".format(self.rpc_timeout))
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2020-04-18 17:03:13 +02:00
|
|
|
def wait_for_cookie_credentials(self):
|
|
|
|
"""Ensures auth cookie credentials can be read, e.g. for testing CLI with -rpcwait before RPC connection is up."""
|
|
|
|
self.log.debug("Waiting for cookie credentials")
|
|
|
|
# Poll at a rate of four times per second.
|
|
|
|
poll_per_s = 4
|
|
|
|
for _ in range(poll_per_s * self.rpc_timeout):
|
|
|
|
try:
|
|
|
|
get_auth_cookie(self.datadir, self.chain)
|
|
|
|
self.log.debug("Cookie credentials successfully retrieved")
|
|
|
|
return
|
|
|
|
except ValueError: # cookie file not found and no rpcuser or rpcpassword; bitcoind is still starting
|
|
|
|
pass # so we continue polling until RPC credentials are retrieved
|
|
|
|
time.sleep(1.0 / poll_per_s)
|
|
|
|
self._raise_assertion_error("Unable to retrieve cookie credentials after {}s".format(self.rpc_timeout))
|
|
|
|
|
2018-10-24 00:11:26 +02:00
|
|
|
def generate(self, nblocks, maxtries=1000000):
|
|
|
|
self.log.debug("TestNode.generate() dispatches `generate` call to `generatetoaddress`")
|
|
|
|
return self.generatetoaddress(nblocks=nblocks, address=self.get_deterministic_priv_key().address, maxtries=maxtries)
|
|
|
|
|
2017-08-15 23:34:07 +02:00
|
|
|
def get_wallet_rpc(self, wallet_name):
|
2018-01-12 23:24:36 +01:00
|
|
|
if self.use_cli:
|
|
|
|
return self.cli("-rpcwallet={}".format(wallet_name))
|
|
|
|
else:
|
2018-04-24 11:06:11 +02:00
|
|
|
assert self.rpc_connected and self.rpc, self._node_msg("RPC not connected")
|
2018-08-02 15:58:39 +02:00
|
|
|
wallet_path = "wallet/{}".format(urllib.parse.quote(wallet_name))
|
2018-01-12 23:24:36 +01:00
|
|
|
return self.rpc / wallet_path
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2022-09-07 20:48:44 +02:00
|
|
|
def version_is_at_least(self, ver):
|
|
|
|
return self.version is None or self.version >= ver
|
|
|
|
|
2021-06-17 19:05:11 +02:00
|
|
|
def stop_node(self, expected_stderr='', wait=0):
|
2017-08-15 23:34:07 +02:00
|
|
|
"""Stop the node."""
|
|
|
|
if not self.running:
|
|
|
|
return
|
|
|
|
self.log.debug("Stopping node")
|
|
|
|
try:
|
Merge #14670: http: Fix HTTP server shutdown
28479f926f21f2a91bec5a06671c60e5b0c55532 qa: Test bitcond shutdown (João Barbosa)
8d3f46ec3938e2ba17654fecacd1d2629f9915fd http: Remove timeout to exit event loop (João Barbosa)
e98a9eede2fb48ff33a020acc888cbcd83e24bbf http: Remove unnecessary event_base_loopexit call (João Barbosa)
6b13580f4e3842c11abd9b8bee7255fb2472b6fe http: Unlisten sockets after all workers quit (João Barbosa)
18e968581697078c36a3c3818f8906cf134ccadd http: Send "Connection: close" header if shutdown is requested (João Barbosa)
02e1e4eff6cda0bfc24b455a7c1583394cbff6eb rpc: Add wait argument to stop (João Barbosa)
Pull request description:
Fixes #11777. Reverts #11006. Replaces #13501.
With this change the HTTP server will exit gracefully, meaning that all requests will finish processing and sending the response, even if this means to wait more than 2 seconds (current time allowed to exit the event loop).
Another small change is that connections are accepted even when the server is stopping, but HTTP requests are rejected. This can be improved later, especially if chunked replies are implemented.
Briefly, before this PR, this is the order or events when a request arrives (RPC `stop`):
1. `bufferevent_disable(..., EV_READ)`
2. `StartShutdown()`
3. `evhttp_del_accept_socket(...)`
4. `ThreadHTTP` terminates (event loop exits) because there are no active or pending events thanks to 1. and 3.
5. client doesn't get the response thanks to 4.
This can be verified by applying
```diff
// Event loop will exit after current HTTP requests have been handled, so
// this reply will get back to the client.
StartShutdown();
+ MilliSleep(2000);
return "Bitcoin server stopping";
}
```
and checking the log output:
```
Received a POST request for / from 127.0.0.1:62443
ThreadRPCServer method=stop user=__cookie__
Interrupting HTTP server
** Exited http event loop
Interrupting HTTP RPC server
Interrupting RPC
tor: Thread interrupt
Shutdown: In progress...
torcontrol thread exit
Stopping HTTP RPC server
addcon thread exit
opencon thread exit
Unregistering HTTP handler for / (exactmatch 1)
Unregistering HTTP handler for /wallet/ (exactmatch 0)
Stopping RPC
RPC stopped.
Stopping HTTP server
Waiting for HTTP worker threads to exit
msghand thread exit
net thread exit
... sleep 2 seconds ...
Waiting for HTTP event thread to exit
Stopped HTTP server
```
For this reason point 3. is moved right after all HTTP workers quit. In that moment HTTP replies are queued in the event loop which keeps spinning util all connections are closed. In order to trigger the server side close with keep alive connections (implicit in HTTP/1.1) the header `Connection: close` is sent if shutdown was requested. This can be tested by
```
bitcoind -regtest
nc localhost 18443
POST / HTTP/1.1
Authorization: Basic ...
Content-Type: application/json
Content-Length: 44
{"jsonrpc": "2.0","method":"stop","id":123}
```
Summing up, this PR:
- removes explicit event loop exit — event loop exits once there are no active or pending events
- changes the moment the listening sockets are removed — explained above
- sends header `Connection: close` on active requests when shutdown was requested which is relevant when it's a persistent connection (default in HTTP 1.1) — libevent is aware of this header and closes the connection gracefully
- removes event loop explicit break after 2 seconds timeout
Tree-SHA512: 4dac1e86abe388697c1e2dedbf31fb36a394cfafe5e64eadbf6ed01d829542785a8c3b91d1ab680d3f03f912d14fc87176428041141441d25dcb6c98a1e069d8
2018-12-06 17:42:52 +01:00
|
|
|
self.stop(wait=wait)
|
2017-08-15 23:34:07 +02:00
|
|
|
except http.client.CannotSendRequest:
|
|
|
|
self.log.exception("Unable to stop node.")
|
2021-06-17 19:05:11 +02:00
|
|
|
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
# If there are any running perf processes, stop them.
|
|
|
|
for profile_name in tuple(self.perf_subprocesses.keys()):
|
|
|
|
self._stop_perf(profile_name)
|
|
|
|
|
2021-06-17 19:05:11 +02:00
|
|
|
# Check that stderr is as expected
|
|
|
|
self.stderr.seek(0)
|
|
|
|
stderr = self.stderr.read().decode('utf-8').strip()
|
|
|
|
if stderr != expected_stderr:
|
|
|
|
raise AssertionError("Unexpected stderr {} != {}".format(stderr, expected_stderr))
|
|
|
|
|
2018-08-11 13:01:29 +02:00
|
|
|
self.stdout.close()
|
|
|
|
self.stderr.close()
|
|
|
|
|
2017-11-08 19:10:43 +01:00
|
|
|
del self.p2ps[:]
|
2017-08-15 23:34:07 +02:00
|
|
|
|
|
|
|
def is_node_stopped(self):
|
|
|
|
"""Checks whether the node has stopped.
|
|
|
|
|
|
|
|
Returns True if the node has stopped. False otherwise.
|
|
|
|
This method is responsible for freeing resources (self.process)."""
|
|
|
|
if not self.running:
|
|
|
|
return True
|
|
|
|
return_code = self.process.poll()
|
2017-09-06 20:02:08 +02:00
|
|
|
if return_code is None:
|
|
|
|
return False
|
|
|
|
|
|
|
|
# process has stopped. Assert that it didn't return an error code.
|
2018-04-24 11:06:11 +02:00
|
|
|
assert return_code == 0, self._node_msg(
|
|
|
|
"Node returned non-zero exit code (%d) when stopping" % return_code)
|
2017-09-06 20:02:08 +02:00
|
|
|
self.running = False
|
|
|
|
self.process = None
|
|
|
|
self.rpc_connected = False
|
|
|
|
self.rpc = None
|
|
|
|
self.log.debug("Node stopped")
|
|
|
|
return True
|
|
|
|
|
|
|
|
def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
|
2020-05-19 02:00:24 +02:00
|
|
|
wait_until(self.is_node_stopped, timeout=timeout, timeout_factor=self.timeout_factor)
|
2017-08-15 23:34:07 +02:00
|
|
|
|
2020-06-13 06:50:03 +02:00
|
|
|
@contextlib.contextmanager
|
2020-01-30 23:10:50 +01:00
|
|
|
def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
|
|
|
|
if unexpected_msgs is None:
|
|
|
|
unexpected_msgs = []
|
2020-05-19 02:00:24 +02:00
|
|
|
time_end = time.time() + timeout * self.timeout_factor
|
2021-01-22 15:58:07 +01:00
|
|
|
chain = get_chain_folder(self.datadir, self.chain)
|
|
|
|
debug_log = os.path.join(self.datadir, chain, 'debug.log')
|
2020-06-13 06:50:03 +02:00
|
|
|
with open(debug_log, encoding='utf-8') as dl:
|
|
|
|
dl.seek(0, 2)
|
|
|
|
prev_size = dl.tell()
|
2019-09-05 13:28:39 +02:00
|
|
|
|
|
|
|
yield
|
|
|
|
|
|
|
|
while True:
|
|
|
|
found = True
|
|
|
|
with open(debug_log, encoding='utf-8') as dl:
|
|
|
|
dl.seek(prev_size)
|
|
|
|
log = dl.read()
|
|
|
|
print_log = " - " + "\n - ".join(log.splitlines())
|
2020-01-30 23:10:50 +01:00
|
|
|
for unexpected_msg in unexpected_msgs:
|
|
|
|
if re.search(re.escape(unexpected_msg), log, flags=re.MULTILINE):
|
|
|
|
self._raise_assertion_error('Unexpected message "{}" partially matches log:\n\n{}\n\n'.format(unexpected_msg, print_log))
|
2019-09-05 13:28:39 +02:00
|
|
|
for expected_msg in expected_msgs:
|
|
|
|
if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
|
|
|
|
found = False
|
|
|
|
if found:
|
|
|
|
return
|
|
|
|
if time.time() >= time_end:
|
|
|
|
break
|
|
|
|
time.sleep(0.05)
|
|
|
|
self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
|
2020-06-13 06:50:03 +02:00
|
|
|
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
@contextlib.contextmanager
|
|
|
|
def profile_with_perf(self, profile_name):
|
|
|
|
"""
|
|
|
|
Context manager that allows easy profiling of node activity using `perf`.
|
|
|
|
|
|
|
|
See `test/functional/README.md` for details on perf usage.
|
|
|
|
|
|
|
|
Args:
|
|
|
|
profile_name (str): This string will be appended to the
|
|
|
|
profile data filename generated by perf.
|
|
|
|
"""
|
|
|
|
subp = self._start_perf(profile_name)
|
|
|
|
|
|
|
|
yield
|
|
|
|
|
|
|
|
if subp:
|
|
|
|
self._stop_perf(profile_name)
|
|
|
|
|
|
|
|
def _start_perf(self, profile_name=None):
|
|
|
|
"""Start a perf process to profile this node.
|
|
|
|
|
|
|
|
Returns the subprocess running perf."""
|
|
|
|
subp = None
|
|
|
|
|
|
|
|
def test_success(cmd):
|
|
|
|
return subprocess.call(
|
|
|
|
# shell=True required for pipe use below
|
|
|
|
cmd, shell=True,
|
|
|
|
stderr=subprocess.DEVNULL, stdout=subprocess.DEVNULL) == 0
|
|
|
|
|
|
|
|
if not sys.platform.startswith('linux'):
|
2021-10-17 04:03:18 +02:00
|
|
|
self.log.warning("Can't profile with perf; only available on Linux platforms")
|
Merge #14519: tests: add utility to easily profile node performance with perf
13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)
Pull request description:
Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.
While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.
`perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.
### Example
```python
with node.profile_with_perf("large-msgs"):
for i in range(200):
node.p2p.send_message(some_large_msg)
node.p2p.sync_with_ping()
```
This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).
Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:
```bash
$ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
| c++filt \
| less
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 135 of event 'cycles:pp'
# Event count (approx.): 1458205679493582
#
# Children Self Command Shared Object Symbol
# ........ ........ ............... ................... ........................................................................................................................................................................................................................................................................
#
70.14% 0.00% bitcoin-net bitcoind [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
|
---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
70.14% 0.00% bitcoin-net bitcoind [.] CNetMessage::readData(char const*, unsigned int)
|
---CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
35.52% 0.00% bitcoin-net bitcoind [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
|
---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
CNetMessage::readData(char const*, unsigned int)
CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
...
```
Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e
2019-02-05 23:40:11 +01:00
|
|
|
return None
|
|
|
|
|
|
|
|
if not test_success('which perf'):
|
|
|
|
self.log.warning("Can't profile with perf; must install perf-tools")
|
|
|
|
return None
|
|
|
|
|
|
|
|
if not test_success('readelf -S {} | grep .debug_str'.format(shlex.quote(self.binary))):
|
|
|
|
self.log.warning(
|
|
|
|
"perf output won't be very useful without debug symbols compiled into bitcoind")
|
|
|
|
|
|
|
|
output_path = tempfile.NamedTemporaryFile(
|
|
|
|
dir=self.datadir,
|
|
|
|
prefix="{}.perf.data.".format(profile_name or 'test'),
|
|
|
|
delete=False,
|
|
|
|
).name
|
|
|
|
|
|
|
|
cmd = [
|
|
|
|
'perf', 'record',
|
|
|
|
'-g', # Record the callgraph.
|
|
|
|
'--call-graph', 'dwarf', # Compatibility for gcc's --fomit-frame-pointer.
|
|
|
|
'-F', '101', # Sampling frequency in Hz.
|
|
|
|
'-p', str(self.process.pid),
|
|
|
|
'-o', output_path,
|
|
|
|
]
|
|
|
|
subp = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
|
|
|
|
self.perf_subprocesses[profile_name] = subp
|
|
|
|
|
|
|
|
return subp
|
|
|
|
|
|
|
|
def _stop_perf(self, profile_name):
|
|
|
|
"""Stop (and pop) a perf subprocess."""
|
|
|
|
subp = self.perf_subprocesses.pop(profile_name)
|
|
|
|
output_path = subp.args[subp.args.index('-o') + 1]
|
|
|
|
|
|
|
|
subp.terminate()
|
|
|
|
subp.wait(timeout=10)
|
|
|
|
|
|
|
|
stderr = subp.stderr.read().decode()
|
|
|
|
if 'Consider tweaking /proc/sys/kernel/perf_event_paranoid' in stderr:
|
|
|
|
self.log.warning(
|
|
|
|
"perf couldn't collect data! Try "
|
|
|
|
"'sudo sysctl -w kernel.perf_event_paranoid=-1'")
|
|
|
|
else:
|
|
|
|
report_cmd = "perf report -i {}".format(output_path)
|
|
|
|
self.log.info("See perf output by running '{}'".format(report_cmd))
|
|
|
|
|
2021-04-08 22:29:01 +02:00
|
|
|
def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, match=ErrorMatch.FULL_TEXT, *args, **kwargs):
|
2018-03-22 10:18:33 +01:00
|
|
|
"""Attempt to start the node and expect it to raise an error.
|
|
|
|
|
|
|
|
extra_args: extra arguments to pass through to dashd
|
|
|
|
expected_msg: regex that stderr should match when dashd fails
|
|
|
|
|
|
|
|
Will throw if dashd starts without an error.
|
|
|
|
Will throw if an expected_msg is provided and it does not match dashd's stdout."""
|
2021-06-17 19:05:11 +02:00
|
|
|
with tempfile.NamedTemporaryFile(dir=self.stderr_dir, delete=False) as log_stderr, \
|
|
|
|
tempfile.NamedTemporaryFile(dir=self.stdout_dir, delete=False) as log_stdout:
|
2018-03-22 10:18:33 +01:00
|
|
|
try:
|
2021-06-17 19:05:11 +02:00
|
|
|
self.start(extra_args, stdout=log_stdout, stderr=log_stderr, *args, **kwargs)
|
2020-12-10 18:37:50 +01:00
|
|
|
ret = self.process.wait(timeout=self.rpc_timeout)
|
|
|
|
self.log.debug(self._node_msg(f'dashd exited with status {ret} during initialization'))
|
2018-03-22 10:18:33 +01:00
|
|
|
self.running = False
|
|
|
|
self.process = None
|
|
|
|
# Check stderr for expected message
|
|
|
|
if expected_msg is not None:
|
|
|
|
log_stderr.seek(0)
|
|
|
|
stderr = log_stderr.read().decode('utf-8').strip()
|
2021-04-08 22:29:01 +02:00
|
|
|
if match == ErrorMatch.PARTIAL_REGEX:
|
2018-03-22 10:18:33 +01:00
|
|
|
if re.search(expected_msg, stderr, flags=re.MULTILINE) is None:
|
2018-04-24 11:06:11 +02:00
|
|
|
self._raise_assertion_error(
|
|
|
|
'Expected message "{}" does not partially match stderr:\n"{}"'.format(expected_msg, stderr))
|
2021-04-08 22:29:01 +02:00
|
|
|
elif match == ErrorMatch.FULL_REGEX:
|
2018-03-22 10:18:33 +01:00
|
|
|
if re.fullmatch(expected_msg, stderr) is None:
|
2018-04-24 11:06:11 +02:00
|
|
|
self._raise_assertion_error(
|
|
|
|
'Expected message "{}" does not fully match stderr:\n"{}"'.format(expected_msg, stderr))
|
2021-04-08 22:29:01 +02:00
|
|
|
elif match == ErrorMatch.FULL_TEXT:
|
|
|
|
if expected_msg != stderr:
|
|
|
|
self._raise_assertion_error(
|
|
|
|
'Expected message "{}" does not fully match stderr:\n"{}"'.format(expected_msg, stderr))
|
2020-12-10 18:37:50 +01:00
|
|
|
except subprocess.TimeoutExpired:
|
|
|
|
self.process.kill()
|
|
|
|
self.running = False
|
|
|
|
self.process = None
|
|
|
|
assert_msg = f'dashd should have exited within {self.rpc_timeout}s '
|
2018-03-22 10:18:33 +01:00
|
|
|
if expected_msg is None:
|
2020-12-10 18:37:50 +01:00
|
|
|
assert_msg += "with an error"
|
2018-03-22 10:18:33 +01:00
|
|
|
else:
|
2020-12-10 18:37:50 +01:00
|
|
|
assert_msg += "with expected error " + expected_msg
|
2018-04-24 11:06:11 +02:00
|
|
|
self._raise_assertion_error(assert_msg)
|
2018-03-22 10:18:33 +01:00
|
|
|
|
2018-08-09 14:07:16 +02:00
|
|
|
def add_p2p_connection(self, p2p_conn, *, wait_for_verack=True, **kwargs):
|
2017-11-08 19:10:43 +01:00
|
|
|
"""Add a p2p connection to the node.
|
|
|
|
|
|
|
|
This method adds the p2p connection to the self.p2ps list and also
|
|
|
|
returns the connection to the caller."""
|
|
|
|
if 'dstport' not in kwargs:
|
|
|
|
kwargs['dstport'] = p2p_port(self.index)
|
|
|
|
if 'dstaddr' not in kwargs:
|
|
|
|
kwargs['dstaddr'] = '127.0.0.1'
|
2020-04-05 13:12:45 +02:00
|
|
|
|
2020-05-19 02:00:24 +02:00
|
|
|
p2p_conn.peer_connect(**kwargs, net=self.chain, timeout_factor=self.timeout_factor)()
|
2017-11-08 19:10:43 +01:00
|
|
|
self.p2ps.append(p2p_conn)
|
2018-08-09 14:07:16 +02:00
|
|
|
if wait_for_verack:
|
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 for the node to send us the version and verack
|
2018-08-09 14:07:16 +02:00
|
|
|
p2p_conn.wait_for_verack()
|
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
|
|
|
# At this point we have sent our version message and received the version and verack, however the full node
|
|
|
|
# has not yet received the verack from us (in reply to their version). So, the connection is not yet fully
|
|
|
|
# established (fSuccessfullyConnected).
|
|
|
|
#
|
|
|
|
# This shouldn't lead to any issues when sending messages, since the verack will be in-flight before the
|
|
|
|
# message we send. However, it might lead to races where we are expecting to receive a message. E.g. a
|
|
|
|
# transaction that will be added to the mempool as soon as we return here.
|
|
|
|
#
|
|
|
|
# So syncing here is redundant when we only want to send a message, but the cost is low (a few milliseconds)
|
2020-05-19 02:00:24 +02:00
|
|
|
# in comparison to the upside of making tests less fragile and unexpected intermittent errors less likely.
|
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
|
|
|
p2p_conn.sync_with_ping()
|
2017-11-08 19:10:43 +01:00
|
|
|
|
|
|
|
return p2p_conn
|
|
|
|
|
|
|
|
@property
|
|
|
|
def p2p(self):
|
|
|
|
"""Return the first p2p connection
|
|
|
|
|
|
|
|
Convenience property - most tests only use a single p2p connection to each
|
|
|
|
node, so this saves having to write node.p2ps[0] many times."""
|
2018-04-24 11:06:11 +02:00
|
|
|
assert self.p2ps, self._node_msg("No p2p connection")
|
2017-11-08 19:10:43 +01:00
|
|
|
return self.p2ps[0]
|
|
|
|
|
2020-06-17 12:20:04 +02:00
|
|
|
def num_connected_mininodes(self):
|
|
|
|
"""Return number of test framework p2p connections to the node."""
|
2020-11-28 18:06:39 +01:00
|
|
|
return len([peer for peer in self.getpeerinfo() if peer['subver'] == MY_SUBVERSION.decode("utf-8")])
|
2020-06-17 12:20:04 +02:00
|
|
|
|
2017-11-14 08:56:04 +01:00
|
|
|
def disconnect_p2ps(self):
|
|
|
|
"""Close all p2p connections to the node."""
|
|
|
|
for p in self.p2ps:
|
2020-04-05 13:12:45 +02:00
|
|
|
p.peer_disconnect()
|
2017-11-14 08:56:04 +01:00
|
|
|
|
2020-04-10 19:24:33 +02:00
|
|
|
# wait for p2p connections to disappear from getpeerinfo()
|
|
|
|
def check_peers():
|
|
|
|
for p in self.getpeerinfo():
|
2021-01-25 19:35:17 +01:00
|
|
|
for p2p in self.p2ps:
|
|
|
|
if p['subver'] == p2p.strSubVer.decode():
|
|
|
|
return False
|
2020-04-10 19:24:33 +02:00
|
|
|
return True
|
|
|
|
wait_until(check_peers, timeout=5)
|
|
|
|
|
2021-01-25 19:35:17 +01:00
|
|
|
del self.p2ps[:]
|
2020-06-17 12:20:04 +02:00
|
|
|
wait_until(lambda: self.num_connected_mininodes() == 0)
|
2021-01-25 19:35:17 +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
|
|
|
|
2018-01-12 23:24:36 +01:00
|
|
|
class TestNodeCLIAttr:
|
|
|
|
def __init__(self, cli, command):
|
|
|
|
self.cli = cli
|
|
|
|
self.command = command
|
|
|
|
|
|
|
|
def __call__(self, *args, **kwargs):
|
|
|
|
return self.cli.send_cli(self.command, *args, **kwargs)
|
|
|
|
|
|
|
|
def get_request(self, *args, **kwargs):
|
|
|
|
return lambda: self(*args, **kwargs)
|
2017-11-08 19:10:43 +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
|
|
|
|
2019-02-01 13:39:43 +01:00
|
|
|
def arg_to_cli(arg):
|
|
|
|
if isinstance(arg, bool):
|
|
|
|
return str(arg).lower()
|
|
|
|
elif isinstance(arg, dict) or isinstance(arg, list):
|
2019-12-12 02:10:59 +01:00
|
|
|
return json.dumps(arg, default=EncodeDecimal)
|
2019-02-01 13:39:43 +01:00
|
|
|
else:
|
|
|
|
return str(arg)
|
|
|
|
|
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-08-24 22:01:16 +02:00
|
|
|
class TestNodeCLI():
|
2020-06-11 10:39:04 +02:00
|
|
|
"""Interface to dash-cli for an individual node"""
|
2017-08-24 22:01:16 +02:00
|
|
|
def __init__(self, binary, datadir):
|
2018-01-24 14:49:33 +01:00
|
|
|
self.options = []
|
2017-08-24 22:01:16 +02:00
|
|
|
self.binary = binary
|
|
|
|
self.datadir = datadir
|
2017-09-06 18:07:21 +02:00
|
|
|
self.input = None
|
2020-06-11 10:39:04 +02:00
|
|
|
self.log = logging.getLogger('TestFramework.dashcli')
|
2017-09-06 18:07:21 +02:00
|
|
|
|
2018-01-24 14:49:33 +01:00
|
|
|
def __call__(self, *options, input=None):
|
2020-06-11 10:39:04 +02:00
|
|
|
# TestNodeCLI is callable with dash-cli command-line options
|
2018-01-12 23:24:36 +01:00
|
|
|
cli = TestNodeCLI(self.binary, self.datadir)
|
2018-01-24 14:49:33 +01:00
|
|
|
cli.options = [str(o) for o in options]
|
2018-01-12 23:24:36 +01:00
|
|
|
cli.input = input
|
|
|
|
return cli
|
2017-08-24 22:01:16 +02:00
|
|
|
|
|
|
|
def __getattr__(self, command):
|
2018-01-12 23:24:36 +01:00
|
|
|
return TestNodeCLIAttr(self, command)
|
|
|
|
|
|
|
|
def batch(self, requests):
|
|
|
|
results = []
|
|
|
|
for request in requests:
|
2018-06-29 18:04:25 +02:00
|
|
|
try:
|
|
|
|
results.append(dict(result=request()))
|
|
|
|
except JSONRPCException as e:
|
|
|
|
results.append(dict(error=e))
|
2018-01-12 23:24:36 +01:00
|
|
|
return results
|
2017-08-24 22:01:16 +02:00
|
|
|
|
2018-01-24 14:49:33 +01:00
|
|
|
def send_cli(self, command=None, *args, **kwargs):
|
2020-06-11 10:39:04 +02:00
|
|
|
"""Run dash-cli command. Deserializes returned string as python object."""
|
2019-02-01 13:39:43 +01:00
|
|
|
pos_args = [arg_to_cli(arg) for arg in args]
|
|
|
|
named_args = [str(key) + "=" + arg_to_cli(value) for (key, value) in kwargs.items()]
|
2018-01-24 14:49:33 +01:00
|
|
|
p_args = [self.binary, "-datadir=" + self.datadir] + self.options
|
2017-08-24 22:01:16 +02:00
|
|
|
if named_args:
|
|
|
|
p_args += ["-named"]
|
2018-01-24 14:49:33 +01:00
|
|
|
if command is not None:
|
|
|
|
p_args += [command]
|
|
|
|
p_args += pos_args + named_args
|
2020-04-24 14:41:12 +02:00
|
|
|
self.log.debug("Running dash-cli {}".format(p_args[2:]))
|
2017-09-06 17:36:13 +02:00
|
|
|
process = subprocess.Popen(p_args, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, universal_newlines=True)
|
|
|
|
cli_stdout, cli_stderr = process.communicate(input=self.input)
|
|
|
|
returncode = process.poll()
|
|
|
|
if returncode:
|
2018-01-12 23:24:36 +01:00
|
|
|
match = re.match(r'error code: ([-0-9]+)\nerror message:\n(.*)', cli_stderr)
|
|
|
|
if match:
|
|
|
|
code, message = match.groups()
|
|
|
|
raise JSONRPCException(dict(code=int(code), message=message))
|
2017-09-06 17:36:13 +02:00
|
|
|
# Ignore cli_stdout, raise with cli_stderr
|
|
|
|
raise subprocess.CalledProcessError(returncode, self.binary, output=cli_stderr)
|
2018-01-12 23:24:36 +01:00
|
|
|
try:
|
|
|
|
return json.loads(cli_stdout, parse_float=decimal.Decimal)
|
Merge #19632: test: Catch decimal.InvalidOperation from TestNodeCLI#send_cli
82fc4017b774aaff8799c2b6e8ba5370d94dbf4d test: Catch decimal.InvalidOperation from TestNodeCLI#send_cli (Ben Woosley)
Pull request description:
`decimal.InvalidOperation` is a special case of a float parsing error, which
presumably should be handled in the same way as a general parsing error,
rather than blow up.
Alternatives include: logging the error, or re-raising with more information.
Example log output:
```
File "/home/travis/build/bitcoin/bitcoin/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 603, in sync_all
self.sync_blocks(nodes)
File "/home/travis/build/bitcoin/bitcoin/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 568, in sync_blocks
best_hash = [x.getbestblockhash() for x in rpc_connections]
File "/home/travis/build/bitcoin/bitcoin/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_framework.py", line 568, in <listcomp>
best_hash = [x.getbestblockhash() for x in rpc_connections]
File "/home/travis/build/bitcoin/bitcoin/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 571, in __call__
return self.cli.send_cli(self.command, *args, **kwargs)
File "/home/travis/build/bitcoin/bitcoin/ci/scratch/build/bitcoin-i686-pc-linux-gnu/test/functional/test_framework/test_node.py", line 639, in send_cli
return json.loads(cli_stdout, parse_float=decimal.Decimal)
File "/usr/lib64/python3.6/json/__init__.py", line 367, in loads
return cls(**kw).decode(s)
File "/usr/lib64/python3.6/json/decoder.py", line 339, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/lib64/python3.6/json/decoder.py", line 355, in raw_decode
obj, end = self.scan_once(s, idx)
decimal.InvalidOperation: [<class 'decimal.InvalidOperation'>]
```
See: https://travis-ci.org/github/bitcoin/bitcoin/jobs/713502326
ACKs for top commit:
laanwj:
ACK 82fc4017b774aaff8799c2b6e8ba5370d94dbf4d
Tree-SHA512: 8c102b8bf831b05c5ca4b2e1feb5574dcbaed8cab0b2f22b013c5dfcb81788a38839a163dd1e2c6470ccbe5874214663b84485f45467738fd850ca38d539ae25
2020-08-05 16:14:12 +02:00
|
|
|
except (json.JSONDecodeError, decimal.InvalidOperation):
|
2018-01-12 23:24:36 +01:00
|
|
|
return cli_stdout.rstrip("\n")
|