Missing InstanceInfoCache entry prevents delete

[Rick Harris]

If you're trying to delete an instance which is out-of-sync such that it's missing a InstanceInfoCache entry, you'll will receive a traceback: http://paste.openstack.org/show/60685/

Delete in this case should be allowed so that you can cleanup these 'broken' instances.

The solution is to catch the InstanceInfoCacheNotFound exception (like we do with other NotFound exceptions around this code), and continue on.

[OpenStack Infra (hudson-openstack)]

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

[jichenjc (jichenjc)]

I got similar but different logs, is your fix able to fix this exception?

2014-01-18 03:41:03.919 15091 INFO nova.compute.manager [-] [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] NV-E7B9660 Destroying instance with name label 'xw00020' which is marked as DELETED but still present on host.
2014-01-18 03:41:03.919 15091 AUDIT nova.compute.manager [req-aef06534-ada2-4751-833f-fc99715e331e None None] [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] NV-067140C Terminating instance
2014-01-18 03:41:04.126 15091 ERROR nova.network.api [-] [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] Failed storing info cache
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] Traceback (most recent call last):
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/network/api.py", line 83, in update_instance_cache_with_nw_info
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] ic.save(update_cells=update_cells)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/objects/base.py", line 143, in wrapper
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] ctxt, self, fn.__name__, args, kwargs)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/conductor/rpcapi.py", line 474, in object_action
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] objmethod=objmethod, args=args, kwargs=kwargs)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/rpcclient.py", line 85, in call
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] return self._invoke(self.proxy.call, ctxt, method, **kwargs)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/rpcclient.py", line 63, in _invoke
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] return cast_or_call(ctxt, msg, **self.kwargs)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/proxy.py", line 126, in call
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] result = rpc.call(context, real_topic, msg, timeout)
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/__init__.py", line 139, in call
2014-01-18 03:41:04.126 15091 TRACE nova.network.api [instance: 6b223492-b954-4d17-9481-bfcc6208e4f6] return _get_impl().call(CONF, context, topic, msg, timeout)
2014...

[Matt Riedemann (mriedem)]

Hitting it here too:

http://logs.openstack.org/67/67767/2/check/check-tempest-dsvm-postgres-full/9a75aa3/logs/screen-n-cpu.txt.gz?level=TRACE

[Matt Riedemann (mriedem)]

Nearly 744K hits on this query in the last 7 days:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRXhjZXB0aW9uIGRpc3BhdGNoaW5nIGV2ZW50XCIgQU5EIG1lc3NhZ2U6XCJJbmZvIGNhY2hlIGZvciBpbnN0YW5jZVwiIEFORCBtZXNzYWdlOlwiY291bGQgbm90IGJlIGZvdW5kXCIgQU5EIGZpbGVuYW1lOlwibG9ncy9zY3JlZW4tbi1jcHUudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTAyMjk1OTMzMzR9

Note that there is a 10% success rate when that shows up also.

[Matt Riedemann (mriedem)]

Making this high importance since it makes debugging the n-cpu log hard when something else fails.

[Matt Riedemann (mriedem)]

Not sure if this is related: https://review.openstack.org/66371

From logstash it looks like this has been showing since before that patch has been around (at least 1/8) so might not be it.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/65374
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=6438d2587e1b93c73b8461b0e7dbd7bcd5243aea
Submitter: Jenkins
Branch: master

commit 6438d2587e1b93c73b8461b0e7dbd7bcd5243aea
Author: Rick Harris <email address hidden>
Date: Tue Jan 7 15:29:03 2014 -0600

    Allow delete when InstanceInfoCache entry is missing

    The existing code wouldn't allow you to delete 'broken' instances that were
    (for whatever reason) missing their InstanceInfoCache entry. This patch fixes
    it such that those instances can be deleted.

    Adds a test case to cover the new exception handling.

    Closes-Bug: #1266919

    Co-Authored-By: Matt Riedemann <email address hidden>
    Change-Id: I3d566a25e340b5d5de86740141e1eaa5b3742915