Fix AttributeError on cached-invalid token checks

Starting with v4.5.0, if a token is found to be cached, but is cached
with an invalid state, the middleware attempts to log a debug message
indicating as much.

However, the logger it attempts to use does not exist and results in
an AttributeError. As a result, this yields HTTP 500 responses once
the invalid token gets cached and is attempted to be used again,
rather than the expected 401.

This fixes the reference and adds a test to ensure the expected log
entry ends up in the logger so that this condition in
AuthProtocol.fetch_token now gets coverage.

Change-Id: Ie391973ea5893531c0b590ffba2d9de7f7f19d94
Closes-bug: #1584289

keystonemiddleware/auth_token/__init__.py

@@ -848,7 +848,7 @@ class AuthProtocol(BaseAuthProtocol):
 
             if cached:
                 if cached == _CACHE_INVALID_INDICATOR:
-                    self._LOG.debug('Cached token is marked unauthorized')
+                    self.log.debug('Cached token is marked unauthorized')
                     raise ksm_exceptions.InvalidToken()
 
                 if self._check_revocations_for_cached:

keystonemiddleware/tests/unit/auth_token/test_auth_token_middleware.py

@@ -269,6 +269,7 @@ class BaseAuthTokenMiddlewareTest(base.BaseAuthTokenTestCase):
     def setUp(self, expected_env=None, auth_version=None, fake_app=None):
         super(BaseAuthTokenMiddlewareTest, self).setUp()
 
+        self.logger = self.useFixture(fixtures.FakeLogger(level=logging.DEBUG))
         self.expected_env = expected_env or dict()
         self.fake_app = fake_app or FakeApp
         self.middleware = None
@@ -1005,6 +1006,23 @@ class CommonAuthTokenMiddlewareTest(object):
         self.assertEqual(auth_token._CACHE_INVALID_INDICATOR,
                          self._get_cached_token(token))
 
+    def test_memcache_hit_invalid_token(self):
+        token = 'invalid-token'
+        invalid_uri = '%s/v2.0/tokens/invalid-token' % BASE_URI
+        self.requests_mock.get(invalid_uri, status_code=404)
+
+        # Call once to cache token's invalid state; verify it cached as such
+        self.call_middleware(headers={'X-Auth-Token': token},
+                             expected_status=401)
+        self.assertEqual(auth_token._CACHE_INVALID_INDICATOR,
+                         self._get_cached_token(token))
+
+        # Call again for a cache hit; verify it detected as cached and invalid
+        self.call_middleware(headers={'X-Auth-Token': token},
+                             expected_status=401)
+        self.assertIn('Cached token is marked unauthorized',
+                      self.logger.output)
+
     def test_memcache_set_expired(self, extra_conf={}, extra_environ={}):
         token_cache_time = 10
         conf = {