yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1476591] Re: volume in_use after VM has terminated

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: AMRITANSHU <amritgeo@xxxxxxxxx>
Date: Thu, 20 Aug 2015 11:34:16 -0000
Reply-to: Bug 1476591 <1476591@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Its  not the bug as I see once  yoy have openstack environment working
properly then you can create a vm attach a volume but when you are
deleting a vm you must detach volume then delete the vm .

As you delete vm  root volume willbe deleted according to functionality
but the volume attached will not be dtached as you had not detached it.

You have to manually detach it by the voulmes tab by going to that
volume.

** Changed in: nova
     Assignee: (unassigned) => AMRITANSHU (amritgeo)

** Changed in: nova
       Status: New => Opinion

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

Title:
  volume in_use after VM has terminated

Status in Cinder:
  New
Status in OpenStack Compute (nova):
  Opinion

Bug description:
  Running the Tempest test
  tempest.scenario.test_volume_boot_pattern.TestVolumeBootPatternV2.test_volume_boot_pattern
  with our CI system runs into a timing issue in the interaction between
  Nova and Cinder.

  Essentially on the Cinder side the volume status of the volume  used
  in the test is 'in_use' for several seconds _after_ the tests VM has
  already been terminated and cleaned up, including the umounting of the
  given volume on the Nova side. As Cinder sees the volume is still
  'in_use' it calls the Nova API to perform the snapshot deletion but
  since the volume has already been umounted on the Nova side the
  resulting qemu-img operation triggered by Nova runs into a 'no such
  file or directory' error.

  The following log excerpts show this issue. Please refer to the given
  time stamps (all components run in a devstack in the same machine so
  times should be comparable):

  1) Cinder log (please note i added two debug lines printing the volume status data in this snippet that are not part of the upstream driver):
  2015-07-21 08:14:10.163 DEBUG cinder.volume.drivers.remotefs [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] Deleting snapshot ca09f072-c736-41ac-b6f3-7a137b0ee072: _delete_s
  napshot /opt/stack/cinder/cinder/volume/drivers/remotefs.py:915
  2015-07-21 08:14:10.164 DEBUG cinder.volume.drivers.remotefs [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] Initial snapshot deletion volume status is in-use _delete_snapsho
  t /opt/stack/cinder/cinder/volume/drivers/remotefs.py:918
  2015-07-21 08:14:10.420 DEBUG cinder.volume.drivers.remotefs [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] snapshot_file for this snap is: volume-7f4a5711-9f2c-4aa7-a6af-c6
  ccf476702d.ca09f072-c736-41ac-b6f3-7a137b0ee072 _delete_snapshot /opt/stack/cinder/cinder/volume/drivers/remotefs.py:941
  2015-07-21 08:14:10.420 DEBUG oslo_concurrency.processutils [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwra
  p.conf env LC_ALL=C qemu-img info /opt/stack/data/cinder/mnt/38effaab97f9ee27ecb78121f511fa07/volume-7f4a5711-9f2c-4aa7-a6af-c6ccf476702d.ca09f072-c736-41ac-b6f3-7a137b0ee072 execute /usr/local/lib/python2.7/dis
  t-packages/oslo_concurrency/processutils.py:230
  2015-07-21 08:14:11.549 DEBUG oslo_concurrency.processutils [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C q
  emu-img info /opt/stack/data/cinder/mnt/38effaab97f9ee27ecb78121f511fa07/volume-7f4a5711-9f2c-4aa7-a6af-c6ccf476702d.ca09f072-c736-41ac-b6f3-7a137b0ee072" returned: 0 in 1.129s execute /usr/local/lib/python2.7/d
  ist-packages/oslo_concurrency/processutils.py:260
  2015-07-21 08:14:11.700 DEBUG cinder.volume.drivers.remotefs [req-6dae7608-e1f4-43af-ac8e-22d6aa7d72c9 tempest-TestVolumeBootPatternV2-966547300] In delete_snapshot, volume status is in-use _delete_snapshot /opt
  /stack/cinder/cinder/volume/drivers/remotefs.py:956

  2) Nova log:
  2015-07-21 08:14:05.153 INFO nova.compute.manager [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] [instance: adbe1fa4-7136-4d29-91d
  0-5772dbf4900d] Terminating instance  
  2015-07-21 08:14:05.167 6183 INFO nova.virt.libvirt.driver [-] [instance: adbe1fa4-7136-4d29-91d0-5772dbf4900d] Instance destroyed successfully.  
  2015-07-21 08:14:05.167 DEBUG nova.virt.libvirt.vif [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] vif_type=bridge instance=Instan
  ce(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=False,config_drive='True',created_at=2015-07-21T08:13:32Z,default_ephemeral_device=No
  ne,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='tempest-TestVolumeBootPatternV2-147549174',display_name='tempest-TestVolumeBootPatternV2-147549174',ec2_ids=
  <?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(6),host='manualvm',hostname='tempest-testvolumebootpatternv2-147549174',id=140,image_ref='',info_cache=InstanceInfoCache,instance_type_id=6,kernel_id='f203cd87-b5ed-491a-b7a5-46ad2e63bcbf',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDJ2yTWvjXK/IwK8xlmSjTn4drDwH5nMr65gYD4j3mkZBfBuk5Zuf10mLwVUFVDTgacJVcG4AE96poXofHD64pbGEcP9NqYGbLV7JSJzgNznUO/RkMdBBmmmfJiACvtWYpigAMIPPddgmpQZVaG+q8VelEWfDiErOBiaajz/NjL8/mmP78Lq0xvuP44vy/EElaSob8iiqFeg6rTlMpzhkFUV1a52CSQYjmD80mSf932ljXgNU9A4pE8NkO4lDOkflQfLO2F6wxV9H94VKxTBJgwnH8BANP7V8rjeIOwwUmpF1F6D4LceA66j1ONHk4ssyU3iimWt+UMwGCFWF6aa58n Generated-by-Nova',key_name='tempest-TestVolumeBootPatternV2-787092881',launch_index=0,launched_at=2015-07-21T08:13:42Z,launched_on='manualvm',locked=False,locked_by=None,memory_mb=64,metadata={},new_flavor=None,node='manualvm',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=4,progress=0,project_id='df3f26e1b7384a749ead0781a707491a',ramdisk_id='7c2ac51d-e571-4de6-b303-0302653677d8',reservation_id='r-40fs0tcw',root_device_name='/dev/vda',root_gb=0,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={image_base_image_ref='',image_checksum='eb9139e4942121f22bbc2afc0400b2a4',image_container_format='ami',image_disk_format='ami',image_image_id='5ce2d454-426c-4db5-8631-64228e29ff53',image_image_name='cirros-0.3.4-x86_64-uec',image_kernel_id='f203cd87-b5ed-491a-b7a5-46ad2e63bcbf',image_min_disk='0',image_min_ram='0',image_ramdisk_id='7c2ac51d-e571-4de6-b303-0302653677d8',image_size='25165824'},tags=<?>,task_state='deleting',terminated_at=None,updated_at=2015-07-21T08:14:04Z,user_data=None,user_id='9c6a53d821864b3ab3fc98933c672faf',uuid=adbe1fa4-7136-4d29-91d0-5772dbf4900d,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='stopped') vif=VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.10.0.4'})], 'version': 4, 'meta': {u'dhcp_server': u'10.10.0.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.10.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.10.0.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'tap1'}, 'id': u'4be2d94e-e059-44e4-a781-919ccf9600a7', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:de:a8:56', 'active': False, 'type': u'bridge', 'id': u'011753cb-a2d1-4cd0-bde6-3abf9b381871', 'qbg_params': None}) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:800  
  2015-07-21 08:14:05.169 DEBUG oslo_concurrency.lockutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lock "connect_volume" acquired by "disconnect_volume" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:251  
  2015-07-21 08:14:05.170 DEBUG oslo_concurrency.processutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Running cmd (subprocess): findmnt --target /opt/stack/data/nova/mnt/38effaab97f9ee27ecb78121f511fa07 --source quobyte@176.9.127.22:7861/quobyteci_test_volume execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:230
  2015-07-21 08:14:05.198 DEBUG oslo_concurrency.processutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] CMD "findmnt --target /opt/stack/data/nova/mnt/38effaab97f9ee27ecb78121f511fa07 --source quobyte@176.9.127.22:7861/quobyteci_test_volume" returned: 0 in 0.028s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:260  
  2015-07-21 08:14:05.199 DEBUG nova.virt.libvirt.quobyte [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Unmounting /opt/stack/data/nova/mnt/38effaab97f9ee27ecb78121f511fa07 umount_volume /opt/stack/nova/nova/virt/libvirt/quobyte.py:55  
  2015-07-21 08:14:05.200 DEBUG oslo_concurrency.processutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Running cmd (subprocess): umount.quobyte /opt/stack/data/nova/mnt/38effaab97f9ee27ecb78121f511fa07 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:230
  2015-07-21 08:14:05.260 DEBUG oslo_concurrency.processutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] CMD "umount.quobyte /opt/stack/data/nova/mnt/38effaab97f9ee27ecb78121f511fa07" returned: 0 in 0.059s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:260  
  2015-07-21 08:14:05.260 DEBUG oslo_concurrency.lockutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lock "connect_volume" released by "disconnect_volume" :: held 0.091s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:262
  [..]
  2015-07-21 08:14:07.243 DEBUG nova.compute.manager [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] [instance: adbe1fa4-7136-4d29-91d0-5772dbf4900d] terminating bdm BlockDeviceMapping(boot_index=0,connection_info='{"driver_volume_type": "quobyte", "mount_point_base": "/opt/stack/data/cinder/mnt", "serial": "313f97e6-e36a-4536-a7c6-00c340f12f8e", "data": {"name": "volume-313f97e6-e36a-4536-a7c6-00c340f12f8e", "format": "qcow2", "encrypted": false, "qos_specs": null, "export": "176.9.127.22:7861/quobyteci_test_volume", "access_mode": "rw", "options": null}}',created_at=2015-07-21T08:13:32Z,delete_on_termination=False,deleted=False,deleted_at=None,destination_type='volume',device_name='/dev/vda',device_type='disk',disk_bus='virtio',guest_format=None,id=178,image_id=None,instance=<?>,instance_uuid=adbe1fa4-7136-4d29-91d0-5772dbf4900d,no_device=False,snapshot_id=None,source_type='volume',updated_at=2015-07-21T08:13:39Z,volume_id='313f97e6-e36a-4536-a7c6-00c340f12f8e',volume_size=1) _cleanup_volumes /opt/stack/nova/nova/compute/manager.py:2265  
  2015-07-21 08:14:07.466 DEBUG oslo_concurrency.lockutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lock "compute_resources" acquired by "update_usage" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:251  
  2015-07-21 08:14:07.467 DEBUG nova.objects.instance [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lazy-loading `numa_topology' on Instance uuid adbe1fa4-7136-4d29-91d0-5772dbf4900d obj_load_attr /opt/stack/nova/nova/objects/instance.py:1016  
  2015-07-21 08:14:07.528 DEBUG oslo_concurrency.lockutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lock "compute_resources" released by "update_usage" :: held 0.061s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:262  
  2015-07-21 08:14:07.777 DEBUG oslo_concurrency.lockutils [req-e9bea12a-88ef-4f08-a320-d6e8e3b21228 tempest-TestVolumeBootPatternV2-1465284168 tempest-TestVolumeBootPatternV2-966547300] Lock "adbe1fa4-7136-4d29-91d0-5772dbf4900d" released by "do_terminate_instance" :: held 2.627s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:262  

  
  So what i see is that Nova terminates (including umount) at 08:14:05 until 08:14:07 and Cinder wants to remove the snapshot and check's the volumes state at 08:14:10 until 08:14:11 where it is still 'in-use'. Cinder subsequently chooses to contact Nova for snapshot deletion which fails as nova has already umounted the required volume.

  Has anybody seen similar issues before?
  And i'm grateful for hints/pointers to the code where the volume status is updated, i could not find out where that happens, so far.

  PS: This setup uses the change under review in
  https://review.openstack.org/#/c/192736/12 . Essentially i ran into
  the issue by doing a manual tempest test run of that change.

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

[Bug 1476591] [NEW] volume in_use after VM has terminated
From: Silvan Kaiser, 2015-07-21