create volume with Chinese character raise error

[Bin Zhou]

Volume created with Chinese name will raise an decode exception, the callchain is as follows:
2017-07-11 08:52:13.917 13034 DEBUG eventlet.wsgi.server [-] (13034) accepted ('192.168.100.174', 55662) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2017-07-11 08:52:13.925 13034 INFO cinder.api.openstack.wsgi [req-1ffa8cd3-abfc-4e87-9fd6-8a3d14a6524a - - - - -] POST http://192.168.100.176:8776/v2/ca4f223b71eb4568b97efed4beadd940/volumes
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault [req-1ffa8cd3-abfc-4e87-9fd6-8a3d14a6524a - - - - -] Caught error: <type 'exceptions.UnicodeDecodeError'> 'ascii' codec can't decode byte 0xe6 in position 96: ordinal not in range(128)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault Traceback (most recent call last):
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/cinder/api/middleware/fault.py", line 79, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return req.get_response(self.application)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault application, catch_exc_info=False)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return resp(environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/osprofiler/web.py", line 108, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return request.get_response(self.application)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault application, catch_exc_info=False)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 467, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault response = req.get_response(self._app)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault application, catch_exc_info=False)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return resp(environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return resp(environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault response = self.app(environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return resp(environ, start_response)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1061, in __call__
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault content_type, body, accept)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1087, in _process_stack
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault 'body': six.text_type(body),
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault UnicodeDecodeError: 'ascii' codec can't decode byte 0xe6 in position 96: ordinal not in range(128)
2017-07-11 08:52:13.927 13034 ERROR cinder.api.middleware.fault
2017-07-11 08:52:13.929 13034 INFO cinder.api.middleware.fault [req-1ffa8cd3-abfc-4e87-9fd6-8a3d14a6524a - - - - -] http://192.168.100.176:8776/v2/ca4f223b71eb4568b97efed4beadd940/volumes returned with HTTP 500
2017-07-11 08:52:13.931 13034 INFO eventlet.wsgi.server [req-1ffa8cd3-abfc-4e87-9fd6-8a3d14a6524a - - - - -] 192.168.100.174 "POST /v2/ca4f223b71eb4568b97efed4beadd940/volumes HTTP/1.1" status: 500 len: 458 time: 0.0117280

[Eric Harney (eharney)]

Please provide the actual input used to generate the above trace.

cinder.tests.tempest.api.test_volume_unicode.CinderUnicodeTest is supposed to catch this error. We need to understand why it's not.

[Bin Zhou (binzhou)]

Hello, Eric, My input is as follows:
[root@ctrl173 ~(keystone_admin)]# cinder --debug create 1 --name 我的云盘
DEBUG:keystoneclient.session:REQ: curl -g -i -X GET http://192.168.100.176:5000/v2.0 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
DEBUG:keystoneclient.session:RESP: [200] Vary: X-Auth-Token Content-Type: application/json Content-Length: 341 X-Openstack-Request-Id: req-07ff8e2a-a2c0-4277-af33-ee34d514b6d2 Date: Wed, 12 Jul 2017 00:34:01 GMT
RESP BODY: {"version": {"status": "stable", "updated": "2014-04-17T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v2.0+json"}], "id": "v2.0", "links": [{"href": "http://192.168.100.176:5000/v2.0/", "rel": "self"}, {"href": "http://docs.openstack.org/", "type": "text/html", "rel": "describedby"}]}}

DEBUG:keystoneclient.auth.identity.v2:Making authentication request to http://192.168.100.176:5000/v2.0/tokens
DEBUG:keystoneclient.session:REQ: curl -g -i -X POST http://ha-vip:8776/v2/27c2a7ceafd645cd832be2dd72c225c8/volumes -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}be5607a968539e2e5f578d40327c51f97dab870c" -d '{"volume": {"status": "creating", "uuid": null, "user_id": null, "name": "\u6211\u7684\u4e91\u76d8", "imageRef": null, "availability_zone": null, "description": null, "multiattach": false, "attach_status": "detached", "volume_type": null, "metadata": {}, "consistencygroup_id": null, "source_volid": null, "snapshot_id": null, "project_id": null, "source_replica": null, "size": 1}}'

[Bin Zhou (binzhou)]

I got it. This bug is triggered in debug mode. when you set debug = True in cinder.conf,
you will get it actually.

[hongwei.xu (dengxiafubi)]

It's a bug from oslo.log

https://review.openstack.org/#/c/535721/

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sean McGinnis (<email address hidden>) on branch: master
Review: https://review.openstack.org/482389
Reason: No updates for a long time. Feel free to restore and update if you wish to continue with this.

[Kevin Carter (kevin-carter)]

I ran into a very similar issue when debug was enabled. Tempest testing was running using unicode tests resulted in the following stacktrace - http://paste.openstack.org/show/726897

These were the tests executed:
* cinder_tempest_plugin.api.volume.test_volume_unicode.CinderUnicodeTest.test_snapshot_create_volume_description_non_ascii_code
* cinder_tempest_plugin.api.volume.test_volume_unicode.CinderUnicodeTest.test_create_delete_unicode_volume_name

The python version running the cinder-volume service and the tempest tests is Python 2.7.12

To resolve the issue I simply enabled "use_json" in the cinder.conf when debug is enabled. This converts all log output to json which resolved the issue. A fix without needing to convert the logs to JSON would be fantastic however using the json option when debug is enabled seems to be a suitable workaround for now.

[hongwei.xu (dengxiafubi)]

hi, Kevin,

Thanks for you reply to me. This problem can be found in the version of mitaka and "use_json" can not be found in cinder.conf of this version

"use_json" was loaded in the latest version.