keystone_driver fails to poll user data

[Masahito Muroi]

Keysttonev2 driver fails to poll user table data in devstack. Following error appears in log periodically.

2016-06-29 23:57:36.486 ERROR congress.datasources.datasource_driver [-] Datasource driver raised exception
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver Traceback (most recent call last):
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/opt/stack/congress/congress/datasources/datasource_driver.py", line 1284, in poll
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver self.update_from_datasource() # sets self.state
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/opt/stack/congress/congress/datasources/keystone_driver.py", line 104, in update_from_datasource
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver users = self.client.users.list()
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneclient/v2_0/users.py", line 128, in list
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver return self._list("/users%s" % query, "users")
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneclient/base.py", line 124, in _list
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver resp, body = self.client.get(url, **kwargs)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 178, in get
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver return self.request(url, 'GET', **kwargs)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 335, in request
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 103, in request
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver return self.session.request(url, method, **kwargs)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver return wrapped(*args, **kwargs)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneclient/session.py", line 419, in request
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver raise exceptions.from_response(resp, method, url)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver NotFound: The resource could not be found. (HTTP 404)
2016-06-29 23:57:36.486 TRACE congress.datasources.datasource_driver

[Aimee Ukasick (aimeeu)]

2016-08-30 17:02:11.941 DEBUG congress.datasources.datasource_driver [-] start to poll from datasource keystone from (pid=29030) poll_loop /opt/stack/congress/congress/datasources/datasource_driver.py:1440
2016-08-30 17:02:11.942 INFO congress.datasources.datasource_driver [-] keystone:: polling
2016-08-30 17:02:11.942 DEBUG keystoneclient.session [-] REQ: curl -g -i -X GET http://192.168.56.101/identity_v2_admin/users -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}9236fab7035bbf7ca2f239a41345b17531314362" from (pid=29030) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:206
2016-08-30 17:02:11.947 DEBUG keystoneclient.session [-] RESP: [404] Date: Tue, 30 Aug 2016 22:02:11 GMT Server: Apache/2.4.7 (Ubuntu) Vary: X-Auth-Token Content-Length: 93 Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Content-Type: application/json
RESP BODY: {"error": {"message": "The resource could not be found.", "code": 404, "title": "Not Found"}}
 from (pid=29030) _http_log_response /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:231
2016-08-30 17:02:11.947 DEBUG keystoneclient.session [-] Request returned failure status: 404 from (pid=29030) request /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:418
2016-08-30 17:02:11.948 ERROR congress.datasources.datasource_driver [-] Datasource driver raised exception
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver Traceback (most recent call last):
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  File "/opt/stack/congress/congress/datasources/datasource_driver.py", line 1390, in poll
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  self.update_from_datasource() # sets self.state
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  File "/opt/stack/congress/congress/datasources/keystone_driver.py", line 105, in update_from_datasource
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  users = self.client.users.list()
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  File "/usr/local/lib/python2.7/dist-packages/keystoneclient/v2_0/users.py", line 124, in list
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  return self._list("/users%s" % query, "users")
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  File "/usr/local/lib/python2.7/dist-packages/keystoneclient/base.py", line 124, in _list
2016-08-30 17:02:11.948 TRACE congress.datasources.datasource_driver  resp, body = self.client.get(url, **kwargs)
2016-08-30 17:02:11.948 ...

[Eric K (ekcs)]

I may have identified the root cause and fix:

This devstack change in Newton changed the keystone auth_url to be unversioned [1].
As a consequence, this line [2] no longer gets the correct auth_url.

So instead of:
  self.creds['auth_url'].replace('v3', 'v2.0')
We may need something like:
  self.creds['auth_url'] + '/v2.0'

[1] https://review.openstack.org/#/c/285879/ (Note it says reverted, but only temporarily; the reverting was then reverted back.)
[2] https://github.com/openstack/congress/blob/master/congress/datasources/keystone_driver.py#L73

[Eric K (ekcs)]

Nope, that's not the root cause. self.creds['auth_url'] appears to be computed correctly (http://192.168.218.145:5000/v2.0 on my devstack setup), so it's something else.

[Eric K (ekcs)]

Looking deeper into the logs, I noticed two things:
1. of the three update methods in Keystone driver, the error occurs only with the tenants method. So it's likely not an authentication error.
2. Looking at the log, it appears that the Keystone driver is calling the Keystone client method correctly [1], but an error occurs deeper down in the Keystone client. I think it may be a bug in Keystone v2 client.

2016-09-20 21:58:25.829 ERROR congress.datasources.datasource_driver [-] Datasource driver raised exception
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver Traceback (most recent call last):
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/opt/stack/congress/congress/datasources/datasource_driver.py", line 1384, in poll
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver self.update_from_datasource() # sets self.state
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/opt/stack/congress/congress/datasources/datasource_driver.py", line 1371, in update_from_datasource
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver self.update_methods[registered_table]()
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/opt/stack/congress/congress/datasources/keystone_driver.py", line 110, in <lambda>
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver self.client.tenants.list())
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneclient/v2_0/tenants.py", line 125, in list
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver tenant_list = self._list('/tenants%s' % query, 'tenants')
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneclient/base.py", line 124, in _list
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver resp, body = self.client.get(url, **kwargs)
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 187, in get
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver return self.request(url, 'GET', **kwargs)
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 344, in request
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 112, in request
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver return self.session.request(url, method, **kwargs)
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-09-20 21:58:25.829 TRACE congress.datasources.datasource_driver return wrapped(*args, **kwargs)
2016-09-20 21:58:25.829 TRACE congress.d...

[Eric K (ekcs)]

I reported it as a potential bug to Keystone client: https://bugs.launchpad.net/python-keystoneclient/+bug/1625931

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/375783

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/374438
Committed: https://git.openstack.org/cgit/openstack/congress/commit/?id=433bdacd62a6f0228b2a92fd8970684f6d0b6f02
Submitter: Jenkins
Branch: master

commit 433bdacd62a6f0228b2a92fd8970684f6d0b6f02
Author: Eric K <email address hidden>
Date: Wed Sep 21 16:10:18 2016 -0700

    Use keystone session in keystone_driver

    Change-Id: I17a0207c1b12568ca05abe5576a860ba9218367c
    Closes-Bug: #1597555

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/375783
Committed: https://git.openstack.org/cgit/openstack/congress/commit/?id=558c56140fb5e1cda576c60e902944b72b89f516
Submitter: Jenkins
Branch: stable/newton

commit 558c56140fb5e1cda576c60e902944b72b89f516
Author: Eric K <email address hidden>
Date: Wed Sep 21 16:10:18 2016 -0700

    Use keystone session in keystone_driver

    Its unable to retrieve users data without this.

    Change-Id: I17a0207c1b12568ca05abe5576a860ba9218367c
    Closes-Bug: #1597555

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/congress 4.0.0.0rc2 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/congress 5.0.0.0b1 development milestone.