yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1885528] Re: snapshot delete fails on shutdown VM

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Elod Illes <1885528@xxxxxxxxxxxxxxxxxx>
Date: Thu, 03 Jun 2021 17:26:29 -0000
Reply-to: Bug 1885528 <1885528@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova/ussuri
       Status: In Progress => Fix Released

** Changed in: nova/victoria
       Status: Fix Committed => Fix Released

-- 
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/1885528

Title:
  snapshot delete fails on shutdown VM

Status in OpenStack Compute (nova):
  Fix Released
Status in OpenStack Compute (nova) queens series:
  New
Status in OpenStack Compute (nova) rocky series:
  In Progress
Status in OpenStack Compute (nova) stein series:
  New
Status in OpenStack Compute (nova) trunk series:
  New
Status in OpenStack Compute (nova) ussuri series:
  Fix Released
Status in OpenStack Compute (nova) victoria series:
  Fix Released

Bug description:
  Description:
  When we try to delete the last snapshot of a VM in shutdown state, this snapshot_delete will fail (and be stuck in state error-deleting). When setting state==available and redeleting the snapshot, the volume will be corrupted and the VM will never start again. Volumes are stored on NFS.
  (for root cause and fix, see the bottom of this post)

  To reproduce:
  - storage on NFS
  - create a VM and some snapshots
  - shut down the VM (ie volume is still considered "attached" but vm is no longer "active")
  - delete the last snapshot

  Expected Result:
  snapshot is deleted, vm still works

  Actual result:
  The snapshot is stuck on error deleting. After setting the snapshot state==available and deleting the snapshot again, the volume will be corrupted and the VM will never start again. (non-existing backing_file in qcow on disk)

  Environment:
  - openstack version: stein, deployed via kolla-ansible. I suspect this downloads from git but i don't know the exact version.
  - hypervisor: Libvirt + KVM
  - storage: NFS
  - networking: Neutron with OpenVSwitch

  Nova debug Logs:
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [req-d38b5ec8-afdb-4dfe-af12-0c47598c6a47 6dd1c995b2ea4ddfbeb0685bc52e5fbf 6bebb564667d4a75b9281fd826b32ecf - d
  efault default] [instance: 711651a3-8440-42dd-a210-e7e550a8624e] Error occurred during volume_snapshot_delete, sending error status to Cinder.: DiskNotFound: No disk at
   volume-86c06b12-699c-4b54-8bca-fb92c99a2bf0.63d1585e-eb76-4e8f-bc96-93960e9c9692
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e] Traceback (most recent call last):
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/dri
  ver.py", line 2726, in volume_snapshot_delete
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]     snapshot_id, delete_info=delete_info)
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/dri
  ver.py", line 2686, in _volume_snapshot_delete
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]     rebase_base)
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/dri
  ver.py", line 2519, in _rebase_with_qemu_img
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]     b_file_fmt = images.qemu_img_info(backing_file).file_forma
  t
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]   File "/usr/lib/python2.7/site-packages/nova/virt/images.py",
   line 58, in qemu_img_info
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e]     raise exception.DiskNotFound(location=path)
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e] DiskNotFound: No disk at volume-86c06b12-699c-4b54-8bca-fb92c9
  9a2bf0.63d1585e-eb76-4e8f-bc96-93960e9c9692
  2020-02-06 12:20:10.713 6 ERROR nova.virt.libvirt.driver [instance: 711651a3-8440-42dd-a210-e7e550a8624e] 
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server [req-d38b5ec8-afdb-4dfe-af12-0c47598c6a47 6dd1c995b2ea4ddfbeb0685bc52e5fbf 6bebb564667d4a75b9281fd826b32ecf - 
  default default] Exception during message handling: DiskNotFound: No disk at volume-86c06b12-699c-4b54-8bca-fb92c99a2bf0.63d1585e-eb76-4e8f-bc96-93960e9c9692
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 166, in _process_incoming
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 265, in dispatch
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 194, in _do_dispatch
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 229, in inner
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     return func(*args, **kwargs)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 79, in wrapped
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     function_name, call_dict, binary, tb)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     self.force_reraise()
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 69, in wrapped
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     return f(self, context, *args, **kw)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3686, in volume_snapshot_delete
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     snapshot_id, delete_info)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2734, in volume_snapshot_delete
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     context, snapshot_id, 'error_deleting')
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     self.force_reraise()
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     six.reraise(self.type_, self.value, self.tb)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2726, in volume_snapshot_delete
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     snapshot_id, delete_info=delete_info)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2686, in _volume_snapshot_delete
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     rebase_base)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2519, in _rebase_with_qemu_img
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     b_file_fmt = images.qemu_img_info(backing_file).file_format
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server   File "/usr/lib/python2.7/site-packages/nova/virt/images.py", line 58, in qemu_img_info
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server     raise exception.DiskNotFound(location=path)
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server DiskNotFound: No disk at volume-86c06b12-699c-4b54-8bca-fb92c99a2bf0.63d1585e-eb76-4e8f-bc96-93960e9c9692
  2020-02-06 12:20:10.780 6 ERROR oslo_messaging.rpc.server 

  Root Cause:
  When you look at the first line in the debug log: "No disk at volume-volid.snapid", you will notice that this is a relative path. When the code does an `os.path.exists("volume-volid.snapid")` this will obviously fail (as nova has a cwd="/") and the volumes are stored under "/usr/lib/nova/mnt/xxxxx/". If an absolute path were used, the code would be much happier :)

  Code path:
    - cinder->snapshot_delete
    - In remotefs.py (called for nfs): if volume is attached -> call nova snapshot_delete
    - nova-> snapshot_delete: If snapshot_to_merge == active -> do rebase
    - if VM is not active: call _rebase_with_qemu_img (virt/libvirt/driver.py)
    - rebase_base/backing_file is now usually a relative file (depends on wether qemu_img_info is called with json or human and can also depend on the cwd). In all instances i saw, this was a relative path. When _rebase_with_qemu_img calls images.qemu_img_info(backing_file), this will fail unless supplied with and absolute path (first line in qemu_img_info does an os.path.exists which will obviously fail on a relative path). This will cause the snapshot delete to fail.

  Potential, cinder_based fix:
  In cinder, qemu_img_info is typically wrapped to always convert the backing_file to a relative path. In the code there are typically 2 variables: backing_file (relative) and backing_path(absolute). The code then decides when to use what variable:

  Patch:
  --- /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py.orig   2020-06-22 14:48:09.760186268 +0000
  +++ /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py        2020-06-25 15:26:42.344963030 +0000
  @@ -2515,8 +2515,10 @@
               # If the rebased image is going to have a backing file then
               # explicitly set the backing file format to avoid any security
               # concerns related to file format auto detection.
  -            backing_file = rebase_base
  -            b_file_fmt = images.qemu_img_info(backing_file).file_format
  +            backing_file = os.path.basename(rebase_base)  # relative path
  +            volume_path = os.path.dirname(active_disk_object.source_path)
  +            backing_path = os.path.join(volume_path, backing_file)  # absolute
  +            b_file_fmt = images.qemu_img_info(backing_path).file_format
               qemu_img_extra_arg = ['-F', b_file_fmt]
   
           qemu_img_extra_arg.append(active_disk_object.source_path)

  Note:
  We've only been able to test on Stein. However based on a code analysis of the current code in git, this bug is probably still present.

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

[Bug 1885528] [NEW] snapshot delete fails on shutdown VM
From: anon, 2020-06-29