Gate failures with 'the resource could not be found'

[Armando Migliaccio]

There have been spurious failures happening in the gate. The most prominent one is:

ft1.186: tempest.api.compute.admin.test_servers.ServersAdminTestJSON.test_list_servers_by_admin_with_all_tenants[id-9f5579ae-19b4-4985-a091-2a5d56106580]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2015-08-24 22:55:50,083 32355 INFO [tempest_lib.common.rest_client] Request (ServersAdminTestJSON:test_list_servers_by_admin_with_all_tenants): 404 GET http://127.0.0.1:8774/v2/fb99c79318b54e668713b25afc52f81a/servers/detail?all_tenants= 0.834s
2015-08-24 22:55:50,083 32355 DEBUG [tempest_lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
        Body: None
    Response - Headers: {'content-length': '78', 'date': 'Mon, 24 Aug 2015 22:55:50 GMT', 'connection': 'close', 'content-type': 'application/json; charset=UTF-8', 'x-compute-request-id': 'req-387b21a9-4ada-48ee-89ed-9acfe5274ef7', 'status': '404'}
        Body: {"itemNotFound": {"message": "The resource could not be found.", "code": 404}}
}}}

Traceback (most recent call last):
  File "tempest/api/compute/admin/test_servers.py", line 81, in test_list_servers_by_admin_with_all_tenants
    body = self.client.list_servers(detail=True, **params)
  File "tempest/services/compute/json/servers_client.py", line 159, in list_servers
    resp, body = self.get(url)
  File "/opt/stack/new/tempest/.tox/full/local/lib/python2.7/site-packages/tempest_lib/common/rest_client.py", line 271, in get
    return self.request('GET', url, extra_headers, headers)
  File "/opt/stack/new/tempest/.tox/full/local/lib/python2.7/site-packages/tempest_lib/common/rest_client.py", line 643, in request
    resp, resp_body)
  File "/opt/stack/new/tempest/.tox/full/local/lib/python2.7/site-packages/tempest_lib/common/rest_client.py", line 695, in _error_checker
    raise exceptions.NotFound(resp_body)
tempest_lib.exceptions.NotFound: Object not found
Details: {u'code': 404, u'message': u'The resource could not be found.'}

but there are other similar failure modes. This seems to be related to bug #1269284

The logstash query:

message:"tempest_lib.exceptions.NotFound: Object not found" AND build_name:"gate-tempest-dsvm-neutron-full"

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

[Ryan Moats (rmoats)]

a similar signature has appeared in the check pipeline:
ft1.774: tempest.api.compute.test_tenant_networks.NetworksTestJSON.test_list_show_tenant_networks[id-edfea98e-bbe3-4c7a-9739-87b986baff26]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2015-08-25 13:33:13,174 13818 INFO [tempest_lib.common.rest_client] Request (NetworksTestJSON:test_list_show_tenant_networks): 200 POST http://127.0.0.1:5000/v2.0/tokens
2015-08-25 13:33:13,175 13818 DEBUG [tempest_lib.common.rest_client] Request - Headers: {}
        Body: None
    Response - Headers: {'x-openstack-request-id': 'req-2a00725c-ebe2-4b74-95e3-152d03ad7f04', 'content-type': 'application/json', 'connection': 'close', 'date': 'Tue, 25 Aug 2015 13:33:13 GMT', 'vary': 'X-Auth-Token', 'content-length': '4108', 'server': 'Apache/2.4.7 (Ubuntu)', 'status': '200'}
        Body: None
2015-08-25 13:33:14,140 13818 INFO [tempest_lib.common.rest_client] Request (NetworksTestJSON:test_list_show_tenant_networks): 200 GET http://127.0.0.1:8774/v2/8bfb517768e84e389e23ac66d3fcee01/os-tenant-networks 0.964s
2015-08-25 13:33:14,140 13818 DEBUG [tempest_lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'X-Auth-Token': '<omitted>', 'Content-Type': 'application/json'}
        Body: None
    Response - Headers: {'x-compute-request-id': 'req-f62eaab2-c79e-4e70-87ed-ad4e4bb387e6', 'content-type': 'application/json', 'connection': 'close', 'date': 'Tue, 25 Aug 2015 13:33:14 GMT', 'status': '200', 'content-length': '174', 'content-location': 'http://127.0.0.1:8774/v2/8bfb517768e84e389e23ac66d3fcee01/os-tenant-networks'}
        Body: {"networks": [{"cidr": "None", "id": "299caaf9-c07a-443f-bd1a-5f4965152e8d", "label": "public"}, {"cidr": "None", "id": "8d374c24-891b-40ad-9450-98fe640622a9", "label": ""}]}
2015-08-25 13:33:15,168 13818 INFO [tempest_lib.common.rest_client] Request (NetworksTestJSON:test_list_show_tenant_networks): 200 GET http://127.0.0.1:8774/v2/8bfb517768e84e389e23ac66d3fcee01/os-tenant-networks/299caaf9-c07a-443f-bd1a-5f4965152e8d 1.026s
2015-08-25 13:33:15,168 13818 DEBUG [tempest_lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'X-Auth-Token': '<omitted>', 'Content-Type': 'application/json'}
        Body: None
    Response - Headers: {'x-compute-request-id': 'req-170c3890-beb2-4dfe-a4d6-6d30a0f2b732', 'content-type': 'application/json', 'connection': 'close', 'date': 'Tue, 25 Aug 2015 13:33:15 GMT', 'status': '200', 'content-length': '94', 'content-location': 'http://127.0.0.1:8774/v2/8bfb517768e84e389e23ac66d3fcee01/os-tenant-networks/299caaf9-c07a-443f-bd1a-5f4965152e8d'}
        Body: {"network": {"cidr": "None", "id": "299caaf9-c07a-443f-bd1a-5f4965152e8d", "label": "public"}}
2015-08-25 13:33:16,100 13818 INFO [tempest_lib.common.rest_client] Request (NetworksTestJSON:test_list_show_tenant_networks): 404 GET http://127.0.0.1:8774/v2/8bfb517768e84e389e23ac66d3fcee01/os-tenant-networks/8d374c24-891b-40ad-9450-98fe640622a9 0.930s
2015-08-25 13:33:16,100 13818 DEBUG [tempest_lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'X-Auth-Token': '<omitted>', 'Content-Type'...

[Salvatore Orlando (salvatore-orlando)]

I seem to have seen this already and have probably a clue.
Assigning to myself for triaging.

[Armando Migliaccio (armando-migliaccio)]

Nice one!

[Salvatore Orlando (salvatore-orlando)]

Actually the root cause for the failure I did observe was different.

This appears to be a genuine nova error where a server is deleted by another test while the list operation is in progress. It is also interesting that nova fails with a 404 here - this appears to really be a bug.

In support of my thesis I can provide examples where the same failure trace occurs with[1], [2] and without [3], [4] neutron

Also, during a server list operation there is no interaction between nova and neutron.

[1] http://logs.openstack.org/04/215604/15/gate/gate-tempest-dsvm-neutron-full/37eb7aa/console.html
[2] http://logs.openstack.org/04/215604/15/gate/gate-tempest-dsvm-neutron-full/37eb7aa/logs/screen-n-api.txt.gz#_2015-08-26_15_32_57_698
[3] http://logs.openstack.org/67/214067/2/gate/gate-tempest-dsvm-full/1b348a3/console.html
[4] http://logs.openstack.org/67/214067/2/gate/gate-tempest-dsvm-full/1b348a3/logs/screen-n-api.txt.gz#_2015-08-25_14_50_13_779

[Salvatore Orlando (salvatore-orlando)]

I've therefore dared adding nova to the list of affected projects. I will wait triaging on the nova side before removing neutron.

[Armando Migliaccio (armando-migliaccio)]

I support you morally.

[Salvatore Orlando (salvatore-orlando)]

Another tests removes it: http://logs.openstack.org/04/215604/15/gate/gate-tempest-dsvm-neutron-full/37eb7aa/logs/screen-n-api.txt.gz#_2015-08-26_15_32_55_908

Therefore there are two issues here in my opinion:

1) Nova should never error with a 404 in this case during instance list
2) The tempest test is poorly designed as it assumes that during test execution instances created by other tests will not be deleted.

The latter issue is common design problem to several compute tests - as there is a similar situation in a different bug: https://bugs.launchpad.net/tempest/+bug/1468523

[Salvatore Orlando (salvatore-orlando)]

My apologies the 2nd issue does not apply to this bug. Therefore I won't add tempest to affected projects.

[Kyle Mestery (mestery)]

No hits in the log stash query since 9-3, wondering if the priority should still be high.

[Kyle Mestery (mestery)]

9 hits in the last 7 days, moving priority down to medium.

[Armando Migliaccio (armando-migliaccio)]

This doesn't show up in the gate queue for a while now, other occurrences might be self inflicted. Marking Incomplete until this starts biting again.

[Launchpad Janitor (janitor)]

[Expired for neutron because there has been no activity for 60 days.]