bitcoin/test
MarcoFalke 67a72466e1
Merge #18247: test: Wait for both veracks in add_p2p_connection
faf1d04731 test: Remove redundant sync_with_ping after add_p2p_connection (MarcoFalke)
fa90647045 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:41 +02:00
..
functional Merge #18247: test: Wait for both veracks in add_p2p_connection 2020-04-01 05:08:41 +02:00
fuzz Merge #18300: fuzz: Add option to merge input dir to test runner 2020-03-18 15:51:44 -04:00
lint Replace std::to_string with locale-independent alternative 2020-03-14 12:23:01 -07:00
sanitizer_suppressions test: Remove unsafe BOOST_TEST_MESSAGE 2020-03-30 15:18:42 -04:00
util Merge #18447: test: Add coverage for script parse error in ParseScript 2020-03-27 09:58:12 -04:00
config.ini.in test: skip tool_wallet test when bitcoin-wallet isn't compiled 2019-11-18 16:48:52 -05:00
README.md test: Explain why test logging should be used 2020-03-10 08:24:49 -04:00

This directory contains integration tests that test bitcoind and its utilities in their entirety. It does not contain unit tests, which can be found in /src/test, /src/wallet/test, etc.

This directory contains the following sets of tests:

  • functional which test the functionality of bitcoind and bitcoin-qt by interacting with them through the RPC and P2P interfaces.
  • util which tests the bitcoin utilities, currently only bitcoin-tx.
  • lint which perform various static analysis checks.

The util tests are run as part of make check target. The functional tests and lint scripts can be run as explained in the sections below.

Running tests locally

Before tests can be run locally, Bitcoin Core must be built. See the building instructions for help.

Functional tests

Dependencies

The ZMQ functional test requires a python ZMQ library. To install it:

  • on Unix, run sudo apt-get install python3-zmq
  • on mac OS, run pip3 install pyzmq

Running the tests

Individual tests can be run by directly calling the test script, e.g.:

test/functional/feature_rbf.py

or can be run through the test_runner harness, eg:

test/functional/test_runner.py feature_rbf.py

You can run any combination (incl. duplicates) of tests by calling:

test/functional/test_runner.py <testname1> <testname2> <testname3> ...

Wildcard test names can be passed, if the paths are coherent and the test runner is called from a bash shell or similar that does the globbing. For example, to run all the wallet tests:

test/functional/test_runner.py test/functional/wallet*
functional/test_runner.py functional/wallet* (called from the test/ directory)
test_runner.py wallet* (called from the test/functional/ directory)

but not

test/functional/test_runner.py wallet*

Combinations of wildcards can be passed:

test/functional/test_runner.py ./test/functional/tool* test/functional/mempool*
test_runner.py tool* mempool*

Run the regression test suite with:

test/functional/test_runner.py

Run all possible tests with

test/functional/test_runner.py --extended

By default, up to 4 tests will be run in parallel by test_runner. To specify how many jobs to run, append --jobs=n

The individual tests and the test_runner harness have many command-line options. Run test/functional/test_runner.py -h to see them all.

Troubleshooting and debugging test failures

Resource contention

The P2P and RPC ports used by the bitcoind nodes-under-test are chosen to make conflicts with other processes unlikely. However, if there is another bitcoind process running on the system (perhaps from a previous test which hasn't successfully killed all its bitcoind nodes), then there may be a port conflict which will cause the test to fail. It is recommended that you run the tests on a system where no other bitcoind processes are running.

On linux, the test framework will warn if there is another bitcoind process running when the tests are started.

If there are zombie bitcoind processes after test failure, you can kill them by running the following commands. Note that these commands will kill all bitcoind processes running on the system, so should not be used if any non-test bitcoind processes are being run.

killall bitcoind

or

pkill -9 bitcoind
Data directory cache

A pre-mined blockchain with 200 blocks is generated the first time a functional test is run and is stored in test/cache. This speeds up test startup times since new blockchains don't need to be generated for each test. However, the cache may get into a bad state, in which case tests will fail. If this happens, remove the cache directory (and make sure bitcoind processes are stopped as above):

rm -rf test/cache
killall bitcoind
Test logging

The tests contain logging at five different levels (DEBUG, INFO, WARNING, ERROR and CRITICAL). From within your functional tests you can log to these different levels using the logger included in the test_framework, e.g. self.log.debug(object). By default:

  • when run through the test_runner harness, all logs are written to test_framework.log and no logs are output to the console.
  • when run directly, all logs are written to test_framework.log and INFO level and above are output to the console.
  • when run by our CI (Continuous Integration), no logs are output to the console. However, if a test fails, the test_framework.log and bitcoind debug.logs will all be dumped to the console to help troubleshooting.

These log files can be located under the test data directory (which is always printed in the first line of test output):

  • <test data directory>/test_framework.log
  • <test data directory>/node<node number>/regtest/debug.log.

The node number identifies the relevant test node, starting from node0, which corresponds to its position in the nodes list of the specific test, e.g. self.nodes[0].

To change the level of logs output to the console, use the -l command line argument.

test_framework.log and bitcoind debug.logs can be combined into a single aggregate log by running the combine_logs.py script. The output can be plain text, colorized text or html. For example:

test/functional/combine_logs.py -c <test data directory> | less -r

will pipe the colorized logs from the test into less.

Use --tracerpc to trace out all the RPC calls and responses to the console. For some tests (eg any that use submitblock to submit a full block over RPC), this can result in a lot of screen output.

By default, the test data directory will be deleted after a successful run. Use --nocleanup to leave the test data directory intact. The test data directory is never deleted after a failed test.

Attaching a debugger

A python debugger can be attached to tests at any point. Just add the line:

import pdb; pdb.set_trace()

anywhere in the test. You will then be able to inspect variables, as well as call methods that interact with the bitcoind nodes-under-test.

If further introspection of the bitcoind instances themselves becomes necessary, this can be accomplished by first setting a pdb breakpoint at an appropriate location, running the test to that point, then using gdb (or lldb on macOS) to attach to the process and debug.

For instance, to attach to self.node[1] during a run you can get the pid of the node within pdb.

(pdb) self.node[1].process.pid

Alternatively, you can find the pid by inspecting the temp folder for the specific test you are running. The path to that folder is printed at the beginning of every test run:

2017-06-27 14:13:56.686000 TestFramework (INFO): Initializing test directory /tmp/user/1000/testo9vsdjo3

Use the path to find the pid file in the temp folder:

cat /tmp/user/1000/testo9vsdjo3/node1/regtest/bitcoind.pid

Then you can use the pid to start gdb:

gdb /home/example/bitcoind <pid>

Note: gdb attach step may require ptrace_scope to be modified, or sudo preceding the gdb. See this link for considerations: https://www.kernel.org/doc/Documentation/security/Yama.txt

Profiling

An easy way to profile node performance during functional tests is provided for Linux platforms using perf.

Perf will sample the running node and will generate profile data in the node's datadir. The profile data can then be presented using perf report or a graphical tool like hotspot.

To generate a profile during test suite runs, use the --perf flag.

To see render the output to text, run

perf report -i /path/to/datadir/send-big-msgs.perf.data.xxxx --stdio | c++filt | less

For ways to generate more granular profiles, see the README in test/functional.

Util tests

Util tests can be run locally by running test/util/bitcoin-util-test.py. Use the -v option for verbose output.

Lint tests

Dependencies

Lint test Dependency Version used by CI Installation
lint-python.sh flake8 3.7.8 pip3 install flake8==3.7.8
lint-shell.sh ShellCheck 0.6.0 details...
lint-shell.sh yq default pip3 install yq
lint-spelling.sh codespell 1.15.0 pip3 install codespell==1.15.0

Please be aware that on Linux distributions all dependencies are usually available as packages, but could be outdated.

Running the tests

Individual tests can be run by directly calling the test script, e.g.:

test/lint/lint-filenames.sh

You can run all the shell-based lint tests by running:

test/lint/lint-all.sh

Writing functional tests

You are encouraged to write functional tests for new or existing features. Further information about the functional test framework and individual tests is found in test/functional.