test: feature_dbcrash listunspent times out #16488

issue MarcoFalke opened this issue on July 29, 2019
  1. MarcoFalke commented at 6:02 PM on July 29, 2019: member

    On current master

    2019-07-29T16:43:20.074000Z TestFramework (INFO): Iteration 31, generating 2500 transactions [15, 3, 0]
    2019-07-29T16:45:53.858000Z TestFramework (ERROR): JSONRPC error
    Traceback (most recent call last):
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 163, in _get_response
        http_response = self.__conn.getresponse()
      File "/usr/lib/python3.6/http/client.py", line 1331, in getresponse
        response.begin()
      File "/usr/lib/python3.6/http/client.py", line 297, in begin
        version, status, reason = self._read_status()
      File "/usr/lib/python3.6/http/client.py", line 258, in _read_status
        line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
      File "/usr/lib/python3.6/socket.py", line 586, in readinto
        return self._sock.recv_into(b)
    socket.timeout: timed out
    
    During handling of the above exception, another exception occurred:
    
    Traceback (most recent call last):
      File "/root/workspace/bitcoin-core/test/functional/test_framework/test_framework.py", line 193, in main
        self.run_test()
      File "./test/functional/feature_dbcrash.py", line 250, in run_test
        utxo_list = self.nodes[3].listunspent()
      File "/root/workspace/bitcoin-core/test/functional/test_framework/coverage.py", line 47, in __call__
        return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 139, in __call__
        response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 107, in _request
        return self._get_response()
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 170, in _get_response
        self.__conn.timeout)})
    test_framework.authproxy.JSONRPCException: 'listunspent' RPC took longer than 90.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
    2019-07-29T16:45:54.033000Z TestFramework (INFO): Stopping nodes
    2019-07-29T16:45:54.060000Z TestFramework.node3 (ERROR): Unable to stop node.
    Traceback (most recent call last):
      File "/root/workspace/bitcoin-core/test/functional/test_framework/test_node.py", line 264, in stop_node
        self.stop(wait=wait)
      File "/root/workspace/bitcoin-core/test/functional/test_framework/coverage.py", line 47, in __call__
        return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 139, in __call__
        response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
      File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 106, in _request
        self.__conn.request(method, path, postdata, headers)
      File "/usr/lib/python3.6/http/client.py", line 1239, in request
        self._send_request(method, url, body, headers, encode_chunked)
      File "/usr/lib/python3.6/http/client.py", line 1250, in _send_request
        self.putrequest(method, url, **skips)
      File "/usr/lib/python3.6/http/client.py", line 1108, in putrequest
        raise CannotSendRequest(self.__state)
    http.client.CannotSendRequest: Request-sent
    2019-07-29T16:46:55.268000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ''''
        def is_node_stopped(self):
            """Checks whether the node has stopped.
    
            Returns True if the node has stopped. False otherwise.
            This method is responsible for freeing resources (self.process)."""
            if not self.running:
                return True
            return_code = self.process.poll()
            if return_code is None:
                return False
    
            # process has stopped. Assert that it didn't return an error code.
            assert return_code == 0, self._node_msg(
                "Node returned non-zero exit code (%d) when stopping" % return_code)
            self.running = False
            self.process = None
            self.rpc_connected = False
            self.rpc = None
            self.log.debug("Node stopped")
            return True
    '''
    Traceback (most recent call last):
      File "./test/functional/feature_dbcrash.py", line 273, in <module>
        ChainstateWriteCrashTest().main()
      File "/root/workspace/bitcoin-core/test/functional/test_framework/test_framework.py", line 218, in main
        self.stop_nodes()
      File "/root/workspace/bitcoin-core/test/functional/test_framework/test_framework.py", line 401, in stop_nodes
        node.wait_until_stopped()
      File "/root/workspace/bitcoin-core/test/functional/test_framework/test_node.py", line 305, in wait_until_stopped
        wait_until(self.is_node_stopped, timeout=timeout)
      File "/root/workspace/bitcoin-core/test/functional/test_framework/util.py", line 225, in wait_until
        raise AssertionError("Predicate {} not true after {} seconds".format(predicate_source, timeout))
    AssertionError: Predicate ''''
        def is_node_stopped(self):
            """Checks whether the node has stopped.
    
            Returns True if the node has stopped. False otherwise.
            This method is responsible for freeing resources (self.process)."""
            if not self.running:
                return True
            return_code = self.process.poll()
            if return_code is None:
                return False
    
            # process has stopped. Assert that it didn't return an error code.
            assert return_code == 0, self._node_msg(
                "Node returned non-zero exit code (%d) when stopping" % return_code)
            self.running = False
            self.process = None
            self.rpc_connected = False
            self.rpc = None
            self.log.debug("Node stopped")
            return True
    ''' not true after 60 seconds
    [node 3] Cleaning up leftover process
    
  2. MarcoFalke commented at 6:23 PM on July 29, 2019: member

    combined log:

     node3 2019-07-29T16:44:10.484477Z [http] Received a POST request for / from 127.0.0.1:37602 
     node3 2019-07-29T16:44:10.484684Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     test  2019-07-29T16:44:10.486000Z TestFramework (DEBUG): Syncing 1 new blocks... 
     node3 2019-07-29T16:44:10.487964Z [http] Received a POST request for / from 127.0.0.1:37602 
     node3 2019-07-29T16:44:10.488139Z [httpworker.3] ThreadRPCServer method=gettxoutsetinfo user=__cookie__ 
     node3 2019-07-29T16:44:10.576131Z [httpworker.3] Writing final batch of 0.63 MiB 
     node3 2019-07-29T16:44:10.635399Z [httpworker.3] Committed 12501 changed transaction outputs (out of 12501) to coin database... 
     node3 2019-07-29T16:44:11.132557Z [http] Received a POST request for / from 127.0.0.1:37602 
     node3 2019-07-29T16:44:11.132760Z [httpworker.1] ThreadRPCServer method=getblock user=__cookie__ 
     test  2019-07-29T16:44:11.358000Z TestFramework (DEBUG): Syncing blocks to node 0 
     test  2019-07-29T16:44:11.359000Z TestFramework (DEBUG): submitting block 5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 
     node0 2019-07-29T16:44:11.456209Z [http] Received a POST request for / from 127.0.0.1:59639 
     node0 2019-07-29T16:44:11.524576Z [httpworker.1] ThreadRPCServer method=submitblock user=__cookie__ 
     node0 2019-07-29T16:44:11.645630Z [httpworker.1] Pre-allocating up to position 0x4000000 in blk00000.dat 
     node0 2019-07-29T16:44:11.670324Z [httpworker.1]   - Load block from disk: 0.00ms [0.00s] 
     node0 2019-07-29T16:44:11.670464Z [httpworker.1]     - Sanity checks: 0.01ms [0.00s (0.01ms/blk)] 
     node0 2019-07-29T16:44:11.725792Z [httpworker.1]     - Fork checks: 55.27ms [0.06s (55.27ms/blk)] 
     node0 2019-07-29T16:44:11.941554Z [httpworker.1]       - Connect 2501 transactions: 215.76ms (0.086ms/tx, 0.043ms/txin) [0.22s (215.76ms/blk)] 
     node0 2019-07-29T16:44:12.531088Z [httpworker.1]     - Verify 5000 txins: 805.29ms (0.161ms/txin) [0.81s (805.29ms/blk)] 
     node0 2019-07-29T16:44:12.550954Z [httpworker.1]     - Index writing: 19.87ms [0.02s (19.87ms/blk)] 
     node0 2019-07-29T16:44:12.551014Z [httpworker.1]     - Callbacks: 0.12ms [0.00s (0.12ms/blk)] 
     node0 2019-07-29T16:44:12.553229Z [httpworker.1]   - Connect total: 882.94ms [0.88s (882.94ms/blk)] 
     node0 2019-07-29T16:44:12.572041Z [httpworker.1]   - Flush: 18.81ms [0.02s (18.81ms/blk)] 
     node0 2019-07-29T16:44:12.572158Z [httpworker.1]   - Writing chainstate: 0.18ms [0.00s (0.18ms/blk)] 
     node0 2019-07-29T16:44:12.574082Z [httpworker.1] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
     node0 2019-07-29T16:44:12.583131Z [httpworker.1] UpdateTip: new best=5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 height=2833 version=0x20000000 log2_work=12.468624 tx=85284 date='2019-07-29T16:44:04Z' progress=1.000000 cache=1.6MiB(12501txo) 
     node0 2019-07-29T16:44:12.583258Z [httpworker.1]   - Connect postprocess: 11.09ms [0.01s (11.09ms/blk)] 
     node0 2019-07-29T16:44:12.583297Z [httpworker.1] - Connect block: 913.02ms [0.91s (913.02ms/blk)] 
     node0 2019-07-29T16:44:12.583427Z [httpworker.1] Checking mempool with 0 transactions and 0 inputs 
     node0 2019-07-29T16:44:12.665974Z [httpworker.1] Writing partial batch of 0.19 MiB 
     node0 2019-07-29T16:44:12.684050Z [httpworker.1] Writing partial batch of 0.19 MiB 
     node0 2019-07-29T16:44:12.704340Z [httpworker.1] Simulating a crash. Goodbye. 
     test  2019-07-29T16:44:12.736000Z TestFramework (DEBUG): node 0 submitblock raised OSError exception: errno=111 
     test  2019-07-29T16:44:12.737000Z TestFramework (DEBUG): Restarting node 0 after block hash 5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 
     test  2019-07-29T16:44:12.738000Z TestFramework.utils (DEBUG): Deleting leftover cookie file 
     test  2019-07-29T16:44:12.790000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up 
     node0 2019-07-29T16:44:12.943234Z [init] Bitcoin Core version v0.18.99.0-fcc4025c1 (release build) 
     node0 2019-07-29T16:44:12.943274Z [init] InitParameterInteraction: parameter interaction: -bind set -> setting -listen=1 
     node0 2019-07-29T16:44:12.943420Z [init] Validating signatures for all blocks. 
     node0 2019-07-29T16:44:12.943446Z [init] Setting nMinimumChainWork=0000000000000000000000000000000000000000000000000000000000000000 
     node0 2019-07-29T16:44:12.943610Z [init] Using the 'standard' SHA256 implementation 
     node0 2019-07-29T16:44:12.999816Z [init] Default data directory /root/.bitcoin 
     node0 2019-07-29T16:44:12.999855Z [init] Using data directory /tmp/bitcoin_func_test__y0cfver/node0/regtest 
     node0 2019-07-29T16:44:12.999907Z [init] Config file: /tmp/bitcoin_func_test__y0cfver/node0/bitcoin.conf 
     node0 2019-07-29T16:44:12.999939Z [init] Using at most 125 automatic connections (1024 file descriptors available) 
     node0 2019-07-29T16:44:13.019870Z [init] Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements 
     node0 2019-07-29T16:44:13.039156Z [init] Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements 
     node0 2019-07-29T16:44:13.039248Z [init] Using 4 threads for script verification 
     node0 2019-07-29T16:44:13.039840Z [scheduler] scheduler thread start 
     node0 2019-07-29T16:44:13.040361Z [init] Allowing HTTP connections from: 127.0.0.0/8 ::1/128 
     node0 2019-07-29T16:44:13.040559Z [init] Binding RPC on address ::1 port 18367 
     node0 2019-07-29T16:44:13.040870Z [init] Binding RPC on address 127.0.0.1 port 18367 
     node0 2019-07-29T16:44:13.041009Z [init] Initialized HTTP server 
     node0 2019-07-29T16:44:13.041045Z [init] HTTP: creating work queue of depth 16 
     node0 2019-07-29T16:44:13.041074Z [init] Starting RPC 
     node0 2019-07-29T16:44:13.041120Z [init] Starting HTTP RPC server 
     node0 2019-07-29T16:44:13.041154Z [init] No rpcpassword set - using random cookie authentication. 
     node0 2019-07-29T16:44:13.041460Z [init] Generated RPC authentication cookie /tmp/bitcoin_func_test__y0cfver/node0/regtest/.cookie 
     node0 2019-07-29T16:44:13.041501Z [init] Registering HTTP handler for / (exactmatch 1) 
     node0 2019-07-29T16:44:13.041533Z [init] Registering HTTP handler for /wallet/ (exactmatch 0) 
     node0 2019-07-29T16:44:13.041572Z [init] Starting HTTP server 
     node0 2019-07-29T16:44:13.041604Z [init] HTTP: starting 4 worker threads 
     node0 2019-07-29T16:44:13.041841Z [http] Entering http event loop 
     node0 2019-07-29T16:44:13.042080Z [init] Using wallet directory /tmp/bitcoin_func_test__y0cfver/node0/regtest 
     node0 2019-07-29T16:44:13.042125Z [init] init message: Verifying wallet(s)... 
     node0 2019-07-29T16:44:13.042460Z [init] Using BerkeleyDB version Berkeley DB 5.3.28: (September  9, 2013) 
     node0 2019-07-29T16:44:13.042491Z [init] Using wallet /tmp/bitcoin_func_test__y0cfver/node0/regtest 
     node0 2019-07-29T16:44:13.043575Z [init] BerkeleyEnvironment::Open: LogDir=/tmp/bitcoin_func_test__y0cfver/node0/regtest/database ErrorFile=/tmp/bitcoin_func_test__y0cfver/node0/regtest/db.log 
     node0 2019-07-29T16:44:13.050761Z [http] Received a POST request for / from 127.0.0.1:59641 
     node0 2019-07-29T16:44:13.051055Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:13.098201Z [init] init message: Loading banlist... 
     node0 2019-07-29T16:44:13.098350Z [init] Loaded 0 banned node ips/subnets from banlist.dat  0ms 
     node0 2019-07-29T16:44:13.098911Z [init] net: setting try another outbound peer=false 
     node0 2019-07-29T16:44:13.101132Z [init] Cache configuration: 
     node0 2019-07-29T16:44:13.101264Z [init] * Using 0.5 MiB for block index database 
     node0 2019-07-29T16:44:13.101302Z [init] * Using 1.8 MiB for chain state database 
     node0 2019-07-29T16:44:13.101337Z [init] * Using 1.8 MiB for in-memory UTXO set (plus up to 0.0 MiB of unused mempool space) 
     node0 2019-07-29T16:44:13.101375Z [init] init message: Loading block index... 
     node0 2019-07-29T16:44:13.101547Z [init] Opening LevelDB in /tmp/bitcoin_func_test__y0cfver/node0/regtest/blocks/index 
     node3 2019-07-29T16:44:13.111589Z [scheduler] Flushing wallet.dat 
     node0 2019-07-29T16:44:13.115126Z [init] Opened LevelDB successfully 
     node0 2019-07-29T16:44:13.115237Z [init] Using obfuscation key for /tmp/bitcoin_func_test__y0cfver/node0/regtest/blocks/index: 0000000000000000 
     node0 2019-07-29T16:44:13.161961Z [init] LoadBlockIndexDB: last block file = 0 
     node0 2019-07-29T16:44:13.162072Z [init] LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=2847, size=51405393, heights=0...2833, time=2011-02-02...2019-07-29) 
     node0 2019-07-29T16:44:13.162116Z [init] Checking all blk files are present... 
     node0 2019-07-29T16:44:13.163700Z [init] Opening LevelDB in /tmp/bitcoin_func_test__y0cfver/node0/regtest/chainstate 
     node0 2019-07-29T16:44:13.263453Z [init] Opened LevelDB successfully 
     node0 2019-07-29T16:44:13.263953Z [init] Using obfuscation key for /tmp/bitcoin_func_test__y0cfver/node0/regtest/chainstate: ae1d26d319a5112e 
     node0 2019-07-29T16:44:13.264105Z [init] Replaying blocks 
     node0 2019-07-29T16:44:13.264145Z [init] Rolling forward 5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 (2833) 
     node0 2019-07-29T16:44:13.307966Z [http] Received a POST request for / from 127.0.0.1:59642 
     node0 2019-07-29T16:44:13.308182Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:13.563882Z [http] Received a POST request for / from 127.0.0.1:59643 
     node0 2019-07-29T16:44:13.564130Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:13.622827Z [init] Writing partial batch of 0.19 MiB 
     node0 2019-07-29T16:44:13.641779Z [init] Writing partial batch of 0.19 MiB 
     node0 2019-07-29T16:44:13.664669Z [init] Writing final batch of 0.17 MiB 
     node0 2019-07-29T16:44:13.676477Z [init] Committed 10341 changed transaction outputs (out of 10341) to coin database... 
     node0 2019-07-29T16:44:13.679261Z [init] Loaded best chain: hashBestChain=5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 height=2833 date=2019-07-29T16:44:04Z progress=1.000000 
     node0 2019-07-29T16:44:13.679350Z [init] init message: Rewinding blocks... 
     node0 2019-07-29T16:44:13.703548Z [init] Writing final batch of 0.00 MiB 
     node0 2019-07-29T16:44:13.703654Z [init] Committed 0 changed transaction outputs (out of 0) to coin database... 
     node0 2019-07-29T16:44:13.703851Z [init] init message: Verifying blocks... 
     node0 2019-07-29T16:44:13.703955Z [init] Verifying last 6 blocks at level 3 
     node0 2019-07-29T16:44:13.704021Z [init] [0%]...Received a POST request for / from 127.0.0.1:59644 
     node0 2019-07-29T16:44:13.820226Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:14.071239Z [init] [16%]...Received a POST request for / from 127.0.0.1:59645 
     node0 2019-07-29T16:44:14.077145Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:14.333307Z [http] Received a POST request for / from 127.0.0.1:59646 
     node0 2019-07-29T16:44:14.333495Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:14.488034Z [init] [33%]...Received a POST request for / from 127.0.0.1:59647 
     node0 2019-07-29T16:44:14.589833Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:14.591316Z [init] [50%]...[66%]...Received a POST request for / from 127.0.0.1:59648 
     node0 2019-07-29T16:44:14.846247Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:15.102195Z [http] Received a POST request for / from 127.0.0.1:59649 
     node0 2019-07-29T16:44:15.102392Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:15.245347Z [init] [83%]...Received a POST request for / from 127.0.0.1:59650 
     node0 2019-07-29T16:44:15.357988Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:15.361879Z [init] [99%]...[DONE]. 
     node0 2019-07-29T16:44:15.361999Z [init] No coin database inconsistencies in last 6 blocks (5002 transactions) 
     node0 2019-07-29T16:44:15.388168Z [init]  block index            2287ms 
     node0 2019-07-29T16:44:15.388389Z [init] init message: Loading wallet... 
     node0 2019-07-29T16:44:15.388790Z [init] BerkeleyEnvironment::Open: LogDir=/tmp/bitcoin_func_test__y0cfver/node0/regtest/database ErrorFile=/tmp/bitcoin_func_test__y0cfver/node0/regtest/db.log 
     node0 2019-07-29T16:44:15.397179Z [init] [default wallet] nFileVersion = 189900 
     node0 2019-07-29T16:44:15.397263Z [init] [default wallet] Keys: 4 plaintext, 0 encrypted, 4 w/ metadata, 4 total. Unknown wallet records: 0 
     node0 2019-07-29T16:44:15.438921Z [init] [default wallet] Wallet completed loading in              50ms 
     node0 2019-07-29T16:44:15.439273Z [init] init message: Rescanning... 
     node0 2019-07-29T16:44:15.439323Z [init] [default wallet] Rescanning last 1 blocks (from block 2832)... 
     node0 2019-07-29T16:44:15.439374Z [init] [default wallet] Rescan started from block 69924f3a2ff7f3e360aeb515e05c52d67d2ceef5702693f9b4917c0122750cd3... 
     node0 2019-07-29T16:44:15.604332Z [init] [default wallet] Rescan completed in             165ms 
     node0 2019-07-29T16:44:15.613847Z [http] Received a POST request for / from 127.0.0.1:59651 
     node0 2019-07-29T16:44:15.614031Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:15.869561Z [http] Received a POST request for / from 127.0.0.1:59652 
     node0 2019-07-29T16:44:15.869746Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:16.125219Z [http] Received a POST request for / from 127.0.0.1:59653 
     node0 2019-07-29T16:44:16.125404Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:16.380669Z [http] Received a POST request for / from 127.0.0.1:59654 
     node0 2019-07-29T16:44:16.380852Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:16.636050Z [http] Received a POST request for / from 127.0.0.1:59655 
     node0 2019-07-29T16:44:16.636232Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:16.891437Z [http] Received a POST request for / from 127.0.0.1:59656 
     node0 2019-07-29T16:44:16.891619Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:17.146818Z [http] Received a POST request for / from 127.0.0.1:59657 
     node0 2019-07-29T16:44:17.147001Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:17.402427Z [http] Received a POST request for / from 127.0.0.1:59658 
     node0 2019-07-29T16:44:17.402607Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:17.657797Z [http] Received a POST request for / from 127.0.0.1:59659 
     node0 2019-07-29T16:44:17.657979Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:17.913287Z [http] Received a POST request for / from 127.0.0.1:59660 
     node0 2019-07-29T16:44:17.913469Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:18.168744Z [http] Received a POST request for / from 127.0.0.1:59661 
     node0 2019-07-29T16:44:18.168932Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:18.424165Z [http] Received a POST request for / from 127.0.0.1:59662 
     node0 2019-07-29T16:44:18.424350Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:18.679678Z [http] Received a POST request for / from 127.0.0.1:59663 
     node0 2019-07-29T16:44:18.679863Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:18.935478Z [http] Received a POST request for / from 127.0.0.1:59664 
     node0 2019-07-29T16:44:18.935662Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:19.191270Z [http] Received a POST request for / from 127.0.0.1:59665 
     node0 2019-07-29T16:44:19.191453Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:19.446972Z [http] Received a POST request for / from 127.0.0.1:59666 
     node0 2019-07-29T16:44:19.447155Z [httpworker.1] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:19.702771Z [http] Received a POST request for / from 127.0.0.1:59667 
     node0 2019-07-29T16:44:19.702957Z [httpworker.2] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:19.958668Z [http] Received a POST request for / from 127.0.0.1:59668 
     node0 2019-07-29T16:44:19.958857Z [httpworker.3] ThreadRPCServer method=getblockcount user=__cookie__ 
     node0 2019-07-29T16:44:20.004391Z [init] [default wallet] setKeyPool.size() = 2 
     node0 2019-07-29T16:44:20.004510Z [init] [default wallet] mapWallet.size() = 50 
     node0 2019-07-29T16:44:20.004544Z [init] [default wallet] mapAddressBook.size() = 3 
     node0 2019-07-29T16:44:20.004755Z [init] block tree size = 2847 
     node0 2019-07-29T16:44:20.004864Z [init] nBestHeight = 2833 
     node0 2019-07-29T16:44:20.004995Z [loadblk] Failed to open mempool file from disk. Continuing anyway. 
     node0 2019-07-29T16:44:20.005317Z [init] Bound to 127.0.0.1:13367 
     node0 2019-07-29T16:44:20.005389Z [init] init message: Loading P2P addresses... 
     node0 2019-07-29T16:44:20.015339Z [init] Loaded 0 addresses from peers.dat  10ms 
     node0 2019-07-29T16:44:20.015453Z [init] init message: Starting network threads... 
     node0 2019-07-29T16:44:20.015653Z [net] net thread start 
     node0 2019-07-29T16:44:20.015896Z [dnsseed] dnsseed thread start 
     node0 2019-07-29T16:44:20.015943Z [dnsseed] Loading addresses from DNS seeds (could take a while) 
     node0 2019-07-29T16:44:20.016070Z [dnsseed] 0 addresses found from DNS seeds 
     node0 2019-07-29T16:44:20.016104Z [dnsseed] dnsseed thread exit 
     node0 2019-07-29T16:44:20.016137Z [addcon] addcon thread start 
     node0 2019-07-29T16:44:20.016199Z [opencon] opencon thread start 
     node0 2019-07-29T16:44:20.016235Z [init] init message: Done loading 
     node0 2019-07-29T16:44:20.016297Z [msghand] msghand thread start 
     node0 2019-07-29T16:44:20.214869Z [http] Received a POST request for / from 127.0.0.1:59669 
     node0 2019-07-29T16:44:20.215043Z [httpworker.0] ThreadRPCServer method=getblockcount user=__cookie__ 
     test  2019-07-29T16:44:20.217000Z TestFramework.node0 (DEBUG): RPC successfully started 
     node0 2019-07-29T16:44:20.219410Z [http] Received a POST request for / from 127.0.0.1:59669 
     node0 2019-07-29T16:44:20.219583Z [httpworker.1] ThreadRPCServer method=waitforblock user=__cookie__ 
     node0 2019-07-29T16:44:20.223240Z [http] Received a POST request for / from 127.0.0.1:59669 
     node0 2019-07-29T16:44:20.223480Z [httpworker.2] ThreadRPCServer method=gettxoutsetinfo user=__cookie__ 
     node0 2019-07-29T16:44:20.238135Z [httpworker.2] Writing final batch of 0.00 MiB 
     node0 2019-07-29T16:44:20.238266Z [httpworker.2] Committed 0 changed transaction outputs (out of 0) to coin database... 
     test  2019-07-29T16:44:20.723000Z TestFramework (DEBUG): Checking txoutsetinfo matches for node 0 
     test  2019-07-29T16:44:20.723000Z TestFramework (DEBUG): Syncing blocks to node 1 
     test  2019-07-29T16:44:20.724000Z TestFramework (DEBUG): submitting block 5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 
     node1 2019-07-29T16:44:20.821030Z [http] Received a POST request for / from 127.0.0.1:51712 
     node1 2019-07-29T16:44:20.878039Z [httpworker.3] ThreadRPCServer method=submitblock user=__cookie__ 
     node0 2019-07-29T16:44:21.016601Z [scheduler] Leaving InitialBlockDownload (latching to false) 
     node3 2019-07-29T16:44:21.403647Z [scheduler] Flushed wallet.dat 8292ms 
     node1 2019-07-29T16:44:21.404914Z [httpworker.3] Pre-allocating up to position 0x4000000 in blk00000.dat 
     node1 2019-07-29T16:44:21.429691Z [httpworker.3]   - Load block from disk: 0.01ms [0.00s] 
     node1 2019-07-29T16:44:21.429825Z [httpworker.3]     - Sanity checks: 0.01ms [0.00s (0.01ms/blk)] 
     node1 2019-07-29T16:44:21.490009Z [httpworker.3]     - Fork checks: 60.13ms [1.05s (95.25ms/blk)] 
     node1 2019-07-29T16:44:21.696990Z [httpworker.3]       - Connect 2501 transactions: 206.98ms (0.083ms/tx, 0.041ms/txin) [3.02s (274.66ms/blk)] 
     node0 2019-07-29T16:44:22.017010Z [scheduler] Flushing wallet.dat 
     node0 2019-07-29T16:44:22.032814Z [scheduler] Flushed wallet.dat 15ms 
     node1 2019-07-29T16:44:22.266936Z [httpworker.3]     - Verify 5000 txins: 776.92ms (0.155ms/txin) [9.34s (849.54ms/blk)] 
     node1 2019-07-29T16:44:22.290078Z [httpworker.3]     - Index writing: 23.15ms [7.27s (661.27ms/blk)] 
     node1 2019-07-29T16:44:22.290142Z [httpworker.3]     - Callbacks: 0.13ms [0.00s (0.12ms/blk)] 
     node1 2019-07-29T16:44:22.291522Z [httpworker.3]   - Connect total: 861.88ms [17.69s (1608.01ms/blk)] 
     node1 2019-07-29T16:44:22.310541Z [httpworker.3]   - Flush: 18.98ms [0.20s (18.46ms/blk)] 
     node1 2019-07-29T16:44:22.310654Z [httpworker.3]   - Writing chainstate: 0.18ms [9.16s (832.62ms/blk)] 
     node1 2019-07-29T16:44:22.312546Z [httpworker.3] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
     node1 2019-07-29T16:44:22.314978Z [httpworker.3] UpdateTip: new best=5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 height=2833 version=0x20000000 log2_work=12.468624 tx=85284 date='2019-07-29T16:44:04Z' progress=1.000000 cache=3.3MiB(24116txo) 
     node1 2019-07-29T16:44:22.315052Z [httpworker.3]   - Connect postprocess: 4.40ms [0.06s (5.24ms/blk)] 
     node1 2019-07-29T16:44:22.315091Z [httpworker.3] - Connect block: 885.44ms [27.11s (2464.33ms/blk)] 
     node1 2019-07-29T16:44:22.315159Z [httpworker.3] Checking mempool with 0 transactions and 0 inputs 
     node1 2019-07-29T16:44:22.398010Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.420337Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.444770Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.474779Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.505724Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.526099Z [httpworker.3] Writing partial batch of 0.19 MiB 
     node1 2019-07-29T16:44:22.555181Z [httpworker.3] Writing final batch of 0.07 MiB 
     node1 2019-07-29T16:44:22.560749Z [httpworker.3] Committed 24116 changed transaction outputs (out of 24116) to coin database... 
     test  2019-07-29T16:44:22.562000Z TestFramework (DEBUG): Syncing blocks to node 2 
     test  2019-07-29T16:44:22.563000Z TestFramework (DEBUG): submitting block 5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 
     node2 2019-07-29T16:44:22.653507Z [http] Received a POST request for / from 127.0.0.1:56713 
     node2 2019-07-29T16:44:22.723905Z [httpworker.1] ThreadRPCServer method=submitblock user=__cookie__ 
     node2 2019-07-29T16:44:22.857646Z [httpworker.1] Pre-allocating up to position 0x4000000 in blk00000.dat 
     node2 2019-07-29T16:44:22.884305Z [httpworker.1]   - Load block from disk: 0.00ms [1.02s] 
     node2 2019-07-29T16:44:22.884444Z [httpworker.1]     - Sanity checks: 0.01ms [0.26s (0.10ms/blk)] 
     node2 2019-07-29T16:44:22.957000Z [httpworker.1]     - Fork checks: 72.50ms [2.85s (1.08ms/blk)] 
     node2 2019-07-29T16:44:23.180708Z [httpworker.1]       - Connect 2501 transactions: 223.71ms (0.089ms/tx, 0.045ms/txin) [5.76s (2.18ms/blk)] 
     node2 2019-07-29T16:44:23.731937Z [httpworker.1]     - Verify 5000 txins: 774.93ms (0.155ms/txin) [34.89s (13.18ms/blk)] 
     node2 2019-07-29T16:44:23.755322Z [httpworker.1]     - Index writing: 23.39ms [1.42s (0.54ms/blk)] 
     node2 2019-07-29T16:44:23.755384Z [httpworker.1]     - Callbacks: 0.13ms [0.12s (0.04ms/blk)] 
     node2 2019-07-29T16:44:23.756776Z [httpworker.1]   - Connect total: 872.53ms [40.14s (15.17ms/blk)] 
     node2 2019-07-29T16:44:23.775149Z [httpworker.1]   - Flush: 18.32ms [1.10s (0.41ms/blk)] 
     node2 2019-07-29T16:44:23.775268Z [httpworker.1]   - Writing chainstate: 0.20ms [3.78s (1.43ms/blk)] 
     node2 2019-07-29T16:44:23.777116Z [httpworker.1] Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current 
     node2 2019-07-29T16:44:23.779700Z [httpworker.1] UpdateTip: new best=5e2275692876439bb72f71f650b62e58d74c53a844e81d7380c39b79d1288145 height=2833 version=0x20000000 log2_work=12.468624 tx=85284 date='2019-07-29T16:44:04Z' progress=1.000000 cache=3.8MiB(24116txo) 
     node2 2019-07-29T16:44:23.779781Z [httpworker.1]   - Connect postprocess: 4.51ms [3.57s (1.35ms/blk)] 
     node2 2019-07-29T16:44:23.779826Z [httpworker.1] - Connect block: 895.56ms [49.61s (18.74ms/blk)] 
     node2 2019-07-29T16:44:23.779896Z [httpworker.1] Checking mempool with 0 transactions and 0 inputs 
     node3 2019-07-29T16:44:23.791698Z [http] Received a POST request for / from 127.0.0.1:37602 
     node3 2019-07-29T16:44:23.791912Z [httpworker.0] ThreadRPCServer method=listunspent user=__cookie__ 
     node1 2019-07-29T16:44:24.154147Z [scheduler] Flushing wallet.dat 
     node1 2019-07-29T16:44:24.163054Z [scheduler] Flushed wallet.dat 9ms 
     node0 2019-07-29T16:45:21.026258Z [opencon] Adding fixed seed nodes as DNS doesn't seem to be available. 
     test  2019-07-29T16:45:53.858000Z TestFramework (ERROR): JSONRPC error 
                                       Traceback (most recent call last):
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 163, in _get_response
                                           http_response = self.__conn.getresponse()
                                         File "/usr/lib/python3.6/http/client.py", line 1331, in getresponse
                                           response.begin()
                                         File "/usr/lib/python3.6/http/client.py", line 297, in begin
                                           version, status, reason = self._read_status()
                                         File "/usr/lib/python3.6/http/client.py", line 258, in _read_status
                                           line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
                                         File "/usr/lib/python3.6/socket.py", line 586, in readinto
                                           return self._sock.recv_into(b)
                                       socket.timeout: timed out
                                       During handling of the above exception, another exception occurred:
                                       Traceback (most recent call last):
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/test_framework.py", line 193, in main
                                           self.run_test()
                                         File "./test/functional/feature_dbcrash.py", line 250, in run_test
                                           utxo_list = self.nodes[3].listunspent()
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/coverage.py", line 47, in __call__
                                           return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 139, in __call__
                                           response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 107, in _request
                                           return self._get_response()
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 170, in _get_response
                                           self.__conn.timeout)})
                                       test_framework.authproxy.JSONRPCException: 'listunspent' RPC took longer than 90.000000 seconds. Consider using larger timeout for calls that take longer to return. (-344)
     test  2019-07-29T16:45:53.917000Z TestFramework (DEBUG): Closing down network thread 
     test  2019-07-29T16:45:54.033000Z TestFramework (INFO): Stopping nodes 
     test  2019-07-29T16:45:54.037000Z TestFramework.node0 (DEBUG): Stopping node 
     node0 2019-07-29T16:45:54.040039Z [http] Received a POST request for / from 127.0.0.1:59669 
     node0 2019-07-29T16:45:54.040258Z [httpworker.3] ThreadRPCServer method=stop user=__cookie__ 
     test  2019-07-29T16:45:54.042000Z TestFramework.node1 (DEBUG): Stopping node 
     node1 2019-07-29T16:45:54.044646Z [http] Received a POST request for / from 127.0.0.1:51712 
     node1 2019-07-29T16:45:54.044877Z [httpworker.0] ThreadRPCServer method=stop user=__cookie__ 
     test  2019-07-29T16:45:54.047000Z TestFramework.node2 (DEBUG): Stopping node 
     node0 2019-07-29T16:45:54.049238Z [init] Interrupting HTTP server 
     node2 2019-07-29T16:45:54.049377Z [http] Received a POST request for / from 127.0.0.1:56713 
     node0 2019-07-29T16:45:54.049381Z [init] Interrupting HTTP RPC server 
     node0 2019-07-29T16:45:54.049415Z [init] Interrupting RPC 
     node0 2019-07-29T16:45:54.049502Z [opencon] opencon thread exit 
     node2 2019-07-29T16:45:54.049585Z [httpworker.3] ThreadRPCServer method=stop user=__cookie__ 
     node0 2019-07-29T16:45:54.049684Z [addcon] addcon thread exit 
     node0 2019-07-29T16:45:54.054453Z [init] Shutdown: In progress... 
     node0 2019-07-29T16:45:54.054563Z [shutoff] Stopping HTTP RPC server 
     node0 2019-07-29T16:45:54.054598Z [shutoff] Unregistering HTTP handler for / (exactmatch 1) 
     node0 2019-07-29T16:45:54.054630Z [shutoff] Unregistering HTTP handler for /wallet/ (exactmatch 0) 
     node0 2019-07-29T16:45:54.054663Z [shutoff] Stopping RPC 
     node0 2019-07-29T16:45:54.054920Z [shutoff] RPC stopped. 
     node0 2019-07-29T16:45:54.054953Z [shutoff] Stopping HTTP server 
     node0 2019-07-29T16:45:54.054980Z [shutoff] Waiting for HTTP worker threads to exit 
     node0 2019-07-29T16:45:54.055220Z [shutoff] Waiting for HTTP event thread to exit 
     node0 2019-07-29T16:45:54.055303Z [http] Exited http event loop 
     node0 2019-07-29T16:45:54.055600Z [shutoff] Stopped HTTP server 
     node0 2019-07-29T16:45:54.055662Z [shutoff] BerkeleyEnvironment::Flush: [/tmp/bitcoin_func_test__y0cfver/node0/regtest] Flush(false) 
     node0 2019-07-29T16:45:54.055697Z [shutoff] BerkeleyEnvironment::Flush: Flush(false) took               0ms 
     test  2019-07-29T16:45:54.059000Z TestFramework.node3 (DEBUG): Stopping node 
     test  2019-07-29T16:45:54.060000Z TestFramework.node3 (ERROR): Unable to stop node. 
                                       Traceback (most recent call last):
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/test_node.py", line 264, in stop_node
                                           self.stop(wait=wait)
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/coverage.py", line 47, in __call__
                                           return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 139, in __call__
                                           response, status = self._request('POST', self.__url.path, postdata.encode('utf-8'))
                                         File "/root/workspace/bitcoin-core/test/functional/test_framework/authproxy.py", line 106, in _request
                                           self.__conn.request(method, path, postdata, headers)
                                         File "/usr/lib/python3.6/http/client.py", line 1239, in request
                                           self._send_request(method, url, body, headers, encode_chunked)
                                         File "/usr/lib/python3.6/http/client.py", line 1250, in _send_request
                                           self.putrequest(method, url, **skips)
                                         File "/usr/lib/python3.6/http/client.py", line 1108, in putrequest
                                           raise CannotSendRequest(self.__state)
                                       http.client.CannotSendRequest: Request-sent
     node1 2019-07-29T16:45:54.065371Z [init] Interrupting HTTP server 
     node1 2019-07-29T16:45:54.065549Z [init] Interrupting HTTP RPC server 
     node1 2019-07-29T16:45:54.065591Z [init] Interrupting RPC 
     node1 2019-07-29T16:45:54.065701Z [addcon] addcon thread exit 
     node1 2019-07-29T16:45:54.068716Z [opencon] opencon thread exit 
     node0 2019-07-29T16:45:54.068798Z [net] net thread exit 
     node1 2019-07-29T16:45:54.068933Z [init] Shutdown: In progress... 
     node1 2019-07-29T16:45:54.069018Z [shutoff] Stopping HTTP RPC server 
     node1 2019-07-29T16:45:54.069053Z [shutoff] Unregistering HTTP handler for / (exactmatch 1) 
     node1 2019-07-29T16:45:54.069097Z [shutoff] Unregistering HTTP handler for /wallet/ (exactmatch 0) 
     node1 2019-07-29T16:45:54.069139Z [shutoff] Stopping RPC 
     node1 2019-07-29T16:45:54.070796Z [shutoff] RPC stopped. 
     node1 2019-07-29T16:45:54.070880Z [shutoff] Stopping HTTP server 
     node1 2019-07-29T16:45:54.070908Z [shutoff] Waiting for HTTP worker threads to exit 
     node0 2019-07-29T16:45:54.086417Z [msghand] msghand thread exit 
     node0 2019-07-29T16:45:54.096788Z [shutoff] Flushed 0 addresses to peers.dat  10ms 
     node1 2019-07-29T16:45:54.100172Z [http] Exited http event loop 
     node1 2019-07-29T16:45:54.100377Z [shutoff] Waiting for HTTP event thread to exit 
     node1 2019-07-29T16:45:54.100606Z [shutoff] Stopped HTTP server 
     node1 2019-07-29T16:45:54.100682Z [shutoff] BerkeleyEnvironment::Flush: [/tmp/bitcoin_func_test__y0cfver/node1/regtest] Flush(false) 
     node1 2019-07-29T16:45:54.100754Z [shutoff] BerkeleyEnvironment::Flush: Flush(false) took               0ms 
     node1 2019-07-29T16:45:54.103161Z [net] net thread exit 
     node0 2019-07-29T16:45:54.103977Z [scheduler] scheduler thread interrupt 
     node0 2019-07-29T16:45:54.113681Z [shutoff] Dumped mempool: 9e-06s to copy, 0.009256s to dump 
     node0 2019-07-29T16:45:54.113769Z [shutoff] Recorded 0 unconfirmed txs from mempool in 2e-06s 
     node0 2019-07-29T16:45:54.120885Z [shutoff] Writing final batch of 0.00 MiB 
     node0 2019-07-29T16:45:54.121042Z [shutoff] Committed 0 changed transaction outputs (out of 0) to coin database... 
     node0 2019-07-29T16:45:54.128371Z [shutoff] Writing final batch of 0.00 MiB 
     node0 2019-07-29T16:45:54.128512Z [shutoff] Committed 0 changed transaction outputs (out of 0) to coin database... 
     node0 2019-07-29T16:45:54.129856Z [shutoff] BerkeleyEnvironment::Flush: [/tmp/bitcoin_func_test__y0cfver/node0/regtest] Flush(true) 
     node0 2019-07-29T16:45:54.129941Z [shutoff] BerkeleyEnvironment::Flush: Flushing wallet.dat (refcount = 0)... 
     node0 2019-07-29T16:45:54.130103Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat checkpoint 
     node0 2019-07-29T16:45:54.131715Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat detach 
     node0 2019-07-29T16:45:54.137027Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat closed 
     node0 2019-07-29T16:45:54.137127Z [shutoff] BerkeleyEnvironment::Flush: Flush(true) took               8ms 
     node1 2019-07-29T16:45:54.139901Z [msghand] msghand thread exit 
     node0 2019-07-29T16:45:54.142191Z [shutoff] [default wallet] Releasing wallet 
     node0 2019-07-29T16:45:54.143183Z [shutoff] Shutdown: done 
     node1 2019-07-29T16:45:54.146637Z [shutoff] Flushed 0 addresses to peers.dat  6ms 
     node1 2019-07-29T16:45:54.147253Z [scheduler] scheduler thread interrupt 
     node1 2019-07-29T16:45:54.154837Z [shutoff] Dumped mempool: 1.1e-05s to copy, 0.006989s to dump 
     node1 2019-07-29T16:45:54.154944Z [shutoff] Recorded 0 unconfirmed txs from mempool in 2e-06s 
     node1 2019-07-29T16:45:54.162660Z [shutoff] Writing final batch of 0.00 MiB 
     node1 2019-07-29T16:45:54.162820Z [shutoff] Committed 0 changed transaction outputs (out of 0) to coin database... 
     node1 2019-07-29T16:45:54.176319Z [shutoff] Writing final batch of 0.00 MiB 
     node1 2019-07-29T16:45:54.176462Z [shutoff] Committed 0 changed transaction outputs (out of 0) to coin database... 
     node1 2019-07-29T16:45:54.177847Z [shutoff] BerkeleyEnvironment::Flush: [/tmp/bitcoin_func_test__y0cfver/node1/regtest] Flush(true) 
     node1 2019-07-29T16:45:54.177918Z [shutoff] BerkeleyEnvironment::Flush: Flushing wallet.dat (refcount = 0)... 
     node1 2019-07-29T16:45:54.178064Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat checkpoint 
     node1 2019-07-29T16:45:54.181237Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat detach 
     node1 2019-07-29T16:45:54.189187Z [shutoff] BerkeleyEnvironment::Flush: wallet.dat closed 
     node1 2019-07-29T16:45:54.189289Z [shutoff] BerkeleyEnvironment::Flush: Flush(true) took              12ms 
     node1 2019-07-29T16:45:54.193131Z [shutoff] [default wallet] Releasing wallet 
     node1 2019-07-29T16:45:54.194273Z [shutoff] Shutdown: done 
     test  2019-07-29T16:45:54.223000Z TestFramework.node0 (DEBUG): Node stopped 
     node2 2019-07-29T16:45:54.252504Z [init] Interrupting HTTP server 
     node2 2019-07-29T16:45:54.253259Z [init] Interrupting HTTP RPC server 
     node2 2019-07-29T16:45:54.253299Z [init] Interrupting RPC 
     node2 2019-07-29T16:45:54.253424Z [init] Shutdown: In progress... 
     node2 2019-07-29T16:45:54.253488Z [shutoff] Stopping HTTP RPC server 
     node2 2019-07-29T16:45:54.253523Z [shutoff] Unregistering HTTP handler for / (exactmatch 1) 
     node2 2019-07-29T16:45:54.253556Z [shutoff] Unregistering HTTP handler for /wallet/ (exactmatch 0) 
     node2 2019-07-29T16:45:54.253599Z [shutoff] Stopping RPC 
     node2 2019-07-29T16:45:54.255136Z [net] net thread exit 
     node2 2019-07-29T16:45:54.258888Z [opencon] opencon thread exit 
     node2 2019-07-29T16:45:54.259161Z [shutoff] RPC stopped. 
     node2 2019-07-29T16:45:54.259218Z [shutoff] Stopping HTTP server 
     node2 2019-07-29T16:45:54.259338Z [shutoff] Waiting for HTTP worker threads to exit 
     node2 2019-07-29T16:45:54.261623Z [addcon] addcon thread exit 
     node2 2019-07-29T16:45:54.268113Z [shutoff] Waiting for HTTP event thread to exit 
     node2 2019-07-29T16:45:54.268203Z [http] Exited http event loop 
     node2 2019-07-29T16:45:54.268514Z [shutoff] Stopped HTTP server 
     node2 2019-07-29T16:45:54.270386Z [shutoff] BerkeleyEnvironment::Flush: [/tmp/bitcoin_func_test__y0cfver/node2/regtest] Flush(false) 
     node2 2019-07-29T16:45:54.270482Z [shutoff] BerkeleyEnvironment::Flush: Flush(false) took               1ms 
     node2 2019-07-29T16:45:54.272283Z [msghand] msghand thread exit 
     test  2019-07-29T16:45:54.274000Z TestFramework.node1 (DEBUG): Node stopped 
     node2 2019-07-29T16:45:54.278992Z [shutoff] Flushed 0 addresses to peers.dat  5ms 
     node2 2019-07-29T16:45:54.281240Z [scheduler] scheduler thread interrupt 
     node2 2019-07-29T16:45:54.291485Z [shutoff] Dumped mempool: 1.2e-05s to copy, 0.009057s to dump 
     node2 2019-07-29T16:45:54.291595Z [shutoff] Recorded 0 unconfirmed txs from mempool in 1e-06s 
     node2 2019-07-29T16:45:54.320786Z [shutoff] Writing partial batch of 0.19 MiB 
     node2 2019-07-29T16:45:54.349409Z [shutoff] Writing partial batch of 0.19 MiB 
     node2 2019-07-29T16:45:54.375721Z [shutoff] Writing partial batch of 0.19 MiB 
     node2 2019-07-29T16:45:54.401969Z [shutoff] Writing partial batch of 0.19 MiB 
     node2 2019-07-29T16:45:54.427052Z [shutoff] Writing partial batch of 0.19 MiB 
     node2 2019-07-29T16:45:54.446145Z [shutoff] Simulating a crash. Goodbye. 
     test  2019-07-29T16:45:54.579000Z TestFramework.node2 (DEBUG): Node stopped 
     test  2019-07-29T16:46:55.268000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: '''' 
                                           def is_node_stopped(self):
                                               """Checks whether the node has stopped.
                                               Returns True if the node has stopped. False otherwise.
                                               This method is responsible for freeing resources (self.process)."""
                                               if not self.running:
                                                   return True
                                               return_code = self.process.poll()
                                               if return_code is None:
                                                   return False
                                               # process has stopped. Assert that it didn't return an error code.
                                               assert return_code == 0, self._node_msg(
                                                   "Node returned non-zero exit code (%d) when stopping" % return_code)
                                               self.running = False
                                               self.process = None
                                               self.rpc_connected = False
                                               self.rpc = None
                                               self.log.debug("Node stopped")
                                               return True
                                       '''
    
  3. MarcoFalke commented at 6:27 PM on July 29, 2019: member

    Probably:

    • listunspent is really slow #10492
  4. jonatack commented at 8:54 PM on July 29, 2019: member

    Huh, feature_dbcrash is passing for me (linux debian). Running a few more times...

  5. MarcoFalke commented at 9:07 PM on July 29, 2019: member

    It might only happen on slow CPU

  6. jonatack commented at 9:35 PM on July 29, 2019: member

    Could be. I've been running the extended tests every 1 or 2 days since March on an i7-6500U CPU @ 2.50GHz × 4, which I thought was a couple of CPU generations behind, and don't recall any issues with that test. Ran it twice more just now. Feature pruning was the flakey one for me sometimes.

  7. MarcoFalke renamed this:
    test: feature_dbcrash fails
    test: feature_dbcrash listunspent times out
    on Jul 30, 2019
  8. fanquake added the label Tests on Jul 30, 2019
  9. jonatack commented at 12:35 PM on July 31, 2019: member

    Dug up a MacBook Pro from 2012... will run the extended tests with it this weekend.

  10. MarcoFalke commented at 12:47 PM on July 31, 2019: member

    I am running the tests on a 1.5GHz ARM 64bit Cortex-A53 Quad-core CPU :sweat_smile:

  11. MarcoFalke referenced this in commit 9f54e9ab90 on Aug 2, 2019
  12. MarcoFalke closed this on Aug 2, 2019

  13. sidhujag referenced this in commit d7a6e39e99 on Aug 3, 2019
  14. MarcoFalke locked this on Dec 16, 2021

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-17 06:14 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me