Public bug reported: 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 ** Affects: nova Importance: Medium Status: Confirmed ** Tags: gate-failure libvirt rebuild -- 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/1794873 Title: rebuild test fails because of "Fixed interval looping call 'nova.virt.libvirt.driver._wait_for_boot' failed: InstanceNotFound" on spawn Status in OpenStack Compute (nova): Confirmed 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 To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1794873/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
