"Unable to find host for Instance" when suspending

[Ken'ichi Ohmichi]

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-api.txt.gz#_2016-08-05_23_17_52_131

2016-08-05 23:17:52.131 10733 DEBUG nova.api.openstack.wsgi [req-a0667e59-84a2-4215-a598-855fc2c28d7b tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] Action: 'action', calling method: <bound method SuspendServerController._suspend of <nova.api.openstack.compute.suspend_server.SuspendServerController object at 0x7face4e01110>>, body: {"suspend": {}} _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:633
2016-08-05 23:17:52.132 10733 DEBUG nova.compute.api [req-a0667e59-84a2-4215-a598-855fc2c28d7b tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] [instance: 42d7671e-c596-4b90-ad5a-9e3d82824e95] Fetching instance by UUID get /opt/stack/new/nova/nova/compute/api.py:1957
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions [req-a0667e59-84a2-4215-a598-855fc2c28d7b tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] Unexpected exception in API method
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/extensions.py", line 338, in wrapped
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/api/openstack/compute/suspend_server.py", line 41, in _suspend
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions self.compute_api.suspend(context, server)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/api.py", line 164, in inner
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions return function(self, context, instance, *args, **kwargs)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/api.py", line 171, in _wrapped
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions return fn(self, context, instance, *args, **kwargs)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/api.py", line 145, in inner
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions return f(self, context, instance, *args, **kw)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/api.py", line 2753, in suspend
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions self.compute_rpcapi.suspend_instance(context, instance)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 953, in suspend_instance
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions server=_compute_host(None, instance), version=version)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions File "/opt/stack/new/nova/nova/compute/rpcapi.py", line 53, in _compute_host
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions 'Instance %s') % instance.uuid)
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions NovaException: Unable to find host for Instance 42d7671e-c596-4b90-ad5a-9e3d82824e95
2016-08-05 23:17:52.509 10733 ERROR nova.api.openstack.extensions

[jichenjc (jichenjc)]

2016-08-05 23:17:51.849 10734 DEBUG nova.api.openstack.compute.servers [req-b1032536-2dce-40c3-a709-aa06ca55eeeb tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] [instance: 42d7671e-c596-4b90-ad5a-9e3d82824e95] stop instance _stop_server /opt/stack/new/nova/nova/api/openstack/compute/servers.py:1086
2016-08-05 23:17:51.849 10734 INFO nova.api.openstack.wsgi [req-b1032536-2dce-40c3-a709-aa06ca55eeeb tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] HTTP exception thrown: Instance 42d7671e-c596-4b90-ad5a-9e3d82824e95 is not ready

looks like the instance might not be ready yet... so we might follow what we did in stop
add host field check before proceed

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/352486

[jichenjc (jichenjc)]

I think this bug duplicate to https://bugs.launchpad.net/nova/+bug/1611008

[Matt Riedemann (mriedem)]

This is really odd. Is this one of those tests where tempest re-uses the same server for multiple tests? Because I can see in the n-api logs that the server is resized at one point:

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-api.txt.gz#_2016-08-05_23_16_55_474

2016-08-05 23:16:55.474 10733 DEBUG nova.compute.api [req-81da40b7-d20e-4fb6-b709-f93659a13ddd tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] [instance: 42d7671e-c596-4b90-ad5a-9e3d82824e95] Old instance type m1.nano, new instance type m1.micro resize /opt/stack/new/nova/nova/compute/api.py:2564

And here we can see it shelve the instance:

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-api.txt.gz#_2016-08-05_23_17_26_320

2016-08-05 23:17:26.320 10734 DEBUG nova.api.openstack.wsgi [req-e3150eef-c86d-4186-a882-395af477d0f9 tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] Action: 'action', calling method: <bound method ShelveController._shelve of <nova.api.openstack.compute.shelve.ShelveController object at 0x7face4e28a50>>, body: {"shelve": {}} _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:633

And here it unshelves:

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-api.txt.gz#_2016-08-05_23_17_44_157

2016-08-05 23:17:44.157 10733 DEBUG nova.api.openstack.wsgi [req-b2a7a246-14d5-4b73-82f1-c64fb5805ff8 tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] Action: 'action', calling method: <bound method ShelveController._unshelve of <nova.api.openstack.compute.shelve.ShelveController object at 0x7face4e28a50>>, body: {"unshelve": {}} _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:633

And then it tries to stop the instance but fails because instance.host isn't set:

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-api.txt.gz#_2016-08-05_23_17_51_849

So something probably failed during the shelve/unshelve or we have some race condition.

[Matt Riedemann (mriedem)]

At this point the instance is unshelved:

http://logs.openstack.org/09/350309/2/check/gate-tempest-dsvm-full-ubuntu-xenial/f975e3b/logs/screen-n-cpu.txt.gz#_2016-08-05_23_16_54_737

2016-08-05 23:16:54.737 12171 INFO nova.compute.manager [req-ece321aa-5b56-45fc-b4ed-cec1218c98dc tempest-ServerActionsTestJSON-519557852 tempest-ServerActionsTestJSON-519557852] [instance: 42d7671e-c596-4b90-ad5a-9e3d82824e95] Took 7.00 seconds to build instance.

Note the timestamps - when tempest tries to stop the instance at 23_17_51_849 we're still unshelving the instance on the compute.

[Matt Riedemann (mriedem)]

This was fixed with e285eb1a382e6d3ce1cc596eeb5cecb3b165a228.

[OpenStack Infra (hudson-openstack)]

Change abandoned by jichenjc (<email address hidden>) on branch: master
Review: https://review.openstack.org/352486