During a run of check-tempest-dsvm-postgres-full
2014-02-17 22:04:31.036 | 2014-02-17 22:03:41,733 Waiting for <Server: scenario-server--1813410115> to get to NotFound status. Currently in ACTIVE status
2014-02-17 22:04:31.036 | 2014-02-17 22:03:41,733 Sleeping for 1 seconds
2014-02-17 22:04:31.036 | 2014-02-17 22:03:42,734
2014-02-17 22:04:31.037 | REQ: curl -i 'http://127.0.0.1:8774/v2/3437c74f89904598a189851959e53779/servers/72361b22-1ea4-49ce-be61-003467145fe5' -X GET -H "X-Auth-Project-Id: TestVolumeBootPattern-1661167687" -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: MIISvQYJKoZIhvcNAQcCoIISrjCCEqoCAQExCTAHBgUrDgMCGjCCERMGCSqGSIb3DQEHAaCCEQQEghEAeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wMi0xN1QyMjowMzowOC4yMjQyMTgiLCAiZXhwaXJlcyI6ICIyMDE0LTAyLTE3VDIzOjAzOjA4WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogIlRlc3RWb2x1bWVCb290UGF0dGVybi0xNjYxMTY3Njg3LWRlc2MiLCAiZW5hYmxlZCI6IHRydWUsICJpZCI6ICIzNDM3Yzc0Zjg5OTA0NTk4YTE4OTg1MTk1OWU1Mzc3OSIsICJuYW1lIjogIlRlc3RWb2x1bWVCb290UGF0dGVybi0xNjYxMTY3Njg3In19LCAic2VydmljZUNhdGFsb2ciOiBbeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjIvMzQzN2M3NGY4OTkwNDU5OGExODk4NTE5NTllNTM3NzkiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjIvMzQzN2M3NGY4OTkwNDU5OGExODk4NTE5NTllNTM3NzkiLCAiaWQiOiAiZDg2ZWYzMjI1M2U0NDBkYTk0YjMxMmQxNjdkNTE3NTAiLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NC92Mi8zNDM3Yzc0Zjg5OTA0NTk4YTE4OTg1MTk1OWU1Mzc3OSJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjb21wdXRlIiwgIm5hbWUiOiAibm92YSJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3Ni92Mi8zNDM3Yzc0Zjg5OTA0NTk4YTE4OTg1MTk1OWU1Mzc3OSIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3Ni92Mi8zNDM3Yzc0Zjg5OTA0NTk4YTE4OTg1MTk1OWU1Mzc3OSIsICJpZCI6ICJkYWIxMWRhMGY0MWQ0OGRlYWQwNGE1YjQ0OWJiOTdiMCIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc2L3YyLzM0MzdjNzRmODk5MDQ1OThhMTg5ODUxOTU5ZTUzNzc5In1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogInZvbHVtZXYyIiwgIm5hbWUiOiAiY2luZGVydjIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjMiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzQvdjMiLCAiaWQiOiAiYzY2ZTU2ZjhlODE1NDZiNGE2ZTgzNWRkZjhkNTY0NTkiLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODc3NC92MyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjb21wdXRldjMiLCAibmFtZSI6ICJub3ZhdjMifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjMzMzMiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjMzMzMiLCAiaWQiOiAiZDUxMTgwMDM2YWQ3NGYzZGEyZWVmZDJmM2M0MmUzZWYiLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6MzMzMyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJzMyIsICJuYW1lIjogInMzIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo5MjkyIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo5MjkyIiwgImlkIjogImNkN2E2NGIyNDA2OTRkZTM4Y2FmMWE0NGQ5OTE2MGI1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjkyOTIifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaW1hZ2UiLCAibmFtZSI6ICJnbGFuY2UifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzcvIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc3LyIsICJpZCI6ICJjMGEyN2Q4ZTQ4NDc0OWE2Yjk1NTI3YWU5MTU0NWI1YiIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc3LyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJtZXRlcmluZyIsICJuYW1lIjogImNlaWxvbWV0ZXIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjgwMDAvdjEiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjgwMDAvdjEiLCAiaWQiOiAiYTAyMDYxNmQ3YzFiNDk2ZjkwMzAyMGM2OGVlMDU2ZDQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xMjcuMC4wLjE6ODAwMC92MSJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjbG91ZGZvcm1hdGlvbiIsICJuYW1lIjogImhlYXQtY2ZuIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc2L3YxLzM0MzdjNzRmODk5MDQ1OThhMTg5ODUxOTU5ZTUzNzc5IiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4Nzc2L3YxLzM0MzdjNzRmODk5MDQ1OThhMTg5ODUxOTU5ZTUzNzc5IiwgImlkIjogIjUzMmU2ZWQ4ZGEyMTQwMzE4N2Y0NmRjMDNmN2M4ODQ4IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzYvdjEvMzQzN2M3NGY4OTkwNDU5OGExODk4NTE5NTllNTM3NzkifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1lIiwgIm5hbWUiOiAiY2luZGVyIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4NzczL3NlcnZpY2VzL0FkbWluIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4NzczL3NlcnZpY2VzL0Nsb3VkIiwgImlkIjogImJmNDVlYWE4MjU1MzQ1OTRiY2MwOTc5Zjc0MjExZDU1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjg3NzMvc2VydmljZXMvQ2xvdWQifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiZWMyIiwgIm5hbWUiOiAiZWMyIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4MDA0L3YxLzM0MzdjNzRmODk5MDQ1OThhMTg5ODUxOTU5ZTUzNzc5IiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4MDA0L3YxLzM0MzdjNzRmODk5MDQ1OThhMTg5ODUxOTU5ZTUzNzc5IiwgImlkIjogIjk1Yjc4ZTVlYTBiODQzNzI5NjY3NTVkODliMzkwYzI0IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjgwMDQvdjEvMzQzN2M3NGY4OTkwNDU5OGExODk4NTE5NTllNTM3NzkifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAib3JjaGVzdHJhdGlvbiIsICJuYW1lIjogImhlYXQifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjgwODAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjgwODAvdjEvQVVUSF8zNDM3Yzc0Zjg5OTA0NTk4YTE4OTg1MTk1OWU1Mzc3OSIsICJpZCI6ICJkYWZlMTIxMmM5OTM0YjFjYjQ4OThmNmM0YzQ1YjQzMyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo4MDgwL3YxL0FVVEhfMzQzN2M3NGY4OTkwNDU5OGExODk4NTE5NTllNTM3NzkifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAib2JqZWN0LXN0b3JlIiwgIm5hbWUiOiAic3dpZnQifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjM1MzU3L3YyLjAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTI3LjAuMC4xOjUwMDAvdjIuMCIsICJpZCI6ICIyYmQyZjExYTg0YTk0YzNlYjQyODk3MDAxMjcwYzgxNiIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzEyNy4wLjAuMTo1MDAwL3YyLjAifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaWRlbnRpdHkiLCAibmFtZSI6ICJrZXlzdG9uZSJ9XSwgInVzZXIiOiB7InVzZXJuYW1lIjogIlRlc3RWb2x1bWVCb290UGF0dGVybi03NTcxNzczMzUiLCAicm9sZXNfbGlua3MiOiBbXSwgImlkIjogIjY1MTQzZWM5OWFjZTQyMDFiZmM2ZmEyMzg4YmMzYTM2IiwgInJvbGVzIjogW3sibmFtZSI6ICJfbWVtYmVyXyJ9LCB7Im5hbWUiOiAiTWVtYmVyIn1dLCAibmFtZSI6ICJUZXN0Vm9sdW1lQm9vdFBhdHRlcm4tNzU3MTc3MzM1In0sICJtZXRhZGF0YSI6IHsiaXNfYWRtaW4iOiAwLCAicm9sZXMiOiBbIjlmZTJmZjllZTQzODRiMTg5NGE5MDg3OGQzZTkyYmFiIiwgIjExNzRjYTc3YjZlYTQ5NjFhYmFkNTdhMTljMGIyZDBiIl19fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEAhIoiFqFpiKm5OacJofWJSXfIGXwV6jfMqCFIBD7+EtoCFJsefNGiHDUvt6PmruwSKH5o562LdRVy0jwZNcCohS+9LGLlJTq877O6HAA44xOwsKzU4XmSlqqzu1nxDnZM5IL0b9EFIYCGqf9AntO0-Pxy0GbSoz85qkJkouzIoykOnzc-+ZLJy5r08fNlqRcRF3MiNNKtV1C7IfNJYhAx9KsBlrlGgmuouBrKPIxkT9XF4A69e+QoClk2iF-F3ChBOVQwKzNQxFWtWvAuBtanDYdr33q8d1RhWwUR1K652pAUP4dZnyvRNvcgz3D7g96QNmklScAofr71V+9hMnJTBQ=="
2014-02-17 22:04:31.037 |
2014-02-17 22:04:31.037 | 2014-02-17 22:03:42,859 "GET /v2/3437c74f89904598a189851959e53779/servers/72361b22-1ea4-49ce-be61-003467145fe5 HTTP/1.1" 200 1854
2014-02-17 22:04:31.037 | 2014-02-17 22:03:42,860 RESP: [200] CaseInsensitiveDict({'date': 'Mon, 17 Feb 2014 22:03:42 GMT', 'content-length': '1854', 'content-type': 'application/json', 'x-compute-request-id': 'req-e7b6a44b-2a86-4873-bce5-b7dc5a112ea8'})
2014-02-17 22:04:31.037 | RESP BODY: {"server": {"status": "ERROR", "updated": "2014-02-17T22:03:41Z", "hostId": "870084b710a66abc3474d13baedc0694ff8ca8e740d7ddf5fd98b51d", "addresses": {"private": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:af:91:07", "version": 4, "addr": "10.1.0.95", "OS-EXT-IPS:type": "fixed"}, {"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:af:91:07", "version": 4, "addr": "172.24.4.19", "OS-EXT-IPS:type": "floating"}]}, "links": [{"href": "http://127.0.0.1:8774/v2/3437c74f89904598a189851959e53779/servers/72361b22-1ea4-49ce-be61-003467145fe5", "rel": "self"}, {"href": "http://127.0.0.1:8774/3437c74f89904598a189851959e53779/servers/72361b22-1ea4-49ce-be61-003467145fe5", "rel": "bookmark"}], "key_name": "scenario-keypair--1126359914", "image": {"id": "ea50123c-2f7e-445b-a5c7-3d86365237a9", "links": [{"href": "http://127.0.0.1:8774/3437c74f89904598a189851959e53779/images/ea50123c-2f7e-445b-a5c7-3d86365237a9", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "error", "OS-SRV-USG:launched_at": "2014-02-17T22:03:20.000000", "flavor": {"id": "42", "links": [{"href": "http://127.0.0.1:8774/3437c74f89904598a189851959e53779/flavors/42", "rel": "bookmark"}]}, "id": "72361b22-1ea4-49ce-be61-003467145fe5", "security_groups": [{"name": "default"}], "OS-SRV-USG:terminated_at": null, "OS-EXT-AZ:availability_zone": "nova", "user_id": "65143ec99ace4201bfc6fa2388bc3a36", "name": "scenario-server--1813410115", "created": "2014-02-17T22:03:12Z", "tenant_id": "3437c74f89904598a189851959e53779", "OS-DCF:diskConfig": "MANUAL", "os-extended-volumes:volumes_attached": [{"id": "3488e37a-9921-435c-82cb-624ee27b45a3"}], "accessIPv4": "", "accessIPv6": "", "fault": {"message": "Failed to terminate instance: Error unfiltering instance.", "code": 400, "created": "2014-02-17T22:03:41Z"}, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}}
2014-02-17 22:04:31.037 | }}}
2014-02-17 22:04:31.038 |
2014-02-17 22:04:31.038 | Traceback (most recent call last):
2014-02-17 22:04:31.038 | File "tempest/test.py", line 101, in wrapper
2014-02-17 22:04:31.038 | return f(self, *func_args, **func_kwargs)
2014-02-17 22:04:31.038 | File "tempest/scenario/test_volume_boot_pattern.py", line 146, in test_volume_boot_pattern
2014-02-17 22:04:31.038 | self._delete_server(instance_1st)
2014-02-17 22:04:31.038 | File "tempest/scenario/test_volume_boot_pattern.py", line 124, in _delete_server
2014-02-17 22:04:31.038 | self.delete_timeout(self.compute_client.servers, server.id)
2014-02-17 22:04:31.038 | File "tempest/scenario/manager.py", line 367, in delete_timeout
2014-02-17 22:04:31.038 | not_found_exception=not_found_exception)
2014-02-17 22:04:31.038 | File "tempest/scenario/manager.py", line 411, in _status_timeout
2014-02-17 22:04:31.039 | CONF.compute.build_interval):
2014-02-17 22:04:31.039 | File "tempest/test.py", line 575, in call_until_true
2014-02-17 22:04:31.039 | if func():
2014-02-17 22:04:31.039 | File "tempest/scenario/manager.py", line 402, in check_status
2014-02-17 22:04:31.039 | server_id=thing_id)
2014-02-17 22:04:31.039 | BuildErrorException: Server 72361b22-1ea4-49ce-be61-003467145fe5 failed to build and is in ERROR status
2014-02-17 22:04:31.039 | Details: <Server: scenario-server--1813410115> failed to get to expected status. In ERROR state.
2014-02-17 22:04:31.039 |
2014-02-17 22:04:31.039 |
2014-02-17 22:04:31.039 | ======================================================================
2014-02-17 22:04:31.039 | FAIL: tearDownClass (tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern)
2014-02-17 22:04:31.039 | tearDownClass (tempest.scenario.test_volume_boot_pattern.TestVolumeBootPattern)
2014-02-17 22:04:31.040 | ----------------------------------------------------------------------
2014-02-17 22:04:31.040 | _StringException: Traceback (most recent call last):
2014-02-17 22:04:31.040 | File "tempest/scenario/manager.py", line 294, in tearDownClass
2014-02-17 22:04:31.040 | thing.delete()
2014-02-17 22:04:31.040 | File "/opt/stack/new/python-cinderclient/cinderclient/v1/volumes.py", line 35, in delete
2014-02-17 22:04:31.040 | self.manager.delete(self)
2014-02-17 22:04:31.040 | File "/opt/stack/new/python-cinderclient/cinderclient/v1/volumes.py", line 228, in delete
2014-02-17 22:04:31.040 | self._delete("/volumes/%s" % base.getid(volume))
2014-02-17 22:04:31.040 | File "/opt/stack/new/python-cinderclient/cinderclient/base.py", line 162, in _delete
2014-02-17 22:04:31.040 | resp, body = self.api.client.delete(url)
2014-02-17 22:04:31.040 | File "/opt/stack/new/python-cinderclient/cinderclient/client.py", line 215, in delete
2014-02-17 22:04:31.040 | return self._cs_request(url, 'DELETE', **kwargs)
2014-02-17 22:04:31.041 | File "/opt/stack/new/python-cinderclient/cinderclient/client.py", line 173, in _cs_request
2014-02-17 22:04:31.041 | **kwargs)
2014-02-17 22:04:31.041 | File "/opt/stack/new/python-cinderclient/cinderclient/client.py", line 156, in request
2014-02-17 22:04:31.041 | raise exceptions.from_response(resp, body)
2014-02-17 22:04:31.041 | BadRequest: Invalid volume: Volume status must be available or error, but current status is: in-use (HTTP 400) (Request-ID: req-5130d2d0-ae88-4267-b200-31cd5adf6297)
I had decided that tonight was the night I was going to fix this on the Cinder side, but alas I'm stuck.
The problem here is that we run into the odd case with nova booting an instance from a volume, compute API starts up the process, grabs the volume and makes the attach (so now the volume status is "in-use"). Then while it's booting something goes very wrong in nova (as can be seen by the multitudes of traces in the n-api logs) so we punch out and call tearDown.
The problem is we never cleaned up the volume-status, so it's still listed as "in-use" but the tearDown is a neat little loop on "thing.delete" so it's not accounting for things like removing attachments etc.
I was thinking doCleanup but realized that won't work because it's called "after" tearDown which is what fails. So the only thing I can think of that's practical as a hack is to add a "if isinstance Volume" in the delete loop and change the state using the admin api to available so that teardown can do it's thing.