[Bug 1832265] Re: py3: inconsistent encoding of token fields

Sat Jun 22 13:25:11 UTC 2019

Ran into a related problem during debugging of dashboard errors ("Unable
to retrieve key pairs") with a Rocky cloud & identity federation.

There was no clear indication as to why failures occurred.

https://paste.ubuntu.com/p/v5HXyyWXC2/ (full pdb trace)

At a high level I was getting validation failures for the identity
provider (which was enabled in Keystone and was otherwise correct in
terms of config) in the /v3/auth/token code path.

I narrowed it down to a validation error due to a type mismatch (bytes
vs str):

1) the error occurs in send_notification:

> /usr/lib/python3/dist-packages/keystone/auth/plugins/mapped.py(101)handle_scoped_token()->None
-> send_notification(taxonomy.OUTCOME_SUCCESS)
(Pdb) l
 96  	        # send off failed authentication notification, raise the exception
 97  	        # after sending the notification
 98  	        send_notification(taxonomy.OUTCOME_FAILURE)
 99  	        raise
100  	    else:
101  ->	        send_notification(taxonomy.OUTCOME_SUCCESS)

# ...

2) this is how the validation error looks like:

(Pdb) setattr(self, FED_CRED_KEYNAME_IDENTITY_PROVIDER, identity_provider)
*** ValueError: identity_provider failed validation: <function FederatedCredential.<lambda> at 0x7fa0016ef9d8>

3) the lambda function where the error occurs

 67  	class FederatedCredential(Credential):
 68  	    identity_provider = cadftype.ValidatorDescriptor(
 69  	        FED_CRED_KEYNAME_IDENTITY_PROVIDER,
 70  ->	        lambda x: isinstance(x, six.string_types))
 71  	    user = cadftype.ValidatorDescriptor(
 72  	        FED_CRED_KEYNAME_USER,
 73  	        lambda x: isinstance(x, six.string_types))
 74  	    groups = cadftype.ValidatorDescriptor(
 75  	        FED_CRED_KEYNAME_GROUPS,

4) type comparison (b'adfs' is the identity provider name):

((Pdb)) x
b'adfs'
((Pdb)) six.string_types
(<class 'str'>,)
((Pdb)) type(x)
<class 'bytes'>

Using a package from James' PPA helped as I am not getting errors in the
same code-path anymore.

apt policy keystone
keystone:
  Installed: 2:14.1.0-0ubuntu2~ubuntu18.04.1~ppa201906140719
  Candidate: 2:14.1.0-0ubuntu2~ubuntu18.04.1~ppa201906140719
  Version table:
 *** 2:14.1.0-0ubuntu2~ubuntu18.04.1~ppa201906140719 500

When clicking through tabs very fast I encountered a glitch which
results in the following error messages being displayed (see the
screencast in the attachment):

Error: "Unable to retrieve key pairs"/"Unable to retrieve images"/""Unable to retrieve server groups"
Warning: "Policy check failed"

I tried to set breakpoints in the same place - the same validation error
does NOT occur with the patch so this is something else unrelated to py2
vs py3 string handling.

** Attachment added: "2019-06-22-16-12-40.mkv"
   https://bugs.launchpad.net/charm-keystone-ldap/+bug/1832265/+attachment/5272335/+files/2019-06-22-16-12-40.mkv

** Also affects: cloud-archive
   Importance: Undecided
       Status: New

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to keystone in Ubuntu.
https://bugs.launchpad.net/bugs/1832265

Title:
  py3: inconsistent encoding of token fields

Status in OpenStack Keystone LDAP integration:
  Invalid
Status in Ubuntu Cloud Archive:
  New
Status in OpenStack Identity (keystone):
  In Progress
Status in keystone package in Ubuntu:
  Fix Released
Status in keystone source package in Cosmic:
  Triaged
Status in keystone source package in Disco:
  Triaged

Bug description:
  When using an LDAP domain user on a bionic-rocky cloud within horizon,
  we are unable to see the projects listed in the project selection
  drop-down, and are unable to query resources from any projects to
  which we are assigned the role Member.

  It appears that the following log entries in keystone may be helpful
  to troubleshooting this issue:

  (keystone.middleware.auth): 2019-06-10 19:47:02,700 DEBUG RBAC: auth_context: {'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_id': None, 'domain_name': None, 'group_ids': [], 'token': <TokenModel (audit_id=8_4AHHWtSQ2JjTiwU7Kh0g, audit_chain_id=['8_4AHHWtSQ2JjTiwU7Kh0g']) at 0x7fed2c7909b0>, 'user_id': b'd4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4', 'user_domain_id': '997b3e91271140feb1635eefba7c65a1', 'system_scope': None, 'project_id': None, 'project_domain_id': None, 'roles': [], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []}
  (keystone.server.flask.application): 2019-06-10 19:47:02,700 DEBUG Dispatching request to legacy mapper: /v3/users
  (keystone.server.flask.application): 2019-06-10 19:47:02,700 DEBUG SCRIPT_NAME: `/v3`, PATH_INFO: `/users/d4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4/projects`
  (routes.middleware): 2019-06-10 19:47:02,700 DEBUG Matched GET /users/d4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4/projects
  (routes.middleware): 2019-06-10 19:47:02,700 DEBUG Route path: '/users/{user_id}/projects', defaults: {'action': 'list_user_projects', 'controller': <keystone.assignment.controllers.ProjectAssignmentV3 object at 0x7fed2ec52ef0>}
  (routes.middleware): 2019-06-10 19:47:02,700 DEBUG Match dict: {'user_id': 'd4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4', 'action': 'list_user_projects', 'controller': <keystone.assignment.controllers.ProjectAssignmentV3 object at 0x7fed2ec52ef0>}
  (keystone.common.wsgi): 2019-06-10 19:47:02,700 INFO GET https://keystone.mysite:5000/v3/users/d4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4/projects
  (keystone.common.controller): 2019-06-10 19:47:02,700 DEBUG RBAC: Adding query filter params ()
  (keystone.common.authorization): 2019-06-10 19:47:02,700 DEBUG RBAC: Authorizing identity:list_user_projects(user_id=d4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4)
  (keystone.policy.backends.rules): 2019-06-10 19:47:02,701 DEBUG enforce identity:list_user_projects: {'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_id': None, 'domain_name': None, 'group_ids': [], 'token': <TokenModel (audit_id=8_4AHHWtSQ2JjTiwU7Kh0g, audit_chain_id=['8_4AHHWtSQ2JjTiwU7Kh0g']) at 0x7fed2c7909b0>, 'user_id': b'd4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4', 'user_domain_id': '997b3e91271140feb1635eefba7c65a1', 'system_scope': None, 'project_id': None, 'project_domain_id': None, 'roles': [], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []}
  (keystone.common.wsgi): 2019-06-10 19:47:02,702 WARNING You are not authorized to perform the requested action: identity:list_user_projects.

  It actually appears elsewhere in the keystone.log that there is a string which has encapsulated bytecode data in it (or vice versa).

  (keystone.common.wsgi): 2019-06-10 19:46:59,019 INFO POST https://keystone.mysite:5000/v3/auth/tokens
  (sqlalchemy.orm.path_registry): 2019-06-10 19:46:59,021 DEBUG set 'memoized_setups' on path 'EntityRegistry((<Mapper at 0x7fed2eccfc50; RevocationEvent>,))' to '{}'
  (sqlalchemy.pool.QueuePool): 2019-06-10 19:46:59,021 DEBUG Connection <pymysql.connections.Connection object at 0x7fed2c7d8320> checked out from pool
  (sqlalchemy.pool.QueuePool): 2019-06-10 19:46:59,024 DEBUG Connection <pymysql.connections.Connection object at 0x7fed2c7d8320> being returned to pool
  (sqlalchemy.pool.QueuePool): 2019-06-10 19:46:59,024 DEBUG Connection <pymysql.connections.Connection object at 0x7fed2c7d8320> rollback-on-return, via agent
  (keystone.auth.core): 2019-06-10 19:46:59,025 DEBUG MFA Rules not processed for user `b'd4fb94cfa3ce0f7829d76fe44697488e7765d88e29f5a896f57d43caadb0fad4'`. Rule list: `[]` (Enabled: `True`).
  (keystone.common.wsgi): 2019-06-10 19:46:59,025 ERROR a bytes-like object is required, not 'str'
  Traceback (most recent call last):
    File "/usr/lib/python3/dist-packages/keystone/common/wsgi.py", line 148, in __call__
      result = method(req, **params)
    File "/usr/lib/python3/dist-packages/keystone/auth/controllers.py", line 102, in authenticate_for_token
      app_cred_id=app_cred_id, parent_audit_id=token_audit_id)
    File "/usr/lib/python3/dist-packages/keystone/common/manager.py", line 116, in wrapped
      __ret_val = __f(*args, **kwargs)
    File "/usr/lib/python3/dist-packages/keystone/token/provider.py", line 251, in issue_token
      token_id, issued_at = self.driver.generate_id_and_issued_at(token)
    File "/usr/lib/python3/dist-packages/keystone/token/providers/fernet/core.py", line 61, in generate_id_and_issued_at
      app_cred_id=token.application_credential_id
    File "/usr/lib/python3/dist-packages/keystone/token/token_formatters.py", line 159, in create_token
      protocol_id, access_token_id, app_cred_id
    File "/usr/lib/python3/dist-packages/keystone/token/token_formatters.py", line 483, in assemble
      b_user_id = cls.attempt_convert_uuid_hex_to_bytes(user_id)
    File "/usr/lib/python3/dist-packages/keystone/token/token_formatters.py", line 337, in attempt_convert_uuid_hex_to_bytes
      return (True, cls.convert_uuid_hex_to_bytes(value))
    File "/usr/lib/python3/dist-packages/keystone/token/token_formatters.py", line 290, in convert_uuid_hex_to_bytes
      uuid_obj = uuid.UUID(uuid_string)
    File "/usr/lib/python3.6/uuid.py", line 137, in __init__
      hex = hex.replace('urn:', '').replace('uuid:', '')
  TypeError: a bytes-like object is required, not 'str'
  (dogpile.lock): 2019-06-10 19:46:59,087 DEBUG value creation lock <dogpile.cache.region.CacheRegion._LockWrapper object at 0x7fed27e994e0> acquired
  (dogpile.lock): 2019-06-10 19:46:59,087 DEBUG Calling creation function

To manage notifications about this bug go to:
https://bugs.launchpad.net/charm-keystone-ldap/+bug/1832265/+subscriptions