Intermittent failure in test_cinder_extra_specs_list

[Thomas Herve]

Just got that here: http://logs.openstack.org/35/98935/22/gate/gate-tempest-dsvm-postgres-full/27809d0

2014-07-18 05:40:39.381 | tempest.cli.simple_read_only.test_cinder.SimpleReadOnlyCinderClientTest.test_cinder_extra_specs_list
2014-07-18 05:40:39.381 | ----------------------------------------------------------------------------------------------------
2014-07-18 05:40:39.381 |
2014-07-18 05:40:39.381 | Captured traceback:
2014-07-18 05:40:39.381 | ~~~~~~~~~~~~~~~~~~~
2014-07-18 05:40:39.381 | Traceback (most recent call last):
2014-07-18 05:40:39.381 | File "tempest/cli/simple_read_only/test_cinder.py", line 59, in test_cinder_extra_specs_list
2014-07-18 05:40:39.382 | extra_specs_list = self.parser.listing(self.cinder('extra-specs-list'))
2014-07-18 05:40:39.382 | File "tempest/cli/__init__.py", line 84, in cinder
2014-07-18 05:40:39.382 | 'cinder', action, flags, params, admin, fail_ok)
2014-07-18 05:40:39.382 | File "tempest/cli/__init__.py", line 116, in cmd_with_auth
2014-07-18 05:40:39.382 | return self.cmd(cmd, action, flags, params, fail_ok, merge_stderr)
2014-07-18 05:40:39.382 | File "tempest/cli/__init__.py", line 136, in cmd
2014-07-18 05:40:39.382 | stderr=result_err)
2014-07-18 05:40:39.382 | CommandFailed: Command '['/usr/local/bin/cinder', '--os-username', 'admin', '--os-tenant-name', 'admin', '--os-password', 'secretadmin', '--os-auth-url', 'http://127.0.0.1:5000/v2.0/', '--endpoint-type', 'publicURL', 'extra-specs-list']' returned non-zero exit status 1
2014-07-18 05:40:39.382 |
2014-07-18 05:40:39.382 |
2014-07-18 05:40:39.382 | Captured pythonlogging:
2014-07-18 05:40:39.382 | ~~~~~~~~~~~~~~~~~~~~~~~
2014-07-18 05:40:39.383 | 2014-07-18 05:33:35,636 22216 INFO [tempest.cli] running: '/usr/local/bin/cinder --os-username admin --os-tenant-name admin --os-password secretadmin --os-auth-url http://127.0.0.1:5000/v2.0/ --endpoint-type publicURL extra-specs-list '

From cinder API logs:

2014-07-18 05:33:36.949 19489 DEBUG routes.middleware [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] Matched GET /607ce2c91a4344e8a32285ff7c4c7ccf/types/580b0a0b-1ba9-4960-b3f1-3cba8292fd6e/extra_specs __call__ /usr/local/lib/python2.7/dist-packages/routes/middleware.py:100
2014-07-18 05:33:36.949 19489 DEBUG routes.middleware [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] Route path: '/{project_id}/types/:type_id/extra_specs', defaults: {'action': u'index', 'controller': <cinder.api.openstack.wsgi.Resource object at 0x7fee51baed10>} __call__ /usr/local/lib/python2.7/dist-packages/routes/middleware.py:102
2014-07-18 05:33:36.949 19489 DEBUG routes.middleware [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] Match dict: {'action': u'index', 'controller': <cinder.api.openstack.wsgi.Resource object at 0x7fee51baed10>, 'project_id': u'607ce2c91a4344e8a32285ff7c4c7ccf', 'type_id': u'580b0a0b-1ba9-4960-b3f1-3cba8292fd6e'} __call__ /usr/local/lib/python2.7/dist-packages/routes/middleware.py:103
2014-07-18 05:33:36.950 19489 INFO cinder.api.openstack.wsgi [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] GET http://127.0.0.1:8776/v1/607ce2c91a4344e8a32285ff7c4c7ccf/types/580b0a0b-1ba9-4960-b3f1-3cba8292fd6e/extra_specs
2014-07-18 05:33:36.950 19489 DEBUG cinder.api.openstack.wsgi [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] Empty body provided in request get_body /opt/stack/new/cinder/cinder/api/openstack/wsgi.py:788
2014-07-18 05:33:36.962 19489 INFO cinder.api.openstack.wsgi [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] HTTP exception thrown: Volume type 580b0a0b-1ba9-4960-b3f1-3cba8292fd6e could not be found.
2014-07-18 05:33:36.963 19489 INFO cinder.api.openstack.wsgi [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] http://127.0.0.1:8776/v1/607ce2c91a4344e8a32285ff7c4c7ccf/types/580b0a0b-1ba9-4960-b3f1-3cba8292fd6e/extra_specs returned with HTTP 404
2014-07-18 05:33:36.964 19489 INFO eventlet.wsgi.server [req-51894d35-4fe0-44a0-af01-f00d7dad2140 4203a17382cb414996a00608a9f53854 607ce2c91a4344e8a32285ff7c4c7ccf - - -] 127.0.0.1 - - [18/Jul/2014 05:33:36] "GET /v1/607ce2c91a4344e8a32285ff7c4c7ccf/types/580b0a0b-1ba9-4960-b3f1-3cba8292fd6e/extra_specs HTTP/1.1" 404 375 0.170924

It seems there is a race condition because a volume type has disapeared during the test. The test that seems to match this is test_volume_type_encryption_create_get_delete although other tests creating and deleting volume types can have the same effect. Not sure if it's a bug in cinder or a problem with the tests.

[Thomas Herve (therve)]

Looking at the code more I understand a bit what's going on. cinder client first do a list of types and then makes a request on each of the types. Arguably it should handle types disappearing between the 2 operations, as there is a race condition.

[Matt Riedemann (mriedem)]

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

Looks like it started on 7/16.

This is the only change to the client on 7/16:

https://github.com/openstack/python-cinderclient/commit/0c4010e7fbc9939905e8647afbe1358c384dc658

Which doesn't look related.

Not seeing anything interesting in cinder commits on 7/16.

Not seeing anything interesting in tempest commits on 7/16 either.

[Jordan Pittier (jordan-pittier)]

Thomas is right.

If you look at http://logs.openstack.org/23/104123/6/check/check-tempest-dsvm-full/e675a9c/logs/screen-c-api.txt.gz#_2014-08-03_21_13_29_197 volume type 0cb5be8f-ff7c-48d4-b168-fb25c7185e4d is deleted. Then the same volume type is GETed : http://logs.openstack.org/23/104123/6/check/check-tempest-dsvm-full/e675a9c/logs/screen-c-api.txt.gz#_2014-08-03_21_13_29_343 The test test_volume_type_encryption_create_get seems to run concurrently.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/111967

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/111967
Committed: https://git.openstack.org/cgit/openstack/python-cinderclient/commit/?id=6565e275fdba7edc0a63330d0be898923f0f5f20
Submitter: Jenkins
Branch: master

commit 6565e275fdba7edc0a63330d0be898923f0f5f20
Author: JordanP <email address hidden>
Date: Tue Aug 5 11:28:09 2014 +0200

    Avoid extra lookups in extra-specs-list

    extra-specs-list used to use the extra-specs cinder extension
    to get information on volume type extra specs. This information
    is publicly available through the volume-type API [1] thus we
    can avoid the extra-lookups of querying the extra-specs extension.

    As the extra-spec info is publicly available, remove the part of
    the docstring of cinder extra-specs-list that says 'admin only'.

    [1] http://docs.openstack.org/api/openstack-block-storage/2.0/content/GET_getVolumeTypes__v2__tenant_id__types_Volume_Types.html

    Change-Id: I9a8256a044511ac5233d8170fc57118ccaa1e217
    Closes-Bug: 1343876

[David Kranz (david-kranz)]

I don't see this issue in logstash so I presume it was just a cinder client issue.