Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ambitious vessel resource targets leave "small" nodes in limbo #157

Open
aaaaalbert opened this issue Jul 22, 2015 · 1 comment
Open

Ambitious vessel resource targets leave "small" nodes in limbo #157

aaaaalbert opened this issue Jul 22, 2015 · 1 comment

Comments

@aaaaalbert
Copy link
Contributor

I'm setting up a new test clearinghouse at the moment. My donating install transitions nodestates alright at first, and counts towards my user's credits correctly, but the clearinghouse never gets to see any vessels donated.

Setting the clearinghouse's DEBUG = True reveals that the clearinghouse tries to split the node into vessels larger than what the node could provide. Trying to split this way is a NMClientException in the CH API (and a BadRequest in the node's nmAPI.py).

No entry in the vessel database is made, neither for the attempted split vessel, nor the original one. Despite this, the node is marked with the twopercent key to signify "all set up correctly". That's bad because with no entry in the DB, the CH can never assign this unsplittable vessel to a user.

To fix this, transition_canonical_to_twopercent.py should detect / handle errors between advancing nodes states.

Below follows the rather large transition script log, redacted so as to replace the unwiedly pubkeys logged. The overall flow of events is

  • 08:41:24.918652 Laundry list of things the transition script will do
  • 08:41:25.709066 Find node in canonical state that needs to be transitioned
  • 08:41:59.749937 Node now in movingto_twopercent, i.e. it's being worked on
  • 08:42:26.801673 Find node in movingto_twopercent state that needs to be transitioned
  • 08:42:41.131846 Attempt to split the vessel
  • 08:42:55.104192 Error, Proposed vessel is too large. Insufficient quantity: Resource 'diskused' has a negative quantity.
  • 08:43:01.073357 Successfully changed the node state to twopercent, which it shouldn't do after the error above
[2015-07-22 08:41:24.918312] INFO 654222770 Waking up from sleep.....
[2015-07-22 08:41:24.918652] DEBUG 654222770 Calling: do_one_processnode_run (module node_transition_lib), args: ([('canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), ('movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), ('movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False)], 'canonical_to_twopercent', 10), kwargs: ().
[2015-07-22 08:41:24.918862] INFO 654222770 Looking up nodes to transition from canonical state to movingto_twopercent state
[2015-07-22 08:41:24.919167] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('canonical', {'e': 65537L, 'n': ---CANONICAL_KEY---}), kwargs: ().
[2015-07-22 08:41:24.919402] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---CANONICAL_KEY---}
[2015-07-22 08:41:24.919666] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---CANONICAL_KEY---},), kwargs: ().
[2015-07-22 08:41:25.708723] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:00.788886): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:41:25.708917] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:00.789592): (True, ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'])
[2015-07-22 08:41:25.709066] INFO 654222770 List of ip/NAT found in advertise_lookup(): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:41:25.709176] INFO 654222770 Length of nodeprocesslist: 1
[2015-07-22 08:41:25.709312] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:41:25.709472] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: (['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'], 'canonical_to_twopercent', 10, 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:41:25.709967] DEBUG 387900153 Calling: processnode (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:41:25.710210] INFO 387900153 Starting to process node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:34.497460] DEBUG 387900153 Calling: create_lockserver_handle (module clearinghouse.common.api.lockserver), args: (), kwargs: ().
[2015-07-22 08:41:34.500487] DEBUG 387900153 Returning from create_lockserver_handle (module clearinghouse.common.api.lockserver) (time 0:00:00.002718): {'proxy': <ServerProxy for 127.0.0.1:8010/RPC2>, 'session_id': '9332330'}
[2015-07-22 08:41:34.500675] INFO 387900153 Created lockserver_handle for use on node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:41:38.595154] INFO 387900153 Acquired node lock for nodeID: 65537 ---NODE_PUBKEY---
[2015-07-22 08:41:38.595517] INFO 387900153 Retrieving node vesseldict for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:53.638355] INFO 387900153 Successfully retrieved node_info for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:53.638906] DEBUG 387900153 Calling: get_node (module clearinghouse.common.api.maindb), args: ('65537 ---NODE_PUBKEY---',), kwargs: ().
[2015-07-22 08:41:53.679171] DEBUG 387900153 Calling: init_maindb (module clearinghouse.common.api.maindb), args: (), kwargs: ().
[2015-07-22 08:41:53.679687] DEBUG 387900153 Resetting django query log because settings.DEBUG is True.
[2015-07-22 08:41:53.679902] ERROR 387900153 Reminder: settings.DEBUG is True. Don't run in production like this!
[2015-07-22 08:41:53.680067] DEBUG 387900153 Returning from init_maindb (module clearinghouse.common.api.maindb) (time 0:00:00.000666): None
[2015-07-22 08:41:53.681199] DEBUG 387900153 Returning from get_node (module clearinghouse.common.api.maindb) (time 0:00:00.041935): Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:53.681584] DEBUG 387900153 Calling: get_node_state (module node_transition_lib), args: ({'nodename': '192.168.99.7', 'nodekey': {'e': 65537L, 'n': ---NODE_PUBKEY---L}, 'version': 'testch-20150721-1440', 'vessels': {'v1': {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---CANONICAL_KEY---}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}, 'v2': {'status': 'Fresh', 'userkeys': [], 'ownerkey': {'e': 65537L, 'n': ---SERVICEVESSEL_PUBKEY---}, 'ownerinfo': '', 'advertise': True}}}, <Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>), kwargs: ().
[2015-07-22 08:41:53.681795] INFO 387900153 Starting get node state for node 65537 ---NODE_PUBKEY---
[2015-07-22 08:41:53.681906] INFO 387900153 Name of extra vessel: v1
[2015-07-22 08:41:53.682118] INFO 387900153 Extra vessel info: {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---CANONICAL_KEY---}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}
[2015-07-22 08:41:53.682357] DEBUG 387900153 Returning from get_node_state (module node_transition_lib) (time 0:00:00.000476): {'e': 65537L, 'n': ---CANONICAL_KEY---}
[2015-07-22 08:41:53.682497] INFO 387900153 Trying to set new state for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:53.682724] DEBUG 387900153 Calling: set_node_state (module node_transition_lib), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:41:53.683061] DEBUG 387900153 Calling: set_vessel_user_keylist (module clearinghouse.common.api.backend), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, u'v1', ['65537 ---MOVINGTO_TWOPERCENT---']), kwargs: ().
[2015-07-22 08:41:59.551975] DEBUG 387900153 Returning from set_vessel_user_keylist (module clearinghouse.common.api.backend) (time 0:00:05.868761): None
[2015-07-22 08:41:59.552311] INFO 387900153 Successfully changed the node state to {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:41:59.552548] DEBUG 387900153 Returning from set_node_state (module node_transition_lib) (time 0:00:05.869641): None
[2015-07-22 08:41:59.552795] DEBUG 387900153 Calling: mark_node_as_inactive (module clearinghouse.common.api.maindb), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>,), kwargs: ().
[2015-07-22 08:41:59.561611] DEBUG 387900153 Returning from mark_node_as_inactive (module clearinghouse.common.api.maindb) (time 0:00:00.008661): None
[2015-07-22 08:41:59.561734] INFO 387900153 Finished setting new state movingto_twopercent on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:41:59.571176] INFO 387900153 released lock for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:41:59.572444] INFO 387900153 Destroyed lockserver_handle for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:41:59.572601] DEBUG 387900153 Returning from processnode (module node_transition_lib) (time 0:00:33.862404): True
[2015-07-22 08:41:59.749937] INFO 654222770 Success on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224. Returnvalue: True
[2015-07-22 08:41:59.750257] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:41:59.750589] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:34.040975): (1, 0)
[2015-07-22 08:41:59.750891] INFO 654222770 Succeeded on 1 nodes, Failed on 0 nodes
[2015-07-22 08:41:59.751109] INFO 654222770 Looking up nodes to transition from movingto_twopercent state to twopercent state
[2015-07-22 08:41:59.751496] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('movingto_twopercent', {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:41:59.751908] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:41:59.752303] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L},), kwargs: ().
[2015-07-22 08:42:00.776964] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:01.024427): []
[2015-07-22 08:42:00.777203] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:01.025456): (True, [])
[2015-07-22 08:42:00.777365] INFO 654222770 List of ip/NAT found in advertise_lookup(): []
[2015-07-22 08:42:00.777541] INFO 654222770 Length of nodeprocesslist: 0
[2015-07-22 08:42:00.777706] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:42:00.777901] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: ([], 'canonical_to_twopercent', 10, 'movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), kwargs: ().
[2015-07-22 08:42:00.778071] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:42:00.778198] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:00.000147): (0, 0)
[2015-07-22 08:42:00.778304] INFO 654222770 Succeeded on 0 nodes, Failed on 0 nodes
[2015-07-22 08:42:00.778425] INFO 654222770 Looking up nodes to transition from movingto_twopercent state to canonical state
[2015-07-22 08:42:00.778634] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('movingto_twopercent', {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:42:00.778885] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:42:00.779112] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L},), kwargs: ().
[2015-07-22 08:42:01.781908] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:01.002630): []
[2015-07-22 08:42:01.782176] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:01.003367): (True, [])
[2015-07-22 08:42:01.782318] INFO 654222770 List of ip/NAT found in advertise_lookup(): []
[2015-07-22 08:42:01.782425] INFO 654222770 Length of nodeprocesslist: 0
[2015-07-22 08:42:01.782550] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:42:01.782699] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: ([], 'canonical_to_twopercent', 10, 'movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:42:01.782911] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:42:01.783101] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:00.000188): (0, 0)
[2015-07-22 08:42:01.783247] INFO 654222770 Succeeded on 0 nodes, Failed on 0 nodes
[2015-07-22 08:42:01.783395] DEBUG 654222770 Returning from do_one_processnode_run (module node_transition_lib) (time 0:00:36.864529): [(1, 0), (0, 0), (0, 0)]
[2015-07-22 08:42:01.783503] INFO 654222770 Finished running do_one_processnode_run(), going to sleep for 10 seconds
[2015-07-22 08:42:11.791745] INFO 654222770 Waking up from sleep.....
[2015-07-22 08:42:11.791936] DEBUG 654222770 Calling: do_one_processnode_run (module node_transition_lib), args: ([('canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), ('movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), ('movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False)], 'canonical_to_twopercent', 10), kwargs: ().
[2015-07-22 08:42:11.791972] INFO 654222770 Looking up nodes to transition from canonical state to movingto_twopercent state
[2015-07-22 08:42:11.792093] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('canonical', {'e': 65537L, 'n': ---CANONICAL_KEY---}), kwargs: ().
[2015-07-22 08:42:11.792217] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---CANONICAL_KEY---}
[2015-07-22 08:42:11.792330] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---CANONICAL_KEY---},), kwargs: ().
[2015-07-22 08:42:12.781844] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:00.989462): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:42:12.782068] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:00.989919): (True, ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'])
[2015-07-22 08:42:12.782231] INFO 654222770 List of ip/NAT found in advertise_lookup(): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:42:12.782347] INFO 654222770 Length of nodeprocesslist: 1
[2015-07-22 08:42:12.782448] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:42:12.782623] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: (['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'], 'canonical_to_twopercent', 10, 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:42:12.783193] DEBUG 339236066 Calling: processnode (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:42:12.783422] INFO 339236066 Starting to process node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:18.978102] DEBUG 339236066 Calling: create_lockserver_handle (module clearinghouse.common.api.lockserver), args: (), kwargs: ().
[2015-07-22 08:42:18.980642] DEBUG 339236066 Returning from create_lockserver_handle (module clearinghouse.common.api.lockserver) (time 0:00:00.002288): {'proxy': <ServerProxy for 127.0.0.1:8010/RPC2>, 'session_id': '2055176'}
[2015-07-22 08:42:18.980828] INFO 339236066 Created lockserver_handle for use on node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:18.982431] INFO 339236066 Acquired node lock for nodeID: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:18.982617] INFO 339236066 Retrieving node vesseldict for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:26.682002] INFO 339236066 Successfully retrieved node_info for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:26.682459] DEBUG 339236066 Calling: get_node (module clearinghouse.common.api.maindb), args: ('65537 ---NODE_PUBKEY---',), kwargs: ().
[2015-07-22 08:42:26.703546] DEBUG 339236066 Calling: init_maindb (module clearinghouse.common.api.maindb), args: (), kwargs: ().
[2015-07-22 08:42:26.704260] DEBUG 339236066 Resetting django query log because settings.DEBUG is True.
[2015-07-22 08:42:26.704593] ERROR 339236066 Reminder: settings.DEBUG is True. Don't run in production like this!
[2015-07-22 08:42:26.704837] DEBUG 339236066 Returning from init_maindb (module clearinghouse.common.api.maindb) (time 0:00:00.000964): None
[2015-07-22 08:42:26.737698] DEBUG 339236066 Returning from get_node (module clearinghouse.common.api.maindb) (time 0:00:00.054839): Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:26.738368] DEBUG 339236066 Calling: get_node_state (module node_transition_lib), args: ({'nodename': '192.168.99.7', 'nodekey': {'e': 65537L, 'n': ---NODE_PUBKEY---L}, 'version': 'testch-20150721-1440', 'vessels': {'v1': {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}, 'v2': {'status': 'Fresh', 'userkeys': [], 'ownerkey': {'e': 65537L, 'n': ---SERVICEVESSEL_PUBKEY---}, 'ownerinfo': '', 'advertise': True}}}, <Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>), kwargs: ().
[2015-07-22 08:42:26.738695] INFO 339236066 Starting get node state for node 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:26.738920] INFO 339236066 Name of extra vessel: v1
[2015-07-22 08:42:26.739298] INFO 339236066 Extra vessel info: {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}
[2015-07-22 08:42:26.739734] DEBUG 339236066 Returning from get_node_state (module node_transition_lib) (time 0:00:00.000878): {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:42:26.740268] INFO 339236066 The node is not in the right transition state. NodeID is: 65537 ---NODE_PUBKEY--- Current state is {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}. Should be in state {'e': 65537L, 'n': ---CANONICAL_KEY---}
[2015-07-22 08:42:26.740613] INFO 339236066 Node data problem when processing node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224Traceback (most recent call last):
  File "/home/ch/deployment/clearinghouse/node_state_transitions/node_transition_lib.py", line 428, in processnode
NodeError: Node is no longer in the right state!

[2015-07-22 08:42:26.751234] INFO 339236066 released lock for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:26.752501] INFO 339236066 Destroyed lockserver_handle for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:26.752649] DEBUG 339236066 Returning from processnode (module node_transition_lib) (time 0:00:13.969234): False
[2015-07-22 08:42:26.800066] INFO 654222770 Failure on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224.
[2015-07-22 08:42:26.800284] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:42:26.800506] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:14.017677): (0, 1)
[2015-07-22 08:42:26.800687] INFO 654222770 Succeeded on 0 nodes, Failed on 1 nodes
[2015-07-22 08:42:26.800890] INFO 654222770 Looking up nodes to transition from movingto_twopercent state to twopercent state
[2015-07-22 08:42:26.801262] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('movingto_twopercent', {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:42:26.801673] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:42:26.802066] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L},), kwargs: ().
[2015-07-22 08:42:27.798380] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:00.996063): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:42:27.799812] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:00.998281): (True, ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'])
[2015-07-22 08:42:27.800220] INFO 654222770 List of ip/NAT found in advertise_lookup(): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:42:27.800503] INFO 654222770 Length of nodeprocesslist: 1
[2015-07-22 08:42:27.800772] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:42:27.801148] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: (['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'], 'canonical_to_twopercent', 10, 'movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), kwargs: ().
[2015-07-22 08:42:27.801766] DEBUG 485939519 Calling: processnode (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', 'movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), kwargs: ().
[2015-07-22 08:42:27.801947] INFO 485939519 Starting to process node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:34.693552] DEBUG 485939519 Calling: create_lockserver_handle (module clearinghouse.common.api.lockserver), args: (), kwargs: ().
[2015-07-22 08:42:34.696712] DEBUG 485939519 Returning from create_lockserver_handle (module clearinghouse.common.api.lockserver) (time 0:00:00.002769): {'proxy': <ServerProxy for 127.0.0.1:8010/RPC2>, 'session_id': '5302604'}
[2015-07-22 08:42:34.697024] INFO 485939519 Created lockserver_handle for use on node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:34.699194] INFO 485939519 Acquired node lock for nodeID: 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:34.699399] INFO 485939519 Retrieving node vesseldict for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:41.091374] INFO 485939519 Successfully retrieved node_info for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:41.091717] DEBUG 485939519 Calling: get_node (module clearinghouse.common.api.maindb), args: ('65537 ---NODE_PUBKEY---',), kwargs: ().
[2015-07-22 08:42:41.122866] DEBUG 485939519 Calling: init_maindb (module clearinghouse.common.api.maindb), args: (), kwargs: ().
[2015-07-22 08:42:41.123356] DEBUG 485939519 Resetting django query log because settings.DEBUG is True.
[2015-07-22 08:42:41.123531] ERROR 485939519 Reminder: settings.DEBUG is True. Don't run in production like this!
[2015-07-22 08:42:41.123765] DEBUG 485939519 Returning from init_maindb (module clearinghouse.common.api.maindb) (time 0:00:00.000707): None
[2015-07-22 08:42:41.130303] DEBUG 485939519 Returning from get_node (module clearinghouse.common.api.maindb) (time 0:00:00.038378): Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:41.130693] DEBUG 485939519 Calling: get_node_state (module node_transition_lib), args: ({'nodename': '192.168.99.7', 'nodekey': {'e': 65537L, 'n': ---NODE_PUBKEY---L}, 'version': 'testch-20150721-1440', 'vessels': {'v1': {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}, 'v2': {'status': 'Fresh', 'userkeys': [], 'ownerkey': {'e': 65537L, 'n': ---SERVICEVESSEL_PUBKEY---}, 'ownerinfo': '', 'advertise': True}}}, <Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>), kwargs: ().
[2015-07-22 08:42:41.130915] INFO 485939519 Starting get node state for node 65537 ---NODE_PUBKEY---
[2015-07-22 08:42:41.131026] INFO 485939519 Name of extra vessel: v1
[2015-07-22 08:42:41.131239] INFO 485939519 Extra vessel info: {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}
[2015-07-22 08:42:41.131478] DEBUG 485939519 Returning from get_node_state (module node_transition_lib) (time 0:00:00.000478): {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:42:41.131846] DEBUG 485939519 Calling: split_vessels (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', {'nodename': '192.168.99.7', 'nodekey': {'e': 65537L, 'n': ---NODE_PUBKEY---L}, 'version': 'testch-20150721-1440', 'vessels': {'v1': {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}, 'v2': {'status': 'Fresh', 'userkeys': [], 'ownerkey': {'e': 65537L, 'n': ---SERVICEVESSEL_PUBKEY---}, 'ownerinfo': '', 'advertise': True}}}, <Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), kwargs: ().
[2015-07-22 08:42:41.132038] INFO 485939519 Beginning to divide vessel on node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:46.926966] INFO 485939519 List of usable ports in node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224. [63104, 63105, 63106, 63107, 63108, 63109, 63110, 63111, 63112, 63113, 63114, 63115, 63116, 63117, 63118, 63119, 63120, 63121, 63122, 63123, 63124, 63125, 63126, 63127, 63128, 63129, 63130, 63131, 63132, 63133, 63134, 63135, 63136, 63137, 63138, 63139, 63140, 63141, 63142, 63143, 63144, 63145, 63146, 63147, 63148, 63149, 63150, 63151, 63152, 63153, 63154, 63155, 63156, 63157, 63158, 63159, 63160, 63161, 63162, 63163, 63164, 63165, 63166, 63167, 63168, 63169, 63170, 63171, 63172, 63173, 63174, 63175, 63176, 63177, 63178, 63179, 63100, 63101, 63102, 63103]
[2015-07-22 08:42:46.927486] INFO 485939519 Name of starting vessel: v1
[2015-07-22 08:42:46.927856] DEBUG 485939519 Calling: get_resource_data (module node_transition_lib), args: ('resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n', [63124, 63155, 63148, 63135, 63104, 63147, 63101, 63156, 63122, 63111, 63119, 63132, 63140, 63103, 63133, 63144, 63151, 63174, 63125, 63173, 63112, 63162, 63134, 63100, 63165, 63114, 63170, 63139, 63157, 63129, 63128, 63126, 63107, 63118, 63136, 63177, 63158, 63108, 63116, 63123, 63159, 63169, 63160, 63153, 63178, 63109, 63176, 63141, 63166, 63150, 63142, 63138, 63164, 63143, 63127, 63179, 63137, 63120, 63105, 63171, 63167, 63102, 63113, 63172, 63131, 63145, 63106, 63117, 63130, 63168, 63152, 63146, 63154, 63161, 63149, 63121, 63110, 63163, 63175, 63115]), kwargs: ().
[2015-07-22 08:42:46.928148] DEBUG 485939519 Returning from get_resource_data (module node_transition_lib) (time 0:00:00.000058): resource cpu .02
resource memory 25000000   # 25 MiB
resource diskused 100000000 # 100 MiB
resource events 50
resource filewrite 10000
resource fileread 10000
resource filesopened 10
resource insockets 10
resource outsockets 10
resource netsend 10000
resource netrecv 10000
resource loopsend 100000
resource looprecv 100000
resource lograte 10000
resource random 1000
resource messport 63124
resource messport 63155
resource messport 63148
resource messport 63135
resource messport 63104
resource messport 63147
resource messport 63101
resource messport 63156
resource messport 63122
resource messport 63111
resource connport 63124
resource connport 63155
resource connport 63148
resource connport 63135
resource connport 63104
resource connport 63147
resource connport 63101
resource connport 63156
resource connport 63122
resource connport 63111

[2015-07-22 08:42:46.928463] INFO 485939519 Ports we are going to use for the new vessel: [63124, 63155, 63148, 63135, 63104, 63147, 63101, 63156, 63122, 63111]
[2015-07-22 08:42:46.928711] INFO 485939519 Starting to split vessel: v1
[2015-07-22 08:42:46.928997] DEBUG 485939519 Calling: split_vessel (module clearinghouse.common.api.backend), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, u'v1', 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport 63124\nresource messport 63155\nresource messport 63148\nresource messport 63135\nresource messport 63104\nresource messport 63147\nresource messport 63101\nresource messport 63156\nresource messport 63122\nresource messport 63111\nresource connport 63124\nresource connport 63155\nresource connport 63148\nresource connport 63135\nresource connport 63104\nresource connport 63147\nresource connport 63101\nresource connport 63156\nresource connport 63122\nresource connport 63111\n'), kwargs: ().
[2015-07-22 08:42:55.104192] DEBUG 485939519 Exception from split_vessel (module clearinghouse.common.api.backend): <class 'clearinghouse.common.exceptions.NodemanagerCommunicationError'> Node communication failure: NodeManager request failed with node ('65537 ---NODE_PUBKEY---', u'b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74', 1224L): Traceback (most recent call last):
  File "/home/ch/deployment/clearinghouse/common/api/nodemanager.py", line 518, in _do_signed_call
  File "/home/ch/deployment/seattle/nmclient.r2py", line 384, in nmclient_signedsay
NMClientException: Node Manager error 'Proposed vessel is too large.
Insufficient quantity: Resource 'diskused' has a negative quantity'

[2015-07-22 08:42:55.104641] INFO 485939519 Could not split v1 any further due to insufficient resource/quantity. Node communication failure: NodeManager request failed with node ('65537 ---NODE_PUBKEY---', u'b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74', 1224L): Traceback (most recent call last):
  File "/home/ch/deployment/clearinghouse/common/api/nodemanager.py", line 518, in _do_signed_call
  File "/home/ch/deployment/seattle/nmclient.r2py", line 384, in nmclient_signedsay
NMClientException: Node Manager error 'Proposed vessel is too large.
Insufficient quantity: Resource 'diskused' has a negative quantity'

[2015-07-22 08:42:55.104845] INFO 485939519 Finished splitting vessels up for the node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:55.105155] DEBUG 485939519 Returning from split_vessels (module node_transition_lib) (time 0:00:13.973103): None
[2015-07-22 08:42:55.105439] INFO 485939519 Trying to set new state for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:42:55.105990] DEBUG 485939519 Calling: set_node_state (module node_transition_lib), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, {'e': 65537L, 'n': ---TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:42:55.106343] DEBUG 485939519 Calling: set_vessel_user_keylist (module clearinghouse.common.api.backend), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>, u'v1', ['65537 ---TWOPERCENT---']), kwargs: ().
[2015-07-22 08:43:01.072977] DEBUG 485939519 Returning from set_vessel_user_keylist (module clearinghouse.common.api.backend) (time 0:00:05.966403): None
[2015-07-22 08:43:01.073357] INFO 485939519 Successfully changed the node state to {'e': 65537L, 'n': ---TWOPERCENT---L}
[2015-07-22 08:43:01.073548] DEBUG 485939519 Returning from set_node_state (module node_transition_lib) (time 0:00:05.967368): None
[2015-07-22 08:43:01.073824] DEBUG 485939519 Calling: mark_node_as_active (module clearinghouse.common.api.maindb), args: (<Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>,), kwargs: ().
[2015-07-22 08:43:01.084726] DEBUG 485939519 Returning from mark_node_as_active (module clearinghouse.common.api.maindb) (time 0:00:00.010464): None
[2015-07-22 08:43:01.084877] INFO 485939519 Finished setting new state twopercent on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:43:01.091176] INFO 485939519 released lock for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:01.095527] INFO 485939519 Destroyed lockserver_handle for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:01.095687] DEBUG 485939519 Returning from processnode (module node_transition_lib) (time 0:00:33.293747): True
[2015-07-22 08:43:01.844304] INFO 654222770 Success on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224. Returnvalue: True
[2015-07-22 08:43:01.845612] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:43:01.846003] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:34.044607): (1, 0)
[2015-07-22 08:43:01.846289] INFO 654222770 Succeeded on 1 nodes, Failed on 0 nodes
[2015-07-22 08:43:01.846614] INFO 654222770 Looking up nodes to transition from movingto_twopercent state to canonical state
[2015-07-22 08:43:01.847157] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('movingto_twopercent', {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}), kwargs: ().
[2015-07-22 08:43:01.847583] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:43:01.847844] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L},), kwargs: ().
[2015-07-22 08:43:02.707959] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:00.859948): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:43:02.708306] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:00.860883): (True, ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'])
[2015-07-22 08:43:02.708617] INFO 654222770 List of ip/NAT found in advertise_lookup(): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:43:02.708948] INFO 654222770 Length of nodeprocesslist: 1
[2015-07-22 08:43:02.709203] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:43:02.709583] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: (['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'], 'canonical_to_twopercent', 10, 'movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:43:02.710327] DEBUG 726326972 Calling: processnode (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', 'movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:43:02.710596] INFO 726326972 Starting to process node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:43:10.421448] DEBUG 726326972 Calling: create_lockserver_handle (module clearinghouse.common.api.lockserver), args: (), kwargs: ().
[2015-07-22 08:43:10.423802] DEBUG 726326972 Returning from create_lockserver_handle (module clearinghouse.common.api.lockserver) (time 0:00:00.002042): {'proxy': <ServerProxy for 127.0.0.1:8010/RPC2>, 'session_id': '6291343'}
[2015-07-22 08:43:10.424001] INFO 726326972 Created lockserver_handle for use on node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:10.425940] INFO 726326972 Acquired node lock for nodeID: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:10.426646] INFO 726326972 Retrieving node vesseldict for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:43:19.136290] INFO 726326972 Successfully retrieved node_info for node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:43:19.136388] DEBUG 726326972 Calling: get_node (module clearinghouse.common.api.maindb), args: ('65537 ---NODE_PUBKEY---',), kwargs: ().
[2015-07-22 08:43:19.138653] DEBUG 726326972 Calling: init_maindb (module clearinghouse.common.api.maindb), args: (), kwargs: ().
[2015-07-22 08:43:19.139139] DEBUG 726326972 Resetting django query log because settings.DEBUG is True.
[2015-07-22 08:43:19.139324] ERROR 726326972 Reminder: settings.DEBUG is True. Don't run in production like this!
[2015-07-22 08:43:19.139530] DEBUG 726326972 Returning from init_maindb (module clearinghouse.common.api.maindb) (time 0:00:00.000649): None
[2015-07-22 08:43:19.151436] DEBUG 726326972 Returning from get_node (module clearinghouse.common.api.maindb) (time 0:00:00.014984): Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
[2015-07-22 08:43:19.151859] DEBUG 726326972 Calling: get_node_state (module node_transition_lib), args: ({'nodename': '192.168.99.7', 'nodekey': {'e': 65537L, 'n': ---NODE_PUBKEY---L}, 'version': 'testch-20150721-1440', 'vessels': {'v1': {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}, 'v2': {'status': 'Fresh', 'userkeys': [], 'ownerkey': {'e': 65537L, 'n': ---SERVICEVESSEL_PUBKEY---}, 'ownerinfo': '', 'advertise': True}}}, <Node: Node:65537_1484:b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224>), kwargs: ().
[2015-07-22 08:43:19.152057] INFO 726326972 Starting get node state for node 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:19.152169] INFO 726326972 Name of extra vessel: v1
[2015-07-22 08:43:19.152383] INFO 726326972 Extra vessel info: {'status': 'Fresh', 'userkeys': [{'e': 65537L, 'n': ---TWOPERCENT---L}], 'ownerkey': {'e': 65537L, 'n': ---NODE_OWNERKEY---}, 'ownerinfo': '', 'advertise': True}
[2015-07-22 08:43:19.152622] DEBUG 726326972 Returning from get_node_state (module node_transition_lib) (time 0:00:00.000480): {'e': 65537L, 'n': ---TWOPERCENT---L}
[2015-07-22 08:43:19.152929] INFO 726326972 The node is not in the right transition state. NodeID is: 65537 ---NODE_PUBKEY--- Current state is {'e': 65537L, 'n': ---TWOPERCENT---L}. Should be in state {'e': 65537L, 'n': ---MOVINGTO_TWOPERCENT---L}
[2015-07-22 08:43:19.153140] INFO 726326972 Node data problem when processing node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224Traceback (most recent call last):
  File "/home/ch/deployment/clearinghouse/node_state_transitions/node_transition_lib.py", line 428, in processnode
NodeError: Node is no longer in the right state!

[2015-07-22 08:43:19.156679] INFO 726326972 released lock for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:19.158497] INFO 726326972 Destroyed lockserver_handle for node: 65537 ---NODE_PUBKEY---
[2015-07-22 08:43:19.158647] DEBUG 726326972 Returning from processnode (module node_transition_lib) (time 0:00:16.448069): False
[2015-07-22 08:43:19.729427] INFO 654222770 Failure on node b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224.
[2015-07-22 08:43:19.729733] INFO 654222770 Cleaning up and closing parallel_handle
[2015-07-22 08:43:19.730222] DEBUG 654222770 Returning from run_parallel_processes (module node_transition_lib) (time 0:00:17.020418): (0, 1)
[2015-07-22 08:43:19.730490] INFO 654222770 Succeeded on 0 nodes, Failed on 1 nodes
[2015-07-22 08:43:19.730896] DEBUG 654222770 Returning from do_one_processnode_run (module node_transition_lib) (time 0:01:07.938879): [(0, 1), (1, 0), (0, 1)]
[2015-07-22 08:43:19.731636] INFO 654222770 Finished running do_one_processnode_run(), going to sleep for 10 seconds
[2015-07-22 08:43:29.741987] INFO 654222770 Waking up from sleep.....
[2015-07-22 08:43:29.742222] DEBUG 654222770 Calling: do_one_processnode_run (module node_transition_lib), args: ([('canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), ('movingto_twopercent', 'twopercent', <function split_vessels at 0x7f009b4ed668>, <function noop at 0x7f009b4eded8>, True, 'resource cpu .02\nresource memory 25000000   # 25 MiB\nresource diskused 100000000 # 100 MiB\nresource events 50\nresource filewrite 10000\nresource fileread 10000\nresource filesopened 10\nresource insockets 10\nresource outsockets 10\nresource netsend 10000\nresource netrecv 10000\nresource loopsend 100000\nresource looprecv 100000\nresource lograte 10000\nresource random 1000\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource messport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\nresource connport %s\n'), ('movingto_twopercent', 'canonical', <function combine_vessels at 0x7f009b4ed848>, <function noop at 0x7f009b4eded8>, False)], 'canonical_to_twopercent', 10), kwargs: ().
[2015-07-22 08:43:29.742281] INFO 654222770 Looking up nodes to transition from canonical state to movingto_twopercent state
[2015-07-22 08:43:29.742495] DEBUG 654222770 Calling: find_advertised_nodes (module node_transition_lib), args: ('canonical', {'e': 65537L, 'n': ---CANONICAL_KEY---}), kwargs: ().
[2015-07-22 08:43:29.742720] INFO 654222770 Looking for nodes with public key: 
{'e': 65537L, 'n': ---CANONICAL_KEY---}
[2015-07-22 08:43:29.742958] DEBUG 654222770 Calling: _do_advertise_lookup (module node_transition_lib), args: ({'e': 65537L, 'n': ---CANONICAL_KEY---},), kwargs: ().
[2015-07-22 08:43:29.948144] DEBUG 654222770 Returning from _do_advertise_lookup (module node_transition_lib) (time 0:00:00.205114): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:43:29.948478] DEBUG 654222770 Returning from find_advertised_nodes (module node_transition_lib) (time 0:00:00.205845): (True, ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'])
[2015-07-22 08:43:29.948738] INFO 654222770 List of ip/NAT found in advertise_lookup(): ['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224']
[2015-07-22 08:43:29.949055] INFO 654222770 Length of nodeprocesslist: 1
[2015-07-22 08:43:29.949322] INFO 654222770 Starting run_parallel_process to spawn threads to process nodes...
[2015-07-22 08:43:29.949643] DEBUG 654222770 Calling: run_parallel_processes (module node_transition_lib), args: (['b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224'], 'canonical_to_twopercent', 10, 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:43:29.950307] DEBUG 815606562 Calling: processnode (module node_transition_lib), args: ('b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224', 'canonical', 'movingto_twopercent', <function noop at 0x7f009b4eded8>, <function noop at 0x7f009b4eded8>, False), kwargs: ().
[2015-07-22 08:43:29.950598] INFO 815606562 Starting to process node: b6f1f1d9aaa64ba9d1507acd4d0bc3dcafb9ab74:1224
@aaaaalbert
Copy link
Contributor Author

And indeed, when the node has sufficient resources, the clearinghouse makes vessels out of it! The node at hand now has v2, the service vessel, and v16, v18, v20, v22 as publicly available vessels.

Now, v21 remains as the thing that's smaller than the split size which the CH wants, and thus isn't added to the database. Note that it is still advertised, has a proper resource file, its sandbox dir, etc.!

Grepping through the transition script logs reveals the split / join action that leads to the final vessels:

$ pbpaste | grep "Successfully split vessel" 
[2015-07-22 10:17:16.370742] INFO 501433424 Successfully split vessel: v1 into vessels: v3 and v4
[2015-07-22 10:17:42.303067] INFO 501433424 Successfully split vessel: v3 into vessels: v5 and v6
[2015-07-22 10:18:07.205756] INFO 501433424 Successfully split vessel: v5 into vessels: v7 and v8
[2015-07-22 10:18:33.305296] INFO 501433424 Successfully split vessel: v7 into vessels: v9 and v10
[2015-07-22 10:21:55.195078] INFO 992914479 Successfully split vessel: v14 into vessels: v15 and v16
[2015-07-22 10:22:10.511091] INFO 992914479 Successfully split vessel: v15 into vessels: v17 and v18
[2015-07-22 10:22:35.191658] INFO 992914479 Successfully split vessel: v17 into vessels: v19 and v20
[2015-07-22 10:23:02.734442] INFO 992914479 Successfully split vessel: v19 into vessels: v21 and v22
$ pbpaste | grep "Combined vessel" 
[2015-07-22 10:19:27.222187] INFO 945190750 Combined vessel v9 and v10 into v11
[2015-07-22 10:19:45.981188] INFO 945190750 Combined vessel v11 and v4 into v12
[2015-07-22 10:19:54.088218] INFO 945190750 Combined vessel v12 and v6 into v13
[2015-07-22 10:20:01.953274] INFO 945190750 Combined vessel v13 and v8 into v14

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@aaaaalbert