yahoo-eng-team team mailing list archive

[Lance Bragstad <lbragstad@xxxxxxxxx>]

Public bug reported:

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 events
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

** Affects: keystone
     Importance: Undecided
         Status: New


** Tags: fernet revoke

** Tags added: fenet

** Tags removed: fenet
** Tags added: fernet revoke

** Description changed:

  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 events
  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.
  
  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)

** Description changed:

  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 events
  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.
+ 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)
  
- 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

-- 
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):
  New

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 events
  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