auth_token middleware reporting valid token as invalid

[Matthew Edmonds]

when keystonemiddleware.auth_token.AuthProtocol.validate_token gets an unexpected Exception, it marks the token invalid in its cache with a store_invalid call [0].

        except Exception:
            self._LOG.debug('Token validation failure.', exc_info=True)
            if token_id:
                self._token_cache.store_invalid(token_id)
            self._LOG.warn(_LW('Authorization failed for token'))
            raise exc.InvalidToken(_('Token authorization failed'))

The token may or may not actually be invalid. An error getting the revocation list, for example, could (and did, it appears, in my case) lead to this. Once marked invalid in the cache, future attempts to use the token will fail until/unless the cache is reinitialized.

[0] https://github.com/openstack/keystonemiddleware/blob/ba68a74e65ad893e4beeb45b984b2514e60cbdea/keystonemiddleware/auth_token/__init__.py#L840-L845

[Matthew Edmonds (edmondsw)]

I hit this with Kilo, but it looks like Liberty has the same issue.

[Dolph Mathews (dolph)]

"except Exception" is always a red flag. It looks like that should at least have two except blocks -- one that invalidates tokens in the cache because they've been confirmed as invalid, and one that handles unknown errors.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/217373
Committed: https://git.openstack.org/cgit/openstack/keystonemiddleware/commit/?id=7dcbdf774803a92bfc24704dec5f919ac75ad315
Submitter: Jenkins
Branch: master

commit 7dcbdf774803a92bfc24704dec5f919ac75ad315
Author: Matthew Edmonds <email address hidden>
Date: Wed Aug 26 16:01:12 2015 -0400

    only make token invalid when it really is

    The auth_token middleware was marking a token invalid in the cache
    on any otherwise-uncaught exception, not only when it has really
    determined that the token is invalid. This will fix that by being
    better about using the InvalidToken exception only when the token is
    really invalid, and only marking invalid in the cache when that
    exception occurs.

    This fix uncovered a bug in the auth_token unit test
    test_composite_auth_delay_invalid_service_and_user_tokens, so that has
    been addressed as well. It was attempting to use "invalid-user-token",
    which was not initialized, where it meant to use "invalid-token". This
    was leading to a NoMockAddress exception. Prior to this fix, the code
    turned all unexpected exceptions into InvalidToken exceptions, masking
    this issue.

    It also uncovered DeprecationWarnings raised in _identity.py for usage
    of logging.warn rather than logging.warning in py34. That has also
    been fixed. As above, prior to this fix those would have been turned
    into InvalidToken exceptions (incorrectly).

    Change-Id: I2e487fb02c9171f743ecc1f4f230b29a5e96212d
    Depends-On: I635a7255112f654141ae35369ccc6f3aea425740
    Closes-Bug: #1488267

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/229478

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/229670

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/230157

[OpenStack Infra (hudson-openstack)]

Change abandoned by Steve Martinelli (<email address hidden>) on branch: stable/kilo
Review: https://review.openstack.org/229670

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/229478
Committed: https://git.openstack.org/cgit/openstack/keystonemiddleware/commit/?id=75fbc5910afad5d6dbce5506cf9b38f793a68644
Submitter: Jenkins
Branch: stable/liberty

commit 75fbc5910afad5d6dbce5506cf9b38f793a68644
Author: Matthew Edmonds <email address hidden>
Date: Wed Aug 26 16:01:12 2015 -0400

    only make token invalid when it really is

    The auth_token middleware was marking a token invalid in the cache
    on any otherwise-uncaught exception, not only when it has really
    determined that the token is invalid. This will fix that by being
    better about using the InvalidToken exception only when the token is
    really invalid, and only marking invalid in the cache when that
    exception occurs.

    This fix uncovered a bug in the auth_token unit test
    test_composite_auth_delay_invalid_service_and_user_tokens, so that has
    been addressed as well. It was attempting to use "invalid-user-token",
    which was not initialized, where it meant to use "invalid-token". This
    was leading to a NoMockAddress exception. Prior to this fix, the code
    turned all unexpected exceptions into InvalidToken exceptions, masking
    this issue.

    It also uncovered DeprecationWarnings raised in _identity.py for usage
    of logging.warn rather than logging.warning in py34. That has also
    been fixed. As above, prior to this fix those would have been turned
    into InvalidToken exceptions (incorrectly).

    Change-Id: I2e487fb02c9171f743ecc1f4f230b29a5e96212d
    Closes-Bug: #1488267
    (cherry picked from commit 7dcbdf774803a92bfc24704dec5f919ac75ad315)

[OpenStack Infra (hudson-openstack)]

Change abandoned by Steve Martinelli (<email address hidden>) on branch: stable/kilo
Review: https://review.openstack.org/230157

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/230157
Committed: https://git.openstack.org/cgit/openstack/keystonemiddleware/commit/?id=7dc6c80f5524e11d63cefd6408fc2bf727205650
Submitter: Jenkins
Branch: stable/kilo

commit 7dc6c80f5524e11d63cefd6408fc2bf727205650
Author: Matthew Edmonds <email address hidden>
Date: Wed Aug 26 16:01:12 2015 -0400

    only make token invalid when it really is

    The auth_token middleware was marking a token invalid in the cache
    on any otherwise-uncaught exception, not only when it has really
    determined that the token is invalid. This will fix that by being
    better about using the InvalidToken exception only when the token is
    really invalid, and only marking invalid in the cache when that
    exception occurs.

    This fix uncovered a bug in the auth_token unit test
    test_composite_auth_delay_invalid_service_and_user_tokens, so that has
    been addressed as well. It was attempting to use "invalid-user-token",
    which was not initialized, where it meant to use "invalid-token". This
    was leading to a NoMockAddress exception. Prior to this fix, the code
    turned all unexpected exceptions into InvalidToken exceptions, masking
    this issue.

    It also uncovered DeprecationWarnings raised in _identity.py for usage
    of logging.warn rather than logging.warning in py34. That has also
    been fixed. As above, prior to this fix those would have been turned
    into InvalidToken exceptions (incorrectly).

    Closes-Bug: #1488267
    (cherry picked from commit 7dcbdf774803a92bfc24704dec5f919ac75ad315)
    (cherry picked from commit 75fbc5910afad5d6dbce5506cf9b38f793a68644)

    Conflicts:
     keystonemiddleware/auth_token/__init__.py
     keystonemiddleware/auth_token/_identity.py
     keystonemiddleware/tests/auth_token/test_auth_token_middleware.py

    Cherry-Pick Note: The main conflict here is that webob is not used in
    this version of auth_token middleware and so you can't simply raise a
    500/503 error from deep in the code and expect it to be handled.
    Currently the ServiceError handles the 503 exception. I added a
    _InternalServiceError exception that does the same job as the similar
    webob exception.

    Change-Id: I2e487fb02c9171f743ecc1f4f230b29a5e96212d