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 <lbrags...@gmail.com> 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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp