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='df3f 26e1b7384a749ead0781a707491a',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', 'sub nets': [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/vi rt/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-21 T08: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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp