Exception handling task error messages in virtualcenter

[kedark3]

Hello, I am trying to run some automation tests that require setting up VMware provider on CFME appliance and creating a test VM on top of it. The task seems to be failing somewhere in wrapanapi. Log follows:

2017-07-05 12:57:47,300 [I] ----------------------- test_html5_vm_console[vsphere55] ----------------------- (fixtures/log.py:21)
2017-07-05 12:57:47,301 [I] Running rails command '"File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:319)
2017-07-05 12:57:47,301 [I] Running command 'cd /var/www/miq/vmdb; bin/rails runner "File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:240)
2017-07-05 12:57:55,721 [I] Running command 'cat /tmp/yam_dump.yaml' (utils/ssh.py:240)
2017-07-05 12:57:56,084 [I] Running command 'ip address show' (utils/ssh.py:240)
2017-07-05 12:57:56,213 [I] [DB] db_url is postgresql://root:smartvm@10.8.198.137:5432/vmdb_production (utils/db.py:196)
2017-07-05 12:57:56,455 [I] Running command 'cat /var/www/miq/vmdb/GUID' (utils/ssh.py:240)
2017-07-05 12:57:56,602 [I] Running rails command '"File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:319)
2017-07-05 12:57:56,602 [I] Running command 'cd /var/www/miq/vmdb; bin/rails runner "File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:240)
2017-07-05 12:58:04,673 [I] Running command 'cat /tmp/yam_dump.yaml' (utils/ssh.py:240)
2017-07-05 12:58:05,218 [I] Running command 'test -s /etc/init.d/merkyl' (utils/ssh.py:240)
2017-07-05 12:58:05,345 [I] Checking appliance's /etc/hosts for its own hostname (cfme/fixtures/base.py:57)
2017-07-05 12:58:05,345 [I] Running command 'grep $(hostname) /etc/hosts' (utils/ssh.py:240)
2017-07-05 12:58:05,528 [I] Running rails command '"File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:319)
2017-07-05 12:58:05,528 [I] Running command 'cd /var/www/miq/vmdb; bin/rails runner "File.open('/tmp/yam_dump.yaml', 'w') {|f| f.write(Settings.to_hash.deep_stringify_keys.to_yaml) }"' (utils/ssh.py:240)
2017-07-05 12:58:14,035 [I] Running command 'cat /tmp/yam_dump.yaml' (utils/ssh.py:240)
2017-07-05 12:58:15,049 [I] (rest-api) [RESTAPI] GET https://10.8.198.137:443/api {} (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/manageiq_client/api.py:84)
2017-07-05 12:58:15,320 [I] (rest-api) [RESTAPI] GET https://10.8.198.137/api/providers {'filter[]': [u'name = "vSphere 5.5 (nested)"']} (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/manageiq_client/api.py:84)
2017-07-05 12:58:15,464 [I] (rest-api) [RESTAPI] GET https://10.8.198.137/api/providers/2 {} (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/manageiq_client/api.py:84)
2017-07-05 12:58:15,603 [I] Running command 'date --iso-8601=seconds -u' (utils/ssh.py:240)
2017-07-05 12:58:15,787 [I] Getting ready to deploy VM/instance test-scat-zfxr from template damnSmallLinux on provider vSphere 5.5 (nested) (utils/virtual_machines.py:69)
2017-07-05 12:58:16,449 [I] Provisioning progress damnSmallLinux->test-scat-zfxr: Picked datastore iSCSI-Datastore-1 (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:579)
2017-07-05 12:58:16,470 [I] Provisioning progress damnSmallLinux->test-scat-zfxr: Picked resource pool Resources (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:579)
2017-07-05 12:58:16,503 [I] Provisioning progress damnSmallLinux->test-scat-zfxr: Picked folder vm (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:579)
2017-07-05 12:58:16,575 [I] Provisioning progress damnSmallLinux->test-scat-zfxr: running (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:579)
2017-07-05 12:58:20,623 [I] Provisioning progress damnSmallLinux->test-scat-zfxr: error (/home/kkulkarn/git/cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:579)
2017-07-05 12:58:20,655 [E] Could not provisioning VM/instance test-scat-zfxr (AttributeError: 'vmodl.LocalizableMessage[]' object has no attribute 'message') (utils/virtual_machines.py:77)
2017-07-05 12:58:21,051 [E] Could not retrieve VM/Instance status: VMInstanceNotFound: Could not find a VM/instance named test-scat-zfxr. (utils/virtual_machines.py:20)
2017-07-05 12:58:21,051 [I] Attempting cleanup on VM/instance test-scat-zfxr (utils/virtual_machines.py:21)
2017-07-05 12:58:21,478 [E] @pytest.fixture(scope="function")
def vm_obj(request, provider, setup_provider, small_template, vm_name):
vm_obj = VM.factory(vm_name, provider, template_name=small_template)

    @request.addfinalizer
    def _delete_vm():
        try:
            vm_obj.delete_from_provider()
        except Exception:
            logger.warning("Failed to delete vm `{}`.".format(vm_obj.name))

  vm_obj.create_on_provider(timeout=2400, find_in_cfme=True, allow_skip="default")

cfme/tests/cloud_infra_common/test_html5_vm_console.py:34:

---

cfme/common/vm.py:731: in create_on_provider
deploy_template(self.provider.key, self.name, self.template_name, **kwargs)
utils/virtual_machines.py:73: in deploy_template
vm_name = provider_crud.mgmt.deploy_template(timeout=timeout, **deploy_args)
../cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:700: in deploy_template
self.clone_vm(template, destination, **kwargs)

---

def clone_vm(self, source, destination, resourcepool=None, datastore=None, power_on=True,
             sparse=False, template=False, provision_timeout=1800, progress_callback=None,
             allowed_datastores=None, cpu=None, ram=None, **kwargs):
    """Clone a VM"""
    try:
        vm = self._get_obj(vim.VirtualMachine, name=destination)
        if vm and vm.name == destination:
            raise Exception("VM already present!")
    except VMInstanceNotFound:
        pass

    if progress_callback is None:
        progress_callback = partial(self._progress_log_callback, self.logger,
            source, destination)

    source_template = self._get_vm(source)

    vm_clone_spec = vim.VirtualMachineCloneSpec()
    vm_reloc_spec = vim.VirtualMachineRelocateSpec()
    # DATASTORE
    if isinstance(datastore, six.string_types):
        vm_reloc_spec.datastore = self._get_obj(vim.Datastore, name=datastore)
    elif isinstance(datastore, vim.Datastore):
        vm_reloc_spec.datastore = datastore
    elif datastore is None:
        if allowed_datastores is not None:
            # Pick a datastore by space
            vm_reloc_spec.datastore = self._pick_datastore(allowed_datastores)
        else:
            # Use the same datastore
            datastores = source_template.datastore
            if isinstance(datastores, (list, tuple)):
                vm_reloc_spec.datastore = datastores[0]
            else:
                vm_reloc_spec.datastore = datastores
    else:
        raise NotImplementedError("{} not supported for datastore".format(datastore))
    progress_callback("Picked datastore `{}`".format(vm_reloc_spec.datastore.name))

    # RESOURCE POOL
    if isinstance(resourcepool, vim.ResourcePool):
        vm_reloc_spec.pool = resourcepool
    else:
        vm_reloc_spec.pool = self._get_resource_pool(resourcepool)
    progress_callback("Picked resource pool `{}`".format(vm_reloc_spec.pool.name))

    vm_reloc_spec.host = None
    if sparse:
        vm_reloc_spec.transform = vim.VirtualMachineRelocateTransformation().sparse
    else:
        vm_reloc_spec.transform = vim.VirtualMachineRelocateTransformation().flat

    vm_clone_spec.powerOn = power_on
    vm_clone_spec.template = template
    vm_clone_spec.location = vm_reloc_spec
    vm_clone_spec.snapshot = None

    if cpu is not None:
        vm_clone_spec.config.numCPUs = int(cpu)
    if ram is not None:
        vm_clone_spec.config.memoryMB = int(ram)

    try:
        folder = source_template.parent.parent.vmParent
    except AttributeError:
        folder = source_template.parent
    progress_callback("Picked folder `{}`".format(folder.name))

    task = source_template.CloneVM_Task(folder=folder, name=destination, spec=vm_clone_spec)

    def _check(store=[task]):
        try:
            if hasattr(store[0].info, 'progress') and store[0].info.progress is not None:
                progress_callback("{}/{}%".format(store[0].info.state, store[0].info.progress))
            else:
                progress_callback("{}".format(store[0].info.state))
        except AttributeError:
            pass
        if store[0].info.state not in {"queued", "running"}:
            return True
        else:
            store[0] = self._get_updated_obj(store[0])
            return False

    wait_for(_check, num_sec=provision_timeout, delay=4)

    if task.info.state != 'success':
        if hasattr(task.info.error, 'localizedMessage'):
            message = str(task.info.error.localizedMessage)
        elif hasattr(task.info.error, 'faultMessage'):

          message = str(task.info.error.faultMessage.message)

E AttributeError: 'vmodl.LocalizableMessage[]' object has no attribute 'message'

../cfme_venv/lib/python2.7/site-packages/wrapanapi/virtualcenter.py:684: AttributeError (fixtures/log.py:70)
2017-07-05 12:58:21,492 [I] Begin delete_from_provider (cfme/common/vm.py:700)
2017-07-05 12:58:21,921 [I] Cleaning up VM test-scat-zfxr on provider vsphere55 (cfme/fixtures/vm_name.py:15)
2017-07-05 12:58:22,326 [W] Failed to clean up VM test-scat-zfxr on provider vsphere55 (cfme/fixtures/vm_name.py:19)
2017-07-05 12:58:22,343 [I] ---------------- test_html5_vm_console[vsphere55] result: error ---------------- (fixtures/log.py:57)
2017-07-05 12:58:22,343 [I] ------------------------ test_html5_vm_console[rhevm36] ------------------------ (fixtures/log.py:21)