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>

4 files changed, 43 insertions, 51 deletions

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