auth_token middleware should properly handle KeyError

[Jay Pipes]

Running devstack, completely clean installation of all components.

Get this:

ubuntu@unagi221:~/devstack$ glance -A openstack index
Failed to show index. Got error:
Internal Server error: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 336, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
    return self.func(req, *args, **kwargs)
  File "/opt/stack/glance/glance/common/wsgi.py", line 279, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1086, in get_response
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1055, in call_application
    app_iter = application(self.environ, start_response)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 163, in __call__
    valid = self._validate_claims(claims)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 287, in _validate_claims
    self.admin_password)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 278, in _get_admin_auth_token
    return json.loads(data)["access"]["token"]["id"]
KeyError: 'access'

Both Nati Ueno and I can verify this behaviour...

At a minimum, the auth_token middleware should never simply barf a KeyError. Too many assumptions are made about the response JSON in the _get_admin_auth_token method apparently.

[Nachi Ueno (nati-ueno)]

I got this error in keystone log.

2012-02-28 06:03:41 WARNING [root] Invalid user / password
2012-02-28 06:03:41 DEBUG [root] ******************** RESPONSE HEADERS ********************
2012-02-28 06:03:41 DEBUG [root] Content-Type = application/json
2012-02-28 06:03:41 DEBUG [root] Content-Length = 89
2012-02-28 06:03:41 DEBUG [root]
2012-02-28 06:03:41 DEBUG [root] ******************** RESPONSE BODY ********************
2012-02-28 06:03:41 DEBUG [root] {"error": {"message": "Invalid user / password", "code": 401, "title": "Not Authorized"}}

[termie (termie)]

i wonder if these are related: https://review.openstack.org/#change,4438

[Joseph Heck (heckj)]

They are - dtroyer just tracked it back to that commit : https://github.com/openstack/keystone/commit/08a3060bade8f14c2f81d4d502d27f097b016b93

On Feb 27, 2012, at 3:58 PM, termie wrote:
> i wonder if these are related: https://review.openstack.org/#change,4438
>
> --
> You received this bug notification because you are a member of Keystone
> Bugs, which is subscribed to Keystone.
> https://bugs.launchpad.net/bugs/942247
>
> Title:
> Admin token auth completely broken
>
> Status in OpenStack Identity (Keystone):
> Confirmed
>
> Bug description:
> Running devstack, completely clean installation of all components.
>
> Get this:
>
> ubuntu@unagi221:~/devstack$ glance -A openstack index
> Failed to show index. Got error:
> Internal Server error: Traceback (most recent call last):
> File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 336, in handle_one_response
> result = self.application(self.environ, start_response)
> File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
> resp = self.call_func(req, *args, **self.kwargs)
> File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
> return self.func(req, *args, **kwargs)
> File "/opt/stack/glance/glance/common/wsgi.py", line 279, in __call__
> response = req.get_response(self.application)
> File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1086, in get_response
> application, catch_exc_info=False)
> File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1055, in call_application
> app_iter = application(self.environ, start_response)
> File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 163, in __call__
> valid = self._validate_claims(claims)
> File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 287, in _validate_claims
> self.admin_password)
> File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 278, in _get_admin_auth_token
> return json.loads(data)["access"]["token"]["id"]
> KeyError: 'access'
>
> Both Nati Ueno and I can verify this behaviour...
>
> At a minimum, the auth_token middleware should never simply barf a
> KeyError. Too many assumptions are made about the response JSON in the
> _get_admin_auth_token method apparently.
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/keystone/+bug/942247/+subscriptions

[Jay Pipes (jaypipes)]

Pulled fresh everything this morning and still having issues. Here is the printout of a successful stack.sh run, where you can clearly see that the glance add command run during the stack.sh run completed successfully with the -A <TOKEN> option, and then immediately afterwards, you can see that trying a glance index with either the service token (-A servicetoken) or the exact same token used in the stack.sh run both fail. :(

+ glance add -A 6a8edb8d09904d9ba0f6eb1bf29bc742 name=cirros-0.3.0-x86_64-blank is_public=true container_format=ami disk_format=ami kernel_id=1d743b59-b122-4a19-a51f-e1b5c0ff1e0e ramdisk_id=1ef39803-190c-46eb-a869-e8cc265ef598
++ zcat --force /home/jpipes/repos/devstack/files/images/cirros-0.3.0-x86_64-uec/cirros-0.3.0-x86_64-blank.img
The progressbar doesn't show-up because the headers[x-meta-size] is zero or missing
Uploading image 'cirros-0.3.0-x86_64-blank'

Added new image with ID: c192ae9b-b8c0-4f28-aae5-73351c250410
+ set +o xtrace

horizon is now available at http://192.168.1.98/
keystone is serving at http://192.168.1.98:5000/v2.0/
examples on using novaclient command line is in exercise.sh
the default users are: admin and demo
the password: pass
This is your host ip: 192.168.1.98
stack.sh completed in 482 seconds.
jpipes@librebox:~/repos/devstack$ /opt/stack/glance/bin/glance -A servicetoken index
Failed to show index. Got error:
Internal Server error: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 336, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 208, in call_func
    return self.func(req, *args, **kwargs)
  File "/opt/stack/glance/glance/common/wsgi.py", line 279, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1053, in get_response
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1022, in call_application
    app_iter = application(self.environ, start_response)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 164, in __call__
    valid = self._validate_claims(claims)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 272, in _validate_claims
    self.admin_password)
  File "/opt/stack/keystone/keystone/middleware/auth_token.py", line 263, in _get_admin_auth_token
    return json.loads(data)["access"]["token"]["id"]
KeyError: 'access'

jpipes@librebox:~/repos/devstack$ glance index -A 6a8edb8d09904d9ba0f6eb1bf29bc742
Failed to show index. Got error:
Internal Server error: Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 336, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 208, in call_fun...

[Jay Pipes (jaypipes)]

After investigating further, it turns out that there are no tokens in the Keystone token table:

mysql> select * from token;
Empty set (0.00 sec)

Looking in devstack's files/keystone_data.sh, I see no commands adding the SERVICE_TOKEN, even though the SERVICE_TOKEN is imported in the beginning of the script...

[Jay Pipes (jaypipes)]

Found the source of the issue in Devstack at least.

https://github.com/openstack-dev/devstack/commit/d1f5243d91de2756fecd52c3b3a15a4f0a488fdf

Note that the call to add the service token was removed at the bottom of the commit.

[Jay Pipes (jaypipes)]

Adding a bug in devstack for the missing token add command... this bug should be about the KeyError raise

[Alan Pevec (apevec)]

SERVICE_TOKEN should still work, it is set as admin_token in keystone.conf

[Jay Pipes (jaypipes)]

Alan, sorry, but please read all of the related bugs... the service token is never added to Keystone now.

[Alan Pevec (apevec)]

I did, I just don't see why would you get _get_admin_auth_token in backtrace if admin_token is set in [filter:authtoken]

Of course, keystone client needs to be fixed to add missing token-create subcommand.

[Dan Prince (dan-prince)]

Is perhaps the python-keystoneclient package getting cached and is out of date on the VMs running Devstack?

The signature for some of the keystone CLI methods recently changed and using an older version might cause failures like this?

[Dan Prince (dan-prince)]

NM. Just saw the devstack fix. I'm going to fix this KeyError issue now.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/4634

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/4634
Committed: http://github.com/openstack/keystone/commit/089f53a6317543660f600f3ec6b819b8d7b7f9a7
Submitter: Jenkins
Branch: master

commit 089f53a6317543660f600f3ec6b819b8d7b7f9a7
Author: Dan Prince <email address hidden>
Date: Tue Feb 28 11:56:24 2012 -0500

    Handle KeyError in _get_admin_auth_token.

    Updates the _get_admin_auth_token so that it more gracefully
    handles KeyError's.
    Also adds a conn.close to the _get_admin_auth_token method.

    Fixes LP Bug #942247.

    Change-Id: I2826f1b02bc7fd46c02ab3d15d88f76b9a8457f0