Improve logging format and configuration

This patch adda an 'origin' argument to the logger formatting that
coms from the configuration parser and ties a log entry to the
implementing class as well as the specific configuration facility
that instantiated it.

Also adds per configuration section debugging unless the global
debug statment is true, in which case all objects have debugging
forcibly turned on.

Signed-off-by: Simo Sorce <simo@redhat.com>
Reviewed-by: Christian Heimes <cheimes@redhat.com>

11 files changed, 146 insertions, 142 deletions

diff --git a/custodia/custodia b/custodia/custodia
index 56652de..8d69dea 100755
--- a/custodia/custodia
+++ b/custodia/custodia
@@ -82,20 +82,19 @@ def parse_config(cfgfile):
             raise ValueError('Invalid section, missing "handler"')
 
         handler = None
-        hconf = None
+        hconf = {'facility_name': s}
         for opt, val in parser.items(s):
             if opt == 'handler':
                 try:
                     module, classname = val.rsplit('.', 1)
                     m = importlib.import_module(module)
                     handler = getattr(m, classname)
+                    hconf['facility_name'] = '%s-[%s]' % (classname, s)
                 except Exception as e:  # pylint: disable=broad-except
                     raise ValueError('Invalid format for "handler" option '
                                      '[%r]: %s' % (e, val))
 
             else:
-                if hconf is None:
-                    hconf = dict()
                 hconf[opt] = val
         config[menu][name] = handler(hconf)
 
diff --git a/custodia/httpd/authenticators.py b/custodia/httpd/authenticators.py
index 854fdc7..ecd3d30 100644
--- a/custodia/httpd/authenticators.py
+++ b/custodia/httpd/authenticators.py
@@ -1,6 +1,5 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
-import logging
 import os
 
 from cryptography.hazmat.primitives import constant_time
@@ -8,14 +7,8 @@ from cryptography.hazmat.primitives import constant_time
 from custodia import log
 from custodia.httpd.server import HTTPError
 
-logger = logging.getLogger(__name__)
 
-
-class HTTPAuthenticator(object):
-
-    def __init__(self, config=None):
-        self.config = config
-        self._auditlog = log.auditlog
+class HTTPAuthenticator(log.CustodiaPlugin):
 
     def handle(self, request):
         raise HTTPError(403)
@@ -35,19 +28,19 @@ class SimpleCredsAuth(HTTPAuthenticator):
     def handle(self, request):
         creds = request.get('creds')
         if creds is None:
-            logger.debug('SCA: Missing "creds" from request')
+            self.logger.debug('SCA: Missing "creds" from request')
             return False
         uid = int(creds['gid'])
         gid = int(creds['uid'])
         if self._gid == gid or self._uid == uid:
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTH_PASS,
-                                      request['client_id'],
-                                      "SCA", "%d, %d" % (uid, gid))
+            self.audit_svc_access(log.AUDIT_SVC_AUTH_PASS,
+                                  request['client_id'],
+                                  "%d, %d" % (uid, gid))
             return True
         else:
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                      request['client_id'],
-                                      "SCA", "%d, %d" % (uid, gid))
+            self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                                  request['client_id'],
+                                  "%d, %d" % (uid, gid))
             return False
 
 
@@ -64,7 +57,7 @@ class SimpleHeaderAuth(HTTPAuthenticator):
 
     def handle(self, request):
         if self.name not in request['headers']:
-            logger.debug('SHA: No "headers" in request')
+            self.logger.debug('SHA: No "headers" in request')
             return None
         value = request['headers'][self.name]
         if self.value is None:
@@ -72,25 +65,21 @@ class SimpleHeaderAuth(HTTPAuthenticator):
             pass
         elif isinstance(self.value, str):
             if value != self.value:
-                self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                          request['client_id'],
-                                          "SHA", value)
+                self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                                      request['client_id'], value)
                 return False
         elif isinstance(self.value, list):
             if value not in self.value:
-                self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                          request['client_id'],
-                                          "SHA", value)
+                self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                                      request['client_id'], value)
                 return False
         else:
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                      request['client_id'],
-                                      "SHA", value)
+            self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                                  request['client_id'], value)
             return False
 
-        self._auditlog.svc_access(log.AUDIT_SVC_AUTH_PASS,
-                                  request['client_id'],
-                                  "SHA", value)
+        self.audit_svc_access(log.AUDIT_SVC_AUTH_PASS,
+                              request['client_id'], value)
         request['remote_user'] = value
         return True
 
@@ -112,7 +101,7 @@ class SimpleAuthKeys(HTTPAuthenticator):
         name = request['headers'].get(self.id_header, None)
         key = request['headers'].get(self.key_header, None)
         if name is None and key is None:
-            logger.debug('SAK: Ignoring request no relevant headers provided')
+            self.logger.debug('Ignoring request no relevant headers provided')
             return None
 
         validated = False
@@ -124,19 +113,16 @@ class SimpleAuthKeys(HTTPAuthenticator):
                                       key.encode('utf-8')):
                 validated = True
         except Exception:
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                      request['client_id'],
-                                      "SAK", name)
+            self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                                  request['client_id'], name)
             return False
 
         if validated:
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTH_PASS,
-                                      request['client_id'],
-                                      "SAK", name)
+            self.audit_svc_access(log.AUDIT_SVC_AUTH_PASS,
+                                  request['client_id'], name)
             request['remote_user'] = name
             return True
 
-        self._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                  request['client_id'],
-                                  "SAK", name)
+        self.audit_svc_access(log.AUDIT_SVC_AUTH_FAIL,
+                              request['client_id'], name)
         return False
diff --git a/custodia/httpd/authorizers.py b/custodia/httpd/authorizers.py
index 292abf1..9827407 100644
--- a/custodia/httpd/authorizers.py
+++ b/custodia/httpd/authorizers.py
@@ -1,18 +1,14 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
-import logging
 import os
 
 from custodia import log
 
-logger = logging.getLogger(__name__)
 
-
-class HTTPAuthorizer(object):
+class HTTPAuthorizer(log.CustodiaPlugin):
 
     def __init__(self, config=None):
-        self.config = config
-        self._auditlog = log.auditlog
+        super(HTTPAuthorizer, self).__init__(config)
         self.store_name = None
         if self.config and 'store' in self.config:
             self.store_name = self.config['store']
@@ -42,23 +38,21 @@ class SimplePathAuthz(HTTPAuthorizer):
                 # special case to match a path ending in /
                 authz = authz[:-1]
             if authz == path:
-                self._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_PASS,
-                                          request['client_id'],
-                                          "SPA", path)
+                self.audit_svc_access(log.AUDIT_SVC_AUTHZ_PASS,
+                                      request['client_id'], path)
                 return True
 
         while path != '':
             if path in self.paths:
-                self._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_PASS,
-                                          request['client_id'],
-                                          "SPA", path)
+                self.audit_svc_access(log.AUDIT_SVC_AUTHZ_PASS,
+                                      request['client_id'], path)
                 return True
             if path == '/':
                 path = ''
             else:
                 path, _ = os.path.split(path)
 
-        logger.debug('SPA: No path in %s matched %s', self.paths, reqpath)
+        self.logger.debug('No path in %s matched %s', self.paths, reqpath)
         return None
 
 
@@ -72,27 +66,24 @@ class UserNameSpace(HTTPAuthorizer):
         # Only check if we are in the right (sub)path
         path = request.get('path', '/')
         if not path.startswith(self.path):
-            logger.debug('UNS: %s is not contained in %s', path, self.path)
+            self.logger.debug('%s is not contained in %s', path, self.path)
             return None
 
         name = request.get('remote_user', None)
         if name is None:
             # UserNameSpace requires a user ...
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_FAIL,
-                                      request['client_id'],
-                                      "UNS(%s)" % self.path, path)
+            self.audit_svc_access(log.AUDIT_SVC_AUTHZ_FAIL,
+                                  request['client_id'], path)
             return False
 
         namespace = self.path.rstrip('/') + '/' + name + '/'
         if not path.startswith(namespace):
             # Not in the namespace
-            self._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_FAIL,
-                                      request['client_id'],
-                                      "UNS(%s)" % self.path, path)
+            self.audit_svc_access(log.AUDIT_SVC_AUTHZ_FAIL,
+                                  request['client_id'], path)
             return False
 
         request['default_namespace'] = name
-        self._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_PASS,
-                                  request['client_id'],
-                                  "UNS(%s)" % self.path, path)
+        self.audit_svc_access(log.AUDIT_SVC_AUTHZ_PASS,
+                              request['client_id'], path)
         return True
diff --git a/custodia/httpd/consumer.py b/custodia/httpd/consumer.py
index bf0c393..9f0a6d5 100644
--- a/custodia/httpd/consumer.py
+++ b/custodia/httpd/consumer.py
@@ -1,15 +1,17 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
 from custodia.httpd.server import HTTPError
+from custodia.log import CustodiaPlugin
 
 
 DEFAULT_CTYPE = 'text/html; charset=utf-8'
 SUPPORTED_COMMANDS = ['GET', 'PUT', 'POST', 'DELETE']
 
 
-class HTTPConsumer(object):
+class HTTPConsumer(CustodiaPlugin):
 
     def __init__(self, config=None):
+        super(HTTPConsumer, self).__init__(config)
         self.config = config
         self.store_name = None
         if config and 'store' in config:
diff --git a/custodia/httpd/server.py b/custodia/httpd/server.py
index b1440ab..2608f3c 100644
--- a/custodia/httpd/server.py
+++ b/custodia/httpd/server.py
@@ -328,9 +328,9 @@ class HTTPRequestHandler(BaseHTTPRequestHandler):
             elif valid is True:
                 valid_once = True
         if valid_once is not True:
-            self.server._auditlog.svc_access(log.AUDIT_SVC_AUTH_FAIL,
-                                             request['client_id'], "MAIN",
-                                             'No auth')
+            self.server._auditlog.svc_access(self.__class__.__name__,
+                                             log.AUDIT_SVC_AUTH_FAIL,
+                                             request['client_id'], 'No auth')
             raise HTTPError(403)
 
         # auhz framework here
@@ -342,8 +342,9 @@ class HTTPRequestHandler(BaseHTTPRequestHandler):
             if valid is not None:
                 break
         if valid is not True:
-            self.server._auditlog.svc_access(log.AUDIT_SVC_AUTHZ_FAIL,
-                                             request['client_id'], "MAIN",
+            self.server._auditlog.svc_access(self.__class__.__name__,
+                                             log.AUDIT_SVC_AUTHZ_FAIL,
+                                             request['client_id'],
                                              request.get('path', '/'))
             raise HTTPError(403)
 
diff --git a/custodia/log.py b/custodia/log.py
index 947af75..a9a0345 100644
--- a/custodia/log.py
+++ b/custodia/log.py
@@ -7,9 +7,16 @@ custodia_logger = logging.getLogger('custodia')
 custodia_logger.addHandler(logging.NullHandler())
 
 
-LOGGING_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
-LOGGING_AUDITFORMAT = "%(asctime)s %(message)s"
-LOGGING_DATEFORMAT = "%Y-%m-%h %H:%M:%S"
+LOGGING_FORMAT = "%(asctime)s - %(origin)-32s - %(message)s"
+LOGGING_DATEFORMAT = "%Y-%m-%d %H:%M:%S"
+
+
+class OriginContextFilter(logging.Filter):
+    def filter(self, record):
+        if not hasattr(record, 'origin'):
+            record.origin = record.name.split('.')[-1]
+
+        return True
 
 
 def setup_logging(debug=False, auditlog='custodia.audit.log'):
@@ -20,18 +27,27 @@ def setup_logging(debug=False, auditlog='custodia.audit.log'):
         default_fmt = logging.Formatter(LOGGING_FORMAT, LOGGING_DATEFORMAT)
         stream_hdlr = logging.StreamHandler(sys.stderr)
         stream_hdlr.setFormatter(default_fmt)
+        stream_hdlr.addFilter(OriginContextFilter())
         root_logger.addHandler(stream_hdlr)
 
     custodia_logger = logging.getLogger('custodia')
     if debug:
         custodia_logger.setLevel(logging.DEBUG)
         custodia_logger.debug('Custodia debug logger enabled')
+        # If the global debug is enabled, turn debug on in all custodia.
+        # loggers
+        logdict = logging.Logger.manager.loggerDict
+        for name, obj in logdict.items():
+            if not isinstance(obj, logging.Logger):
+                continue
+            if name.startswith('custodia.'):
+                obj.setLevel(logging.DEBUG)
     else:
         custodia_logger.setLevel(logging.INFO)
 
     audit_logger = logging.getLogger('custodia.audit')
     if len(audit_logger.handlers) == 0:
-        audit_fmt = logging.Formatter(LOGGING_AUDITFORMAT, LOGGING_DATEFORMAT)
+        audit_fmt = logging.Formatter(LOGGING_FORMAT, LOGGING_DATEFORMAT)
         audit_hdrl = logging.FileHandler(auditlog)
         audit_hdrl.setFormatter(audit_fmt)
         audit_logger.addHandler(audit_hdrl)
@@ -63,10 +79,10 @@ AUDIT_MESSAGES = [
     "DENIED: '%(client)s' deleted key '%(key)s'",     # AUDIT_DEL_DENIED
     "AUDIT FAILURE 7",
     "AUDIT FAILURE 8",
-    "PASS(%(tag)s): '%(cli)s' authenticated as '%(name)s'",  # SVC_AUTH_PASS
-    "FAIL(%(tag)s): '%(cli)s' authenticated as '%(name)s'",  # SVC_AUTH_FAIL
-    "PASS(%(tag)s): '%(cli)s' authorized for '%(name)s'",    # SVC_AUTHZ_PASS
-    "FAIL(%(tag)s): '%(cli)s' authorized for '%(name)s'",    # SVC_AUTHZ_FAIL
+    "PASS: '%(cli)s' authenticated as '%(name)s'",  # SVC_AUTH_PASS
+    "FAIL: '%(cli)s' authenticated as '%(name)s'",  # SVC_AUTH_FAIL
+    "PASS: '%(cli)s' authorized for '%(name)s'",    # SVC_AUTHZ_PASS
+    "FAIL: '%(cli)s' authorized for '%(name)s'",    # SVC_AUTHZ_FAIL
     "AUDIT FAILURE 13",
 ]
 
@@ -75,18 +91,39 @@ class AuditLog(object):
     def __init__(self, logger):
         self.logger = logger
 
-    def key_access(self, action, client, keyname):
+    def key_access(self, origin, action, client, keyname):
         if action <= AUDIT_NONE or action >= AUDIT_LAST:
             action = AUDIT_NONE
         msg = AUDIT_MESSAGES[action]
         args = {'client': client, 'key': keyname}
-        self.logger.info(msg, args)
+        self.logger.info(msg, args, extra={'origin': origin})
 
-    def svc_access(self, action, client, tag, name):
+    def svc_access(self, origin, action, client, name):
         if action <= AUDIT_SVC_NONE or action >= AUDIT_SVC_LAST:
             action = AUDIT_NONE
         msg = AUDIT_MESSAGES[action]
-        args = {'cli': client, 'tag': tag, 'name': name}
-        self.logger.info(msg, args)
+        args = {'cli': client, 'name': name}
+        self.logger.info(msg, args, extra={'origin': origin})
 
 auditlog = AuditLog(logging.getLogger('custodia.audit'))
+
+
+class CustodiaPlugin(object):
+
+    def __init__(self, config=None):
+        self.config = config if config is not None else dict()
+        self._auditlog = auditlog
+        self.origin = self.config.get('facility_name', self.__class__.__name__)
+        l = logging.getLogger(
+            'custodia.plugins.%s' % self.__class__.__name__)
+        self.logger = logging.LoggerAdapter(l, {'origin': self.origin})
+        if self.config.get('debug', 'false').lower() == 'true':
+            l.setLevel(logging.DEBUG)
+        else:
+            l.setLevel(logging.INFO)
+
+    def audit_key_access(self, *args, **kwargs):
+        self._auditlog.key_access(self.origin, *args, **kwargs)
+
+    def audit_svc_access(self, *args, **kwargs):
+        self._auditlog.svc_access(self.origin, *args, **kwargs)
diff --git a/custodia/secrets.py b/custodia/secrets.py
index aeaa560..1c3248d 100644
--- a/custodia/secrets.py
+++ b/custodia/secrets.py
@@ -17,9 +17,6 @@ from custodia.store.interface import CSStoreExists
 from custodia.store.sqlite import SqliteStore
 
 
-logger = logging.getLogger(__name__)
-
-
 class Secrets(HTTPConsumer):
 
     def __init__(self, *args, **kwargs):
@@ -29,7 +26,6 @@ class Secrets(HTTPConsumer):
             kt = self.config['allowed_keytypes'].split()
             self.allowed_keytypes = kt
         self._validator = Validator(self.allowed_keytypes)
-        self._auditlog = log.auditlog
 
     def _db_key(self, trail):
         if len(trail) < 2:
@@ -61,8 +57,8 @@ class Secrets(HTTPConsumer):
         except CSStoreError:
             raise HTTPError(500)
 
-        logger.debug('parent_exists: %s (%s, %r) -> %r',
-                     basename, default, trail, keylist)
+        self.logger.debug('parent_exists: %s (%s, %r) -> %r',
+                          basename, default, trail, keylist)
 
         if keylist is not None:
             return True
@@ -110,7 +106,7 @@ class Secrets(HTTPConsumer):
         basename = self._db_container_key(default, trail)
         try:
             keylist = self.root.store.list(basename)
-            logger.debug('list %s returned %r', basename, keylist)
+            self.logger.debug('list %s returned %r', basename, keylist)
             if keylist is None:
                 raise HTTPError(404)
             response['output'] = json.dumps(keylist)
@@ -168,7 +164,7 @@ class Secrets(HTTPConsumer):
             fn(trail, request, response)
             action = ok
         finally:
-            self._auditlog.key_access(action, client, key)
+            self.audit_key_access(action, client, key)
 
     def _get_key(self, trail, request, response):
         self._audit(log.AUDIT_GET_ALLOWED, log.AUDIT_GET_DENIED,
diff --git a/custodia/store/enclite.py b/custodia/store/enclite.py
index c5b883f..8c1f9c8 100644
--- a/custodia/store/enclite.py
+++ b/custodia/store/enclite.py
@@ -1,7 +1,5 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
-import logging
-
 from jwcrypto.common import json_decode, json_encode
 from jwcrypto.jwe import JWE
 from jwcrypto.jwk import JWK
@@ -9,8 +7,6 @@ from jwcrypto.jwk import JWK
 from custodia.store.interface import CSStoreError
 from custodia.store.sqlite import SqliteStore
 
-logger = logging.getLogger(__name__)
-
 
 class EncryptedStore(SqliteStore):
 
@@ -40,7 +36,7 @@ class EncryptedStore(SqliteStore):
             jwe.deserialize(value, self.mkey)
             return jwe.payload.decode('utf-8')
         except Exception:
-            logger.exception("Error parsing key %s", key)
+            self.logger.exception("Error parsing key %s", key)
             raise CSStoreError('Error occurred while trying to parse key')
 
     def set(self, key, value, replace=False):
diff --git a/custodia/store/etcdstore.py b/custodia/store/etcdstore.py
index 46c6943..44d7075 100644
--- a/custodia/store/etcdstore.py
+++ b/custodia/store/etcdstore.py
@@ -2,19 +2,15 @@
 
 from __future__ import print_function
 
-import logging
-
 import etcd
 
 from custodia.store.interface import CSStore, CSStoreError, CSStoreExists
 
 
-logger = logging.getLogger(__name__)
-
-
 class EtcdStore(CSStore):
 
     def __init__(self, config):
+        super(EtcdStore, self).__init__(config)
         self.server = config.get('etcd_server', '127.0.0.1')
         self.port = int(config.get('etcd_port', 4001))
         self.namespace = config.get('namespace', "/custodia")
@@ -27,7 +23,8 @@ class EtcdStore(CSStore):
             # Already exists
             pass
         except etcd.EtcdException:
-            logger.exception("Error creating namespace %s", self.namespace)
+            self.logger.exception("Error creating namespace %s",
+                                  self.namespace)
             raise CSStoreError('Error occurred while trying to init db')
 
     def _absolute_key(self, key):
@@ -40,51 +37,51 @@ class EtcdStore(CSStore):
         return '/'.join([self.namespace] + parts).replace('//', '/')
 
     def get(self, key):
-        logger.debug("Fetching key %s", key)
+        self.logger.debug("Fetching key %s", key)
         try:
             result = self.etcd.get(self._absolute_key(key))
         except etcd.EtcdException:
-            logger.exception("Error fetching key %s", key)
+            self.logger.exception("Error fetching key %s", key)
             raise CSStoreError('Error occurred while trying to get key')
-        logger.debug("Fetched key %s got result: %r", key, result)
+        self.logger.debug("Fetched key %s got result: %r", key, result)
         return result.value
 
     def set(self, key, value, replace=False):
-        logger.debug("Setting key %s to value %s (replace=%s)", key, value,
-                     replace)
+        self.logger.debug("Setting key %s to value %s (replace=%s)",
+                          key, value, replace)
         path = self._absolute_key(key)
         try:
             self.etcd.write(path, value, prevExist=replace)
         except etcd.EtcdAlreadyExist as err:
             raise CSStoreExists(str(err))
         except etcd.EtcdException:
-            logger.exception("Error storing key %s", key)
+            self.logger.exception("Error storing key %s", key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def span(self, key):
         path = self._absolute_key(key)
-        logger.debug("Creating directory %s", path)
+        self.logger.debug("Creating directory %s", path)
         try:
             self.etcd.write(path, None, dir=True, prevExist=False)
         except etcd.EtcdAlreadyExist as err:
             raise CSStoreExists(str(err))
         except etcd.EtcdException:
-            logger.exception("Error storing key %s", key)
+            self.logger.exception("Error storing key %s", key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def list(self, keyfilter='/'):
         path = self._absolute_key(keyfilter)
         if path != '/':
             path = path.rstrip('/')
-        logger.debug("Listing keys matching %s", path)
+        self.logger.debug("Listing keys matching %s", path)
         try:
             result = self.etcd.read(path, recursive=True)
         except etcd.EtcdKeyNotFound:
             return None
         except etcd.EtcdException:
-            logger.exception("Error listing %s", keyfilter)
+            self.logger.exception("Error listing %s", keyfilter)
             raise CSStoreError('Error occurred while trying to list keys')
-        logger.debug("Searched for %s got result: %r", path, result)
+        self.logger.debug("Searched for %s got result: %r", path, result)
         value = set()
         for entry in result.get_subtree():
             if entry.key == path:
@@ -96,14 +93,14 @@ class EtcdStore(CSStore):
         return sorted(value)
 
     def cut(self, key):
-        logger.debug("Removing key %s", key)
+        self.logger.debug("Removing key %s", key)
         try:
             self.etcd.delete(self._absolute_key(key))
         except etcd.EtcdKeyNotFound:
-            logger.debug("Key %s not found", key)
+            self.logger.debug("Key %s not found", key)
             return False
         except etcd.EtcdException:
-            logger.exception("Error removing key %s", key)
+            self.logger.exception("Error removing key %s", key)
             raise CSStoreError('Error occurred while trying to cut key')
-        logger.debug("Key %s removed", key)
+        self.logger.debug("Key %s removed", key)
         return True
diff --git a/custodia/store/interface.py b/custodia/store/interface.py
index 37857fe..22ca143 100644
--- a/custodia/store/interface.py
+++ b/custodia/store/interface.py
@@ -2,6 +2,8 @@
 
 import logging
 
+from custodia.log import CustodiaPlugin
+
 logger = logging.getLogger(__name__)
 
 
@@ -17,7 +19,7 @@ class CSStoreExists(Exception):
         super(CSStoreExists, self).__init__(message)
 
 
-class CSStore(object):
+class CSStore(CustodiaPlugin):
 
     def get(self, key):
         raise NotImplementedError
diff --git a/custodia/store/sqlite.py b/custodia/store/sqlite.py
index 936c8d0..4c4b5af 100644
--- a/custodia/store/sqlite.py
+++ b/custodia/store/sqlite.py
@@ -2,7 +2,6 @@
 
 from __future__ import print_function
 
-import logging
 import os
 import sqlite3
 import unittest
@@ -10,12 +9,10 @@ import unittest
 from custodia.store.interface import CSStore, CSStoreError, CSStoreExists
 
 
-logger = logging.getLogger(__name__)
-
-
 class SqliteStore(CSStore):
 
     def __init__(self, config):
+        super(SqliteStore, self).__init__(config)
         if 'dburi' not in config:
             raise ValueError('Missing "dburi" for Sqlite Store')
         self.dburi = config['dburi']
@@ -31,11 +28,11 @@ class SqliteStore(CSStore):
                 c = conn.cursor()
                 self._create(c)
         except sqlite3.Error:
-            logger.exception("Error creating table %s", self.table)
+            self.logger.exception("Error creating table %s", self.table)
             raise CSStoreError('Error occurred while trying to init db')
 
     def get(self, key):
-        logger.debug("Fetching key %s", key)
+        self.logger.debug("Fetching key %s", key)
         query = "SELECT value from %s WHERE key=?" % self.table
         try:
             conn = sqlite3.connect(self.dburi)
@@ -43,9 +40,9 @@ class SqliteStore(CSStore):
             r = c.execute(query, (key,))
             value = r.fetchall()
         except sqlite3.Error:
-            logger.exception("Error fetching key %s", key)
+            self.logger.exception("Error fetching key %s", key)
             raise CSStoreError('Error occurred while trying to get key')
-        logger.debug("Fetched key %s got result: %r", key, value)
+        self.logger.debug("Fetched key %s got result: %r", key, value)
         if len(value) > 0:
             return value[0][0]
         else:
@@ -57,8 +54,8 @@ class SqliteStore(CSStore):
         cur.execute(create)
 
     def set(self, key, value, replace=False):
-        logger.debug("Setting key %s to value %s (replace=%s)", key, value,
-                     replace)
+        self.logger.debug("Setting key %s to value %s (replace=%s)",
+                          key, value, replace)
         if key.endswith('/'):
             raise ValueError('Invalid Key name, cannot end in "/"')
         if replace:
@@ -75,12 +72,12 @@ class SqliteStore(CSStore):
         except sqlite3.IntegrityError as err:
             raise CSStoreExists(str(err))
         except sqlite3.Error as err:
-            logger.exception("Error storing key %s", key)
+            self.logger.exception("Error storing key %s", key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def span(self, key):
         name = key.rstrip('/')
-        logger.debug("Creating container %s", name)
+        self.logger.debug("Creating container %s", name)
         query = "INSERT into %s VALUES (?, '')"
         setdata = query % (self.table,)
         try:
@@ -92,12 +89,12 @@ class SqliteStore(CSStore):
         except sqlite3.IntegrityError as err:
             raise CSStoreExists(str(err))
         except sqlite3.Error:
-            logger.exception("Error creating key %s", name)
+            self.logger.exception("Error creating key %s", name)
             raise CSStoreError('Error occurred while trying to span container')
 
     def list(self, keyfilter=''):
         path = keyfilter.rstrip('/')
-        logger.debug("Listing keys matching %s", path)
+        self.logger.debug("Listing keys matching %s", path)
         child_prefix = path if path == '' else path + '/'
         search = "SELECT key FROM %s WHERE key LIKE ?" % self.table
         key = "%s%%" % (path,)
@@ -106,9 +103,9 @@ class SqliteStore(CSStore):
             r = conn.execute(search, (key,))
             rows = r.fetchall()
         except sqlite3.Error:
-            logger.exception("Error listing %s: [%r]", keyfilter)
+            self.logger.exception("Error listing %s: [%r]", keyfilter)
             raise CSStoreError('Error occurred while trying to list keys')
-        logger.debug("Searched for %s got result: %r", path, rows)
+        self.logger.debug("Searched for %s got result: %r", path, rows)
         if len(rows) > 0:
             parent_exists = False
             value = list()
@@ -121,19 +118,19 @@ class SqliteStore(CSStore):
                 value.append(row[0][len(child_prefix):].lstrip('/'))
 
             if value:
-                logger.debug("Returning sorted values %r", value)
+                self.logger.debug("Returning sorted values %r", value)
                 return sorted(value)
             elif parent_exists:
-                logger.debug("Returning empty list")
+                self.logger.debug("Returning empty list")
                 return []
         elif keyfilter == '':
-            logger.debug("Returning empty list")
+            self.logger.debug("Returning empty list")
             return []
-        logger.debug("Returning 'Not Found'")
+        self.logger.debug("Returning 'Not Found'")
         return None
 
     def cut(self, key):
-        logger.debug("Removing key %s", key)
+        self.logger.debug("Removing key %s", key)
         query = "DELETE from %s WHERE key=?" % self.table
         try:
             conn = sqlite3.connect(self.dburi)
@@ -141,10 +138,10 @@ class SqliteStore(CSStore):
                 c = conn.cursor()
                 r = c.execute(query, (key,))
         except sqlite3.Error:
-            logger.error("Error removing key %s", key)
+            self.logger.error("Error removing key %s", key)
             raise CSStoreError('Error occurred while trying to cut key')
-        logger.debug("Key %s %s", key,
-                     "removed" if r.rowcount > 0 else "not found")
+        self.logger.debug("Key %s %s", key,
+                          "removed" if r.rowcount > 0 else "not found")
         if r.rowcount > 0:
             return True
         return False