Issues when using fernet tokens in Keystone

[Logan V]

When using fernet tokens in a 2 keystone container configuration behind haproxy I get a bunch of these in my keystone logs:
2015-10-26 14:08:31.771 7600 WARNING keystone.middleware.core [-] RBAC: Invalid token
2015-10-26 14:08:31.771 7600 WARNING keystone.common.wsgi [-] The request you have made requires authentication.

This commonly causes heat deployment to fail:
TASK: [os_heat | Ensure heat_stack_user role] *********************************
ok: [oscontroller5_heat_apis_container-7d02e7e1]

TASK: [os_heat | Ensure heat domain] ******************************************
ok: [oscontroller5_heat_apis_container-7d02e7e1]

TASK: [os_heat | Ensure heat project] *****************************************
ok: [oscontroller5_heat_apis_container-7d02e7e1]

TASK: [os_heat | Ensure heat user] ********************************************
failed: [oscontroller5_heat_apis_container-7d02e7e1] => {"changed": true, "cmd": ". /root/openrc\n openstack --os-identity-api-version=3 --os-auth-url=http://x.x.x.x:35357/v3 --os-project-name=admin --os-project-domain-name=Default --os-user-domain-name=Default user create --or-show --domain heat --password <removed> \"stack_domain_admin\"", "delta": "0:00:01.151826", "end": "2015-10-26 14:19:00.055889", "rc": 1, "start": "2015-10-26 14:18:58.904063", "warnings": []}
stderr: ERROR: openstack The request you have made requires authentication. (HTTP 401) (Request-ID: req-5a30cf63-90f9-4f7a-a1d1-a0ac8fb84be6)
FATAL: all hosts have already failed -- aborting

And keystone logs during this..
2015-10-26 14:18:58.406 7605 INFO keystone.common.wsgi [-] POST http://x.x.x.x:35357/v3/domains
2015-10-26 14:18:58.407 7605 WARNING keystone.common.controller [-] RBAC: Bypassing authorization
2015-10-26 14:18:58.422 7605 WARNING keystone.common.wsgi [-] Conflict occurred attempting to store domain - Duplicate Entry
2015-10-26 14:18:58.771 7611 INFO keystone.common.wsgi [-] GET http://x.x.x.x:35357/v3/domains
2015-10-26 14:18:58.771 7611 WARNING keystone.common.controller [-] RBAC: Bypassing authorization
2015-10-26 14:18:59.378 7609 INFO keystone.common.wsgi [-] POST http://x.x.x.x:35357/v3/auth/tokens
2015-10-26 14:18:59.545 7609 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:18:59.545 7609 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:18:59.719 7615 INFO keystone.common.wsgi [-] GET http://x.x.x.x:35357/v3/
2015-10-26 14:18:59.825 7616 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:18:59.826 7616 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:18:59.827 7616 WARNING keystone.middleware.core [-] RBAC: Invalid token
2015-10-26 14:18:59.827 7616 WARNING keystone.common.wsgi [-] The request you have made requires authentication.
2015-10-26 14:19:00.012 7606 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:19:00.014 7606 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:19:00.015 7606 WARNING keystone.middleware.core [-] RBAC: Invalid token
2015-10-26 14:19:00.015 7606 WARNING keystone.common.wsgi [-] The request you have made requires authentication.

Also when this happens, deployment fails or horizon denies logins:

Log below while trying to log into horizon:
2015-10-26 14:08:31.673 7601 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:31.674 7601 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:31.675 7601 WARNING keystone.middleware.core [-] RBAC: Invalid token
2015-10-26 14:08:31.675 7601 WARNING keystone.common.wsgi [-] The request you have made requires authentication.
2015-10-26 14:08:31.769 7600 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:31.770 7600 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:31.771 7600 WARNING keystone.middleware.core [-] RBAC: Invalid token
2015-10-26 14:08:31.771 7600 WARNING keystone.common.wsgi [-] The request you have made requires authentication.
2015-10-26 14:08:32.585 7616 INFO keystone.common.wsgi [-] OPTIONS http://oscontroller5_keystone_container-b237c6ec:35357/
2015-10-26 14:08:33.842 7615 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:33.842 7615 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:33.924 7615 INFO keystone.common.wsgi [-] GET http://x.x.x.x:35357/v3/auth/tokens
2015-10-26 14:08:33.925 7615 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:33.926 7615 INFO keystone.token.providers.fernet.utils [-] Loaded 2 encryption keys from: /etc/keystone/fernet-keys
2015-10-26 14:08:33.926 7615 WARNING keystone.common.wsgi [-] This is not a recognized Fernet token

Horizon login failure log:
[Mon Oct 26 19:11:47.492630 2015] [:error] [pid 2768:tid 140563208566528] Internal Server Error: /auth/login/
[Mon Oct 26 19:11:47.492669 2015] [:error] [pid 2768:tid 140563208566528] Traceback (most recent call last):
[Mon Oct 26 19:11:47.492681 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/core/handlers/base.py", line 111, in get_response
[Mon Oct 26 19:11:47.492691 2015] [:error] [pid 2768:tid 140563208566528] response = wrapped_callback(request, *callback_args, **callback_kwargs)
[Mon Oct 26 19:11:47.492701 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/debug.py", line 76, in sensitive_post_parameters_wrapper
[Mon Oct 26 19:11:47.492710 2015] [:error] [pid 2768:tid 140563208566528] return view(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492720 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/utils/decorators.py", line 105, in _wrapped_view
[Mon Oct 26 19:11:47.492732 2015] [:error] [pid 2768:tid 140563208566528] response = view_func(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492742 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/cache.py", line 52, in _wrapped_view_func
[Mon Oct 26 19:11:47.492752 2015] [:error] [pid 2768:tid 140563208566528] response = view_func(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492763 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/openstack_dashboard/wsgi/../../openstack_auth/views.py", line 111, in login
[Mon Oct 26 19:11:47.492774 2015] [:error] [pid 2768:tid 140563208566528] **kwargs)
[Mon Oct 26 19:11:47.492784 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/debug.py", line 76, in sensitive_post_parameters_wrapper
[Mon Oct 26 19:11:47.492794 2015] [:error] [pid 2768:tid 140563208566528] return view(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492804 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/utils/decorators.py", line 105, in _wrapped_view
[Mon Oct 26 19:11:47.492815 2015] [:error] [pid 2768:tid 140563208566528] response = view_func(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492825 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/cache.py", line 52, in _wrapped_view_func
[Mon Oct 26 19:11:47.492836 2015] [:error] [pid 2768:tid 140563208566528] response = view_func(request, *args, **kwargs)
[Mon Oct 26 19:11:47.492846 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/contrib/auth/views.py", line 37, in login
[Mon Oct 26 19:11:47.492856 2015] [:error] [pid 2768:tid 140563208566528] if form.is_valid():
[Mon Oct 26 19:11:47.492894 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/forms/forms.py", line 162, in is_valid
[Mon Oct 26 19:11:47.492905 2015] [:error] [pid 2768:tid 140563208566528] return self.is_bound and not bool(self.errors)
[Mon Oct 26 19:11:47.492915 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/forms/forms.py", line 154, in errors
[Mon Oct 26 19:11:47.492926 2015] [:error] [pid 2768:tid 140563208566528] self.full_clean()
[Mon Oct 26 19:11:47.492936 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/forms/forms.py", line 354, in full_clean
[Mon Oct 26 19:11:47.492946 2015] [:error] [pid 2768:tid 140563208566528] self._clean_form()
[Mon Oct 26 19:11:47.492955 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/forms/forms.py", line 378, in _clean_form
[Mon Oct 26 19:11:47.492966 2015] [:error] [pid 2768:tid 140563208566528] cleaned_data = self.clean()
[Mon Oct 26 19:11:47.492977 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/debug.py", line 36, in sensitive_variables_wrapper
[Mon Oct 26 19:11:47.492987 2015] [:error] [pid 2768:tid 140563208566528] return func(*func_args, **func_kwargs)
[Mon Oct 26 19:11:47.492998 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/openstack_dashboard/wsgi/../../openstack_auth/forms.py", line 122, in clean
[Mon Oct 26 19:11:47.493009 2015] [:error] [pid 2768:tid 140563208566528] auth_url=region)
[Mon Oct 26 19:11:47.493019 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/django/contrib/auth/__init__.py", line 60, in authenticate
[Mon Oct 26 19:11:47.493029 2015] [:error] [pid 2768:tid 140563208566528] user = backend.authenticate(**credentials)
[Mon Oct 26 19:11:47.493039 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/openstack_dashboard/wsgi/../../openstack_auth/backend.py", line 127, in authenticate
[Mon Oct 26 19:11:47.493050 2015] [:error] [pid 2768:tid 140563208566528] unscoped_auth_ref)
[Mon Oct 26 19:11:47.493060 2015] [:error] [pid 2768:tid 140563208566528] File "/usr/local/lib/python2.7/dist-packages/openstack_dashboard/wsgi/../../openstack_auth/plugin/base.py", line 95, in list_projects
[Mon Oct 26 19:11:47.493071 2015] [:error] [pid 2768:tid 140563208566528] msg = _('Unable to retrieve authorized projects.')
[Mon Oct 26 19:11:47.493081 2015] [:error] [pid 2768:tid 140563208566528] NameError: global name '_' is not defined

Same failure after quickly patching for https://review.openstack.org/#/c/199194/ (unrelated to the fernet tokens issue, just showing that the fernet token issue still causes login failure to horizon even with the unrelated fix implemented):
[Mon Oct 26 14:14:54.376648 2015] [:info] [pid 3784:tid 140718753974016] [remote x.x.x.x:20906] mod_wsgi (pid=3784, process='horizon', application='horizon'): Loading WSGI script '/usr/local/lib/python2.7/dist-packages/openstack_dashboard/wsgi/django.wsgi'.
[Mon Oct 26 19:14:55.307609 2015] [:error] [pid 3784:tid 140718753974016] Login failed for user "admin".

If I deploy with keystone_token_provider: "keystone.token.providers.uuid.Provider", everything deploys fine and I can log in to horizon reliably etc.

A few notes:
-oscontroller4 and oscontroller5 both host keystone nodes. the failures only occur on oscontroller5.
-both keystone containers have identical configurations
-the contents of /etc/keystone/fernet-keys/* is identical on both containers
-deploying with ONLY 1 keystone container using fernet keys works fine, the bugs only happen when I deploy redundant containers
-I have tried failing the haproxy VIP between oscontroller4 and oscontroller5, no change in behavior. oscontroller4 logs remain clean and oscontroller5 logs show token issues

[Ian Cordasco (icordasc)]

Hi Logan,

Have you tried restarting both keystone services (since you've already confirmed that the contents of the fernet-keys directory is identical)? Are there any TRACE logs in either keystone.log or the apache log file?

[Logan V (loganv)]

Yes I am fairly certain I restarted apache instances on both containers as I enabled debugging in keystone.conf at some point while looking at this last weekend. I will redeploy with fernet and restart keystone, check for traces, etc. to verify but I do not recall seeing anything like that.

[Jesse Pretorius (jesse-pretorius)]

Can you provide details on which branch/tag this relates to?

[Lance Bragstad (lbragstad)]

I assume both of these nodes were deployed in the same way, so we should have to worry about permission differences between the two repositories, do we?

[Logan V (loganv)]

I am seeing it on Kilo. Will check the permissions and other items when I can redeploy with fernet again, hopefully this week after I finish up some other testing on this equipment.

[Logan V (loganv)]

I think this can be closed. I discovered clock skew between the openstack services nodes which, once fixed, has apparently resolved the issue with using fernet tokens in my env. Sorry about the bug report!

[Dolph Mathews (dolph)]

If this is due to a race condition (related to clock skew or not), then this is basically a duplicate of bug 1473567 which we're trying to fix upstream. The latest summaries of that issue is here:

  https://bugs.launchpad.net/keystone/+bug/1473567/comments/15

  https://bugs.launchpad.net/keystone/+bug/1473567/comments/17

If that accurately describes the scenario here, then this bug should be marked as a duplicate.