tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_get_console_output flakey fail

[Christopher Yeoh]

Looks like tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_get_console_output sometimes fails due to not getting any console output (times out too soon?)

ft92.3: tempest.api.compute.servers.test_server_actions.ServerActionsTestJSON.test_get_console_output[gate]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2013-11-15 09:37:40,572 Request: GET http://127.0.0.1:8774/v2/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6
2013-11-15 09:37:40,581 Request Headers: {'X-Auth-Token': '<Token omitted>'}
2013-11-15 09:37:40,707 Response Status: 200
2013-11-15 09:37:40,707 Nova request id: req-c0a66c8d-84ef-49b8-97c7-8500b31e044d
2013-11-15 09:37:40,707 Response Headers: {'content-length': '1566', 'content-location': u'http://127.0.0.1:8774/v2/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6', 'date': 'Fri, 15 Nov 2013 09:37:40 GMT', 'content-type': 'application/json', 'connection': 'close'}
2013-11-15 09:37:40,707 Response Body: {"server": {"status": "ACTIVE", "updated": "2013-11-15T09:37:37Z", "hostId": "b8b3cb6c77b64cfd901d937c2af47d1a7461be6870d6db191a202461", "addresses": {"private": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:39:d6:1f", "version": 4, "addr": "10.1.0.45", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://127.0.0.1:8774/v2/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6", "rel": "self"}, {"href": "http://127.0.0.1:8774/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6", "rel": "bookmark"}], "key_name": null, "image": {"id": "bf506580-344c-4b73-982c-643229712453", "links": [{"href": "http://127.0.0.1:8774/a12951a2dcd44dd29151dd5ecfaf8f78/images/bf506580-344c-4b73-982c-643229712453", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2013-11-15T09:36:54.279155", "flavor": {"id": "42", "links": [{"href": "http://127.0.0.1:8774/a12951a2dcd44dd29151dd5ecfaf8f78/flavors/42", "rel": "bookmark"}]}, "id": "1bba2f52-61a6-4c29-a3ec-7f848d8e76d6", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "401f6d4586ea4840983835fd212aedcb", "name": "ServerActionsTestJSON-instance-tempest-1775626609", "created": "2013-11-15T09:36:44Z", "tenant_id": "a12951a2dcd44dd29151dd5ecfaf8f78", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [], "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}
2013-11-15 09:37:40,708 Request: POST http://127.0.0.1:8774/v2/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6/action
2013-11-15 09:37:40,708 Request Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<Token omitted>'}
2013-11-15 09:37:40,708 Request Body: {"os-getConsoleOutput": {"length": 10}}
2013-11-15 09:37:41,865 Response Status: 200

<snip>

013-11-15 09:40:56,234 Response Headers: {'content-length': '14', 'date': 'Fri, 15 Nov 2013 09:40:56 GMT', 'content-type': 'application/json', 'connection': 'close'}
2013-11-15 09:40:56,234 Response Body: {"output": ""}
2013-11-15 09:40:56,234 Request: POST http://127.0.0.1:8774/v2/a12951a2dcd44dd29151dd5ecfaf8f78/servers/1bba2f52-61a6-4c29-a3ec-7f848d8e76d6/action
2013-11-15 09:40:56,234 Request Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<Token omitted>'}
2013-11-15 09:40:56,235 Request Body: {"os-getConsoleOutput": {"length": 10}}
2013-11-15 09:40:56,389 Response Status: 200
2013-11-15 09:40:56,389 Nova request id: req-70a90d60-c6b3-41a8-ab4a-a2e44a5c281b
2013-11-15 09:40:56,390 Response Headers: {'content-length': '14', 'date': 'Fri, 15 Nov 2013 09:40:56 GMT', 'content-type': 'application/json', 'connection': 'close'}
2013-11-15 09:40:56,390 Response Body: {"output": ""}
}}}

Traceback (most recent call last):
  File "tempest/api/compute/servers/test_server_actions.py", line 281, in test_get_console_output
    self.wait_for(get_output)
  File "tempest/api/compute/base.py", line 133, in wait_for
    condition()
  File "tempest/api/compute/servers/test_server_actions.py", line 278, in get_output
    self.assertTrue(output, "Console output was empty.")
  File "/usr/lib/python2.7/unittest/case.py", line 420, in assertTrue
    raise self.failureException(msg)
AssertionError: Console output was empty.

http://logs.openstack.org/58/53258/3/check/check-tempest-devstack-vm-postgres-full/b3b9fb8/testr_results.html.gz

[Masayuki Igawa (igawa)]

This occurred in the type of XML:
tempest.api.compute.servers.test_server_actions.ServerActionsTestXML.test_get_console_output

http://logs.openstack.org/88/54688/6/check/check-tempest-devstack-vm-postgres-full/831ca45/testr_results.html.gz

[David Kranz (david-kranz)]

According to logstash, the first occurrence of this was at 2013-11-14T22:32:48.468Z