Traceback is logged when delete an instance.

[Danny Choi]

OpenStack version: Icehouse

Issue: traceback is logged in nova-compute.log when delete an instance.

Setup: 3 nodes, namely Controller, Compute and Network; with nova-compute running solely on Compute node.

Steps to reproduce:
1. Create an instance using image cirrus 0.3.2.
2. Verify instance is running: nova list
3. Delete the instance: nova delete <name>
4. Check nova-compute.log at Compute node.

root@Controller:/home/guest# nova --version
2.17.0
root@Controller:/home/guest# nova service-list
+------------------+------------+----------+---------+-------+----------------------------+-----------------+
| Binary | Host | Zone | Status | State | Updated_at | Disabled Reason |
+------------------+------------+----------+---------+-------+----------------------------+-----------------+
| nova-cert | Controller | internal | enabled | up | 2014-09-10T17:12:34.000000 | - |
| nova-conductor | Controller | internal | enabled | up | 2014-09-10T17:12:26.000000 | - |
| nova-consoleauth | Controller | internal | enabled | up | 2014-09-10T17:12:28.000000 | - |
| nova-scheduler | Controller | internal | enabled | up | 2014-09-10T17:12:31.000000 | - |
| nova-compute | Compute | nova | enabled | up | 2014-09-10T17:12:34.000000 | - |
+------------------+------------+----------+---------+-------+----------------------------+-----------------+
root@Controller:/home/guest# nova boot --image cirros-0.3.2-x86_64 --flavor 1 --nic net-id=75375f9b-0f26-4e1a-aedc-24457192f265 cirros
+--------------------------------------+------------------------------------------------------------+
| Property | Value |
+--------------------------------------+------------------------------------------------------------+
| OS-DCF:diskConfig | MANUAL |
| OS-EXT-AZ:availability_zone | nova |
| OS-EXT-SRV-ATTR:host | - |
| OS-EXT-SRV-ATTR:hypervisor_hostname | - |
| OS-EXT-SRV-ATTR:instance_name | instance-00000046 |
| OS-EXT-STS:power_state | 0 |
| OS-EXT-STS:task_state | scheduling |
| OS-EXT-STS:vm_state | building |
| OS-SRV-USG:launched_at | - |
| OS-SRV-USG:terminated_at | - |
| accessIPv4 | |
| accessIPv6 | |
| adminPass | jFmNDB5Jsd77 |
| config_drive | |
| created | 2014-09-10T17:13:06Z |
| flavor | m1.tiny (1) |
| hostId | |
| id | bc01c570-c40f-4088-a17c-0278fc6c3315 |
| image | cirros-0.3.2-x86_64 (38f00c62-f9df-4133-abf2-7c9ba948d414) |
| key_name | - |
| metadata | {} |
| name | cirros |
| os-extended-volumes:volumes_attached | [] |
| progress | 0 |
| security_groups | default |
| status | BUILD |
| tenant_id | 73a095bf078443c9b340d871deaabcc3 |
| updated | 2014-09-10T17:13:06Z |
| user_id | 77bdd3f911744f72af7038d40d722439 |
+--------------------------------------+------------------------------------------------------------+
root@Controller:/home/guest# nova list
+--------------------------------------+--------+--------+------------+-------------+---------------------+
| ID | Name | Status | Task State | Power State | Networks |
+--------------------------------------+--------+--------+------------+-------------+---------------------+
| bc01c570-c40f-4088-a17c-0278fc6c3315 | cirros | ACTIVE | - | Running | int-net=172.16.1.48 |
+--------------------------------------+--------+--------+------------+-------------+---------------------+
root@Controller:/home/guest# nova delete cirros
root@Controller:/home/guest# nova list
+----+------+--------+------------+-------------+----------+
| ID | Name | Status | Task State | Power State | Networks |
+----+------+--------+------------+-------------+----------+
+----+------+--------+------------+-------------+----------+
root@Controller:/home/guest#

Snippet of nova-compute.log:

2014-09-10 13:13:06.521 1893 AUDIT nova.compute.manager [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Starting instance...
2014-09-10 13:13:06.607 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Attempting claim: memory 512 MB, disk 1 GB, VCPUs 1
2014-09-10 13:13:06.610 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Total memory: 7985 MB, used: 512.00 MB
2014-09-10 13:13:06.611 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] memory limit: 11977.50 MB, free: 11465.50 MB
2014-09-10 13:13:06.611 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Total disk: 9 GB, used: 0.00 GB
2014-09-10 13:13:06.612 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] disk limit not specified, defaulting to unlimited
2014-09-10 13:13:06.612 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Total CPUs: 1 VCPUs, used: 0.00 VCPUs
2014-09-10 13:13:06.612 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] CPUs limit not specified, defaulting to unlimited
2014-09-10 13:13:06.613 1893 AUDIT nova.compute.claims [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Claim successful
2014-09-10 13:13:07.044 1893 INFO nova.virt.libvirt.driver [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Creating image
2014-09-10 13:13:07.256 1893 WARNING nova.virt.disk.vfs.guestfs [req-4de48240-de8f-4fce-ab6c-28e3b9541131 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] Failed to close augeas aug_close: call launch before using this function
(in guestfish, don't forget to use the 'run' command)
2014-09-10 13:13:09.306 1893 INFO nova.compute.manager [-] Lifecycle event 0 on VM bc01c570-c40f-4088-a17c-0278fc6c3315
2014-09-10 13:13:09.327 1893 INFO nova.virt.libvirt.driver [-] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Instance spawned successfully.
2014-09-10 13:13:09.441 1893 INFO nova.compute.manager [-] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] During sync_power_state the instance has a pending task (spawning). Skip.
2014-09-10 13:13:23.031 1893 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2014-09-10 13:13:23.202 1893 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6961
2014-09-10 13:13:23.203 1893 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 8
2014-09-10 13:13:23.204 1893 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 0
2014-09-10 13:13:23.222 1893 INFO nova.compute.resource_tracker [-] Compute_service record updated for Compute:compute
2014-09-10 13:13:44.709 1893 AUDIT nova.compute.manager [req-6c9a4f5f-d9e7-4e12-b5c2-8ee7716fe97a 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Terminating instance
2014-09-10 13:13:45.269 1893 INFO nova.compute.manager [-] Lifecycle event 1 on VM bc01c570-c40f-4088-a17c-0278fc6c3315
2014-09-10 13:13:45.276 1893 INFO nova.virt.libvirt.driver [-] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Instance destroyed successfully.
2014-09-10 13:13:45.391 1893 ERROR nova.virt.driver [-] Exception dispatching event <nova.virt.event.LifecycleEvent object at 0x7fc7e4178490>: Info cache for instance bc01c570-c40f-4088-a17c-0278fc6c3315 could not be found.
Traceback (most recent call last):

  File "/usr/lib/python2.7/dist-packages/nova/conductor/manager.py", line 597, in _object_dispatch
    return getattr(target, method)(context, *args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/objects/base.py", line 151, in wrapper
    return fn(self, ctxt, *args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/objects/instance.py", line 500, in refresh
    self.info_cache.refresh()

  File "/usr/lib/python2.7/dist-packages/nova/objects/base.py", line 151, in wrapper
    return fn(self, ctxt, *args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/objects/instance_info_cache.py", line 103, in refresh
    self.instance_uuid)

  File "/usr/lib/python2.7/dist-packages/nova/objects/base.py", line 112, in wrapper
    result = fn(cls, context, *args, **kwargs)

  File "/usr/lib/python2.7/dist-packages/nova/objects/instance_info_cache.py", line 70, in get_by_instance_uuid
    instance_uuid=instance_uuid)

InstanceInfoCacheNotFound: Info cache for instance bc01c570-c40f-4088-a17c-0278fc6c3315 could not be found.

2014-09-10 13:13:45.946 1893 INFO nova.virt.libvirt.driver [req-6c9a4f5f-d9e7-4e12-b5c2-8ee7716fe97a 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Deleting instance files /var/lib/nova/instances/bc01c570-c40f-4088-a17c-0278fc6c3315
2014-09-10 13:13:45.947 1893 INFO nova.virt.libvirt.driver [req-6c9a4f5f-d9e7-4e12-b5c2-8ee7716fe97a 77bdd3f911744f72af7038d40d722439 73a095bf078443c9b340d871deaabcc3] [instance: bc01c570-c40f-4088-a17c-0278fc6c3315] Deletion of /var/lib/nova/instances/bc01c570-c40f-4088-a17c-0278fc6c3315 complete

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit 43c8cff8252ff38eb2fca88c44193049afb711ee
Author: Hans Lindgren <email address hidden>
Date: Thu Sep 11 14:23:49 2014 +0200

    Only load necessary instance info for use in sync power state

    During sync power state, instance is refreshed from the db. If the
    instance gets deleted, this can result in InstanceInfoCacheNotFound
    being thrown due to info_cache being loaded and therefore refreshed.

    Sync power state does not make use of any extra instance attrs, so
    this problem can be avoided by not loading any extra attrs in the
    first place.

    Two callers of _sync_instance_power_state() are updated to not load
    extra attrs. 1) The periodic sync and 2) the lifecycle event handler.

    Change-Id: I150bd95da65263981608dd9a033232bd142e737f
    Closes-Bug: #1367845