[Bug 1418590] Re: No ERROR state if image deleted, _base is lost and instance is rescued

Tue Jul 14 15:01:47 UTC 2015

Solving an inconsistency: The bug is 'In Progress' but without an
assignee. I set the status back to the last known status before the
change to 'In Progress'.

Feel free to assign the bug to yourself. If you do so, please set it to
'In Progress'.

** Changed in: nova
       Status: In Progress => New

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to nova in Ubuntu.
https://bugs.launchpad.net/bugs/1418590

Title:
  No ERROR state if image deleted, _base is lost and instance is rescued

Status in OpenStack Compute (nova):
  New
Status in nova package in Ubuntu:
  New

Bug description:
  nova version: 1:2014.2.1-0ubuntu1~cloud0

  State to reproduce:
  1. Boot instance from image
  2. Delete image
  3. Stop nova-compute
  4. Remove /var/lib/nova/instances/_base/*
  5. start nova-compute
  6. Try to rescue instance (nova rescue image)

  Nova-compute will fail with few  traces (see below) and instance get
  strange state:

  nova show 290ab4b7-7225-4b74-853a-d342974a2080
  +--------------------------------------+----------------------------------------------------------+
  | Property                             | Value                                                    |
  +--------------------------------------+----------------------------------------------------------+
  | OS-DCF:diskConfig                    | AUTO                                                     |
  | OS-EXT-AZ:availability_zone          | nova                                                     |
  | OS-EXT-SRV-ATTR:host                 | pp3                                                      |
  | OS-EXT-SRV-ATTR:hypervisor_hostname  | pp3                                                      |
  | OS-EXT-SRV-ATTR:instance_name        | instance-000000f6                                        |
  | OS-EXT-STS:power_state               | 1                                                        |
  | OS-EXT-STS:task_state                | -                                                        |
  | OS-EXT-STS:vm_state                  | active                                                   |
  | OS-SRV-USG:launched_at               | 2015-02-05T14:15:30.000000                               |
  | OS-SRV-USG:terminated_at             | -                                                        |
  (skip)

  After that it is impossible to unrescue instance  (Cannot 'unrescue'
  while instance is in vm_state active) or hard-reset (nothing happens).

  Only nova reset-state helps.

  Expected behavior: set it to ERROR state or, better, to reject rescue
  if no image found.

  Traces:

  2015-02-05 15:59:41.973 7281 INFO nova.virt.libvirt.driver [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Instance failed to shutdown in 60 seconds.
  2015-02-05 15:59:42.363 7281 DEBUG nova.virt.driver [-] Emitting event <LifecycleEvent: 1423148382.36, 290ab4b7-7225-4b74-853a-d342974a2080 => Stopped> emit_event /usr/lib/python2.7/dist-packages/nova/virt/driver.py:1298
  2015-02-05 15:59:42.364 7281 INFO nova.compute.manager [-] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] VM Stopped (Lifecycle Event)
  2015-02-05 15:59:42.366 7281 INFO nova.virt.libvirt.driver [-] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Instance destroyed successfully.
  2015-02-05 15:59:42.368 7281 INFO nova.virt.libvirt.driver [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Creating image
  2015-02-05 15:59:42.369 7281 DEBUG nova.openstack.common.processutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf chown 106 /var/lib/nova/instances/290ab4b7-7225-4b74-853a-d342974a2080/console.log execute /usr/lib/python2.7/dist-packages/nova/openstack/common/processutils.py:161
  2015-02-05 15:59:42.389 7281 DEBUG nova.compute.manager [-] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Synchronizing instance power state after lifecycle event "Stopped"; current vm_state: active, current task_state: rescuing, current DB power_state: 1, VM power_state: 4 handle_lifecycle_event /usr/lib/python2.7/dist-packages/nova/compute/manager.py:1111
  2015-02-05 15:59:42.405 7281 DEBUG nova.openstack.common.processutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] Result was 0 execute /usr/lib/python2.7/dist-packages/nova/openstack/common/processutils.py:195
  2015-02-05 15:59:42.406 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Created new semaphore "70a880bdefde82d942a92de4c180c202e6090dd6" internal_lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:206
  2015-02-05 15:59:42.406 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Acquired semaphore "70a880bdefde82d942a92de4c180c202e6090dd6" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:229
  2015-02-05 15:59:42.406 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Attempting to grab external lock "70a880bdefde82d942a92de4c180c202e6090dd6" external_lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:178
  2015-02-05 15:59:42.406 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Got file lock "/var/lib/nova/instances/locks/nova-70a880bdefde82d942a92de4c180c202e6090dd6" acquire /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:93
  2015-02-05 15:59:42.407 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Got semaphore / lock "fetch_func_sync" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:271
  2015-02-05 15:59:42.407 7281 DEBUG glanceclient.common.http [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] curl -i -X GET -H 'User-Agent: python-glanceclient' -H 'Content-Type: application/octet-stream' -H 'Accept-Encoding: gzip, deflate' -H 'Accept: */*' -H 'X-Auth-Token: ***' http://gi.controller:9292/v1/images/a58da6f6-cea3-4b3a-bdd0-30aefcdb37cf log_curl_request /usr/lib/python2.7/dist-packages/glanceclient/common/http.py:119
  2015-02-05 15:59:42.417 7281 INFO nova.compute.manager [-] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] During sync_power_state the instance has a pending task (rescuing). Skip.
  2015-02-05 15:59:42.515 7281 ERROR glanceclient.common.http [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Request returned failure status 404.
  2015-02-05 15:59:42.515 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Released file lock "/var/lib/nova/instances/locks/nova-70a880bdefde82d942a92de4c180c202e6090dd6" release /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:115
  2015-02-05 15:59:42.515 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Releasing semaphore "70a880bdefde82d942a92de4c180c202e6090dd6" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:238
  2015-02-05 15:59:42.516 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Semaphore / lock released "fetch_func_sync" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:275
  2015-02-05 15:59:42.516 7281 ERROR nova.compute.manager [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Error trying to Rescue Instance
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080] Traceback (most recent call last):
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 3277, in rescue_instance
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     rescue_image_meta, admin_password)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 2569, in rescue
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     admin_pass=rescue_password)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3005, in _create_image
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     project_id=instance['project_id'])
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 208, in cache
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     *args, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 410, in create_image
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     prepare_template(target=base, max_size=size, *args, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py", line 272, in inner
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     return f(*args, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/imagebackend.py", line 198, in fetch_func_sync
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     fetch_func(target=target, *args, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/utils.py", line 452, in fetch_image
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     max_size=max_size)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 79, in fetch_to_raw
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     max_size=max_size)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/virt/images.py", line 73, in fetch
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     IMAGE_API.download(context, image_href, dest_path=path)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/image/api.py", line 178, in download
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     dst_path=dest_path)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 359, in download
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     _reraise_translated_image_exception(image_id)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 357, in download
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     image_chunks = self._client.call(context, 1, 'data', image_id)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/nova/image/glance.py", line 232, in call
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     return getattr(client.images, method)(*args, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/glanceclient/v1/images.py", line 142, in data
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     % urlparse.quote(str(image_id)))
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/glanceclient/common/http.py", line 253, in get
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     return self._request('GET', url, **kwargs)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]   File "/usr/lib/python2.7/dist-packages/glanceclient/common/http.py", line 221, in _request
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]     raise exc.from_response(resp, resp.content)
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080] ImageNotFound: Image a58da6f6-cea3-4b3a-bdd0-30aefcdb37cf could not be found.
  2015-02-05 15:59:42.516 7281 TRACE nova.compute.manager [instance: 290ab4b7-7225-4b74-853a-d342974a2080]
  2015-02-05 15:59:42.649 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Created new semaphore "compute_resources" internal_lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:206
  2015-02-05 15:59:42.650 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Acquired semaphore "compute_resources" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:229
  2015-02-05 15:59:42.650 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:271
  2015-02-05 15:59:42.671 7281 INFO nova.scheduler.client.report [req-af7026f3-4d85-4899-8452-2b69a3e66123 None] Compute_service record updated for ('pp3', 'pp3')
  2015-02-05 15:59:42.671 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Releasing semaphore "compute_resources" lock /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:238
  2015-02-05 15:59:42.672 7281 DEBUG nova.openstack.common.lockutils [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/dist-packages/nova/openstack/common/lockutils.py:275
  2015-02-05 15:59:42.672 7281 ERROR oslo.messaging.rpc.dispatcher [req-af7026f3-4d85-4899-8452-2b69a3e66123 ] Exception during message handling: Instance 290ab4b7-7225-4b74-853a-d342974a2080 cannot be rescued: Driver Error: Image a58da6f6-cea3-4b3a-bdd0-30aefcdb37cf could not be found.
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 419, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 88, in wrapped
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     payload)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/exception.py", line 71, in wrapped
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 303, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     pass
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 289, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 353, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 331, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     kwargs['instance'], e, sys.exc_info())
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/openstack/common/excutils.py", line 82, in __exit__
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 319, in decorated_function
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 3283, in rescue_instance
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher     reason=_("Driver Error: %s") % unicode(e))
  2015-02-05 15:59:42.672 7281 TRACE oslo.messaging.rpc.dispatcher InstanceNotRescuable: Instance 290ab4b7-7225-4b74-853a-d342974a2080 cannot be rescued: Driver Error: Image a58da6f6-cea3-4b3a-bdd0-30aefcdb37cf could not be found.

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