Refactor keystone.common.logging use (bug 948224)

Change-Id: I01b2b5748a2524273bb8c2b734ab22415652f739

HACKING.rst

@@ -8,6 +8,7 @@ Keystone Style Commandments
 
 General
 -------
+
 - Put two newlines between top-level code (funcs, classes, etc)
 - Put one newline between methods in classes and anywhere else
 - Do not write "except:", use "except Exception:" at the very least
@@ -15,6 +16,7 @@ General
 - Do not name anything the same name as a built-in or reserved word
 - When defining global constants, define them before functions and classes
 
+
 TODO vs FIXME
 -------------
 
@@ -23,8 +25,20 @@ TODO vs FIXME
 - FIXME(name): implies that the method/function/etc shouldn't be used until
   that code is resolved and bug fixed.
 
+Logging
+-------
+
+Use the built-in logging module, and ensure you ``getLogger``::
+
+    from keystone.common import logging
+
+    LOG = logging.getLogger(__name__)
+
+    LOG.debug('Foobar')
+
 Imports
 -------
+
 - Do not import objects, only modules
 - Do not import more than one module per line
 - Do not make relative imports
@@ -46,6 +60,7 @@ Example::
 
 Human Alphabetical Order Examples
 ---------------------------------
+
 Example::
 
   import httplib
@@ -70,6 +85,7 @@ Example::
 
 Docstrings
 ----------
+
 Example::
 
   """A one line docstring looks like this and ends in a period."""
@@ -102,6 +118,7 @@ Example::
 
 Dictionaries/Lists
 ------------------
+
 If a dictionary (dict) or list object is longer than 80 characters, its items
 should be split with newlines. Embedded iterables should have their items
 indented. Additionally, the last item in the dictionary should have a trailing
@@ -128,6 +145,7 @@ Example::
 
 Calling Methods
 ---------------
+
 Calls to methods 80 characters or longer should format each argument with
 newlines. This is not a requirement, but a guideline::
 
@@ -158,6 +176,7 @@ Rather than constructing parameters inline, it is better to break things up::
 
 Internationalization (i18n) Strings
 -----------------------------------
+
 In order to support multiple languages, we have a mechanism to support
 automatic translations of exception and log strings.
 
@@ -185,6 +204,7 @@ Example::
 
 Creating Unit Tests
 -------------------
+
 For every new feature, unit tests should be created that both test and
 (implicitly) document the usage of said feature. If submitting a patch for a
 bug that had no unit test, a new passing unit test should be added. If a

keystone/catalog/backends/templated.py

@@ -19,7 +19,7 @@ from keystone.common import logging
 from keystone.catalog.backends import kvs
 
 
-LOG = logging.getLogger('keystone.catalog.backends.templated')
+LOG = logging.getLogger(__name__)
 
 CONF = config.CONF
 config.register_str('template_file', group='catalog')

keystone/common/bufferedhttp.py

@@ -29,12 +29,16 @@ BufferedHTTPResponse.
 """
 
 from urllib import quote
-import logging
 import time
 
 from eventlet.green.httplib import (CONTINUE, HTTPConnection, HTTPMessage,
                                     HTTPResponse, HTTPSConnection, _UNKNOWN)
 
+from keystone.common import logging
+
+
+LOG = logging.getLogger(__name__)
+
 
 class BufferedHTTPResponse(HTTPResponse):
     """HTTPResponse class that buffers reading of headers"""
@@ -95,7 +99,7 @@ class BufferedHTTPConnection(HTTPConnection):
 
     def getresponse(self):
         response = HTTPConnection.getresponse(self)
-        logging.debug(('HTTP PERF: %(time).5f seconds to %(method)s '
+        LOG.debug(('HTTP PERF: %(time).5f seconds to %(method)s '
                         '%(host)s:%(port)s %(path)s)'),
            {'time': time.time() - self._connected_time, 'method': self._method,
             'host': self.host, 'port': self.port, 'path': self._path})

keystone/common/ldap/core.py

@@ -14,14 +14,13 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
-import logging
-
 import ldap
 
+from keystone.common import logging
 from keystone.common.ldap import fakeldap
 
 
-LOG = logging.getLogger('keystone.common.ldap')
+LOG = logging.getLogger(__name__)
 
 
 LDAP_VALUES = {'TRUE': True, 'FALSE': False}

keystone/common/ldap/fakeldap.py

@@ -24,12 +24,12 @@ library to work with nova.
 
 """
 
-import logging
 import re
 import shelve
 
 import ldap
 
+from keystone.common import logging
 from keystone.common import utils
 
 
@@ -40,7 +40,7 @@ SCOPE_NAMES = {
 }
 
 
-LOG = logging.getLogger('keystone.backends.ldap.fakeldap')
+LOG = logging.getLogger(__name__)
 
 
 def _match_query(query, attrs):

keystone/common/sql/nova.py

@@ -16,14 +16,14 @@
 
 """Export data from Nova database and import through Identity Service."""
 
-import logging
 import uuid
 
+from keystone.common import logging
 from keystone.contrib.ec2.backends import sql as ec2_sql
 from keystone.identity.backends import sql as identity_sql
 
 
-logger = logging.getLogger('keystone.common.sql.nova')
+LOG = logging.getLogger(__name__)
 
 
 def import_auth(data):
@@ -55,7 +55,7 @@ def _create_tenants(api, tenants):
             'enabled': True,
         }
         tenant_map[tenant['id']] = tenant_dict['id']
-        logger.debug('Create tenant %s' % tenant_dict)
+        LOG.debug('Create tenant %s' % tenant_dict)
         api.create_tenant(tenant_dict['id'], tenant_dict)
     return tenant_map
 
@@ -71,7 +71,7 @@ def _create_users(api, users):
             'enabled': True,
         }
         user_map[user['id']] = user_dict['id']
-        logger.debug('Create user %s' % user_dict)
+        LOG.debug('Create user %s' % user_dict)
         api.create_user(user_dict['id'], user_dict)
     return user_map
 
@@ -80,7 +80,7 @@ def _create_memberships(api, memberships, user_map, tenant_map):
     for membership in memberships:
         user_id = user_map[membership['user_id']]
         tenant_id = tenant_map[membership['tenant_id']]
-        logger.debug('Add user %s to tenant %s' % (user_id, tenant_id))
+        LOG.debug('Add user %s to tenant %s' % (user_id, tenant_id))
         api.add_user_to_tenant(tenant_id, user_id)
 
 
@@ -92,7 +92,7 @@ def _create_roles(api, roles):
             'name': role,
         }
         role_map[role] = role_dict['id']
-        logger.debug('Create role %s' % role_dict)
+        LOG.debug('Create role %s' % role_dict)
         api.create_role(role_dict['id'], role_dict)
     return role_map
 
@@ -102,7 +102,7 @@ def _assign_roles(api, assignments, role_map, user_map, tenant_map):
         role_id = role_map[assignment['role']]
         user_id = user_map[assignment['user_id']]
         tenant_id = tenant_map[assignment['tenant_id']]
-        logger.debug('Assign role %s to user %s on tenant %s' %
+        LOG.debug('Assign role %s to user %s on tenant %s' %
                      (role_id, user_id, tenant_id))
         api.add_role_to_user_and_tenant(user_id, tenant_id, role_id)
 
@@ -117,6 +117,6 @@ def _create_ec2_creds(ec2_api, identity_api, ec2_creds, user_map):
                 'user_id': user_id,
                 'tenant_id': tenant_id,
             }
-            logger.debug('Creating ec2 cred for user %s and tenant %s' %
+            LOG.debug('Creating ec2 cred for user %s and tenant %s' %
                           (user_id, tenant_id))
             ec2_api.create_credential(None, cred_dict)

keystone/common/utils.py

@@ -37,6 +37,7 @@ from keystone.common import logging
 CONF = config.CONF
 config.register_int('crypt_strength', default=40000)
 
+LOG = logging.getLogger(__name__)
 
 ISO_TIME_FORMAT = '%Y-%m-%dT%H:%M:%SZ'
 
@@ -48,7 +49,7 @@ def import_class(import_str):
         __import__(mod_str)
         return getattr(sys.modules[mod_str], class_str)
     except (ImportError, ValueError, AttributeError), exc:
-        logging.debug('Inner Exception: %s', exc)
+        LOG.debug('Inner Exception: %s', exc)
         raise
 
 
@@ -163,7 +164,7 @@ class Ec2Signer(object):
 
     def _calc_signature_2(self, params, verb, server_string, path):
         """Generate AWS signature version 2 string."""
-        logging.debug('using _calc_signature_2')
+        LOG.debug('using _calc_signature_2')
         string_to_sign = '%s\n%s\n%s\n' % (verb, server_string, path)
         if self.hmac_256:
             current_hmac = self.hmac_256
@@ -179,13 +180,13 @@ class Ec2Signer(object):
             val = urllib.quote(val, safe='-_~')
             pairs.append(urllib.quote(key, safe='') + '=' + val)
         qs = '&'.join(pairs)
-        logging.debug('query string: %s', qs)
+        LOG.debug('query string: %s', qs)
         string_to_sign += qs
-        logging.debug('string_to_sign: %s', string_to_sign)
+        LOG.debug('string_to_sign: %s', string_to_sign)
         current_hmac.update(string_to_sign)
         b64 = base64.b64encode(current_hmac.digest())
-        logging.debug('len(b64)=%d', len(b64))
+        LOG.debug('len(b64)=%d', len(b64))
-        logging.debug('base64 encoded digest: %s', b64)
+        LOG.debug('base64 encoded digest: %s', b64)
         return b64
 
 
@@ -250,7 +251,7 @@ def check_output(*popenargs, **kwargs):
     """
     if 'stdout' in kwargs:
         raise ValueError('stdout argument not allowed, it will be overridden.')
-    logging.debug(' '.join(popenargs[0]))
+    LOG.debug(' '.join(popenargs[0]))
     process = subprocess.Popen(stdout=subprocess.PIPE, *popenargs, **kwargs)
     output, unused_err = process.communicate()
     retcode = process.poll()

keystone/common/wsgi.py

@@ -21,7 +21,6 @@
 """Utility methods for working with WSGI servers."""
 
 import json
-import logging
 import sys
 
 import eventlet
@@ -34,9 +33,13 @@ import webob.dec
 import webob.exc
 
 from keystone import exception
+from keystone.common import logging
 from keystone.common import utils
 
 
+LOG = logging.getLogger(__name__)
+
+
 class WritableLogger(object):
     """A thin wrapper that responds to `write` and logs."""
 
@@ -61,7 +64,7 @@ class Server(object):
 
     def start(self, key=None, backlog=128):
         """Run a WSGI server with the given application."""
-        logging.debug('Starting %(arg0)s on %(host)s:%(port)s' %
+        LOG.debug('Starting %(arg0)s on %(host)s:%(port)s' %
                       {'arg0': sys.argv[0],
                        'host': self.host,
                        'port': self.port})
@@ -83,9 +86,9 @@ class Server(object):
 
     def _run(self, application, socket):
         """Start a WSGI server in a new green thread."""
-        logger = logging.getLogger('eventlet.wsgi.server')
+        log = logging.getLogger('eventlet.wsgi.server')
         eventlet.wsgi.server(socket, application, custom_pool=self.pool,
-                             log=WritableLogger(logger))
+                             log=WritableLogger(log))
 
 
 class Request(webob.Request):
@@ -163,7 +166,7 @@ class Application(BaseApplication):
         arg_dict = req.environ['wsgiorg.routing_args'][1]
         action = arg_dict.pop('action')
         del arg_dict['controller']
-        logging.debug('arg_dict: %s', arg_dict)
+        LOG.debug('arg_dict: %s', arg_dict)
 
         # allow middleware up the stack to provide context & params
         context = req.environ.get('openstack.context', {})
@@ -180,7 +183,7 @@ class Application(BaseApplication):
         try:
             result = method(context, **params)
         except exception.Error as e:
-            logging.warning(e)
+            LOG.warning(e)
             return render_exception(e)
 
         if result is None:
@@ -295,21 +298,21 @@ class Debug(Middleware):
 
     @webob.dec.wsgify(RequestClass=Request)
     def __call__(self, req):
-        logging.debug('%s %s %s', ('*' * 20), 'REQUEST ENVIRON', ('*' * 20))
+        LOG.debug('%s %s %s', ('*' * 20), 'REQUEST ENVIRON', ('*' * 20))
         for key, value in req.environ.items():
-            logging.debug('%s = %s', key, value)
+            LOG.debug('%s = %s', key, value)
-        logging.debug('')
+        LOG.debug('')
-        logging.debug('%s %s %s', ('*' * 20), 'REQUEST BODY', ('*' * 20))
+        LOG.debug('%s %s %s', ('*' * 20), 'REQUEST BODY', ('*' * 20))
         for line in req.body_file:
-            logging.debug(line)
+            LOG.debug(line)
-        logging.debug('')
+        LOG.debug('')
 
         resp = req.get_response(self.application)
 
-        logging.debug('%s %s %s', ('*' * 20), 'RESPONSE HEADERS', ('*' * 20))
+        LOG.debug('%s %s %s', ('*' * 20), 'RESPONSE HEADERS', ('*' * 20))
         for (key, value) in resp.headers.iteritems():
-            logging.debug('%s = %s', key, value)
+            LOG.debug('%s = %s', key, value)
-        logging.debug('')
+        LOG.debug('')
 
         resp.app_iter = self.print_generator(resp.app_iter)
 
@@ -318,10 +321,10 @@ class Debug(Middleware):
     @staticmethod
     def print_generator(app_iter):
         """Iterator that prints the contents of a wrapper string."""
-        logging.debug('%s %s %s', ('*' * 20), 'RESPONSE BODY', ('*' * 20))
+        LOG.debug('%s %s %s', ('*' * 20), 'RESPONSE BODY', ('*' * 20))
         for part in app_iter:
             #sys.stdout.write(part)
-            logging.debug(part)
+            LOG.debug(part)
             #sys.stdout.flush()
             yield part
         print

keystone/middleware/auth_token.py

@@ -99,7 +99,7 @@ import webob
 import webob.exc
 
 
-logger = logging.getLogger('keystone.middleware.auth_token')
+LOG = logging.getLogger(__name__)
 
 
 class InvalidUserToken(Exception):
@@ -114,7 +114,7 @@ class AuthProtocol(object):
     """Auth Middleware that handles authenticating client calls."""
 
     def __init__(self, app, conf):
-        logger.info('Starting keystone auth_token middleware')
+        LOG.info('Starting keystone auth_token middleware')
         self.conf = conf
         self.app = app
 
@@ -153,11 +153,11 @@ class AuthProtocol(object):
             try:
                 import memcache
                 import iso8601
-                logger.info('Using memcache for caching token')
+                LOG.info('Using memcache for caching token')
                 self._cache = memcache.Client(memcache_servers.split(','))
                 self._iso8601 = iso8601
             except NameError as e:
-                logger.warn('disabled caching due to missing libraries %s', e)
+                LOG.warn('disabled caching due to missing libraries %s', e)
 
     def __call__(self, env, start_response):
         """Handle incoming request.
@@ -166,7 +166,7 @@ class AuthProtocol(object):
         we can't authenticate.
 
         """
-        logger.debug('Authenticating user token')
+        LOG.debug('Authenticating user token')
         try:
             self._remove_auth_headers(env)
             user_token = self._get_user_token_from_header(env)
@@ -177,15 +177,15 @@ class AuthProtocol(object):
 
         except InvalidUserToken:
             if self.delay_auth_decision:
-                logger.info('Invalid user token - deferring reject downstream')
+                LOG.info('Invalid user token - deferring reject downstream')
                 self._add_headers(env, {'X-Identity-Status': 'Invalid'})
                 return self.app(env, start_response)
             else:
-                logger.info('Invalid user token - rejecting request')
+                LOG.info('Invalid user token - rejecting request')
                 return self._reject_request(env, start_response)
 
         except ServiceError, e:
-            logger.critical('Unable to obtain admin token: %s' % e)
+            LOG.critical('Unable to obtain admin token: %s' % e)
             resp = webob.exc.HTTPServiceUnavailable()
             return resp(env, start_response)
 
@@ -207,7 +207,7 @@ class AuthProtocol(object):
             'X-Tenant',
             'X-Role',
         )
-        logger.debug('Removing headers from request environment: %s' %
+        LOG.debug('Removing headers from request environment: %s' %
                      ','.join(auth_headers))
         self._remove_headers(env, auth_headers)
 
@@ -285,7 +285,7 @@ class AuthProtocol(object):
             response = conn.getresponse()
             body = response.read()
         except Exception, e:
-            logger.error('HTTP connection exception: %s' % e)
+            LOG.error('HTTP connection exception: %s' % e)
             raise ServiceError('Unable to communicate with keystone')
         finally:
             conn.close()
@@ -293,7 +293,7 @@ class AuthProtocol(object):
         try:
             data = json.loads(body)
         except ValueError:
-            logger.debug('Keystone did not return json-encoded body')
+            LOG.debug('Keystone did not return json-encoded body')
             data = {}
 
         return response, data
@@ -356,13 +356,13 @@ class AuthProtocol(object):
             self._cache_store_invalid(user_token)
             raise InvalidUserToken('Token authorization failed')
         if response.status == 401:
-            logger.info('Keystone rejected admin token, resetting')
+            LOG.info('Keystone rejected admin token, resetting')
             self.admin_token = None
         else:
-            logger.error('Bad response code while validating token: %s' %
+            LOG.error('Bad response code while validating token: %s' %
                          response.status)
         if retry:
-            logger.info('Retrying validation')
+            LOG.info('Retrying validation')
             return self._validate_user_token(user_token, False)
         else:
             raise InvalidUserToken()
@@ -470,15 +470,15 @@ class AuthProtocol(object):
             key = 'tokens/%s' % token
             cached = self._cache.get(key)
             if cached == 'invalid':
-                logger.debug('Cached Token %s is marked unauthorized', token)
+                LOG.debug('Cached Token %s is marked unauthorized', token)
                 raise InvalidUserToken('Token authorization failed')
             if cached:
                 data, expires = cached
                 if time.time() < float(expires):
-                    logger.debug('Returning cached token %s', token)
+                    LOG.debug('Returning cached token %s', token)
                     return data
                 else:
-                    logger.debug('Cached Token %s seems expired', token)
+                    LOG.debug('Cached Token %s seems expired', token)
 
     def _cache_put(self, token, data):
         """Put token data into the cache.
@@ -492,9 +492,9 @@ class AuthProtocol(object):
                 timestamp = data['access']['token']['expires']
                 expires = self._iso8601.parse_date(timestamp).strftime('%s')
             else:
-                logger.error('invalid token format')
+                LOG.error('invalid token format')
                 return
-            logger.debug('Storing %s token in memcache', token)
+            LOG.debug('Storing %s token in memcache', token)
             self._cache.set(key,
                             (data, expires),
                             time=self.token_cache_time)
@@ -503,7 +503,7 @@ class AuthProtocol(object):
         """Store invalid token in cache."""
         if self._cache:
             key = 'tokens/%s' % token
-            logger.debug('Marking token %s as unauthorized in memcache', token)
+            LOG.debug('Marking token %s as unauthorized in memcache', token)
             self._cache.set(key,
                             'invalid',
                             time=self.token_cache_time)

keystone/policy/backends/rules.py

@@ -40,7 +40,7 @@ CONF = config.CONF
 CONF.register_opts(policy_opts)
 
 
-LOG = logging.getLogger('keystone.policy.backends.rules')
+LOG = logging.getLogger(__name__)
 
 
 _POLICY_PATH = None

keystone/test.py

@@ -31,6 +31,7 @@ from keystone.common import utils
 from keystone.common import wsgi
 
 
+LOG = logging.getLogger(__name__)
 ROOTDIR = os.path.dirname(os.path.dirname(__file__))
 VENDOR = os.path.join(ROOTDIR, 'vendor')
 TESTSDIR = os.path.join(ROOTDIR, 'tests')
@@ -80,7 +81,7 @@ def checkout_vendor(repo, rev):
         with open(modcheck, 'w') as fd:
             fd.write('1')
     except subprocess.CalledProcessError as e:
-        logging.warning('Failed to checkout %s', repo)
+        LOG.warning('Failed to checkout %s', repo)
     cd(working_dir)
     return revdir