noelbk/gist:9788358

## gistfile1.txt
The ContrailApi task depends on group:Zookeeper

    class ContrailApi(Task):
	"""Contrail API Server running on every node"""
	DEPENDS = ['group:NetworkConf', 'group:Hosts', 'group:KeystoneConf', 'group:NeutronConf',
		   'group:Redis', 'group:Ifmap', 'group:Cassandra', 'id:Zookeeper', 'id:ContrailDiscovery']
	GROUPS = ['Contrail']

	@property
	def port(self):
	    """Port the Contrail api server listens on"""
	    return 8022

	def configure(self, bootflags, **_kw):
	    ContrailApiJob(task=self).configure()

	def start(self, bootflags, **_kw):
	    ContrailApiJob(task=self).restart()

Zookeeper defines @property for ip and port

    class Zookeeper(Task):
	DEPENDS = ['group:Hosts']
	GROUPS  = ['Zookeeper']

	@property
	def port(self):
	    """standard zookeeper port"""
	    return 2181

	@property
	def ip(self):
	    """Zookeeper always runs on the local node"""
	    return self.depends['group:Hosts'].get_current_host().ip

The template references the port and ip properties

    zk_server_ip=$task.depends['group:Zookeeper'].ip:$task.depends['group:Zookeeper'].port

but the property lookup fails in unit tests

      File "contrail_api_server_conf_template.py", line 133, in respond
    NotFound: cannot find 'ip' while searching for 'ip'


$ nosetests -x ./tests/unit/test_fred.py

TestFredBoot
    test_firstboot_fake_zk_child                                 ERROR  0.45

======================================================================
ERROR: test_firstboot_fake_zk_child (tests.unit.test_fred.TestFredBoot)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/noel/projects/piston/projects/pentos/savage/tests/unit/test_fred.py", line 2016, in test_firstboot_fake_zk_child
    self.fred_realish_config_firstboot(enabled=(CHILD, FIRST, NOVANET))
  File "/home/noel/projects/piston/projects/pentos/savage/tests/unit/test_fred.py", line 761, in fred_realish_config_firstboot
    self.simulate_fred(enabled)
  File "/home/noel/projects/piston/projects/pentos/savage/tests/unit/test_fred.py", line 694, in simulate_fred
    expected_files = self.fred_new_message(enabled)
  File "/home/noel/projects/piston/projects/pentos/savage/tests/unit/test_fred.py", line 812, in fred_new_message
    f.step(Input=machines.SendConfig(mode=machines.SendConfigMode.full, config=self.config))
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 694, in step
    effect.extend(super(QueueNFA, self).step(Input=i))
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 652, in step
    self.__newstate(trans['state'], acc, trigger=True)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 622, in __newstate
    self.__newstate(ret, acc, trigger=True)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 620, in __newstate
    ret = self.__state_action_helper(state)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 587, in __state_action_helper
    ret = action()
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/nfa.py", line 246, in newaction
    return cls.__decorate_action_return(func(*args, **kw), method=newname)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/services/fred.py", line 733, in action_firstboot_full
    self.__run_start_phase('configure', partial=False)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/services/fred.py", line 957, in __run_start_phase
    run_phase(task, phase, interface_kwargs)
  File "/home/noel/projects/piston/projects/pentos/savage/tests/unit/test_fred.py", line 553, in fake_execute_task
    ret = self.__real_run_phase(task, phase, args)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/services/fred.py", line 982, in run_phase
    return getattr(task, phase)(**kwargs)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/jobs/contrail.py", line 225, in configure
    ContrailApiJob(task=self).configure()
  File "/home/noel/projects/piston/projects/pentos/savage/savage/command/utils/job.py", line 223, in configure
    dirty = cfg(*args, **kw).write()
  File "/home/noel/projects/piston/projects/pentos/savage/savage/utils/config.py", line 238, in write
    changed_config = template.write_output(self.output_file, self.build())
  File "/home/noel/projects/piston/projects/pentos/savage/savage/jobs/contrail.py", line 191, in build
    return template.build_template('contrail_api_server.conf.template', data)
  File "/home/noel/projects/piston/projects/pentos/savage/savage/command/template.py", line 41, in build_template
    return str(t(namespaces=data))
  File "/home/noel/projects/piston/projects/pentos/savage/venv/local/lib/python2.7/site-packages/Cheetah/Template.py", line 1005, in __str__
    rc = getattr(self, mainMethName)()
  File "contrail_api_server_conf_template.py", line 133, in respond
NotFound: cannot find 'ip' while searching for 'ip'
-------------------- >> begin captured logging << --------------------
savage.test: DEBUG: ********************************************** entering TestHelper.setUp ***********************************************
savage.test: DEBUG: **** patching interfaces with <MagicMock name='interfaces.__name__' id='84707344'>
savage.test: DEBUG: **** patching iface_is_phy(savage/command/utils/system.py:57) with <lambda>(tests/utils.py:868)
savage.test: DEBUG: **** patching iface_speed(savage/command/utils/system.py:64) with <lambda>(tests/utils.py:869)
savage.test: DEBUG: **** patching getHwAddr(savage/command/utils/system.py:270) with <lambda>(tests/utils.py:870)
savage.test: DEBUG: **** patching getIps(savage/command/utils/system.py:301) with getIps(<string>:1)
savage.test: DEBUG: **** patching ifaddresses with <MagicMock name='ifaddresses.__name__' id='84740176'>
savage.test: DEBUG: **** patching _lan_print_base(savage/command/utils/ipmi.py:46) with _lan_print_base(<string>:1)
savage.test: DEBUG: **** patching HTTPAdapter with <functools.partial object at 0x50cafc8>
savage.test: DEBUG: fake_execute called with () {}
savage.test: INFO: norecord helper
savage.test: DEBUG: **** patching execute(savage/utils/execution.py:76) with <MagicMock id='84773072'>
savage.test: DEBUG: **** patching execute_pexpect(savage/utils/execution.py:142) with pexpect_to_execute(tests/utils.py:974)
savage.test: DEBUG: **** patching spawn with <MagicMock name='spawn' spec_set='spawn' id='84788368'>
savage.test: DEBUG: **** patching <lambda>(savage/utils/retry_manager.py:34) with <lambda>(tests/utils.py:980)
savage.test: DEBUG: **** patching inf with 2
savage.test: DEBUG: **** patching chown_name(savage/command/utils/system.py:33) with fake_chown(tests/utils.py:944)
savage.test: DEBUG: **** patching chmod(savage/command/utils/system.py:39) with fake_chmod(tests/utils.py:952)
savage.test: DEBUG: **** patching /proc/cpuinfo with /home/noel/projects/piston/projects/pentos/savage/tests/data/cpuinfo/node-18a
savage.test: DEBUG: **** patching package_install_path(savage/utils/filenames.py:54) with <lambda>(tests/utils.py:985)
savage.test: DEBUG: **** patching None with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/tmp
savage: INFO: making sure /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root is gone
savage: INFO: making sure /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root is recursively gone
savage.test: DEBUG: **** patching PrettyPrinter with MyPrettyPrinter
savage.test: DEBUG: **** patching loads(/usr/lib/python2.7/json/__init__.py:293) with loads(savage/utils/json.py:28)
savage.test: DEBUG: **** patching dumps(/usr/lib/python2.7/json/__init__.py:193) with dumps(savage/utils/json.py:17)
savage.test: DEBUG: **** patching shutdown_runnable_index(savage/moxie/task_manager.py:164) with name_based_index(tests/utils.py:1024)
savage.test: DEBUG: *********************************************** leaving TestHelper.setUp ***********************************************
savage.test: DEBUG: **** patching run_phase(savage/services/fred.py:981) with fake_execute_task(tests/unit/test_fred.py:549)
savage.test: DEBUG: **** patching get_baked_version(savage/utils/config.py:132) with get_baked_version(<string>:1)
savage.test: DEBUG: **** patching <MagicMock name='ifaddresses.__name__' id='84740176'> with <MagicMock name='ifaddresses.__name__' id='85539792'>
savage.test: DEBUG: **** patching _lan_print_base(<string>:1) with fake_lan_print(tests/utils.py:325)
stevedore.extension: DEBUG: found extension EntryPoint.parse('NovaServiceState = savage.jobs:NovaServiceState')
stevedore.extension: DEBUG: found extension EntryPoint.parse('BootNode = savage.jobs:BootNode')
stevedore.extension: DEBUG: found extension EntryPoint.parse('BasicConfiguration = savage.jobs:BasicConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('BeforeNova = savage.jobs:BeforeNova')
stevedore.extension: DEBUG: found extension EntryPoint.parse('KeystoneLoadBalancer = savage.jobs:KeystoneLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('MoveCrashDumps = savage.jobs:MoveCrashDumps')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Redis = savage.jobs.redis:Redis')
stevedore.extension: DEBUG: found extension EntryPoint.parse('RadosgwConfiguration = savage.jobs:RadosgwConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Nova = savage.jobs:Nova')
stevedore.extension: DEBUG: found extension EntryPoint.parse('KeystoneConfiguration = savage.jobs:KeystoneConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CinderFinalSetup = savage.jobs:CinderFinalSetup')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CephWatchdog = savage.jobs.ceph_kick:CephWatchdog')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Keystone = savage.jobs:Keystone')
stevedore.extension: DEBUG: found extension EntryPoint.parse('AuxiliaryNetwork = savage.jobs.network:AuxiliaryNetwork')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Radosgw = savage.jobs:Radosgw')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Mysql = savage.jobs:Mysql')
stevedore.extension: DEBUG: found extension EntryPoint.parse('MyHost = savage.jobs:MyHost')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Snmpd = savage.jobs:Snmpd')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NovaConfiguration = savage.jobs:NovaConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Neutron = savage.jobs.neutron:Neutron')
stevedore.extension: DEBUG: found extension EntryPoint.parse('LocalDisk = savage.jobs:LocalDisk')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Ceph = savage.jobs:Ceph')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NetTest = savage.jobs.network:NetTest')
stevedore.extension: DEBUG: found extension EntryPoint.parse('AuthStoreConfiguration = savage.jobs.auth:AuthStoreConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('ShutdownLevels = savage.services.fred:ShutdownLevels')
stevedore.extension: DEBUG: found extension EntryPoint.parse('LocalDiskConfiguration = savage.jobs:LocalDiskConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('SnmpdConfiguration = savage.jobs:SnmpdConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('GlanceConfiguration = savage.jobs:GlanceConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('LibvirtSave = savage.jobs:LibvirtSave')
stevedore.extension: DEBUG: found extension EntryPoint.parse('ContrailDiscovery = savage.jobs.contrail:ContrailDiscovery')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Memcache = savage.jobs:Memcache')
stevedore.extension: DEBUG: found extension EntryPoint.parse('SSLConfiguration = savage.jobs:SSLConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('RabbitConfiguration = savage.jobs:RabbitConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Rabbit = savage.jobs:Rabbit')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Apache = savage.jobs:Apache')
stevedore.extension: DEBUG: found extension EntryPoint.parse('RadosgwLoadBalancer = savage.jobs:RadosgwLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('KeystoneFinalSetup = savage.jobs:KeystoneFinalSetup')
stevedore.extension: DEBUG: found extension EntryPoint.parse('FirewallConfiguration = savage.jobs.network:FirewallConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NeutronConfiguration = savage.jobs.neutron:NeutronConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('UpstreamServers = savage.jobs.network:UpstreamServers')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Debug = savage.jobs:Debug')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NoVNC = savage.jobs:NoVNC')
stevedore.extension: DEBUG: found extension EntryPoint.parse('DashboardLoadBalancer = savage.jobs:DashboardLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('DashboardConfiguration = savage.jobs:DashboardConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('WriteUUID = savage.jobs:WriteUUID')
stevedore.extension: DEBUG: found extension EntryPoint.parse('HostStoreConfiguration = savage.jobs:HostStoreConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NovaLoadBalancer = savage.jobs:NovaLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Ifmap = savage.jobs.ifmap:Ifmap')
stevedore.extension: DEBUG: found extension EntryPoint.parse('GrandpaConfiguration = savage.machines:GrandpaConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Hosts = savage.jobs:Hosts')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Dashboard = savage.jobs:Dashboard')
stevedore.extension: DEBUG: found extension EntryPoint.parse('MysqlConfiguration = savage.jobs:MysqlConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NoVNCConfiguration = savage.jobs:NoVNCConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Cinder = savage.jobs:Cinder')
stevedore.extension: DEBUG: found extension EntryPoint.parse('OpenstackInternal = savage.jobs:OpenstackInternal')
stevedore.extension: DEBUG: found extension EntryPoint.parse('BeforeNeutron = savage.jobs.neutron:BeforeNeutron')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NetworkConfiguration = savage.jobs.network:NetworkConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('BootNodeMinimalConfiguration = savage.machines:BootNodeMinimalConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('NovaNetworkFinalSetup = savage.jobs:NovaNetworkFinalSetup')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CephMounted = savage.jobs:CephMounted')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CephReplication = savage.jobs:CephReplication')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Firewall = savage.jobs.network:Firewall')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Zookeeper = savage.jobs:Zookeeper')
stevedore.extension: DEBUG: found extension EntryPoint.parse('GlanceLoadBalancer = savage.jobs:GlanceLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('FredConfiguration = savage.services.fred:FredConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CinderLoadBalancer = savage.jobs:CinderLoadBalancer')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Cron = savage.jobs:Cron')
stevedore.extension: DEBUG: found extension EntryPoint.parse('ContrailApi = savage.jobs.contrail:ContrailApi')
stevedore.extension: DEBUG: found extension EntryPoint.parse('LibVirtd = savage.jobs:LibVirtd')
stevedore.extension: DEBUG: found extension EntryPoint.parse('SSH = savage.jobs:SSH')
stevedore.extension: DEBUG: found extension EntryPoint.parse('SupportConfiguration = savage.services.support:SupportConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('CinderConfiguration = savage.jobs:CinderConfiguration')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Openstack = savage.jobs:Openstack')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Glance = savage.jobs:Glance')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Disk = savage.jobs:Disk')
stevedore.extension: DEBUG: found extension EntryPoint.parse('PublicApi = savage.jobs.api:PublicApi')
stevedore.extension: DEBUG: found extension EntryPoint.parse('Cassandra = savage.jobs.cassandra:Cassandra')
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: DEBUG: **** patching ensure_keystone(savage/command/commands/keystone.py:105) with ensure_keystone(<string>:1)
savage.test: DEBUG: **** patching Client with <tests.fakes.fake_neutron.FakeClient object at 0x5198fd0>
savage.test: DEBUG: **** patching clear_locks(savage/utils/logging.py:32) with clear_locks(<string>:1)
savage.test: DEBUG: **** patching 10 with 1
savage: INFO: Temporarily setting loglevel to ERROR
savage: INFO: Restoring loglevel to NOTSET
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: DEBUG: **** patching mkfs(savage/utils/logging.py:32) with mkfs_mocker(tests/unit/test_fred.py:514)
savage.test: DEBUG: **** patching virtual_memory(venv/local/lib/python2.7/site-packages/psutil/__init__.py:1605) with virtual_memory(<string>:1)
savage.test: DEBUG: **** patching run(savage/medic/agent.py:335) with child_runfunc(tests/unit/test_fred.py:468)
savage.test: DEBUG: **** patching wait(savage/medic/agent.py:311) with wait(<string>:1)
savage.test: DEBUG: **** patching join(savage/medic/agent.py:118) with join(<string>:1)
savage.test: DEBUG: **** patching force_quit(savage/medic/agent.py:95) with child_stopfunc(tests/unit/test_fred.py:488)
savage.test: DEBUG: **** patching run(savage/medic/one_time_agent.py:101) with child_runfunc(tests/unit/test_fred.py:468)
savage.test: DEBUG: **** patching Client with <tests.fakes.fake_nova.FakeClient object at 0x5b40410>
savage.fake_keystone: DEBUG: Created new keystone client with {}
savage.test: DEBUG: **** patching Client with <tests.fakes.fake_keystone.FakeClient object at 0x5b404d0>
savage.test: DEBUG: **** patching Client with <tests.fakes.fake_cinder.FakeClient object at 0x5b405d0>
savage.test: DEBUG: **** patching SSHConnection with FakeSSH
savage.test: DEBUG: **** patching mkdtemp(/usr/lib/python2.7/tempfile.py:307) with fake_mkdtemp(tests/utils.py:1652)
savage.test: DEBUG: **** patching start(venv/local/lib/python2.7/site-packages/kazoo/client.py:504) with start(<string>:1)
savage.test: DEBUG: **** patching ZookeeperSentinelOnce(savage/medic/zookeeper_sync.py:191) with stub_sentinel_once(tests/unit/test_fred.py:504)
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: DEBUG: **** patching getIps(<string>:1) with <lambda>(tests/unit/test_fred.py:540)
savage.test: DEBUG: **** patching health_val(savage/utils/logging.py:32) with health_val(<string>:1)
savage.test: DEBUG: **** patching add_monitor(savage/utils/logging.py:32) with add_monitor(<string>:1)
savage.test: DEBUG: **** patching suicide(savage/command/utils/system.py:126) with suicide(<string>:1)
savage: INFO: Called execute_blkid
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_blkid returned
savage: INFO: Called execute_list_block
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute 'split' due to <unbound method _DiskDataMixin.execute_list_block>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_list_block returned ['loop0', 'loop0', 'nbd0', 'nbd0', 'ram0', 'ram0', 'rbd0', 'rbd0', 'rbd1', 'rbd1', 'sda', 'sdb']
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd1
savage: DEBUG: ignoring block device rbd1
savage: INFO: Analyzing sda
savage: INFO: Called execute_is_removable
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_removable>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_removable returned False
savage: INFO: Called execute_get_iops
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_iops>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_iops returned 100
savage: INFO: Called execute_get_bandwidth
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_bandwidth>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_bandwidth returned 150000
savage: INFO: Called execute_get_hdparm
savage: INFO: Called get_disk_info
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_hdparm>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_hdparm returned ('SATAMODELFAKE1', 'FAKESATASERIALsda', '3 TB')
savage: INFO: Called execute_is_ssd
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_ssd>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_ssd returned False
savage: INFO: disk sda reports {'serial_num': 'FAKESATASERIALsda', 'failed': False, 'removable': False, 'ssd': False, 'model': 'SATAMODELFAKE1', 'size': '3 TB', 'speed': {'rand_read_iops': 100, 'seq_read_bw': 150000}, 'partitions': {}}
savage: INFO: Analyzing sdb
savage: INFO: Called execute_is_removable
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_removable>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_removable returned False
savage: INFO: Called execute_get_iops
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_iops>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_iops returned 100
savage: INFO: Called execute_get_bandwidth
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_bandwidth>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_bandwidth returned 150000
savage: INFO: Called execute_get_hdparm
savage: INFO: Called get_disk_info
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_hdparm>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_hdparm returned ('SATAMODELFAKE1', 'FAKESATASERIALsdb', '3 TB')
savage: INFO: Called execute_is_ssd
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_ssd>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_ssd returned False
savage: INFO: disk sdb reports {'serial_num': 'FAKESATASERIALsdb', 'failed': False, 'removable': False, 'ssd': False, 'model': 'SATAMODELFAKE1', 'size': '3 TB', 'speed': {'rand_read_iops': 100, 'seq_read_bw': 150000}, 'partitions': {}}
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=[]), trying partition comparison
savage: DEBUG: no partition match found (partitions=[]), trying partition comparison
savage: DEBUG: disk identified as unknown
savage: INFO: update_dtype returned None
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=[]), trying partition comparison
savage: DEBUG: no partition match found (partitions=[]), trying partition comparison
savage: DEBUG: disk identified as unknown
savage: INFO: update_dtype returned None
savage: INFO: refresh done, drives = [<Disk: 0x5c27d10 dev=sda type=unknown, parts: []>, <Disk: 0x5c29550 dev=sdb type=unknown, parts: []>]
savage.test: DEBUG: **** patching ismount(venv/lib/python2.7/posixpath.py:189) with ismount(tests/fakes/fake_mount_manager.py:60)
savage.test: DEBUG: **** patching get_mount_point(savage/utils/logging.py:32) with mount_point(tests/fakes/fake_mount_manager.py:65)
savage.test: DEBUG: **** patching lspools(savage/utils/logging.py:32) with lspools(tests/unit/test_fred.py:78)
savage.test: DEBUG: **** patching rbd_list(savage/utils/logging.py:32) with rbd_list(tests/unit/test_fred.py:76)
savage.test: DEBUG: **** patching mon_command(savage/utils/logging.py:32) with mon_command(tests/unit/test_fred.py:240)
savage.test: DEBUG: fake_execute called with () {'match': {'keystone-manage token list': <bound method KeystoneManager.list_tokens of <tests.unit.test_fred.KeystoneManager object at 0x5c29810>>, 'lvcreate .*': <bound method FakeVgmgr.lvcreate of <tests.fakes.fake_vgmgr.FakeVgmgr object at 0x5c296d0>>, 'umount .*': <function <lambda> at 0x5c238c0>, 'mdadm --create .*': <function mdadm at 0x5c236e0>, 'ceph quorum_status': <bound method CephManager.quorum_status of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'mkcephfs .*': <bound method CephManager.mkcephfs of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'lvdisplay .*': <bound method FakeVgmgr.lvdisplay of <tests.fakes.fake_vgmgr.FakeVgmgr object at 0x5c296d0>>, 'nova-manage floating list': <bound method NovaManager.list_ips of <tests.unit.test_fred.NovaManager object at 0x5c29850>>, 'crushtool --enable-unsafe-tunables -d .*': <bound method CephManager.crushtool_first of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'ceph osd create *': <function <lambda> at 0x5c23a28>, 'ceph osd pool create \\S+ \\d+ \\d+': <function <lambda> at 0x5c239b0>, 'pvscan': <bound method FakeVgmgr.pvscan of <tests.fakes.fake_vgmgr.FakeVgmgr object at 0x5c296d0>>, 'ceph.*fsid.*--concise': <bound method CephManager.fsid of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'ceph status --format=json': <bound method CephManager.ceph_status of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'ceph.*osd.*dump': 'max_osd 0', 'pvcreate .*': <bound method FakeVgmgr.pvcreate of <tests.fakes.fake_vgmgr.FakeVgmgr object at 0x5c296d0>>, 'keystone-manage token add .*': <function <lambda> at 0x5c237d0>, 'nova-manage floating create .*': <function <lambda> at 0x5c23848>, 'mount .*': <bound method MountManager.mount of <tests.fakes.fake_mount_manager.MountManager object at 0x5c29890>>, 'ceph-osd.*--mkfs': <bound method CephManager.ceph_osd of <tests.unit.test_fred.CephManager object at 0x5c29590>>, 'df -B GB .*': <function <lambda> at 0x5c23938>, 'mountpoint -q .*osd[0-9]+': <tests.unit.test_fred.CephManager object at 0x5c29590>, '^rbd .*': <tests.unit.test_fred.RbdManager object at 0x5c29750>, 'dd if=/dev/zero of=.*': <function mkjournal at 0x5c23758>, 'vgchange .*': <bound method FakeVgmgr.vgchange of <tests.fakes.fake_vgmgr.FakeVgmgr object at 0x5c296d0>>}}
savage.test: INFO: norecord helper
savage.test: DEBUG: **** patching <MagicMock id='84773072'> with <MagicMock id='96690512'>
savage.test: DEBUG: **** patching <MagicMock id='84773072'> with <MagicMock id='96690512'>
savage.test: DEBUG: **** patching is_firstboot(savage/services/fred.py:94) with is_firstboot(<string>:1)
savage.test: DEBUG: **** adding http handler <webtest.app.TestApp object at 0x5c39d50> for 192.168.0.1
stevedore.extension: DEBUG: found extension EntryPoint.parse('NodeStatus = savage.services.fred:NodeStatus')
stevedore.extension: DEBUG: found extension EntryPoint.parse('FredStatus = savage.services.fred:FredStatus')
savage: INFO: Called execute_blkid
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_blkid returned
savage: INFO: Called execute_list_block
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute 'split' due to <unbound method _DiskDataMixin.execute_list_block>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_list_block returned ['loop0', 'loop0', 'nbd0', 'nbd0', 'ram0', 'ram0', 'rbd0', 'rbd0', 'rbd1', 'rbd1', 'sda', 'sdb']
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd1
savage: DEBUG: ignoring block device rbd1
savage: INFO: Analyzing sda
savage: INFO: Called execute_is_removable
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_removable>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_removable returned False
savage: INFO: Called execute_get_iops
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_iops>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_iops returned 100
savage: INFO: Called execute_get_bandwidth
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_bandwidth>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_bandwidth returned 150000
savage: INFO: Called execute_get_hdparm
savage: INFO: Called get_disk_info
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_hdparm>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_hdparm returned ('SATAMODELFAKE1', 'FAKESATASERIALsda', '3 TB')
savage: INFO: Called execute_is_ssd
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_ssd>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_ssd returned False
savage: INFO: disk sda reports {'serial_num': 'FAKESATASERIALsda', 'failed': False, 'removable': False, 'ssd': False, 'model': 'SATAMODELFAKE1', 'size': '3 TB', 'speed': {'rand_read_iops': 100, 'seq_read_bw': 150000}, 'partitions': {}}
savage: INFO: Analyzing sdb
savage: INFO: Called execute_is_removable
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_removable>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_removable returned False
savage: INFO: Called execute_get_iops
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_iops>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_iops returned 100
savage: INFO: Called execute_get_bandwidth
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_bandwidth>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_bandwidth returned 150000
savage: INFO: Called execute_get_hdparm
savage: INFO: Called get_disk_info
savage: DEBUG: ignored expected exception expected string or buffer due to <unbound method _DiskDataMixin.execute_get_hdparm>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_get_hdparm returned ('SATAMODELFAKE1', 'FAKESATASERIALsdb', '3 TB')
savage: INFO: Called execute_is_ssd
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute '__getitem__' due to <unbound method _DiskDataMixin.execute_is_ssd>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_is_ssd returned False
savage: INFO: disk sdb reports {'serial_num': 'FAKESATASERIALsdb', 'failed': False, 'removable': False, 'ssd': False, 'model': 'SATAMODELFAKE1', 'size': '3 TB', 'speed': {'rand_read_iops': 100, 'seq_read_bw': 150000}, 'partitions': {}}
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=[]), trying partition comparison
savage: DEBUG: no partition match found (partitions=[]), trying partition comparison
savage: DEBUG: disk identified as unknown
savage: INFO: update_dtype returned None
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=[]), trying partition comparison
savage: DEBUG: no partition match found (partitions=[]), trying partition comparison
savage: DEBUG: disk identified as unknown
savage: INFO: update_dtype returned None
savage: INFO: refresh done, drives = [<Disk: 0x5c43990 dev=sda type=unknown, parts: []>, <Disk: 0x5c43ed0 dev=sdb type=unknown, parts: []>]
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage: INFO: Called gather_cluster_uuids
savage: INFO: gather_cluster_uuids returned []
savage.test: DEBUG: **** patching pick_zk_hosts(savage/services/fred.py:557) with pick_zk_hosts(<string>:1)
savage.Fred: INFO: State change: startup -> wait-for-config: Fred<ip=172.17.0.13, state=wait-for-config>
savage.moxie.config: INFO: Saving config to /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/tmp/fredboot.json
savage.Fred: INFO: State change: wait-for-config -> full-config: Fred<ip=172.17.0.13, state=full-config>
savage.Fred: INFO: State change: full-config -> firstboot-full: Fred<ip=172.17.0.13, state=firstboot-full>
savage.Fred: INFO: Configure phase.
savage.Fred: DEBUG: Task: starting Debug.configure
savage.Fred: DEBUG: Task: finished (success) Debug.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting ShutdownLevels.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/shutdown-everything.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writexSbUBV.
savage.Fred: DEBUG: Task: finished (success) ShutdownLevels.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting SSH.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/ssh exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/ssh'], mode=None, owner=None, group=None)
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/root/.ssh/ exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/root/.ssh/'], mode=448, owner=None, group=None)
savage.config: INFO: Changed umask to 077 from 077
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 077 from 077
savage.config: INFO: Restored umask to 077 from 077
savage: INFO: making sure /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/root/.ssh/known_hosts is gone
savage.Fred: DEBUG: Task: finished (success) SSH.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Disk.configure
savage: INFO: Called disks_are_mounted
savage: INFO: disks_are_mounted returned False
savage: INFO: Called reconfigure_drive_allocation
savage: INFO: Called _reconfigure_drive_allocation
savage: INFO: Called scan_for_raids
savage: INFO: Called verify_uuid
savage: INFO: verify_uuid returned None
savage: INFO: Called verify_uuid
savage: INFO: verify_uuid returned None
savage: INFO: scan_for_raids returned []
savage: INFO: Called assign_disks
savage: DEBUG: disks: [<Disk: 0x5c27d10 dev=sda type=unformatted, parts: []>, <Disk: 0x5c29550 dev=sdb type=unformatted, parts: []>]
profiles: [{'profile_name': 'ceph', 'match': {'count': [{'operator': '>=', 'percent': False, 'value': 1}, {'operator': '<=', 'percent': True, 'value': 50}], 'ssd': 'prefer'}, 'partitions': ['ceph_journal', 'ceph_journal', 'ceph_monitor', 'identity', 'ceph_data', 'cass_log']}, {'profile_name': 'ephemeral', 'match': {'count': [{'operator': '>=', 'percent': False, 'value': 1}, {'operator': '<=', 'percent': True, 'value': 50}], 'ssd': 'avoid'}, 'partitions': ['identity', 'ephemeral', 'cass_data']}, {'profile_name': 'bad_but_test', 'match': {'ssd': 'avoid', 'model': {'operator': '==', 'value': 'IBM30209000'}, 'iops': [{'operator': '>=', 'percent': False, 'value': 20}, {'operator': '<=', 'percent': False, 'value': 200000}], 'serial': {'operator': '=~', 'value': 'IBM123'}, 'size': [{'operator': '>=', 'percent': False, 'value': 200000000.0}, {'operator': '<=', 'percent': False, 'value': 500000000000000.0}]}, 'partitions': ['ceph_journal', 'ephemeral', 'ceph_data:200GB', 'identity']}, {'profile_name': '__piston_init__', 'match': {'count': [{'operator': '>=', 'percent': False, 'value': 0}]}, 'partitions': ['identity']}]
savage: DEBUG: checking {'operator': '==', 'value': 'IBM30209000'}
savage: DEBUG: checking model(SATAMODELFAKE1) is (==) IBM30209000
savage: DEBUG: checking {'operator': '==', 'value': 'IBM30209000'}
savage: DEBUG: checking model(SATAMODELFAKE1) is (==) IBM30209000
savage: DEBUG: mins = [1]
savage: DEBUG: mins = [1]
savage: DEBUG: mins = [0]
savage: DEBUG: dmin: 0
savage: DEBUG: mins = [1]
savage: DEBUG: dmin: 1
savage: INFO: Called set_format
savage: DEBUG: disk now: <96632080 sda ceph disk, parts: [<Partition label=ceph_journal id=0x5ce4850>, <Partition label=ceph_journal id=0x5ce4890>, <Partition label=ceph_monitor id=0x5ce48d0>, <Partition label=identity id=0x5ce4910>, <Partition label=ceph_data id=0x5ce4950>, <Partition label=cass_log id=0x5c597d0>]>
savage: INFO: set_format returned None
savage: INFO: assigned 1 disks on first pass to profile ceph
savage: DEBUG: mins = [1]
savage: DEBUG: dmin: 1
savage: INFO: Called set_format
savage: DEBUG: disk now: <96638288 sdb ephemeral disk, parts: [<Partition label=identity id=0x5ce49d0>, <Partition label=ephemeral id=0x5ce4a10>, <Partition label=cass_data id=0x5ce4a50>]>
savage: INFO: set_format returned None
savage: INFO: assigned 1 disks on first pass to profile ephemeral
savage: DEBUG: mins = [0]
savage: DEBUG: dmin: 0
savage: DEBUG: max from [{'operator': '>=', 'percent': False, 'value': 1}, {'operator': '<=', 'percent': True, 'value': 50}] is 1
savage: DEBUG: max from [{'operator': '>=', 'percent': False, 'value': 1}, {'operator': '<=', 'percent': True, 'value': 50}] is 1
savage: INFO: assigned 0 disks on second pass to profile bad_but_test
savage: DEBUG: max from [{'operator': '>=', 'percent': False, 'value': 0}] is 2
savage: INFO: assigned 0 disks on second pass to profile __piston_init__
savage: INFO: assign_disks returned None
savage: INFO: _reconfigure_drive_allocation returned [<Disk: 0x5c27d10 dev=sda type=ceph, parts: [<Partition label=ceph_journal id=0x5ce4850>, <Partition label=ceph_journal id=0x5ce4890>, <Partition label=ceph_monitor id=0x5ce48d0>, <Partition label=identity id=0x5ce4910>, <Partition label=ceph_data id=0x5ce4950>, <Partition label=cass_log id=0x5c597d0>]>, <Disk: 0x5c29550 dev=sdb type=ephemeral, parts: [<Partition label=identity id=0x5ce49d0>, <Partition label=ephemeral id=0x5ce4a10>, <Partition label=cass_data id=0x5ce4a50>]>]
savage: INFO: Called format_drives
savage: INFO: Called format_drive
savage: INFO: Called make_partition_table
savage: INFO: Called make_drive_partition_table
savage: INFO: make_drive_partition_table returned None
savage: INFO: make_partition_table returned None
savage: INFO: Called partition_drive
savage: INFO: Partition #0 is ceph_journal
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #1 is ceph_journal
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #2 is ceph_monitor
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #3 is identity
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #4 is ceph_data
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #5 is cass_log
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: partition_drive returned None
savage: INFO: Called settle_udev_if_needed
savage: INFO: Called settle_udev
savage: INFO: settle_udev returned None
savage: INFO: settle_udev_if_needed returned None
savage.test: INFO: using callable hook key dd if=/dev/zero of=.*
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: using callable hook key dd if=/dev/zero of=.*
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sda3
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sda4
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sda5
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sda6
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: format_drive returned None
savage: INFO: Called format_drive
savage: INFO: Called make_partition_table
savage: INFO: Called make_drive_partition_table
savage: INFO: make_drive_partition_table returned None
savage: INFO: make_partition_table returned None
savage: INFO: Called partition_drive
savage: INFO: Partition #0 is identity
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #1 is ephemeral
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Partition #2 is cass_data
savage: INFO: Called mkpart
savage: INFO: mkpart returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: partition_drive returned None
savage: INFO: Called settle_udev_if_needed
savage: INFO: Called settle_udev
savage: INFO: settle_udev returned None
savage: INFO: settle_udev_if_needed returned None
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sdb1
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /dev/sdb3
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: format_drive returned None
savage: INFO: Called create_or_extend_raids
savage: INFO: Called create_mirror_raids
savage: INFO: Called make_raid1
savage.test: INFO: using callable hook key mdadm --create .*
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: make_raid1 returned True
savage: INFO: Called make_raid0
savage.test: INFO: using callable hook key mdadm --create .*
savage: INFO: make_raid0 returned True
savage: INFO: Called vgcreate
savage.test: INFO: using callable hook key pvcreate .*
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: vgcreate returned None
savage: INFO: create_mirror_raids returned True
savage: INFO: create_or_extend_raids returned True
savage: INFO: format_drives returned [<Disk: 0x5c27d10 dev=sda type=ceph, parts: [<Partition label=ceph_journal id=0x5ce4850>, <Partition label=ceph_journal id=0x5ce4890>, <Partition label=ceph_monitor id=0x5ce48d0>, <Partition label=identity id=0x5ce4910>, <Partition label=ceph_data id=0x5ce4950>, <Partition label=cass_log id=0x5c597d0>]>, <Disk: 0x5c29550 dev=sdb type=ephemeral, parts: [<Partition label=identity id=0x5ce49d0>, <Partition label=ephemeral id=0x5ce4a10>, <Partition label=cass_data id=0x5ce4a50>]>]
savage: INFO: Called execute_blkid
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_blkid returned /dev/sdb2: UUID="PART_00:FF:EE:DD:10:03_SDB_2" MEOW="pants" TYPE="linux_raid_member" BLAH="false"
/dev/sdb3: LABEL="cass_data" UUID="PART_00:FF:EE:DD:10:03_SDB_3" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda5: LABEL="ceph_data" UUID="PART_00:FF:EE:DD:10:03_SDA_5" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda1: PARTLABEL="primary" PARTUUID="SILLYUUID"
/dev/sdb1: LABEL="identity" UUID="PART_00:FF:EE:DD:10:03_SDB_1" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/md0: LABEL="lvm" UUID="None" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda6: LABEL="cass_log" UUID="PART_00:FF:EE:DD:10:03_SDA_6" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda3: LABEL="ceph_monitor" UUID="PART_00:FF:EE:DD:10:03_SDA_3" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda4: LABEL="identity" UUID="PART_00:FF:EE:DD:10:03_SDA_4" MEOW="pants" TYPE="xfs" BLAH="false"
/dev/sda2: PARTLABEL="primary" PARTUUID="SILLYUUID"
savage: INFO: Called execute_list_block
savage: DEBUG: ignored expected exception 'NoneType' object has no attribute 'split' due to <unbound method _DiskDataMixin.execute_list_block>
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: execute_list_block returned ['loop0', 'loop0', 'md0', 'md0', 'nbd0', 'nbd0', 'ram0', 'ram0', 'rbd0', 'rbd0', 'rbd1', 'rbd1', 'sda', 'sda1', 'sda2', 'sda3', 'sda4', 'sda5', 'sda6', 'sdb', 'sdb1', 'sdb2', 'sdb3']
savage: DEBUG: ignoring block device md0
savage: DEBUG: ignoring block device md0
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device nbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd0
savage: DEBUG: ignoring block device rbd1
savage: DEBUG: ignoring block device rbd1
savage: INFO: Using cached disk data for sda
savage: INFO: Using cached disk data for sdb
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=['journal', 'journal', 'ceph_monitor', 'identity', 'ceph_data', 'cass_log']), trying partition comparison
savage: DEBUG: disk identified as ceph
savage: INFO: update_dtype returned None
savage: INFO: Called update_dtype
savage: DEBUG: no label match found (labels=['identity', 'raid', 'cass_data']), trying partition comparison
savage: DEBUG: disk identified as ephemeral
savage: INFO: update_dtype returned None
savage: INFO: refresh done, drives = [<Disk: 0x7f6053aae710 dev=sda type=ceph, parts: [<Partition label=journal id=0x5ced8d0>, <Partition label=journal id=0x5cf49d0>, <Partition label=ceph_monitor id=0x5cf4410>, <Partition label=identity id=0x5cf4490>, <Partition label=ceph_data id=0x5cf4550>, <Partition label=cass_log id=0x5cf4590>]>, <Disk: 0x5cedf50 dev=sdb type=ephemeral, parts: [<Partition label=identity id=0x5cf4650>, <Partition label=raid id=0x5cf4210>, <Partition label=cass_data id=0x5cf4250>]>]
savage: INFO: reconfigure_drive_allocation returned [<Disk: 0x5c27d10 dev=sda type=ceph, parts: [<Partition label=ceph_journal id=0x5ce4850>, <Partition label=ceph_journal id=0x5ce4890>, <Partition label=ceph_monitor id=0x5ce48d0>, <Partition label=identity id=0x5ce4910>, <Partition label=ceph_data id=0x5ce4950>, <Partition label=cass_log id=0x5c597d0>]>, <Disk: 0x5c29550 dev=sdb type=ephemeral, parts: [<Partition label=identity id=0x5ce49d0>, <Partition label=ephemeral id=0x5ce4a10>, <Partition label=cass_data id=0x5ce4a50>]>]
savage: INFO: Called mount_local_disks
savage: INFO: Called local_disk_device
savage: INFO: Called local_disk_part
savage: INFO: local_disk_part returned <ceph_monitor partition>
savage: INFO: Called local_disk_part
savage: INFO: local_disk_part returned <ceph_monitor partition>
savage: INFO: local_disk_device returned /dev/sda3
savage.test: INFO: fake ismount: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local ([])
savage: INFO: Called xfs_fsck
savage: INFO: xfs_fsck returned None
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local// exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local//'], mode=493, owner=None, group=None)
savage.test: INFO: using callable hook key mount .*
savage.test: INFO: fake mount: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local ([])
savage.test: INFO: stopped recording
savage.test: INFO: started recording
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local// exists (created=[], mode=493, owner=None, group=None)
savage: INFO: mount_local_disks returned None
savage: INFO: Called disks_are_mounted
savage: INFO: Mounted disk found: /dev/sda3 /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local blah blah,blah 0 0
savage: INFO: disks_are_mounted returned True
savage.Fred: DEBUG: Task: finished (success) Disk.configure (0.1s elapsed)
savage.Fred: DEBUG: Task: starting Apache.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/apache.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeQdnoxw.
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/run/apache exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/run/apache'], mode=None, owner=apache, group=apache)
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 022 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/www/empty exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/www', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/www/empty'], mode=None, owner=root, group=root)
savage.config: INFO: Restored umask to 077 from 022
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/apache2 exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/apache2'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/apache2 exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/apache2/httpd.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/apache2/template_writemMNlIu.
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (success) Apache.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting LocalDisk.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/mdadm.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeSUznAk.
savage.MdadmJob[mdadm]: INFO: Called start
savage.MdadmJob[mdadm]: INFO: start returned None
savage: INFO: Called settle_udev
savage: INFO: settle_udev returned None
savage: INFO: Called mount_lv_or_tmpfs
savage: INFO: Called vgscan
savage: INFO: vgscan returned True
savage.test: INFO: using callable hook key vgchange .*
savage: INFO: Called settle_udev
savage: INFO: settle_udev returned None
savage.test: INFO: using callable hook key lvcreate .*
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/dev/nova exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/dev/nova'], mode=None, owner=None, group=None)
savage: INFO: Called mkfs
savage: INFO: Scheduling mkfs.xfs /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/dev/nova/novadisk
savage: INFO: mkfs returned None
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage.test: INFO: stopped recording
savage: INFO: Called gather_mac_addresses
savage: INFO: gather_mac_addresses returned {'host': {'mac': '00:00:00:00:00:01', 'speed': 10000}, 'eth2': {'mac': '00:00:00:00:00:03', 'speed': 0}, 'eth1': {'mac': '00:FF:EE:DD:10:03', 'speed': 10000}}
savage.test: INFO: started recording
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk/ exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk/'], mode=493, owner=None, group=None)
savage.test: INFO: using callable hook key mount .*
savage.test: INFO: fake mount: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk ([('/dev/sda3', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local')])
savage.test: INFO: stopped recording
savage.test: INFO: started recording
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk/ exists (created=[], mode=493, owner=None, group=None)
savage: INFO: mount_lv_or_tmpfs returned None
savage.Fred: DEBUG: Task: finished (success) LocalDisk.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Redis.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/redis.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writezpzwmg.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/redis exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/redis'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/redis exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/redis/redis.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/redis/template_writehOaAV7.
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (success) Redis.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Zookeeper.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/zookeeper.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writevY9cwH.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper/zoo.cfg with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper/template_write7fYnWv.
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 077
savage.test: INFO: fake ismount: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper ([('/dev/sda3', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local'), ('/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/dev/nova/novadisk', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk')])
savage.test: INFO: using callable hook key mount .*
savage.test: INFO: fake mount: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper ([('/dev/sda3', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/local'), ('/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/dev/nova/novadisk', '/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/mnt/novadisk')])
savage.test: INFO: stopped recording
savage.test: INFO: started recording
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/logs exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/logs'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data exists (created=[], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 077 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data/myid with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/zookeeper/data/template_write1BeBKb.
savage.config: INFO: Restored umask to 077 from 077
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper exists (created=[], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper/log4j.properties with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/zookeeper/template_writeFV4Gcr.
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (success) Zookeeper.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting ContrailDiscovery.configure
savage.Fred: DEBUG: Task: finished (success) ContrailDiscovery.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Ifmap.configure
savage.Fred: DEBUG: Task: finished (success) Ifmap.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting PublicApi.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/public_api.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeHyXv_u.
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/floating-ip.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeAQZxWS.
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/zookeeper-sentinel.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeCTB3RF.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/piston exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/piston'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/piston exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/piston/auth_store.json with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/piston/template_writerRgr2z.
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (success) PublicApi.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Cassandra.configure
savage.Fred: DEBUG: Task: finished (success) Cassandra.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Ceph.configure
savage.config: INFO: Changed umask to 022 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/run/ceph exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/run/ceph'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 022
savage.Fred: DEBUG: Task: finished (success) Ceph.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Rabbit.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/rabbitmq.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writelpdfLN.
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/floating-ip.conf and /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeSSmCHR are the same, ignoring update.
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/zookeeper-sentinel.conf and /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_write41wSen are the same, ignoring update.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/rabbitmq exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/rabbitmq'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/rabbitmq exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/rabbitmq/rabbitmq.config with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/rabbitmq/template_write2UtpiI.
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 07 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/rabbitmq exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/rabbitmq'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 07
savage.config: INFO: Changed umask to 0377 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/rabbitmq exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/rabbitmq/.erlang.cookie with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/var/lib/rabbitmq/template_writeVkxaGl.
savage.config: INFO: Restored umask to 077 from 0377
savage.Fred: DEBUG: Task: finished (success) Rabbit.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting Snmpd.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/snmpd.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_write7mfGLl.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/snmp exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/snmp'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/snmp exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/snmp/snmpd.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/snmp/template_writeln36H0.
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (success) Snmpd.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting CephMounted.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/umount-ceph.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeRe1Hbb.
savage.Fred: DEBUG: Task: finished (success) CephMounted.configure (0.0s elapsed)
savage.Fred: DEBUG: Task: starting ContrailApi.configure
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init exists (created=[], mode=None, owner=None, group=None)
savage: INFO: Updating /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/contrail_api.conf with /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/init/template_writeWGQ3Ck.
savage.config: INFO: Changed umask to 027 from 077
savage: INFO: guaranteed that /home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/contrail exists (created=['/home/noel/projects/piston/projects/pentos/savage/tests/data/output/root/etc/contrail'], mode=None, owner=None, group=None)
savage.config: INFO: Restored umask to 077 from 027
savage.config: INFO: Changed umask to 027 from 077
savage.config: INFO: Restored umask to 077 from 027
savage.Fred: DEBUG: Task: finished (failure) ContrailApi.configure (0.0s elapsed)
--------------------- >> end captured logging << ---------------------

Slowest 1 tests took 0.45 secs:
    0.45    TestFredBoot.test_firstboot_fake_zk_child
----------------------------------------------------------------------
Ran 1 test in 0.459s

FAILED (errors=1)