MySQL rounds timestamps

Bug #1622010 reported by Lance Bragstad
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Fix Released
High
Lance Bragstad

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

tags: added: fenet
tags: added: fernet revoke
removed: fenet
description: updated
description: updated
Changed in keystone:
importance: Undecided → Critical
importance: Critical → High
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (master)

Fix proposed to branch: master
Review: https://review.openstack.org/368244

Changed in keystone:
assignee: nobody → Lance Bragstad (lbragstad)
status: New → In Progress
description: updated
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (master)

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 <email address hidden>
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
Changed in keystone:
milestone: none → newton-rc1
tags: added: rc-potential
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (stable/mitaka)

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/374245

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/keystone 10.0.0.0rc1

This issue was fixed in the openstack/keystone 10.0.0.0rc1 release candidate.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (stable/mitaka)

Reviewed: https://review.openstack.org/374245
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=8d12ba37367a55ccdf3c73cc74783951c3adcb68
Submitter: Jenkins
Branch: stable/mitaka

commit 8d12ba37367a55ccdf3c73cc74783951c3adcb68
Author: Lance Bragstad <email address hidden>
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.

    Closes-Bug: 1622010
    (cherry picked from commit 301b6a7bc770830485937f0b9927a26e2e5ec8c8)

    Conflicts:
     keystone/tests/unit/test_v3_auth.py: freezegun was added only in Newton
     keystone/tests/unit/test_v3_os_revoke.py: minor conflict

    In addition to cherry-pick, time.sleep() was added to several tests.
    The tests assume that some time must pass between some operations.
    In Newton and later this was done in other, unrelated commits and
    freezegun was used. Freezegun cannot be used in Mitaka. Because of
    that, time.sleep() was added at the same places where freezegun's
    tick() is used in Newton.

    Change-Id: I7c6d525dfb4ec13edb360a77b27422310d545305

tags: added: in-stable-mitaka
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/keystone 10.0.0.0rc1

This issue was fixed in the openstack/keystone 10.0.0.0rc1 release candidate.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/keystone 9.3.0

This issue was fixed in the openstack/keystone 9.3.0 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.