os-collect-config returns http error 400 Remote error: BadRequest

[Ryan Hallisey]

On both the controller and compute node, heat gets an error running os-collect-config.
http://paste.fedoraproject.org/311376/14528905/

This is the error returned from the keystone client:
https://paste.fedoraproject.org/311380/28912221/

[Ryan Hallisey (rthall14)]

os-collect-config error:

Jan 15 20:40:44 localhost os-collect-config: [2016-01-15 20:40:44,348] (os-refresh-config) [INFO] Completed phase configure
Jan 15 20:40:44 localhost os-collect-config: [2016-01-15 20:40:44,348] (os-refresh-config) [INFO] Starting phase post-configure
Jan 15 20:40:44 localhost os-collect-config: dib-run-parts Fri Jan 15 20:40:44 UTC 2016 Running /usr/libexec/os-refresh-config/post-configure.d/99-refresh-completed
Jan 15 20:40:44 localhost os-collect-config: ++ os-apply-config --key completion-handle --type raw --key-default ''
Jan 15 20:40:44 localhost os-collect-config: + HANDLE=
Jan 15 20:40:44 localhost os-collect-config: ++ os-apply-config --key completion-signal --type raw --key-default ''
Jan 15 20:40:44 localhost os-collect-config: + SIGNAL=
Jan 15 20:40:44 localhost os-collect-config: ++ os-apply-config --key instance-id --type raw --key-default ''
Jan 15 20:40:44 localhost os-collect-config: + ID=i-00000006
Jan 15 20:40:44 localhost os-collect-config: + '[' -n i-00000006 ']'
Jan 15 20:40:44 localhost os-collect-config: + '[' -n '' ']'
Jan 15 20:40:44 localhost os-collect-config: + '[' -n '' ']'
Jan 15 20:40:44 localhost os-collect-config: ++ os-apply-config --key deployments --type raw --key-default ''
Jan 15 20:40:44 localhost os-collect-config: ++ jq -r 'map(select(.group == "os-apply-config") |
Jan 15 20:40:44 localhost os-collect-config: select(.inputs[].name == "deploy_signal_id") |
Jan 15 20:40:44 localhost os-collect-config: .id + (.inputs | map(select(.name == "deploy_signal_id")) | .[].value)) |
Jan 15 20:40:44 localhost os-collect-config: .[]'
Jan 15 20:40:44 localhost os-collect-config: + DEPLOYMENTS='012c624c-5b65-4151-9414-4488a04346cfhttp://192.0.2.1:8000/v1/signal/arn%3Aopenstack%3Aheat%3A%3Aa429d0c73d694f1ca21de329a7d80919%3Astacks%2Fovercloud-Controller-iqmakrdgab3l-0-6up45yxvaopg%2F6c74198f-b105-4d4c-b682-7a9abf14f8fc%2Fresources%2FNetworkDeployment?Timestamp=2016-01-15T20%3A17%3A45Z&SignatureMethod=HmacSHA256&AWSAccessKeyId=a9ad461474b24fb7ba484e014e347b41&SignatureVersion=2&Signature=5ytio7aayJ2colKfOirskzCP96UU3fNvB91ETwIf9VY%3D'
Jan 15 20:40:44 localhost os-collect-config: + for dep in '${DEPLOYMENTS}'
Jan 15 20:40:44 localhost os-collect-config: ++ echo '012c624c-5b65-4151-9414-4488a04346cfhttp://192.0.2.1:8000/v1/signal/arn%3Aopenstack%3Aheat%3A%3Aa429d0c73d694f1ca21de329a7d80919%3Astacks%2Fovercloud-Controller-iqmakrdgab3l-0-6up45yxvaopg%2F6c74198f-b105-4d4c-b682-7a9abf14f8fc%2Fresources%2FNetworkDeployment?Timestamp=2016-01-15T20%3A17%3A45Z&SignatureMethod=HmacSHA256&AWSAccessKeyId=a9ad461474b24fb7ba484e014e347b41&SignatureVersion=2&Signature=5ytio7aayJ2colKfOirskzCP96UU3fNvB91ETwIf9VY%3D'
Jan 15 20:40:44 localhost os-collect-config: ++ sed 's/http.*$//'
Jan 15 20:40:44 localhost os-collect-config: + DEPLOY_ID=012c624c-5b65-4151-9414-4488a04346cf
Jan 15 20:40:44 localhost os-collect-config: ++ sed 's/^.*http/http/'
Jan 15 20:40:44 localhost os-collect-config: ++ echo '012c624c-5b65-4151-9414-4488a04346cfhttp://192.0.2.1:8000/v1/signal/arn%3Aopenstack%3Aheat%3A%3Aa429d0c73d694f1ca21de329a7d80919%3Astacks%2Fovercloud-Controller-iqmakrdgab3l-0-6up45yxvaopg%2F6c74198f-b105-4d4c-b682-7a...

[Ryan Hallisey (rthall14)]

keystone returned from the keystone client:

2016-01-15 20:21:37.948 21568 DEBUG heat.engine.scheduler [-] Task create running step /usr/lib/python2.7/site-packages/heat/engine/scheduler.py:214
2016-01-15 20:21:37.987 21567 WARNING heat.common.context [req-b5388cd1-1b86-4788-846c-ecc8e25962e1 - admin - - -] Using the keystone_authtoken user as the heat trustee user directly is deprecated. Please add t\
he trustee credentials you need to the trustee section of your heat.conf file.
2016-01-15 20:21:37.988 21567 DEBUG keystoneclient.auth.identity.v3.base [req-b5388cd1-1b86-4788-846c-ecc8e25962e1 - admin - - -] Making authentication request to http://192.0.2.1:5000/v3/auth/tokens get_auth_r\
ef /usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v3/base.py:188
2016-01-15 20:21:38.042 21567 DEBUG keystoneclient.session [req-b5388cd1-1b86-4788-846c-ecc8e25962e1 - admin - - -] Request returned failure status: 400 request /usr/lib/python2.7/site-packages/keystoneclient/s\
ession.py:404
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher [req-b5388cd1-1b86-4788-846c-ecc8e25962e1 - admin - - -] Exception during message handling: Expecting to find domain in user - the server could \
not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-a9a55d3b-6f3e-4bc6-baee-667e1579949e) (HTTP 400)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 143, in _dispatch_and_reply
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher executor_callback))
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 189, in _dispatch
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher executor_callback)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 109, in wrapper
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/heat/common/context.py", line 325, in wrapped
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher return func(self, ctx, *args, **kwargs)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/heat/engine/service.py", line 1475, in resource_signal
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher stack = parser.Stack.load(cnxt, stack=s, use_stored_context=True)
2016-01-15 20:21:38.043 21567 ERROR oslo_messaging.rpc.dispatcher File "/usr/lib/python...

[Steven Hardy (shardy)]

I think this is a regression in recent heat, fixed by the now-merged https://review.openstack.org/#/c/267275/

Can you confirm that fixes the issue please?

[Ryan Hallisey (rthall14)]

This fixes the issue thanks!