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...
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.
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 keystone. conf cdn.pasteraw. com/57im8ttixko otaf7xc6t3gjr79 wirz6 api.identity. admin.v3. test_users. UsersV3TestJSON .test_update_ user_password repeatedly.
2.) Switch `CONF [token] provider = fernet` in /etc/keystone/
3.) Litter keystone with timing debug statements - http://
4.) Run ./run_tempest.sh tempest.
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/srnx0722bfp gzx39sd9tapd068 6c4yl cdn.pasteraw. com/k75ivklu77f fz8eh2yqjpkb8a4 b51iq
Here is the output from keystone with additional logging: http://
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.