[yoga] Tempest fails to start a server

[Bas de Bruijne]

In testrun:
https://solutions.qa.canonical.com/testruns/testRun/194ee801-04bf-4ed9-83cf-ac2e19669bfc

Yoga builds correctly but fails on tempest:
https://oil-jenkins.canonical.com/artifacts/194ee801-04bf-4ed9-83cf-ac2e19669bfc/generated/generated/openstack/tempest_result.html

In this test, tempest stop and starts a server, but it does not come back up.

In the nova logs we see:
--------------------------------------------
2022-04-12 20:48:26.281 1820614 INFO nova.virt.libvirt.driver [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Instance destroyed successfully.
2022-04-12 20:48:27.310 1820614 WARNING nova.compute.manager [req-577b95c6-b3ec-49eb-8d63-b40f9bb7e5ce a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-unplugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state None.
2022-04-12 20:48:30.655 1820614 WARNING nova.compute.manager [req-6bce62da-4634-471e-a504-13bbe3270d61 a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-plugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state None.
2022-04-12 20:48:33.254 1820614 INFO nova.virt.libvirt.driver [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Instance destroyed successfully.
2022-04-12 20:48:34.588 1820614 WARNING nova.compute.manager [req-f6586bba-4012-4eaa-b000-1a56e22c45a0 a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-plugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state powering-on.
2022-04-12 20:48:36.722 1820614 WARNING nova.compute.manager [req-c8345295-08bd-4e32-a210-8ab99c7f25b9 a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-plugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state powering-on.
2022-04-12 20:48:40.986 1820614 INFO nova.compute.manager [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] VM Stopped (Lifecycle Event)
2022-04-12 20:49:04.836 1820614 INFO nova.compute.manager [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] During sync_power_state the instance has a pending task (powering-on). Skip.
  <uuid>79ae643f-c915-4557-82f8-f17da1c44755</uuid>
      <entry name='serial'>79ae643f-c915-4557-82f8-f17da1c44755</entry>
      <entry name='uuid'>79ae643f-c915-4557-82f8-f17da1c44755</entry>
      <source file='/var/lib/nova/instances/79ae643f-c915-4557-82f8-f17da1c44755/disk'/>
      <log file='/var/lib/nova/instances/79ae643f-c915-4557-82f8-f17da1c44755/console.log' append='off'/>
      <log file='/var/lib/nova/instances/79ae643f-c915-4557-82f8-f17da1c44755/console.log' append='off'/>
2022-04-12 20:49:04.847 1820614 ERROR nova.virt.libvirt.driver [req-cbfa0bed-3e3e-4402-a071-76c9da1f5661 c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Failed to start libvirt guest: libvirt.libvirtError: error from service: Timeout was reached
2022-04-12 20:49:04.974 1820614 INFO nova.compute.manager [req-abaa98f3-840b-4e5f-8833-a18043823319 - - - - -] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] During sync_power_state the instance has a pending task (powering-on). Skip.
2022-04-12 20:49:05.079 1820614 INFO nova.compute.manager [req-cbfa0bed-3e3e-4402-a071-76c9da1f5661 c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Successfully reverted task state from powering-on on failure for instance.
2022-04-12 20:49:05.785 1820614 WARNING nova.compute.manager [req-13b96ce5-9969-49fb-a5e1-73bd06190227 a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-unplugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state None.
2022-04-12 20:49:08.229 1820614 WARNING nova.compute.manager [req-24e1c96f-04bd-46be-9ce1-5468a0bf2d7e a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Received unexpected event network-vif-plugged-ee0dab67-3fd9-4943-a70a-b53a1edafffc for instance with vm_state stopped and task_state None.
2022-04-12 20:59:06.499 1820614 INFO nova.compute.manager [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] During _sync_instance_power_state the DB power_state (4) does not match the vm_power_state from the hypervisor (0). Updating power_state in the DB to match the hypervisor.
2022-04-12 21:08:32.088 1820614 INFO nova.compute.manager [req-11d57952-8002-450d-9122-2739af9e25dd c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Terminating instance
2022-04-12 21:08:32.094 1820614 INFO nova.virt.libvirt.driver [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Instance destroyed successfully.
2022-04-12 21:08:32.148 1820614 INFO nova.virt.libvirt.driver [req-11d57952-8002-450d-9122-2739af9e25dd c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Deleting instance files /var/lib/nova/instances/79ae643f-c915-4557-82f8-f17da1c44755_del
2022-04-12 21:08:32.148 1820614 INFO nova.virt.libvirt.driver [req-11d57952-8002-450d-9122-2739af9e25dd c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Deletion of /var/lib/nova/instances/79ae643f-c915-4557-82f8-f17da1c44755_del complete
2022-04-12 21:08:32.231 1820614 INFO nova.compute.manager [req-11d57952-8002-450d-9122-2739af9e25dd c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Took 0.14 seconds to destroy the instance on the hypervisor.
2022-04-12 21:08:34.605 1820614 INFO nova.compute.manager [req-3f77554c-6cbf-48ed-9598-8854d7687267 a6a714097fbd450fa917189d6e89b073 - - dda5fe657938420a947ac87de5ae0b29 dda5fe657938420a947ac87de5ae0b29] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Neutron deleted interface ee0dab67-3fd9-4943-a70a-b53a1edafffc; detaching it from the instance and deleting it from the info cache
2022-04-12 21:08:34.641 1820614 INFO nova.compute.manager [-] [instance: 79ae643f-c915-4557-82f8-f17da1c44755] Took 2.41 seconds to deallocate network for instance.
2022-04-12 21:08:34.910 1820614 INFO nova.scheduler.client.report [req-11d57952-8002-450d-9122-2739af9e25dd c3202ca4eb774fa8a0f357564a4dd572 - - f6ca11d407354d8f9af85c0b58e31019 f6ca11d407354d8f9af85c0b58e31019] Deleted allocations for instance 79ae643f-c915-4557-82f8-f17da1c44755
--------------------------------------------

So there seem to be some network problems preventing the server from starting again.

Reproducers:
Deploy the bundle https://oil-jenkins.canonical.com/artifacts/194ee801-04bf-4ed9-83cf-ac2e19669bfc/generated/generated/openstack/bundle.yaml
run the test tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_stop_start_server[id-af8eafd4-38a7-4a4b-bdbc-75145a580560]

Link to crashdumps etc.:
https://oil-jenkins.canonical.com/artifacts/194ee801-04bf-4ed9-83cf-ac2e19669bfc/index.html

All occurrences of this bug are listed here:
https://solutions.qa.canonical.com/bugs/bugs/bug/1968898

[Bas de Bruijne (basdbruijne)]

Something similar is happening in this run:
https://solutions.qa.canonical.com/testruns/testRun/04c8ea16-f704-4933-a9d2-1ac81cdf1d55

The tempest results are:
https://oil-jenkins.canonical.com/artifacts/04c8ea16-f704-4933-a9d2-1ac81cdf1d55/generated/generated/openstack/tempest_result.html

In the logs we see:
--------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/nova/virt/libvirt/driver.py", line 7499, in _create_guest_with_network
    guest = self._create_guest(
  File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
    next(self.gen)
  File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 557, in wait_for_instance_event
    self._wait_for_instance_events(
  File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 469, in _wait_for_instance_events
    actual_event = event.wait()
  File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 434, in wait
    instance_event = self.event.wait()
  File "/usr/lib/python3/dist-packages/eventlet/event.py", line 125, in wait
    result = hub.switch()
  File "/usr/lib/python3/dist-packages/eventlet/hubs/hub.py", line 313, in switch
    return self.greenlet.switch()
eventlet.timeout.Timeout: 300 seconds

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 2489, in _build_and_run_instance
    self.driver.spawn(context, instance, image_meta,
  File "/usr/lib/python3/dist-packages/nova/virt/libvirt/driver.py", line 4333, in spawn
    self._create_guest_with_network(
  File "/usr/lib/python3/dist-packages/nova/virt/libvirt/driver.py", line 7517, in _create_guest_with_network
    raise exception.VirtualInterfaceCreateException()
nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed

2022-04-12 19:38:02.588 1678077 ERROR nova.compute.manager [req-38acfeb8-a8cf-4fa2-a863-321341f602e8 1dea977949dd4a1585a46f6b83e2ddea - - 1ccf2567ce064e49bc11b1ec9aa6dd7d 1ccf2567ce064e49bc11b1ec9aa6dd7d] [instance: 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf] Build of instance 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf aborted: Failed to allocate the network(s), not rescheduling.: nova.exception.BuildAbortException: Build of instance 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf aborted: Failed to allocate the network(s), not rescheduling.
2022-04-12 19:38:06.648 1678077 INFO nova.compute.manager [req-38acfeb8-a8cf-4fa2-a863-321341f602e8 1dea977949dd4a1585a46f6b83e2ddea - - 1ccf2567ce064e49bc11b1ec9aa6dd7d 1ccf2567ce064e49bc11b1ec9aa6dd7d] [instance: 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf] Took 4.06 seconds to deallocate network for instance.
2022-04-12 19:38:06.861 1678077 INFO nova.scheduler.client.report [req-38acfeb8-a8cf-4fa2-a863-321341f602e8 1dea977949dd4a1585a46f6b83e2ddea - - 1ccf2567ce064e49bc11b1ec9aa6dd7d 1ccf2567ce064e49bc11b1ec9aa6dd7d] Deleted allocations for instance 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf
2022-04-12 19:38:17.125 1678077 INFO nova.compute.manager [-] [instance: 35b7bc20-05d0-45a4-9a3f-9f2bec913fbf] VM Stopped (Lifecycle Event)
------------------------------------------...

[Bas de Bruijne (basdbruijne)]

This is still a relevant issue. Subscribing Moises for follow up questions