yahoo-eng-team team mailing list archive

[Nikita Kalyanov <1840647@xxxxxxxxxxxxxxxxxx>]

Public bug reported:

When trying to validate user token through Keystone an inconsistent behavior is observed:
The very first request for a given user to Keystone is successful, while the second and subsequent requests for the same user result in a Key Error in Keystone _decrypt_credential method and thus auth failure (See the attached traceback). The problem is observed by merely repeating the same aws-cli commands for the same user 2 or more times.

After inserting some debug log messages in core.py the problem seem to
happen in _get_credential method in keystone.credential.core:

In first request to Keystone:
Aug 15 20:14:13 ubuntu-vm6 devstack@keystone.service[22678]: #033[00;36mINFO keystone.credential.core [#033[01;36mNone req-14485eaa-4172-4074-ac28-aa22fea7ce32 #033[00;36mNone None#033[00;36m] #033[01;35m#033[00;36mcontents of credential after _get_credential are user_id=u'4ad247ca077743078bf6109ff5c57dc1', key_hash=u'716d67b1efbe8c7b46d13e6f4b5ccfbe095a3f73', encrypted_blob=u'gAAAAABdVZLCpdDXGjdHk3kglftCMUDnxOKWNuLR6_6ZJtVTFt7VvJ-Y7VzyfxO6JwDv88OQtSMlJzbG8hUcfFftqhH6l5jpx6eNXdhTpO6_ZF57xyey1BmFI8JYh-PWdJkYtfDsOWJzCyWACQaUXU9N2J_r83xEYx691ToCwGCrkL-NgfFX-hVy3dYl9_4-5HcCOR4RoK2VXjLdvuAjWdvWCAxiVs-kxARpT0jkoZP1dnw-zs3pgDE=', project_id=u'9be611818d0b4bac82ea0d468f91541b', type=u'ec2', id=u'11755be627c5e6f22f3a31062afbd631bbe0f3176701ea23e5284920ded89e76'#033[00m#033[00m

In second request to Keystone:
Aug 15 20:14:43 ubuntu-vm6 devstack@keystone.service[22678]: #033[00;36mINFO keystone.credential.core [#033[01;36mNone req-4e4cc471-f9c7-461b-9245-65f8ac8c843b #033[00;36mNone None#033[00;36m] #033[01;35m#033[00;36mcontents of credential after _get_credential are user_id=u'4ad247ca077743078bf6109ff5c57dc1', blob=u'{"access": "09b2bb6d93ff47098198ceaf060baa8a", "secret": "d25c0c2c4ef542a29f84e7924ec89773", "trust_id": null}', project_id=u'9be611818d0b4bac82ea0d468f91541b', type=u'ec2', id=u'11755be627c5e6f22f3a31062afbd631bbe0f3176701ea23e5284920ded89e76'#033[00m#033[00m


=> Basically _get_credential method returns normal encrypted credential (encrypted_blob) for the first call, and an unencrypted credential (blob) for the second and subsequent calls by the same credential_id after 30 seconds. After that, the already decrypted credential incorrectly returned by _get_credential is passed to _decrypt_credential which fails because there is no 'encrypted_blob' key in the dictionary. The stack trace for the second and subsequent calls led to a package named 'dogpile' and some cache-related methods inside it.

The problem seem to happen due to in-place modification of the
credential dictionary in _decrypt_credential method. During the first
request to Keystone the normal encrypted credential dictionary is
returned by _get_credential method and the returned result is cached.
However, after that the credential dictionary is modified in-place by
_decrypt_credential method. For the second and subsequent calls to the
_get_credential for the same user it tries to return the result from
cache. But the cached result has been modified by _decrypt_credential.
So, the already decrypted during first request credential is returned
and passed again to _decrypt_credential breaking it.

The solution is to modify a copy of the credential dictionary inside
_decrypt_credential method, not the original credential in-place (the
same approach as in _encrypt_credential where a copy is modified). This
way the encrypted value of the credential is cached and it does not gets
modified afterwards. So the normal encrypted credential is returned from
cache and passed to _decrypt_credential again and again even for the
same user which fixes the problem.

** Affects: keystone
     Importance: Undecided
         Status: New

** Attachment added: "The traceback of an Auth Failure to Keystone. The 'Key Error' in the credential dictionary is seen at the bottom of the trace."
   https://bugs.launchpad.net/bugs/1840647/+attachment/5283312/+files/keystone_traceback.txt

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1840647

Title:
  EC2 API Auth Failure

Status in OpenStack Identity (keystone):
  New

Bug description:
  When trying to validate user token through Keystone an inconsistent behavior is observed:
  The very first request for a given user to Keystone is successful, while the second and subsequent requests for the same user result in a Key Error in Keystone _decrypt_credential method and thus auth failure (See the attached traceback). The problem is observed by merely repeating the same aws-cli commands for the same user 2 or more times.

  After inserting some debug log messages in core.py the problem seem to
  happen in _get_credential method in keystone.credential.core:

  In first request to Keystone:
  Aug 15 20:14:13 ubuntu-vm6 devstack@keystone.service[22678]: #033[00;36mINFO keystone.credential.core [#033[01;36mNone req-14485eaa-4172-4074-ac28-aa22fea7ce32 #033[00;36mNone None#033[00;36m] #033[01;35m#033[00;36mcontents of credential after _get_credential are user_id=u'4ad247ca077743078bf6109ff5c57dc1', key_hash=u'716d67b1efbe8c7b46d13e6f4b5ccfbe095a3f73', encrypted_blob=u'gAAAAABdVZLCpdDXGjdHk3kglftCMUDnxOKWNuLR6_6ZJtVTFt7VvJ-Y7VzyfxO6JwDv88OQtSMlJzbG8hUcfFftqhH6l5jpx6eNXdhTpO6_ZF57xyey1BmFI8JYh-PWdJkYtfDsOWJzCyWACQaUXU9N2J_r83xEYx691ToCwGCrkL-NgfFX-hVy3dYl9_4-5HcCOR4RoK2VXjLdvuAjWdvWCAxiVs-kxARpT0jkoZP1dnw-zs3pgDE=', project_id=u'9be611818d0b4bac82ea0d468f91541b', type=u'ec2', id=u'11755be627c5e6f22f3a31062afbd631bbe0f3176701ea23e5284920ded89e76'#033[00m#033[00m

  In second request to Keystone:
  Aug 15 20:14:43 ubuntu-vm6 devstack@keystone.service[22678]: #033[00;36mINFO keystone.credential.core [#033[01;36mNone req-4e4cc471-f9c7-461b-9245-65f8ac8c843b #033[00;36mNone None#033[00;36m] #033[01;35m#033[00;36mcontents of credential after _get_credential are user_id=u'4ad247ca077743078bf6109ff5c57dc1', blob=u'{"access": "09b2bb6d93ff47098198ceaf060baa8a", "secret": "d25c0c2c4ef542a29f84e7924ec89773", "trust_id": null}', project_id=u'9be611818d0b4bac82ea0d468f91541b', type=u'ec2', id=u'11755be627c5e6f22f3a31062afbd631bbe0f3176701ea23e5284920ded89e76'#033[00m#033[00m

  
  => Basically _get_credential method returns normal encrypted credential (encrypted_blob) for the first call, and an unencrypted credential (blob) for the second and subsequent calls by the same credential_id after 30 seconds. After that, the already decrypted credential incorrectly returned by _get_credential is passed to _decrypt_credential which fails because there is no 'encrypted_blob' key in the dictionary. The stack trace for the second and subsequent calls led to a package named 'dogpile' and some cache-related methods inside it.

  The problem seem to happen due to in-place modification of the
  credential dictionary in _decrypt_credential method. During the first
  request to Keystone the normal encrypted credential dictionary is
  returned by _get_credential method and the returned result is cached.
  However, after that the credential dictionary is modified in-place by
  _decrypt_credential method. For the second and subsequent calls to the
  _get_credential for the same user it tries to return the result from
  cache. But the cached result has been modified by _decrypt_credential.
  So, the already decrypted during first request credential is returned
  and passed again to _decrypt_credential breaking it.

  The solution is to modify a copy of the credential dictionary inside
  _decrypt_credential method, not the original credential in-place (the
  same approach as in _encrypt_credential where a copy is modified).
  This way the encrypted value of the credential is cached and it does
  not gets modified afterwards. So the normal encrypted credential is
  returned from cache and passed to _decrypt_credential again and again
  even for the same user which fixes the problem.

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1840647/+subscriptions