Bug 1318883

Summary: Nova deletes an instance, but doesn't update the database
Product: Red Hat OpenStack Reporter: VIKRANT <vaggarwa>
Component: openstack-novaAssignee: Diana Clarke <dclarke>
Status: CLOSED ERRATA QA Contact: Gabriel Szasz <gszasz>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.0 (Kilo)CC: berrange, dasmith, dclarke, eglynn, kchamart, natsuki.ogawa.mb, sbauza, sbezverk, sferdjao, sgordon, srevivo, vaggarwa, vromanso
Target Milestone: ---Keywords: ZStream
Target Release: 7.0 (Kilo)   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: openstack-nova-2015.1.3-13.el7ost Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-06-01 12:26:52 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1236756    

Comment 2 VIKRANT 2016-03-28 05:57:15 UTC 
Hi,

On the different case # 01601450 from same Cu. It has been identified that host parameter was configured in cinder.conf file which was leading to the host mismatch issue when the cinder service was getting fail-over between controller nodes.

After adding this parameter, previously created volumes are also updated in DB.

~~~
host=<something> in cinder.conf
~~~

But it seems like that still cinder vol detaching issue persist.
Comment 3 Diana Clarke 2016-03-29 22:20:14 UTC 
I was able to reproduce this bug using devstack, so I created an upstream bug here:

    https://bugs.launchpad.net/nova/+bug/1563547

I have also proposed a small patch upstream to Nova master (Newton/OSP10).

    https://review.openstack.org/#/c/298997/

If that merges, I will also propose an upstream backport patch for Nova Mitaka/OSP9 (and perhaps Liberty/OSP8 if it isn't too late).

This fix will likely not be backported to OSP7 (and perhaps not OSP8) since the root cause is really the failing cinder connection which should be troubleshooted in a different ticket.

In the mean time, you can reset the instance status back to ACTIVE from ERROR using 'nova reset-state'. For example:

    http://paste.openstack.org/show/492368/
Comment 5 Stephen Gordon 2016-03-31 19:06:35 UTC 
A version of the original bug description follows to assist with collaborating on a resolution in the upstream community, potentially customer sensitive values have been replaced with <placeholder>.

Description of problem:
Nova deletes an instance, but doesn't update the database

Version-Release number of selected component (if applicable):
RHEL OSP 6 

How reproducible:
Most of the time for Cu. 

Steps to Reproduce:
1) Boot an instance and attach a volume to it.
2) Delete the instance using "nova delete" command.
3) Instance is deleted from host it's not showing in output "virsh list --all".
4) Vol. stuck in detaching state.
5) Instance is still present in DB and "nova list" output.
6) The instance cannot be deleted via a nova command, since it will attempt to detach the volume from the non-existent instance and fail.

Actual results:
Instance is not get deleted.

Expected results:
It should get deleted.

Additional info:

- cinder vol is coming EMC VNX storage. Multipath is used to talk to the VNX.

- From compute node nova log file [sosreport-<placeholder>.localdomain-20160315195803] : 

~~~
grep 'd0670b16-1bf9-49b9-ae26-194dfa425147' var/log/nova/nova-compute.log | grep -i error
2016-03-15 15:04:24.249 49083 ERROR nova.compute.manager [req-8aa90f3b-6695-4ab1-bcec-fa0ccc9482dc 6a0ec1d4df0c47169e231da823ed058b cab71e273d404e2d8409957545edd2ca - - -] [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] Setting instance vm_state to ERROR
2016-03-15 19:47:15.913 49083 ERROR nova.compute.manager [req-e70622b4-0a7b-4f06-98a5-641b0c4ee8c8 6a0ec1d4df0c47169e231da823ed058b cab71e273d404e2d8409957545edd2ca - - -] [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] Setting instance vm_state to ERROR
2016-03-15 20:01:07.937 49083 ERROR nova.compute.manager [req-8a1de3cd-360f-4cae-8d5b-35131e3fc761 6a0ec1d4df0c47169e231da823ed058b cab71e273d404e2d8409957545edd2ca - - -] [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] Setting instance vm_state to ERROR
~~~

- Call trace showing the error : 

~~~
awk '/2016-03-15 15:04:18.963 49083/,/2016-03-15 15:04:24.447 49083/ {print $0}'  var/log/nova/nova-compute.log
2016-03-15 15:04:18.963 49083 DEBUG nova.openstack.common.periodic_task [req-f60489b5-9a10-4acf-97da-ee1799bf3e46 - - - - -] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:219
2016-03-15 15:04:18.963 49083 DEBUG nova.openstack.common.loopingcall [req-f60489b5-9a10-4acf-97da-ee1799bf3e46 - - - - -] Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x4bf2b90>> sleeping for 6.22 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132
2016-03-15 15:04:24.249 49083 ERROR nova.compute.manager [req-8aa90f3b-6695-4ab1-bcec-fa0ccc9482dc 6a0ec1d4df0c47169e231da823ed058b cab71e273d404e2d8409957545edd2ca - - -] [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] Setting instance vm_state to ERROR
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] Traceback (most recent call last):
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2772, in do_terminate_instance
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     self._delete_instance(context, instance, bdms, quotas)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     rv = f(*args, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2741, in _delete_instance
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     quotas.rollback()
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 85, in __exit__
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     six.reraise(self.type_, self.value, self.tb)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2711, in _delete_instance
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     self._shutdown_instance(context, instance, bdms)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2647, in _shutdown_instance
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     connector)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 214, in wrapper
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     res = method(self, ctx, volume_id, *args, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 369, in terminate_connection
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     connector)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 448, in terminate_connection
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     {'connector': connector})
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 375, in _action
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     return self.api.client.post(url, body=body)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 118, in post
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     return self._cs_request(url, 'POST', **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 112, in _cs_request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     return self.request(url, method, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 103, in request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 206, in request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 95, in request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     return self.session.request(url, method, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     return func(*args, **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 382, in request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     resp = send(**kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 439, in _send_request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 439, in _send_request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 439, in _send_request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     **kwargs)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 426, in _send_request
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147]     raise exceptions.ConnectionRefused(msg)
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] ConnectionRefused: Unable to establish connection to http://192.168.88.10:8776/v2/cab71e273d404e2d8409957545edd2ca/volumes/e2257e46-28df-4537-948c-98ae45a12940/action
2016-03-15 15:04:24.249 49083 TRACE nova.compute.manager [instance: d0670b16-1bf9-49b9-ae26-194dfa425147] 
2016-03-15 15:04:24.447 49083 DEBUG oslo_concurrency.lockutils [req-8aa90f3b-6695-4ab1-bcec-fa0ccc9482dc 6a0ec1d4df0c47169e231da823ed058b cab71e273d404e2d8409957545edd2ca - - -] Lock "compute_resources" acquired by "update_usage" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:444
~~~

- Above call trace is showing that IP http://192.168.88.10:8776/ is not accessible but Cu confirmed that curl was able to connect at the time of issue.


[heat-admin@<placeholder> ~]$ curl http://192.168.88.10:8776
{"versions": [{"status": "SUPPORTED", "updated": "2014-06-28T12:20:21Z",
"id": "v1.0", "links": [{"href": "http://192.168.88.10:8776/v1/", "rel":
"self"}]}, {"status": "CURRENT", "updated": "2012-11-21T11:33:21Z", "id":
"v2.0", "links": [{"href": "http://192.168.88.10:8776/v2/", "rel":
"self"}]}]}

- DB output while reproducing the issue with other instance.

[stack@sl<placeholder>ospd ~]$ nova list --all | grep slsg2
| 36d323a1-4d57-4e7f-939c-b7edf3ab74ce | slsg2-s00c01h0             |
00c4d7d296c140069190c53df54aa413 | ACTIVE  | deleting   | Running     |

[stack@sl<placeholder>ospd ~]$ cinder list --all | grep c01h0
| 34e3cb7e-bda5-4d92-98ea-cb4ec0cf4ce4 | 00c4d7d296c140069190c53df54aa413 |
detaching |               slsg2-s00c01h0VOL                |  68  |      -
     |  false   | 36d323a1-4d57-4e7f-9|

[heat-admin@sl<placeholder>ctl0 ~]$ echo "select * from volumes where
id='34e3cb7e-bda5-4d92-98ea-cb4ec0cf4ce4'\G" | sudo mysql cinder
*************************** 1. row ***************************
                 created_at: 2016-03-02 04:31:29
                 updated_at: 2016-03-15 21:23:15
                 deleted_at: NULL
                    deleted: 0
                         id: 34e3cb7e-bda5-4d92-98ea-cb4ec0cf4ce4
                     ec2_id: NULL
                    user_id: 5785cff2b204457b87ff97ed5b65182b
                 project_id: 00c4d7d296c140069190c53df54aa413
                       host: sl<placeholder>ctl0.localdomain@cinder_vnx#Pool1-iSCSI
                       size: 68
          availability_zone: nova
                     status: detaching
              attach_status: attached
               scheduled_at: 2016-03-02 04:31:29
                launched_at: 2016-03-02 04:31:46
              terminated_at: NULL
               display_name: slsg2-s00c01h0VOL
        display_description: Used for VM /storage partition.
          provider_location:
version^05.04.02|type^lun|system^APM00144418842|id^80
              provider_auth: NULL
                snapshot_id: NULL
             volume_type_id: NULL
               source_volid: NULL
                   bootable: 0
          provider_geometry: NULL
                   _name_id: NULL
          encryption_key_id: NULL
           migration_status: NULL
         replication_status: disabled
replication_extended_status: NULL
    replication_driver_data: NULL
        consistencygroup_id: NULL
                provider_id: NULL
                multiattach: 0

[heat-admin@sl<placeholder>ctl0 ~]$ echo "select * from instances where
uuid='36d323a1-4d57-4e7f-939c-b7edf3ab74ce'\G" | sudo mysql nova
*************************** 1. row ***************************
              created_at: 2016-03-02 04:33:48
              updated_at: 2016-03-16 13:41:55
              deleted_at: NULL
                      id: 1643
             internal_id: NULL
                 user_id: 5785cff2b204457b87ff97ed5b65182b
              project_id: 00c4d7d296c140069190c53df54aa413
               image_ref: 20f689ec-471c-4d0e-8e25-3b13211f89b9
               kernel_id:
              ramdisk_id:
            launch_index: 0
                key_name: NULL
                key_data: NULL
             power_state: 0
                vm_state: error
               memory_mb: 8192
                   vcpus: 2
                hostname: slsg2-s00c01h0
                    host: <placeholder>.localdomain
               user_data:
<placeholder>
          reservation_id: r-jaebuhz5
            scheduled_at: NULL
             launched_at: 2016-03-02 04:34:38
           terminated_at: NULL
            display_name: slsg2-s00c01h0
     display_description: slsg2-s00c01h0
       availability_zone: sl<placeholder>-mtc-zone1
                  locked: 0
                 os_type: NULL
             launched_on: <placeholder>.localdomain
        instance_type_id: 143
                 vm_mode: NULL
                    uuid: 36d323a1-4d57-4e7f-939c-b7edf3ab74ce
            architecture: NULL
        root_device_name: /dev/vda
            access_ip_v4: NULL
            access_ip_v6: NULL
            config_drive: True
              task_state: NULL
default_ephemeral_device: /dev/vdb
     default_swap_device: /dev/vdc
                progress: 0
        auto_disk_config: 0
      shutdown_terminate: 0
       disable_terminate: 0
                 root_gb: 21
            ephemeral_gb: 21
               cell_name: NULL
                    node: <placeholder>.localdomain
                 deleted: 0
               locked_by: NULL
                 cleaned: 1
      ephemeral_key_uuid: NULL


[root@<placeholder> ~]# virsh list --all
 Id    Name                           State
----------------------------------------------------
Comment 8 Diana Clarke 2016-05-13 13:38:23 UTC 
*** Bug 1293235 has been marked as a duplicate of this bug. ***
Comment 9 Diana Clarke 2016-05-13 13:55:57 UTC 
*** Bug 1260426 has been marked as a duplicate of this bug. ***
Comment 13 errata-xmlrpc 2016-06-01 12:26:52 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2016:1198