Add more debug logging to storage plugins

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

2 files changed, 25 insertions, 2 deletions

diff --git a/custodia/store/etcdstore.py b/custodia/store/etcdstore.py
index a24dc88..46c6943 100644
--- a/custodia/store/etcdstore.py
+++ b/custodia/store/etcdstore.py
@@ -40,14 +40,18 @@ class EtcdStore(CSStore):
         return '/'.join([self.namespace] + parts).replace('//', '/')
 
     def get(self, key):
+        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)
             raise CSStoreError('Error occurred while trying to get key')
+        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)
         path = self._absolute_key(key)
         try:
             self.etcd.write(path, value, prevExist=replace)
@@ -59,6 +63,7 @@ class EtcdStore(CSStore):
 
     def span(self, key):
         path = self._absolute_key(key)
+        logger.debug("Creating directory %s", path)
         try:
             self.etcd.write(path, None, dir=True, prevExist=False)
         except etcd.EtcdAlreadyExist as err:
@@ -71,6 +76,7 @@ class EtcdStore(CSStore):
         path = self._absolute_key(keyfilter)
         if path != '/':
             path = path.rstrip('/')
+        logger.debug("Listing keys matching %s", path)
         try:
             result = self.etcd.read(path, recursive=True)
         except etcd.EtcdKeyNotFound:
@@ -78,7 +84,7 @@ class EtcdStore(CSStore):
         except etcd.EtcdException:
             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)
         value = set()
         for entry in result.get_subtree():
             if entry.key == path:
@@ -90,11 +96,14 @@ class EtcdStore(CSStore):
         return sorted(value)
 
     def cut(self, key):
+        logger.debug("Removing key %s", key)
         try:
             self.etcd.delete(self._absolute_key(key))
         except etcd.EtcdKeyNotFound:
+            logger.debug("Key %s not found", key)
             return False
         except etcd.EtcdException:
             logger.exception("Error removing key %s", key)
             raise CSStoreError('Error occurred while trying to cut key')
+        logger.debug("Key %s removed", key)
         return True
diff --git a/custodia/store/sqlite.py b/custodia/store/sqlite.py
index 43df8e1..936c8d0 100644
--- a/custodia/store/sqlite.py
+++ b/custodia/store/sqlite.py
@@ -35,6 +35,7 @@ class SqliteStore(CSStore):
             raise CSStoreError('Error occurred while trying to init db')
 
     def get(self, key):
+        logger.debug("Fetching key %s", key)
         query = "SELECT value from %s WHERE key=?" % self.table
         try:
             conn = sqlite3.connect(self.dburi)
@@ -44,6 +45,7 @@ class SqliteStore(CSStore):
         except sqlite3.Error:
             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)
         if len(value) > 0:
             return value[0][0]
         else:
@@ -55,6 +57,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)
         if key.endswith('/'):
             raise ValueError('Invalid Key name, cannot end in "/"')
         if replace:
@@ -71,11 +75,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)
+            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)
         query = "INSERT into %s VALUES (?, '')"
         setdata = query % (self.table,)
         try:
@@ -92,6 +97,7 @@ class SqliteStore(CSStore):
 
     def list(self, keyfilter=''):
         path = keyfilter.rstrip('/')
+        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,)
@@ -102,6 +108,7 @@ class SqliteStore(CSStore):
         except sqlite3.Error:
             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)
         if len(rows) > 0:
             parent_exists = False
             value = list()
@@ -114,14 +121,19 @@ class SqliteStore(CSStore):
                 value.append(row[0][len(child_prefix):].lstrip('/'))
 
             if value:
+                logger.debug("Returning sorted values %r", value)
                 return sorted(value)
             elif parent_exists:
+                logger.debug("Returning empty list")
                 return []
         elif keyfilter == '':
+            logger.debug("Returning empty list")
             return []
+        logger.debug("Returning 'Not Found'")
         return None
 
     def cut(self, key):
+        logger.debug("Removing key %s", key)
         query = "DELETE from %s WHERE key=?" % self.table
         try:
             conn = sqlite3.connect(self.dburi)
@@ -131,6 +143,8 @@ class SqliteStore(CSStore):
         except sqlite3.Error:
             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")
         if r.rowcount > 0:
             return True
         return False