fuzz: investigate test adequacy (unit and fuzz) via mutation testing #22690

@MarcoFalke / @practicalswift I'm starting some mutation analysis using https://github.com/agroce/universalmutator

A couple of questions:

• At random I picked tx_verify.cpp as a file with high coverage that is likely critical, where any missed non-equivalent mutants should be carefully investigated. Is this a good choice to get the workflow going on?

• Is there any mapping from fuzz targets to code expected to be covered? I can run all targets, of course, but knowing which ones might possibly detect tx_verify.cppmutants would be helpful.

Hmm. make check is thu far killing 0% of tx_verify.cpp mutants. That seems odd...

I'm using make; make check to build the changed code and then test, it's taking a couple of minutes to run the tests. But some of these are extreme enough it must just be that the unit tests don't check the tx_verify code or I'm doing something wrong...

@MarcoFalke @practicalswift

is it expected the make check unit tests detected 0 mutants of tx_verify.cpp?

@MarcoFalke @practicalswift I'm also getting 0 mutant kills on tx_verify.cpp with FUZZ=process_messages and the process_messages_tx corpus.

Have I just chosen a bad target? Does testing turn off tx verification (at least this kind)?

@MarcoFalke and @practicalswift

Never mind on fuzzing -- I spoke too soon, there are killed mutants, just a very low rate, 1 in 37 runs. The mutant detected changed an assertion:

MUTANT: mutants/tx_verify.mutant.357.cpp
*** Original
--- Mutant
***************
*** 177,183 ****
      for (unsigned int i = 0; i < tx.vin.size(); ++i) {
          const COutPoint &prevout = tx.vin[i].prevout;
          const Coin& coin = inputs.AccessCoin(prevout);
!         assert(!coin.IsSpent());
  
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {
--- 177,183 ----
      for (unsigned int i = 0; i < tx.vin.size(); ++i) {
          const COutPoint &prevout = tx.vin[i].prevout;
          const Coin& coin = inputs.AccessCoin(prevout);
!         assert(coin.IsSpent());
  
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {

That gets detected in < 30s, counting recompiling the file and copying the corpus.

OK, the fuzzing does indeed kill maybe 5% of mutants. And not just a broken assertion, but removing a return statement and some things. This does suggest the unit tests do in fact not kill any?

For more context-dependent checks, the functional tests might provide higher coverage.

Due to the general nature of the fuzz tests, they might be less suited to detect unwanted consensus changes.

Finally, some mutants might survive because they modify redundant code. For example #22761.

Aha. The functional tests are what I need to look to, then, to prune. Thanks!

(the idea is to see if anything serious escapes ALL tests, and looks suitable for fuzzing; if it's not suitable for fuzzing, it is a likely candidate for additional functional testing, of course)

At about 14% done, functional tests are killiing ~60% of the mutants not killed by fuzzing for 'tx_verify.cpp'

more anon (Venn diagram of which methods kill what, and some close analysis of the survivors)

(since fuzzing killed 10-12% maybe, this means about a 70% kill ratio, which is probably very good; chances are most of those left over are functionally equivalent or otherwise invalid, though probably some deserve covering tests)

ok, functional tests may actually be > 70% effective, on their own.

Gotta back up the run a bit; the functional tests don't clean up /tmp, so eventually it caused failures due to space usage. Unlike fuzzing, this isn't a "problem" just something future users of the functional tests in an automated loop need to know. I'm going to write up a mutation testing primer/FAQ -- where should that go? Into the same place as doc/fuzzing.md etc.? Is there a propr place for a higher level link to that?

Jup, there is the doc/README where you can put the link

Ok, functional tests look solid, definitely high kill rate.

AND, which is worth knowing, there ARE mutants the fuzzing can kill that functional tests cannot.

Analysis to follow when all runs are done.

Functional tests catch 326 of 430 valid mutants of tx_verify.cpp (75.8%). Fuzzing catches an additional two mutants.

Fuzzing overall catches 50 of 430 mutants (11.6%), which is pretty respectable with an oracle presumably mostly limited to crashes, sanitizer issues, and internal asserts.

The two mutants only fuzzing detects are:

********************************************************************************
MUTANT [#1](/bitcoin-bitcoin/1/):
tx_verify.mutant.379.cpp: src/consensus/tx_verify.cpp:185
*** Original
--- Mutant
***************
*** 182,188 ****
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {
              return state.Invalid(TxValidationResult::TX_PREMATURE_SPEND, "bad-txns-premature-spend-of-coinbase",
!                 strprintf("tried to spend coinbase at depth %d", nSpendHeight - coin.nHeight));
          }
  
          // Check for negative or overflow input values
--- 182,188 ----
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {
              return state.Invalid(TxValidationResult::TX_PREMATURE_SPEND, "bad-txns-premature-spend-of-coinbase",
!                 strprintf("tried to spend coinbase at depth %d", nSpendHeight / coin.nHeight));
          }
  
          // Check for negative or overflow input values


********************************************************************************
MUTANT [#2](/bitcoin-bitcoin/2/):
tx_verify.mutant.380.cpp: src/consensus/tx_verify.cpp:185
*** Original
--- Mutant
***************
*** 182,188 ****
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {
              return state.Invalid(TxValidationResult::TX_PREMATURE_SPEND, "bad-txns-premature-spend-of-coinbase",
!                 strprintf("tried to spend coinbase at depth %d", nSpendHeight - coin.nHeight));
          }
  
          // Check for negative or overflow input values
--- 182,188 ----
          // If prev is coinbase, check that it's matured
          if (coin.IsCoinBase() && nSpendHeight - coin.nHeight < COINBASE_MATURITY) {
              return state.Invalid(TxValidationResult::TX_PREMATURE_SPEND, "bad-txns-premature-spend-of-coinbase",
!                 strprintf("tried to spend coinbase at depth %d", nSpendHeight % coin.nHeight));
          }
  
          // Check for negative or overflow input values

Ah! This may not be the full power of the functional tests. I speculate that the fuzzing may not be the cause of detection here, but the fact my initial functional run was without any sanitizers, in order to kill the easily killed mutants quickly. I'll run a sanitizer functional run (I assume CI does that at some point?) on the remaining mutants soon.

Yes, I don't know how many, but there are additional mutants the functional tests catch with sanitizers. Probably no more than an additional 10-20 mutants, but that will reduce the challenge of analyzing the 100+ unkilled.

Mutant #379 and #380 above appear to be genuinely unique to fuzzing, in particular coins_view fuzzing. Not killed via sanitizer run of functional tests, either. Final kill for functional tests with sanitizer is 78.6% of mutants. Now running valgrind to see if it adds a few more.

Here's a Venn diagram of the pre-Valgrind results (the * is because I only ran the sanitizer tests on things functional hadn't killed yet, though you can obviously assume it shares all functional-alone kills)

Hmm. Valgrind complains a lot on the functional tests without any mutants, I'll see if the tests still pass...

hmm, how do I actually get the functional tests to run under valgrind, vs valgrind checking the python? I'm sure in doc, but not an option to test_runner that I see...

You'll just pass --valgrind to the test runner. Though the suppressions file is only tested on Ubuntu: https://github.com/bitcoin/bitcoin/blob/0ebd88fe0bf45d872883b4d361147f5c047b1a46/contrib/valgrind.supp#L16

thanks!

hmm, I'm on ubuntu (in docker) but --valgrind --failfast is failing on wallet_hd.py --legacy-wallet even for the base, ok, code.

Yeah, the suppressions just don't seem to be working in my (20.04 I am fairly sure) ubuntu docker.

OK!

https://github.com/agroce/bitcorpus/blob/master/mutation/prioritized_full_inspect.txt

is the full text of the mutants 1) not killed by anything (have not run valgrind yet) and 2) that are not, to my inspection, obviously semantically equivalent.

The main things I have pruned are weakenings or removals of assertions. I think some of these are also in that category. Can someone confirm the loops around assert(!coin.IsSpent()) are just checks, not doing anything, so (e.g.) iterating through fewer items is fine?

tx_verify.mutant.249.cpp: ./tx_verify.cpp:136
*** Original
--- Mutant
***************
*** 133,139 ****
          return 0;
  
      unsigned int nSigOps = 0;
!     for (unsigned int i = 0; i < tx.vin.size(); i++)
      {
          const Coin& coin = inputs.AccessCoin(tx.vin[i].prevout);
          assert(!coin.IsSpent());
--- 133,139 ----
          return 0;
  
      unsigned int nSigOps = 0;
!     for (unsigned int i = (0+1); i < tx.vin.size(); i++)
      {
          const Coin& coin = inputs.AccessCoin(tx.vin[i].prevout);
          assert(!coin.IsSpent());

There are also probably some equivalent comparisons, where an unsigned is <= not just ==. And some string replacements in failure messages that might be harmless.

But the rest here likely bears close examination as potential holes in testing.

At least an 85.8% kill rate after pruning, which is solid. Presumably a large number of these are also not problems.

With valgrind, you will also need to increase the timeout-factor a bit. What is the error you are seeing?

Aha. I see:

python3 test/functional/test_runner.py --extended --valgrind --failfast 
Temporary test directory at /tmp/test_runner_₿_🏃_20210906_092947
Running Unit Tests for Test Framework Modules
..........
----------------------------------------------------------------------
Ran 10 tests in 1.499s

OK
1/219 - wallet_hd.py --descriptors skipped
2/219 - wallet_hd.py --legacy-wallet failed, Duration: 71 s                                                                           

stdout:
2021-09-06T16:29:51.954000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20210906_092947/wallet_hd_216
2021-09-06T16:30:55.211000Z TestFramework (ERROR): Assertion failed
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 530, in start_nodes
    node.wait_for_rpc_connection()
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 283, in wait_for_rpc_connection
    self._raise_assertion_error("Unable to connect to bitcoind after {}s".format(self.rpc_timeout))
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 166, in _raise_assertion_error
    raise AssertionError(self._node_msg(msg))
AssertionError: [node 0] Unable to connect to bitcoind after 60s

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 130, in main
    self.setup()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 285, in setup
    self.setup_network()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 379, in setup_network
    self.setup_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 404, in setup_nodes
    self.start_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 533, in start_nodes
    self.stop_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 548, in stop_nodes
    node.stop_node(wait=wait, wait_until_stopped=False)
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 323, in stop_node
    self.stop(wait=wait)
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 183, in __getattr__
    assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
AssertionError: [node 0] Error: no RPC connection
2021-09-06T16:30:55.743000Z TestFramework (INFO): Stopping nodes
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/wallet_hd.py", line 280, in <module>
    WalletHDTest().main()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 154, in main
    exit_code = self.shutdown()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 301, in shutdown
    self.stop_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 548, in stop_nodes
    node.stop_node(wait=wait, wait_until_stopped=False)
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 323, in stop_node
    self.stop(wait=wait)
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 183, in __getattr__
    assert self.rpc_connected and self.rpc is not None, self._node_msg("Error: no RPC connection")
AssertionError: [node 0] Error: no RPC connection


Early exiting after test failure

TEST                                               | STATUS    | DURATION

wallet_hd.py --descriptors                         | ○ Skipped | 0 s
wallet_hd.py --legacy-wallet                       | ✖ Failed  | 71 s

ALL                                                | ✖ Failed  | 71 s (accumulated) 
Runtime: 71 s

Killed

When I try to use --timeout-factor to fix that I get:

python3 test/functional/test_runner.py --extended --valgrind --failfast --timeout-factor 100
Temporary test directory at /tmp/test_runner_₿_🏃_20210906_094537
WARNING! Test '100' not found in full test list.
No valid test scripts specified. Check that your test is in one of the test lists in test_runner.py, or run test_runner.py with no arguments to run all tests

Does --timeout-factor=100 work?

Aha! Yes!

Well, sort of. It runs, though even with a 1000x factor I get:

Ran 10 tests in 0.773s

OK
1/219 - wallet_hd.py --descriptors skipped
2/219 - feature_dbcrash.py failed, Duration: 55 s                                                            

stdout:
2021-09-07T08:05:42.904000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20210907_010540/feature_dbcrash_217
2021-09-07T08:06:38.157000Z TestFramework (ERROR): Unexpected exception caught during testing
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 108, in _request
    return self._get_response()
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 168, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1344, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 276, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response

which is different at least...

Does ./test/functional/combine_logs.py /tmp/test_runner_₿_🏃_20210907_010540/feature_dbcrash_217 yield anything?

On a non-mutated version and some mutants it dies like this, more common actually:

rm -rf /tmp/test_runner*; make; python3 test/functional/test_runner.py --extended --valgrind --timeout-factor=0 --failfast
Making all in src
make[1]: Entering directory '/root/bitcoin/src'
make[2]: Entering directory '/root/bitcoin/src'
make[3]: Entering directory '/root/bitcoin'
make[3]: Leaving directory '/root/bitcoin'
  CXX      consensus/libbitcoin_server_a-tx_verify.o
  AR       libbitcoin_server.a
  CXXLD    bitcoind
  CXXLD    test/test_bitcoin
  CXXLD    bench/bench_bitcoin
  CXXLD    test/fuzz/fuzz
make[2]: Leaving directory '/root/bitcoin/src'
make[1]: Leaving directory '/root/bitcoin/src'
Making all in doc/man
make[1]: Entering directory '/root/bitcoin/doc/man'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory '/root/bitcoin/doc/man'
make[1]: Entering directory '/root/bitcoin'
make[1]: Nothing to be done for 'all-am'.
make[1]: Leaving directory '/root/bitcoin'
Temporary test directory at /tmp/test_runner_₿_🏃_20210907_065517
Running Unit Tests for Test Framework Modules
..........
----------------------------------------------------------------------
Ran 10 tests in 1.061s

OK
1/219 - wallet_hd.py --descriptors skipped
..................................................................................................................................................                                                                                                                                                  2/219 - wallet_hd.py --legacy-wallet failed, Duration: 139 s                                                                    

stdout:
2021-09-07T13:55:20.310000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216
2021-09-07T13:57:39.289000Z TestFramework (ERROR): Unexpected exception caught during testing
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 108, in _request
    return self._get_response()
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 168, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1344, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 276, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 130, in main
    self.setup()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 285, in setup
    self.setup_network()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 379, in setup_network
    self.setup_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 406, in setup_nodes
    self.import_deterministic_coinbase_privkeys()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 423, in import_deterministic_coinbase_privkeys
    self.init_wallet(i)
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 431, in init_wallet
    n.importprivkey(privkey=n.get_deterministic_priv_key().key, label='coinbase')
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 689, in importprivkey
    return self.__getattr__('importprivkey')(privkey, label, rescan)
  File "/root/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 113, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.8/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.8/http/client.py", line 1298, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/usr/lib/python3.8/http/client.py", line 1247, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/usr/lib/python3.8/http/client.py", line 1007, in _send_output
    self.send(msg)
  File "/usr/lib/python3.8/http/client.py", line 947, in send
    self.connect()
  File "/usr/lib/python3.8/http/client.py", line 918, in connect
    self.sock = self._create_connection(
  File "/usr/lib/python3.8/socket.py", line 808, in create_connection
    raise err
  File "/usr/lib/python3.8/socket.py", line 796, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused
2021-09-07T13:57:39.347000Z TestFramework (INFO): Stopping nodes
2021-09-07T13:57:39.348000Z TestFramework.node0 (ERROR): Unable to stop node.
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 323, in stop_node
    self.stop(wait=wait)
  File "/root/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
    response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
  File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 107, in _request
    self.__conn.request(method, path, postdata, headers)
  File "/usr/lib/python3.8/http/client.py", line 1252, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/usr/lib/python3.8/http/client.py", line 1263, in _send_request
    self.putrequest(method, url, **skips)
  File "/usr/lib/python3.8/http/client.py", line 1089, in putrequest
    raise CannotSendRequest(self.__state)
http.client.CannotSendRequest: Request-sent
[node 1] Cleaning up leftover process
[node 0] Cleaning up leftover process


stderr:
Traceback (most recent call last):
  File "/root/bitcoin/test/functional/wallet_hd.py", line 280, in <module>
    WalletHDTest().main()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 154, in main
    exit_code = self.shutdown()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 301, in shutdown
    self.stop_nodes()
  File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 548, in stop_nodes
    node.stop_node(wait=wait, wait_until_stopped=False)
  File "/root/bitcoin/test/functional/test_framework/test_node.py", line 337, in stop_node
    raise AssertionError("Unexpected stderr {} != {}".format(stderr, expected_stderr))
AssertionError: Unexpected stderr ==48855== Thread 13 b-httpworker.2:
==48855== Conditional jump or move depends on uninitialised value(s)
==48855==    at 0x5BFDBB: CWallet::ScanForWalletTransactions(uint256 const&, int, std::optional<int>, WalletRescanReserver const&, bool) (wallet.cpp:1653)
==48855==    by 0x5C07CB: CWallet::RescanFromTime(long, WalletRescanReserver const&, bool) (wallet.cpp:1556)
==48855==    by 0x60E5ED: RescanWallet(CWallet&, WalletRescanReserver const&, long, bool) (rpcdump.cpp:85)
==48855==    by 0x628253: importprivkey()::{lambda(RPCHelpMan const&, JSONRPCRequest const&)#1}::operator()(RPCHelpMan const&, JSONRPCRequest const&) const [clone .isra.0] (rpcdump.cpp:187)
==48855==    by 0x628554: std::_Function_handler<UniValue (RPCHelpMan const&, JSONRPCRequest const&), importprivkey()::{lambda(RPCHelpMan const&, JSONRPCRequest const&)#1}>::_M_invoke(std::_Any_data const&, RPCHelpMan const&, JSONRPCRequest const&) (std_function.h:286)
==48855==    by 0x692115: operator() (std_function.h:688)
==48855==    by 0x692115: RPCHelpMan::HandleRequest(JSONRPCRequest const&) const (util.cpp:575)
==48855==    by 0x3471CB: CRPCCommand::CRPCCommand(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, RPCHelpMan (*)())::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}::operator()(JSONRPCRequest const&, UniValue&, bool) const (server.h:110)
==48855==    by 0x4E417B: wallet::(anonymous namespace)::WalletClientImpl::registerRpcs()::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}::operator()(JSONRPCRequest const&, UniValue&, bool) const (std_function.h:688)
==48855==    by 0x2BF324: operator() (std_function.h:688)
==48855==    by 0x2BF324: operator() (interfaces.cpp:397)
==48855==    by 0x2BF324: std::_Function_handler<bool (JSONRPCRequest const&, UniValue&, bool), node::(anonymous namespace)::RpcHandlerImpl::RpcHandlerImpl(CRPCCommand const&)::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}>::_M_invoke(std::_Any_data const&, JSONRPCRequest const&, UniValue&, bool&&) (std_function.h:285)
==48855==    by 0x3D9396: operator() (std_function.h:688)
==48855==    by 0x3D9396: ExecuteCommand(CRPCCommand const&, JSONRPCRequest const&, UniValue&, bool) (server.cpp:480)
==48855==    by 0x3D9FB6: ExecuteCommands(std::vector<CRPCCommand const*, std::allocator<CRPCCommand const*> > const&, JSONRPCRequest const&, UniValue&) [clone .constprop.0] (server.cpp:444)
==48855==    by 0x3DA55D: CRPCTable::execute(JSONRPCRequest const&) const (server.cpp:464)
==48855== 
{
   <insert_a_suppression_name_here>
   Memcheck:Cond
   fun:_ZN7CWallet25ScanForWalletTransactionsERK7uint256iSt8optionalIiERK20WalletRescanReserverb
   fun:_ZN7CWallet14RescanFromTimeElRK20WalletRescanReserverb
   fun:_ZL12RescanWalletR7CWalletRK20WalletRescanReserverlb
   fun:_ZZ13importprivkeyvENKUlRK10RPCHelpManRK14JSONRPCRequestE_clES1_S4_.isra.0
   fun:_ZNSt17_Function_handlerIF8UniValueRK10RPCHelpManRK14JSONRPCRequestEZ13importprivkeyvEUlS3_S6_E_E9_M_invokeERKSt9_Any_dataS3_S6_
   fun:operator()
   fun:_ZNK10RPCHelpMan13HandleRequestERK14JSONRPCRequest
   fun:_ZZN11CRPCCommandC4ENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEPF10RPCHelpManvEENKUlRK14JSONRPCRequestR8UniValuebE_clESB_SD_b
   fun:_ZZN6wallet12_GLOBAL__N_116WalletClientImpl12registerRpcsEvENKUlRK14JSONRPCRequestR8UniValuebE_clES4_S6_b
   fun:operator()
   fun:operator()
   fun:_ZNSt17_Function_handlerIFbRK14JSONRPCRequestR8UniValuebEZN4node12_GLOBAL__N_114RpcHandlerImplC4ERK11CRPCCommandEUlS2_S4_bE_E9_M_invokeERKSt9_Any_dataS2_S4_Ob
   fun:operator()
   fun:_ZL14ExecuteCommandRK11CRPCCommandRK14JSONRPCRequestR8UniValueb
   fun:_ZL15ExecuteCommandsRKSt6vectorIPK11CRPCCommandSaIS2_EERK14JSONRPCRequestR8UniValue.constprop.0
   fun:_ZNK9CRPCTable7executeERK14JSONRPCRequest
}
==48855== 
==48855== Exit program on first error (--exit-on-first-error=yes) != 


Early exiting after test failure

TEST                                               | STATUS    | DURATION

wallet_hd.py --descriptors                         | ○ Skipped | 0 s
wallet_hd.py --legacy-wallet                       | ✖ Failed  | 139 s

ALL                                                | ✖ Failed  | 139 s (accumulated) 
Runtime: 139 s

Killed
root@53f441e8d7b7:~/bitcoin# ./test/functional/combine_logs.py /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/
 test  2021-09-07T13:55:20.309000Z TestFramework (DEBUG): PRNG seed is: 4065656687483736910 
 test  2021-09-07T13:55:20.309000Z TestFramework (DEBUG): Setting up network thread 
 test  2021-09-07T13:55:20.310000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216 
 test  2021-09-07T13:55:20.315000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
 test  2021-09-07T13:55:20.320000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up 
 node0 2021-09-07T13:56:06.935968Z [init] [init/common.cpp:165] [LogPackageVersion] Bitcoin Core version v22.99.0-9948f114f8e6-dirty (release build) 
 node0 2021-09-07T13:56:07.196264Z [init] [init.cpp:635] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 node0 2021-09-07T13:56:07.665759Z [init] [init.cpp:894] [AppInitParameterInteraction] Validating signatures for all blocks. 
 node0 2021-09-07T13:56:07.678041Z [init] [init.cpp:905] [AppInitParameterInteraction] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2021-09-07T13:56:08.867738Z [init] [init/common.cpp:29] [SetGlobals] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node0 2021-09-07T13:56:08.872269Z [init] [random.cpp:103] [ReportHardwareRand] Using RdRand as an additional entropy source 
 node0 2021-09-07T13:56:17.801824Z [init] [init/common.cpp:136] [StartLogging] Default data directory /root/.bitcoin 
 node0 2021-09-07T13:56:17.819558Z [init] [init/common.cpp:137] [StartLogging] Using data directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest 
 node0 2021-09-07T13:56:17.843184Z [init] [init/common.cpp:142] [StartLogging] Config file: /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/bitcoin.conf 
 node0 2021-09-07T13:56:17.882798Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: regtest="1" 
 node0 2021-09-07T13:56:17.917085Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 node0 2021-09-07T13:56:17.917851Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 node0 2021-09-07T13:56:17.920743Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 node0 2021-09-07T13:56:17.921267Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 node0 2021-09-07T13:56:17.921679Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 node0 2021-09-07T13:56:17.925587Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 node0 2021-09-07T13:56:17.926333Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 node0 2021-09-07T13:56:17.926941Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 node0 2021-09-07T13:56:17.932689Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 node0 2021-09-07T13:56:17.933435Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] port="13592" 
 node0 2021-09-07T13:56:17.934006Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 node0 2021-09-07T13:56:17.941317Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] rpcport="18592" 
 node0 2021-09-07T13:56:17.941764Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] server="1" 
 node0 2021-09-07T13:56:17.945603Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 node0 2021-09-07T13:56:17.950130Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 node0 2021-09-07T13:56:17.950775Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 node0 2021-09-07T13:56:17.961095Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: datadir="/tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0" 
 node0 2021-09-07T13:56:17.967528Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debug="" 
 node0 2021-09-07T13:56:17.968359Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 node0 2021-09-07T13:56:17.968785Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 node0 2021-09-07T13:56:17.975666Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 node0 2021-09-07T13:56:17.976403Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logthreadnames="" 
 node0 2021-09-07T13:56:17.977104Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logtimemicros="" 
 node0 2021-09-07T13:56:17.983332Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: uacomment="testnode0" 
 node0 2021-09-07T13:56:18.001812Z [init] [init.cpp:1081] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
 node1 2021-09-07T13:56:19.664512Z [init] [init/common.cpp:165] [LogPackageVersion] Bitcoin Core version v22.99.0-9948f114f8e6-dirty (release build) 
 node1 2021-09-07T13:56:20.409849Z [init] [init.cpp:635] [InitParameterInteraction] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
 node1 2021-09-07T13:56:20.867233Z [init] [init.cpp:894] [AppInitParameterInteraction] Validating signatures for all blocks. 
 node1 2021-09-07T13:56:20.990075Z [init] [init.cpp:905] [AppInitParameterInteraction] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
 node0 2021-09-07T13:56:22.068187Z [init] [script/sigcache.cpp:101] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 
 node1 2021-09-07T13:56:26.898616Z [init] [init/common.cpp:29] [SetGlobals] Using the 'sse4(1way),sse41(4way),avx2(8way)' SHA256 implementation 
 node1 2021-09-07T13:56:26.957534Z [init] [random.cpp:103] [ReportHardwareRand] Using RdRand as an additional entropy source 
 node0 2021-09-07T13:56:27.300549Z [init] [validation.cpp:1371] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 
 node0 2021-09-07T13:56:27.347787Z [init] [init.cpp:1108] [AppInitMain] Script verification uses 7 additional threads 
 node0 2021-09-07T13:56:32.545649Z [scheduler] [util/thread.cpp:17] [TraceThread] scheduler thread start 
 node1 2021-09-07T13:56:39.688847Z [init] [init/common.cpp:136] [StartLogging] Default data directory /root/.bitcoin 
 node1 2021-09-07T13:56:39.735887Z [init] [init/common.cpp:137] [StartLogging] Using data directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest 
 node1 2021-09-07T13:56:39.784951Z [init] [init/common.cpp:142] [StartLogging] Config file: /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/bitcoin.conf 
 node1 2021-09-07T13:56:39.860548Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: regtest="1" 
 node1 2021-09-07T13:56:39.865511Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] bind="127.0.0.1" 
 node1 2021-09-07T13:56:39.890011Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] connect="0" 
 node1 2021-09-07T13:56:39.891165Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] discover="0" 
 node1 2021-09-07T13:56:39.892218Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] dnsseed="0" 
 node1 2021-09-07T13:56:39.923316Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] fallbackfee="0.0002" 
 node1 2021-09-07T13:56:39.924016Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] fixedseeds="0" 
 node1 2021-09-07T13:56:40.142828Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] keypool="1" 
 node1 2021-09-07T13:56:40.143739Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] listenonion="0" 
 node1 2021-09-07T13:56:40.166353Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] natpmp="0" 
 node1 2021-09-07T13:56:40.167765Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] port="13593" 
 node1 2021-09-07T13:56:40.168796Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] printtoconsole="0" 
 node1 2021-09-07T13:56:40.169547Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] rpcport="18593" 
 node1 2021-09-07T13:56:40.170271Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] server="1" 
 node1 2021-09-07T13:56:40.187957Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] shrinkdebugfile="0" 
 node1 2021-09-07T13:56:40.189017Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] unsafesqlitesync="1" 
 node1 2021-09-07T13:56:40.189946Z [init] [util/system.cpp:1041] [logArgsPrefix] Config file arg: [regtest] upnp="0" 
 node1 2021-09-07T13:56:40.209049Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: datadir="/tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1" 
 node1 2021-09-07T13:56:40.211108Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debug="" 
 node1 2021-09-07T13:56:40.231056Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debugexclude="libevent" 
 node1 2021-09-07T13:56:40.231794Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: debugexclude="leveldb" 
 node1 2021-09-07T13:56:40.232977Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: keypool="0" 
 node1 2021-09-07T13:56:40.233782Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logsourcelocations="" 
 node1 2021-09-07T13:56:40.234453Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logthreadnames="" 
 node1 2021-09-07T13:56:40.235061Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: logtimemicros="" 
 node1 2021-09-07T13:56:40.261083Z [init] [util/system.cpp:1041] [logArgsPrefix] Command-line arg: uacomment="testnode1" 
 node1 2021-09-07T13:56:40.316717Z [init] [init.cpp:1081] [AppInitMain] Using at most 125 automatic connections (1048564 file descriptors available) 
 node1 2021-09-07T13:56:41.813963Z [init] [script/sigcache.cpp:101] [InitSignatureCache] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 
 node1 2021-09-07T13:56:42.890949Z [init] [validation.cpp:1371] [InitScriptExecutionCache] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 
 node1 2021-09-07T13:56:42.896969Z [init] [init.cpp:1108] [AppInitMain] Script verification uses 7 additional threads 
 node1 2021-09-07T13:56:47.832157Z [scheduler] [util/thread.cpp:17] [TraceThread] scheduler thread start 
 node0 2021-09-07T13:57:09.451400Z [init] [httpserver.cpp:180] [InitHTTPAllowList] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2021-09-07T13:57:09.831978Z [init] [httpserver.cpp:316] [HTTPBindAddresses] Binding RPC on address ::1 port 18592 
 node0 2021-09-07T13:57:09.949957Z [init] [httpserver.cpp:346] [libevent_log_cb] libevent: getaddrinfo: address family for nodename not supported 
 node0 2021-09-07T13:57:09.967851Z [init] [httpserver.cpp:325] [HTTPBindAddresses] Binding RPC on address ::1 port 18592 failed. 
 node0 2021-09-07T13:57:09.973666Z [init] [httpserver.cpp:316] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 18592 
 node0 2021-09-07T13:57:10.049649Z [init] [httpserver.cpp:391] [InitHTTPServer] Initialized HTTP server 
 node0 2021-09-07T13:57:10.062719Z [init] [httpserver.cpp:393] [InitHTTPServer] HTTP: creating work queue of depth 16 
 node0 2021-09-07T13:57:10.086949Z [init] [rpc/server.cpp:292] [StartRPC] Starting RPC 
 node0 2021-09-07T13:57:10.235111Z [init] [httprpc.cpp:294] [StartHTTPRPC] Starting HTTP RPC server 
 node0 2021-09-07T13:57:10.247861Z [init] [httprpc.cpp:246] [InitRPCAuthentication] Using random cookie authentication. 
 node0 2021-09-07T13:57:10.334449Z [init] [rpc/request.cpp:101] [GenerateAuthCookie] Generated RPC authentication cookie /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/.cookie 
 node0 2021-09-07T13:57:10.390215Z [init] [httpserver.cpp:635] [RegisterHTTPHandler] Registering HTTP handler for / (exactmatch 1) 
 node0 2021-09-07T13:57:10.503791Z [init] [httpserver.cpp:635] [RegisterHTTPHandler] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node0 2021-09-07T13:57:10.523827Z [init] [httpserver.cpp:421] [StartHTTPServer] Starting HTTP server 
 node0 2021-09-07T13:57:10.527761Z [init] [httpserver.cpp:423] [StartHTTPServer] HTTP: starting 4 worker threads 
 node0 2021-09-07T13:57:10.950373Z [http] [httpserver.cpp:282] [ThreadHTTP] Entering http event loop 
 node0 2021-09-07T13:57:13.239373Z [init] [wallet/load.cpp:40] [VerifyWallets] Using wallet directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/wallets 
 node0 2021-09-07T13:57:13.283893Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying wallet(s)… 
 node0 2021-09-07T13:57:13.553405Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
 node0 2021-09-07T13:57:14.433623Z [init] [banman.cpp:27] [BanMan] Recreating the banlist database 
 node0 2021-09-07T13:57:14.777974Z [init] [banman.cpp:54] [DumpBanlist] Flushed 0 banned node addresses/subnets to disk  249ms 
 node0 2021-09-07T13:57:14.813418Z [init] [net.cpp:1796] [SetTryNewOutboundPeer] net: setting try another outbound peer=false 
 node0 2021-09-07T13:57:15.222911Z [init] [net.cpp:2443] [SetNetworkActive] SetNetworkActive: true 
 node0 2021-09-07T13:57:15.408359Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37230 
 node0 2021-09-07T13:57:15.482771Z [init] [policy/fees.cpp:530] [CBlockPolicyEstimator] Failed to read fee estimates from /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/fee_estimates.dat. Continue anyway. 
 node0 2021-09-07T13:57:16.795892Z [init] [init.cpp:1294] [AppInitMain] Using /16 prefix for IP bucketing 
 node0 2021-09-07T13:57:16.815381Z [init] [init.cpp:1330] [AppInitMain] Cache configuration: 
 node0 2021-09-07T13:57:16.898518Z [init] [init.cpp:1331] [AppInitMain] * Using 2.0 MiB for block index database 
 node0 2021-09-07T13:57:16.910571Z [init] [init.cpp:1339] [AppInitMain] * Using 8.0 MiB for chain state database 
 node0 2021-09-07T13:57:16.979730Z [init] [init.cpp:1340] [AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 node0 2021-09-07T13:57:16.995518Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
 node0 2021-09-07T13:57:17.024124Z [init] [validation.cpp:4693] [InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null) 
 node0 2021-09-07T13:57:17.126877Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:17.924400Z [init] [dbwrapper.cpp:137] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/blocks/index 
 node0 2021-09-07T13:57:19.213440Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37244 
 node0 2021-09-07T13:57:19.223686Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:19.425879Z [init] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully 
 node0 2021-09-07T13:57:19.618900Z [init] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/blocks/index: 0000000000000000 
 node0 2021-09-07T13:57:19.632098Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37248 
 node0 2021-09-07T13:57:19.638342Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:20.104391Z [init] [validation.cpp:3765] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 node0 2021-09-07T13:57:20.120763Z [init] [validation.cpp:3769] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01) 
 node0 2021-09-07T13:57:20.146437Z [init] [validation.cpp:3780] [LoadBlockIndexDB] Checking all blk files are present... 
 node0 2021-09-07T13:57:20.147555Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37252 
 node0 2021-09-07T13:57:20.162222Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:20.279115Z [init] [validation.cpp:4116] [LoadBlockIndex] Initializing databases... 
 node0 2021-09-07T13:57:20.416546Z [init] [flatfile.cpp:69] [Allocate] Pre-allocating up to position 0x1000000 in blk00000.dat 
 node0 2021-09-07T13:57:20.510269Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37256 
 node0 2021-09-07T13:57:20.600687Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:20.624614Z [init] [dbwrapper.cpp:137] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/chainstate 
 node0 2021-09-07T13:57:20.757770Z [init] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully 
 node0 2021-09-07T13:57:20.866792Z [init] [dbwrapper.cpp:163] [CDBWrapper] Wrote new obfuscate key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/chainstate: 9831a575612aa084 
 node0 2021-09-07T13:57:20.873942Z [init] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/chainstate: 9831a575612aa084 
 node0 2021-09-07T13:57:21.279722Z [init] [init.cpp:1519] [AppInitMain]  block index            4256ms 
 node0 2021-09-07T13:57:21.743837Z [loadblk] [util/thread.cpp:17] [TraceThread] loadblk thread start 
 node1 2021-09-07T13:57:21.797508Z [init] [httpserver.cpp:180] [InitHTTPAllowList] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
 node0 2021-09-07T13:57:21.862132Z [loadblk] [validation.cpp:2367] [ConnectTip]   - Load block from disk: 68.23ms [0.07s] 
 node0 2021-09-07T13:57:21.975736Z [loadblk] [validationinterface.cpp:248] [BlockChecked] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
 node0 2021-09-07T13:57:22.038696Z [loadblk] [validation.cpp:2379] [ConnectTip]   - Connect total: 183.08ms [0.18s (183.08ms/blk)] 
 node0 2021-09-07T13:57:22.066766Z [loadblk] [validation.cpp:2384] [ConnectTip]   - Flush: 31.90ms [0.03s (31.90ms/blk)] 
 node0 2021-09-07T13:57:22.169693Z [loadblk] [validation.cpp:2390] [ConnectTip]   - Writing chainstate: 61.07ms [0.06s (61.07ms/blk)] 
 node0 2021-09-07T13:57:22.420105Z [loadblk] [validation.cpp:2224] [UpdateTip] UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1.000000 tx=1 date='2011-02-02T23:16:42Z' progress=1.000000 cache=0.0MiB(0txo) 
 node0 2021-09-07T13:57:22.457718Z [loadblk] [validation.cpp:2401] [ConnectTip]   - Connect postprocess: 333.39ms [0.33s (333.39ms/blk)] 
 node0 2021-09-07T13:57:22.509004Z [loadblk] [validation.cpp:2402] [ConnectTip] - Connect block: 677.67ms [0.68s (677.67ms/blk)] 
 node0 2021-09-07T13:57:22.561556Z [loadblk] [txmempool.cpp:691] [check] Checking mempool with 0 transactions and 0 inputs 
 node0 2021-09-07T13:57:22.685999Z [loadblk] [validationinterface.cpp:224] [BlockConnected] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2021-09-07T13:57:22.710758Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37260 
 node0 2021-09-07T13:57:22.726058Z [scheduler] [validationinterface.cpp:224] [operator()] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node0 2021-09-07T13:57:22.805888Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:22.877361Z [loadblk] [validationinterface.cpp:196] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node0 2021-09-07T13:57:23.127233Z [init] [init.cpp:1661] [AppInitMain] block tree size = 1 
 node0 2021-09-07T13:57:23.130210Z [init] [init.cpp:1673] [AppInitMain] nBestHeight = 0 
 node0 2021-09-07T13:57:23.327826Z [init] [net.cpp:2376] [BindListenPort] Bound to 127.0.0.1:13592 
 node0 2021-09-07T13:57:23.391577Z [scheduler] [validationinterface.cpp:196] [operator()] UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node1 2021-09-07T13:57:23.422606Z [init] [httpserver.cpp:316] [HTTPBindAddresses] Binding RPC on address ::1 port 18593 
 node0 2021-09-07T13:57:23.551249Z [init] [net.cpp:2373] [BindListenPort] Unable to bind to 127.0.0.1:18445 on this computer. Bitcoin Core is probably already running. 
 node1 2021-09-07T13:57:23.626397Z [init] [httpserver.cpp:346] [libevent_log_cb] libevent: getaddrinfo: address family for nodename not supported 
 node0 2021-09-07T13:57:23.643950Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
 node1 2021-09-07T13:57:23.665530Z [init] [httpserver.cpp:325] [HTTPBindAddresses] Binding RPC on address ::1 port 18593 failed. 
 node1 2021-09-07T13:57:23.669433Z [init] [httpserver.cpp:316] [HTTPBindAddresses] Binding RPC on address 127.0.0.1 port 18593 
 node0 2021-09-07T13:57:23.691027Z [init] [addrdb.cpp:174] [DeserializeFileDB] Missing or invalid file /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/peers.dat 
 node1 2021-09-07T13:57:23.808986Z [init] [httpserver.cpp:391] [InitHTTPServer] Initialized HTTP server 
 node0 2021-09-07T13:57:23.832718Z [init] [net.cpp:2545] [Start] Recreating peers.dat 
 node1 2021-09-07T13:57:23.832916Z [init] [httpserver.cpp:393] [InitHTTPServer] HTTP: creating work queue of depth 16 
 node1 2021-09-07T13:57:23.888004Z [init] [rpc/server.cpp:292] [StartRPC] Starting RPC 
 node0 2021-09-07T13:57:23.912846Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37266 
 node0 2021-09-07T13:57:23.918825Z [loadblk] [validation.cpp:4496] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
 node0 2021-09-07T13:57:23.927562Z [loadblk] [util/thread.cpp:19] [TraceThread] loadblk thread exit 
 node0 2021-09-07T13:57:24.229740Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:24.241799Z [init] [httprpc.cpp:294] [StartHTTPRPC] Starting HTTP RPC server 
 node0 2021-09-07T13:57:24.308306Z [init] [net.cpp:1767] [DumpAddresses] Flushed 0 addresses to peers.dat  417ms 
 node1 2021-09-07T13:57:24.334791Z [init] [httprpc.cpp:246] [InitRPCAuthentication] Using random cookie authentication. 
 node0 2021-09-07T13:57:24.343752Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
 node1 2021-09-07T13:57:24.559539Z [init] [rpc/request.cpp:101] [GenerateAuthCookie] Generated RPC authentication cookie /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/.cookie 
 node1 2021-09-07T13:57:24.681570Z [init] [httpserver.cpp:635] [RegisterHTTPHandler] Registering HTTP handler for / (exactmatch 1) 
 node1 2021-09-07T13:57:24.735133Z [init] [httpserver.cpp:635] [RegisterHTTPHandler] Registering HTTP handler for /wallet/ (exactmatch 0) 
 node1 2021-09-07T13:57:24.771386Z [init] [httpserver.cpp:421] [StartHTTPServer] Starting HTTP server 
 node1 2021-09-07T13:57:24.800696Z [init] [httpserver.cpp:423] [StartHTTPServer] HTTP: starting 4 worker threads 
 node0 2021-09-07T13:57:24.874591Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37274 
 node0 2021-09-07T13:57:24.875615Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:24.885237Z [net] [util/thread.cpp:17] [TraceThread] net thread start 
 node0 2021-09-07T13:57:24.958358Z [init] [net.cpp:2589] [Start] DNS seeding disabled 
 node0 2021-09-07T13:57:25.563751Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37278 
 node0 2021-09-07T13:57:25.565539Z [addcon] [util/thread.cpp:17] [TraceThread] addcon thread start 
 node1 2021-09-07T13:57:25.642169Z [http] [httpserver.cpp:282] [ThreadHTTP] Entering http event loop 
 node0 2021-09-07T13:57:27.111865Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node0 2021-09-07T13:57:27.151684Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 node0 2021-09-07T13:57:27.304194Z [msghand] [util/thread.cpp:17] [TraceThread] msghand thread start 
 node0 2021-09-07T13:57:27.568758Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37290 
 node0 2021-09-07T13:57:27.570382Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:27.699964Z [init] [wallet/load.cpp:40] [VerifyWallets] Using wallet directory /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/wallets 
 node0 2021-09-07T13:57:27.751237Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37290 
 node0 2021-09-07T13:57:27.752990Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 node1 2021-09-07T13:57:27.862732Z [init] [noui.cpp:56] [noui_InitMessage] init message: Verifying wallet(s)… 
 test  2021-09-07T13:57:28.202000Z TestFramework.node0 (DEBUG): RPC successfully started 
 node1 2021-09-07T13:57:29.091523Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading banlist… 
 node1 2021-09-07T13:57:29.113932Z [init] [banman.cpp:27] [BanMan] Recreating the banlist database 
 node1 2021-09-07T13:57:29.724503Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35146 
 node1 2021-09-07T13:57:29.827696Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:29.977769Z [init] [banman.cpp:54] [DumpBanlist] Flushed 0 banned node addresses/subnets to disk  824ms 
 node1 2021-09-07T13:57:30.055667Z [init] [net.cpp:1796] [SetTryNewOutboundPeer] net: setting try another outbound peer=false 
 node1 2021-09-07T13:57:30.122550Z [init] [net.cpp:2443] [SetNetworkActive] SetNetworkActive: true 
 node1 2021-09-07T13:57:30.284579Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35156 
 node1 2021-09-07T13:57:30.295812Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:30.301008Z [init] [policy/fees.cpp:530] [CBlockPolicyEstimator] Failed to read fee estimates from /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/fee_estimates.dat. Continue anyway. 
 node1 2021-09-07T13:57:30.430442Z [init] [init.cpp:1294] [AppInitMain] Using /16 prefix for IP bucketing 
 node1 2021-09-07T13:57:30.438784Z [init] [init.cpp:1330] [AppInitMain] Cache configuration: 
 node1 2021-09-07T13:57:30.465210Z [init] [init.cpp:1331] [AppInitMain] * Using 2.0 MiB for block index database 
 node1 2021-09-07T13:57:30.473203Z [init] [init.cpp:1339] [AppInitMain] * Using 8.0 MiB for chain state database 
 node1 2021-09-07T13:57:30.498934Z [init] [init.cpp:1340] [AppInitMain] * Using 440.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space) 
 node1 2021-09-07T13:57:30.502418Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading block index… 
 node1 2021-09-07T13:57:30.542945Z [init] [validation.cpp:4693] [InitializeChainstate] Switching active chainstate to Chainstate [ibd] @ height -1 (null) 
 node1 2021-09-07T13:57:30.676789Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35162 
 node1 2021-09-07T13:57:31.068678Z [init] [dbwrapper.cpp:137] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/blocks/index 
 node1 2021-09-07T13:57:31.175371Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:31.441259Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35172 
 node1 2021-09-07T13:57:31.442924Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:31.738188Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35176 
 node1 2021-09-07T13:57:31.825641Z [httpworker.0] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:31.970139Z [init] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully 
 node1 2021-09-07T13:57:32.067722Z [init] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/blocks/index: 0000000000000000 
 node1 2021-09-07T13:57:32.148264Z [init] [validation.cpp:3765] [LoadBlockIndexDB] LoadBlockIndexDB: last block file = 0 
 node1 2021-09-07T13:57:32.197162Z [init] [validation.cpp:3769] [LoadBlockIndexDB] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=0, size=0, heights=0...0, time=1970-01-01...1970-01-01) 
 node1 2021-09-07T13:57:32.210105Z [init] [validation.cpp:3780] [LoadBlockIndexDB] Checking all blk files are present... 
 node1 2021-09-07T13:57:32.232674Z [init] [validation.cpp:4116] [LoadBlockIndex] Initializing databases... 
 node1 2021-09-07T13:57:32.273238Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35180 
 node1 2021-09-07T13:57:32.275911Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:32.288601Z [init] [flatfile.cpp:69] [Allocate] Pre-allocating up to position 0x1000000 in blk00000.dat 
 node1 2021-09-07T13:57:32.534851Z [init] [dbwrapper.cpp:137] [CDBWrapper] Opening LevelDB in /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/chainstate 
 node1 2021-09-07T13:57:32.568685Z [init] [dbwrapper.cpp:141] [CDBWrapper] Opened LevelDB successfully 
 node0 2021-09-07T13:57:32.616713Z [scheduler] [random.cpp:523] [SeedPeriodic] Feeding 17283 bytes of dynamic environment data into RNG 
 node1 2021-09-07T13:57:32.647204Z [init] [dbwrapper.cpp:163] [CDBWrapper] Wrote new obfuscate key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/chainstate: 8a10a9d90b4fb6d7 
 node1 2021-09-07T13:57:32.649261Z [init] [dbwrapper.cpp:166] [CDBWrapper] Using obfuscation key for /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/chainstate: 8a10a9d90b4fb6d7 
 node1 2021-09-07T13:57:32.688104Z [init] [init.cpp:1519] [AppInitMain]  block index            2181ms 
 node1 2021-09-07T13:57:32.833181Z [loadblk] [util/thread.cpp:17] [TraceThread] loadblk thread start 
 node1 2021-09-07T13:57:32.977798Z [loadblk] [validation.cpp:2367] [ConnectTip]   - Load block from disk: 55.28ms [0.06s] 
 node1 2021-09-07T13:57:33.093695Z [loadblk] [validationinterface.cpp:248] [BlockChecked] BlockChecked: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 state=Valid 
 node1 2021-09-07T13:57:33.147168Z [loadblk] [validation.cpp:2379] [ConnectTip]   - Connect total: 212.62ms [0.21s (212.62ms/blk)] 
 node1 2021-09-07T13:57:33.150760Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35186 
 node1 2021-09-07T13:57:33.175520Z [loadblk] [validation.cpp:2384] [ConnectTip]   - Flush: 47.14ms [0.05s (47.14ms/blk)] 
 node1 2021-09-07T13:57:33.225933Z [loadblk] [validation.cpp:2390] [ConnectTip]   - Writing chainstate: 41.99ms [0.04s (41.99ms/blk)] 
 node1 2021-09-07T13:57:33.270161Z [loadblk] [validation.cpp:2224] [UpdateTip] UpdateTip: new best=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 height=0 version=0x00000001 log2_work=1.000000 tx=1 date='2011-02-02T23:16:42Z' progress=1.000000 cache=0.0MiB(0txo) 
 node1 2021-09-07T13:57:33.298504Z [loadblk] [validation.cpp:2401] [ConnectTip]   - Connect postprocess: 79.31ms [0.08s (79.31ms/blk)] 
 node1 2021-09-07T13:57:33.300964Z [loadblk] [validation.cpp:2402] [ConnectTip] - Connect block: 436.35ms [0.44s (436.35ms/blk)] 
 node1 2021-09-07T13:57:33.325638Z [loadblk] [txmempool.cpp:691] [check] Checking mempool with 0 transactions and 0 inputs 
 node1 2021-09-07T13:57:33.339820Z [loadblk] [validationinterface.cpp:224] [BlockConnected] Enqueuing BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node1 2021-09-07T13:57:33.378950Z [loadblk] [validationinterface.cpp:196] [UpdatedBlockTip] Enqueuing UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node1 2021-09-07T13:57:33.548166Z [init] [init.cpp:1661] [AppInitMain] block tree size = 1 
 node1 2021-09-07T13:57:33.556792Z [init] [init.cpp:1673] [AppInitMain] nBestHeight = 0 
 node1 2021-09-07T13:57:33.885723Z [init] [net.cpp:2376] [BindListenPort] Bound to 127.0.0.1:13593 
 node1 2021-09-07T13:57:33.972750Z [init] [net.cpp:2373] [BindListenPort] Unable to bind to 127.0.0.1:18445 on this computer. Bitcoin Core is probably already running. 
 node1 2021-09-07T13:57:33.999124Z [init] [noui.cpp:56] [noui_InitMessage] init message: Loading P2P addresses… 
 node1 2021-09-07T13:57:34.052180Z [init] [addrdb.cpp:174] [DeserializeFileDB] Missing or invalid file /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node1/regtest/peers.dat 
 node1 2021-09-07T13:57:34.074013Z [init] [net.cpp:2545] [Start] Recreating peers.dat 
 node1 2021-09-07T13:57:34.212576Z [scheduler] [validationinterface.cpp:224] [operator()] BlockConnected: block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 block height=0 
 node1 2021-09-07T13:57:34.398569Z [init] [net.cpp:1767] [DumpAddresses] Flushed 0 addresses to peers.dat  314ms 
 node1 2021-09-07T13:57:34.405508Z [init] [noui.cpp:56] [noui_InitMessage] init message: Starting network threads… 
 node1 2021-09-07T13:57:34.632975Z [init] [net.cpp:2589] [Start] DNS seeding disabled 
 node1 2021-09-07T13:57:34.962240Z [net] [util/thread.cpp:17] [TraceThread] net thread start 
 node1 2021-09-07T13:57:34.978698Z [msghand] [util/thread.cpp:17] [TraceThread] msghand thread start 
 node1 2021-09-07T13:57:34.987257Z [init] [noui.cpp:56] [noui_InitMessage] init message: Done loading 
 node1 2021-09-07T13:57:35.033508Z [addcon] [util/thread.cpp:17] [TraceThread] addcon thread start 
 node1 2021-09-07T13:57:35.062112Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getblockcount user=__cookie__ 
 node1 2021-09-07T13:57:35.137026Z [loadblk] [validation.cpp:4496] [LoadMempool] Failed to open mempool file from disk. Continuing anyway. 
 node1 2021-09-07T13:57:35.143933Z [loadblk] [util/thread.cpp:19] [TraceThread] loadblk thread exit 
 node1 2021-09-07T13:57:35.187840Z [scheduler] [validationinterface.cpp:196] [operator()] UpdatedBlockTip: new block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 fork block hash=null (in IBD=true) 
 node1 2021-09-07T13:57:35.210357Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:35186 
 node1 2021-09-07T13:57:35.216239Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getmempoolinfo user=__cookie__ 
 test  2021-09-07T13:57:35.249000Z TestFramework.node1 (DEBUG): RPC successfully started 
 node0 2021-09-07T13:57:35.253602Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37290 
 node0 2021-09-07T13:57:35.267245Z [httpworker.3] [rpc/request.cpp:174] [parse] ThreadRPCServer method=createwallet user=__cookie__ 
 node0 2021-09-07T13:57:35.342394Z [httpworker.3] [wallet/bdb.cpp:263] [Verify] Using BerkeleyDB version Berkeley DB 5.3.28: (September  9, 2013) 
 node0 2021-09-07T13:57:35.344129Z [httpworker.3] [wallet/bdb.cpp:264] [Verify] Using wallet /tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/wallets/wallet.dat 
 node0 2021-09-07T13:57:35.358589Z [httpworker.3] [wallet/bdb.cpp:143] [Open] BerkeleyEnvironment::Open: LogDir=/tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/wallets/database ErrorFile=/tmp/test_runner_₿_🏃_20210907_065517/wallet_hd_216/node0/regtest/wallets/db.log 
 node0 2021-09-07T13:57:35.712488Z [httpworker.3] [noui.cpp:56] [noui_InitMessage] init message: Loading wallet… 
 node0 2021-09-07T13:57:36.996061Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] Wallet File Version = 10500 
 node0 2021-09-07T13:57:37.006487Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] Keys: 0 plaintext, 0 encrypted, 0 w/ metadata, 0 total. Unknown wallet records: 0 
 node0 2021-09-07T13:57:37.915740Z [httpworker.3] [wallet/scriptpubkeyman.h:244] [WalletLogPrintf] [default wallet] keypool added 2 keys (1 internal), size=2 (1 internal) 
 node0 2021-09-07T13:57:37.929966Z [httpworker.3] [wallet/scriptpubkeyman.h:244] [WalletLogPrintf] [default wallet] LegacyScriptPubKeyMan::NewKeyPool rewrote keypool 
 node0 2021-09-07T13:57:38.018919Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] Wallet completed loading in            2298ms 
 node0 2021-09-07T13:57:38.052556Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] setKeyPool.size() = 2 
 node0 2021-09-07T13:57:38.057586Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] mapWallet.size() = 0 
 node0 2021-09-07T13:57:38.059772Z [httpworker.3] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] m_address_book.size() = 0 
 node0 2021-09-07T13:57:38.133420Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37290 
 node0 2021-09-07T13:57:38.135066Z [httpworker.1] [rpc/request.cpp:174] [parse] ThreadRPCServer method=getwalletinfo user=__cookie__ 
 node0 2021-09-07T13:57:38.287181Z [http] [httpserver.cpp:236] [http_request_cb] Received a POST request for / from 127.0.0.1:37290 
 node0 2021-09-07T13:57:38.290967Z [httpworker.2] [rpc/request.cpp:174] [parse] ThreadRPCServer method=importprivkey user=__cookie__ 
 node0 2021-09-07T13:57:38.691672Z [httpworker.2] [wallet/scriptpubkeyman.h:244] [WalletLogPrintf] [default wallet] Already have script 00142b4569203694fc997e13f2c0a1383b9e16c77a0d, skipping 
 node0 2021-09-07T13:57:38.721144Z [httpworker.2] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] RescanFromTime: Rescanning last 1 blocks 
 node0 2021-09-07T13:57:38.736585Z [httpworker.2] [wallet/wallet.h:826] [WalletLogPrintf] [default wallet] Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... 
 test  2021-09-07T13:57:39.289000Z TestFramework (ERROR): Unexpected exception caught during testing 
                                   Traceback (most recent call last):
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 108, in _request
                                       return self._get_response()
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 168, in _get_response
                                       http_response = self.__conn.getresponse()
                                     File "/usr/lib/python3.8/http/client.py", line 1344, in getresponse
                                       response.begin()
                                     File "/usr/lib/python3.8/http/client.py", line 307, in begin
                                       version, status, reason = self._read_status()
                                     File "/usr/lib/python3.8/http/client.py", line 276, in _read_status
                                       raise RemoteDisconnected("Remote end closed connection without"
                                   http.client.RemoteDisconnected: Remote end closed connection without response
                                   During handling of the above exception, another exception occurred:
                                   Traceback (most recent call last):
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 130, in main
                                       self.setup()
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 285, in setup
                                       self.setup_network()
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 379, in setup_network
                                       self.setup_nodes()
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 406, in setup_nodes
                                       self.import_deterministic_coinbase_privkeys()
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 423, in import_deterministic_coinbase_privkeys
                                       self.init_wallet(i)
                                     File "/root/bitcoin/test/functional/test_framework/test_framework.py", line 431, in init_wallet
                                       n.importprivkey(privkey=n.get_deterministic_priv_key().key, label='coinbase')
                                     File "/root/bitcoin/test/functional/test_framework/test_node.py", line 689, in importprivkey
                                       return self.__getattr__('importprivkey')(privkey, label, rescan)
                                     File "/root/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
                                       response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 113, in _request
                                       self.__conn.request(method, path, postdata, headers)
                                     File "/usr/lib/python3.8/http/client.py", line 1252, in request
                                       self._send_request(method, url, body, headers, encode_chunked)
                                     File "/usr/lib/python3.8/http/client.py", line 1298, in _send_request
                                       self.endheaders(body, encode_chunked=encode_chunked)
                                     File "/usr/lib/python3.8/http/client.py", line 1247, in endheaders
                                       self._send_output(message_body, encode_chunked=encode_chunked)
                                     File "/usr/lib/python3.8/http/client.py", line 1007, in _send_output
                                       self.send(msg)
                                     File "/usr/lib/python3.8/http/client.py", line 947, in send
                                       self.connect()
                                     File "/usr/lib/python3.8/http/client.py", line 918, in connect
                                       self.sock = self._create_connection(
                                     File "/usr/lib/python3.8/socket.py", line 808, in create_connection
                                       raise err
                                     File "/usr/lib/python3.8/socket.py", line 796, in create_connection
                                       sock.connect(sa)
                                   ConnectionRefusedError: [Errno 111] Connection refused
 test  2021-09-07T13:57:39.295000Z TestFramework (DEBUG): Closing down network thread 
 test  2021-09-07T13:57:39.347000Z TestFramework (INFO): Stopping nodes 
 test  2021-09-07T13:57:39.347000Z TestFramework.node0 (DEBUG): Stopping node 
 test  2021-09-07T13:57:39.348000Z TestFramework.node0 (ERROR): Unable to stop node. 
                                   Traceback (most recent call last):
                                     File "/root/bitcoin/test/functional/test_framework/test_node.py", line 323, in stop_node
                                       self.stop(wait=wait)
                                     File "/root/bitcoin/test/functional/test_framework/coverage.py", line 49, in __call__
                                       return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 144, in __call__
                                       response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                                     File "/root/bitcoin/test/functional/test_framework/authproxy.py", line 107, in _request
                                       self.__conn.request(method, path, postdata, headers)
                                     File "/usr/lib/python3.8/http/client.py", line 1252, in request
                                       self._send_request(method, url, body, headers, encode_chunked)
                                     File "/usr/lib/python3.8/http/client.py", line 1263, in _send_request
                                       self.putrequest(method, url, **skips)
                                     File "/usr/lib/python3.8/http/client.py", line 1089, in putrequest
                                       raise CannotSendRequest(self.__state)
                                   http.client.CannotSendRequest: Request-sent

 node0 stderr ==48855== Thread 13 b-httpworker.2:
==48855== Conditional jump or move depends on uninitialised value(s)
==48855==    at 0x5BFDBB: CWallet::ScanForWalletTransactions(uint256 const&, int, std::optional<int>, WalletRescanReserver const&, bool) (wallet.cpp:1653)
==48855==    by 0x5C07CB: CWallet::RescanFromTime(long, WalletRescanReserver const&, bool) (wallet.cpp:1556)
==48855==    by 0x60E5ED: RescanWallet(CWallet&, WalletRescanReserver const&, long, bool) (rpcdump.cpp:85)
==48855==    by 0x628253: importprivkey()::{lambda(RPCHelpMan const&, JSONRPCRequest const&)#1}::operator()(RPCHelpMan const&, JSONRPCRequest const&) const [clone .isra.0] (rpcdump.cpp:187)
==48855==    by 0x628554: std::_Function_handler<UniValue (RPCHelpMan const&, JSONRPCRequest const&), importprivkey()::{lambda(RPCHelpMan const&, JSONRPCRequest const&)#1}>::_M_invoke(std::_Any_data const&, RPCHelpMan const&, JSONRPCRequest const&) (std_function.h:286)
==48855==    by 0x692115: operator() (std_function.h:688)
==48855==    by 0x692115: RPCHelpMan::HandleRequest(JSONRPCRequest const&) const (util.cpp:575)
==48855==    by 0x3471CB: CRPCCommand::CRPCCommand(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, RPCHelpMan (*)())::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}::operator()(JSONRPCRequest const&, UniValue&, bool) const (server.h:110)
==48855==    by 0x4E417B: wallet::(anonymous namespace)::WalletClientImpl::registerRpcs()::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}::operator()(JSONRPCRequest const&, UniValue&, bool) const (std_function.h:688)
==48855==    by 0x2BF324: operator() (std_function.h:688)
==48855==    by 0x2BF324: operator() (interfaces.cpp:397)
==48855==    by 0x2BF324: std::_Function_handler<bool (JSONRPCRequest const&, UniValue&, bool), node::(anonymous namespace)::RpcHandlerImpl::RpcHandlerImpl(CRPCCommand const&)::{lambda(JSONRPCRequest const&, UniValue&, bool)#1}>::_M_invoke(std::_Any_data const&, JSONRPCRequest const&, UniValue&, bool&&) (std_function.h:285)
==48855==    by 0x3D9396: operator() (std_function.h:688)
==48855==    by 0x3D9396: ExecuteCommand(CRPCCommand const&, JSONRPCRequest const&, UniValue&, bool) (server.cpp:480)
==48855==    by 0x3D9FB6: ExecuteCommands(std::vector<CRPCCommand const*, std::allocator<CRPCCommand const*> > const&, JSONRPCRequest const&, UniValue&) [clone .constprop.0] (server.cpp:444)
==48855==    by 0x3DA55D: CRPCTable::execute(JSONRPCRequest const&) const (server.cpp:464)
==48855== 
{
   <insert_a_suppression_name_here>
   Memcheck:Cond
   fun:_ZN7CWallet25ScanForWalletTransactionsERK7uint256iSt8optionalIiERK20WalletRescanReserverb
   fun:_ZN7CWallet14RescanFromTimeElRK20WalletRescanReserverb
   fun:_ZL12RescanWalletR7CWalletRK20WalletRescanReserverlb
   fun:_ZZ13importprivkeyvENKUlRK10RPCHelpManRK14JSONRPCRequestE_clES1_S4_.isra.0
   fun:_ZNSt17_Function_handlerIF8UniValueRK10RPCHelpManRK14JSONRPCRequestEZ13importprivkeyvEUlS3_S6_E_E9_M_invokeERKSt9_Any_dataS3_S6_
   fun:operator()
   fun:_ZNK10RPCHelpMan13HandleRequestERK14JSONRPCRequest
   fun:_ZZN11CRPCCommandC4ENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEPF10RPCHelpManvEENKUlRK14JSONRPCRequestR8UniValuebE_clESB_SD_b
   fun:_ZZN6wallet12_GLOBAL__N_116WalletClientImpl12registerRpcsEvENKUlRK14JSONRPCRequestR8UniValuebE_clES4_S6_b
   fun:operator()
   fun:operator()
   fun:_ZNSt17_Function_handlerIFbRK14JSONRPCRequestR8UniValuebEZN4node12_GLOBAL__N_114RpcHandlerImplC4ERK11CRPCCommandEUlS2_S4_bE_E9_M_invokeERKSt9_Any_dataS2_S4_Ob
   fun:operator()
   fun:_ZL14ExecuteCommandRK11CRPCCommandRK14JSONRPCRequestR8UniValueb
   fun:_ZL15ExecuteCommandsRKSt6vectorIPK11CRPCCommandSaIS2_EERK14JSONRPCRequestR8UniValue.constprop.0
   fun:_ZNK9CRPCTable7executeERK14JSONRPCRequest
}
==48855== 
==48855== Exit program on first error (--exit-on-first-error=yes) 

Hmm, that looks like a valgrind false positive. You can work around it by adding a suppression to contrib/valgrind.supp.

Any chance of anyone expert in tx validation or the testing thereof getting a chance to look at the mutants? They are pretty easy to understand if you know context, I would guess, in many cases.

@practicalswift and @MarcoFalke a draft of the report on my efforts, as an ICSE SEIP paper (https://conf.researchr.org/track/icse-2021/icse-2021-Software-Engineering-in-Practice) is up here:

https://github.com/agroce/icseseip21/blob/master/currentdraft.pdf

Your comments if there are any glaring inaccuracies or points that you'd like to see elaborated on, would be VERY welcome. Our deadline (there are other authors, doing the mutation & coverage analysis with me, not yet added in to the author list) is end of this week, Friday the 15th

Thanks for the writeup. Now I have something to point to if someone asks about the state of fuzzing in Bitcoin Core.

Some minor comments:

ran the first mutation analysis of Bitcoin Core code

While the efforts aren't documented, this has been done numerous times before. Especially for consensus code. Though, you might have been the first one to run mutation testing against the fuzz tests.

At the time, the basic strategy was to run libFuzzer on each of these for 100,000 iterations.

This is the default in the test runner. Though, personally I am running a modified version of the test runner. I believe that others (Evan from Chaincode or #20752) are also running with a modified version. Obviously, 100k iterations for serious fuzzing is not enough, so your claim still holds in essence. Edit: nvm, just read the next section, Evan seems to have adjusted it based on your feedback.

The most obvious solution when fuzzer A

I think some readers might not be able to infer the meaning of "fuzzer" based on the context. Generally, it can mean "fuzz target" or "fuzz engine", depending on context. Might be clearer to just use "fuzz engine" here. See also https://github.com/google/fuzzing/blob/master/docs/glossary.md#fuzzer This applies throughout the paper.

Building a one-off verson

version

Also in this section "Ensemble fuzzing", I believe this is already done by us. I read section 2.3 of the reference [5] you linked to, and the authors seem to be misunderstanding how OSS-Fuzz works. OSS-Fuzz doesn't run the same instance of libFuzzer on all VMs. Instead it runs different fuzzing engines (afl, honggfuzz, libFuzzer) with different compilation flags (32-bit, 64-bit), as well as sanitizers (msan, asan, ubsan). On my servers I am also running with different flags. Our fuzz inputs are already synced via the qa-assets repo, which serves as ensemble fuzzing. Maybe I am just misunderstanding, but some readers might benefit from a minor clarification/distinction here.

it simply generates an arbitrary string that will be parsed as a message type, a nondeter-ministic number of times

Hopefully our fuzzing is deterministic ;) Maybe you meant to write indeterminate or unlimited?

dynamic parser to use in-filght data

in-flight

and72.6% of branches

missing space

Firstly, bitcoin reached out to the first author to investigate the quality of their test suite

I wonder which language bitcoin spoke in ;)

we spent more time was spent

grammar

8. CONCLUSIONS

empty section?

"bitcoin reached out" -- now "money talks" is literal!

Thanks a million! Yes, this is great info. Conclusions is always the last thing I write, but it's never very exciting.

Good point that there is already a form of ensemble fuzzing going on. On-the-fly direction of the specific cross-seeds that a particular engine is missing adds value (I think, that's my reading of the literature and some limited experiments of my own) but the basic thing is there via qa-assets.

By nondeterministic I mean "fuzzer chosen"; it's a common use in testing lit, but yeah, it is easily mixed up with bad nondeterminism like test flakiness or threads. The field needs a new term.

The mutation section's comparison part is under a lot of editing, we'll probably add and subtract typos there until Friday :)

BTW, I want to add you all to the Acknowledgements, I have Jonas and Evan's names -- how would you, @MarcoFalke and @practicalswift, like to be credited? I assume "Marco Falke" but "Practical Swift" is probably not right!

I haven't followed the entire discussion here, but in the libsecp256k1 code (implementation of ECDSA and related algorithms, subtreed into Bitcoin Core), (manual) mutation testing is occasionally done to find/verify the adequacy of included test vectors. I explained one (unexpected) result of this here: https://mobile.twitter.com/pwuille/status/1348835954396516353

@sipa -- nice! I convinced Richard Hipp to mutate the code for SQLite years ago, and his main result was finding a small but nice opportunity for optimization. We've written a little about that in some work on automatic resource adaptation, with my former student Arpit Christi.

You can just credit me as "anonymous reviewer", if you like

I'll do that if that's what you prefer; I bow to your wishes here, just want to ack the huge help you've been!

@MarcoFalke

While looking at all, this, I noticed https://marcofalke.github.io/btc_cov/total.coverage/src/consensus/tx_verify.cpp.gcov.html vs. https://marcofalke.github.io/btc_cov/fuzz.coverage/src/consensus/tx_verify.cpp.gcov.html

-- same code, but different line counts and branch counts for unit/functional vs. fuzz coverage. Any idea what's going on there?

Jup, one is compiled with gcc the other with clang. The only difference should be the order of branches and whether control statements are counted as a line.

Ah, makes sense. The annotated code is pretty easy to compare.

If the pdf is done, feel free to add a link to it to our fuzzing doc. It might offer newcomers an intro to our fuzzing.

Maybe we can also link to https://blog.regehr.org/archives/1687 as general guidelines?

John's post is definitely a good overview of how devs can help make/keep the fuzzing solid. The pdf is "done" but in submission; it'll likely get some useful input from reviewers, but since it's not even blinded, I think a link would be a good idea. I'll PR right now.

Closing this based on lack of further comments and after the addition of https://github.com/bitcoin/bitcoin/pull/23482/.