Trust-scoped user requests failed while using fernet tokens

Bug #1525219 reported by Oleksii Chuprykov on 2015-12-11
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Medium
Boris Bobrov

Bug Description

1. Enable reauthentication in heat: add reauthentication_auth_method = trusts in heat.conf
2. Enable fernet tokens in keystone.
3. Create stack with the following template:

heat_template_version: 2013-05-23
parameters:
  key_name:
    type: string
    default: default
  flavor:
    type: string
    default: m1.tiny
  image:
    type: string
    default: fedora-heat-test-image

resources:
  server:
    type: OS::Nova::Server
    properties:
      image: {get_param: image}
      flavor: {get_param: flavor}

heat stack-create abc -f <template_file.yaml>

Creation stack failed.

Found this in heat logs:
2015-12-11 14:56:52.992 INFO heat.engine.resource [-] CREATE: Server "server" Stack "abc" [b1957493-41b6-437d-87af-64ebe166e6dd]
2015-12-11 14:56:52.992 TRACE heat.engine.resource Traceback (most recent call last):
2015-12-11 14:56:52.992 TRACE heat.engine.resource File "/opt/stack/heat/heat/engine/resource.py", line 636, in _action_recorder
2015-12-11 14:56:52.992 TRACE heat.engine.resource yield
2015-12-11 14:56:52.992 TRACE heat.engine.resource File "/opt/stack/heat/heat/engine/resource.py", line 703, in _do_action
2015-12-11 14:56:52.992 TRACE heat.engine.resource pre_func()
2015-12-11 14:56:52.992 TRACE heat.engine.resource File "/opt/stack/heat/heat/engine/properties.py", line 410, in validate
2015-12-11 14:56:52.992 TRACE heat.engine.resource message=ex.error_message
2015-12-11 14:56:52.992 TRACE heat.engine.resource StackValidationFailed: Property error: server.Properties.image: Error retrieving image list from glance: 503 Service Unavailable: The server is currently unavailable. Please try again at a later time. (HTTP 503)

Found in glance log:
380cf351a6a29fbe971e3a1b32" -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}15a31c1b48e559620d731e3756fb882eb3796ef3" from (pid=3209) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:198
2015-12-11 14:56:52.987 DEBUG keystoneclient.session [-] RESP: [403] Content-Length: 131 Vary: X-Auth-Token Keep-Alive: timeout=5, max=99 Server: Apache/2.4.7 (Ubuntu) Connection: Keep-Alive Date: Fri, 11 Dec 2015 12:56:52 GMT Content-Type: application/json x-openstack-request-id: req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8
RESP BODY: {"error": {"message": "User is not a trustee. (Disable debug mode to suppress these details.)", "code": 403, "title": "Forbidden"}}
 from (pid=3209) _http_log_response /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:216
2015-12-11 14:56:52.987 DEBUG keystoneclient.session [-] Request returned failure status: 403 from (pid=3209) request /usr/local/lib/python2.7/dist-packages/keystoneclient/session.py:401
2015-12-11 14:56:52.989 ERROR keystonemiddleware.auth_token [-] Bad response code while validating token: 403
2015-12-11 14:56:52.989 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "User is not a trustee. (Disable debug mode to suppress these details.)", "code": 403, "title": "Forbidden"}}
2015-12-11 14:56:52.989 CRITICAL keystonemiddleware.auth_token [-] Unable to validate token: Failed to fetch token data from identity server

Keystone logs:
2015-12-11 14:56:52.975204 10268 DEBUG keystone.middleware.auth [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] RBAC: auth_context: {'is_delegated_auth': False, 'access_token_id': None, 'user_id': u'be1cc1b5290a4e8c9e54abea7d247d77', 'roles': [u'service'], 'user_domain_id': u'default', 'trustee_id': None, 'trustor_id': None, 'consumer_id': None, 'token': <KeystoneToken (audit_id=BApjKcwhT5ycn7fFpBCshg, audit_chain_id=BApjKcwhT5ycn7fFpBCshg) at 0x7fc51e4e8990>, 'project_id': u'4eb9350e276f49ddbea4c7d2e6f0a013', 'trust_id': None, 'project_domain_id': u'default'} process_request /opt/stack/keystone/keystone/middleware/auth.py:187
2015-12-11 14:56:52.975976 10268 INFO keystone.common.wsgi [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] GET http://192.168.122.82:35357/v3/auth/tokens
2015-12-11 14:56:52.976121 10268 DEBUG keystone.common.controller [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] RBAC: Authorizing identity:validate_token() _build_policy_check_credentials /opt/stack/keystone/keystone/common/controller.py:62
2015-12-11 14:56:52.976227 10268 DEBUG keystone.common.controller [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] RBAC: using auth context from the request environment _build_policy_check_credentials /opt/stack/keystone/keystone/common/controller.py:67
2015-12-11 14:56:52.976640 10268 WARNING keystone.token.providers.fernet.utils [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] [fernet_tokens] key_repository is world readable: /etc/keystone/fernet-keys/
2015-12-11 14:56:52.976986 10268 INFO keystone.token.providers.fernet.utils [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] Loaded 2 encryption keys (max_active_keys=3) from: /etc/keystone/fernet-keys/
2015-12-11 14:56:52.985646 10268 WARNING keystone.common.wsgi [req-cb5a4c23-85fc-4e02-a7d6-e138ae7f6ff8 be1cc1b5290a4e8c9e54abea7d247d77 4eb9350e276f49ddbea4c7d2e6f0a013 - default default] User is not a trustee. (Disable debug mode to suppress these details.)

We fail at the point where we try to retrieve glance image list by using trust-scoped token.

Boris Bobrov (bbobrov) wrote :

> Found in glance log:

Could you please post ~50 lines of glance log before the failure in it? Use http://paste.openstack.org for that

Oleksii Chuprykov (ochuprykov) wrote :

Sure, but I found that there are only 26 lines from first request to fail http://paste.openstack.org/show/481634/

Oleksii Chuprykov (ochuprykov) wrote :

Minimal reproducer on devstack: http://paste.openstack.org/show/481667/

Boris Bobrov (bbobrov) wrote :

http://paste.openstack.org/show/481789/ -- to reproduce without devstack, on standalone keystone

Changed in keystone:
status: New → Confirmed
Boris Bobrov (bbobrov) on 2015-12-14
Changed in keystone:
assignee: nobody → Boris Bobrov (bbobrov)
Boris Bobrov (bbobrov) wrote :
Changed in keystone:
status: Confirmed → Fix Committed
Changed in keystone:
milestone: none → mitaka-2
importance: Undecided → Medium
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers