rebuild test fails because of "Fixed interval looping call 'nova.virt.libvirt.driver._wait_for_boot' failed: InstanceNotFound" on spawn

Bug #1794873 reported by Matt Riedemann
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Expired
Medium
Unassigned

Bug Description

Test times out waiting for a server being rebuilt to go to ACTIVE status:

http://logs.openstack.org/06/604906/5/check/nova-multiattach/bf3ea47/job-output.txt.gz#_2018-09-27_15_34_39_538772

Details: (ServerActionsTestJSON:test_rebuild_server) Server 94b4ab8e-47d6-43be-870c-4e4011db32ff failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: REBUILD. Current task state: rebuild_spawning.

There is an error in the n-cpu logs where the spawn() method in the libvirt driver is waiting for the guest to be powered on and running which fails with an InstanceNotFound because libvirt apparently loses track of the domain for a split second:

http://logs.openstack.org/06/604906/5/check/nova-multiattach/bf3ea47/logs/screen-n-cpu.txt.gz?level=TRACE#_Sep_27_15_28_06_252895

Sep 27 15:28:06.217569 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: DEBUG nova.virt.libvirt.host [None req-6d8d60b7-b21d-4e72-bedd-0dfec222115d None None] Removed pending event for 94b4ab8e-47d6-43be-870c-4e4011db32ff due to lifecycle event {{(pid=27781) _event_emit_delayed /opt/stack/new/nova/nova/virt/libvirt/host.py:321}}
Sep 27 15:28:06.217880 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: DEBUG nova.virt.driver [None req-6d8d60b7-b21d-4e72-bedd-0dfec222115d None None] Emitting event <LifecycleEvent: 1538062086.22, 94b4ab8e-47d6-43be-870c-4e4011db32ff => Resumed> {{(pid=27781) emit_event /opt/stack/new/nova/nova/virt/driver.py:1577}}
Sep 27 15:28:06.218134 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: INFO nova.compute.manager [None req-6d8d60b7-b21d-4e72-bedd-0dfec222115d None None] [instance: 94b4ab8e-47d6-43be-870c-4e4011db32ff] VM Resumed (Lifecycle Event)
Sep 27 15:28:06.223191 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: DEBUG nova.virt.libvirt.driver [None req-db723532-7a30-4319-804e-9304847c5d66 tempest-ServerActionsTestJSON-807586552 tempest-ServerActionsTestJSON-807586552] [instance: 94b4ab8e-47d6-43be-870c-4e4011db32ff] Guest created on hypervisor {{(pid=27781) spawn /opt/stack/new/nova/nova/virt/libvirt/driver.py:3076}}
Sep 27 15:28:06.252895 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall [-] Fixed interval looping call 'nova.virt.libvirt.driver._wait_for_boot' failed: InstanceNotFound: Instance 94b4ab8e-47d6-43be-870c-4e4011db32ff could not be found.
Sep 27 15:28:06.253155 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall Traceback (most recent call last):
Sep 27 15:28:06.253394 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall File "/usr/local/lib/python2.7/dist-packages/oslo_service/loopingcall.py", line 193, in _run_loop
Sep 27 15:28:06.253641 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall result = func(*self.args, **self.kw)
Sep 27 15:28:06.253861 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3080, in _wait_for_boot
Sep 27 15:28:06.254098 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall state = self.get_info(instance).state
Sep 27 15:28:06.254326 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 5443, in get_info
Sep 27 15:28:06.254572 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall guest = self._host.get_guest(instance)
Sep 27 15:28:06.254806 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall File "/opt/stack/new/nova/nova/virt/libvirt/host.py", line 548, in get_guest
Sep 27 15:28:06.255035 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall return libvirt_guest.Guest(self._get_domain(instance))
Sep 27 15:28:06.255255 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall File "/opt/stack/new/nova/nova/virt/libvirt/host.py", line 568, in _get_domain
Sep 27 15:28:06.255472 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall raise exception.InstanceNotFound(instance_id=instance.uuid)
Sep 27 15:28:06.255708 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall InstanceNotFound: Instance 94b4ab8e-47d6-43be-870c-4e4011db32ff could not be found.
Sep 27 15:28:06.255926 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: ERROR oslo.service.loopingcall
Sep 27 15:28:06.256139 ubuntu-xenial-inap-mtl01-0002375163 nova-compute[27781]: DEBUG nova.compute.manager [None req-db723532-7a30-4319-804e-9304847c5d66 tempest-ServerActionsTestJSON-807586552 tempest-ServerActionsTestJSON-807586552] [instance: 94b4ab8e-47d6-43be-870c-4e4011db32ff] Instance was deleted while rebuilding {{(pid=27781) rebuild_instance /opt/stack/new/nova/nova/compute/manager.py:3056}}

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Fixed%20interval%20looping%20call%20'nova.virt.libvirt.driver._wait_for_boot'%20failed%3A%20InstanceNotFound%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d

Lee Yarwood (lyarwood)
Changed in nova:
status: Confirmed → Incomplete
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

Changed in nova:
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.