Error observed on duplicate type creation

[satyadev svn]

ssatya@devstack:/etc/cinder$ cinder type-list
+--------------------------------------+--------+
| ID | Name |
+--------------------------------------+--------+
| 086c6dc2-b2ab-48cf-ab73-2d56372d4704 | sliver |
| 13b20d84-6e32-45b2-a122-bac2fcd00e44 | gold |
| 18ad8cf2-8195-4a3f-9bc1-b647415ce206 | thin |
| eaccb2d1-ac25-4f1d-b76e-a06cf6b6c56d | thick |
+--------------------------------------+--------+
ssatya@devstack:/etc/cinder$ cinder type-create sliver
ERROR: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-932eea44-fe00-4083-b053-b6004e128d40)

cinder-api logs :

2014-03-11 12:26:32.281 INFO eventlet.wsgi.server [-] (21026) accepted ('10.113.161.215', 31467)
2014-03-11 12:26:32.298 DEBUG keystoneclient.middleware.auth_token [-] Authenticating user token from (pid=21026) __call__ /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:583
2014-03-11 12:26:32.298 DEBUG keystoneclient.middleware.auth_token [-] Removing headers from request environment: X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role from (pid=21026) _remove_auth_headers /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:642
2014-03-11 12:26:33.432 DEBUG keystoneclient.middleware.auth_token [-] Storing 13223be76493a4e211c5a3bec6574496 token in memcache from (pid=21026) _cache_put /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:1158
2014-03-11 12:26:33.433 DEBUG keystoneclient.middleware.auth_token [-] Received request from user: 8a674f2790ae4032b87bc3a3d6276614 with project_id : a593ac3af6d74be3b6178ec5ea33bc7e and roles: admin from (pid=21026) _build_user_headers /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:946
2014-03-11 12:26:33.435 DEBUG routes.middleware [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] Matched POST /a593ac3af6d74be3b6178ec5ea33bc7e/types from (pid=21026) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2014-03-11 12:26:33.435 DEBUG routes.middleware [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] Route path: '/{project_id}/types', defaults: {'action': u'create', 'controller': <cinder.api.openstack.wsgi.Resource object at 0x50066d0>} from (pid=21026) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2014-03-11 12:26:33.436 DEBUG routes.middleware [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] Match dict: {'action': u'create', 'controller': <cinder.api.openstack.wsgi.Resource object at 0x50066d0>, 'project_id': u'a593ac3af6d74be3b6178ec5ea33bc7e'} from (pid=21026) __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2014-03-11 12:26:33.437 INFO cinder.api.openstack.wsgi [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] POST http://10.112.185.199:8776/v2/a593ac3af6d74be3b6178ec5ea33bc7e/types
2014-03-11 12:26:33.451 INFO cinder.api.openstack.wsgi [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] HTTP exception thrown: Volume Type thin already exists.
2014-03-11 12:26:33.452 INFO cinder.api.openstack.wsgi [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] http://10.112.185.199:8776/v2/a593ac3af6d74be3b6178ec5ea33bc7e/types returned with HTTP 409
2014-03-11 12:26:33.452 ERROR cinder.api.middleware.fault [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] Caught error: Circular reference detected
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/api/middleware/fault.py", line 75, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return req.get_response(self.application)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault application, catch_exc_info=False)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 596, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return self.app(env, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault response = self.app(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 1178, in __call__
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault self.wrapped_exc.body = serializer.serialize(fault_data)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 324, in serialize
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return self.dispatch(data, action=action)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 190, in dispatch
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return action_method(*args, **kwargs)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 334, in default
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return jsonutils.dumps(data)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/opt/stack/cinder/cinder/openstack/common/jsonutils.py", line 164, in dumps
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return json.dumps(value, default=default, **kwargs)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/json/__init__.py", line 238, in dumps
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault **kw).encode(obj)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/json/encoder.py", line 201, in encode
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault chunks = self.iterencode(o, _one_shot=True)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/json/encoder.py", line 264, in iterencode
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault return _iterencode(o, 0)
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault ValueError: Circular reference detected
2014-03-11 12:26:33.452 TRACE cinder.api.middleware.fault
2014-03-11 12:26:33.454 INFO cinder.api.middleware.fault [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] http://10.112.185.199:8776/v2/a593ac3af6d74be3b6178ec5ea33bc7e/types returned with HTTP 500
2014-03-11 12:26:33.455 INFO eventlet.wsgi.server [req-9d4cb67f-e142-43ec-9512-bf7aeed0fd0d 8a674f2790ae4032b87bc3a3d6276614 a593ac3af6d74be3b6178ec5ea33bc7e] 10.112.185.199,10.113.161.210,10.113.161.215 - - [11/Mar/2014 12:26:33] "POST /v2/a593ac3af6d74be3b6178ec5ea33bc7e/types HTTP/1.0" 500 425 1.157837

[Swapnil Kulkarni (coolsvap-deactivatedaccount)]

Was trying to reproduce the bug, got following results,

~/devstack$ cinder type-list
+--------------------------------------+------+
| ID | Name |
+--------------------------------------+------+
| 5264722d-b3a6-43b2-b284-e1c5a07c3ea3 | gfs2 |
| a7367581-8e09-4d88-970e-16d8e479a59e | gfs1 |
+--------------------------------------+------+
~/devstack$ cinder type-create gfs1
ERROR: Volume Type gfs1 already exists. (HTTP 409) (Request-ID: req-fb3be7a4-8794-4edd-80ca-ff5a8a19d7f8)
~/devstack$

Satyadev, are you trying with master or any specific release/branch which you can mention?

[Mike Perez (thingee)]

Was able to reproduce the problem:

vagrant@precise64:/vagrant$ cinder type-create foo
+--------------------------------------+------+
| ID | Name |
+--------------------------------------+------+
| af2bfaad-98cd-416f-a4c9-b6097b1daec4 | foo |
+--------------------------------------+------+
vagrant@precise64:/vagrant$ cinder type-list

+--------------------------------------+------+
| ID | Name |
+--------------------------------------+------+
| af2bfaad-98cd-416f-a4c9-b6097b1daec4 | foo |
+--------------------------------------+------+
vagrant@precise64:/vagrant$ cinder type-create foo
ERROR: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-3676e9d6-33c7-4910-8c71-6df31469d91e

cinder-api had the same stacktrace as bug creator.

[John Griffith (john-griffith)]

Well that's troubling.... V1 versus V2 maybe? Or something related between middleware or wsgi?

Regardless it's obvious there's a bug here we need to fix but I'd like to understand the details between the different responses. I also notice the past of the trace had the "thin" type in the error message, however the command was attempting to create "sliver"... I assumed this was an error in the pasting of the two sets of text but now I'm wondering if I need to ask that someone confirms that.

[Mike Perez (thingee)]

John, I have reproduced this in both v1 and v2. Definitely something in cinder.api.openstack.wsgi.

[git-harry (git-harry)]

It looks to relate to this commit - https://github.com/openstack/cinder/commit/cbe1d5f5e22e5f792128643e4cdd6afb2ff2b5bf

For example the same thing happens with qos-create if you try to create a qos spec that already exists.

It looks like the data can't be converted to JSON, because there is now an Exception object and not a string, and the to_primitive function is where it fails - https://github.com/openstack/cinder/blob/master/cinder/openstack/common/jsonutils.py

[Jay Bryant (jsbryant)]

Good catch! I know how to fix this now. Working on the explanation for the problem.

[Jay Bryant (jsbryant)]

Thanks for the pointer on this one git-harry. So, what I did was break the contract with webob's exception class. When I was going through the process of creating commit https://github.com/openstack/cinder/commit/cbe1d5f5e22e5f792128643e4cdd6afb2ff2b5bf Jim Carey and I talked about this case. I thought I had handled these but I hadn't.

Anyway, this is currently failing because I am trying to send a message object from OpenStack to the webob library, which it isn't designed to handle. The 'raise.webob.HTTP*' needs to have the err being sent wrapped with six.text_type. I will go make sure that I fix all the places where that is happening.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/80107
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=5757c857bdf526dc82cc8c1d4200d92c183e9374
Submitter: Jenkins
Branch: master

commit 5757c857bdf526dc82cc8c1d4200d92c183e9374
Author: Jay S. Bryant <email address hidden>
Date: Wed Mar 12 17:39:18 2014 -0500

    Don't send untextified exc to webob

    As part of commit cbe1d5f5e22e5f792128643e4cdd6afb2ff2b5bf I
    accidentally removed the str() from exceptions that were being
    passed out of OpenStack to webob. This broke the contract with
    webob which was expecting strings (text) to be sent. This
    resulted in webob doing bad things if we encountered an exception,
    like trying to create a duplicate volume type.

    This commit replaces the str()'s that shouldn't have been removed
    with six.text_type() which should be used in place of str() to
    resolve this issue. There was one instance where a message was
    instead being unicoded, this also was changed to use six.text_type.

    This commit also fixes one message that should have been translated
    but was not.

    Change-Id: Iad6a81108f58c1bfd13397479022c4c4ad1ccc56
    Closes-bug: 1290715

[satyadev svn (svnsatya)]

Verified on latest code bits. Now it throw error message .
ssatya@devstack:~$ cinder type-create test
ERROR: Volume Type test already exists. (HTTP 409) (Request-ID: req-775cd9e2-d0d2-437c-ae93-59