v2.0 catalog seen in v3 token

[Eric Brown]

During a Rally test of our deployment using Mitaka keystone we observed the following traceback in the logs. It seems that the v3 catalog is returned as a list whereas the v2.0 catalog is a dict. But the format_catalog() function always expects a dict.

2016-07-06 03:00:55.171 18314 INFO eventlet.wsgi.server [req-5ebbe11b-5efb-4606-a46c-58f100a8a550 5716d29278b8438a95f718ea926e4e7a 954d6157b061441197b228ac7b4dd6ee - default default] 10.111.109.191,10.111.109.89 - - [06/Jul/2016 03:00:55] "DELETE /v2.0/tenants/37b1a3bad0e54dc2a9824ac51ba02a9f HTTP/1.1" 204 212 0.070017
2016-07-06 03:00:55.779 18323 DEBUG keystone.middleware.auth [req-9843ab92-0f8f-42b9-8b56-a5fc6d011569 - - - - -] There is either no auth token in the request or the certificate issuer is not trusted. No auth context will be set. _build_auth_context /usr/lib/python2.7/dist-packages/keystone/middleware/auth.py:71
2016-07-06 03:00:55.781 18323 INFO keystone.common.wsgi [req-9843ab92-0f8f-42b9-8b56-a5fc6d011569 - - - - -] POST http://10.111.109.81:5000/v2.0/tokens
2016-07-06 03:00:55.879 18323 INFO keystone.token.providers.fernet.utils [req-9843ab92-0f8f-42b9-8b56-a5fc6d011569 - - - - -] Loaded 2 encryption keys (max_active_keys=3) from: /etc/keystone/fernet-keys/
2016-07-06 03:00:55.882 18323 INFO eventlet.wsgi.server [req-9843ab92-0f8f-42b9-8b56-a5fc6d011569 - - - - -] 10.111.109.191,10.111.109.89 - - [06/Jul/2016 03:00:55] "POST /v2.0/tokens HTTP/1.1" 200 3585 0.102872
2016-07-06 03:00:57.450 18323 DEBUG keystone.middleware.auth [req-57632939-e139-4dc7-a1f4-833ce4e84665 - - - - -] There is either no auth token in the request or the certificate issuer is not trusted. No auth context will be set. _build_auth_context /usr/lib/python2.7/dist-packages/keystone/middleware/auth.py:71
2016-07-06 03:00:57.452 18323 INFO keystone.common.wsgi [req-57632939-e139-4dc7-a1f4-833ce4e84665 - - - - -] POST http://10.111.109.81:5000/v2.0/tokens
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi [req-57632939-e139-4dc7-a1f4-833ce4e84665 - - - - -] 'list' object has no attribute 'items'
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi Traceback (most recent call last):
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/wsgi.py", line 249, in __call__
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi result = method(context, **params)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/oslo_log/versionutils.py", line 165, in wrapped
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi return func_or_cls(*args, **kwargs)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/controllers.py", line 144, in authenticate
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi auth_token_data, roles_ref=roles_ref, catalog_ref=catalog_ref)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 124, in wrapped
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/provider.py", line 360, in issue_v2_token
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi token_ref, roles_ref, catalog_ref)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/fernet/core.py", line 38, in issue_v2_token
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi *args, **kwargs)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 570, in issue_v2_token
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi token_ref, roles_ref, catalog_ref, trust_ref)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 163, in format_token
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi catalog_ref)
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi File "/usr/lib/python2.7/dist-packages/keystone/token/providers/common.py", line 214, in format_catalog
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi for region, region_ref in catalog_ref.items():
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi AttributeError: 'list' object has no attribute 'items'
2016-07-06 03:00:57.565 18323 ERROR keystone.common.wsgi
2016-07-06 03:00:57.570 18323 INFO eventlet.wsgi.server [req-57632939-e139-4dc7-a1f4-833ce4e84665 - - - - -] 10.111.109.191,10.111.109.89 - - [06/Jul/2016 03:00:57] "POST /v2.0/tokens HTTP/1.1" 500 400 0.120986
2016-07-06 03:00:58.181 18317 INFO keystone.token.providers.fernet.utils [req-7e2abf43-3cee-4335-a061-6a5c57a66b8d - - - - -] Loaded 2 encryption keys (max_active_keys=3) from: /etc/keystone/fernet-keys/
2016-07-06 03:00:58.273 18317 DEBUG keystone.middleware.auth [req-7e2abf43-3cee-4335-a061-6a5c57a66b8d 5716d29278b8438a95f718ea926e4e7a 954d6157b061441197b228ac7b4dd6ee - default default] RBAC: auth_context: {'is_delegated_auth': False, 'access_token_id': None, 'user_id': u'5716d29278b8438a95f718ea926e4e7a', 'roles': [u'_member_', u'admin'], 'user_domain_id': u'default', 'trustee_id': None, 'trustor_id': None, 'consumer_id': None, 'token': <KeystoneToken (audit_id=4qmxuLzaSS-IFbH_5iawCQ, audit_chain_id=4qmxuLzaSS-IFbH_5iawCQ) at 0x7ff84d604868>, 'project_id': u'954d6157b061441197b228ac7b4dd6ee', 'trust_id': None, 'project_domain_id': u'default'} process_request /usr/lib/python2.7/dist-packages/keystone/middleware/auth.py:221

[Lance Bragstad (lbragstad)]

Eric, do you have anymore configuration information or scenarios on how to recreate this?

[Steve Martinelli (stevemar)]

I think we're also hitting this in our keystoneclient to keystoneauth migration for cinderclient:

See: http://logs.openstack.org/64/290464/9/check/gate-cinderclient-dsvm-functional/b0ee1d1/testr_results.html.gz

[Eric Brown (ericwb)]

I think our issues are mostly related keystone's use of memcache. We had to globally disable caching because we kept running into so many exceptions. We use eventlet with memcache_pool in our stable/mitaka if that matters.

[Steve Martinelli (stevemar)]

Ignore my comment in #2, it is completely unrelated

[Steve Martinelli (stevemar)]

Related to https://bugs.launchpad.net/keystonemiddleware/+bug/1605355 ?

[Matt Fischer (mfisch)]

Seeing this in the lab running a container built on Mitaka from Aug 1.

[Matt Fischer (mfisch)]

Some info (and more to follow later). We have caching enabled in Keystone & the middleware layer in all environments, but only Mitaka Keystone in dev and we ONLY see this issue in dev.

It also comes and goes. Yesterday it happened on all nodes from 16:15 to 16:45 then went away. The day before it happened from 17:19 to 20:16 then stopped. Before that it last occurred on July 12.

Here is what I see out of the middleware stack:

2016-08-02 15:58:48.489 144 ERROR nova.api.openstack [req-cb1199ba-a752-481c-82bb-9dcbb35d5330 dd8836bbbe4545aa96e11eb2e54251c9 41c98257b5de46f3aefe5b7ad23d2f65 - - -] Caught error: 'interface'
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack Traceback (most recent call last):
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 134, in __call__
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack return req.get_response(self.application)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/webob/request.py", line 1317, in send
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack application, catch_exc_info=False)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/webob/request.py", line 1281, in call_application
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack app_iter = application(self.environ, start_response)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack return resp(environ, start_response)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack return self.func(req, *args, **kwargs)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 452, in __call__
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack response = self.process_request(req)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 752, in process_request
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack self._include_service_catalog)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token/_request.py", line 163, in set_user_headers
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack catalog = _v3_to_v2_catalog(catalog)
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token/_request.py", line 47, in _v3_to_v2_catalog
2016-08-02 15:58:48.489 144 ERROR nova.api.openstack int...

[Matt Fischer (mfisch)]

Here it is on designate which is running keystonemiddleware 1.3.1. Designate is still back on Juno. (Nova is on Liberty).

2016-08-01 18:41:11.707 1 INFO eventlet.wsgi [-] Traceback (most recent call last):
  File "/venv/local/lib/python2.7/site-packages/eventlet/wsgi.py", line 433, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/venv/local/lib/python2.7/site-packages/paste/urlmap.py", line 203, in __call__
    return app(environ, start_response)
  File "/venv/local/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/venv/local/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/venv/local/lib/python2.7/site-packages/designate/openstack/common/middleware/request_id.py", line 38, in __call__
    response = req.get_response(self.application)
  File "/venv/local/lib/python2.7/site-packages/webob/request.py", line 1320, in send
    application, catch_exc_info=False)
  File "/venv/local/lib/python2.7/site-packages/webob/request.py", line 1284, in call_application
    app_iter = application(self.environ, start_response)
  File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 789, in __call__
    user_headers = self._build_user_headers(auth_ref, token_info)
  File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 1009, in _build_user_headers
    catalog = _v3_to_v2_catalog(catalog)
  File "/venv/local/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 444, in _v3_to_v2_catalog
    interface_name = v3_endpoint['interface'].lower() + 'URL'
KeyError: 'interface'

[Matt Fischer (mfisch)]

I want to also throw this out there but don't consider it to be authoritative. I don't see the errors at all on Heat and Swift. Both of them have Mitakaish versions of the middleware (both are on M).

Swift is running python-keystonemiddleware 4.0.0-1~cloud0
Heat is running keystonemiddleware==4.4.1

Now, I say this with caution because neither service is exercised very much in our lab and so it's possible they just didn't get called enough to see it. But it is curious and bears some investigation.

[Steve Martinelli (stevemar)]

Example logs http://paste.openstack.org/show/549271/

[Steve Martinelli (stevemar)]

likely related to our caching woes: https://bugs.launchpad.net/keystone/+bug/1600394

[Steve Martinelli (stevemar)]

like related also: https://bugs.launchpad.net/oslo.cache/+bug/1590779

[Steve Martinelli (stevemar)]

There is no patch for this bug so I am removing it from the milestone-3 target. I have also unassigned David.

[Steve Martinelli (stevemar)]

It's been a while since we've heard about this one. Eric / Matt, do either of you see this now?

[Launchpad Janitor (janitor)]

[Expired for OpenStack Identity (keystone) because there has been no activity for 60 days.]