yahoo-eng-team team mailing list archive

[OpenStack Infra <1622010@xxxxxxxxxxxxxxxxxx>]

Reviewed:  https://review.openstack.org/368244
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=301b6a7bc770830485937f0b9927a26e2e5ec8c8
Submitter: Jenkins
Branch:    master

commit 301b6a7bc770830485937f0b9927a26e2e5ec8c8
Author: Lance Bragstad <lbragstad@xxxxxxxxx>
Date:   Fri Sep 9 22:10:02 2016 +0000

    Consistently round down timestamps
    
    This is one of the ways we can prevent race conditions with backends that round
    datetime objects or strings before persisting them.
    
    Change-Id: Iaee0ec8c7acd512b9d93096ce8306a2952061c7a
    Closes-Bug: 1622010


** Changed in: keystone
       Status: In Progress => Fix Released

-- 
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/1622010

Title:
  MySQL rounds timestamps

Status in OpenStack Identity (keystone):
  Fix Released

Bug description:
  It was known that MySQL would *truncate* datetimes before inserting
  them. In the process of debugging issues with making fernet the
  default, I found that MySQL will actually *round* in some cases.

  To create I did the following:

  1.) Stand up a fresh devstack
  2.) Switch `CONF [token] provider = fernet` in /etc/keystone/keystone.conf
  3.) Litter keystone with timing debug statements - http://cdn.pasteraw.com/57im8ttixkootaf7xc6t3gjr79wirz6
  4.) Run ./run_tempest.sh tempest.api.identity.admin.v3.test_users.UsersV3TestJSON.test_update_user_password repeatedly.

  The tests creates a new user, changes their password, authenticates
  for a fresh token, and expects the new token to be valid. When the
  test fails, keystone returns a 404 saying the token isn't found even
  though the token was created more than one second after the password
  was changed...

  Here is the output from tempest: http://cdn.pasteraw.com/srnx0722bfpgzx39sd9tapd0686c4yl
  Here is the output from keystone with additional logging: http://cdn.pasteraw.com/k75ivklu77ffz8eh2yqjpkb8a4b51iq

  We can see that the revocation event is being persisted at
  2016-09-09T19:54:49.664802Z. When the retrieve the revocation event
  later we can see that value has been rounded to
  2016-09-09T19:54:50.000000Z. The same is true for the event's
  issued_before key.

  What I think is happening here is that when revocation events are
  created during the last half of a second - the timestamps are getting
  rounded to the next second. This naturally works against the Fernet
  implementation because the Fernet implementation will *always*
  truncate it's issued_at time [0].

  In the worst case, if a revocation event is created at
  2016-09-09T19:54:49.664802Z it will be stored with an issued_before
  time of 2016-09-09T19:54:50.000000Z. If a Fernet token is created
  right after 2016-09-09T19:54:49.664802Z, it will have an issued_at
  time of 2016-09-09T19:54:49.000000Z, resulting in a 404 instead of a
  200.

  I did this on a devstack install on Ubuntu 16.04 and MySQL Server
  version: 5.7.13-0ubuntu0.16.04.2 (Ubuntu)

  [0]
  https://github.com/pyca/cryptography/blob/ee9710fad662616454cbf99faaaa3b47d547ccd9/src/cryptography/fernet.py#L49

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