nova compute instance deletion on NFS filesystem fails

[Sreenivasa Rao Bavisetti]

Instance creation on NFS leave qemu-system process which locks Instance disk file on NFS cause deletion failure.

The process locks the instance disk on NFS :
qemu-system-x86_64 -machine accel=kvm:tcg -global virtio-blk-pci.scsi=off -drive file=/var/lib/nova/instances/f8f5481e-b5f2-4dfb-a299-245f9ad691b9/disk,cache=off,format=qcow2,if=virtio -nodefconfig -machine accel=kvm:tcg -nodefaults -nographic -m 500 -no-reboot -no-hpet -device virtio-serial -serial stdio -chardev socket,path=/tmp/libguestfsO9sbVq/guestfsd.sock,id=channel0 -device virtserialport,chardev=channel0,name=org.libguestfs.channel.0 -kernel /var/tmp/.guestfs-120/kernel.23462 -initrd /var/tmp/.guestfs-120/initrd.23462 -append panic=1 console=ttyS0 udevtimeout=300 no_timer_check acpi=off printk.time=1 cgroup_disable=memory selinux=0 TERM=linux -drive file=/var/tmp/.guestfs-120/root.23462,snapshot=on,if=virtio,cache=unsafe

When instance is deleted, the following messages are logged:

=================================
2014-04-18 16:35:17.905 5731 INFO nova.compute.resource_tracker [-] Compute_service record updated for dmsosnovacomp6:dmsosnovacomp6.dmlabs.verizon.com
2014-04-18 16:35:18.379 5731 INFO nova.ceilometer.notifier [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] processing compute.instance.delete.start
2014-04-18 16:35:18.565 5731 INFO ceilometer.compute.pollsters.disk [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] DISKIO USAGE: <ceilometer.compute.nova_notifier.Instance object at 0x394d1d0> vda: read-requests=5183 read-bytes=77607936 write-requests=3796 write-bytes=344785920 errors=-1
2014-04-18 16:35:18.595 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] checking instance 2190
2014-04-18 16:35:18.620 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] NETWORK USAGE: instance-0000088e tapffb76b64-bc: read-bytes=18510 write-bytes=17101
2014-04-18 16:35:18.623 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] checking instance 2190
2014-04-18 16:35:18.623 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] NETWORK USAGE: instance-0000088e tapffb76b64-bc: read-bytes=18510 write-bytes=17101
2014-04-18 16:35:18.624 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] checking instance 2190
2014-04-18 16:35:18.625 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] NETWORK USAGE: instance-0000088e tapffb76b64-bc: read-bytes=18510 write-bytes=17101
2014-04-18 16:35:18.626 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] checking instance 2190
2014-04-18 16:35:18.627 5731 INFO ceilometer.compute.pollsters.net [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] NETWORK USAGE: instance-0000088e tapffb76b64-bc: read-bytes=18510 write-bytes=17101
2014-04-18 16:35:18.628 5731 INFO ceilometer.compute.pollsters.cpu [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] checking instance 2190
2014-04-18 16:35:18.651 5731 INFO ceilometer.compute.pollsters.cpu [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] CPUTIME USAGE: {'flavor_name': u'm1.small', 'vm_state': u'active', 'internal_id': None, 'availability_zone': u'nova', 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 5, 'user_data': None, 'OS-EXT-SRV-ATTR:instance_name': u'instance-0000088e', 'cleaned': 0, 'vm_mode': None, 'deleted_at': None, 'reservation_id': u'r-tx9y20gm', 'id': 2190, 'security_groups': [{u'project_id': u'1129030a03974f5087edd212704d3a4c', u'user_id': u'1f631c561b634f31a31e207a999c70b3', u'name': u'default', u'deleted': 0, u'created_at': u'2014-03-14T16:47:30.000000', u'updated_at': None, u'rules': [], u'deleted_at': None, u'id': 3, u'description': u'default'}], 'disable_terminate': False, 'user_id': u'1f631c561b634f31a31e207a999c70b3', 'uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', 'default_swap_device': None, 'info_cache': {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 2190, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': u'2014-04-18T20:32:32.000000', u'network_info': u'[{"ovs_interfaceid": "ffb76b64-bc06-4493-9a3b-9a2aad74bb45", "network": {"bridge": "br-int", "subnets": [{"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.5.5.3"}], "version": 4, "meta": {"dhcp_server": "10.5.5.2"}, "dns": [{"meta": {}, "version": 4, "type": "dns", "address": "152.190.136.8"}], "routes": [], "cidr": "10.5.5.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "10.5.5.1"}}], "meta": {"injected": false, "tenant_id": "1129030a03974f5087edd212704d3a4c"}, "id": "2b41e5b5-d995-44a9-9d15-ad55765227f0", "label": "demo-net-1"}, "devname": "tapffb76b64-bc", "qbh_params": null, "meta": {}, "address": "fa:16:3e:9e:6a:66", "type": "ovs", "id": "ffb76b64-bc06-4493-9a3b-9a2aad74bb45", "qbg_params": null}]', u'deleted_at': u'2014-04-18T20:35:18.000000', u'id': 2190}, 'hostname': u'sreeni-test1', 'launched_on': u'dmsosnovacomp6', 'display_description': u'sreeni-test1', 'key_data': u'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCizOGhx/xs+hU03hlmDA5rK33Sy+p8oGRp7AimL5mqMGjwurZMpG61gn4ak/Wps9ZwSwsTi0bIl9C+imnNzNJHcL4+kbbj0Mg1TpostgIvqsAMnRN9BjXMAEMzcoEh4Ob81i151oGvI8dgZvnQeJYPko/WcC9hNfNL6ZEujzQ9AihH4NOtXME+bb+D4GiduLIfy+akTB94t7UJD5I89lR9XP3tU0z3KULztuHu+xf+JIAwhMi2X+shP0JqRKYHfP9W6qhx+855vbvAA9bfhNYHgTWhSZIxF7bdiMxKDesRtiCnKmu62IOfd9msB91B6v35U5VpLI12RmcLxODXFV7R dmsos@dmsosadmin1\n', 'kernel_id': u'', 'power_state': 1, 'default_ephemeral_device': None, 'progress': 0, 'project_id': u'1129030a03974f5087edd212704d3a4c', 'launched_at': u'2014-04-18T20:33:33.000000', 'scheduled_at': u'2014-04-18T20:32:30.000000', 'node': u'dmsosnovacomp6.dmlabs.verizon.com', 'ramdisk_id': u'', 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': 0, 'key_name': u'mar21demokey', 'updated_at': u'2014-04-18T20:35:18.000000', 'host': u'dmsosnovacomp6', 'architecture': u'x86_64', 'display_name': u'sreeni-test1', 'system_metadata': [{u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'ubuntu', u'key': u'image_os_distro', u'deleted_at': None, u'id': 36798}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'2048', u'key': u'instance_type_memory_mb', u'deleted_at': None, u'id': 36801}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_swap', u'deleted_at': None, u'id': 36804}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': None, u'key': u'instance_type_vcpu_weight', u'deleted_at': None, u'id': 36807}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'20', u'key': u'instance_type_root_gb', u'deleted_at': None, u'id': 36810}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'5', u'key': u'instance_type_id', u'deleted_at': None, u'id': 36813}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'm1.small', u'key': u'instance_type_name', u'deleted_at': None, u'id': 36816}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'0', u'key': u'instance_type_ephemeral_gb', u'deleted_at': None, u'id': 36819}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_rxtx_factor', u'deleted_at': None, u'id': 36822}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'raw', u'key': u'image_disk_format', u'deleted_at': None, u'id': 36825}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'x86_64', u'key': u'image_architecture', u'deleted_at': None, u'id': 36828}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'2', u'key': u'instance_type_flavorid', u'deleted_at': None, u'id': 36831}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'bare', u'key': u'image_container_format', u'deleted_at': None, u'id': 36834}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'1', u'key': u'instance_type_vcpus', u'deleted_at': None, u'id': 36837}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'0', u'key': u'image_min_ram', u'deleted_at': None, u'id': 36840}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'20', u'key': u'image_min_disk', u'deleted_at': None, u'id': 36843}, {u'instance_uuid': u'1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5', u'deleted': 0, u'created_at': u'2014-04-18T20:32:29.000000', u'updated_at': None, u'value': u'd947c1fa-6099-4a02-914e-0cc74f79bbce', u'key': u'image_base_image_ref', u'deleted_at': None, u'id': 36846}], 'task_state': u'deleting', 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 20, 'locked': False, 'created_at': u'2014-04-18T20:32:29.000000', 'locked_by': None, 'launch_index': 0, 'metadata': {}, 'memory_mb': 2048, 'vcpus': 1, 'image_ref': u'd947c1fa-6099-4a02-914e-0cc74f79bbce', 'root_device_name': u'/dev/vda', 'auto_disk_config': False, 'os_type': None, 'config_drive': u''} 10900000000
2014-04-18 16:35:18.663 5731 AUDIT nova.compute.manager [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] Terminating instance
2014-04-18 16:35:19.828 5731 INFO nova.compute.manager [-] Lifecycle event 1 on VM 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5
2014-04-18 16:35:19.835 5731 INFO nova.virt.libvirt.driver [-] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] Instance destroyed successfully.
2014-04-18 16:35:19.997 5731 INFO nova.compute.manager [-] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] During sync_power_state the instance has a pending task. Skip.
2014-04-18 16:35:20.022 5731 INFO nova.virt.libvirt.driver [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] Deleting instance files /var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5
2014-04-18 16:35:20.029 5731 ERROR nova.virt.libvirt.driver [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] Failed to cleanup directory /var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5: [Errno 39] Directory not empty: '/var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5'
2014-04-18 16:35:20.030 5731 INFO nova.virt.libvirt.driver [req-aa9cc8e7-8fb8-4d11-960c-41fec0e1d2e7 1f631c561b634f31a31e207a999c70b3 1129030a03974f5087edd212704d3a4c] [instance: 1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5] Deletion of /var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5 failed
================================
the instance folder listing :

drwxr-xr-x 2 nova nova 4096 Apr 18 16:35 .
drwxrwxrwx 170 nova nova 20480 Apr 18 16:33 ..
-rw-r--r-- 1 root root 346488832 Apr 18 16:35 .nfs000000000b5e52a900000001
================================
~# fuser -vm /var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5/
                     USER PID ACCESS COMMAND
/var/lib/nova/instances/1d82813e-c1ee-4d4d-b9b2-d532fc83c2c5:
                     root kernel mount /var/lib/nova/instances
                     nova 1602 F.... qemu-system-x86
                     nova 1603 F.... nova-compute
================================

restarting nova-compute service releases the nfs lock,

[Thang Pham (thang-pham)]

Which version of nova are you using?

[Sreenivasa Rao Bavisetti (sreenivas-bavisetti)]

nova --version
2.15.0

[Thang Pham (thang-pham)]

Did the NFS server crash or something, for you to get the lock? What was the state of the NFS server at the time of instance delete?

[Markus Zoeller (markus_z) (mzoeller)]

This is an automated cleanup. This bug report has been closed because it
is older than 18 months and there is no open code change to fix this.
After this time it is unlikely that the circumstances which lead to
the observed issue can be reproduced.

If you can reproduce the bug, please:
* reopen the bug report (set to status "New")
* AND add the detailed steps to reproduce the issue (if applicable)
* AND leave a comment "CONFIRMED FOR: <RELEASE_NAME>"
  Only still supported release names are valid (LIBERTY, MITAKA, OCATA, NEWTON).
  Valid example: CONFIRMED FOR: LIBERTY