InstanceNotFound during instance usage audit

[Corey Wright]

tl;dr set read_deleted to "yes" on the admin context used by the periodic _instance_usage_audit() so info can be retrieved on deleted instances.

Explanation:

nova.compute.manager.Manager._instance_usage_audit() has a bug where, though get_active_by_window_joined() properly returned a list of instances including deleted ones (because it's implicit that read_deleted must be set to "yes" for that function to correctly operate), notify_usage_exists() indirectly uses the more generic get_flavor() (which cannot assume read_deleted should be "yes" to properly operate and therefor defaults to "no") to report on each instance without setting read_deleted to "yes". this was masked until commit 1337890a was merged which removed compatibility code that retrieved the flavor if InstanceNotFound was encountered and the instance was deleted.

Nova version: git HEAD since commit 1337890a

Log excerpt:

2016-01-14 00:01:51.112 18707 DEBUG nova.objects.instance [req-66e4a380-ed24-4ca1-a971-ee1d80878e2e - - - - -] Lazy-loading `flavor' on Instance uuid 85388355-6f83-4bca-9a11-a0914a2e3a3a obj_load_attr /opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/objects/instance.py:843
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [req-66e4a380-ed24-4ca1-a971-ee1d80878e2e - - - - -] [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] Failed to generate usage audit for instance on host c-10-13-135-245
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] Traceback (most recent call last):
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/compute/manager.py", line 6036, in _instance_usage_audit
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] include_bandwidth=True)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/compute/utils.py", line 297, in notify_usage_exists
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] system_metadata=system_metadata, extra_usage_info=extra_info)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/compute/utils.py", line 317, in notify_about_instance_usage
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] network_info, system_metadata, **extra_usage_info)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/notifications.py", line 386, in info_from_instance
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] instance_type = instance.get_flavor()
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/objects/instance.py", line 871, in get_flavor
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] return getattr(self, attr)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 67, in getter
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] self.obj_load_attr(name)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/objects/instance.py", line 861, in obj_load_attr
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] self._load_flavor()
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/objects/instance.py", line 754, in _load_flavor
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] expected_attrs=['flavor', 'system_metadata'])
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/oslo_versionedobjects/base.py", line 179, in wrapper
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] result = fn(cls, context, *args, **kwargs)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/objects/instance.py", line 373, in get_by_uuid
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] use_slave=use_slave)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/db/api.py", line 676, in instance_get_by_uuid
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] columns_to_join, use_slave=use_slave)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 219, in wrapper
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] return f(*args, **kwargs)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 1815, in instance_get_by_uuid
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] columns_to_join=columns_to_join, use_slave=use_slave)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] File "/opt/rackstack/rackstack.497.5/nova/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 1827, in _instance_get_by_uuid
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] raise exception.InstanceNotFound(instance_id=uuid)
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a] InstanceNotFound: Instance 85388355-6f83-4bca-9a11-a0914a2e3a3a could not be found.
2016-01-14 00:01:51.181 18707 ERROR nova.compute.manager [instance: 85388355-6f83-4bca-9a11-a0914a2e3a3a]

Reproduction steps:
1. enable instance usage audit
2. create instance
3. delete instance

Explanation:

[Corey Wright (coreywright)]

commit coming shortly to gerrit.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit c21786b922dee78c0711a224fbb7f5efd801967a
Author: Corey Wright <email address hidden>
Date: Mon Jan 18 23:52:55 2016 -0600

    Avoid lazy-loading flavor during usage audit

    Explicitly load flavor data when creating list of instances active
    during audit window so as to avoid lazy-loading it during usage audit
    notification generation and causing an InstanceNotFound exception on a
    deleted instance (because flavor is loaded using a database query that
    respects read_deleted and read_deleted is 'no').

    Change-Id: I1b237d1a8a68cd64f8a60f5d34fb1a6c3ab86e82
    Closes-Bug: 1540682

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/nova 13.0.0.0b3 development milestone.