cannot use newly issued token immediately after admin password change

[Stefan Nica]

The following issue was observed while running an automated job which changed the password of the admin account (Pike release was used). If an admin token is issued immediately after the admin password is changed, using the token to authenticate to Keystone is met with an Unauthorized error:

{"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}

Steps to reproduce this:

1. generate a token with the current admin password:

  curl -d '{"auth":{"tenantName": "admin", "passwordCredentials": {"username": "admin", "password": "password"}}}' -H "Content-type: application/json" \
    http://cluster-data.vn1.cloud.suse.de:35357/v2.0/tokens

2. change the admin password using the token generated at step 1:

  curl -X PUT -d '{"user":{"id": "<admin-user-uuid>", "password": "newpassword"}}' \
    -H "X-Auth-Token:<token-id>" \
    -H "Content-type: application/json" \
    http://cluster-data.vn1.cloud.suse.de:35357/v2.0/users/<admin-user-uuid>/OS-KSADM/password

3. generate a token with the new admin password:

  curl -d '{"auth":{"tenantName": "admin", "passwordCredentials": {"username": "admin", "password": "newpassword"}}}' \
    -H "Content-type: application/json" \
    http://cluster-data.vn1.cloud.suse.de:35357/v2.0/tokens

4. run a simple check using the token generated at 3.:

  curl -H "X-Auth-Token:<new-token-id>" \
    http://cluster-data.vn1.cloud.suse.de:35357/v2.0/OS-KSADM/services

To reproduce this issue, step 4 needs to be executed immediately after 3. Inserting a 1-2 second delay between 3 and 4 makes the problem go away.

[Stefan Nica (stefan.nica)]

The same issue can be reproduced using v3 API calls instead of 2.0:

1. generate a token with the current admin password:

curl -i -d '{
    "auth": {
      "identity": {
        "methods": [
          "password"
        ],
        "password": {
          "user": {
            "name": "admin",
            "password": "password",
            "domain": {
              "name": "Default"
            }
          }
        }
      },
      "scope": {
        "project": {
          "name": "admin",
          "domain": {
            "name": "Default"
          }
        }
      }
    }
  }' \
  -H "Content-type: application/json" \
  http://cluster-data.vn1.cloud.suse.de:35357/v3/auth/tokens

2. change the admin password using the token generated at step 1:

curl -X PATCH -d '{
    "user": {
      "name": "admin",
      "password": "newpassword",
      "default_project_id": <admin-project-uuid>,
      "domain_id": "default",
      "enabled": true
    }
  }' \
  -H "X-Auth-Token:<token-id>" \
  -H "Content-type: application/json" \
  http://cluster-data.vn1.cloud.suse.de:35357/v3/users/<admin-user-uuid>

3. generate a token with the new admin password:

curl -i -d '{
    "auth": {
      "identity": {
        "methods": [
          "password"
        ],
        "password": {
          "user": {
            "name": "admin",
            "password": "newpassword",
            "domain": {
              "name": "Default"
            }
          }
        }
      },
      "scope": {
        "project": {
          "name": "admin",
          "domain": {
            "name": "Default"
          }
        }
      }
    }
  }' \
  -H "Content-type: application/json" \
  http://cluster-data.vn1.cloud.suse.de:35357/v3/auth/tokens

4. run a simple check using the token generated at 3.:

curl -H "X-Auth-Token:<token-id>" \
  http://cluster-data.vn1.cloud.suse.de:35357/v3/services

[Stefan Nica (stefan.nica)]

One other important aspect: I'm not using HA/haproxy, so there's only one keystone service instance involved.

[Guang Yee (guang-yee)]

I can't seem to reproduce the issue with devstack.

[Colleen Murphy (krinkle)]

I can reproduce this on master of devstack using a script like this: http://paste.openstack.org/show/720630/

The problem goes away if you introduce a sleep after the password change, or if you restart memcached. That's probably not pointing to memcached as the culprit but just demonstrating the timing issue.

I suspect this probably has to do with fernet's lack of subsecond precision, and if that's the case I don't think there's anything that can really be done besides adding an artificial wait after the password change.

[Lance Bragstad (lbragstad)]

Colleen's assessment is accurate and her workaround is about the best we have. This happens when a token is created within the same second as a revocation event (e.g. changing your password then immediately authenticating for a token). The token's creation timestamp is determined when the token is minted [0], which is handled outside of keystone.

Lack of sub-second support for creation timestamps is a known issue in the fernet specification [1], which is implemented by pyca/cryptography [2] and consumed by keystone [3]. There is an issue opened up against the fernet specification itself [4], but that hasn't moved in a while, despite our attempts to propose a subsequent version of the document.

The workaround is to make sure you pass the threshold of a new second before authenticating for a new token, which we had to work into several tempest tests when we made fernet the default token provider [5][6].

Hopefully this helps clarify why the issue still exists. Unfortunately, there isn't much we can do from a keystone perspective short of consuming a fernet implementation of an updated specification.

[0] https://github.com/pyca/cryptography/blob/611fa5a0458a36bb8b13b3e251a5cd359fa34296/src/cryptography/fernet.py#L49
[1] https://github.com/fernet/spec
[2] https://github.com/pyca/cryptography/
[3] https://github.com/openstack/keystone/blob/37ce5417418f8acbd27f3dacb70c605b0fe48301/keystone/token/token_formatters.py#L18
[4] https://github.com/fernet/spec/issues/12
[5] https://review.openstack.org/#/q/status:merged+project:openstack/tempest+branch:master+topic:bug/1473567
[6] https://bugs.launchpad.net/keystone/+bug/1473567