yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1520396] Re: Nova compute automatically down when I delete an instance as admin

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Fan Yang <1520396@xxxxxxxxxxxxxxxxxx>
Date: Mon, 12 Sep 2016 05:10:16 -0000
Reply-to: Bug 1520396 <1520396@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: nova
       Status: Expired => Incomplete

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1520396

Title:
  Nova compute automatically down when I delete an instance as admin

Status in OpenStack Compute (nova):
  Incomplete

Bug description:
  When I use to terminate an instance as admin user. The compute node of
  where the VMs/Instance is located will turn to 'down' state.

  I am using the following:
  CentOS Linux release 7.1.1503 (Core)

  openstack-nova-compute-2015.1.0-3.el7.noarch
  libvirt-client-1.2.8-16.el7_1.3.x86_64
  openstack-neutron-openvswitch-2015.1.0-1.el7.noarch
  ceph-0.94.2-0.el7.x86_64

  I don't know if it also related to ceph, as it still on the
  replicating at the moments when done those steps. I tried more than 5
  same results.

  But the remedy is restart both nova and neutron, but you keeps on monitoring once you deleted. Sill monitoring up no next week if still occur.
  > service neutron-openvswitch-agent restart
  > service openstack-nova-compute restart

  Logs:

  InstanceInfoCacheNotFound: Info cache for instance
  e3575681-1ea7-45f4-97b4-cf00cfc0fa00 could not be found.

  2015-11-27 14:49:44.593 19796 INFO nova.compute.manager [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Destroying instance with name label 'instance-000000c1' which is marked as DELETED but still present on host.
  2015-11-27 14:49:44.605 19796 INFO nova.compute.manager [req-e24f56f0-a0c4-44d2-b7f8-865e753c3bbc - - - - -] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Terminating instance
  2015-11-27 14:49:44.660 19796 INFO nova.virt.libvirt.driver [-] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Instance destroyed successfully.
  [root@Compute16 nova]# tail nova-compute.log -n 100
  2015-11-27 14:42:32.680 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:42:32.681 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:42:32.703 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:42:32.703 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:43:31.705 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Auditing locally available compute resources for node Compute16
  2015-11-27 14:43:32.346 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:43:32.347 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:43:32.364 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:43:32.365 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:44:31.706 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Auditing locally available compute resources for node Compute16
  2015-11-27 14:44:32.363 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:44:32.363 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:44:32.381 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:44:32.382 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:45:32.705 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Auditing locally available compute resources for node Compute16
  2015-11-27 14:45:33.424 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:45:33.424 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:45:33.443 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:45:33.443 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:46:33.705 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Auditing locally available compute resources for node Compute16
  2015-11-27 14:46:34.384 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:46:34.384 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:46:34.414 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:46:34.414 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:47:34.705 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Auditing locally available compute resources for node Compute16
  2015-11-27 14:47:35.346 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Total usable vcpus: 8, total allocated vcpus: 23
  2015-11-27 14:47:35.347 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Final resource view: name=Compute16 phys_ram=23939MB used_ram=26112MB phys_disk=16760GB used_disk=474GB total_vcpus=8 used_vcpus=23 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x48775d0>
  2015-11-27 14:47:35.364 19796 INFO nova.scheduler.client.report [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for ('Compute16', 'Compute16')
  2015-11-27 14:47:35.364 19796 INFO nova.compute.resource_tracker [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] Compute_service record updated for Compute16:Compute16
  2015-11-27 14:48:10.746 19796 INFO nova.compute.manager [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Destroying instance with name label 'instance-000000c9' which is marked as DELETED but still present on host.
  2015-11-27 14:48:10.758 19796 INFO nova.compute.manager [req-e24f56f0-a0c4-44d2-b7f8-865e753c3bbc - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Terminating instance
  2015-11-27 14:48:10.809 19796 INFO nova.virt.libvirt.driver [-] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Instance destroyed successfully.
  2015-11-27 14:49:44.311 19796 INFO nova.virt.libvirt.driver [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Deletion of /var/lib/nova/instances/e3575681-1ea7-45f4-97b4-cf00cfc0fa00_del complete
  2015-11-27 14:49:44.510 19796 ERROR nova.network.base_api [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Failed storing info cache
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Traceback (most recent call last):
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 49, in update_instance_cache_with_nw_info
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     ic.save(update_cells=update_cells)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 192, in wrapper
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     self._context, self, fn.__name__, args, kwargs)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/conductor/rpcapi.py", line 340, in object_action
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     objmethod=objmethod, args=args, kwargs=kwargs)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 156, in call
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     retry=self.retry)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     timeout=timeout, retry=retry)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 350, in send
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     retry=retry)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 341, in _send
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     raise result
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] InstanceInfoCacheNotFound_Remote: Info cache for instance e3575681-1ea7-45f4-97b4-cf00cfc0fa00 could not be found.
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Traceback (most recent call last):
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 422, in _object_dispatch
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     return getattr(target, method)(*args, **kwargs)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 208, in wrapper
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     return fn(self, *args, **kwargs)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 95, in save
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     {'network_info': nw_info_json})
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 888, in instance_info_cache_update
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     return IMPL.instance_info_cache_update(context, instance_uuid, values)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 233, in wrapper
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     return f(*args, **kwargs)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2624, in instance_info_cache_update
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]     instance_uuid=instance_uuid)
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] InstanceInfoCacheNotFound: Info cache for instance e3575681-1ea7-45f4-97b4-cf00cfc0fa00 could not be found.
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.510 19796 TRACE nova.network.base_api [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00]
  2015-11-27 14:49:44.513 19796 ERROR nova.compute.manager [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Failed to deallocate network for instance.
  2015-11-27 14:49:44.593 19796 WARNING nova.compute.manager [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: e3575681-1ea7-45f4-97b4-cf00cfc0fa00] Periodic cleanup failed to delete instance: Info cache for instance e3575681-1ea7-45f4-97b4-cf00cfc0fa00 could not be found.
  Traceback (most recent call last):

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

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

    File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 95, in save
      {'network_info': nw_info_json})

    File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 888, in instance_info_cache_update
      return IMPL.instance_info_cache_update(context, instance_uuid, values)

    File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 233, in wrapper
      return f(*args, **kwargs)

    File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2624, in instance_info_cache_update
      instance_uuid=instance_uuid)

  InstanceInfoCacheNotFound: Info cache for instance
  e3575681-1ea7-45f4-97b4-cf00cfc0fa00 could not be found.

  2015-11-27 14:49:44.593 19796 INFO nova.compute.manager [req-bc5bab4c-bcf6-407b-8f6e-5ecfb89e3609 - - - - -] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Destroying instance with name label 'instance-000000c1' which is marked as DELETED but still present on host.
  2015-11-27 14:49:44.605 19796 INFO nova.compute.manager [req-e24f56f0-a0c4-44d2-b7f8-865e753c3bbc - - - - -] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Terminating instance
  2015-11-27 14:49:44.660 19796 INFO nova.virt.libvirt.driver [-] [instance: 28c73c43-d3a0-4640-9e8a-ce6a09fd0cd4] Instance destroyed successfully.

  Other logs
     Compute06 nova]# tail nova-compute.log
  2015-11-27 14:54:33.197 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:54:33.198 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:55:30.327 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:55:34.095 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:55:34.095 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:55:34.114 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:55:34.114 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:55:57.358 4927 INFO nova.compute.manager [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Destroying instance with name label 'instance-00000103' which is marked as DELETED but still present on host.
  2015-11-27 14:55:57.370 4927 INFO nova.compute.manager [req-edeebef0-82ba-4647-90ef-12ecbbfb88da - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Terminating instance
  2015-11-27 14:55:57.419 4927 INFO nova.virt.libvirt.driver [-] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Instance destroyed successfully.
  [root@Compute06 nova]# tail nova-compute.log -n 100
  2015-11-27 14:49:25.118 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:50:23.327 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:50:27.076 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:50:27.077 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:50:27.095 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:50:27.096 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:51:24.524 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:51:28.313 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:51:28.314 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:51:28.334 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:51:28.334 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:52:26.429 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:52:30.207 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:52:30.207 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:52:30.224 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:52:30.225 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:53:28.476 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:53:32.188 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:53:32.188 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:53:32.206 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:53:32.206 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:54:29.476 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:54:33.178 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:54:33.178 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:54:33.197 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:54:33.198 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:55:30.327 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Auditing locally available compute resources for node Compute06
  2015-11-27 14:55:34.095 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Total usable vcpus: 8, total allocated vcpus: 22
  2015-11-27 14:55:34.095 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Final resource view: name=Compute06 phys_ram=23939MB used_ram=29184MB phys_disk=16760GB used_disk=532GB total_vcpus=8 used_vcpus=22 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4b6fc90>
  2015-11-27 14:55:34.114 4927 INFO nova.scheduler.client.report [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for ('Compute06', 'Compute06')
  2015-11-27 14:55:34.114 4927 INFO nova.compute.resource_tracker [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] Compute_service record updated for Compute06:Compute06
  2015-11-27 14:55:57.358 4927 INFO nova.compute.manager [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Destroying instance with name label 'instance-00000103' which is marked as DELETED but still present on host.
  2015-11-27 14:55:57.370 4927 INFO nova.compute.manager [req-edeebef0-82ba-4647-90ef-12ecbbfb88da - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Terminating instance
  2015-11-27 14:55:57.419 4927 INFO nova.virt.libvirt.driver [-] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Instance destroyed successfully.
  2015-11-27 15:01:43.712 4927 INFO nova.virt.libvirt.driver [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Deletion of /var/lib/nova/instances/d26e6e47-68b0-4914-bbd8-6d3d2cc577b9_del complete
  2015-11-27 15:01:43.880 4927 ERROR nova.network.base_api [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Failed storing info cache
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Traceback (most recent call last):
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 49, in update_instance_cache_with_nw_info
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     ic.save(update_cells=update_cells)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 192, in wrapper
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     self._context, self, fn.__name__, args, kwargs)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/conductor/rpcapi.py", line 340, in object_action
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     objmethod=objmethod, args=args, kwargs=kwargs)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 156, in call
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     retry=self.retry)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     timeout=timeout, retry=retry)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 350, in send
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     retry=retry)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 341, in _send
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     raise result
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] InstanceInfoCacheNotFound_Remote: Info cache for instance d26e6e47-68b0-4914-bbd8-6d3d2cc577b9 could not be found.
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Traceback (most recent call last):
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 422, in _object_dispatch
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     return getattr(target, method)(*args, **kwargs)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 208, in wrapper
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     return fn(self, *args, **kwargs)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 95, in save
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     {'network_info': nw_info_json})
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 888, in instance_info_cache_update
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     return IMPL.instance_info_cache_update(context, instance_uuid, values)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 233, in wrapper
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     return f(*args, **kwargs)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]   File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2624, in instance_info_cache_update
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]     instance_uuid=instance_uuid)
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] InstanceInfoCacheNotFound: Info cache for instance d26e6e47-68b0-4914-bbd8-6d3d2cc577b9 could not be found.
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.880 4927 TRACE nova.network.base_api [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9]
  2015-11-27 15:01:43.943 4927 ERROR nova.compute.manager [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Failed to deallocate network for instance.
  2015-11-27 15:01:44.000 4927 WARNING nova.compute.manager [req-52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] [instance: d26e6e47-68b0-4914-bbd8-6d3d2cc577b9] Periodic cleanup failed to delete instance: Info cache for instance d26e6e47-68b0-4914-bbd8-6d3d2cc577b9 could not be found.
  Traceback (most recent call last):

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

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

    File "/usr/lib/python2.7/site-packages/nova/objects/instance_info_cache.py", line 95, in save
      {'network_info': nw_info_json})

    File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 888, in instance_info_cache_update
      return IMPL.instance_info_cache_update(context, instance_uuid, values)

    File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 233, in wrapper
      return f(*args, **kwargs)

    File "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2624, in instance_info_cache_update
      instance_uuid=instance_uuid)

  InstanceInfoCacheNotFound: Info cache for instance
  d26e6e47-68b0-4914-bbd8-6d3d2cc577b9 could not be found.

  2015-11-27 15:01:44.107 4927 WARNING nova.compute.manager [req-
  52e5a18d-9429-4cde-b2c4-5503a1d8abf5 - - - - -] While synchronizing
  instance power states, found 28 instances in the database and 29
  instances on the hypervisor.

   Other Log

   sed_vcpus=18 pci_stats=<nova.pci.stats.PciDeviceStats object at 0x4ba0d10>
  2015-11-27 15:13:20.584 17205 INFO nova.scheduler.client.report [req-95072099-fdd4-42c2-bd28-50813a0df37b - - - - -] Compute_service record updated for ('Compute05', u'Compute05')
  2015-11-27 15:13:20.584 17205 INFO nova.compute.resource_tracker [req-95072099-fdd4-42c2-bd28-50813a0df37b - - - - -] Compute_service record updated for Compute05:Compute05
  2015-11-27 15:14:02.876 17205 INFO nova.compute.manager [req-95072099-fdd4-42c2-bd28-50813a0df37b - - - - -] [instance: 714390bc-f342-42f9-a01a-15b63ab794d5] Destroying instance with name label 'instance-00000070' which is marked as DELETED but still present on host.
  2015-11-27 15:14:02.892 17205 INFO nova.compute.manager [req-944a9b01-e8dd-48fa-a7b6-29f946b78196 - - - - -] [instance: 714390bc-f342-42f9-a01a-15b63ab794d5] Terminating instance
  2015-11-27 15:14:02.959 17205 INFO nova.virt.libvirt.driver [-] [instance: 714390bc-f342-42f9-a01a-15b63ab794d5] Instance destroyed successfully.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1520396/+subscriptions
References

[Bug 1520396] [NEW] Nova compute automatically down when I delete an instance as admin
From: codbla, 2015-11-27