"nova list --delete" failed due to InstanceNotFound exception

[WeiguoFan]

Description
===========
When I run "nova list --delete" on our OpenStack environment(Mitaka(RHOSP9)), it failed due to the following error.
------------
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.InstanceNotFound'> (HTTP 500) (Request-ID: req-f2ee67f2-2d81-4e6f-b707-d9a713383191)
------------

   Note: I reproduced it on our Newton(RHOSP10) environment too.

And the following messages was outputted from nova-api.log.
-----------------------------
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions [req-f2ee67f2-2d81-4e6f-b707-d9a713383191 48c0c48c3a284a909b5dd6aa20073ffa ebb9a4f3d9d845bdb984c18c1d8fae05 - - -] Unexpected exception in API method
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 478, in wrapped
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 294, in detail
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions servers = self._get_servers(req, is_detail=True)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 421, in _get_servers
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions response = self._view_builder.detail(req, instance_list)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/views/servers.py", line 150, in detail
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return self._list_view(self.show, request, instances, coll_name)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/views/servers.py", line 162, in _list_view
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions server_list = [func(request, server)["server"] for server in servers]
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/views/servers.py", line 290, in show
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions "flavor": self._get_flavor(request, instance),
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/views/servers.py", line 222, in _get_flavor
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions instance_type = instance.get_flavor()
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 932, in get_flavor
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return getattr(self, attr)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 67, in getter
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions self.obj_load_attr(name)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 917, in obj_load_attr
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions self._load_flavor()
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 793, in _load_flavor
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions expected_attrs=['flavor', 'system_metadata'])
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 181, in wrapper
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions result = fn(cls, context, *args, **kwargs)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 399, in get_by_uuid
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions use_slave=use_slave)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 285, in wrapper
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 391, in _db_instance_get_by_uuid
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions columns_to_join=columns_to_join)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 696, in instance_get_by_uuid
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return IMPL.instance_get_by_uuid(context, uuid, columns_to_join)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 229, in wrapper
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 330, in wrapped
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions return f(context, *args, **kwargs)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 1970, in instance_get_by_uuid
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions columns_to_join=columns_to_join)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 1979, in _instance_get_by_uuid
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions raise exception.InstanceNotFound(instance_id=uuid)
2016-11-25 11:22:25.660 21809 ERROR nova.api.openstack.extensions InstanceNotFound: Instance decfb2f4-d8a6-49dd-89f0-3aa2fdeb8b6e could not be found.
-----------------------------

I noticed that when this problem happened, there were 2 records about the
instance(decfb2f4-d8a6-49dd-89f0-3aa2fdeb8b6) that caused the error in
instance_extra table of nova DB. And one of their flavor is NULL.

--------
# mysql -u root nova -e "select * from instance_extra where instance_uuid='decfb2f4-d8a6-49dd-89f0-3aa2fdeb8b6e'\G"
*************************** 1. row ***************************
        created_at: 2016-11-16 07:25:09
        updated_at: 2016-11-16 07:27:24
        deleted_at: 2016-11-16 07:27:26
           deleted: 5837
                id: 5837
     instance_uuid: decfb2f4-d8a6-49dd-89f0-3aa2fdeb8b6e
     numa_topology: NULL
      pci_requests: []
            flavor: {"new": null, "old": null, "cur": {"nova_object.version": "1.1", ....
            .....
*************************** 2. row ***************************
        created_at: 2016-11-16 07:27:26
        updated_at: NULL
        deleted_at: NULL
           deleted: 0
                id: 5838
     instance_uuid: decfb2f4-d8a6-49dd-89f0-3aa2fdeb8b6e
     numa_topology: NULL
      pci_requests: []
            flavor: NULL
            .....
--------

According to my investigating, in the current instance_extra_update_by_uuid(),
when updating an instance, if there is no entry for an instance, nova create
a new entry for it. For somehow, if updating comes after the instance has been deleted
(its entry would be soft-deleted), nova would create a new entry for
the deleted instance and keep its flavor being NULL. It causes instance_extra
entry duplicate for the same instance_uuid. I think it cause this problem.

Steps to reproduce
==================
I can reproduce the problem with the following steps.

   Note: please notice it's timing problem. It doesn't alway heppen.
         But once it happened, it can be reproduced always.
         Unless you delete the duplicate entry from instance_extra table.

1, Boot an instance. Meanwhile stop rabbitmq-server.
2, Restart rabbitmq-server.
3, Delete the instance.
4, Run "nova list --delete".

For those deleted instance, I think we shouldn't
create a new entry for it. It's better to just skip the "updating".

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/412771

[Sean Dague (sdague)]

Automatically discovered version mitaka in description. If this is incorrect, please update the description to include 'nova version: ...'

[Vishakha Agarwal (vishakha.agarwal)]

Hi,

Is there anyone working on it??

Thanks

[Vishakha Agarwal (vishakha.agarwal)]

Hi,

Tried to reproduce the same from the steps mentioned above in nova version: Rocky. But It is working fine.

Thanks.