Bug 1142424

+++ This bug was initially created as a clone of Bug #1141615 +++

Description of problem:

Seeing some errors in keystone logs
2014-09-15 02:56:42.758 11094 ERROR keystoneclient.common.cms [-] Signing error: Error opening signer certificate /etc/keystone/ssl/certs/signing_cert.pem
140528271488928:error:02001002:system library:fopen:No such file or directory:bss_file.c:398:fopen('/etc/keystone/ssl/certs/signing_cert.pem','r')
140528271488928:error:20074002:BIO routines:FILE_CTRL:system lib:bss_file.c:400:
unable to load certificate

2014-09-15 02:56:42.758 11094 ERROR keystoneclient.common.cms [-] Signing error: Unable to load certificate - ensure you have configured PKI with "keystone-manage pki_setup"
2014-09-15 02:56:42.758 11094 ERROR keystone.common.wsgi [-] Command 'openssl' returned non-zero exit status 3
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi Traceback (most recent call last):
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 207, in __call__
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi     result = method(context, **params)
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/controller.py", line 152, in inner
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi     return f(self, context, *args, **kwargs)
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/token/controllers.py", line 440, in revocation_list
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi     CONF.signing.keyfile)
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 294, in cms_sign_text
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi     signing_key_file_name)
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystoneclient/common/cms.py", line 340, in cms_sign_data
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi     raise subprocess.CalledProcessError(retcode, 'openssl')
2014-09-15 02:56:42.758 11094 TRACE keystone.common.wsgi CalledProcessError: Command 'openssl' returned non-zero exit status 3

We have provider config in place but still seems to be bitching here. 
[token]
provider=keystone.token.providers.uuid.Provider

All the RedHat Docs here: https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux_OpenStack_Platform/5/html/Installation_and_Configuration_Guide/sect-Configure_the_Identity_Service.html
Would seem to indicate using the [signing] section and config options in keystone.conf for this.  However that was supposed to be deprecated in favor the of the provider config under token section.


Version-Release number of selected component (if applicable):
openstack-keystone-2014.1.1-1.el7ost.noarch

--- Additional comment from RHEL Product and Program Management on 2014-09-14 23:41:59 EDT ---

Since this issue was entered in bugzilla, the release flag has been
set to ? to ensure that it is properly evaluated for this release.

--- Additional comment from Nathan Kinder on 2014-09-15 11:01:31 EDT ---

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?

--- Additional comment from Ken Schroeder on 2014-09-15 11:29:33 EDT ---

[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

--- Additional comment from Nathan Kinder on 2014-09-15 15:23:12 EDT ---

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?

--- Additional comment from Ken Schroeder on 2014-09-16 00:19:35 EDT ---

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.

--- Additional comment from Nathan Kinder on 2014-09-16 00:37:47 EDT ---

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

--- Additional comment from Ken Schroeder on 2014-09-16 00:51:04 EDT ---

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

--- Additional comment from Nathan Kinder on 2014-09-16 14:06:56 EDT ---

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