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

Deep Dive into Keystone Fernet Tokens

Share Button
PowerVC GUI : error 500

Laisser un commentaire