safe_minidom_parse_string raising ExpatError in Jenkins runs since 8/20; lxml random hashseed failure

[Matt Riedemann]

Seeing this in a stable/icehouse run, it's happening on the old side of grenade so it'd be havana:

http://logs.openstack.org/15/115815/1/check/check-grenade-dsvm/d1f4c81/logs/old/screen-c-api.txt.gz?level=TRACE#_2014-08-21_19_28_06_073

2014-08-21 19:28:06.073 21432 ERROR cinder.api.middleware.fault [req-bc1108e0-f789-4199-9aad-255602890bcb 14d0d0efd9364e0c82f1df6c5552782c f7707522d52b46bc8fa7d1aeae668777] Caught error:
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/middleware/fault.py", line 77, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return req.get_response(self.application)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault application, catch_exc_info=False)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 663, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return self.app(env, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault response = self.app(environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/openstack/wsgi.py", line 898, in __call__
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault content_type, body, accept)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/openstack/wsgi.py", line 920, in _process_stack
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault contents = self.deserialize(meth, content_type, body)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/openstack/wsgi.py", line 816, in deserialize
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return deserializer().deserialize(body)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/openstack/wsgi.py", line 209, in deserialize
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return self.dispatch(datastring, action=action)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/openstack/wsgi.py", line 199, in dispatch
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault return action_method(*args, **kwargs)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/api/v1/volumes.py", line 210, in default
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault dom = utils.safe_minidom_parse_string(string)
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault File "/opt/stack/old/cinder/cinder/utils.py", line 534, in safe_minidom_parse_string
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault raise expat.ExpatError()
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault ExpatError
2014-08-21 19:28:06.073 21432 TRACE cinder.api.middleware.fault

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwic2FmZV9taW5pZG9tX3BhcnNlX3N0cmluZ1wiIEFORCBtZXNzYWdlOlwiRXhwYXRFcnJvclwiIEFORCB0YWdzOlwic2NyZWVuLWMtYXBpLnR4dFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDA4NjcyNTE2MzA0LCJtb2RlIjoiIiwiYW5hbHl6ZV9maWVsZCI6IiJ9

There are 506 since 8/20, all branches, check and gate, all failures. Did something change with keystoneclient on 8/20?

[Matt Riedemann (mriedem)]

I think the keystoneclient authtoken part of the trace confused me. I'm wondering if a dependent package was updated/released on 8/20 or something? Nothing is jumping out at me. I'm not really seeing anything in the cinder, tempest or devstack commit history so it probably has to be some infra/dependent package update related to parsing xml?

[Matt Riedemann (mriedem)]

See this related tempest issue:

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

Not sure if that's related to this failure or not:

http://logs.openstack.org/15/115815/1/check/check-grenade-dsvm/61a9020/logs/grenade.sh.txt.gz#_2014-08-22_05_25_07_843

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiWE1MU3ludGF4RXJyb3I6IFN0YXJ0IHRhZyBleHBlY3RlZCwgJzwnIG5vdCBmb3VuZCwgbGluZSAxLCBjb2x1bW4gMVwiIEFORCB0YWdzOlwiY29uc29sZVwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDA4NzE4NTAzNzEwLCJtb2RlIjoiIiwiYW5hbHl6ZV9maWVsZCI6IiJ9

So this is definitely looking like an lxml hashseed ordering issue.

[Matt Riedemann (mriedem)]

This was the backport fix for Tempest: https://review.openstack.org/#/c/115963/

[Matt Riedemann (mriedem)]

The cinder failures drop off after tempest was fixed, so tempest was sending garbage to cinder and that's why the xml requests were failing the parse, so this is fixed.