Keystone 500 on OPTIONS

[Honza Pokorny]

When trying to authenticate against https://192.168.24.2/keystone/v3/auth/tokens with CORS (the OPTIONS req), I get a 500 error. Inside the keystone container, the logs have this:

018-11-05 19:01:33.396 230 DEBUG keystone.common.rbac_enforcer.enforcer [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] RBAC: Policy Enforcement Cred Data `identity:validate_token creds(service_project_id=None, service_user_id=None, service_user_domain_id=None, service_project_domain_id=None, trustor_id=None, user_domain_id=default, domain_id=None, trust_id=None, project_domain_id=default, service_roles=[], group_ids=[], user_id=f2ff68e4483344268c959e3dcf6b8b45, roles=[u'member', u'reader', u'admin'], system_scope=None, trustee_id=None, domain_name=None, is_admin_project=True, token=*** (audit_id=RyLKr6cyRLC2p6oV5-52Cg, audit_chain_id=[u'RyLKr6cyRLC2p6oV5-52Cg']) at 0x7f371cf0dc50>, project_id=53568db657e445a49d40a25c4a7fdd42)` enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:418
2018-11-05 19:01:33.396 230 DEBUG keystone.common.rbac_enforcer.enforcer [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] RBAC: Policy Enforcement Target Data `identity:validate_token => target(target.token.user.domain.id=default, target.token.user_id=5f351e642aa54a1abc20726ffe9bcc04)` enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:426
2018-11-05 19:01:33.415 230 DEBUG keystone.common.rbac_enforcer.enforcer [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] RBAC: Authorization granted enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:432
2018-11-05 19:01:33.425 230 ERROR keystone.assignment.core [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] Circular reference found role inference rules - 5be439ef59e949b28f7e38599a828374.
2018-11-05 19:01:33.433 230 ERROR keystone.assignment.core [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] Circular reference found role inference rules - 5be439ef59e949b28f7e38599a828374.
2018-11-05 19:01:33.447 230 ERROR keystone.assignment.core [req-def53dc3-9ac5-4470-9d21-7f737534dc90 f2ff68e4483344268c959e3dcf6b8b45 53568db657e445a49d40a25c4a7fdd42 - default default] Circular reference found role inference rules - 5be439ef59e949b28f7e38599a828374.

This is blocking the tripleo-ui because I can't log in. It's a brand new install using reproducer in RDO cloud. The deployment finished successfully.

[Jason E. Rist (jason-rist)]

<jrist> hi all. we've got a bug in tripleo that seems like it's keystone. does anyone have a moment to look? https://bugs.launchpad.net/bugs/1801778
<openstack> Launchpad bug 1801778 in tripleo "Keystone circular reference on OPTIONS" [High,Triaged]
<lbragstad> jrist it's detecting a circular reference in your roles
<jrist> it sort of seemed like that. do you happen to have any insight on how we might go about fixing?
<jrist> I'm clueless.
<lbragstad> specifically, the role implication has a circular reference
<lbragstad> jrist you can query the implied role linkage using openstackclient
<lbragstad> `openstack implied role list` should give you that information, which you should be able to use to track down the circular reference
<lbragstad> biab
<jrist> thanks lbragstad

[Honza Pokorny (hpokorny)]

(undercloud) [zuul@undercloud ~]$ openstack implied role list
+----------------------------------+-----------------+----------------------------------+-------------------+
| Prior Role ID | Prior Role Name | Implied Role ID | Implied Role Name |
+----------------------------------+-----------------+----------------------------------+-------------------+
| 5be439ef59e949b28f7e38599a828374 | member | 173c66dac9604457a0ae504ae0bd4e4b | reader |
| a2af4503e7994045adecdab4dd1831e2 | admin | 5be439ef59e949b28f7e38599a828374 | member |
+----------------------------------+-----------------+----------------------------------+-------------------+
(undercloud) [zuul@undercloud ~]$

[Honza Pokorny (hpokorny)]

This might be easier to read:

(undercloud) [zuul@undercloud ~]$ openstack implied role list -f json
[
  {
    "Implied Role Name": "reader",
    "Prior Role Name": "member",
    "Implied Role ID": "173c66dac9604457a0ae504ae0bd4e4b",
    "Prior Role ID": "5be439ef59e949b28f7e38599a828374"
  },
  {
    "Implied Role Name": "member",
    "Prior Role Name": "admin",
    "Implied Role ID": "5be439ef59e949b28f7e38599a828374",
    "Prior Role ID": "a2af4503e7994045adecdab4dd1831e2"
  }
]

[Honza Pokorny (hpokorny)]

The var/log/containers/httpd/keystone/keystone_wsgi_main_error.log file has the following error as a direct response to the OPTIONS request:

[Tue Nov 06 18:57:11.413600 2018] [:error] [pid 2951] [remote 192.168.24.1:37626] AssertionError: PROGRAMMING ERROR: enforcement (`keystone.common.rbac_enforcer.enforcer.RBACKEnforcer.enforce_call()`) has not been called; API is unenforced.

[Honza Pokorny (hpokorny)]

This error seems to come from the newly introduced keystone.server.flask.request_processing middleware:

https://github.com/openstack/keystone/commits/master/keystone/server/flask/request_processing

[Honza Pokorny (hpokorny)]

Here are some logs:

2018-11-09 16:01:35.944 2950 DEBUG keystone.server.flask.request_processing.req_logging [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] REQUEST_METHOD: `GET` log_request_info /usr/lib/python2.7/site-packages/keystone/server/flask/request_processing/req_logging.py:27
2018-11-09 16:01:35.944 2950 DEBUG keystone.server.flask.request_processing.req_logging [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] SCRIPT_NAME: `` log_request_info /usr/lib/python2.7/site-packages/keystone/server/flask/request_processing/req_logging.py:28
2018-11-09 16:01:35.944 2950 DEBUG keystone.server.flask.request_processing.req_logging [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] PATH_INFO: `/v3/auth/tokens` log_request_info /usr/lib/python2.7/site-packages/keystone/server/flask/request_processing/req_logging.py:29
2018-11-09 16:01:35.945 2950 DEBUG keystone.common.fernet_utils [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] Loaded 2 Fernet keys from /etc/keystone/fernet-keys, but `[fernet_tokens] max_active_keys = 5`; perhaps there have not been enough key rotations to reach `max_active_keys` yet? load_keys /usr/lib/python2.7/site-packages/keystone/common/fernet_utils.py:307
2018-11-09 16:01:35.952 2950 DEBUG keystone.common.rbac_enforcer.enforcer [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] RBAC: Authorizing `identity:validate_token()` enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:410
2018-11-09 16:01:35.953 2950 DEBUG keystone.common.rbac_enforcer.enforcer [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] RBAC: Policy Enforcement Cred Data `identity:validate_token creds(service_project_id=None, service_user_id=None, service_user_domain_id=None, service_project_domain_id=None, trustor_id=None, user_domain_id=default, domain_id=None, trust_id=None, project_domain_id=default, service_roles=[], group_ids=[], user_id=fd3bbebfac87486c97ed7dc5091d604f, roles=[u'admin'], system_scope=None, trustee_id=None, domain_name=None, is_admin_project=True, token=*** (audit_id=i98r6xYhRXWMLpFzydG0AQ, audit_chain_id=[u'i98r6xYhRXWMLpFzydG0AQ']) at 0x7fd651650a50>, project_id=1e43121813974b8d9c2cf5502b56dc88)` enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:418
2018-11-09 16:01:35.953 2950 DEBUG keystone.common.rbac_enforcer.enforcer [req-4424851b-93ac-4d82-925a-832142745a04 fd3bbebfac87486c97ed7dc5091d604f 1e43121813974b8d9c2cf5502b56dc88 - default default] RBAC: Policy Enforcement Target Data `identity:validate_token => target(target.token.user.domain.id=default, target.token.user_id=fd3bbebfac87486c97ed7dc5091d604f)` enforce_call /usr/lib/python2.7/site-packages/keystone/common/rbac_enforcer/enforcer.py:426
2018-11...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/617062

[Morgan Fainberg (mdrnstm)]

The 500 error in keystone is due to additional enforcement we have to make sure all API calls are enforced. OPTIONS is handled by flask and therefore needs to be exempted.

The circular reference bit seems to be something else in how the roles are being created.

I've added Keystone to the bug so that the 500 error (which is somewhat of a red herring to the circular reference bit) can be addressed.

[Adam Young (ayoung)]

The circular referne code is to detect a cycle like admin->member->admin. It should be thrown at the implied-rule creation time. I suspect something has created an improper inference rule. Can you check?

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/617062
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=8d0ad2c93b57b00187e5e02f6fe440c6b3592018
Submitter: Zuul
Branch: master

commit 8d0ad2c93b57b00187e5e02f6fe440c6b3592018
Author: Morgan Fainberg <email address hidden>
Date: Fri Nov 9 19:21:44 2018 -0800

    Correct HTTP OPTIONS method

    When HTTP OPTIONS method was used, keystone was incorrectly classifying
    the request to require enforcement. OPTIONS is handled automatically
    by flask and needs no additional implementation. It is now explicitly
    exempted from the "unenforced api" assertion.

    Change-Id: Ifdb850c1fbc10c05108466ad68d808f3f5c20b37
    closes-bug: #1801778

[Honza Pokorny (hpokorny)]

The above patch does in fact fix the issue for me. Thanks!

[Morgan Fainberg (mdrnstm)]

Marking this as invalid in Triple-O, there is an underlying issue in keystone causing the "recursive" error. The OPTIONS bug solved the issue directly.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 15.0.0.0rc1 release candidate.