yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1184807] Re: Snapshot failure with VMwareVCDriver

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Tracy Jones <tjones@xxxxxxxxxx>
Date: Wed, 25 Sep 2013 21:12:07 -0000
Reply-to: Bug 1184807 <1184807@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: openstack-vmwareapi-team
       Status: Fix Released => Fix Committed

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1184807

Title:
  Snapshot failure with VMwareVCDriver

Status in OpenStack Compute (Nova):
  Fix Committed
Status in The OpenStack VMwareAPI subTeam:
  Fix Committed

Bug description:
  I am unable to get snapshots working in my dev setup with the
  VCDriver.

  snapshot API call claims to succeed, but we get an internal exception
  (below) and the snapshot stays  in 'queued' status in Horizon.

  The relevant code is here:
  https://github.com/openstack/nova/blob/master/nova/virt/vmwareapi/vmops.py#L515

   It seems like the underlying snapshot succeeds, but the attempt to copy the disk afterward fails.  Browsing the datastore, I see that a vmware-tmp directory was created, but I do not see any files in it.  
   

  
  space/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:04.615 DEBUG nova.virt.vmwareapi.driver [-] Task [CreateSnapshot_Task] (returnval){
     value = "task-123"
     _type = "Task"
   } status: success from (pid=4595) _poll_task /extraspace/stack/nova/nova/virt/vmwareapi/driver.py:576
  2013-05-27 17:15:04.615 DEBUG nova.virt.vmwareapi.vmops [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] [instance: 0d044e1b-074b-47de-9002-de5d87230aa5] Created Snapshot of the VM instance from (pid=4595) _create_vm_snapshot /extraspace/stack/nova/nova/virt/vmwareapi/vmops.py:477
  2013-05-27 17:15:04.616 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Making synchronous call on conductor ... from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:586
  2013-05-27 17:15:04.616 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] MSG_ID is 43832e8692c64fdeabba8b34c531b682 from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:589
  2013-05-27 17:15:04.617 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] UNIQUE_ID is ff2a695783ba459e8aef5a0097eefb95. from (pid=4595) _add_unique_id /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:04.981 DEBUG nova.openstack.common.lockutils [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Got semaphore "compute_resources" for method "update_usage"... from (pid=4595) inner /extraspace/stack/nova/nova/openstack/common/lockutils.py:186
  2013-05-27 17:15:04.982 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Making synchronous call on conductor ... from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:586
  2013-05-27 17:15:04.982 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] MSG_ID is 8de1b35ad1624e4cbbd25dca3b7ff41e from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:589
  2013-05-27 17:15:04.983 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] UNIQUE_ID is 96b0cd1f45e84bc486863e9bab4b1b8f. from (pid=4595) _add_unique_id /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:05.174 DEBUG nova.virt.vmwareapi.vmops [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] [instance: 0d044e1b-074b-47de-9002-de5d87230aa5] Copying disk data before snapshot of the VM from (pid=4595) _copy_vmdk_content /extraspace/stack/nova/nova/virt/vmwareapi/vmops.py:522
  2013-05-27 17:15:05.222 WARNING nova.virt.vmwareapi.driver [-] Task [CopyVirtualDisk_Task] (returnval){
     value = "task-124"
     _type = "Task"
   } status: error The requested operation is not implemented by the server.
  2013-05-27 17:15:05.224 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Making synchronous call on conductor ... from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:586
  2013-05-27 17:15:05.224 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] MSG_ID is 838e0c86a1b04e46856ed43797442f6f from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:589
  2013-05-27 17:15:05.225 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] UNIQUE_ID is bcb86dcabbb040bf81bfa0a0676e4b14. from (pid=4595) _add_unique_id /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:05.244 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Making synchronous call on conductor ... from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:586
  2013-05-27 17:15:05.244 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] MSG_ID is 41c6cb58361f4686b717f3e3f3074178 from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:589
  2013-05-27 17:15:05.244 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] UNIQUE_ID is c732adbadd424eb1ac56d2e259041600. from (pid=4595) _add_unique_id /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:05.624 DEBUG nova.openstack.common.lockutils [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Got semaphore "compute_resources" for method "update_usage"... from (pid=4595) inner /extraspace/stack/nova/nova/openstack/common/lockutils.py:186
  2013-05-27 17:15:05.625 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Making synchronous call on conductor ... from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:586
  2013-05-27 17:15:05.626 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] MSG_ID is 206d42da6b5947caaaa3473d80744544 from (pid=4595) multicall /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:589
  2013-05-27 17:15:05.626 DEBUG nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] UNIQUE_ID is 2ab81258b1c8413e83eb278d4d3539a2. from (pid=4595) _add_unique_id /extraspace/stack/nova/nova/openstack/common/rpc/amqp.py:337
  2013-05-27 17:15:05.672 ERROR nova.openstack.common.rpc.amqp [req-5a19f94a-6e87-4196-8bbd-4ea396e2f04f demo demo] Exception during message handling
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/openstack/common/rpc/amqp.py", line 433, in _process_data
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     **args)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 148, in dispatch
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return getattr(proxyobj, method)(ctxt, **kwargs)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/exception.py", line 98, in wrapped
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     temp_level, payload)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/exception.py", line 75, in wrapped
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return f(self, context, *args, **kw)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/compute/manager.py", line 214, in decorated_function
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     pass
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/compute/manager.py", line 200, in decorated_function
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/compute/manager.py", line 242, in decorated_function
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     e, sys.exc_info())
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/compute/manager.py", line 229, in decorated_function
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/compute/manager.py", line 1887, in snapshot_instance
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self.driver.snapshot(context, instance, image_id, update_task_state)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/virt/vmwareapi/driver.py", line 180, in snapshot
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self._vmops.snapshot(context, instance, name, update_task_state)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/virt/vmwareapi/vmops.py", line 537, in snapshot
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     _copy_vmdk_content()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/virt/vmwareapi/vmops.py", line 533, in _copy_vmdk_content
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     self._session._wait_for_task(instance['uuid'], copy_disk_task)
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/extraspace/stack/nova/nova/virt/vmwareapi/driver.py", line 559, in _wait_for_task
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     ret_val = done.wait()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 116, in wait
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return hubs.get_hub().switch()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp   File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 187, in switch
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp     return self.greenlet.switch()
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp NovaException: The requested operation is not implemented by the server.
  2013-05-27 17:15:05.672 TRACE nova.openstack.common.rpc.amqp

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1184807/+subscriptions