Bug 1141615

I am unable to reproduce this problem.  I've moved/renamed my /etc/keystone/ssl directory and changed the token provider to the 'uuid' token provider in the '[token]' section of keystone.conf.  Tokens are issued and no errors are logged:

----------------------------------------------------------------------
[nkinder@rhos ~(keystone_admin)]$ rpm -q openstack-keystone
openstack-keystone-2014.1.2.1-2.el7ost.noarch
[nkinder@rhos ~(keystone_admin)]$ sudo grep keystone.token.providers /etc/keystone/keystone.conf 
# "keystone.token.providers.[pki|uuid].Provider". (string
#provider=keystone.token.providers.pki.Provider
provider=keystone.token.providers.uuid.Provider
[nkinder@rhos ~(keystone_admin)]$ keystone token-get
+-----------+----------------------------------+
|  Property |              Value               |
+-----------+----------------------------------+
|  expires  |       2014-09-15T15:55:07Z       |
|     id    | f0132a5ad6d340d8911dd238d93c5193 |
| tenant_id | e6dec8be305d4dcbb1b62befe92619bd |
|  user_id  |             keystone             |
+-----------+----------------------------------+
----------------------------------------------------------------------

If I switch back to the 'pki' token provider with my renamed ssl directory, then I see errors like those reported:

-------------------------------------------------------------------------------
2014-09-15 10:53:07.463 25811 ERROR keystoneclient.common.cms [-] Signing error: Error opening signer certificate /etc/keystone/ssl/certs/signing_cert.pem
140039752165280:error:02001002:system library:fopen:No such file or directory:bss_file.c:398:fopen('/etc/keystone/ssl/certs/signing_cert.pem','r')
140039752165280:error:20074002:BIO routines:FILE_CTRL:system lib:bss_file.c:400:
unable to load certificate

2014-09-15 10:53:07.463 25811 ERROR keystoneclient.common.cms [-] Signing error: Unable to load certificate - ensure you have configured PKI with "keystone-manage pki_setup"
2014-09-15 10:53:07.464 25811 ERROR keystone.token.providers.pki [-] Unable to sign token
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki Traceback (most recent call last):
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki   File "/usr/lib/python2.7/site-packages/keystone/token/providers/pki.py", line 39, in _get_token_id
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki     CONF.signing.keyfile)
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 348, in cms_sign_token
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki     output = cms_sign_data(text, signing_cert_file_name, signing_key_file_name)
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 340, in cms_sign_data
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki     raise subprocess.CalledProcessError(retcode, 'openssl')
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki CalledProcessError: Command 'openssl' returned non-zero exit status 3
2014-09-15 10:53:07.464 25811 TRACE keystone.token.providers.pki
2014-09-15 10:53:07.464 25811 WARNING keystone.common.wsgi [-] An unexpected error prevented the server from fulfilling your request.
-------------------------------------------------------------------------------

Would we be able to see a copy of the keystone.conf from the affected system?  Specifically, the '[signing]' and '[token]' sections?

[signing]

#
# Options defined in keystone
#

# Deprecated in favor of provider in the [token] section.
# (string value)
#token_format=<None>

# Path of the certfile for token signing. (string value)
#certfile=/etc/keystone/ssl/certs/signing_cert.pem

# Path of the keyfile for token signing. (string value)
#keyfile=/etc/keystone/ssl/private/signing_key.pem

# Path of the CA for token signing. (string value)
#ca_certs=/etc/keystone/ssl/certs/ca.pem

# Path of the CA Key for token signing. (string value)
#ca_key=/etc/keystone/ssl/private/cakey.pem

# Key Size (in bits) for token signing cert (auto generated
# certificate). (integer value)
#key_size=2048

# Day the token signing cert is valid for (auto generated
# certificate). (integer value)
#valid_days=3650

# Certificate Subject (auto generated certificate) for token
# signing. (string value)
#cert_subject=/C=US/ST=Unset/L=Unset/O=Unset/CN=www.example.com



[token]

#
# Options defined in keystone
#

# External auth mechanisms that should add bind information to
# token e.g. kerberos, x509. (list value)
#bind=

# Enforcement policy on tokens presented to keystone with bind
# information. One of disabled, permissive, strict, required
# or a specifically required bind mode e.g. kerberos or x509
# to require binding to that authentication. (string value)
#enforce_token_bind=permissive

# Amount of time a token should remain valid (in seconds).
# (integer value)
#expiration=3600
expiration=3600

# Controls the token construction, validation, and revocation
# operations. Core providers are
# "keystone.token.providers.[pki|uuid].Provider". (string
# value)
#provider=<None>
provider=keystone.token.providers.uuid.Provider

# Keystone Token persistence backend driver. (string value)
#driver=keystone.token.backends.sql.Token
driver=keystone.token.backends.sql.Token

# Toggle for token system cacheing. This has no effect unless
# global caching is enabled. (boolean value)
#caching=true

# Time to cache the revocation list and the revocation events
# if revoke extension is enabled (in seconds). This has no
# effect unless global and token caching are enabled. (integer
# value)
#revocation_cache_time=3600

# Time to cache tokens (in seconds). This has no effect unless
# global and token caching are enabled. (integer value)
#cache_time=<None>

# Revoke token by token identifier.  Setting revoke_by_id to
# True enables various forms of enumerating tokens, e.g. `list
# tokens for user`.  These enumerations are processed to
# determine the list of tokens to revoke.   Only disable if
# you are switching to using the Revoke extension with a
# backend other than KVS, which stores events in memory.
# (boolean value)
#revoke_by_id=true

This is strange.  Our config seems to be the same.  I have nothing other than comments in the '[signing]' section, and these are the only uncommented settings in my '[token]' section:

---------------------------------------------------
[token]
expiration=3600
provider=keystone.token.providers.uuid.Provider
driver=keystone.token.backends.sql.Token
---------------------------------------------------

What operation are you performing when you get the error?  Are you performing a v2 or v3 token request?

I've not had any luck in figuring out how to reproduce this issue. Any v2.0 or v3 request tests I ran did not generate the error. I enabled debug and included some additional output when this error is occurring.  


2014-09-16 04:12:18.853 1796 DEBUG keystone.middleware.core [-] RBAC: auth_context: {} process_request /usr/lib/python2.7/site-packages/keystone/middleware/core.py:281
2014-09-16 04:12:18.857 1796 DEBUG keystone.common.wsgi [-] arg_dict: {} __call__ /usr/lib/python2.7/site-packages/keystone/common/wsgi.py:181
2014-09-16 04:12:18.858 1796 WARNING keystone.common.controller [-] RBAC: Bypassing authorization
2014-09-16 04:12:18.913 1796 ERROR keystoneclient.common.cms [-] Signing error: Error opening signer certificate /etc/keystone/ssl/certs/signing_cert.pem
140340188632992:error:02001002:system library:fopen:No such file or directory:bss_file.c:398:fopen('/etc/keystone/ssl/certs/signing_cert.pem','r')
140340188632992:error:20074002:BIO routines:FILE_CTRL:system lib:bss_file.c:400:
unable to load certificate

2014-09-16 04:12:18.913 1796 ERROR keystoneclient.common.cms [-] Signing error: Unable to load certificate - ensure you have configured PKI with "keystone-manage pki_setup"
2014-09-16 04:12:18.913 1796 ERROR keystone.common.wsgi [-] Command 'openssl' returned non-zero exit status 3
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi Traceback (most recent call last):
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 212, in __call__
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi     result = method(context, **params)
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/controller.py", line 152, in inner
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi     return f(self, context, *args, **kwargs)
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/token/controllers.py", line 443, in revocation_list
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi     CONF.signing.keyfile)
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 294, in cms_sign_text
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi     signing_key_file_name)
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 340, in cms_sign_data
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi     raise subprocess.CalledProcessError(retcode, 'openssl')
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi CalledProcessError: Command 'openssl' returned non-zero exit status 3
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi 
2014-09-16 04:12:18.916 1796 INFO eventlet.wsgi.server [-] 10.114.197.135 - - [16/Sep/2014 04:12:18] "GET /v2.0/tokens/revoked HTTP/1


Strangely enough looking through log data it would seem that this error is popping up nearly exactly every 15 minutes. So it would seem to indicate something cron/schedule drivin is generating this error.  There are currently no external systems connected here outside of Rados Gateways so its pretty contained at the moment.  

In general system is behaving and we're not seeing general auth errors, just trying to established a clean baseline and this is one open issue.

(In reply to Ken Schroeder from comment #5)
> Strangely enough looking through log data it would seem that this error is
> popping up nearly exactly every 15 minutes. So it would seem to indicate
> something cron/schedule drivin is generating this error.  There are
> currently no external systems connected here outside of Rados Gateways so
> its pretty contained at the moment.  

The 15 minute interval is a very good clue.  The call stack also indicates that this is related to the token revocation list:

--------------------------------------------------------------------------
2014-09-16 04:12:18.913 1796 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/token/controllers.py", line 443, in revocation_list
--------------------------------------------------------------------------

Something is trying to fetch the revocation list every 15 minutes, and the revocation list only applies when using PKI format tokens.  There are a few things here to point out:

- Keystone should detect that the token provider is not set to 'pki' and return a more sane response to the requester of the revocation list (as opposed to blowing up when calling openssl)

- We need to track down which other service is attempting to fetch the revocation list on a 15 minute interval.

Yeah agree.  FYI I also updated my packages to openstack-keystone-2014.1.2.1-1.el7ost.noarch so there are no deltas.

I think the culprit sending the revocation list requests is the RADOS gateway.  It defaults to a 15 minute interval when fetching the revocation list from Keystone:

-------------------------------------------------------------------------------
OPTION(rgw_keystone_revocation_interval, OPT_INT, 15 * 60)  // seconds between tokens revocation check
-------------------------------------------------------------------------------

The interval setting is defined in your ceph.conf, though the implicit default mentioned above will be used if it's not specified in the config file.  There are some details on this here:

  http://ceph.com/docs/master/radosgw/keystone/

I do not see a way to disable revocation list fetching in the Ceph source code.  It would be nice to be able to set the interval in ceph.conf to a value like 0 or -1 to indicate that revocation list fetching should not be performed.  Without this, I would expect that Ceph will log errors if Keystone is changed to return a failure response when one attempts to fetch the revocation list when the token provider is 'uuid'.

I have created a clone bug to handle the Ceph side of this issue as bug 1142424.  The Keystone side of things will be dealt with here in this bug.

After some more investigation, it is possible to simple configure certificates for signing of the revocation list when using UUID tokens.  Keystone currently only supports signed revocation lists, which requires you to set up certificates in the same way that you would when using PKI tokens.  You would need to set up your certificates as specified here:

  https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux_OpenStack_Platform/5/html/Cloud_Administrator_Guide/certificates-for-pki.html

You would then need to set up Ceph to be able to validate the revocation list signature by importing and trusting the Keystone certificate as described here:

  http://ceph.com/docs/master/radosgw/keystone/

I would expect that these errors will be eliminated if you follow these procedures.

Ken - Have you had any luck with generating the signing key/cert and setting up the certificate trust on your RADOS gateway?  I'd like to confirm that doing so resolves the errors you are seeing.

Keystone requires the key/cert setup for revocation lists to work, even when using the UUID token format.  We can make this clear in the documentation, but I'd like to confirm that it resolves your errors before changing this over to a documentation bug.

Since this is not critical issue we have not yet made any changes to the system to address this. We will be pushing out updates next week and will try to incorporate fix to this in our automation baseline.

There is a bug/improvement to make here, and that is that the puppet-keystone module should allow one to have the signing key/cert configured (and optionally created) automatically when the token provider is UUID.  It currently only sets up the key/cert if the provider is PKI.

I have filed a bug and proposed a fix for this upstream:

  https://launchpad.net/bugs/1373064
  https://review.openstack.org/#/c/123547/

code merged to the patches branch

can  have qe ack for this bug? 
thanks!

To verify this bug check that: certfile, keyfile, ca_certs, ca_key in keystone configuration file are set.

[root@aqua-vds1 keystone]# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.1 (Maipo)
[root@aqua-vds1 keystone]# ls /etc/yum.repos.d/
redhat.repo  rhel-optional.repo  rhel-server.repo  rhos-release-5-rhel-7.1.repo  rhos-release.repo
[root@aqua-vds1 keystone]# egrep "^certfile|^keyfile|^ca_certs" keystone.conf 
certfile=/etc/keystone/ssl/certs/signing_cert.pem
keyfile=/etc/keystone/ssl/private/signing_key.pem
ca_certs=/etc/keystone/ssl/certs/ca.pem
[root@aqua-vds1 keystone]#

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-0831.html