Use Python's logging framework for logging

The custom logging and traceback functions as well as the audit logger
are replaced with Python's logging framework. For now the loggers are
hard-coded to use a StreamHandler(sys.stderr) as root handler and a
FileHandler for the audit log.

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

13 files changed, 123 insertions, 118 deletions

diff --git a/custodia/custodia b/custodia/custodia
index f6a9f3f..56652de 100755
--- a/custodia/custodia
+++ b/custodia/custodia
@@ -11,10 +11,13 @@ except ImportError:
 from custodia.httpd.server import HTTPServer
 from custodia import log
 import importlib
+import logging
 import os
 import six
 import sys
 
+logger = logging.getLogger('custodia')
+
 
 def source_config():
     cfgfile = None
@@ -26,7 +29,7 @@ def source_config():
         cfgfile = '/etc/custodia/custodia.conf'
     else:
         raise IOError("Configuration file not found")
-    return cfgfile
+    return os.path.abspath(cfgfile)
 
 def attach_store(typename, plugins, stores):
     for name, c in six.iteritems(plugins):
@@ -88,7 +91,7 @@ def parse_config(cfgfile):
                     handler = getattr(m, classname)
                 except Exception as e:  # pylint: disable=broad-except
                     raise ValueError('Invalid format for "handler" option '
-                                     '[%r]' % e)
+                                     '[%r]: %s' % (e, val))
 
             else:
                 if hconf is None:
@@ -106,8 +109,10 @@ def parse_config(cfgfile):
 if __name__ == '__main__':
     cfgfile = source_config()
     config = parse_config(cfgfile)
-    if config.get('debug') == 'True':
-        log.DEBUG = True
+    debug = config.get('debug', 'false').lower() == 'true'
+    auditlog = os.path.abspath(config.get('auditlog', 'custodia.audit.log'))
+    log.setup_logging(debug, auditlog)
+    logger.debug('Config file %s loaded', cfgfile)
 
     url = config.get('server_url', None)
     if url is None:
diff --git a/custodia/forwarder.py b/custodia/forwarder.py
index e4372ba..e5028c5 100644
--- a/custodia/forwarder.py
+++ b/custodia/forwarder.py
@@ -3,7 +3,6 @@
 import json
 import uuid
 
-from custodia import log
 from custodia.client import CustodiaHTTPClient
 from custodia.httpd.consumer import HTTPConsumer
 from custodia.httpd.server import HTTPError
@@ -13,7 +12,6 @@ class Forwarder(HTTPConsumer):
 
     def __init__(self, *args, **kwargs):
         super(Forwarder, self).__init__(*args, **kwargs)
-        self._auditlog = log.AuditLog(self.config)
         self.client = CustodiaHTTPClient(self.config['forward_uri'])
         self.headers = json.loads(self.config.get('forward_headers', '{}'))
         self.use_prefix = self.config.get('prefix_remote_user', True)
diff --git a/custodia/httpd/authenticators.py b/custodia/httpd/authenticators.py
index 33166ec..9ec622d 100644
--- a/custodia/httpd/authenticators.py
+++ b/custodia/httpd/authenticators.py
@@ -12,7 +12,7 @@ class HTTPAuthenticator(object):
 
     def __init__(self, config=None):
         self.config = config
-        self._auditlog = log.AuditLog(self.config)
+        self._auditlog = log.auditlog
 
     def handle(self, request):
         raise HTTPError(403)
diff --git a/custodia/httpd/authorizers.py b/custodia/httpd/authorizers.py
index 3758f3c..365b80c 100644
--- a/custodia/httpd/authorizers.py
+++ b/custodia/httpd/authorizers.py
@@ -9,7 +9,7 @@ class HTTPAuthorizer(object):
 
     def __init__(self, config=None):
         self.config = config
-        self._auditlog = log.AuditLog(self.config)
+        self._auditlog = log.auditlog
         self.store_name = None
         if self.config and 'store' in self.config:
             self.store_name = self.config['store']
diff --git a/custodia/httpd/server.py b/custodia/httpd/server.py
index dfc89d6..656015c 100644
--- a/custodia/httpd/server.py
+++ b/custodia/httpd/server.py
@@ -1,6 +1,7 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
 import errno
+import logging
 import os
 import shutil
 import socket
@@ -22,6 +23,7 @@ except ImportError:
 
 from custodia import log
 
+logger = logging.getLogger(__name__)
 
 SO_PEERCRED = getattr(socket, 'SO_PEERCRED', 17)
 SO_PEERSEC = getattr(socket, 'SO_PEERSEC', 31)
@@ -35,7 +37,7 @@ class HTTPError(Exception):
         self.code = code if code is not None else 500
         self.mesg = message
         errstring = '%d: %s' % (self.code, self.mesg)
-        log.debug(errstring)
+        logger.exception(errstring)
         super(HTTPError, self).__init__(errstring)
 
 
@@ -60,7 +62,7 @@ class ForkingHTTPServer(ForkingTCPServer):
         self.config = config
         if 'server_string' in self.config:
             self.server_string = self.config['server_string']
-        self._auditlog = log.AuditLog(self.config)
+        self._auditlog = log.auditlog
 
 
 class ForkingUnixHTTPServer(ForkingHTTPServer):
@@ -158,8 +160,8 @@ class HTTPRequestHandler(BaseHTTPRequestHandler):
             creds = self.request.getsockopt(socket.SOL_SOCKET, SO_PEERSEC,
                                             SELINUX_CONTEXT_LEN)
             context = creds.decode('utf-8')
-        except Exception as e:
-            log.debug("Couldn't retrieve SELinux Context: (%s)" % str(e))
+        except Exception:
+            log.debug("Couldn't retrieve SELinux Context", exc_info=True)
             context = None
 
         self._creds = {'pid': pid, 'uid': uid, 'gid': gid, 'context': context}
@@ -256,8 +258,7 @@ class HTTPRequestHandler(BaseHTTPRequestHandler):
                 self.close_connection = 1
                 return
             except Exception as e:  # pylint: disable=broad-except
-                self.log_error("Handler failed: %r", e)
-                self.log_traceback()
+                self.log_error("Handler failed: %r", e, exc_info=True)
                 self.send_error(500)
                 self.wfile.flush()
                 return
@@ -280,8 +281,8 @@ class HTTPRequestHandler(BaseHTTPRequestHandler):
             self.close_connection = 1
             return
 
-    def log_traceback(self):
-        self.log_error('Traceback:\n%s' % log.stacktrace())
+    def log_error(self, format, *args, **kwargs):
+        logger.error(format, *args, **kwargs)
 
     def pipeline(self, config, request):
         """
@@ -388,6 +389,8 @@ class HTTPServer(object):
         else:
             raise ValueError('Unknown URL Scheme: %s' % url.scheme)
 
+        logger.debug('Serving on %s', address)
+
         self.httpd = serverclass(address,
                                  HTTPRequestHandler,
                                  config)
diff --git a/custodia/log.py b/custodia/log.py
index c49a29e..947af75 100644
--- a/custodia/log.py
+++ b/custodia/log.py
@@ -1,47 +1,42 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
+import logging
 import sys
-import time
-import traceback
 
-try:
-    from StringIO import StringIO
-except ImportError:
-    from io import StringIO
+custodia_logger = logging.getLogger('custodia')
+custodia_logger.addHandler(logging.NullHandler())
 
-DEBUG = False
 
+LOGGING_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+LOGGING_AUDITFORMAT = "%(asctime)s %(message)s"
+LOGGING_DATEFORMAT = "%Y-%m-%h %H:%M:%S"
 
-def stacktrace():
-    _, _, tb = sys.exc_info()
-    if tb is None:
-        return None
-    try:
-        f = StringIO()
-        traceback.print_tb(tb, None, file=f)
-        return f.getvalue()
-    finally:
-        del tb
 
+def setup_logging(debug=False, auditlog='custodia.audit.log'):
+    # prevent multiple stream handlers
+    root_logger = logging.getLogger()
+    if not any(isinstance(hdlr, logging.StreamHandler)
+               for hdlr in root_logger.handlers):
+        default_fmt = logging.Formatter(LOGGING_FORMAT, LOGGING_DATEFORMAT)
+        stream_hdlr = logging.StreamHandler(sys.stderr)
+        stream_hdlr.setFormatter(default_fmt)
+        root_logger.addHandler(stream_hdlr)
 
-def get_time():
-    t = time.gmtime(time.time())
-    return '%04d/%02d/%02d %02d:%02d:%02d' % (
-        t[0], t[1], t[2], t[3], t[4], t[5])
+    custodia_logger = logging.getLogger('custodia')
+    if debug:
+        custodia_logger.setLevel(logging.DEBUG)
+        custodia_logger.debug('Custodia debug logger enabled')
+    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_hdrl = logging.FileHandler(auditlog)
+        audit_hdrl.setFormatter(audit_fmt)
+        audit_logger.addHandler(audit_hdrl)
 
-def error(msg, head=None):
-    if head is not None:
-        head = get_time()
-    sys.stderr.write('[%s] %s\n' % (head, msg))
-
-
-def debug(msg):
-    if DEBUG:
-        error(msg, 'DEBUG')
-        trace = stacktrace()
-        if trace is not None:
-            sys.stderr.write(trace + '\n')
+        custodia_logger.debug('Custodia audit log: %s', auditlog)
 
 
 AUDIT_NONE = 0
@@ -60,41 +55,38 @@ AUDIT_SVC_AUTHZ_FAIL = 12
 AUDIT_SVC_LAST = 13
 AUDIT_MESSAGES = [
     "AUDIT FAILURE",
-    "ALLOWED: '{client:s}' requested key '{key:s}'",  # AUDIT_GET_ALLOWED
-    "DENIED: '{client:s}' requested key '{key:s}'",   # AUDIT_GET_DENIED
-    "ALLOWED: '{client:s}' stored key '{key:s}'",     # AUDIT_SET_ALLOWED
-    "DENIED: '{client:s}' stored key '{key:s}'",      # AUDIT_SET_DENIED
-    "ALLOWED: '{client:s}' deleted key '{key:s}'",    # AUDIT_DEL_ALLOWED
-    "DENIED: '{client:s}' deleted key '{key:s}'",     # AUDIT_DEL_DENIED
+    "ALLOWED: '%(client)s' requested key '%(key)s'",  # AUDIT_GET_ALLOWED
+    "DENIED: '%(client)s' requested key '%(key)s'",   # AUDIT_GET_DENIED
+    "ALLOWED: '%(client)s' stored key '%(key)s'",     # AUDIT_SET_ALLOWED
+    "DENIED: '%(client)s' stored key '%(key)s'",      # AUDIT_SET_DENIED
+    "ALLOWED: '%(client)s' deleted key '%(key)s'",    # AUDIT_DEL_ALLOWED
+    "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(%(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
     "AUDIT FAILURE 13",
 ]
 
 
 class AuditLog(object):
-
-    def __init__(self, config):
-        if config is None:
-            config = {}
-        self.logfile = config.get('auditlog', 'custodia.audit.log')
-
-    def _log(self, message):
-        with open(self.logfile, 'a+') as f:
-            f.write('%s: %s\n' % (get_time(), message))
-            f.flush()
+    def __init__(self, logger):
+        self.logger = logger
 
     def key_access(self, action, client, keyname):
         if action <= AUDIT_NONE or action >= AUDIT_LAST:
             action = AUDIT_NONE
-        self._log(AUDIT_MESSAGES[action].format(client=client, key=keyname))
+        msg = AUDIT_MESSAGES[action]
+        args = {'client': client, 'key': keyname}
+        self.logger.info(msg, args)
 
     def svc_access(self, action, client, tag, name):
         if action <= AUDIT_SVC_NONE or action >= AUDIT_SVC_LAST:
             action = AUDIT_NONE
-        self._log(AUDIT_MESSAGES[action].format(cli=str(client), tag=tag,
-                                                name=name))
+        msg = AUDIT_MESSAGES[action]
+        args = {'cli': client, 'tag': tag, 'name': name}
+        self.logger.info(msg, args)
+
+auditlog = AuditLog(logging.getLogger('custodia.audit'))
diff --git a/custodia/message/common.py b/custodia/message/common.py
index c538a57..d774e3c 100644
--- a/custodia/message/common.py
+++ b/custodia/message/common.py
@@ -1,6 +1,8 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
-from custodia import log
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 class InvalidMessage(Exception):
@@ -10,7 +12,7 @@ class InvalidMessage(Exception):
     or validated.
     """
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(InvalidMessage, self).__init__(message)
 
 
@@ -21,7 +23,7 @@ class UnknownMessageType(Exception):
     type.
     """
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(UnknownMessageType, self).__init__(message)
 
 
@@ -32,7 +34,7 @@ class UnallowedMessage(Exception):
     is not allowed.
     """
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(UnallowedMessage, self).__init__(message)
 
 
diff --git a/custodia/message/kem.py b/custodia/message/kem.py
index 6001f49..c832b12 100644
--- a/custodia/message/kem.py
+++ b/custodia/message/kem.py
@@ -1,5 +1,6 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
+import logging
 import os
 import time
 import unittest
@@ -11,12 +12,12 @@ from jwcrypto.jwk import JWK
 from jwcrypto.jws import JWS
 from jwcrypto.jwt import JWT
 
-from custodia import log
 from custodia.httpd.authorizers import SimplePathAuthz
 from custodia.message.common import InvalidMessage
 from custodia.message.common import MessageHandler
 from custodia.store.sqlite import SqliteStore
 
+logger = logging.getLogger(__name__)
 
 KEY_USAGE_SIG = 0
 KEY_USAGE_ENC = 1
@@ -25,7 +26,7 @@ KEY_USAGE_MAP = {KEY_USAGE_SIG: 'sig', KEY_USAGE_ENC: 'enc'}
 
 class UnknownPublicKey(Exception):
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(UnknownPublicKey, self).__init__(message)
 
 
diff --git a/custodia/secrets.py b/custodia/secrets.py
index 90dac4c..8a4d821 100644
--- a/custodia/secrets.py
+++ b/custodia/secrets.py
@@ -1,6 +1,7 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
 import json
+import logging
 import os
 import unittest
 
@@ -25,7 +26,7 @@ class Secrets(HTTPConsumer):
             kt = self.config['allowed_keytypes'].split()
             self.allowed_keytypes = kt
         self._validator = Validator(self.allowed_keytypes)
-        self._auditlog = log.AuditLog(self.config)
+        self._auditlog = log.auditlog
 
     def _db_key(self, trail):
         if len(trail) < 2:
@@ -248,14 +249,16 @@ class SecretsTests(unittest.TestCase):
 
     @classmethod
     def setUpClass(cls):
-        cls.secrets = Secrets({'auditlog': 'test.audit.log'})
+        cls.log_handlers = log.auditlog.logger.handlers[:]
+        log.auditlog.logger.handlers = [logging.NullHandler()]
+        cls.secrets = Secrets()
         cls.secrets.root.store = SqliteStore({'dburi': 'testdb.sqlite'})
         cls.authz = UserNameSpace({})
 
     @classmethod
     def tearDownClass(cls):
+        log.auditlog.logger.handlers = cls.log_handlers
         try:
-            os.unlink('test.audit.log')
             os.unlink('testdb.sqlite')
         except OSError:
             pass
diff --git a/custodia/store/enclite.py b/custodia/store/enclite.py
index 787e5ca..c5b883f 100644
--- a/custodia/store/enclite.py
+++ b/custodia/store/enclite.py
@@ -1,13 +1,16 @@
 # 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
 
-from custodia import log
 from custodia.store.interface import CSStoreError
 from custodia.store.sqlite import SqliteStore
 
+logger = logging.getLogger(__name__)
+
 
 class EncryptedStore(SqliteStore):
 
@@ -36,8 +39,8 @@ class EncryptedStore(SqliteStore):
             jwe = JWE()
             jwe.deserialize(value, self.mkey)
             return jwe.payload.decode('utf-8')
-        except Exception as err:
-            log.error("Error parsing key %s: [%r]" % (key, repr(err)))
+        except Exception:
+            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 f7e55f4..a24dc88 100644
--- a/custodia/store/etcdstore.py
+++ b/custodia/store/etcdstore.py
@@ -2,15 +2,14 @@
 
 from __future__ import print_function
 
-import sys
+import logging
 
 import etcd
 
 from custodia.store.interface import CSStore, CSStoreError, CSStoreExists
 
 
-def log_error(error):
-    print(error, file=sys.stderr)
+logger = logging.getLogger(__name__)
 
 
 class EtcdStore(CSStore):
@@ -27,9 +26,8 @@ class EtcdStore(CSStore):
         except etcd.EtcdNotFile:
             # Already exists
             pass
-        except etcd.EtcdException as err:
-            log_error("Error creating namespace %s: [%r]" % (self.namespace,
-                                                             repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error creating namespace %s", self.namespace)
             raise CSStoreError('Error occurred while trying to init db')
 
     def _absolute_key(self, key):
@@ -44,8 +42,8 @@ class EtcdStore(CSStore):
     def get(self, key):
         try:
             result = self.etcd.get(self._absolute_key(key))
-        except etcd.EtcdException as err:
-            log_error("Error fetching key %s: [%r]" % (key, repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error fetching key %s", key)
             raise CSStoreError('Error occurred while trying to get key')
         return result.value
 
@@ -55,8 +53,8 @@ class EtcdStore(CSStore):
             self.etcd.write(path, value, prevExist=replace)
         except etcd.EtcdAlreadyExist as err:
             raise CSStoreExists(str(err))
-        except etcd.EtcdException as err:
-            log_error("Error storing key %s: [%r]" % (key, repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error storing key %s", key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def span(self, key):
@@ -65,8 +63,8 @@ class EtcdStore(CSStore):
             self.etcd.write(path, None, dir=True, prevExist=False)
         except etcd.EtcdAlreadyExist as err:
             raise CSStoreExists(str(err))
-        except etcd.EtcdException as err:
-            log_error("Error storing key %s: [%r]" % (key, repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error storing key %s", key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def list(self, keyfilter='/'):
@@ -77,8 +75,8 @@ class EtcdStore(CSStore):
             result = self.etcd.read(path, recursive=True)
         except etcd.EtcdKeyNotFound:
             return None
-        except etcd.EtcdException as err:
-            log_error("Error listing %s: [%r]" % (keyfilter, repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error listing %s", keyfilter)
             raise CSStoreError('Error occurred while trying to list keys')
 
         value = set()
@@ -96,7 +94,7 @@ class EtcdStore(CSStore):
             self.etcd.delete(self._absolute_key(key))
         except etcd.EtcdKeyNotFound:
             return False
-        except etcd.EtcdException as err:
-            log_error("Error removing key %s: [%r]" % (key, repr(err)))
+        except etcd.EtcdException:
+            logger.exception("Error removing key %s", key)
             raise CSStoreError('Error occurred while trying to cut key')
         return True
diff --git a/custodia/store/interface.py b/custodia/store/interface.py
index 850fc91..37857fe 100644
--- a/custodia/store/interface.py
+++ b/custodia/store/interface.py
@@ -1,17 +1,19 @@
 # Copyright (C) 2015  Custodia Project Contributors - see LICENSE file
 
-from custodia import log
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 class CSStoreError(Exception):
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(CSStoreError, self).__init__(message)
 
 
 class CSStoreExists(Exception):
     def __init__(self, message=None):
-        log.debug(message)
+        logger.debug(message)
         super(CSStoreExists, self).__init__(message)
 
 
diff --git a/custodia/store/sqlite.py b/custodia/store/sqlite.py
index 0a50651..43df8e1 100644
--- a/custodia/store/sqlite.py
+++ b/custodia/store/sqlite.py
@@ -2,16 +2,15 @@
 
 from __future__ import print_function
 
+import logging
 import os
 import sqlite3
-import sys
 import unittest
 
 from custodia.store.interface import CSStore, CSStoreError, CSStoreExists
 
 
-def log_error(error):
-    print(error, file=sys.stderr)
+logger = logging.getLogger(__name__)
 
 
 class SqliteStore(CSStore):
@@ -31,9 +30,8 @@ class SqliteStore(CSStore):
             with conn:
                 c = conn.cursor()
                 self._create(c)
-        except sqlite3.Error as err:
-            log_error("Error creating table %s: [%r]" % (self.table,
-                                                         repr(err)))
+        except sqlite3.Error:
+            logger.exception("Error creating table %s", self.table)
             raise CSStoreError('Error occurred while trying to init db')
 
     def get(self, key):
@@ -43,8 +41,8 @@ class SqliteStore(CSStore):
             c = conn.cursor()
             r = c.execute(query, (key,))
             value = r.fetchall()
-        except sqlite3.Error as err:
-            log_error("Error fetching key %s: [%r]" % (key, repr(err)))
+        except sqlite3.Error:
+            logger.exception("Error fetching key %s", key)
             raise CSStoreError('Error occurred while trying to get key')
         if len(value) > 0:
             return value[0][0]
@@ -73,7 +71,7 @@ class SqliteStore(CSStore):
         except sqlite3.IntegrityError as err:
             raise CSStoreExists(str(err))
         except sqlite3.Error as err:
-            log_error("Error storing key %s: [%r]" % (key, repr(err)))
+            logger.exception("Error storing key %s" % key)
             raise CSStoreError('Error occurred while trying to store key')
 
     def span(self, key):
@@ -88,8 +86,8 @@ class SqliteStore(CSStore):
                 c.execute(setdata, (name,))
         except sqlite3.IntegrityError as err:
             raise CSStoreExists(str(err))
-        except sqlite3.Error as err:
-            log_error("Error creating key %s: [%r]" % (name, repr(err)))
+        except sqlite3.Error:
+            logger.exception("Error creating key %s", name)
             raise CSStoreError('Error occurred while trying to span container')
 
     def list(self, keyfilter=''):
@@ -101,8 +99,8 @@ class SqliteStore(CSStore):
             conn = sqlite3.connect(self.dburi)
             r = conn.execute(search, (key,))
             rows = r.fetchall()
-        except sqlite3.Error as err:
-            log_error("Error listing %s: [%r]" % (keyfilter, repr(err)))
+        except sqlite3.Error:
+            logger.exception("Error listing %s: [%r]", keyfilter)
             raise CSStoreError('Error occurred while trying to list keys')
         if len(rows) > 0:
             parent_exists = False
@@ -130,8 +128,8 @@ class SqliteStore(CSStore):
             with conn:
                 c = conn.cursor()
                 r = c.execute(query, (key,))
-        except sqlite3.Error as err:
-            log_error("Error removing key %s: [%r]" % (key, repr(err)))
+        except sqlite3.Error:
+            logger.error("Error removing key %s", key)
             raise CSStoreError('Error occurred while trying to cut key')
         if r.rowcount > 0:
             return True