keystone_driver fails to poll user data

Bug #1597555 reported by Masahito Muroi
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
congress
Fix Released
High
Aimee Ukasick

Bug Description

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)
Changed in congress:
assignee: nobody → Aimee Ukasick (aimeeu)
Revision history for this message
Aimee Ukasick (aimeeu) wrote :
Download full text (5.1 KiB)

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 ...

Read more...

Eric K (ekcs)
Changed in congress:
importance: Undecided → High
milestone: none → newton-rc1
milestone: newton-rc1 → none
Eric K (ekcs)
Changed in congress:
milestone: none → newton-rc2
Revision history for this message
Eric K (ekcs) wrote :

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

Revision history for this message
Eric K (ekcs) wrote :

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.

Revision history for this message
Eric K (ekcs) wrote :
Download full text (3.8 KiB)

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...

Read more...

Revision history for this message
Eric K (ekcs) wrote :

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

Eric K (ekcs)
Changed in congress:
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to congress (stable/newton)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to congress (master)

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

Changed in congress:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to congress (stable/newton)

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

tags: added: in-stable-newton
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/congress 4.0.0.0rc2

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/congress 5.0.0.0b1

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.