Images are zero filled

[cristifalcas]

Hi all,

We have an openstack-vmware installation, but we've hit some problems.

Openstack is havana, vmware is vsphere 5.0.

1. Images from glance are not copied to the vmware datastore correctly: when I launch the first instance from an image, the file from vmware_base has the correct size, but it's all zeros. No data. If I manually copy the file from glance to the datastore, the instances start successfully.

2. First time when an instance+flavor is used, the virtual machine fails to boot and it's deleted from the vmware side. I presume that this is happening when the new flavor disk is created on the vmware datastore and maybe the api is responding with success too fast?

The second issue is not really a show stopper, because it is happening only once.

The first one we would really like to solve, so, any help will be appreciated.

Best regards,

Cristian Falcas

[Vui]

Thanks for the post Cristian. Are you using the VMwareESXDriver or VMwareVCDriver?

2. is probably related to the 1. so let's address the latter first.  The blank disk you are seeing may not be the result of the upload, but a blank disk that is created whose contents are intended to be overrited by the uploaded disk contents.  Did the nova-compute log show any errors regarding uploading the image to the ESX host? Can you give more details as to the

type of disk you uploaded to glance, the command you used to do so, as well as the steps you did to manually copy the glance image to ESX?. I ask because the how the compute driver use the image depends on its format, and a common error is one uploading the descriptor file (foo.vmdk) instead of the data file (foo-flat.vmdk) of a vmfs flat disk.

If you can collect the diagnostic bundle from ESX/VC and the nova compute log after one such failure, that would be really useful to help investigate the root cause as well.

Thanks

Vui

[cristifalcas]

actually, the only error is in the compute.log. and it's the same as the one from https://bugs.launchpad.net/nova/+bug/1215958

I applied the patch from the above bug, but it just moves the error to "AttributeError: 'NoneType' object has no attribute 'name'"

Original error:

2013-10-30 10:06:21.205 21924 CRITICAL nova.virt.vmwareapi.driver [-] In vmwareapi:_call_method, got this exception: ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:21.205 21924 WARNING nova.virt.vmwareapi.driver [-] In vmwareapi:_poll_task, Got this error ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:21.206 21924 ERROR nova.compute.manager [req-fcea4b5b-edaa-4a54-a1b8-1aeabf9cdb4f 78fa1b4284df4bcab09336354855c3b7 ff01d74511684ca697a87f4d82ab54d6] [instance: 7d83e581-7023-4899-8783-196fc27a2808] Instance failed to spawn

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808] Traceback (most recent call last):

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1407, in _spawn

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     block_device_info)

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 623, in spawn

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     admin_password, network_info, block_device_info)

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 440, in spawn

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     _create_virtual_disk()

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 301, in _create_virtual_disk

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     self._session._wait_for_task(instance['uuid'], vmdk_create_task)

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 900, in _wait_for_task

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     ret_val = done.wait()

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/eventlet/event.py", line 116, in wait

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     return hubs.get_hub().switch()

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/eventlet/hubs/hub.py", line 177, in switch

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     return self.greenlet.switch()

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808] AttributeError: ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:21.206 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]

2013-10-30 10:06:21.340 21924 AUDIT nova.compute.manager [req-fcea4b5b-edaa-4a54-a1b8-1aeabf9cdb4f 78fa1b4284df4bcab09336354855c3b7 ff01d74511684ca697a87f4d82ab54d6] [instance: 7d83e581-7023-4899-8783-196fc27a2808] Terminating instance

2013-10-30 10:06:24.402 21924 ERROR nova.compute.manager [req-fcea4b5b-edaa-4a54-a1b8-1aeabf9cdb4f 78fa1b4284df4bcab09336354855c3b7 ff01d74511684ca697a87f4d82ab54d6] [instance: 7d83e581-7023-4899-8783-196fc27a2808] Error: ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808] Traceback (most recent call last):

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1037, in _build_instance

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     set_access_ip=set_access_ip)

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1410, in _spawn

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     LOG.exception(_('Instance failed to spawn'), instance=instance)

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1407, in _spawn

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     block_device_info)

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 623, in spawn

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     admin_password, network_info, block_device_info)

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 440, in spawn

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     _create_virtual_disk()

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 301, in _create_virtual_disk

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     self._session._wait_for_task(instance['uuid'], vmdk_create_task)

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 900, in _wait_for_task

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     ret_val = done.wait()

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/eventlet/event.py", line 116, in wait

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     return hubs.get_hub().switch()

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]   File "/usr/lib/python2.6/site-packages/eventlet/hubs/hub.py", line 177, in switch

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]     return self.greenlet.switch()

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808] AttributeError: ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:24.402 21924 TRACE nova.compute.manager [instance: 7d83e581-7023-4899-8783-196fc27a2808]

2013-10-30 10:06:26.206 21924 CRITICAL nova.virt.vmwareapi.driver [-] In vmwareapi:_call_method, got this exception: ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:26.207 21924 WARNING nova.virt.vmwareapi.driver [-] In vmwareapi:_poll_task, Got this error ObjectContent instance has no attribute 'propSet'

2013-10-30 10:06:26.208 21924 ERROR nova.openstack.common.loopingcall [-] in fixed duration looping call

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall Traceback (most recent call last):

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall   File "/usr/lib/python2.6/site-packages/nova/openstack/common/loopingcall.py", line 78, in _inner

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall     self.f(*self.args, **self.kw)

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 929, in _poll_task

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall     done.send_exception(excep)

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall   File "/usr/lib/python2.6/site-packages/eventlet/event.py", line 208, in send_exception

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall     return self.send(None, args)

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall   File "/usr/lib/python2.6/site-packages/eventlet/event.py", line 150, in send

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall     assert self._result is NOT_USED, 'Trying to re-send() an already-triggered event.'

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall AssertionError: Trying to re-send() an already-triggered event.

2013-10-30 10:06:26.208 21924 TRACE nova.openstack.common.loopingcall

Error after applied patch from bug:

2013-10-30 09:33:03.753 19599 ERROR nova.compute.manager [req-0de41999-6c3d-4153-9281-78dde5cf6e9a 78fa1b4284df4bcab09336354855c3b7 ff01d74511684ca697a87f4d82ab54d6] [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1] Error: 'NoneType' object has no attribute 'name'

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1] Traceback (most recent call last):

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1037, in _build_instance

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     set_access_ip=set_access_ip)

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1410, in _spawn

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     LOG.exception(_('Instance failed to spawn'), instance=instance)

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 1407, in _spawn

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     block_device_info)

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 623, in spawn

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     admin_password, network_info, block_device_info)

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 440, in spawn

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     _create_virtual_disk()

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/vmops.py", line 301, in _create_virtual_disk

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     self._session._wait_for_task(instance['uuid'], vmdk_create_task)

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/nova/virt/vmwareapi/driver.py", line 900, in _wait_for_task

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     ret_val = done.wait()

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/eventlet/event.py", line 116, in wait

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     return hubs.get_hub().switch()

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]   File "/usr/lib/python2.6/site-packages/eventlet/hubs/hub.py", line 177, in switch

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]     return self.greenlet.switch()

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1] AttributeError: 'NoneType' object has no attribute 'name'

2013-10-30 09:33:03.753 19599 TRACE nova.compute.manager [instance: ba8ca5d3-3c30-4b81-b46a-b99ba04b5cc1]

[cristifalcas]

I forgot to explain how the errors go:

1. At instance first boot from image+any flavor it will create a 0 file on the datastore and fail

2. At second boot from image+each flavor, it will copy the base file and fail again for each flavor

3. third boot from image+flavor will go correct.

Machine will still not boot into an os because of the 0 size image.

If I copy the image with scp to the host and replace it in the datastore with the correct uuid, it will boot correctly.

[Vui]

Hi Cristian,

Thanks for the additional info. It looks like the spawn is failing very early in the operation, when we are merely trying to create a blank vmdk on the datastore. It would be helpful to gather the vCenter diagnostic logs as well a bit more of the compute log prior to the failure. Let me work with you off-discussion to get to the bottom of this.

Vui

[cristifalcas]

Hi Vui,

Image uuid is 50d55b93-9d4b-483f-a86e-59fd370ae0b0.

Second instance uuid is 5831e1c6-19bd-448a-9cd4-113f219a485f.

Successful instance uuid is e1ffc8a1-5cc0-4189-aaf9-1fe0eb1cf746.

Unfortunately I delete from openstack the uuid of the first instance, when the image was supposed to be copied.

I think the problems may came from this warning:

2013-10-31T11:33:53.177Z [2F509B90 warning 'DiskLib' opID=d585da63-10] DISKLIB-FLAT  : "/vmfs/volumes/6f2842d4-8057899d/vmware_base/50d55b93-9d4b-483f-a86e-59fd370ae0b0-flat.vmdk": Unable to reserve space: The specified feature is not supported by this version. The disk will be created as 'Thin'.

[admin]

Did we ever get to the bottom of this issue, or is it still pending?