stacks-network / stacks-core

The Stacks blockchain implementation
https://docs.stacks.co
GNU General Public License v3.0
3.01k stars 664 forks source link

regtest mock insight api requires authentication #627

Closed larrysalibra closed 6 years ago

larrysalibra commented 6 years ago

The current mock implementation of the regtest insight api requires authentication while our production api doesn't require authentication.

Behavior should be the same.

larrysalibra commented 6 years ago

My attempted fixes for this issue and #626 broke some integration tests and make it so that regtest won't start up:

[2017-10-02 00:42:56,981] [DEBUG] [blockstackd:305] (51716.123145581555712) Inbound RPC begin rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
[2017-10-02 00:42:56,982] [DEBUG] [namedb:91] (51716.123145581555712) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 00:42:56,982] [DEBUG] [indexer:175] (51716.123145581555712) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 00:42:56,982] [DEBUG] [indexer:210] (51716.123145581555712) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 00:42:56,982] [DEBUG] [indexer:213] (51716.123145581555712) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 00:42:56,990] [DEBUG] [blockstackd:315] (51716.123145581555712) Inbound RPC end rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
127.0.0.1 - - [02/Oct/2017 00:42:56] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 00:42:58,023] [DEBUG] [actions:1546] (51716.140736228193088) RPC error: register failed.
Failed operation sanity checks:
Operation sanity checks failed:

  * Failed to get name cost
  * Some fee-query tasks failed: preorder_tx_fee (Failed to get name cost)
{
    "error": "register failed.\nFailed operation sanity checks:\nOperation sanity checks failed:\n\n  * Failed to get name cost\n  * Some fee-query tasks failed: preorder_tx_fee (Failed to get name cost)"
}
[2017-10-02 00:42:58,023] [ERROR] [blockstack-test-scenario:743] (51716.140736228193088) Scenario exits in error
[2017-10-02 00:42:58,023] [ERROR] [blockstack-test-scenario:744] (51716.140736228193088) Failed to run tests 'blockstack_integration_tests.scenarios.portal_test_env'
[2017-10-02 00:42:58,023] [INFO] [blockstack-test-scenario:671] (51716.140736228193088) Shutting down network
[2017-10-02 00:42:58,023] [DEBUG] [blockstackd:2037] (51716.140736228193088) Shutting down RPC
[2017-10-02 00:42:58,023] [WARNING] [blockstackd:1709] (51716.140736228193088) Failed to shut down server socket
[2017-10-02 00:42:58,493] [DEBUG] [blockstackd:2040] (51716.140736228193088) RPC joined
[2017-10-02 00:42:58,493] [DEBUG] [blockstackd:2072] (51716.140736228193088) Shutting down GC thread
[2017-10-02 00:42:59,077] [DEBUG] [blockstackd:2075] (51716.140736228193088) GC thread joined
[2017-10-02 00:42:59,078] [INFO] [blockstack-test-scenario:674] (51716.140736228193088) Shutting down atlas
[2017-10-02 00:42:59,078] [DEBUG] [atlas:3560] (51716.140736228193088) Stopping Atlas component 'health_checker'
[2017-10-02 00:42:59,164] [DEBUG] [atlas:3560] (51716.140736228193088) Stopping Atlas component 'peer_crawler'
[2017-10-02 00:42:59,237] [DEBUG] [atlas:3560] (51716.140736228193088) Stopping Atlas component 'zonefile_crawler'
[2017-10-02 00:43:00,107] [INFO] [blockstack-test-scenario:677] (51716.140736228193088) Shutting down storage
[2017-10-02 00:43:00,107] [DEBUG] [blockstackd:2098] (51716.140736228193088) Draining storage pusher queue
[2017-10-02 00:43:00,107] [DEBUG] [blockstackd:2101] (51716.140736228193088) Shutting down storage pusher
[2017-10-02 00:43:00,107] [DEBUG] [blockstackd:2005] (51716.140736228193088) StoragePusher signal stop
[2017-10-02 00:43:00,319] [DEBUG] [blockstackd:1999] (51716.123145585762304) StoragePusher thread exit
[2017-10-02 00:43:00,319] [DEBUG] [blockstackd:2104] (51716.140736228193088) Storage pusher joined
[2017-10-02 00:43:00,320] [INFO] [blockstack-test-scenario:680] (51716.140736228193088) Shutting down bitcoin
Bitcoin server stopping
[2017-10-02 00:43:00,363] [INFO] [blockstack-test-scenario:683] (51716.140736228193088) Shutting down API endpoint
Sending SIGTERM to 51735
Exception in thread Thread-7:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 810, in __bootstrap_inner
    self.run()
  File "blockstack-venv/bin/blockstack-test-scenario", line 162, in run
    bitcoind.ping()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/virtualchain/lib/blockchain/bitcoin_blockchain/authproxy.py", line 143, in __call__
    response = self._get_response()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/virtualchain/lib/blockchain/bitcoin_blockchain/authproxy.py", line 193, in _get_response
    'code': -342, 'message': 'non-JSON HTTP response with \'%i %s\' from server' % (http_response.status, http_response.reason)})
JSONRPCException: -342: non-JSON HTTP response with '503 Service Unavailable' from server

Sending SIGKILL to 51735
[2017-10-02 00:43:03,370] [INFO] [blockstack-test-scenario:687] (51716.140736228193088) Shutting down pinger
FAILURE blockstack_integration_tests.scenarios.portal_test_env
Test output in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env
./start_regtest.sh: line 5: 51716 Abort trap: 6           BLOCKSTACK_TEST_CLIENT_RPC_PORT=6270 blockstack-venv/bin/blockstack-test-scenario --interactive 2 blockstack_integration_tests.scenarios.portal_test_env
Vanquish:develop larry$ 
kantai commented 6 years ago

That is a strange error, it could possibly be a concurrency bug in the test run (if the id namespace hasn't finished setting up yet, you'd see that error.)

Running it again may solve that problem --

Otherwise, I just committed an error-checking path to the mock insight-api which responds with 400 on malformed addresses, but otherwise, your changes seem to work okay for me:

$ curl localhost:6270/insight-api/addr/mvF2KY1UbdopoomiB371epM99GTnzjSUfj/balance -v && echo
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 6270 (#0)
> GET /insight-api/addr/mvF2KY1UbdopoomiB371epM99GTnzjSUfj/balance HTTP/1.1
> Host: localhost:6270
> User-Agent: curl/7.50.1
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< Server: SimpleHTTP/0.6 Python/2.7.12
< Date: Sun, 01 Oct 2017 16:59:53 GMT
< content-type: application/json
< Access-Control-Allow-Origin: *
< 
* Closing connection 0
4993452245
$ curl -X OPTIONS localhost:6270/insight-api/addr/mvF2KY1UbdopoomiB371epM99GTnzjSUfj/balance -v && echo
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 6270 (#0)
> OPTIONS /insight-api/addr/mvF2KY1UbdopoomiB371epM99GTnzjSUfj/balance HTTP/1.1
> Host: localhost:6270
> User-Agent: curl/7.50.1
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< Server: SimpleHTTP/0.6 Python/2.7.12
< Date: Sun, 01 Oct 2017 17:04:01 GMT
< Access-Control-Allow-Origin: *
< Access-Control-Allow-Methods: GET, PUT, POST, DELETE
< Access-Control-Allow-Headers: content-type, authorization, range
< Access-Control-Expose-Headers: content-length, content-range
< Access-Control-Max-Age: 21600
< 
* Closing connection 0

And malformed addresses:

$ curl localhost:6270/insight-api/addr/2345/balance -v && echo
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 6270 (#0)
> GET /insight-api/addr/2345/balance HTTP/1.1
> Host: localhost:6270
> User-Agent: curl/7.50.1
> Accept: */*
> 
* HTTP 1.0, assume close after body
< HTTP/1.0 400 Bad Request
< Server: SimpleHTTP/0.6 Python/2.7.12
< Date: Sun, 01 Oct 2017 17:04:53 GMT
< content-type: application/json
< Access-Control-Allow-Origin: *
< 
* Closing connection 0
{"error": "Invalid address 2345"}
kantai commented 6 years ago

Oh, If you add the api_endpoint log from /tmp/blockstack-run-test.../client/api_endpoint.log, it could have additional clues

larrysalibra commented 6 years ago

Running it again may solve that problem --

weird - i've run it a bunch of times with the same result.

let me try your commit. if it fails again i'll post the api_endpoint.log too. thanks @kantai !

larrysalibra commented 6 years ago

This is from the artifact on this build: https://circleci.com/gh/blockstack/blockstack-core/742

Same problem. Appears to be a problem looking up fees?

api_endpoint.log.zip

[2017-10-02 01:15:57,453] [DEBUG] [spv:110] (51859.140736228193088) Using testnet/regtest
[2017-10-02 01:15:57,458] [DEBUG] [blockstack-test-scenario:1185] (51859.140736228193088) Interactive session; block time is 2
[2017-10-02 01:15:57,458] [DEBUG] [blockstack-test-scenario:1201] (51859.140736228193088) Remove /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env
[2017-10-02 01:15:57,469] [DEBUG] [blockstack-test-scenario:336] (51859.140736228193088) Load scenario blockstack_integration_tests.scenarios.portal_test_env
[2017-10-02 01:15:57,469] [DEBUG] [blockstack-test-scenario:343] (51859.140736228193088) Identifying scenario path
[2017-10-02 01:15:59,459] [DEBUG] [blockstack-test-scenario:355] (51859.140736228193088) Path of blockstack_integration_tests.scenarios.portal_test_env is /Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack_integration_tests/scenarios/portal_test_env.py
TEST ACTIVE: TX_MIN_CONFIRMATIONS = 0
TEST ACTIVE: FIRST_BLOCK_MAINNET = 256
TEST ACTIVE: CONFIG_PATH = /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/client.ini
[2017-10-02 01:15:59,581] [WARNING] [config:428] (51859.140736228193088) (51859): in test environment
[2017-10-02 01:15:59,582] [WARNING] [config:449] (51859.140736228193088) NUM_CONFIRMATIONS = 0
[2017-10-02 01:15:59,808] [DEBUG] [testlib:76] (51859.140736228193088) Wallet 6e50431b955fe73f079469b24f06480aee44e4519282686433195b3c4b5336ef01 (mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx)
[2017-10-02 01:16:00,107] [DEBUG] [testlib:76] (51859.140736228193088) Wallet c244642ce0b4eb68da8e098facfcad889e3063c36a68b7951fb4c085de49df1b01 (msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn)
[2017-10-02 01:16:00,293] [DEBUG] [testlib:76] (51859.140736228193088) Wallet f4c3907cb5769c28ff603c145db7fc39d7d26f69f726f8a7f995a40d3897bb5201 (mvF2KY1UbdopoomiB371epM99GTnzjSUfj)
[2017-10-02 01:16:00,524] [DEBUG] [testlib:76] (51859.140736228193088) Wallet 8f87d1ea26d03259371675ea3bd31231b67c5df0012c205c154764a124f5b8fe01 (myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K)
[2017-10-02 01:16:00,719] [DEBUG] [testlib:76] (51859.140736228193088) Wallet bb68eda988e768132bc6c7ca73a87fb9b0918e9a38d3618b74099be25f7cab7d01 (mr1XvuxPtCvv4GCR3W1SoVTQtMGhxZFr3t)
[2017-10-02 01:16:00,725] [DEBUG] [blockstack-test-scenario:909] (51859.140736228193088) Starting up bitcoind in regtest mode
Bitcoin server starting
[2017-10-02 01:16:00,787] [DEBUG] [blockstack-test-scenario:916] (51859.140736228193088) Waiting for bitcoind to start up
[2017-10-02 01:16:01,791] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:02,809] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:03,828] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:04,851] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:05,873] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:06,885] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:06,891] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:09,786] [DEBUG] [blockstack-test-scenario:945] (51859.140736228193088) bitcoind -regtest is ready
[2017-10-02 01:16:10,236] [DEBUG] [testlib:89] (51859.140736228193088) Multisig wallet 2MxMQEYf7bXPT2s8fLbYCLKxfXv9kL5x9BL
[2017-10-02 01:16:10,236] [DEBUG] [testlib:90] (51859.140736228193088) {
    "address": "2MxMQEYf7bXPT2s8fLbYCLKxfXv9kL5x9BL", 
    "private_keys": [
        "5f1907a7805fcad134440439eb28708f166e337828a6ee32cbc760a991c3d56201", 
        "f3d6424e12968fa752a73637d48540713e41dfdac4cfba17eac2016048d730aa01", 
        "5cd7af0dc6cb15d2c89f69337c60f748bcdd4fc7160d8f8265cb2d12052d96d201"
    ], 
    "redeem_script": "522103d08049604200cd1ae7baa91e790b62e39e61b7d2233534eb9d644a272b35d97b2102fe0d1db6f7f375eef01d9f898a6a377a79d7d2f411793bd54359d56ce7e958c021033a659fd2ad1aa32ea29d71d4252c3aeb17bd2462fae99fd36b07fbace227c2d353ae", 
    "segwit": false
}
[2017-10-02 01:16:10,236] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:10,393] [DEBUG] [blockstack-test-scenario:962] (51859.140736228193088) Fill mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx (6e50431b955fe73f079469b24f06480aee44e4519282686433195b3c4b5336ef01) (cRH8tAZw6gSbewktG2Ajeq7KwFQ29Q7yADrfwBMxYHnMUvTxxNx8) with 50
[2017-10-02 01:16:10,812] [DEBUG] [blockstack-test-scenario:962] (51859.140736228193088) Fill msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn (c244642ce0b4eb68da8e098facfcad889e3063c36a68b7951fb4c085de49df1b01) (cU6LBm2hSSpFbwE6tZBvDBEghgfjzdG2oHr5K2urLqpTaAy8hBgt) with 50
[2017-10-02 01:16:11,227] [DEBUG] [blockstack-test-scenario:962] (51859.140736228193088) Fill mvF2KY1UbdopoomiB371epM99GTnzjSUfj (f4c3907cb5769c28ff603c145db7fc39d7d26f69f726f8a7f995a40d3897bb5201) (cVnVR3ehEmu4vxqG1va99YF48JFpcKCsXLKbjbmG7jvYcDyZk3EG) with 50
[2017-10-02 01:16:11,624] [DEBUG] [blockstack-test-scenario:962] (51859.140736228193088) Fill myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K (8f87d1ea26d03259371675ea3bd31231b67c5df0012c205c154764a124f5b8fe01) (cSPhv8wqPLN7o69jJ2pJ3nYDxXTAo7WmzmUiz9ZTTc66VtUEcmuM) with 50
[2017-10-02 01:16:12,036] [DEBUG] [blockstack-test-scenario:962] (51859.140736228193088) Fill mr1XvuxPtCvv4GCR3W1SoVTQtMGhxZFr3t (bb68eda988e768132bc6c7ca73a87fb9b0918e9a38d3618b74099be25f7cab7d01) (cTs14pEWitbXXQF7qN4jRvJGwgeEU4FCcJNTwXYdSngBYkmCkBpi) with 50
[2017-10-02 01:16:13,711] [DEBUG] [blockstack-test-scenario:982] (51859.140736228193088) Fill 2MxMQEYf7bXPT2s8fLbYCLKxfXv9kL5x9BL with 250

Address mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx loaded with 5000000000 satoshis
Address msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn loaded with 5000000000 satoshis
Address mvF2KY1UbdopoomiB371epM99GTnzjSUfj loaded with 5000000000 satoshis
Address myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K loaded with 5000000000 satoshis
Address mr1XvuxPtCvv4GCR3W1SoVTQtMGhxZFr3t loaded with 5000000000 satoshis
Address 2MxMQEYf7bXPT2s8fLbYCLKxfXv9kL5x9BL loaded with 25000000000 satoshis

[2017-10-02 01:16:14,175] [DEBUG] [blockstack-test-scenario:521] (51859.140736228193088) atexit_cleanup
[2017-10-02 01:16:14,175] [DEBUG] [config:1092] (51859.140736228193088) Load config from '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.ini'
[2017-10-02 01:16:14,177] [DEBUG] [config:939] (51859.140736228193088) Change blockstack-client.client_version to 0.16.0.1
[2017-10-02 01:16:14,177] [DEBUG] [config:910] (51859.140736228193088) Add new field subdomain-resolution.subdomains_db
Saving configuration to /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/client.ini
Saving configuration to /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.ini

blockstack opts
{
    "atlasdb_path": "/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/atlas.db", 
    "data_servers": "True", 
    "data_storage_drivers": "disk", 
    "serve_zonefiles": true, 
    "zonefile_storage_drivers_write": "disk", 
    "profile_storage_drivers": "disk", 
    "backup_max_age": 30, 
    "serve_profiles": true, 
    "atlas": true, 
    "analytics_key": "abcdef0123456789", 
    "email": "", 
    "atlas_hostname": "localhost", 
    "zonefiles": "/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/zonefiles", 
    "zonefile_storage_drivers": "disk", 
    "serve_data": true, 
    "announcers": "judecn.id,muneeb.id,shea256.id", 
    "server_version": "0.14.4", 
    "atlas_seeds": "", 
    "data_storage_drivers_write": "disk", 
    "redirect_data": false, 
    "rpc_port": 16264, 
    "backup_frequency": 1, 
    "profile_storage_drivers_write": "disk", 
    "atlas_blacklist": ""
}

blockchain opts
{
    "bitcoind_passwd": "blockstacksystem", 
    "bitcoind_user": "blockstack", 
    "bitcoind_server": "localhost", 
    "bitcoind_spv_path": "/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat", 
    "bitcoind_p2p_port": 18444, 
    "bitcoind_port": 18332, 
    "bitcoind_regtest": true
}

blockchain service opts
{
    "spv_headers_path": "/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat", 
    "rpc_password": "blockstacksystem", 
    "utxo_provider": "bitcoind_utxo", 
    "server": "localhost", 
    "rpc_username": "blockstack", 
    "port": 18332, 
    "blockchain_server": "localhost", 
    "version_byte": 0, 
    "use_https": false, 
    "blockchain_port": 18332
}
blockchain headers: /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat

atlas node initialization

[2017-10-02 01:16:14,189] [DEBUG] [namedb:89] (51859.140736228193088) Initialize database from '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:14,199] [DEBUG] [indexer:191] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:14,200] [DEBUG] [indexer:221] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:14,200] [DEBUG] [indexer:223] (51859.140736228193088) Store lastblock 255 to /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock
[2017-10-02 01:16:14,204] [DEBUG] [atlas:1268] (51859.140736228193088) Initializing Atlas DB at /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/atlas.db
[2017-10-02 01:16:14,207] [DEBUG] [atlas:1279] (51859.140736228193088) Queuing all zonefiles
[2017-10-02 01:16:14,207] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 256-255
[2017-10-02 01:16:14,207] [DEBUG] [atlas:1282] (51859.140736228193088) Adding seed peers
[2017-10-02 01:16:14,207] [DEBUG] [atlas:1289] (51859.140736228193088) peer_table: []

bitcoind connection

[2017-10-02 01:16:14,208] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
working_dir: /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env
[2017-10-02 01:16:14,208] [DEBUG] [blockstackd:2062] (51859.140736228193088) Optimistic GC thread start
[2017-10-02 01:16:14,208] [DEBUG] [atlas:1239] (51859.140736228193088) Atlas DB exists at /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/atlas.db
[2017-10-02 01:16:14,208] [DEBUG] [atlas:1246] (51859.140736228193088) Synchronize zonefiles from 256 to 255
[2017-10-02 01:16:14,209] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 256-255
[2017-10-02 01:16:14,209] [DEBUG] [atlas:1250] (51859.140736228193088) Refreshing seed peers
[2017-10-02 01:16:14,209] [DEBUG] [atlas:1259] (51859.140736228193088) Loading peer table
[2017-10-02 01:16:14,209] [DEBUG] [atlas:1289] (51859.140736228193088) peer_table: []
[2017-10-02 01:16:14,209] [DEBUG] [atlas:3549] (51859.140736228193088) Starting Atlas component 'health_checker'
[2017-10-02 01:16:14,209] [DEBUG] [atlas:3549] (51859.140736228193088) Starting Atlas component 'peer_crawler'
[2017-10-02 01:16:14,210] [DEBUG] [atlas:2954] (51859.123145424699392) localhost:16264: max neighbors is 80
[2017-10-02 01:16:14,210] [DEBUG] [atlas:3549] (51859.140736228193088) Starting Atlas component 'zonefile_crawler'
[2017-10-02 01:16:14,210] [DEBUG] [blockstackd:2027] (51859.140736228193088) Starting RPC
[2017-10-02 01:16:14,210] [INFO] [blockstackd:333] (51859.123145433112576) Listening on 0.0.0.0:16264
[2017-10-02 01:16:14,210] [DEBUG] [blockstackd:2086] (51859.140736228193088) Starting storage pusher
[2017-10-02 01:16:14,212] [DEBUG] [session:104] (51859.123145441525760) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:14,218] [DEBUG] [atlas:2915] (51859.123145424699392) localhost:16264: revalidate old peers
[2017-10-02 01:16:14,222] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:14,327] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_getinfo(())
[2017-10-02 01:16:14,328] [DEBUG] [session:104] (51859.123145433112576) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=300.0
[2017-10-02 01:16:14,351] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:14,352] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:14,352] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:14,352] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 255 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:14,366] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_getinfo(())
127.0.0.1 - - [02/Oct/2017 01:16:14] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:14,367] [DEBUG] [blockstack-test-scenario:714] (51859.140736228193088) Need periodic DB refreshes (server_version = 0.16.0.1)
[2017-10-02 01:16:14,371] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:14,449] [DEBUG] [blockstack-test-scenario:1044] (51859.140736228193088) next block (now at 256)
[2017-10-02 01:16:14,449] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:14,454] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:14,454] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:14,455] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:14,455] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 255 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:14,466] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:14,570] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:14] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:14,572] [DEBUG] [blockstack-test-scenario:554] (51859.140736228193088) sync virtualchain up to 256
[2017-10-02 01:16:14,572] [DEBUG] [indexer:1125] (51859.140736228193088) Sync virtualchain state from 256 to 257
[2017-10-02 01:16:14,573] [DEBUG] [transactions:75] (51859.140736228193088) Will download SPV headers to /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat
[2017-10-02 01:16:14,573] [DEBUG] [spv:744] (51859.140736228193088) Synchronize testnet 0 to 256
[2017-10-02 01:16:14,573] [DEBUG] [spv:767] (51859.140736228193088) connect to localhost:18444
[2017-10-02 01:16:14,574] [DEBUG] [spv:368] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:14,574] [DEBUG] [spv:371] (51859.140736228193088) send Version
[2017-10-02 01:16:14,577] [DEBUG] [spv:384] (51859.140736228193088) handle version
[2017-10-02 01:16:14,577] [DEBUG] [spv:386] (51859.140736228193088) send VerAck
[2017-10-02 01:16:14,577] [DEBUG] [spv:358] (51859.140736228193088) send getheaders
[2017-10-02 01:16:14,581] [DEBUG] [spv:403] (51859.140736228193088) handle ping
[2017-10-02 01:16:14,581] [DEBUG] [spv:406] (51859.140736228193088) send pong
[2017-10-02 01:16:14,590] [DEBUG] [spv:250] (51859.140736228193088) handle headers (256)
[2017-10-02 01:16:14,590] [DEBUG] [spv:272] (51859.140736228193088) Receive 256 testnet headers (0 to 255)
[2017-10-02 01:16:14,645] [DEBUG] [spv:785] (51859.140736228193088) synced headers from -1 to 256 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat
[2017-10-02 01:16:14,647] [DEBUG] [blocks:125] (51859.140736228193088) BlockDownloader: fetch blocks 256-256
[2017-10-02 01:16:14,647] [DEBUG] [blocks:173] (51859.140736228193088) Segwit support: False
[2017-10-02 01:16:14,647] [DEBUG] [blocks:311] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:14,647] [DEBUG] [blocks:314] (51859.140736228193088) send Version
[2017-10-02 01:16:14,649] [DEBUG] [blocks:327] (51859.140736228193088) handle version
[2017-10-02 01:16:14,649] [DEBUG] [blocks:329] (51859.140736228193088) send VerAck
[2017-10-02 01:16:14,649] [DEBUG] [blocks:345] (51859.140736228193088) send getdata for 256-256 (62e6dc19579e5898427592356c790bcc07e2b7c50b13433863cde8ac3f741b8e-62e6dc19579e5898427592356c790bcc07e2b7c50b13433863cde8ac3f741b8e)
[2017-10-02 01:16:14,653] [DEBUG] [blocks:370] (51859.140736228193088) handle ping
[2017-10-02 01:16:14,653] [DEBUG] [blocks:373] (51859.140736228193088) send pong
[2017-10-02 01:16:14,655] [DEBUG] [blocks:207] (51859.140736228193088) num blocks received = 0, num requested = 1
[2017-10-02 01:16:14,655] [DEBUG] [blocks:577] (51859.140736228193088) handle block 256 (62e6dc19579e5898427592356c790bcc07e2b7c50b13433863cde8ac3f741b8e)
[2017-10-02 01:16:14,655] [DEBUG] [blocks:673] (51859.140736228193088) Request 1 nulldata sender TXs
[2017-10-02 01:16:14,656] [DEBUG] [blocks:238] (51859.140736228193088) Fetch 1 TXs via JSON-RPC (0-1 of 1)
[2017-10-02 01:16:14,673] [DEBUG] [indexer:1065] (51859.140736228193088) Process block 256 (0 virtual transactions)
[2017-10-02 01:16:14,673] [DEBUG] [indexer:794] (51859.140736228193088) Snapshotting block 256
[2017-10-02 01:16:14,673] [DEBUG] [indexer:715] (51859.140736228193088) Snapshot('5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456', [])
[2017-10-02 01:16:14,674] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 256 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:14,674] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 256
[2017-10-02 01:16:14,674] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 256
[2017-10-02 01:16:14,674] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 256
[2017-10-02 01:16:14,675] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 256
[2017-10-02 01:16:14,675] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 256
[2017-10-02 01:16:14,676] [DEBUG] [namedb:1764] (51859.140736228193088) ops hash at 256 is 5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456
[2017-10-02 01:16:14,676] [DEBUG] [virtualchain_hooks:410] (51859.140736228193088) Synchronize Atlas DB for 255
[2017-10-02 01:16:14,691] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 255 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:14,692] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 255
[2017-10-02 01:16:14,692] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 255
[2017-10-02 01:16:14,692] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 255
[2017-10-02 01:16:14,692] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 255
[2017-10-02 01:16:14,692] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 255
[2017-10-02 01:16:14,692] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 255-255
[2017-10-02 01:16:14,707] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'lastblock': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock
[2017-10-02 01:16:14,708] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'snapshots': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots
[2017-10-02 01:16:14,710] [DEBUG] [indexer:1154] (51859.140736228193088) CONSENSUS(256): 2a9148d8b13939723d2aca16c75c6d68
[2017-10-02 01:16:14,710] [DEBUG] [indexer:1168] (51859.140736228193088) Last block is 256
[2017-10-02 01:16:14,710] [INFO] [virtualchain:69] (51859.140736228193088) 0 seconds
[2017-10-02 01:16:14,710] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:14,711] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:14,712] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:14,712] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 256 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:14,720] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:14,825] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:14] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:14,826] [DEBUG] [blockstack-test-scenario:564] (51859.140736228193088) sync atlas node up to 256
[2017-10-02 01:16:14,826] [DEBUG] [blockstack-test-scenario:569] (51859.140736228193088) Synchronize Atlas DB from 256 to 257
[2017-10-02 01:16:14,827] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 256 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:14,827] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 256
[2017-10-02 01:16:14,828] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 256
[2017-10-02 01:16:14,828] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 256
[2017-10-02 01:16:14,829] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 256
[2017-10-02 01:16:14,829] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 256
[2017-10-02 01:16:14,829] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 256-256
[2017-10-02 01:16:14,830] [DEBUG] [db:229] (51859.140736228193088) /usr/bin/sqlite3 /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db .backup "/var/folders/nf/ylp1ctks7c11dfpdly8pv_980000gn/T/blockstack-test-databases-ReJfC7/blockstack.db.256"
[2017-10-02 01:16:14,861] [DEBUG] [client:97] (51859.140736228193088) Connect to http://localhost:16264
[2017-10-02 01:16:14,863] [DEBUG] [client:112] (51859.140736228193088) Loaded storage drivers ['disk']
[2017-10-02 01:16:14,968] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_cost(('id',))
[2017-10-02 01:16:14,969] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:14,970] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:14,970] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:14,970] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 256 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:14,978] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_cost(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:14] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:15,152] [DEBUG] [safety:1180] (51859.140736228193088) Check namespace_preorder on id: test is_namespace_available, is_payment_address_usable, is_namespace_reveal_address_valid
[2017-10-02 01:16:15,397] [DEBUG] [blockchain:46] (51859.140736228193088) Connect to bitcoind at localhost:18332 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/client.ini)
[2017-10-02 01:16:15,397] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=300.0
[2017-10-02 01:16:15,740] [DEBUG] [safety:590] (51859.140736228193088) Getting UTXOs for msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:15,747] [DEBUG] [safety:602] (51859.140736228193088) Balance of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx is 5000000000 satoshis
[2017-10-02 01:16:15,747] [DEBUG] [safety:618] (51859.140736228193088) Get total operation fees for running 'namespace_preorder' on id owned by msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn paid by mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:15,747] [DEBUG] [safety:622] (51859.140736228193088) Operation namespace_preorder may consume owner inputs
[
    {
        "confirmations": 7, 
        "out_script": "76a91482093b62a3699282d926981bed7665e8384caa5588ac", 
        "outpoint": {
            "hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
            "index": 0
        }, 
        "transaction_hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:15,747] [DEBUG] [safety:623] (51859.140736228193088) Operation namespace_preorder may consume payment inputs
[
    {
        "confirmations": 7, 
        "out_script": "76a91474178497e927ff3ff1428a241be454d393c3c91c88ac", 
        "outpoint": {
            "hash": "287813c6c077deedad1aa3f9872966ffb4dc7375c2a885da6561c4e95e41893c", 
            "index": 0
        }, 
        "transaction_hash": "287813c6c077deedad1aa3f9872966ffb4dc7375c2a885da6561c4e95e41893c", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:15,747] [DEBUG] [safety:1056] (51859.140736228193088) Add task namespace_preorder_tx_fee (<function _estimate_namespace_preorder_tx at 0x105617938>)
[2017-10-02 01:16:15,747] [DEBUG] [safety:431] (51859.140736228193088) Queued tasks for namespace_preorder on id: get_balance, is_namespace_available, is_namespace_reveal_address_valid, is_payment_address_usable, namespace_preorder_tx_fee
[2017-10-02 01:16:15,747] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_payment_address_usable'
[2017-10-02 01:16:15,748] [DEBUG] [utils:283] (51859.123145446805504) Run task <function <lambda> at 0x1055c4398>
[2017-10-02 01:16:15,748] [DEBUG] [utils:337] (51859.140736228193088) Start task 'namespace_preorder_tx_fee'
[2017-10-02 01:16:15,748] [DEBUG] [utils:283] (51859.123145451012096) Run task <functools.partial object at 0x10554a9f0>
[2017-10-02 01:16:15,748] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:15,748] [DEBUG] [utils:283] (51859.123145455218688) Run task <function <lambda> at 0x1055c46e0>
[2017-10-02 01:16:15,748] [DEBUG] [utils:337] (51859.140736228193088) Start task 'get_balance'
[2017-10-02 01:16:15,749] [DEBUG] [utils:283] (51859.123145459425280) Run task <function _get_balance at 0x105617b18>
[2017-10-02 01:16:15,749] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_available'
[2017-10-02 01:16:15,749] [DEBUG] [utils:285] (51859.123145459425280) Task exit <function _get_balance at 0x105617b18>
[2017-10-02 01:16:15,750] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_payment_address_usable'
[2017-10-02 01:16:15,750] [DEBUG] [utils:283] (51859.123145463631872) Run task <function <lambda> at 0x1055c4578>
[2017-10-02 01:16:15,756] [WARNING] [blockchain:335] (51859.123145446805504) Address mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx useable with zero confirmations
[2017-10-02 01:16:15,756] [DEBUG] [utils:285] (51859.123145446805504) Task exit <function <lambda> at 0x1055c4398>
[2017-10-02 01:16:15,756] [DEBUG] [utils:344] (51859.140736228193088) Join task 'namespace_preorder_tx_fee'
[2017-10-02 01:16:15,758] [DEBUG] [utils:285] (51859.123145455218688) Task exit <function <lambda> at 0x1055c46e0>
[2017-10-02 01:16:15,851] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_cost(('id',))
[2017-10-02 01:16:15,852] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:15,853] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:15,854] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:15,854] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 256 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:15,862] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_cost(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:15] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:15,865] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_blockchain_record(('id',))
[2017-10-02 01:16:15,866] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:15,868] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:15,868] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:15,869] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 256 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:15,877] [DEBUG] [safety:898] (51859.123145451012096) Estimate namespace preorder TX fee (from mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx)
[2017-10-02 01:16:16,092] [DEBUG] [nameops:171] (51859.123145451012096) Try building a NAMESPACE_PREORDER with inputs 0-1 of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:16,094] [DEBUG] [nameops:176] (51859.123145451012096) Funded NAMESPACE_PREORDER with inputs 0-1 of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:16,094] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_blockchain_record(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:16] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:16,094] [ERROR] [utils:289] (51859.123145451012096) tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 901, in _estimate_namespace_preorder_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 907, in estimate_namespace_preorder_tx_fee
    signed_tx = sign_tx( unsigned_tx, payment_privkey_info )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
[2017-10-02 01:16:16,095] [DEBUG] [proxy:1874] (51859.123145463631872) Failed to read blockchain record for namespace id
[2017-10-02 01:16:16,096] [DEBUG] [utils:290] (51859.123145451012096) Task exit <functools.partial object at 0x10554a9f0>
[2017-10-02 01:16:16,096] [DEBUG] [utils:285] (51859.123145463631872) Task exit <function <lambda> at 0x1055c4578>
[2017-10-02 01:16:16,097] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:16,097] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_available'
[2017-10-02 01:16:16,097] [DEBUG] [utils:344] (51859.140736228193088) Join task 'get_balance'
[2017-10-02 01:16:16,097] [ERROR] [safety:451] (51859.140736228193088) Task 'namespace_preorder_tx_fee' failed: Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 901, in _estimate_namespace_preorder_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 907, in estimate_namespace_preorder_tx_fee
    signed_tx = sign_tx( unsigned_tx, payment_privkey_info )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

[2017-10-02 01:16:16,097] [DEBUG] [safety:1148] (51859.140736228193088) Total cost of namespace_preorder is 0 satoshis
[2017-10-02 01:16:16,097] [ERROR] [safety:1165] (51859.140736228193088) Some fee-query tasks failed: namespace_preorder_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 901, in _estimate_namespace_preorder_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 907, in estimate_namespace_preorder_tx_fee
    signed_tx = sign_tx( unsigned_tx, payment_privkey_info )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:16,097] [ERROR] [safety:1205] (51859.140736228193088) Failed to interpret operation sanity checks
[2017-10-02 01:16:16,097] [ERROR] [nameops:1880] (51859.140736228193088) Failed to check namespace preorder: Failed operation sanity checks:
Operation sanity checks failed:

  * Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 901, in _estimate_namespace_preorder_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 907, in estimate_namespace_preorder_tx_fee
    signed_tx = sign_tx( unsigned_tx, payment_privkey_info )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

  * Some fee-query tasks failed: namespace_preorder_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 901, in _estimate_namespace_preorder_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 907, in estimate_namespace_preorder_tx_fee
    signed_tx = sign_tx( unsigned_tx, payment_privkey_info )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:16,097] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:16,168] [DEBUG] [blockstack-test-scenario:1044] (51859.140736228193088) next block (now at 257)
[2017-10-02 01:16:16,168] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:16,172] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:16,172] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:16,173] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:16,173] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 256 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:16,181] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:16,284] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:16] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:16,286] [DEBUG] [blockstack-test-scenario:554] (51859.140736228193088) sync virtualchain up to 257
[2017-10-02 01:16:16,286] [DEBUG] [indexer:1125] (51859.140736228193088) Sync virtualchain state from 257 to 258
[2017-10-02 01:16:16,286] [DEBUG] [spv:744] (51859.140736228193088) Synchronize testnet 257 to 257
[2017-10-02 01:16:16,287] [DEBUG] [spv:767] (51859.140736228193088) connect to localhost:18444
[2017-10-02 01:16:16,288] [DEBUG] [spv:368] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:16,288] [DEBUG] [spv:371] (51859.140736228193088) send Version
[2017-10-02 01:16:16,294] [DEBUG] [spv:384] (51859.140736228193088) handle version
[2017-10-02 01:16:16,294] [DEBUG] [spv:386] (51859.140736228193088) send VerAck
[2017-10-02 01:16:16,295] [DEBUG] [spv:358] (51859.140736228193088) send getheaders
[2017-10-02 01:16:16,298] [DEBUG] [spv:403] (51859.140736228193088) handle ping
[2017-10-02 01:16:16,298] [DEBUG] [spv:406] (51859.140736228193088) send pong
[2017-10-02 01:16:16,300] [DEBUG] [spv:250] (51859.140736228193088) handle headers (1)
[2017-10-02 01:16:16,300] [DEBUG] [spv:268] (51859.140736228193088) Receive 1 headers (256 to 257)
[2017-10-02 01:16:16,301] [DEBUG] [spv:785] (51859.140736228193088) synced headers from 256 to 257 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat
[2017-10-02 01:16:16,302] [DEBUG] [blocks:125] (51859.140736228193088) BlockDownloader: fetch blocks 257-257
[2017-10-02 01:16:16,302] [DEBUG] [blocks:173] (51859.140736228193088) Segwit support: False
[2017-10-02 01:16:16,302] [DEBUG] [blocks:311] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:16,302] [DEBUG] [blocks:314] (51859.140736228193088) send Version
[2017-10-02 01:16:16,305] [DEBUG] [blocks:327] (51859.140736228193088) handle version
[2017-10-02 01:16:16,305] [DEBUG] [blocks:329] (51859.140736228193088) send VerAck
[2017-10-02 01:16:16,305] [DEBUG] [blocks:345] (51859.140736228193088) send getdata for 257-257 (3397f03f041897839eeec2c59d04cc9f5fcb50b8debb9ad6d28ba00730d64715-3397f03f041897839eeec2c59d04cc9f5fcb50b8debb9ad6d28ba00730d64715)
[2017-10-02 01:16:16,308] [DEBUG] [blocks:370] (51859.140736228193088) handle ping
[2017-10-02 01:16:16,308] [DEBUG] [blocks:373] (51859.140736228193088) send pong
[2017-10-02 01:16:16,310] [DEBUG] [blocks:207] (51859.140736228193088) num blocks received = 0, num requested = 1
[2017-10-02 01:16:16,310] [DEBUG] [blocks:577] (51859.140736228193088) handle block 257 (3397f03f041897839eeec2c59d04cc9f5fcb50b8debb9ad6d28ba00730d64715)
[2017-10-02 01:16:16,311] [DEBUG] [blocks:673] (51859.140736228193088) Request 1 nulldata sender TXs
[2017-10-02 01:16:16,311] [DEBUG] [blocks:238] (51859.140736228193088) Fetch 1 TXs via JSON-RPC (0-1 of 1)
[2017-10-02 01:16:16,317] [DEBUG] [indexer:1065] (51859.140736228193088) Process block 257 (0 virtual transactions)
[2017-10-02 01:16:16,317] [DEBUG] [indexer:794] (51859.140736228193088) Snapshotting block 257
[2017-10-02 01:16:16,317] [DEBUG] [indexer:807] (51859.140736228193088) Snapshotting block 257: consensus hash of 256 is 2a9148d8b13939723d2aca16c75c6d68
[2017-10-02 01:16:16,317] [DEBUG] [indexer:715] (51859.140736228193088) Snapshot('5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456', [u'2a9148d8b13939723d2aca16c75c6d68'])
[2017-10-02 01:16:16,318] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 257 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:16,318] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 257
[2017-10-02 01:16:16,318] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 257
[2017-10-02 01:16:16,319] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 257
[2017-10-02 01:16:16,319] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 257
[2017-10-02 01:16:16,319] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 257
[2017-10-02 01:16:16,320] [DEBUG] [namedb:1764] (51859.140736228193088) ops hash at 257 is 5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456
[2017-10-02 01:16:16,321] [DEBUG] [virtualchain_hooks:410] (51859.140736228193088) Synchronize Atlas DB for 256
[2017-10-02 01:16:16,342] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 256 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:16,342] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 256
[2017-10-02 01:16:16,342] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 256
[2017-10-02 01:16:16,342] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 256
[2017-10-02 01:16:16,343] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 256
[2017-10-02 01:16:16,343] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 256
[2017-10-02 01:16:16,343] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 256-256
[2017-10-02 01:16:16,360] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'lastblock': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock
[2017-10-02 01:16:16,360] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'snapshots': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots
[2017-10-02 01:16:16,362] [DEBUG] [indexer:1154] (51859.140736228193088) CONSENSUS(257): 1c54465d3486f07be2c7a81af0ef44ad
[2017-10-02 01:16:16,362] [DEBUG] [indexer:1168] (51859.140736228193088) Last block is 257
[2017-10-02 01:16:16,362] [INFO] [virtualchain:69] (51859.140736228193088) 0 seconds
[2017-10-02 01:16:16,362] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:16,363] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:16,363] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:16,363] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 257 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:16,375] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:16,481] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:16] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:16,482] [DEBUG] [blockstack-test-scenario:564] (51859.140736228193088) sync atlas node up to 257
[2017-10-02 01:16:16,483] [DEBUG] [blockstack-test-scenario:569] (51859.140736228193088) Synchronize Atlas DB from 257 to 258
[2017-10-02 01:16:16,483] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 257 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:16,484] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 257
[2017-10-02 01:16:16,485] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 257
[2017-10-02 01:16:16,485] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 257
[2017-10-02 01:16:16,485] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 257
[2017-10-02 01:16:16,486] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 257
[2017-10-02 01:16:16,486] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 257-257
[2017-10-02 01:16:16,487] [DEBUG] [db:229] (51859.140736228193088) /usr/bin/sqlite3 /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db .backup "/var/folders/nf/ylp1ctks7c11dfpdly8pv_980000gn/T/blockstack-test-databases-ReJfC7/blockstack.db.257"
[2017-10-02 01:16:16,511] [DEBUG] [client:97] (51859.140736228193088) Connect to http://localhost:16264
[2017-10-02 01:16:16,512] [DEBUG] [client:112] (51859.140736228193088) Loaded storage drivers ['disk']
[2017-10-02 01:16:16,702] [DEBUG] [safety:1180] (51859.140736228193088) Check namespace_reveal on id: test is_namespace_available, is_payment_address_usable, is_namespace_reveal_address_valid
[2017-10-02 01:16:16,883] [DEBUG] [blockchain:46] (51859.140736228193088) Connect to bitcoind at localhost:18332 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/client.ini)
[2017-10-02 01:16:16,883] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=300.0
[2017-10-02 01:16:17,233] [DEBUG] [safety:590] (51859.140736228193088) Getting UTXOs for msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:17,240] [DEBUG] [safety:602] (51859.140736228193088) Balance of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx is 5000000000 satoshis
[2017-10-02 01:16:17,240] [DEBUG] [safety:618] (51859.140736228193088) Get total operation fees for running 'namespace_reveal' on id owned by msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn paid by mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:17,240] [DEBUG] [safety:622] (51859.140736228193088) Operation namespace_reveal may consume owner inputs
[
    {
        "confirmations": 8, 
        "out_script": "76a91482093b62a3699282d926981bed7665e8384caa5588ac", 
        "outpoint": {
            "hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
            "index": 0
        }, 
        "transaction_hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:17,240] [DEBUG] [safety:623] (51859.140736228193088) Operation namespace_reveal may consume payment inputs
[
    {
        "confirmations": 8, 
        "out_script": "76a91474178497e927ff3ff1428a241be454d393c3c91c88ac", 
        "outpoint": {
            "hash": "287813c6c077deedad1aa3f9872966ffb4dc7375c2a885da6561c4e95e41893c", 
            "index": 0
        }, 
        "transaction_hash": "287813c6c077deedad1aa3f9872966ffb4dc7375c2a885da6561c4e95e41893c", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:17,240] [DEBUG] [safety:1056] (51859.140736228193088) Add task namespace_reveal_tx_fee (<function _estimate_namespace_reveal_tx at 0x105617500>)
[2017-10-02 01:16:17,240] [DEBUG] [safety:431] (51859.140736228193088) Queued tasks for namespace_reveal on id: get_balance, is_namespace_available, is_namespace_reveal_address_valid, is_payment_address_usable, namespace_reveal_tx_fee
[2017-10-02 01:16:17,240] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_payment_address_usable'
[2017-10-02 01:16:17,241] [DEBUG] [utils:283] (51859.123145446805504) Run task <function <lambda> at 0x105a67e60>
[2017-10-02 01:16:17,241] [DEBUG] [utils:337] (51859.140736228193088) Start task 'namespace_reveal_tx_fee'
[2017-10-02 01:16:17,241] [DEBUG] [utils:283] (51859.123145451012096) Run task <functools.partial object at 0x105614db8>
[2017-10-02 01:16:17,241] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:17,241] [DEBUG] [utils:283] (51859.123145455218688) Run task <function <lambda> at 0x105a6d230>
[2017-10-02 01:16:17,241] [DEBUG] [utils:337] (51859.140736228193088) Start task 'get_balance'
[2017-10-02 01:16:17,242] [DEBUG] [utils:283] (51859.123145459425280) Run task <function _get_balance at 0x105617b18>
[2017-10-02 01:16:17,242] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_available'
[2017-10-02 01:16:17,242] [DEBUG] [utils:285] (51859.123145459425280) Task exit <function _get_balance at 0x105617b18>
[2017-10-02 01:16:17,243] [DEBUG] [utils:283] (51859.123145463631872) Run task <function <lambda> at 0x105a6d0c8>
[2017-10-02 01:16:17,243] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_payment_address_usable'
[2017-10-02 01:16:17,258] [WARNING] [blockchain:335] (51859.123145446805504) Address mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx useable with zero confirmations
[2017-10-02 01:16:17,258] [DEBUG] [utils:285] (51859.123145446805504) Task exit <function <lambda> at 0x105a67e60>
[2017-10-02 01:16:17,259] [DEBUG] [safety:934] (51859.123145451012096) Estimate namespace reveal TX fee (from mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx)
[2017-10-02 01:16:17,259] [DEBUG] [utils:344] (51859.140736228193088) Join task 'namespace_reveal_tx_fee'
[2017-10-02 01:16:17,271] [DEBUG] [utils:285] (51859.123145455218688) Task exit <function <lambda> at 0x105a6d230>
[2017-10-02 01:16:17,386] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_blockchain_record(('id',))
[2017-10-02 01:16:17,439] [DEBUG] [nameops:171] (51859.123145451012096) Try building a NAMESPACE_REVEAL with inputs 0-1 of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:17,440] [DEBUG] [nameops:176] (51859.123145451012096) Funded NAMESPACE_REVEAL with inputs 0-1 of mr6nrMvvh44sR5MiX929mMXP5hqgaTr6fx
[2017-10-02 01:16:17,440] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:17,440] [ERROR] [utils:289] (51859.123145451012096) tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 937, in _estimate_namespace_reveal_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 973, in estimate_namespace_reveal_tx_fee
    signed_tx = sign_tx(unsigned_tx, payment_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
[2017-10-02 01:16:17,441] [DEBUG] [utils:290] (51859.123145451012096) Task exit <functools.partial object at 0x105614db8>
[2017-10-02 01:16:17,441] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:17,441] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_available'
[2017-10-02 01:16:17,441] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:17,442] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:17,442] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 257 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:17,448] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_blockchain_record(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:17] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:17,449] [DEBUG] [proxy:1874] (51859.123145463631872) Failed to read blockchain record for namespace id
[2017-10-02 01:16:17,449] [DEBUG] [utils:285] (51859.123145463631872) Task exit <function <lambda> at 0x105a6d0c8>
[2017-10-02 01:16:17,449] [DEBUG] [utils:344] (51859.140736228193088) Join task 'get_balance'
[2017-10-02 01:16:17,449] [ERROR] [safety:451] (51859.140736228193088) Task 'namespace_reveal_tx_fee' failed: Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 937, in _estimate_namespace_reveal_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 973, in estimate_namespace_reveal_tx_fee
    signed_tx = sign_tx(unsigned_tx, payment_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

[2017-10-02 01:16:17,449] [DEBUG] [safety:1148] (51859.140736228193088) Total cost of namespace_reveal is 0 satoshis
[2017-10-02 01:16:17,449] [ERROR] [safety:1165] (51859.140736228193088) Some fee-query tasks failed: namespace_reveal_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 937, in _estimate_namespace_reveal_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 973, in estimate_namespace_reveal_tx_fee
    signed_tx = sign_tx(unsigned_tx, payment_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:17,449] [ERROR] [safety:1205] (51859.140736228193088) Failed to interpret operation sanity checks
[2017-10-02 01:16:17,449] [ERROR] [nameops:1952] (51859.140736228193088) Failed to check namespace preorder: Failed operation sanity checks:
Operation sanity checks failed:

  * Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 937, in _estimate_namespace_reveal_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 973, in estimate_namespace_reveal_tx_fee
    signed_tx = sign_tx(unsigned_tx, payment_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

  * Some fee-query tasks failed: namespace_reveal_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 937, in _estimate_namespace_reveal_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 973, in estimate_namespace_reveal_tx_fee
    signed_tx = sign_tx(unsigned_tx, payment_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:17,450] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:17,527] [DEBUG] [blockstack-test-scenario:1044] (51859.140736228193088) next block (now at 258)
[2017-10-02 01:16:17,527] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:17,531] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:17,531] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:17,532] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:17,532] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 257 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:17,539] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:17,643] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:17] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:17,644] [DEBUG] [blockstack-test-scenario:554] (51859.140736228193088) sync virtualchain up to 258
[2017-10-02 01:16:17,645] [DEBUG] [indexer:1125] (51859.140736228193088) Sync virtualchain state from 258 to 259
[2017-10-02 01:16:17,645] [DEBUG] [spv:744] (51859.140736228193088) Synchronize testnet 258 to 258
[2017-10-02 01:16:17,645] [DEBUG] [spv:767] (51859.140736228193088) connect to localhost:18444
[2017-10-02 01:16:17,646] [DEBUG] [spv:368] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:17,647] [DEBUG] [spv:371] (51859.140736228193088) send Version
[2017-10-02 01:16:17,649] [DEBUG] [spv:384] (51859.140736228193088) handle version
[2017-10-02 01:16:17,649] [DEBUG] [spv:386] (51859.140736228193088) send VerAck
[2017-10-02 01:16:17,649] [DEBUG] [spv:358] (51859.140736228193088) send getheaders
[2017-10-02 01:16:17,652] [DEBUG] [spv:403] (51859.140736228193088) handle ping
[2017-10-02 01:16:17,652] [DEBUG] [spv:406] (51859.140736228193088) send pong
[2017-10-02 01:16:17,654] [DEBUG] [spv:250] (51859.140736228193088) handle headers (1)
[2017-10-02 01:16:17,654] [DEBUG] [spv:268] (51859.140736228193088) Receive 1 headers (257 to 258)
[2017-10-02 01:16:17,655] [DEBUG] [spv:785] (51859.140736228193088) synced headers from 257 to 258 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat
[2017-10-02 01:16:17,656] [DEBUG] [blocks:125] (51859.140736228193088) BlockDownloader: fetch blocks 258-258
[2017-10-02 01:16:17,656] [DEBUG] [blocks:173] (51859.140736228193088) Segwit support: False
[2017-10-02 01:16:17,656] [DEBUG] [blocks:311] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:17,656] [DEBUG] [blocks:314] (51859.140736228193088) send Version
[2017-10-02 01:16:17,658] [DEBUG] [blocks:327] (51859.140736228193088) handle version
[2017-10-02 01:16:17,659] [DEBUG] [blocks:329] (51859.140736228193088) send VerAck
[2017-10-02 01:16:17,659] [DEBUG] [blocks:345] (51859.140736228193088) send getdata for 258-258 (4f2126436f6929d0d3a0699d51cb4792f3e2443370e7f042e5c78242e1f08ac1-4f2126436f6929d0d3a0699d51cb4792f3e2443370e7f042e5c78242e1f08ac1)
[2017-10-02 01:16:17,662] [DEBUG] [blocks:370] (51859.140736228193088) handle ping
[2017-10-02 01:16:17,662] [DEBUG] [blocks:373] (51859.140736228193088) send pong
[2017-10-02 01:16:17,664] [DEBUG] [blocks:207] (51859.140736228193088) num blocks received = 0, num requested = 1
[2017-10-02 01:16:17,664] [DEBUG] [blocks:577] (51859.140736228193088) handle block 258 (4f2126436f6929d0d3a0699d51cb4792f3e2443370e7f042e5c78242e1f08ac1)
[2017-10-02 01:16:17,665] [DEBUG] [blocks:673] (51859.140736228193088) Request 1 nulldata sender TXs
[2017-10-02 01:16:17,665] [DEBUG] [blocks:238] (51859.140736228193088) Fetch 1 TXs via JSON-RPC (0-1 of 1)
[2017-10-02 01:16:17,670] [DEBUG] [indexer:1065] (51859.140736228193088) Process block 258 (0 virtual transactions)
[2017-10-02 01:16:17,670] [DEBUG] [indexer:794] (51859.140736228193088) Snapshotting block 258
[2017-10-02 01:16:17,670] [DEBUG] [indexer:807] (51859.140736228193088) Snapshotting block 258: consensus hash of 257 is 1c54465d3486f07be2c7a81af0ef44ad
[2017-10-02 01:16:17,670] [DEBUG] [indexer:715] (51859.140736228193088) Snapshot('5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456', [u'1c54465d3486f07be2c7a81af0ef44ad'])
[2017-10-02 01:16:17,671] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 258 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:17,672] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 258
[2017-10-02 01:16:17,672] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 258
[2017-10-02 01:16:17,672] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 258
[2017-10-02 01:16:17,672] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 258
[2017-10-02 01:16:17,672] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 258
[2017-10-02 01:16:17,673] [DEBUG] [namedb:1764] (51859.140736228193088) ops hash at 258 is 5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456
[2017-10-02 01:16:17,673] [DEBUG] [virtualchain_hooks:410] (51859.140736228193088) Synchronize Atlas DB for 257
[2017-10-02 01:16:17,692] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 257 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:17,692] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 257
[2017-10-02 01:16:17,692] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 257
[2017-10-02 01:16:17,692] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 257
[2017-10-02 01:16:17,693] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 257
[2017-10-02 01:16:17,693] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 257
[2017-10-02 01:16:17,693] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 257-257
[2017-10-02 01:16:17,708] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'lastblock': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock
[2017-10-02 01:16:17,709] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'snapshots': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots
[2017-10-02 01:16:17,710] [DEBUG] [indexer:1154] (51859.140736228193088) CONSENSUS(258): 0efa29f955c6ae3bb5037039d89dba5e
[2017-10-02 01:16:17,711] [DEBUG] [indexer:1168] (51859.140736228193088) Last block is 258
[2017-10-02 01:16:17,711] [INFO] [virtualchain:69] (51859.140736228193088) 0 seconds
[2017-10-02 01:16:17,711] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:17,712] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:17,712] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:17,713] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 258 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:17,723] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:17,827] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:17] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:17,829] [DEBUG] [blockstack-test-scenario:564] (51859.140736228193088) sync atlas node up to 258
[2017-10-02 01:16:17,829] [DEBUG] [blockstack-test-scenario:569] (51859.140736228193088) Synchronize Atlas DB from 258 to 259
[2017-10-02 01:16:17,830] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 258 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:17,830] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 258
[2017-10-02 01:16:17,831] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 258
[2017-10-02 01:16:17,831] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 258
[2017-10-02 01:16:17,832] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 258
[2017-10-02 01:16:17,832] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 258
[2017-10-02 01:16:17,832] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 258-258
[2017-10-02 01:16:17,833] [DEBUG] [db:229] (51859.140736228193088) /usr/bin/sqlite3 /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db .backup "/var/folders/nf/ylp1ctks7c11dfpdly8pv_980000gn/T/blockstack-test-databases-ReJfC7/blockstack.db.258"
[2017-10-02 01:16:17,858] [DEBUG] [client:97] (51859.140736228193088) Connect to http://localhost:16264
[2017-10-02 01:16:17,859] [DEBUG] [client:112] (51859.140736228193088) Loaded storage drivers ['disk']
[2017-10-02 01:16:18,193] [DEBUG] [safety:1180] (51859.140736228193088) Check namespace_ready on id: test is_namespace_reveal_address_valid, is_namespace_revealer, is_namespace_still_revealed, is_payment_address_usable
[2017-10-02 01:16:18,354] [DEBUG] [blockchain:46] (51859.140736228193088) Connect to bitcoind at localhost:18332 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/client.ini)
[2017-10-02 01:16:18,354] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=300.0
[2017-10-02 01:16:18,686] [DEBUG] [safety:590] (51859.140736228193088) Getting UTXOs for msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:18,693] [DEBUG] [safety:602] (51859.140736228193088) Balance of msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn is 5000000000 satoshis
[2017-10-02 01:16:18,693] [DEBUG] [safety:618] (51859.140736228193088) Get total operation fees for running 'namespace_ready' on id owned by msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn paid by msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:18,693] [DEBUG] [safety:622] (51859.140736228193088) Operation namespace_ready may consume owner inputs
[
    {
        "confirmations": 9, 
        "out_script": "76a91482093b62a3699282d926981bed7665e8384caa5588ac", 
        "outpoint": {
            "hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
            "index": 0
        }, 
        "transaction_hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:18,693] [DEBUG] [safety:623] (51859.140736228193088) Operation namespace_ready may consume payment inputs
[
    {
        "confirmations": 9, 
        "out_script": "76a91482093b62a3699282d926981bed7665e8384caa5588ac", 
        "outpoint": {
            "hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
            "index": 0
        }, 
        "transaction_hash": "f4fc84a7285c96af947a40ef7044b33f7d233d4daad9b1c35e9c3fa3401e2094", 
        "value": 10000000000
    }
]
[2017-10-02 01:16:18,693] [DEBUG] [safety:1056] (51859.140736228193088) Add task namespace_ready_tx_fee (<function _estimate_namespace_ready_tx at 0x105a67758>)
[2017-10-02 01:16:18,693] [DEBUG] [safety:431] (51859.140736228193088) Queued tasks for namespace_ready on id: get_balance, is_namespace_reveal_address_valid, is_namespace_revealer, is_namespace_still_revealed, is_payment_address_usable, namespace_ready_tx_fee
[2017-10-02 01:16:18,694] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_payment_address_usable'
[2017-10-02 01:16:18,694] [DEBUG] [utils:283] (51859.123145446805504) Run task <function <lambda> at 0x105a6c488>
[2017-10-02 01:16:18,694] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:18,694] [DEBUG] [utils:283] (51859.123145451012096) Run task <function <lambda> at 0x105a6c7d0>
[2017-10-02 01:16:18,694] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_revealer'
[2017-10-02 01:16:18,695] [DEBUG] [utils:283] (51859.123145455218688) Run task <function <lambda> at 0x105a6c758>
[2017-10-02 01:16:18,695] [DEBUG] [utils:337] (51859.140736228193088) Start task 'namespace_ready_tx_fee'
[2017-10-02 01:16:18,696] [DEBUG] [utils:283] (51859.123145459425280) Run task <functools.partial object at 0x105a65cb0>
[2017-10-02 01:16:18,696] [DEBUG] [utils:337] (51859.140736228193088) Start task 'is_namespace_still_revealed'
[2017-10-02 01:16:18,697] [DEBUG] [utils:283] (51859.123145463631872) Run task <function <lambda> at 0x105a6c6e0>
[2017-10-02 01:16:18,698] [DEBUG] [utils:337] (51859.140736228193088) Start task 'get_balance'
[2017-10-02 01:16:18,699] [DEBUG] [utils:283] (51859.123145467838464) Run task <function _get_balance at 0x105a679b0>
[2017-10-02 01:16:18,699] [DEBUG] [utils:285] (51859.123145467838464) Task exit <function _get_balance at 0x105a679b0>
[2017-10-02 01:16:18,699] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_payment_address_usable'
[2017-10-02 01:16:18,712] [WARNING] [blockchain:335] (51859.123145446805504) Address msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn useable with zero confirmations
[2017-10-02 01:16:18,712] [DEBUG] [utils:285] (51859.123145446805504) Task exit <function <lambda> at 0x105a6c488>
[2017-10-02 01:16:18,712] [DEBUG] [safety:970] (51859.123145459425280) Estimate namespace ready TX fee (from msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn)
[2017-10-02 01:16:18,713] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_reveal_address_valid'
[2017-10-02 01:16:18,742] [DEBUG] [utils:285] (51859.123145451012096) Task exit <function <lambda> at 0x105a6c7d0>
[2017-10-02 01:16:18,753] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_revealer'
[2017-10-02 01:16:18,801] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_blockchain_record(('id',))
[2017-10-02 01:16:18,813] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:18,825] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:18,826] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:18,841] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 258 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:18,922] [DEBUG] [nameops:171] (51859.123145459425280) Try building a NAMESPACE_READY with inputs 0-1 of msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:18,923] [DEBUG] [nameops:176] (51859.123145459425280) Funded NAMESPACE_READY with inputs 0-1 of msNXCSWz2pyDnpBpUb8As6EhXU5cR3UhPn
[2017-10-02 01:16:18,923] [ERROR] [utils:289] (51859.123145459425280) tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 973, in _estimate_namespace_ready_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 1034, in estimate_namespace_ready_tx_fee
    signed_tx = sign_tx(unsigned_tx, reveal_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
[2017-10-02 01:16:18,925] [DEBUG] [utils:290] (51859.123145459425280) Task exit <functools.partial object at 0x105a65cb0>
[2017-10-02 01:16:18,927] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_blockchain_record(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:18] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:18,928] [DEBUG] [utils:285] (51859.123145455218688) Task exit <function <lambda> at 0x105a6c758>
[2017-10-02 01:16:18,928] [DEBUG] [utils:344] (51859.140736228193088) Join task 'namespace_ready_tx_fee'
[2017-10-02 01:16:18,928] [DEBUG] [utils:344] (51859.140736228193088) Join task 'is_namespace_still_revealed'
[2017-10-02 01:16:18,928] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_namespace_blockchain_record(('id',))
[2017-10-02 01:16:18,929] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:18,930] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:18,930] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:18,931] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 258 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:18,936] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_namespace_blockchain_record(('id',))
127.0.0.1 - - [02/Oct/2017 01:16:18] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:18,937] [DEBUG] [proxy:1874] (51859.123145463631872) Failed to read blockchain record for namespace id
[2017-10-02 01:16:18,937] [DEBUG] [utils:285] (51859.123145463631872) Task exit <function <lambda> at 0x105a6c6e0>
[2017-10-02 01:16:18,937] [DEBUG] [utils:344] (51859.140736228193088) Join task 'get_balance'
[2017-10-02 01:16:18,937] [ERROR] [safety:451] (51859.140736228193088) Task 'is_namespace_revealer' failed: No such namespace
[2017-10-02 01:16:18,938] [ERROR] [safety:451] (51859.140736228193088) Task 'namespace_ready_tx_fee' failed: Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 973, in _estimate_namespace_ready_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 1034, in estimate_namespace_ready_tx_fee
    signed_tx = sign_tx(unsigned_tx, reveal_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

[2017-10-02 01:16:18,938] [ERROR] [safety:451] (51859.140736228193088) Task 'is_namespace_still_revealed' failed: Namespace is not revealed
[2017-10-02 01:16:18,938] [DEBUG] [safety:1148] (51859.140736228193088) Total cost of namespace_ready is 0 satoshis
[2017-10-02 01:16:18,938] [ERROR] [safety:1165] (51859.140736228193088) Some fee-query tasks failed: namespace_ready_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 973, in _estimate_namespace_ready_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 1034, in estimate_namespace_ready_tx_fee
    signed_tx = sign_tx(unsigned_tx, reveal_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:18,938] [ERROR] [safety:1205] (51859.140736228193088) Failed to interpret operation sanity checks
[2017-10-02 01:16:18,938] [ERROR] [nameops:2012] (51859.140736228193088) Failed to check namespace preorder: Failed operation sanity checks:
Operation sanity checks failed:

  * No such namespace
  * Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 973, in _estimate_namespace_ready_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 1034, in estimate_namespace_ready_tx_fee
    signed_tx = sign_tx(unsigned_tx, reveal_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)

  * Namespace is not revealed
  * Some fee-query tasks failed: namespace_ready_tx_fee (Task encountered a fatal exception:
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/utils.py", line 284, in do_work
    res = rpc_call()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/safety.py", line 973, in _estimate_namespace_ready_tx
    config_path=config_path, include_dust=True )
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/backend/nameops.py", line 1034, in estimate_namespace_ready_tx_fee
    signed_tx = sign_tx(unsigned_tx, reveal_privkey_info)
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack_client/tx.py", line 165, in sign_tx
    return virtualchain.tx_sign_all_unsigned_inputs(private_key_info, tx_hex)
TypeError: tx_sign_all_unsigned_inputs() takes at least 3 arguments (2 given)
)
[2017-10-02 01:16:18,938] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:19,003] [DEBUG] [blockstack-test-scenario:1044] (51859.140736228193088) next block (now at 259)
[2017-10-02 01:16:19,003] [DEBUG] [session:104] (51859.140736228193088) [51859] Connect to bitcoind at http://blockstack@localhost:18332, timeout=60.0
[2017-10-02 01:16:19,006] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:19,007] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:19,007] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:19,007] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 258 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:19,014] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:19,117] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:19] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:19,118] [DEBUG] [blockstack-test-scenario:554] (51859.140736228193088) sync virtualchain up to 259
[2017-10-02 01:16:19,119] [DEBUG] [indexer:1125] (51859.140736228193088) Sync virtualchain state from 259 to 260
[2017-10-02 01:16:19,119] [DEBUG] [spv:744] (51859.140736228193088) Synchronize testnet 259 to 259
[2017-10-02 01:16:19,120] [DEBUG] [spv:767] (51859.140736228193088) connect to localhost:18444
[2017-10-02 01:16:19,121] [DEBUG] [spv:368] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:19,121] [DEBUG] [spv:371] (51859.140736228193088) send Version
[2017-10-02 01:16:19,125] [DEBUG] [spv:384] (51859.140736228193088) handle version
[2017-10-02 01:16:19,125] [DEBUG] [spv:386] (51859.140736228193088) send VerAck
[2017-10-02 01:16:19,126] [DEBUG] [spv:358] (51859.140736228193088) send getheaders
[2017-10-02 01:16:19,133] [DEBUG] [spv:403] (51859.140736228193088) handle ping
[2017-10-02 01:16:19,133] [DEBUG] [spv:406] (51859.140736228193088) send pong
[2017-10-02 01:16:19,136] [DEBUG] [spv:250] (51859.140736228193088) handle headers (1)
[2017-10-02 01:16:19,136] [DEBUG] [spv:268] (51859.140736228193088) Receive 1 headers (258 to 259)
[2017-10-02 01:16:19,138] [DEBUG] [spv:785] (51859.140736228193088) synced headers from 258 to 259 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/spv_headers.dat
[2017-10-02 01:16:19,139] [DEBUG] [blocks:125] (51859.140736228193088) BlockDownloader: fetch blocks 259-259
[2017-10-02 01:16:19,139] [DEBUG] [blocks:173] (51859.140736228193088) Segwit support: False
[2017-10-02 01:16:19,139] [DEBUG] [blocks:311] (51859.140736228193088) handshake (version 60002)
[2017-10-02 01:16:19,139] [DEBUG] [blocks:314] (51859.140736228193088) send Version
[2017-10-02 01:16:19,142] [DEBUG] [blocks:327] (51859.140736228193088) handle version
[2017-10-02 01:16:19,142] [DEBUG] [blocks:329] (51859.140736228193088) send VerAck
[2017-10-02 01:16:19,142] [DEBUG] [blocks:345] (51859.140736228193088) send getdata for 259-259 (6774ca3422ceb3cf1bb3ae439af56845e93c2eff33bdc11bec959cf0d9f6dc8e-6774ca3422ceb3cf1bb3ae439af56845e93c2eff33bdc11bec959cf0d9f6dc8e)
[2017-10-02 01:16:19,145] [DEBUG] [blocks:370] (51859.140736228193088) handle ping
[2017-10-02 01:16:19,145] [DEBUG] [blocks:373] (51859.140736228193088) send pong
[2017-10-02 01:16:19,147] [DEBUG] [blocks:207] (51859.140736228193088) num blocks received = 0, num requested = 1
[2017-10-02 01:16:19,148] [DEBUG] [blocks:577] (51859.140736228193088) handle block 259 (6774ca3422ceb3cf1bb3ae439af56845e93c2eff33bdc11bec959cf0d9f6dc8e)
[2017-10-02 01:16:19,148] [DEBUG] [blocks:673] (51859.140736228193088) Request 1 nulldata sender TXs
[2017-10-02 01:16:19,148] [DEBUG] [blocks:238] (51859.140736228193088) Fetch 1 TXs via JSON-RPC (0-1 of 1)
[2017-10-02 01:16:19,155] [DEBUG] [indexer:1065] (51859.140736228193088) Process block 259 (0 virtual transactions)
[2017-10-02 01:16:19,155] [DEBUG] [indexer:794] (51859.140736228193088) Snapshotting block 259
[2017-10-02 01:16:19,155] [DEBUG] [indexer:807] (51859.140736228193088) Snapshotting block 259: consensus hash of 258 is 0efa29f955c6ae3bb5037039d89dba5e
[2017-10-02 01:16:19,155] [DEBUG] [indexer:807] (51859.140736228193088) Snapshotting block 259: consensus hash of 256 is 2a9148d8b13939723d2aca16c75c6d68
[2017-10-02 01:16:19,155] [DEBUG] [indexer:715] (51859.140736228193088) Snapshot('5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456', [u'0efa29f955c6ae3bb5037039d89dba5e', u'2a9148d8b13939723d2aca16c75c6d68'])
[2017-10-02 01:16:19,156] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 259 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:19,157] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 259
[2017-10-02 01:16:19,157] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 259
[2017-10-02 01:16:19,157] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 259
[2017-10-02 01:16:19,157] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 259
[2017-10-02 01:16:19,158] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 259
[2017-10-02 01:16:19,159] [DEBUG] [namedb:1764] (51859.140736228193088) ops hash at 259 is 5df6e0e2761359d30a8275058e299fcc0381534545f55cf43e41983f5d4c9456
[2017-10-02 01:16:19,159] [DEBUG] [virtualchain_hooks:410] (51859.140736228193088) Synchronize Atlas DB for 258
[2017-10-02 01:16:19,175] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 258 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:19,175] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 258
[2017-10-02 01:16:19,176] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 258
[2017-10-02 01:16:19,176] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 258
[2017-10-02 01:16:19,176] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 258
[2017-10-02 01:16:19,176] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 258
[2017-10-02 01:16:19,176] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 258-258
[2017-10-02 01:16:19,190] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'lastblock': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock
[2017-10-02 01:16:19,191] [DEBUG] [indexer:376] (51859.140736228193088) Rename 'snapshots': /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots.tmp --> /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots
[2017-10-02 01:16:19,193] [DEBUG] [indexer:1154] (51859.140736228193088) CONSENSUS(259): 9daa6e59877b9e0ca4772a3df475abd2
[2017-10-02 01:16:19,193] [DEBUG] [indexer:1168] (51859.140736228193088) Last block is 259
[2017-10-02 01:16:19,193] [INFO] [virtualchain:69] (51859.140736228193088) 0 seconds
[2017-10-02 01:16:19,193] [DEBUG] [namedb:91] (51859.140736228193088) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:19,194] [DEBUG] [indexer:175] (51859.140736228193088) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:19,194] [DEBUG] [indexer:210] (51859.140736228193088) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:19,194] [DEBUG] [indexer:213] (51859.140736228193088) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:19,204] [DEBUG] [testlib:112] (51859.140736228193088) Connect to Blockstack node at localhost:16264
[2017-10-02 01:16:19,308] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_db_refresh(())

rpc_db_refresh(())
Traceback (most recent call last):
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/blockstack-0.16.0.1-py2.7.egg/blockstack/blockstackd.py", line 309, in _dispatch
    res = self.server.funcs["rpc_" + str(method)](*params, **con_info)
KeyError: 'rpc_db_refresh'

127.0.0.1 - - [02/Oct/2017 01:16:19] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:19,310] [DEBUG] [blockstack-test-scenario:564] (51859.140736228193088) sync atlas node up to 259
[2017-10-02 01:16:19,310] [DEBUG] [blockstack-test-scenario:569] (51859.140736228193088) Synchronize Atlas DB from 259 to 260
[2017-10-02 01:16:19,311] [DEBUG] [namedb:765] (51859.140736228193088) Get all ops at 259 in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db
[2017-10-02 01:16:19,312] [DEBUG] [db:1830] (51859.140736228193088) 0 name-preorder/import states at 259
[2017-10-02 01:16:19,312] [DEBUG] [db:1885] (51859.140736228193088) 0 name-change states at 259
[2017-10-02 01:16:19,312] [DEBUG] [db:1931] (51859.140736228193088) 0 preorders created at 259
[2017-10-02 01:16:19,313] [DEBUG] [db:1975] (51859.140736228193088) 0 namespace-preorder states at 259
[2017-10-02 01:16:19,313] [DEBUG] [db:2023] (51859.140736228193088) 0 namespace-change states at 259
[2017-10-02 01:16:19,314] [DEBUG] [atlas:932] (51859.140736228193088) Queued 0 zonefiles from 259-259
[2017-10-02 01:16:19,315] [DEBUG] [db:229] (51859.140736228193088) /usr/bin/sqlite3 /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db .backup "/var/folders/nf/ylp1ctks7c11dfpdly8pv_980000gn/T/blockstack-test-databases-ReJfC7/blockstack.db.259"

{
    "data_pubkey": "03ea5d8c2a3ba84eb17625162320bb53440557c71f7977a57d61405e86be7bdcda", 
    "data_pubkeys": [
        "03ea5d8c2a3ba84eb17625162320bb53440557c71f7977a57d61405e86be7bdcda"
    ], 
    "enc": "c2NyeXB0ABQAAAAIAAAAAbV+kPixlkBvyBXmtm8S0rDV3xhAAqyT0V61uaCzjBUHcZl6Sj33SSGrHZ/Wo1eyGToR7oF3GwARrqwQtO1djqasnn5QUlLbSc1rnML2Wx4HgNyUVlP+ifNE0A2ePP4LUxgiomEVi2WxTJP0qEoCOLgQ9vUHco/acUUBPhIkI55Ho9aal+IDlkNfXVxfZMzu5t5SfcozfaNKfdxQM2H0jmLt1AGSmBveGA3RmgU7w/mRV1lPFXWk2BKub9Ncn1Il4WXc2hqLPS304FAm0wCle0Nm3Wz17htBsly3nC+2wGxsdbNgkcFSNnxWfvWiVOR20z8TL+t4eimEdenT4F3IyHnInOlfFl/7HEStzBGQy0F1MTU9v05UOkkWP9p3PwOo2QcUhrdMs3zMReQusnPdx3a/VC9VcwNS3MXUhLfeCY8Y9wmXcln3cuCaZAMl8CFsZ9PdEQ/w2iOrq2GfwrwbHyX4RMRiDbGTn8mjGglx91bRi0yn7UX1", 
    "owner_addresses": [
        "myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K"
    ], 
    "payment_addresses": [
        "mvF2KY1UbdopoomiB371epM99GTnzjSUfj"
    ], 
    "version": "0.16.0"
}

{
    "data_privkey": "bb68eda988e768132bc6c7ca73a87fb9b0918e9a38d3618b74099be25f7cab7d01", 
    "data_pubkey": "04ea5d8c2a3ba84eb17625162320bb53440557c71f7977a57d61405e86be7bdcdab63a7f1eda1e6c1670c64a9f532b9f55458019d9b80fdf41748d06cd7f60d451", 
    "data_pubkeys": [
        "04ea5d8c2a3ba84eb17625162320bb53440557c71f7977a57d61405e86be7bdcdab63a7f1eda1e6c1670c64a9f532b9f55458019d9b80fdf41748d06cd7f60d451"
    ], 
    "owner_addresses": [
        "myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K"
    ], 
    "owner_privkey": "8f87d1ea26d03259371675ea3bd31231b67c5df0012c205c154764a124f5b8fe01", 
    "payment_addresses": [
        "mvF2KY1UbdopoomiB371epM99GTnzjSUfj"
    ], 
    "payment_privkey": "f4c3907cb5769c28ff603c145db7fc39d7d26f69f726f8a7f995a40d3897bb5201", 
    "version": "0.16.0"
}

stopping API daemon

Not running (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/api_endpoint.pid)

starting API daemon

[2017-10-02 01:16:28,860] [INFO] [rpc:5276] (51859.140736228193088) API server version 0.16.0 starting...
[2017-10-02 01:16:28,860] [INFO] [rpc:5277] (51859.140736228193088) Machine:   x86_64
[2017-10-02 01:16:28,860] [INFO] [rpc:5278] (51859.140736228193088) Version:   Darwin Kernel Version 17.0.0: Thu Aug 24 21:48:19 PDT 2017; root:xnu-4570.1.46~2/RELEASE_X86_64
[2017-10-02 01:16:28,873] [INFO] [rpc:5279] (51859.140736228193088) Platform:  Darwin-17.0.0-x86_64-i386-64bit
[2017-10-02 01:16:28,874] [INFO] [rpc:5280] (51859.140736228193088) uname:     Darwin Vanquish.local 17.0.0 Darwin Kernel Version 17.0.0: Thu Aug 24 21:48:19 PDT 2017; root:xnu-4570.1.46~2/RELEASE_X86_64 x86_64 i386
[2017-10-02 01:16:28,874] [INFO] [rpc:5281] (51859.140736228193088) System:    Darwin
[2017-10-02 01:16:28,874] [INFO] [rpc:5282] (51859.140736228193088) Processor: i386
[2017-10-02 01:16:28,874] [INFO] [rpc:5283] (51859.140736228193088) pip:
appdirs==1.4.3
asn1crypto==0.22.0
base58==0.2.4
basicrpc==0.0.2
bitcoin==1.1.42
bitmerchant==0.1.8
blockstack==0.16.0.1
blockstack-integration-tests==0.14.2
blockstack-profiles==0.14.1
blockstack-zones==0.14.3
boto==2.47.0
cachetools==2.0.0
certifi==2017.4.17
cffi==1.10.0
chardet==3.0.3
commontools==0.1.0
cryptography==1.9
defusedxml==0.5.0
dropbox==8.0.0
ecdsa==0.13
enum34==1.1.6
functools32==3.2.3.post2
google-api-python-client==1.6.2
httplib2==0.10.3
idna==2.5
influxdb==4.1.1
ipaddress==1.0.18
jsonpatch==1.15
jsonpointer==1.10
jsonschema==2.6.0
jsontokens==0.0.4
keychain==0.14.2.0
keylib==0.1.1
mixpanel==4.3.2
nose==1.3.7
oauth2client==4.1.0
onedrivesdk==1.1.8
packaging==16.8
protocoin==0.2
pyasn1==0.2.3
pyasn1-modules==0.0.8
pybitcoin==0.9.9
pycparser==2.17
PyDrive==1.3.1
pyparsing==2.2.0
python-bitcoinrpc==0.1
python-dateutil==2.6.1
pytz==2017.2
PyYAML==3.12
requests==2.17.3
rsa==3.4.2
scrypt==0.8.0
simplejson==3.10.0
six==1.10.0
uritemplate==3.0.0
urllib3==1.21.1
utilitybelt==0.2.6
virtualchain==0.17.0
warlock==1.3.0
xmlrunner==1.7.7

[2017-10-02 01:16:28,878] [WARNING] [rpc:5318] (51859.140736228193088) Not setting signal handlers since we are in test mode
[2017-10-02 01:16:32,765] [DEBUG] [rpc:5337] (51859.140736228193088) Running in the background
[2017-10-02 01:16:33,374] [DEBUG] [rpc:5349] (51859.140736228193088) Parent 51859 forked intermediate child 51876
[2017-10-02 01:16:33,380] [DEBUG] [client:97] (51859.140736228193088) Connect to http://localhost:16264
[2017-10-02 01:16:33,382] [DEBUG] [client:112] (51859.140736228193088) Loaded storage drivers ['disk']
[2017-10-02 01:16:33,382] [DEBUG] [testlib:661] (51859.140736228193088) Stored zonefile to None
[2017-10-02 01:16:33,382] [DEBUG] [rpc:5491] (51859.140736228193088) RPC running (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/client/api_endpoint.pid)
[2017-10-02 01:16:33,387] [DEBUG] [actions:1402] (51859.140736228193088) Use UTXOs with a minimum of 0 confirmations
[2017-10-02 01:16:33,412] [DEBUG] [zonefile:71] (51859.140736228193088) WARN: Scheme "file" has no known transport protocol
[2017-10-02 01:16:33,413] [DEBUG] [actions:1527] (51859.140736228193088) Preorder foo.id, zonefile=$ORIGIN foo.id
$TTL 3600
pubkey TXT "pubkey:data:03ea5d8c2a3ba84eb17625162320bb53440557c71f7977a57d61405e86be7bdcda"
_file URI 10 1 "file:///tmp/blockstack-disk/mutable/foo.id"
, profile={'accounts': [], '@type': 'Person'}, recipient=None min_confs=0
[2017-10-02 01:16:33,417] [DEBUG] [rpc:4993] (51859.140736228193088) Connect to API at localhost:6270
[2017-10-02 01:16:33,531] [DEBUG] [rpc:4269] (51859.140736228193088) Remote API endpoint is running version 0.16.0
[2017-10-02 01:16:33,750] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
[2017-10-02 01:16:33,750] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:33,752] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:33,752] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:33,752] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:33,760] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
127.0.0.1 - - [02/Oct/2017 01:16:33] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:33,882] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_name_blockchain_record(('foo.id',))
[2017-10-02 01:16:33,882] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:33,883] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:33,883] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:33,884] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:33,890] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_name_blockchain_record(('foo.id',))
127.0.0.1 - - [02/Oct/2017 01:16:33] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:34,840] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_name_cost(('foo.id',))
[2017-10-02 01:16:34,840] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:34,841] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:34,841] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:34,841] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:34,848] [DEBUG] [blockstackd:236] (51859.123145433112576) Revealing namespace 'id'
[2017-10-02 01:16:34,848] [DEBUG] [blockstackd:241] (51859.123145433112576) No namespace 'id'
[2017-10-02 01:16:34,848] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_name_cost(('foo.id',))
127.0.0.1 - - [02/Oct/2017 01:16:34] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:34,849] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_name_blockchain_record(('foo.id',))
[2017-10-02 01:16:34,849] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:34,849] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:34,850] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:34,850] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:34,857] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_name_blockchain_record(('foo.id',))
127.0.0.1 - - [02/Oct/2017 01:16:34] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:34,857] [DEBUG] [blockstackd:305] (51859.123145433112576) Inbound RPC begin rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
[2017-10-02 01:16:34,857] [DEBUG] [namedb:91] (51859.123145433112576) Connect to database '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.db'
[2017-10-02 01:16:34,858] [DEBUG] [indexer:175] (51859.123145433112576) consensus snapshots at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.snapshots'
[2017-10-02 01:16:34,858] [DEBUG] [indexer:210] (51859.123145433112576) lastblock at '/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock'
[2017-10-02 01:16:34,858] [DEBUG] [indexer:213] (51859.123145433112576) Lastblock: 259 (/tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env/blockstack-server.lastblock)
[2017-10-02 01:16:34,865] [DEBUG] [blockstackd:315] (51859.123145433112576) Inbound RPC end rpc_get_names_owned_by_address(('myaPViveUWiiZQQTb51KXCDde4iLC3Rf3K',))
127.0.0.1 - - [02/Oct/2017 01:16:34] "POST /RPC2 HTTP/1.0" 200 -
[2017-10-02 01:16:35,913] [DEBUG] [actions:1546] (51859.140736228193088) RPC error: register failed.
Failed operation sanity checks:
Operation sanity checks failed:

  * Failed to get name cost
  * Some fee-query tasks failed: preorder_tx_fee (Failed to get name cost)
{
    "error": "register failed.\nFailed operation sanity checks:\nOperation sanity checks failed:\n\n  * Failed to get name cost\n  * Some fee-query tasks failed: preorder_tx_fee (Failed to get name cost)"
}
[2017-10-02 01:16:35,913] [ERROR] [blockstack-test-scenario:743] (51859.140736228193088) Scenario exits in error
[2017-10-02 01:16:35,913] [ERROR] [blockstack-test-scenario:744] (51859.140736228193088) Failed to run tests 'blockstack_integration_tests.scenarios.portal_test_env'
[2017-10-02 01:16:35,913] [INFO] [blockstack-test-scenario:671] (51859.140736228193088) Shutting down network
[2017-10-02 01:16:35,913] [DEBUG] [blockstackd:2037] (51859.140736228193088) Shutting down RPC
[2017-10-02 01:16:35,913] [WARNING] [blockstackd:1709] (51859.140736228193088) Failed to shut down server socket
[2017-10-02 01:16:36,368] [DEBUG] [blockstackd:2040] (51859.140736228193088) RPC joined
[2017-10-02 01:16:36,368] [DEBUG] [blockstackd:2072] (51859.140736228193088) Shutting down GC thread
[2017-10-02 01:16:37,276] [DEBUG] [blockstackd:2075] (51859.140736228193088) GC thread joined
[2017-10-02 01:16:37,277] [INFO] [blockstack-test-scenario:674] (51859.140736228193088) Shutting down atlas
[2017-10-02 01:16:37,277] [DEBUG] [atlas:3560] (51859.140736228193088) Stopping Atlas component 'health_checker'
[2017-10-02 01:16:38,278] [DEBUG] [atlas:3560] (51859.140736228193088) Stopping Atlas component 'peer_crawler'
[2017-10-02 01:16:38,292] [DEBUG] [atlas:3560] (51859.140736228193088) Stopping Atlas component 'zonefile_crawler'
[2017-10-02 01:16:39,288] [INFO] [blockstack-test-scenario:677] (51859.140736228193088) Shutting down storage
[2017-10-02 01:16:39,289] [DEBUG] [blockstackd:2098] (51859.140736228193088) Draining storage pusher queue
[2017-10-02 01:16:39,289] [DEBUG] [blockstackd:2101] (51859.140736228193088) Shutting down storage pusher
[2017-10-02 01:16:39,289] [DEBUG] [blockstackd:2005] (51859.140736228193088) StoragePusher signal stop
[2017-10-02 01:16:39,451] [DEBUG] [blockstackd:1999] (51859.123145437319168) StoragePusher thread exit
[2017-10-02 01:16:39,451] [DEBUG] [blockstackd:2104] (51859.140736228193088) Storage pusher joined
[2017-10-02 01:16:39,451] [INFO] [blockstack-test-scenario:680] (51859.140736228193088) Shutting down bitcoin
Bitcoin server stopping
[2017-10-02 01:16:39,466] [INFO] [blockstack-test-scenario:683] (51859.140736228193088) Shutting down API endpoint
Sending SIGTERM to 51877
Exception in thread Thread-7:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 810, in __bootstrap_inner
    self.run()
  File "blockstack-venv/bin/blockstack-test-scenario", line 162, in run
    bitcoind.ping()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/virtualchain/lib/blockchain/bitcoin_blockchain/authproxy.py", line 143, in __call__
    response = self._get_response()
  File "/Users/larry/git/blockstack-testing/develop/blockstack-venv/lib/python2.7/site-packages/virtualchain/lib/blockchain/bitcoin_blockchain/authproxy.py", line 193, in _get_response
    'code': -342, 'message': 'non-JSON HTTP response with \'%i %s\' from server' % (http_response.status, http_response.reason)})
JSONRPCException: -342: non-JSON HTTP response with '503 Service Unavailable' from server

Sending SIGKILL to 51877
[2017-10-02 01:16:42,472] [INFO] [blockstack-test-scenario:687] (51859.140736228193088) Shutting down pinger
FAILURE blockstack_integration_tests.scenarios.portal_test_env
Test output in /tmp/blockstack-run-scenario.blockstack_integration_tests.scenarios.portal_test_env
./start_regtest.sh: line 5: 51859 Abort trap: 6           BLOCKSTACK_TEST_CLIENT_RPC_PORT=6270 blockstack-venv/bin/blockstack-test-scenario --interactive 2 blockstack_integration_tests.scenarios.portal_test_env
Vanquish:develop larry$
kantai commented 6 years ago

It looks like the venv built on circleCI is pulling in the wrong version of virtualchain for develop right now. I'm away from my computer at the moment, but can fix this once I get back.

larrysalibra commented 6 years ago

No rush - going to head to bed. Will give it another try in 8 or 9 hours.

Thanks @kantai !

kantai commented 6 years ago

I set the requirement to be explicit in commit f26954a455cf409dfb974e6389990d2bfed0c290

The circleCI artifact should work for you now

larrysalibra commented 6 years ago

Beautiful. Works for me now. Thank you!