| 2016-09-09 20:38:23 |
Lance Bragstad |
bug |
|
|
added bug |
| 2016-09-09 20:38:34 |
Lance Bragstad |
tags |
|
fenet |
|
| 2016-09-09 20:38:43 |
Lance Bragstad |
tags |
fenet |
fernet revoke |
|
| 2016-09-09 20:41:55 |
Lance Bragstad |
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.
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
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) |
|
| 2016-09-09 20:44:35 |
Lance Bragstad |
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.
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) |
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 |
|
| 2016-09-09 21:30:30 |
Samuel de Medeiros Queiroz |
keystone: importance |
Undecided |
Critical |
|
| 2016-09-09 21:30:33 |
Samuel de Medeiros Queiroz |
keystone: importance |
Critical |
High |
|
| 2016-09-09 22:13:15 |
OpenStack Infra |
keystone: status |
New |
In Progress |
|
| 2016-09-09 22:13:15 |
OpenStack Infra |
keystone: assignee |
|
Lance Bragstad (lbragstad) |
|
| 2016-09-12 12:52:40 |
Lance Bragstad |
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 |
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 |
|
| 2016-09-14 04:23:47 |
OpenStack Infra |
keystone: status |
In Progress |
Fix Released |
|
| 2016-09-14 04:39:14 |
Steve Martinelli |
keystone: milestone |
|
newton-rc1 |
|
| 2016-09-14 04:39:22 |
Steve Martinelli |
tags |
fernet revoke |
fernet rc-potential revoke |
|
| 2016-10-06 19:02:15 |
OpenStack Infra |
tags |
fernet rc-potential revoke |
fernet in-stable-mitaka rc-potential revoke |
|
