tempest.api.compute.servers.test_server_rescue.ServerRescueTestJSON.test_rescue_paused_instance fails sporadically in gate jobs

[Peter Portante]

tempest.api.compute.servers.test_server_rescue.ServerRescueTestJSON.test_rescue_paused_instance fails sporadically in gate jobs

See: http://logs.openstack.org/08/66108/3/check/check-tempest-dsvm-full/fdbbfd3/console.html

2014-01-15 00:40:01.541 | ======================================================================
2014-01-15 00:40:01.542 | FAIL: tempest.api.compute.servers.test_server_rescue.ServerRescueTestJSON.test_rescue_paused_instance[gate,negative]
2014-01-15 00:40:01.542 | tempest.api.compute.servers.test_server_rescue.ServerRescueTestJSON.test_rescue_paused_instance[gate,negative]
2014-01-15 00:40:01.543 | ----------------------------------------------------------------------
2014-01-15 00:40:01.544 | _StringException: Empty attachments:
2014-01-15 00:40:01.544 | stderr
2014-01-15 00:40:01.544 | stdout
2014-01-15 00:40:01.544 |
2014-01-15 00:40:01.544 | pythonlogging:'': {{{
2014-01-15 00:40:01.544 | 2014-01-15 00:12:20,256 Request: POST http://127.0.0.1:8774/v2/64edf5122f2d486682ecfaa53bd071b6/servers/83997448-4700-4333-8022-99328e6b5e1f/action
2014-01-15 00:40:01.545 | 2014-01-15 00:12:20,256 Request Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<Token omitted>'}
2014-01-15 00:40:01.545 | 2014-01-15 00:12:20,256 Request Body: {"pause": {}}
2014-01-15 00:40:01.545 | 2014-01-15 00:12:20,916 Response Status: 202
2014-01-15 00:40:01.545 | 2014-01-15 00:12:20,916 Nova request id: req-f716db87-36c7-46be-8672-9f5fbecd2c04
2014-01-15 00:40:01.545 | 2014-01-15 00:12:20,916 Response Headers: {'content-length': '0', 'date': 'Wed, 15 Jan 2014 00:12:20 GMT', 'content-type': 'text/html; charset=UTF-8', 'connection': 'close'}
.
.
.
2014-01-15 00:40:01.934 | 2014-01-15 00:15:37,090 Request: POST http://127.0.0.1:8774/v2/64edf5122f2d486682ecfaa53bd071b6/servers/83997448-4700-4333-8022-99328e6b5e1f/action
2014-01-15 00:40:01.934 | 2014-01-15 00:15:37,090 Request Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<Token omitted>'}
2014-01-15 00:40:01.934 | 2014-01-15 00:15:37,090 Request Body: {"unpause": {}}
2014-01-15 00:40:01.935 | 2014-01-15 00:15:37,138 Response Status: 409
2014-01-15 00:40:01.935 | 2014-01-15 00:15:37,138 Nova request id: req-ff9827ce-fbae-4f3b-addf-8e0ddf6a29a7
2014-01-15 00:40:01.935 | 2014-01-15 00:15:37,138 Response Headers: {'content-length': '105', 'date': 'Wed, 15 Jan 2014 00:15:37 GMT', 'content-type': 'application/json; charset=UTF-8', 'connection': 'close'}
2014-01-15 00:40:01.935 | 2014-01-15 00:15:37,138 Response Body: {"conflictingRequest": {"message": "Cannot 'unpause' while instance is in vm_state active", "code": 409}}
2014-01-15 00:40:01.935 | }}}
2014-01-15 00:40:01.935 |
2014-01-15 00:40:01.935 | traceback-1: {{{
2014-01-15 00:40:01.936 | Traceback (most recent call last):
2014-01-15 00:40:01.936 | File "tempest/api/compute/servers/test_server_rescue.py", line 107, in _unpause
2014-01-15 00:40:01.936 | resp, body = self.servers_client.unpause_server(server_id)
2014-01-15 00:40:01.936 | File "tempest/services/compute/json/servers_client.py", line 374, in unpause_server
2014-01-15 00:40:01.936 | return self.action(server_id, 'unpause', None, **kwargs)
2014-01-15 00:40:01.936 | File "tempest/services/compute/json/servers_client.py", line 198, in action
2014-01-15 00:40:01.936 | post_body, self.headers)
2014-01-15 00:40:01.937 | File "tempest/common/rest_client.py", line 302, in post
2014-01-15 00:40:01.937 | return self.request('POST', url, headers, body)
2014-01-15 00:40:01.937 | File "tempest/common/rest_client.py", line 436, in request
2014-01-15 00:40:01.937 | resp, resp_body)
2014-01-15 00:40:01.937 | File "tempest/common/rest_client.py", line 491, in _error_checker
2014-01-15 00:40:01.937 | raise exceptions.Conflict(resp_body)
2014-01-15 00:40:01.937 | Conflict: An object with that identifier already exists
2014-01-15 00:40:01.938 | Details: {u'conflictingRequest': {u'message': u"Cannot 'unpause' while instance is in vm_state active", u'code': 409}}
2014-01-15 00:40:01.938 | }}}
2014-01-15 00:40:01.938 |
2014-01-15 00:40:01.938 | Traceback (most recent call last):
2014-01-15 00:40:01.938 | File "tempest/api/compute/servers/test_server_rescue.py", line 128, in test_rescue_paused_instance
2014-01-15 00:40:01.938 | self.servers_client.wait_for_server_status(self.server_id, 'PAUSED')
2014-01-15 00:40:01.938 | File "tempest/services/compute/json/servers_client.py", line 162, in wait_for_server_status
2014-01-15 00:40:01.939 | raise_on_error=raise_on_error)
2014-01-15 00:40:01.939 | File "tempest/common/waiters.py", line 91, in wait_for_server_status
2014-01-15 00:40:01.939 | raise exceptions.TimeoutException(message)
2014-01-15 00:40:01.939 | TimeoutException: Request timed out
2014-01-15 00:40:01.939 | Details: Server 83997448-4700-4333-8022-99328e6b5e1f failed to reach PAUSED status and task state "None" within the required time (196 s). Current status: ACTIVE. Current task state: None.

[Matt Riedemann (mriedem)]

Maybe a dupe of bug 1226412.

[Matt Riedemann (mriedem)]

4 hits on this in the last 7 days:

message:"Server" AND message:"failed to reach PAUSED status and task state \"None\" within the required time" AND message:"Current status: ACTIVE." AND filename:"console.html"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiU2VydmVyXCIgQU5EIG1lc3NhZ2U6XCJmYWlsZWQgdG8gcmVhY2ggUEFVU0VEIHN0YXR1cyBhbmQgdGFzayBzdGF0ZSBcXFwiTm9uZVxcXCIgd2l0aGluIHRoZSByZXF1aXJlZCB0aW1lXCIgQU5EIG1lc3NhZ2U6XCJDdXJyZW50IHN0YXR1czogQUNUSVZFLlwiIEFORCBmaWxlbmFtZTpcImNvbnNvbGUuaHRtbFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxMzkwODY1OTM3MTcwfQ==

Sometimes the task_state is None, sometimes it's 'pausing', so looks like the instance is transitioning states when the timeout is reached.