openstack/python-keystoneclient
Code Issues Proposed changes

Fix middleware logging for swift

Browse Source 
Swift sets 'log_name' in the conf, and this can be used to set the
correct logger.  This patch moves the log configuration to
initialization so that the logger can be set appropriately and the
middleware will log to the swift proxy logs.  This also requires the
following review in swift to work:
https://review.openstack.org/#/c/17983/

Fixes bug #1089664

Change-Id: I315102ba277ac1f5ff92f4d79ae745bf53559328
This commit is contained in:
Chuck Thier
2012-12-12 17:11:34 -06:00
parent 095cdd1057
commit 665eeba82c
1 changed files with 49 additions and 39 deletions
Download Patch File Download Diff File Expand all files Collapse all files

88
keystoneclient/middleware/auth_token.py
View File

@@ -136,7 +136,6 @@ except ImportError:
if not CONF: if not CONF:
from keystoneclient.openstack.common import cfg from keystoneclient.openstack.common import cfg
CONF = cfg.CONF CONF = cfg.CONF
LOG = logging.getLogger(__name__)
# alternative middleware configuration in the main application's # alternative middleware configuration in the main application's
# configuration file e.g. in nova.conf # configuration file e.g. in nova.conf
@@ -193,7 +192,8 @@ class AuthProtocol(object):
"""Auth Middleware that handles authenticating client calls.""" """Auth Middleware that handles authenticating client calls."""
def __init__(self, app, conf): def __init__(self, app, conf):
LOG.info('Starting keystone auth_token middleware') self.LOG = logging.getLogger(conf.get('log_name', __name__))
self.LOG.info('Starting keystone auth_token middleware')
self.conf = conf self.conf = conf
self.app = app self.app = app
@@ -226,8 +226,8 @@ class AuthProtocol(object):
self.signing_dirname = self._conf_get('signing_dir') self.signing_dirname = self._conf_get('signing_dir')
if self.signing_dirname is None: if self.signing_dirname is None:
self.signing_dirname = '%s/keystone-signing' % os.environ['HOME'] self.signing_dirname = '%s/keystone-signing' % os.environ['HOME']
LOG.info('Using %s as cache directory for signing certificate' % self.LOG.info('Using %s as cache directory for signing certificate' %
self.signing_dirname) self.signing_dirname)
if (os.path.exists(self.signing_dirname) and if (os.path.exists(self.signing_dirname) and
not os.access(self.signing_dirname, os.W_OK)): not os.access(self.signing_dirname, os.W_OK)):
raise ConfigurationError("unable to access signing dir %s" % raise ConfigurationError("unable to access signing dir %s" %
@@ -267,11 +267,12 @@ class AuthProtocol(object):
try: try:
import memcache import memcache
import iso8601 import iso8601
LOG.info('Using memcache for caching token') self.LOG.info('Using memcache for caching token')
self._cache = memcache.Client(memcache_servers) self._cache = memcache.Client(memcache_servers)
self._iso8601 = iso8601 self._iso8601 = iso8601
except ImportError as e: except ImportError as e:
LOG.warn('disabled caching due to missing libraries %s', e) self.LOG.warn(
'disabled caching due to missing libraries %s', e)
def _conf_get(self, name): def _conf_get(self, name):
# try config from paste-deploy first # try config from paste-deploy first
@@ -287,7 +288,7 @@ class AuthProtocol(object):
we can't authenticate. we can't authenticate.
""" """
LOG.debug('Authenticating user token') self.LOG.debug('Authenticating user token')
try: try:
self._remove_auth_headers(env) self._remove_auth_headers(env)
user_token = self._get_user_token_from_header(env) user_token = self._get_user_token_from_header(env)
@@ -299,15 +300,16 @@ class AuthProtocol(object):
except InvalidUserToken: except InvalidUserToken:
if self.delay_auth_decision: if self.delay_auth_decision:
LOG.info('Invalid user token - deferring reject downstream') self.LOG.info(
'Invalid user token - deferring reject downstream')
self._add_headers(env, {'X-Identity-Status': 'Invalid'}) self._add_headers(env, {'X-Identity-Status': 'Invalid'})
return self.app(env, start_response) return self.app(env, start_response)
else: else:
LOG.info('Invalid user token - rejecting request') self.LOG.info('Invalid user token - rejecting request')
return self._reject_request(env, start_response) return self._reject_request(env, start_response)
except ServiceError as e: except ServiceError as e:
LOG.critical('Unable to obtain admin token: %s' % e) self.LOG.critical('Unable to obtain admin token: %s' % e)
resp = webob.exc.HTTPServiceUnavailable() resp = webob.exc.HTTPServiceUnavailable()
return resp(env, start_response) return resp(env, start_response)
@@ -330,8 +332,8 @@ class AuthProtocol(object):
'X-Tenant', 'X-Tenant',
'X-Role', 'X-Role',
) )
LOG.debug('Removing headers from request environment: %s' % self.LOG.debug('Removing headers from request environment: %s' %
','.join(auth_headers)) ','.join(auth_headers))
self._remove_headers(env, auth_headers) self._remove_headers(env, auth_headers)
def _get_user_token_from_header(self, env): def _get_user_token_from_header(self, env):
@@ -347,7 +349,8 @@ class AuthProtocol(object):
if token: if token:
return token return token
else: else:
LOG.warn("Unable to find authentication token in headers: %s", env) self.LOG.warn(
"Unable to find authentication token in headers: %s", env)
raise InvalidUserToken('Unable to find token in headers') raise InvalidUserToken('Unable to find token in headers')
def _reject_request(self, env, start_response): def _reject_request(self, env, start_response):
@@ -408,7 +411,7 @@ class AuthProtocol(object):
response = conn.getresponse() response = conn.getresponse()
body = response.read() body = response.read()
except Exception as e: except Exception as e:
LOG.error('HTTP connection exception: %s' % e) self.LOG.error('HTTP connection exception: %s' % e)
raise ServiceError('Unable to communicate with keystone') raise ServiceError('Unable to communicate with keystone')
finally: finally:
conn.close() conn.close()
@@ -448,7 +451,7 @@ class AuthProtocol(object):
response = conn.getresponse() response = conn.getresponse()
body = response.read() body = response.read()
except Exception as e: except Exception as e:
LOG.error('HTTP connection exception: %s' % e) self.LOG.error('HTTP connection exception: %s' % e)
raise ServiceError('Unable to communicate with keystone') raise ServiceError('Unable to communicate with keystone')
finally: finally:
conn.close() conn.close()
@@ -456,7 +459,7 @@ class AuthProtocol(object):
try: try:
data = jsonutils.loads(body) data = jsonutils.loads(body)
except ValueError: except ValueError:
LOG.debug('Keystone did not return json-encoded body') self.LOG.debug('Keystone did not return json-encoded body')
data = {} data = {}
return response, data return response, data
@@ -490,10 +493,12 @@ class AuthProtocol(object):
datetime_expiry = timeutils.parse_isotime(expiry) datetime_expiry = timeutils.parse_isotime(expiry)
return (token, timeutils.normalize_time(datetime_expiry)) return (token, timeutils.normalize_time(datetime_expiry))
except (AssertionError, KeyError): except (AssertionError, KeyError):
LOG.warn("Unexpected response from keystone service: %s", data) self.LOG.warn(
"Unexpected response from keystone service: %s", data)
raise ServiceError('invalid json response') raise ServiceError('invalid json response')
except (ValueError): except (ValueError):
LOG.warn("Unable to parse expiration time from token: %s", data) self.LOG.warn(
"Unable to parse expiration time from token: %s", data)
raise ServiceError('invalid json response') raise ServiceError('invalid json response')
def _validate_user_token(self, user_token, retry=True): def _validate_user_token(self, user_token, retry=True):
@@ -519,9 +524,9 @@ class AuthProtocol(object):
self._cache_put(token_id, data) self._cache_put(token_id, data)
return data return data
except Exception as e: except Exception as e:
LOG.debug('Token validation failure.', exc_info=True) self.LOG.debug('Token validation failure.', exc_info=True)
self._cache_store_invalid(user_token) self._cache_store_invalid(user_token)
LOG.warn("Authorization failed for token %s", user_token) self.LOG.warn("Authorization failed for token %s", user_token)
raise InvalidUserToken('Token authorization failed') raise InvalidUserToken('Token authorization failed')
def _build_user_headers(self, token_info): def _build_user_headers(self, token_info):
@@ -636,15 +641,15 @@ class AuthProtocol(object):
key = 'tokens/%s' % token key = 'tokens/%s' % token
cached = self._cache.get(key) cached = self._cache.get(key)
if cached == 'invalid': if cached == 'invalid':
LOG.debug('Cached Token %s is marked unauthorized', token) self.LOG.debug('Cached Token %s is marked unauthorized', token)
raise InvalidUserToken('Token authorization failed') raise InvalidUserToken('Token authorization failed')
if cached: if cached:
data, expires = cached data, expires = cached
if time.time() < float(expires): if time.time() < float(expires):
LOG.debug('Returning cached token %s', token) self.LOG.debug('Returning cached token %s', token)
return data return data
else: else:
LOG.debug('Cached Token %s seems expired', token) self.LOG.debug('Cached Token %s seems expired', token)
def _cache_put(self, token, data): def _cache_put(self, token, data):
"""Put token data into the cache. """Put token data into the cache.
@@ -658,9 +663,9 @@ class AuthProtocol(object):
timestamp = data['access']['token']['expires'] timestamp = data['access']['token']['expires']
expires = self._iso8601.parse_date(timestamp).strftime('%s') expires = self._iso8601.parse_date(timestamp).strftime('%s')
else: else:
LOG.error('invalid token format') self.LOG.error('invalid token format')
return return
LOG.debug('Storing %s token in memcache', token) self.LOG.debug('Storing %s token in memcache', token)
self._cache.set(key, self._cache.set(key,
(data, expires), (data, expires),
time=self.token_cache_time) time=self.token_cache_time)
@@ -669,7 +674,8 @@ class AuthProtocol(object):
"""Store invalid token in cache.""" """Store invalid token in cache."""
if self._cache: if self._cache:
key = 'tokens/%s' % token key = 'tokens/%s' % token
LOG.debug('Marking token %s as unauthorized in memcache', token) self.LOG.debug(
'Marking token %s as unauthorized in memcache', token)
self._cache.set(key, self._cache.set(key,
'invalid', 'invalid',
time=self.token_cache_time) time=self.token_cache_time)
@@ -703,20 +709,21 @@ class AuthProtocol(object):
# FIXME(ja): I'm assuming the 404 status means that user_token is # FIXME(ja): I'm assuming the 404 status means that user_token is
# invalid - not that the admin_token is invalid # invalid - not that the admin_token is invalid
self._cache_store_invalid(user_token) self._cache_store_invalid(user_token)
LOG.warn("Authorization failed for token %s", user_token) self.LOG.warn("Authorization failed for token %s", user_token)
raise InvalidUserToken('Token authorization failed') raise InvalidUserToken('Token authorization failed')
if response.status == 401: if response.status == 401:
LOG.info('Keystone rejected admin token %s, resetting', headers) self.LOG.info(
'Keystone rejected admin token %s, resetting', headers)
self.admin_token = None self.admin_token = None
else: else:
LOG.error('Bad response code while validating token: %s' % self.LOG.error('Bad response code while validating token: %s' %
response.status) response.status)
if retry: if retry:
LOG.info('Retrying validation') self.LOG.info('Retrying validation')
return self._validate_user_token(user_token, False) return self._validate_user_token(user_token, False)
else: else:
LOG.warn("Invalid user token: %s. Keystone response: %s.", self.LOG.warn("Invalid user token: %s. Keystone response: %s.",
user_token, data) user_token, data)
raise InvalidUserToken() raise InvalidUserToken()
@@ -730,8 +737,8 @@ class AuthProtocol(object):
token_id = utils.hash_signed_token(signed_text) token_id = utils.hash_signed_token(signed_text)
for revoked_id in revoked_ids: for revoked_id in revoked_ids:
if token_id == revoked_id: if token_id == revoked_id:
LOG.debug('Token %s is marked as having been revoked', self.LOG.debug('Token %s is marked as having been revoked',
token_id) token_id)
return True return True
return False return False
@@ -813,8 +820,9 @@ class AuthProtocol(object):
additional_headers=headers) additional_headers=headers)
if response.status == 401: if response.status == 401:
if retry: if retry:
LOG.info('Keystone rejected admin token %s, resetting admin ' self.LOG.info(
'token', headers) 'Keystone rejected admin token %s, resetting admin token',
headers)
self.admin_token = None self.admin_token = None
return self.fetch_revocation_list(retry=False) return self.fetch_revocation_list(retry=False)
if response.status != 200: if response.status != 200:
@@ -832,7 +840,8 @@ class AuthProtocol(object):
certfile.write(data) certfile.write(data)
certfile.close() certfile.close()
except (AssertionError, KeyError): except (AssertionError, KeyError):
LOG.warn("Unexpected response from keystone service: %s", data) self.LOG.warn(
"Unexpected response from keystone service: %s", data)
raise ServiceError('invalid json response') raise ServiceError('invalid json response')
def fetch_ca_cert(self): def fetch_ca_cert(self):
@@ -844,7 +853,8 @@ class AuthProtocol(object):
certfile.write(data) certfile.write(data)
certfile.close() certfile.close()
except (AssertionError, KeyError): except (AssertionError, KeyError):
LOG.warn("Unexpected response from keystone service: %s", data) self.LOG.warn(
"Unexpected response from keystone service: %s", data)
raise ServiceError('invalid json response') raise ServiceError('invalid json response')