Trust-scoped user requests failed while using fernet tokens

Bug #1525219 reported by Oleksii Chuprykov
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Fix Released
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.

Revision history for this message
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

Revision history for this message
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/

Revision history for this message
Oleksii Chuprykov (ochuprykov) wrote :

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

Revision history for this message
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)
Changed in keystone:
assignee: nobody → Boris Bobrov (bbobrov)
Revision history for this message
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  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.