Keystone + Devstack fail when KEYSTONE_TOKEN_FORMAT=UUID

[Ryan Petrello]

Running devstack in fresh Ubuntu 12.04 virtual machine with:

$ cat local_rc
KEYSTONE_TOKEN_FORMAT=UUID

...fails to start Keystone. Despite being configured for the UUID provider, keystone attempts to read `/etc/keystone/ssl/certs/signing_cert.pem` and fails (because it doesn't exist):

2014-04-25 10:36:25.289 INFO eventlet.wsgi.server [-] 192.168.121.46 - - [25/Apr/2014 10:36:25] "GET /v2.0/tokens/69da781ae31c405e9aaa7adbf8f6f806 HTTP/1.1" 200 3988 0.009096
2014-04-25 10:36:25.294 DEBUG keystone.middleware.core [-] RBAC: auth_context: {'project_id': u'7fab1d7a9ba741208bd748749a394902', 'user_id': u'8d21c5353bdd4eb7a1a805cb3b7fd1b2', 'roles': [u'_member_', u'service
']} from (pid=13334) process_request /opt/stack/keystone/keystone/middleware/core.py:281
2014-04-25 10:36:25.296 DEBUG keystone.common.wsgi [-] arg_dict: {} from (pid=13334) __call__ /opt/stack/keystone/keystone/common/wsgi.py:181
2014-04-25 10:36:25.296 DEBUG keystone.common.controller [-] RBAC: Authorizing identity:revocation_list() from (pid=13334) _build_policy_check_credentials /opt/stack/keystone/keystone/common/controller.py:54
2014-04-25 10:36:25.297 DEBUG keystone.common.controller [-] RBAC: using auth context from the request environment from (pid=13334) _build_policy_check_credentials /opt/stack/keystone/keystone/common/controller.
py:59
2014-04-25 10:36:25.297 DEBUG keystone.policy.backends.rules [-] enforce identity:revocation_list: {'project_id': u'7fab1d7a9ba741208bd748749a394902', 'user_id': u'8d21c5353bdd4eb7a1a805cb3b7fd1b2', 'roles': [u'
_member_', u'service']} from (pid=13334) enforce /opt/stack/keystone/keystone/policy/backends/rules.py:101
2014-04-25 10:36:25.297 DEBUG keystone.openstack.common.policy [-] Rule identity:revocation_list will be now enforced from (pid=13334) enforce /opt/stack/keystone/keystone/openstack/common/policy.py:287
2014-04-25 10:36:25.298 DEBUG keystone.common.controller [-] RBAC: Authorization granted from (pid=13334) inner /opt/stack/keystone/keystone/common/controller.py:151
2014-04-25 10:36:25.309 ERROR keystoneclient.common.cms [-] Signing error: Error opening signer certificate /etc/keystone/ssl/certs/signing_cert.pem
140424564475552:error:02001002:system library:fopen:No such file or directory:bss_file.c:398:fopen('/etc/keystone/ssl/certs/signing_cert.pem','r')
140424564475552:error:20074002:BIO routines:FILE_CTRL:system lib:bss_file.c:400:
unable to load certificate

2014-04-25 10:36:25.310 ERROR keystone.common.wsgi [-] Command 'openssl' returned non-zero exit status 3
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi Traceback (most recent call last):
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi File "/opt/stack/keystone/keystone/common/wsgi.py", line 207, in __call__
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi result = method(context, **params)
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi File "/opt/stack/keystone/keystone/common/controller.py", line 152, in inner
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi return f(self, context, *args, **kwargs)
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi File "/opt/stack/keystone/keystone/token/controllers.py", line 436, in revocation_list
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi CONF.signing.keyfile)
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi File "/opt/stack/python-keystoneclient/keystoneclient/common/cms.py", line 251, in cms_sign_text
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi raise subprocess.CalledProcessError(retcode, 'openssl')
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi CalledProcessError: Command 'openssl' returned non-zero exit status 3
2014-04-25 10:36:25.310 TRACE keystone.common.wsgi
2014-04-25 10:36:25.316 INFO eventlet.wsgi.server [-] 192.168.121.46 - - [25/Apr/2014 10:36:25] "GET /v2.0/tokens/revoked HTTP/1.1" 500 341 0.024887

https://asciinema.org/a/9116

[Dolph Mathews (dolph)]

Can you paste the keystone.conf that results from setting KEYSTONE_TOKEN_FORMAT=UUID ?

[Brant Knudson (blk-u)]

Keystone starts but when auth_token tries to validate the token it fails with the 500, so you can't validate any tokens.

[Brant Knudson (blk-u)]

Here's the error in g-api:

2014-04-25 14:29:52.947 354 DEBUG keystoneclient.middleware.auth_token [-] Token validation failure. _validate_user_token /opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:871
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token Traceback (most recent call last):
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token File "/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 859, in _validate_user_token
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token if self._is_token_id_in_revoked_list(token_id):
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token File "/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1201, in _is_token_id_in_revoked_list
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token revocation_list = self.token_revocation_list
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token File "/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1296, in token_revocation_list
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token self.token_revocation_list = self.fetch_revocation_list()
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token File "/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 1339, in fetch_revocation_list
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token raise ServiceError('Unable to fetch token revocation list.')
2014-04-25 14:29:52.947 354 TRACE keystoneclient.middleware.auth_token ServiceError: Unable to fetch token revocation list.

[Brant Knudson (blk-u)]

Note that we recently changed the auth_token middleware code to check the revocation list even for UUID tokens -- https://review.openstack.org/#/c/78241/

[Ryan Petrello (ryan-petrello)]

[DEFAULT]
logging_exception_prefix = %(color)s%(asctime)s.%(msecs)03d TRACE %(name)s %(instance)s
logging_debug_format_suffix = from (pid=%(process)d) %(funcName)s %(pathname)s:%(lineno)d
logging_default_format_string = %(asctime)s.%(msecs)03d %(color)s%(levelname)s %(name)s [-%(color)s] %(instance)s%(color)s%(message)s
logging_context_format_string = %(asctime)s.%(msecs)03d %(color)s%(levelname)s %(name)s [%(request_id)s %(user_name)s %(project_name)s%(color)s] %(instance)s%(color)s%(message)s
admin_token = secrete
admin_bind_host = 192.168.100.2
admin_endpoint = http://192.168.100.2:%(admin_port)s/
public_endpoint = http://192.168.100.2:%(public_port)s/

#
# Options defined in keystone
#

# A "shared secret" that can be used to bootstrap Keystone.
# This "token" does not represent a user, and carries no
# explicit authorization. To disable in production (highly
# recommended), remove AdminTokenAuthMiddleware from your
# paste application pipelines (for example, in keystone-
# paste.ini). (string value)
#admin_token=ADMIN

# The IP address of the network interface for the public
# service to listen on. (string value)
# Deprecated group/name - [DEFAULT]/bind_host
#public_bind_host=0.0.0.0

# The IP address of the network interface for the admin
# service to listen on. (string value)
# Deprecated group/name - [DEFAULT]/bind_host
#admin_bind_host=0.0.0.0

# The port which the OpenStack Compute service listens on.
# (integer value)
#compute_port=8774

# The port number which the admin service listens on. (integer
# value)
#admin_port=35357

# The port number which the public service listens on.
# (integer value)
#public_port=5000

# The base public endpoint URL for Keystone that is advertised
# to clients (NOTE: this does NOT affect how Keystone listens
# for connections). Defaults to the base host URL of the
# request. E.g. a request to http://server:5000/v2.0/users
# will default to http://server:5000. You should only need to
# set this value if the base URL contains a path (e.g.
# /prefix/v2.0) or the endpoint should be found on a different
# server. (string value)
#public_endpoint=<None>

# The base admin endpoint URL for Keystone that is advertised
# to clients (NOTE: this does NOT affect how Keystone listens
# for connections). Defaults to the base host URL of the
# request. E.g. a request to http://server:35357/v2.0/users
# will default to http://server:35357. You should only need to
# set this value if the base URL contains a path (e.g.
# /prefix/v2.0) or the endpoint should be found on a different
# server. (string value)
#admin_endpoint=<None>

# onready allows you to send a notification when the process
# is ready to serve. For example, to have it notify using
# systemd, one could set shell command: "onready = systemd-
# notify --ready" or a module with notify() method: "onready =
# keystone.common.systemd". (string value)
#onready=<None>

# Enforced by optional sizelimit middleware
# (keystone.middleware:RequestBodySizeLimiter). (integer
# value)
#max_request_body_size=114688

# Limit the sizes of user & project ID/names. (integer value)
#max_param_size=64

#...

[Openstack Gerrit (openstack-gerrit)]

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

[Dolph Mathews (dolph)]

Brant: is there actually anything to fix in keystone or devstack here?

[Brant Knudson (blk-u)]

It was a change to keystoneclient that broke this recently, so my opinion is that the fix is in keystoneclient and not keystone or devstack.

[Dolph Mathews (dolph)]

Brant: Thanks!

[Dolph Mathews (dolph)]

This also raised https://bugs.launchpad.net/openstack-api-site/+bug/1314285

[Dolph Mathews (dolph)]

Elevated to critical since UUID deployments are left completely broken.

[Openstack Gerrit (openstack-gerrit)]

Reviewed: https://review.openstack.org/90472
Committed: https://git.openstack.org/cgit/openstack/python-keystoneclient/commit/?id=a03c6b9f346dfd6b838fb8175bc50191642576a2
Submitter: Jenkins
Branch: master

commit a03c6b9f346dfd6b838fb8175bc50191642576a2
Author: Brant Knudson <email address hidden>
Date: Thu May 1 14:35:20 2014 -0500

    auth_token configurable check of revocations for cached

    The auth_token middleware would fail if it couldn't fetch the
    revocation list. If the system is configured for UUID tokens then
    the revocation list may not be available.

    With this fix, the revocation list will only be checked for
    cached tokens if the new check_revocations_for_cached option
    is set to True.

    Also, this change prevents the revocation list from being
    checked twice for a PKI token that's validate off-line.

    Change-Id: I5408bbe12aefda608ebcb81cf3c7ef068b2bf2f6
    Closes-Bug: #1312858