VMware: volume create fails with "VimFaultException: Unable to access the virtual machine configuration"

[satyadev svn]

test setps :
1) create volume [say vol1] of volume-type bronze [ bronze type mapped to local data stores as bronze profile in vcenter]
2) now attach & detach a vol to instance [observe vm backing found in vcenter]
3) now create clone from above vol1
4) observe clone volume failed with clone volume status in error.

c-vol log have following exception trace :

 }. from (pid=29640) _get_clone_spec /opt/stack/cinder/cinder/volume/drivers/vmware/volumeops.py:1024
2014-10-13 17:27:10.964 DEBUG cinder.volume.drivers.vmware.volumeops [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Initiated clone of backing: volume-1944f3df-0649-4e05-b561-a1327c873e20. from (pid=29640) clone_backing /opt/stack/cinder/cinder/volume/drivers/vmware/volumeops.py:1057
2014-10-13 17:27:11.856 ERROR cinder.volume.drivers.vmware.api [-] Task: (returnval){
   value = "task-1255"
   _type = "Task"
 } failed with error: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)].
2014-10-13 17:27:11.856 TRACE cinder.volume.drivers.vmware.api None
2014-10-13 17:27:11.856 TRACE cinder.volume.drivers.vmware.api 
2014-10-13 17:27:11.857 ERROR cinder.volume.drivers.vmware.api [-] Task: (returnval){
   value = "task-1255"
   _type = "Task"
 } failed with error: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)].
2014-10-13 17:27:11.857 TRACE cinder.volume.drivers.vmware.api Traceback (most recent call last):
2014-10-13 17:27:11.857 TRACE cinder.volume.drivers.vmware.api  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 315, in _poll_task
2014-10-13 17:27:11.857 TRACE cinder.volume.drivers.vmware.api  raise error_util.VimFaultException([], error_msg)
2014-10-13 17:27:11.857 TRACE cinder.volume.drivers.vmware.api VimFaultException: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)]
2014-10-13 17:27:11.857 TRACE cinder.volume.drivers.vmware.api 
2014-10-13 17:27:11.858 ERROR cinder.openstack.common.loopingcall [-] in fixed duration looping call
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall Traceback (most recent call last):
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall  File "/opt/stack/cinder/cinder/openstack/common/loopingcall.py", line 81, in _inner
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall  self.f(*self.args, **self.kw)
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 319, in _poll_task
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall  raise excep
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall VimFaultException: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)]
2014-10-13 17:27:11.858 TRACE cinder.openstack.common.loopingcall 
2014-10-13 17:27:11.878 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'SCHEDULING' in response to event 'wait' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.879 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'WAITING' in response to event 'wait' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.879 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'WAITING' in response to event 'analyze' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.879 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'ANALYZING' in response to event 'analyze' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.880 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.CreateVolumeFromSpecTask;volume:create' (8b526818-cc9c-4908-b971-efa70e9fe0aa) transitioned into state 'FAILURE'
2014-10-13 17:27:11.880 TRACE cinder.volume.manager Traceback (most recent call last):
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 35, in _execute_task
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  result = task.execute(**arguments)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 631, in execute
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  context, volume_ref=volume_ref, **volume_spec)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 446, in _create_from_source_volume
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  model_update = self.driver.create_cloned_volume(volume_ref, srcvol_ref)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  return f(*args, **kwargs)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 2071, in create_cloned_volume
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  self._create_cloned_volume(volume, src_vref)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 2063, in _create_cloned_volume
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  src_vref['size'])
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 1985, in _clone_backing
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  snapshot, clone_type, datastore)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/volumeops.py", line 1058, in clone_backing
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  task_info = self._session.wait_for_task(task)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 288, in wait_for_task
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  return loop.start(self._task_poll_interval).wait()
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  return hubs.get_hub().switch()
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 293, in switch
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  return self.greenlet.switch()
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/openstack/common/loopingcall.py", line 81, in _inner
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  self.f(*self.args, **self.kw)
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 319, in _poll_task
2014-10-13 17:27:11.880 TRACE cinder.volume.manager  raise excep
2014-10-13 17:27:11.880 TRACE cinder.volume.manager VimFaultException: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)]
2014-10-13 17:27:11.880 TRACE cinder.volume.manager 
2014-10-13 17:27:11.882 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'ANALYZING' in response to event 'schedule' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.882 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'SCHEDULING' in response to event 'schedule' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.884 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.CreateVolumeFromSpecTask;volume:create' (8b526818-cc9c-4908-b971-efa70e9fe0aa) transitioned into state 'REVERTING'
2014-10-13 17:27:11.884 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'SCHEDULING' in response to event 'wait' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.884 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'WAITING' in response to event 'wait' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.885 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'WAITING' in response to event 'analyze' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.885 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'ANALYZING' in response to event 'analyze' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.886 DEBUG cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.CreateVolumeFromSpecTask;volume:create' (8b526818-cc9c-4908-b971-efa70e9fe0aa) transitioned into state 'REVERTED' from (pid=29640) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2014-10-13 17:27:11.886 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'ANALYZING' in response to event 'schedule' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.886 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'SCHEDULING' in response to event 'schedule' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.887 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.NotifyVolumeActionTask;volume:create, create.start' (afbf3a87-9681-4efe-be24-1ac0144d3fad) transitioned into state 'REVERTING'
2014-10-13 17:27:11.887 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'SCHEDULING' in response to event 'wait' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.887 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'WAITING' in response to event 'wait' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.888 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'WAITING' in response to event 'analyze' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.888 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'ANALYZING' in response to event 'analyze' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.888 DEBUG cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.NotifyVolumeActionTask;volume:create, create.start' (afbf3a87-9681-4efe-be24-1ac0144d3fad) transitioned into state 'REVERTED' from (pid=29640) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2014-10-13 17:27:11.889 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'ANALYZING' in response to event 'schedule' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.889 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'SCHEDULING' in response to event 'schedule' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.889 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' (03de8daa-aa11-4c3c-89ec-bb76ef76a5dc) transitioned into state 'REVERTING'
2014-10-13 17:27:11.890 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'SCHEDULING' in response to event 'wait' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.890 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'WAITING' in response to event 'wait' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.890 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'WAITING' in response to event 'analyze' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.891 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'ANALYZING' in response to event 'analyze' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.891 DEBUG cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' (03de8daa-aa11-4c3c-89ec-bb76ef76a5dc) transitioned into state 'REVERTED' from (pid=29640) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2014-10-13 17:27:11.891 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'ANALYZING' in response to event 'schedule' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.892 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'SCHEDULING' in response to event 'schedule' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.892 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (d5872268-d521-482c-83e6-03a4a94c75fe) transitioned into state 'REVERTING'
2014-10-13 17:27:11.893 DEBUG cinder.volume.flows.common [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Updating volume: 1944f3df-0649-4e05-b561-a1327c873e20 with {'status': 'error'} due to: ??? from (pid=29640) error_out_volume /opt/stack/cinder/cinder/volume/flows/common.py:88
2014-10-13 17:27:11.975 ERROR cinder.volume.flows.manager.create_volume [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Volume 1944f3df-0649-4e05-b561-a1327c873e20: create failed
2014-10-13 17:27:11.976 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'SCHEDULING' in response to event 'wait' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.976 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'WAITING' in response to event 'wait' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.977 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'WAITING' in response to event 'analyze' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.977 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'ANALYZING' in response to event 'analyze' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.978 DEBUG cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (d5872268-d521-482c-83e6-03a4a94c75fe) transitioned into state 'REVERTED' from (pid=29640) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2014-10-13 17:27:11.978 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'ANALYZING' in response to event 'finished' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.979 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'GAME_OVER' in response to event 'finished' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.979 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exiting old state 'GAME_OVER' in response to event 'reverted' from (pid=29640) on_exit /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:156
2014-10-13 17:27:11.979 DEBUG taskflow.engines.action_engine.runner [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Entering new state 'REVERTED' in response to event 'reverted' from (pid=29640) on_enter /usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py:160
2014-10-13 17:27:11.980 WARNING cinder.volume.manager [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Flow 'volume_create_manager' (5cd74cc1-3345-4530-8dd6-36d624fe2538) transitioned into state 'REVERTED' from state 'RUNNING'
2014-10-13 17:27:11.981 DEBUG cinder.openstack.common.lockutils [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Released file lock "4fb5708f-6203-43f9-8635-c783340270d5-delete_volume" at /opt/stack/data/cinder/cinder-4fb5708f-6203-43f9-8635-c783340270d5-delete_volume for method "_run_flow_locked"... from (pid=29640) inner /opt/stack/cinder/cinder/openstack/common/lockutils.py:239
2014-10-13 17:27:11.982 ERROR oslo.messaging.rpc.dispatcher [req-2b424d40-c308-495d-84eb-ec75ca9112ec d1f75a08e30e49fb8204c42e0d904187 fe1fb4e47b254cebb1ff6858eb4967be] Exception during message handling: (VimFaultException('Unable to access the virtual machine configuration: Unable to access file [local-0 (3)]',),)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  incoming.message))
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return self._do_dispatch(endpoint, method, ctxt, args)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  result = getattr(endpoint, method)(ctxt, **new_args)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return f(*args, **kwargs)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/manager.py", line 382, in create_volume
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  _run_flow_locked()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/openstack/common/lockutils.py", line 233, in inner
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  retval = f(*args, **kwargs)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/manager.py", line 377, in _run_flow_locked
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  _run_flow()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/manager.py", line 373, in _run_flow
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  flow_engine.run()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 99, in run
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  for _state in self.run_iter():
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 156, in run_iter
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  misc.Failure.reraise_if_any(failures.values())
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 733, in reraise_if_any
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  failures[0].reraise()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 740, in reraise
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  six.reraise(*self._exc_info)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 35, in _execute_task
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  result = task.execute(**arguments)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 631, in execute
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  context, volume_ref=volume_ref, **volume_spec)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 446, in _create_from_source_volume
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  model_update = self.driver.create_cloned_volume(volume_ref, srcvol_ref)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return f(*args, **kwargs)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 2071, in create_cloned_volume
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  self._create_cloned_volume(volume, src_vref)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 2063, in _create_cloned_volume
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  src_vref['size'])
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/vmdk.py", line 1985, in _clone_backing
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  snapshot, clone_type, datastore)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/volumeops.py", line 1058, in clone_backing
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  task_info = self._session.wait_for_task(task)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 288, in wait_for_task
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return loop.start(self._task_poll_interval).wait()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return hubs.get_hub().switch()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 293, in switch
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  return self.greenlet.switch()
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/openstack/common/loopingcall.py", line 81, in _inner
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  self.f(*self.args, **self.kw)
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  File "/opt/stack/cinder/cinder/volume/drivers/vmware/api.py", line 319, in _poll_task
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher  raise excep
2014-10-13 17:27:11.982 TRACE oslo.messaging.rpc.dispatcher VimFaultException: Unable to access the virtual machine configuration: Unable to access file [local-0 (3)]

[Vipin Balachandran (vbala)]

Is bronze mapped to VMFS datastore?
Does the problem exist for NFS and vSAN?

[satyadev svn (svnsatya)]

Local data store means only VMFS 5/3 . we verified with VMFS5.
VSAN datastore, shared vmfs, nfs- behavior is working fine.

[satyadev svn (svnsatya)]

Same exception observed when we create volume from snapshot taken from bronze profile

test setps :
1) create volume [say vol1] of volume-type bronze [ bronze type mapped to local vmfs data stores as bronze profile in vcenter]
2) now attach & detach a vol to instance [observe vm backing found in vcenter]
3) now take snapshot of vol1 say snap1
4) now create volume from above snapshot 'snap1' observe same exception trace as per comment1

[Vipin Balachandran (vbala)]

I am unable to reproduce this using the following steps:

1) Create volume vol-1 with a profile mapped to vmfs local datastore
2) Create nova VM vm-1 from a sparse image with vmware_adaptertype=lsiLogic
3) Attach vol-1 to vm-1
4) Detach vol-1
5) Clone vol-1

[Vipin Balachandran (vbala)]

Steps to reproduce:

* Two local datastores: ds1 and ds2 mapped to the same profile
* Create volume vol-1
* Remove profile mapping from vol-1's datastore
* Clone vol-1

This is because, we are not setting the destination host and vim CloneVM_Task API uses the source host as the destination host. If the destination datastore returned by the datastore selection logic is not accessible to the source host, clone fails.

This bug exists in Icehouse as well and is caused by Icehouse commit 848ef0043f60795db680afe8f67b633459eaf52c. Due to this, intermittent failures can occur during:
* Create volume from another volume with vmware:clone_type = full
* Create volume from image
* Restore backup
* Retype

The workaround is to use a setup where datastores are connected to all hosts. Since this is the recommended setup, the bug priority can be set to medium.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/135599

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/135599
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=9e590a6c854cec6df18630954734e4a4e0249a91
Submitter: Jenkins
Branch: master

commit 9e590a6c854cec6df18630954734e4a4e0249a91
Author: Vipin Balachandran <email address hidden>
Date: Wed Nov 19 16:08:45 2014 +0530

    VMware: Set target ESX host for backing VM clone

    The backing VM corresponding to a volume is cloned during create volume
    from another volume, snapshot or image. The backing VM is also cloned
    during retype and backup restore. Currently, the target ESX host is
    unset while calling vCenter CloneVM_Task API and hence the source ESX
    host is used as the target. If the destination datastore returned by
    the datastore selection logic is not accessible to the source host,
    clone fails. This patch fixes the problem by setting the target ESX
    host (returned by datastore selection logic) while invoking clone.

    Closes-Bug: #1380602
    Change-Id: I030d5ce6378fb70f7f98356114825abc12297687

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/137537

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/137537
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=0d60ddc76796e47f2921bdb51fc8174aa3800ab0
Submitter: Jenkins
Branch: stable/juno

commit 0d60ddc76796e47f2921bdb51fc8174aa3800ab0
Author: Vipin Balachandran <email address hidden>
Date: Wed Nov 19 16:08:45 2014 +0530

    VMware: Set target ESX host for backing VM clone

    The backing VM corresponding to a volume is cloned during create volume
    from another volume, snapshot or image. The backing VM is also cloned
    during retype and backup restore. Currently, the target ESX host is
    unset while calling vCenter CloneVM_Task API and hence the source ESX
    host is used as the target. If the destination datastore returned by
    the datastore selection logic is not accessible to the source host,
    clone fails. This patch fixes the problem by setting the target ESX
    host (returned by datastore selection logic) while invoking clone.

    Conflicts:
            cinder/volume/drivers/vmware/vmdk.py

    Closes-Bug: #1380602
    Change-Id: I030d5ce6378fb70f7f98356114825abc12297687
    (cherry picked from commit 9e590a6c854cec6df18630954734e4a4e0249a91)