[bug] unify logging style using class attr

I changed most of the logger statements to use a class attribute, in
this way it's easier to identify which class it's logging them.

in some cases I leave a module-level logger, when we're either using
functions or when the module it's too small.

at the same time I did a general review and cleanup of the logging
statements.

6 files changed, 67 insertions, 73 deletions

diff --git a/src/leap/bitmask/keymanager/__init__.py b/src/leap/bitmask/keymanager/__init__.py
index fb4668c7..190e26ff 100644
--- a/src/leap/bitmask/keymanager/__init__.py
+++ b/src/leap/bitmask/keymanager/__init__.py
@@ -40,12 +40,6 @@ from leap.bitmask.keymanager.refresher import RandomRefreshPublicKey
 from leap.bitmask.keymanager.validation import ValidationLevels, can_upgrade
 from leap.bitmask.keymanager.openpgp import OpenPGPScheme
 
-logger = Logger()
-
-
-#
-# The Key Manager
-#
 
 class KeyManager(object):
 
@@ -53,6 +47,8 @@ class KeyManager(object):
     # server's key storage constants
     #
 
+    log = Logger()
+
     OPENPGP_KEY = 'openpgp'
     PUBKEY_KEY = "user[public_key]"
 
@@ -94,7 +90,7 @@ class KeyManager(object):
         try:
             self._combined_ca_bundle = combined_ca_bundle or create()
         except Exception:
-            logger.warn('error while creating combined ca bundle')
+            self.log.warn('Error while creating combined ca bundle')
             self._combined_ca_bundle = ''
 
         self._async_client = HTTPClient(self._combined_ca_bundle)
@@ -155,17 +151,17 @@ class KeyManager(object):
         except keymanager_errors.KeyNotFound:
             raise
         except IOError as e:
-            logger.warn("HTTP error retrieving key: %r" % (e,))
-            logger.warn("%s" % (content,))
+            self.log.warn("HTTP error retrieving key: %r" % (e,))
+            self.log.warn("%s" % (content,))
             raise keymanager_errors.KeyNotFound(e.message), \
                 None, sys.exc_info()[2]
         except ValueError as v:
-            logger.warn("invalid JSON data from key: %s" % (uri,))
+            self.log.warn("Invalid JSON data from key: %s" % (uri,))
             raise keymanager_errors.KeyNotFound(v.message + ' - ' + uri), \
                 None, sys.exc_info()[2]
 
         except Exception as e:
-            logger.warn("error retrieving key: %r" % (e,))
+            self.log.warn("Error retrieving key: %r" % (e,))
             raise keymanager_errors.KeyNotFound(e.message), \
                 None, sys.exc_info()[2]
         # Responses are now text/plain, although it's json anyway, but
@@ -190,7 +186,7 @@ class KeyManager(object):
         def check_404(response):
             if response.code == NOT_FOUND:
                 message = '%s: %s key not found.' % (response.code, address)
-                logger.warn(message)
+                self.log.warn(message)
                 raise KeyNotFound(message), None, sys.exc_info()[2]
             return response
 
@@ -218,7 +214,7 @@ class KeyManager(object):
         try:
             content = yield self._async_client.request(str(uri), 'GET')
         except Exception as e:
-            logger.warn("There was a problem fetching key: %s" % (e,))
+            self.log.warn("There was a problem fetching key: %s" % (e,))
             raise keymanager_errors.KeyNotFound(uri)
         if not content:
             raise keymanager_errors.KeyNotFound(uri)
@@ -307,8 +303,7 @@ class KeyManager(object):
 
         :raise UnsupportedKeyTypeError: if invalid key type
         """
-        logger.debug("getting key for %s" % (address,))
-
+        self.log.debug('Getting key for %s' % (address,))
         emit_async(catalog.KEYMANAGER_LOOKING_FOR_KEY, address)
 
         def key_found(key):
@@ -455,7 +450,6 @@ class KeyManager(object):
 
         :raise UnsupportedKeyTypeError: if invalid key type
         """
-
         @defer.inlineCallbacks
         def encrypt(keys):
             pubkey, signkey = keys
@@ -726,7 +720,7 @@ class KeyManager(object):
         :raise UnsupportedKeyTypeError: if invalid key type
         """
 
-        logger.info("fetch key for %s from %s" % (address, uri))
+        self.log.info('Fetch key for %s from %s' % (address, uri))
         key_content = yield self._get_with_combined_ca_bundle(uri)
 
         # XXX parse binary keys
diff --git a/src/leap/bitmask/keymanager/keys.py b/src/leap/bitmask/keymanager/keys.py
index 622c1c68..54609c05 100644
--- a/src/leap/bitmask/keymanager/keys.py
+++ b/src/leap/bitmask/keymanager/keys.py
@@ -30,7 +30,7 @@ from leap.bitmask.keymanager.wrapper import TempGPGWrapper
 from leap.bitmask.keymanager.validation import ValidationLevels
 from leap.bitmask.keymanager import documents as doc
 
-logger = Logger()
+log = Logger()
 
 
 #
@@ -71,9 +71,9 @@ def build_key_from_dict(key, active=None):
         try:
             validation = ValidationLevels.get(active[doc.KEY_VALIDATION_KEY])
         except ValueError:
-            logger.error("Not valid validation level (%s) for key %s",
-                         (active[doc.KEY_VALIDATION_KEY],
-                          active[doc.KEY_FINGERPRINT_KEY]))
+            log.error('Not valid validation level (%s) for key %s',
+                      (active[doc.KEY_VALIDATION_KEY],
+                       active[doc.KEY_FINGERPRINT_KEY]))
         last_audited_at = _to_datetime(active[doc.KEY_LAST_AUDITED_AT_KEY])
         encr_used = active[doc.KEY_ENCR_USED_KEY]
         sign_used = active[doc.KEY_SIGN_USED_KEY]
@@ -112,6 +112,7 @@ def _to_unix_time(date):
 
 
 class OpenPGPKey(object):
+
     """
     Base class for OpenPGP keys.
     """
@@ -120,6 +121,7 @@ class OpenPGPKey(object):
                  'private', 'length', 'expiry_date', 'validation',
                  'last_audited_at', 'refreshed_at',
                  'encr_used', 'sign_used', '_index', '_gpgbinary')
+    log = Logger()
 
     def __init__(self, address=None, gpgbinary=None, uids=[], fingerprint="",
                  key_data="", private=False, length=0, expiry_date=None,
@@ -184,7 +186,7 @@ class OpenPGPKey(object):
 
     def merge(self, newkey):
         if newkey.fingerprint != self.fingerprint:
-            logger.critical(
+            self.log.critical(
                 "Can't put a key whith the same key_id and different "
                 "fingerprint: %s, %s"
                 % (newkey.fingerprint, self.fingerprint))
diff --git a/src/leap/bitmask/keymanager/nicknym.py b/src/leap/bitmask/keymanager/nicknym.py
index 7c738da0..8e3a08f9 100644
--- a/src/leap/bitmask/keymanager/nicknym.py
+++ b/src/leap/bitmask/keymanager/nicknym.py
@@ -1,6 +1,6 @@
 # -*- coding: utf-8 -*-
 # nicknym.py
-# Copyright (C) 2016 LEAP
+# Copyright (C) 2016-2017 LEAP
 #
 # This program is free software: you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
@@ -17,10 +17,10 @@
 
 import json
 import sys
-import logging
 import urllib
 
 from twisted.internet import defer
+from twisted.logger import Logger
 from twisted.web import client
 from twisted.web._responses import NOT_FOUND
 
@@ -30,14 +30,14 @@ from leap.common.http import HTTPClient
 from leap.common.decorators import memoized_method
 
 
-logger = logging.getLogger(__name__)
-
-
 class Nicknym(object):
+
     """
     Responsible for communication to the nicknym server.
     """
 
+    log = Logger()
+
     PUBKEY_KEY = "user[public_key]"
 
     def __init__(self, nickserver_uri, ca_cert_path, token):
@@ -83,12 +83,12 @@ class Nicknym(object):
                                                           body=str(data),
                                                           headers=headers)
         except Exception as e:
-            logger.warning("Error uploading key: %r" % (e,))
+            self.log.warn('Error uploading key: %r' % (e,))
             raise e
         if 'error' in res:
             # FIXME: That's a workaround for 500,
             # we need to implement a readBody to assert response code
-            logger.warning("Error uploading key: %r" % (res,))
+            self.log.warn('Error uploading key: %r' % (res,))
             raise Exception(res)
 
     @defer.inlineCallbacks
@@ -105,19 +105,17 @@ class Nicknym(object):
         try:
             content = yield self._fetch_and_handle_404_from_nicknym(uri)
             json_content = json.loads(content)
-
         except KeyNotFound:
             raise
         except IOError as e:
-            logger.warning("HTTP error retrieving key: %r" % (e,))
-            logger.warning("%s" % (content,))
+            self.log.warn('HTTP error retrieving key: %r' % (e,))
+            self.log.warn("%s" % (content,))
             raise KeyNotFound(e.message), None, sys.exc_info()[2]
         except ValueError as v:
-            logger.warning("Invalid JSON data from key: %s" % (uri,))
+            self.log.warn('Invalid JSON data from key: %s' % (uri,))
             raise KeyNotFound(v.message + ' - ' + uri), None, sys.exc_info()[2]
-
         except Exception as e:
-            logger.warning("Error retrieving key: %r" % (e,))
+            self.log.warn('Error retrieving key: %r' % (e,))
             raise KeyNotFound(e.message), None, sys.exc_info()[2]
         # Responses are now text/plain, although it's json anyway, but
         # this will fail when it shouldn't
@@ -141,7 +139,7 @@ class Nicknym(object):
             if response.code == NOT_FOUND:
                 message = ' %s: Key not found. Request: %s' \
                           % (response.code, uri)
-                logger.warning(message)
+                self.log.warn(message)
                 raise KeyNotFound(message), None, sys.exc_info()[2]
             return response
 
diff --git a/src/leap/bitmask/keymanager/openpgp.py b/src/leap/bitmask/keymanager/openpgp.py
index b72c62ce..8c9dc1e8 100644
--- a/src/leap/bitmask/keymanager/openpgp.py
+++ b/src/leap/bitmask/keymanager/openpgp.py
@@ -1,6 +1,6 @@
 # -*- coding: utf-8 -*-
 # openpgp.py
-# Copyright (C) 2013-2016 LEAP
+# Copyright (C) 2013-2017 LEAP
 #
 # This program is free software: you can redistribute it and/or modify
 # it under the terms of the GNU General Public License as published by
@@ -14,9 +14,11 @@
 #
 # You should have received a copy of the GNU General Public License
 # along with this program. If not, see <http://www.gnu.org/licenses/>.
+
 """
 Infrastructure for using OpenPGP keys in Key Manager.
 """
+
 import os
 import re
 import tempfile
@@ -74,13 +76,6 @@ except ImportError:
             return bool(result.key)
 
 
-logger = Logger()
-
-
-#
-# A temporary GPG keyring wrapped to provide OpenPGP functionality.
-#
-
 # This function will be used to call blocking GPG functions outside
 # of Twisted reactor and match the concurrent calls to the amount of CPU cores
 cpu_core_semaphore = defer.DeferredSemaphore(cpu_count())
@@ -91,16 +86,22 @@ def from_thread(func, *args, **kwargs):
     return cpu_core_semaphore.run(call)
 
 
+log = Logger()
+
+
 #
 # The OpenPGP wrapper
 #
 
 class OpenPGPScheme(object):
+
     """
     A wrapper for OpenPGP keys management and use (encryption, decyption,
     signing and verification).
     """
 
+    log = Logger()
+
     # type used on the soledad documents
     KEY_TYPE = OpenPGPKey.__name__
     ACTIVE_TYPE = KEY_TYPE + KEYMANAGER_ACTIVE_TYPE
@@ -186,11 +187,11 @@ class OpenPGPScheme(object):
                     name_real=address,
                     name_email=address,
                     name_comment='')
-                logger.info("About to generate keys... "
-                            "This might take SOME time.")
+                self.log.info('About to generate keys... '
+                              'This might take SOME time.')
                 yield from_thread(gpg.gen_key, params)
-                logger.info("Keys for %s have been successfully "
-                            "generated." % (address,))
+                self.log.info('Keys for %s have been successfully '
+                              'generated.' % (address,))
                 pubkeys = gpg.list_keys()
 
                 # assert for new key characteristics
@@ -509,8 +510,8 @@ class OpenPGPScheme(object):
             if len(docs) == 0:
                 raise errors.KeyNotFound(key)
             elif len(docs) > 1:
-                logger.warn("There is more than one key for fingerprint %s"
-                            % key.fingerprint)
+                self.log.warn('There is more than one key for fingerprint %s'
+                              % key.fingerprint)
 
             has_deleted = False
             deferreds = []
@@ -559,7 +560,7 @@ class OpenPGPScheme(object):
         """
         stderr = getattr(result, 'stderr', None)
         if stderr:
-            logger.debug("%s" % (stderr,))
+            log.debug("%s" % (stderr,))
         if getattr(result, 'ok', None) is not True:
             raise errors.GPGError(
                 'Failed to encrypt/decrypt: %s' % stderr)
@@ -612,7 +613,7 @@ class OpenPGPScheme(object):
                 self._assert_gpg_result_ok(result)
                 defer.returnValue(result.data)
             except errors.GPGError as e:
-                logger.warn('Failed to encrypt: %s.' % str(e))
+                self.log.warn('Failed to encrypt: %s.' % str(e))
                 raise errors.EncryptError()
 
     @defer.inlineCallbacks
@@ -658,7 +659,7 @@ class OpenPGPScheme(object):
 
                 defer.returnValue((result.data, sign_valid))
             except errors.GPGError as e:
-                logger.warn('Failed to decrypt: %s.' % str(e))
+                self.log.warn('Failed to decrypt: %s.' % str(e))
                 raise errors.DecryptError(str(e))
 
     def is_encrypted(self, data):
@@ -803,8 +804,8 @@ class OpenPGPScheme(object):
         :rtype: Deferred
         """
         def log_key_doc(doc):
-            logger.error("\t%s: %s" % (doc.content[KEY_UIDS_KEY],
-                                       doc.content[KEY_FINGERPRINT_KEY]))
+            self.log.error("\t%s: %s" % (doc.content[KEY_UIDS_KEY],
+                                         doc.content[KEY_FINGERPRINT_KEY]))
 
         def cmp_key(d1, d2):
             return cmp(d1.content[KEY_REFRESHED_AT_KEY],
@@ -833,8 +834,8 @@ class OpenPGPScheme(object):
                 pass
 
         def log_active_doc(doc):
-            logger.error("\t%s: %s" % (doc.content[KEY_ADDRESS_KEY],
-                                       doc.content[KEY_FINGERPRINT_KEY]))
+            self.log.error("\t%s: %s" % (doc.content[KEY_ADDRESS_KEY],
+                                         doc.content[KEY_FINGERPRINT_KEY]))
 
         def cmp_active(d1, d2):
             # XXX: for private keys it will be nice to check which key is known
@@ -857,9 +858,9 @@ class OpenPGPScheme(object):
         defer.returnValue(doc)
 
     def _repair_docs(self, doclist, cmp_func, log_func):
-        logger.error("BUG ---------------------------------------------------")
-        logger.error("There is more than one doc of type %s:"
-                     % (doclist[0].content[KEY_TYPE_KEY],))
+        self.log.error("BUG -------------------------------------------------")
+        self.log.error("There is more than one doc of type %s:"
+                       % (doclist[0].content[KEY_TYPE_KEY],))
 
         doclist.sort(cmp=cmp_func, reverse=True)
         log_func(doclist[0])
@@ -869,9 +870,8 @@ class OpenPGPScheme(object):
             d = self._soledad.delete_doc(doc)
             deferreds.append(d)
 
-        logger.error("")
-        logger.error(traceback.extract_stack())
-        logger.error("BUG (please report above info) ------------------------")
+        self.log.error('Error repairing')
+        self.log.error("BUG (please report above info) ----------------------")
         d = defer.gatherResults(deferreds, consumeErrors=True)
         d.addCallback(lambda _: doclist[0])
         return d
diff --git a/src/leap/bitmask/keymanager/refresher.py b/src/leap/bitmask/keymanager/refresher.py
index 694a537f..d1ae9f84 100644
--- a/src/leap/bitmask/keymanager/refresher.py
+++ b/src/leap/bitmask/keymanager/refresher.py
@@ -28,18 +28,18 @@ from random import choice, randrange
 
 DEBUG_STOP_REFRESH = "Stop to refresh the key directory ..."
 DEBUG_START_REFRESH = "Start to refresh the key directory ..."
-ERROR_UNEQUAL_FINGERPRINTS = "[WARNING] Your provider might be cheat " \
-                             "on you, and gave a wrong key back. " \
-                             "Fingerprints are unequal, old %s new %s "
+ERROR_UNEQUAL_FINGERPRINTS = "[WARNING] Your provider *might* be cheating " \
+                             "on you, and given a wrong key back. " \
+                             "Fingerprints do not match: old-> %s, new-> %s "
 
 MIN_RANDOM_INTERVAL_RANGE = 4 * 60  # four minutes
 MAX_RANDOM_INTERVAL_RANGE = 6 * 60  # six minutes
 
-logger = Logger()
-
 
 class RandomRefreshPublicKey(object):
 
+    log = Logger()
+
     def __init__(self, openpgp, keymanager):
         """
         Initialize the RandomRefreshPublicKey.
@@ -59,14 +59,14 @@ class RandomRefreshPublicKey(object):
         :rtype: A deferred.
         """
         self._loop.start(self._get_random_interval_to_refresh(), False)
-        logger.debug(DEBUG_START_REFRESH)
+        self.log.debug(DEBUG_START_REFRESH)
 
     def stop(self):
         """
         Stop the looping call with random interval.
         """
         self._loop.stop()
-        logger.debug(DEBUG_STOP_REFRESH)
+        self.log.debug(DEBUG_STOP_REFRESH)
 
     @defer.inlineCallbacks
     def _get_random_key(self):
@@ -110,7 +110,7 @@ class RandomRefreshPublicKey(object):
             fetch_key_with_fingerprint(old_key.fingerprint)
 
         if old_updated_key.fingerprint != old_key.fingerprint:
-            logger.error(ERROR_UNEQUAL_FINGERPRINTS %
+            self.log.error(ERROR_UNEQUAL_FINGERPRINTS %
                          (old_key.fingerprint, old_updated_key.fingerprint))
             defer.returnValue(None)
 
diff --git a/src/leap/bitmask/keymanager/wrapper.py b/src/leap/bitmask/keymanager/wrapper.py
index ef8e6640..eb5074f3 100644
--- a/src/leap/bitmask/keymanager/wrapper.py
+++ b/src/leap/bitmask/keymanager/wrapper.py
@@ -35,7 +35,6 @@ except ImportError:
     GNUPG_NG = False
 
 
-logger = Logger()
 
 
 class TempGPGWrapper(object):
@@ -43,6 +42,7 @@ class TempGPGWrapper(object):
     A context manager that wraps a temporary GPG keyring which only contains
     the keys given at object creation.
     """
+    log = Logger()
 
     def __init__(self, keys=None, gpgbinary=None):
         """
@@ -160,6 +160,6 @@ class TempGPGWrapper(object):
             homedir = os.path.normpath(homedir).replace("\\", "/")
             homedir = str(homedir.replace("c:/", "c://"))
             if platform.system() == "Windows":
-                logger.error("BUG! Not erasing folder in Windows")
+                self.log.error("BUG! Not erasing folder in Windows")
                 return
             shutil.rmtree(homedir)