Comment 0 for bug 1622010

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.