when testing rebooting of a server a race condition occurs sometimes
1. request to reboot HARD
2016-04-19 14:42:33.062 24414 INFO tempest.lib.common.rest_client [req-61fcfe57-53a7-4cbf-a7e1-8155294406a7 ] Request (CPUPolicyTest:test_reboot_pinned_server): 202 POST http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629/action 0.161s
2016-04-19 14:42:33.062 24414 DEBUG tempest.lib.common.rest_client [req-61fcfe57-53a7-4cbf-a7e1-8155294406a7 ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
Body: {"reboot": {"type": "HARD"}}
2. checking status: HARD_REBOOT
2016-04-19 14:42:33.132 24414 INFO tempest.lib.common.rest_client [req-f5415cd1-4dc8-4a5f-be45-329eecaa24f0 ] Request (CPUPolicyTest:test_reboot_pinned_server): 200 GET http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629 0.069s
2016-04-19 14:42:33.132 24414 DEBUG tempest.lib.common.rest_client [req-f5415cd1-4dc8-4a5f-be45-329eecaa24f0 ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
Body: None
Response - Headers: {'status': '200', 'content-length': '1583', 'content-location': 'http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629', 'x-compute-request-id': 'req-f5415cd1-4dc8-4a5f-be45-329eecaa24f0', 'vary': 'X-OpenStack-Nova-API-Version',
'connection': 'close', 'x-openstack-nova-api-version': '2.1', 'date': 'Tue, 19 Apr 2016 14:42:33 GMT', 'content-type': 'application/json'}
Body: {"server": {"status": "HARD_REBOOT", "updated": "2016-04-19T14:42:33Z", "hostId": "77ad4e027a52afb981d2f56e14b1d7fe877473f9d5cb3962969a2c46", "OS-EXT-SRV-ATTR:host": "ubuntu", "addresses": {"private": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:76:f8:7f", "versi
on": 4, "addr": "10.1.12.9", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629", "rel": "self"}, {"href": "http://127.0.0.1:8774/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629", "rel": "bookmark"}], "
key_name": null, "image": {"id": "8763180f-ecec-492f-9671-9b7cca8963dd", "links": [{"href": "http://127.0.0.1:8774/images/8763180f-ecec-492f-9671-9b7cca8963dd", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": "rebooting_hard", "OS-EXT-STS:vm_state": "active", "OS-EXT-SRV-
ATTR:instance_name": "instance-000000b8", "OS-SRV-USG:launched_at": "2016-04-19T14:42:31.000000", "OS-EXT-SRV-ATTR:hypervisor_hostname": "ubuntu", "flavor": {"id": "30736933", "links": [{"href": "http://127.0.0.1:8774/flavors/30736933", "rel": "bookmark"}]}, "id": "84ab01ac-8d94-4cc8-83a5-287c8e0aa629", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "8fa7afb29697452fa04ce29f0290fb76", "name": "tempest.common.compute-instance-423347370", "created": "2016-04-19
T14:42:27Z", "tenant_id": "167fbb1b36e74238b9aa206c09ed26f6", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "OS-EXT-STS:power_state": 1, "config_drive": "True", "metadata": {}}} _log_request_full tempest/li
b/common/rest_client.py:414
3. cleanup request to DELETE instance
2016-04-19 14:42:33.326 24414 INFO tempest.lib.common.rest_client [req-a35c5085-9059-4b24-a475-c98aa046502d ] Request (CPUPolicyTest:_run_cleanups): 204 DELETE http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629 0.183s
2016-04-19 14:42:33.327 24414 DEBUG tempest.lib.common.rest_client [req-a35c5085-9059-4b24-a475-c98aa046502d ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
Body: None
Response - Headers: {'status': '204', 'content-length': '0', 'x-compute-request-id': 'req-a35c5085-9059-4b24-a475-c98aa046502d', 'vary': 'X-OpenStack-Nova-API-Version', 'connection': 'close', 'x-openstack-nova-api-version': '2.1', 'date': 'Tue, 19 Apr 2016 14:42:33 G
MT', 'content-type': 'application/json'}
4. conflicting instance state:
expected: u'reboot_pending_hard
actual: u'deleting
2016-04-19 14:42:35.279 24414 INFO tempest.lib.common.rest_client [req-2d1634dc-6bd7-445d-bcb8-704ed4e81cdc ] Request (CPUPolicyTest:tearDownClass): 200 GET http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629 0.076s
2016-04-19 14:42:35.279 24414 DEBUG tempest.lib.common.rest_client [req-2d1634dc-6bd7-445d-bcb8-704ed4e81cdc ] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
Body: None
Response - Headers: {'status': '200', 'content-length': '3308', 'content-location': 'http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629', 'x-compute-request-id': 'req-2d1634dc-6bd7-445d-bcb8-704ed4e81cdc', 'vary': 'X-OpenStack-Nova-API-Version',
'connection': 'close', 'x-openstack-nova-api-version': '2.1', 'date': 'Tue, 19 Apr 2016 14:42:35 GMT', 'content-type': 'application/json'}
Body: {"server": {"status": "ERROR", "updated": "2016-04-19T14:42:34Z", "hostId": "77ad4e027a52afb981d2f56e14b1d7fe877473f9d5cb3962969a2c46", "OS-EXT-SRV-ATTR:host": "ubuntu", "addresses": {"private": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:76:f8:7f", "version": 4
, "addr": "10.1.12.9", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://127.0.0.1:8774/v2.1/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629", "rel": "self"}, {"href": "http://127.0.0.1:8774/servers/84ab01ac-8d94-4cc8-83a5-287c8e0aa629", "rel": "bookmark"}], "key_na
me": null, "image": {"id": "8763180f-ecec-492f-9671-9b7cca8963dd", "links": [{"href": "http://127.0.0.1:8774/images/8763180f-ecec-492f-9671-9b7cca8963dd", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "error", "OS-EXT-SRV-ATTR:instance
_name": "instance-000000b8", "OS-SRV-USG:launched_at": "2016-04-19T14:42:31.000000", "OS-EXT-SRV-ATTR:hypervisor_hostname": "ubuntu", "flavor": {"id": "30736933", "links": [{"href": "http://127.0.0.1:8774/flavors/30736933", "rel": "bookmark"}]}, "id": "84ab01ac-8d94-4cc8
-83a5-287c8e0aa629", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "8fa7afb29697452fa04ce29f0290fb76", "name": "tempest.common.compute-instance-423347370", "created": "2016-04-19T14:42:27Z",
"tenant_id": "167fbb1b36e74238b9aa206c09ed26f6", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Conflict updating instance 84ab01ac-8d94-4cc8-83a5-287c8e0aa629. Expected: {'task_state':
[u'reboot_pending_hard']}. Actual: {'task_state': u'deleting'}", "code": 500, "details": " File \"/opt/stack/new/nova/nova/compute/manager.py\", line 366, in decorated_function\n return function(self, context, *args, **kwargs)\n File \"/opt/stack/new/nova/nova/comp
ute/manager.py\", line 3084, in reboot_instance\n self._set_instance_obj_error_state(context, instance)\n File \"/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py\", line 220, in __exit__\n self.force_reraise()\n File \"/usr/local/lib/python2.7/dist-p
ackages/oslo_utils/excutils.py\", line 196, in force_reraise\n six.reraise(self.type_, self.value, self.tb)\n File \"/opt/stack/new/nova/nova/compute/manager.py\", line 3060, in reboot_instance\n instance.save(expected_task_state=expected_state)\n File \"/usr/loc
al/lib/python2.7/dist-packages/oslo_versionedobjects/base.py\", line 207, in wrapper\n ctxt, self, fn.__name__, args, kwargs)\n File \"/opt/stack/new/nova/nova/conductor/rpcapi.py\", line 241, in object_action\n objmethod=objmethod, args=args, kwargs=kwargs)\n Fi
le \"/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py\", line 158, in call\n retry=self.retry)\n File \"/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py\", line 90, in _send\n timeout=timeout, retry=retry)\n File \"/usr/local/
lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py\", line 470, in send\n retry=retry)\n File \"/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py\", line 461, in _send\n raise result\n", "created": "2016-04-19T14:42:34Z"},
"OS-EXT-STS:power_state": 1, "config_drive": "True", "metadata": {}}} _log_request_full tempest/lib/common/rest_client.py:414
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base [-] Waiting for deletion of server 84ab01ac-8d94-4cc8-83a5-287c8e0aa629 failed
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base Traceback (most recent call last):
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base File "tempest/api/compute/base.py", line 148, in clear_servers
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base server['id'])
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base File "tempest/common/waiters.py", line 111, in wait_for_server_termination
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base raise exceptions.BuildErrorException(server_id=server_id)
2016-04-19 14:42:35.287 24414 ERROR tempest.api.compute.base BuildErrorException: Server 84ab01ac-8d94-4cc8-83a5-287c8e0aa629 failed to build and is in ERROR status
5. it looks like lack of waiter after requesting to reboot the server is causing the race condition (server is being cleaned up as the runtime of the code has finished - but the server hasn't shutdown for reboot yet)
Reviewed: https:/
Committed: https:/
Submitter: Jenkins
Branch: master
commit 8d82cbe0d62a16b
Author: Waldemar Znoinski <email address hidden>
Date: Tue Apr 19 16:16:10 2016 +0100
add waiter for server to become ACTIVE after reboot
There looks to be a race condition between server
reboot request and cleanup fuction that runs when the test finishes.
This change add explicit waiting for server to be back to 'ACTIVE'
state after being rebooted.
Change-Id: I990977e02bd09e
Closes-Bug: #1572197