tempest.api.compute.servers.test_server_rescue.ServerRescueTestXML.test_rescue_unrescue_instance[gate,smoke] failed

[Robert Collins]

http://logs.openstack.org/20/62520/1/gate/gate-tempest-dsvm-postgres-full/f3a9033/

2013-12-18 05:47:02,936 Request: GET http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd
2013-12-18 05:47:02,936 Request Headers: {'Content-Type': 'application/xml', 'Accept': 'application/xml', 'X-Auth-Token': '<Token omitted>'}
2013-12-18 05:47:03,077 Response Status: 200
2013-12-18 05:47:03,077 Nova request id: req-1456f54f-7299-49fc-b3f5-66455360eb67
2013-12-18 05:47:03,077 Response Headers: {'content-length': '2167', 'content-location': u'http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd', 'date': 'Wed, 18 Dec 2013 05:47:03 GMT', 'content-type': 'application/xml', 'connection': 'close'}
2013-12-18 05:47:03,078 Response Body: <?xml version='1.0' encoding='UTF-8'?>
<server xmlns:OS-DCF="http://docs.openstack.org/compute/ext/disk_config/api/v1.1" xmlns:os-extended-volumes="http://docs.openstack.org/compute/ext/extended_volumes/api/v1.1" xmlns:OS-EXT-IPS="http://docs.openstack.org/compute/ext/extended_ips/api/v1.1" xmlns:atom="http://www.w3.org/2005/Atom" xmlns:OS-EXT-IPS-MAC="http://docs.openstack.org/compute/ext/extended_ips_mac/api/v1.1" xmlns:OS-SRV-USG="http://docs.openstack.org/compute/ext/server_usage/api/v1.1" xmlns:OS-EXT-STS="http://docs.openstack.org/compute/ext/extended_status/api/v1.1" xmlns:OS-EXT-AZ="http://docs.openstack.org/compute/ext/extended_availability_zone/api/v2" xmlns="http://docs.openstack.org/compute/api/v1.1" status="SHUTOFF" updated="2013-12-18T05:43:58Z" hostId="eeb1a42b0840fab07838a1e353499b1a9c944d2197844cf6814eddad" name="ServerRescueTestXML-instance-tempest-189395512" created="2013-12-18T05:43:13Z" userId="a2733398afa247febff6e65b90712351" tenantId="0c07b2e10c454d3fa80773627d2dea67" accessIPv4="" accessIPv6="" id="b7e78cb2-a215-4909-8fee-ed0f9cdd11cd" key_name="None" config_drive="" OS-SRV-USG:terminated_at="None" OS-SRV-USG:launched_at="2013-12-18 05:43:47.580612" OS-EXT-STS:vm_state="stopped" OS-EXT-STS:task_state="None" OS-EXT-STS:power_state="4" OS-EXT-AZ:availability_zone="nova" OS-DCF:diskConfig="MANUAL"><image id="31de6d39-e307-4c81-9959-413efc2e5fa7"><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/images/31de6d39-e307-4c81-9959-413efc2e5fa7" rel="bookmark"/></image><flavor id="42"><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/flavors/42" rel="bookmark"/></flavor><metadata/><addresses><network id="private"><ip OS-EXT-IPS:type="fixed" version="4" addr="10.1.0.64" OS-EXT-IPS-MAC:mac_addr="fa:16:3e:67:09:e2"/></network></addresses><atom:link href="http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd" rel="self"/><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a2
2013-12-18 05:47:03,078 Large body (2167) md5 summary: d0d26dbee429d4a58d9073037362e4fa
2013-12-18 05:47:04,080 Request: GET http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd
2013-12-18 05:47:04,080 Request Headers: {'Content-Type': 'application/xml', 'Accept': 'application/xml', 'X-Auth-Token': '<Token omitted>'}
2013-12-18 05:47:04,158 Response Status: 200
2013-12-18 05:47:04,158 Nova request id: req-0a3509d6-9c61-439f-9be5-056de21d60ef
2013-12-18 05:47:04,158 Response Headers: {'content-length': '2167', 'content-location': u'http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd', 'date': 'Wed, 18 Dec 2013 05:47:04 GMT', 'content-type': 'application/xml', 'connection': 'close'}
2013-12-18 05:47:04,159 Response Body: <?xml version='1.0' encoding='UTF-8'?>
<server xmlns:OS-DCF="http://docs.openstack.org/compute/ext/disk_config/api/v1.1" xmlns:os-extended-volumes="http://docs.openstack.org/compute/ext/extended_volumes/api/v1.1" xmlns:OS-EXT-IPS="http://docs.openstack.org/compute/ext/extended_ips/api/v1.1" xmlns:atom="http://www.w3.org/2005/Atom" xmlns:OS-EXT-IPS-MAC="http://docs.openstack.org/compute/ext/extended_ips_mac/api/v1.1" xmlns:OS-SRV-USG="http://docs.openstack.org/compute/ext/server_usage/api/v1.1" xmlns:OS-EXT-STS="http://docs.openstack.org/compute/ext/extended_status/api/v1.1" xmlns:OS-EXT-AZ="http://docs.openstack.org/compute/ext/extended_availability_zone/api/v2" xmlns="http://docs.openstack.org/compute/api/v1.1" status="SHUTOFF" updated="2013-12-18T05:43:58Z" hostId="eeb1a42b0840fab07838a1e353499b1a9c944d2197844cf6814eddad" name="ServerRescueTestXML-instance-tempest-189395512" created="2013-12-18T05:43:13Z" userId="a2733398afa247febff6e65b90712351" tenantId="0c07b2e10c454d3fa80773627d2dea67" accessIPv4="" accessIPv6="" id="b7e78cb2-a215-4909-8fee-ed0f9cdd11cd" key_name="None" config_drive="" OS-SRV-USG:terminated_at="None" OS-SRV-USG:launched_at="2013-12-18 05:43:47.580612" OS-EXT-STS:vm_state="stopped" OS-EXT-STS:task_state="None" OS-EXT-STS:power_state="4" OS-EXT-AZ:availability_zone="nova" OS-DCF:diskConfig="MANUAL"><image id="31de6d39-e307-4c81-9959-413efc2e5fa7"><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/images/31de6d39-e307-4c81-9959-413efc2e5fa7" rel="bookmark"/></image><flavor id="42"><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/flavors/42" rel="bookmark"/></flavor><metadata/><addresses><network id="private"><ip OS-EXT-IPS:type="fixed" version="4" addr="10.1.0.64" OS-EXT-IPS-MAC:mac_addr="fa:16:3e:67:09:e2"/></network></addresses><atom:link href="http://127.0.0.1:8774/v2/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a215-4909-8fee-ed0f9cdd11cd" rel="self"/><atom:link href="http://127.0.0.1:8774/0c07b2e10c454d3fa80773627d2dea67/servers/b7e78cb2-a2
2013-12-18 05:47:04,159 Large body (2167) md5 summary: d0d26dbee429d4a58d9073037362e4fa
}}}

Traceback (most recent call last):
  File "tempest/api/compute/servers/test_server_rescue.py", line 119, in test_rescue_unrescue_instance
    self.servers_client.wait_for_server_status(self.server_id, 'ACTIVE')
  File "tempest/services/compute/xml/servers_client.py", line 371, in wait_for_server_status
    raise_on_error=raise_on_error)
  File "tempest/common/waiters.py", line 88, in wait_for_server_status
    raise exceptions.TimeoutException(message)
TimeoutException: Request timed out
Details: Server b7e78cb2-a215-4909-8fee-ed0f9cdd11cd failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: SHUTOFF. Current task state: None.

[Andrea Frittoli (andrea-frittoli)]

It seems related to bug 1260644

[Joe Gordon (jogo)]

libvirt looks unhappy http://logs.openstack.org/20/62520/1/gate/gate-tempest-dsvm-postgres-full/f3a9033/logs/screen-n-cpu.txt.gz?level=TRACE#_2013-12-18_05_46_18_721

[Matt Riedemann (mriedem)]

This isn't postgresql only, I hit it here also:

http://logs.openstack.org/21/62621/2/check/check-tempest-dsvm-full/30d9ded/console.html

[Matt Riedemann (mriedem)]

Is this still a problem? If so, we need to get a fingerprint for logstash.

[Matt Riedemann (mriedem)]

In the linked logs, json was ok but xml failed, so definitely a timing issue.

However, not seeing any hits in the gate in the last 7 days on this:

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

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

This shows up a lot though:

message:"libvirtError: Unable to write to monitor: Broken pipe" AND filename:"logs/screen-n-cpu.txt" AND build_queue:"gate"

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwibGlidmlydEVycm9yOiBVbmFibGUgdG8gd3JpdGUgdG8gbW9uaXRvcjogQnJva2VuIHBpcGVcIiBBTkQgZmlsZW5hbWU6XCJsb2dzL3NjcmVlbi1uLWNwdS50eHRcIiBBTkQgYnVpbGRfcXVldWU6XCJnYXRlXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzOTA3NzM3NDUzNDF9

[Joe Gordon (jogo)]

no hits for this anymore