PowerVC problem error 500 on login page : look for keystone problem
CONTEXT :
/ full on our powervc host early in the morning because of toot many powervc-diag and huge logfiles (and /tmp and /var had not their own filesystem, and thus are under /)
ERROR : impossible to connect to powerVC gui : error 500
After looking everywhere in the logs, I ran into this log /var/log/keystone/keystone.log :
2017-11-22 14:47:20.089 9119 INFO keystone.common.wsgi [req-f144035c-1d57-4d46-ba19-038b34e95ad7 - - - - -] POST https://powervchost:5000/v3/auth/tokens
2017-11-22 14:47:20.106 9119 INFO keystone.common.wsgi [req-c6d2c7e2-6f45-46aa-bc88-6154ffe8cc10 - - - - -] POST https://127.0.0.1:5000/v3/auth/tokens
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi [req-036ae534-e2f6-4997-9bcc-5c441b9598e5 - - - - -] Fernet key must be 32 url-safe base64-encoded bytes.
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 225, in __call__
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi result = method(req, **params)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 422, in authenticate_for_token
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi include_catalog, parent_audit_id=token_audit_id)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 124, in wrapped
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/provider.py", line 403, in issue_v3_token
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi parent_audit_id)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/fernet/core.py", line 61, in issue_v3_token
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi *args, **kwargs)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/common.py", line 685, in issue_v3_token
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi token_id = self._get_token_id(token_data)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/fernet/core.py", line 221, in _get_token_id
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi access_token_id=access_token_id
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/fernet/token_formatters.py", line 170, in create_token
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi token = self.pack(serialized_payload)
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/fernet/token_formatters.py", line 80, in pack
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi return self.crypto.encrypt(payload).rstrip(b'=').decode('utf-8')
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/token/providers/fernet/token_formatters.py", line 69, in crypto
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi fernet_instances = [fernet.Fernet(key) for key in keys]
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/site-packages/cryptography/fernet.py", line 37, in __init__
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi "Fernet key must be 32 url-safe base64-encoded bytes."
2017-11-22 14:47:20.243 9119 ERROR keystone.common.wsgi ValueError: Fernet key must be 32 url-safe base64-encoded bytes.
There it was (last line)!
A fernet key was truncated or in the wrong format.
a fernet what?
Here’s what I found about fernet tokens/keys (I wasn’t even aware of their existence, being a total OpenStack n00b):
What is a fernet token?
A fernet token is a bearer token that represents user authentication. Fernet tokens contain a limited amount of identity and authorization data in a MessagePacked payload. The payload is then wrapped as a Fernet message for transport, where Fernet provides the required web safe characteristics for use in URLs and headers. The data inside a fernet token is protected using symmetric encryption keys, or fernet keys.
What is a fernet key?
A fernet key is used to encrypt and decrypt fernet tokens. Each key is actually composed of two smaller keys: a 128-bit AES encryption key and a 128-bit SHA256 HMAC signing key. The keys are held in a key repository that keystone passes to a library that handles the encryption and decryption of tokens.
location, location, location
Fernet keys are located here : /etc/keystone/fernet-keys
# ls -ltr total 20 -rw------- 1 keystone keystone 44 Nov 28 03:00 2733 -rw------- 1 keystone keystone 44 Nov 28 06:00 2734 -rw------- 1 keystone keystone 44 Nov 28 09:00 2735 -rw------- 1 keystone keystone 44 Nov 28 12:00 2736 -rw------- 1 keystone keystone 44 Nov 28 14:41 0
Generated every 3 hours as it seems.
As you can see in my environment, the 3 in the middle are empty…
Why ? Because my / filesystem was full at that time (we can date the fullfilling at around midnight – 3 o’clock).
As long as these keys will be present on the system, I won’t be able to log into PowerVC GUI..
Rotation
–> We need to force-rotate the keys to generate new ones that will be correctly filled up with correct encrypting/decrypting information.
You can check the rotation expiration by issuing this command :
# powervc-config identity token_expiration Current value: 6:00:00 Default value: 6:00:00
–> so each key will be active for 6 hours, before being replaced.
From command line, source the powervcrc file to ease the interaction with Openstack, then try this command:
# source /opt/ibm/powervc/powervcrc # ls -ltr total 20 -rw------- 1 keystone keystone 44 Nov 28 03:00 2733 -rw------- 1 keystone keystone 44 Nov 28 06:00 2734 -rw------- 1 keystone keystone 44 Nov 28 09:00 2735 -rw------- 1 keystone keystone 44 Nov 28 12:00 2736 -rw------- 1 keystone keystone 44 Nov 28 14:41 0 # keystone-manage fernet_rotate --keystone-user keystone --keystone-group keystone # ls -ltr total 20 -rw------- 1 keystone keystone 44 Nov 28 06:00 2734 -rw------- 1 keystone keystone 44 Nov 28 09:00 2735 -rw------- 1 keystone keystone 44 Nov 28 12:00 2736 -rw------- 1 keystone keystone 44 Nov 28 14:41 2737 -rw------- 1 keystone keystone 44 Nov 28 14:43 0
See ? the higher index file (2733) was forced to expire and be removed, and a new one appeared(2737).
Keep doing this until all keys are properly formatted, then retry to log into PowerVC GUI, it will work !
I think I get it…
My newbie explanation (please be nice with me ) :
The thing is , that as keystone works with the highest index to encrypt/decrypt, if your oldest fernet key is empty and the other 2 (or 4 in the case of powerVC which requires 5 keys by default) are OK, it won’t work… you CAN’T have authentication if you have empty high-indexed fernet-keys… when you rotate or issue new tokens with openstack token issue, don’t forget to get rid of the extra empty keys that are higher (1 is the highest, 0 is reserved).
LINKS
