[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.

4 files changed, 42 insertions, 77 deletions

diff --git a/src/leap/bitmask/mail/imap/account.py b/src/leap/bitmask/mail/imap/account.py
index 63d214e4..9b26dbaa 100644
--- a/src/leap/bitmask/mail/imap/account.py
+++ b/src/leap/bitmask/mail/imap/account.py
@@ -32,16 +32,6 @@ from leap.bitmask.mail.mail import Account
 from leap.bitmask.mail.imap.mailbox import IMAPMailbox, normalize_mailbox
 from leap.soledad.client import Soledad
 
-logger = Logger()
-
-PROFILE_CMD = os.environ.get('LEAP_PROFILE_IMAPCMD', False)
-
-if PROFILE_CMD:
-    def _debugProfiling(result, cmdname, start):
-        took = (time.time() - start) * 1000
-        logger.debug("CMD " + cmdname + " TOOK: " + str(took) + " msec")
-        return result
-
 
 #######################################
 # Soledad IMAP Account
@@ -49,6 +39,7 @@ if PROFILE_CMD:
 
 
 class IMAPAccount(object):
+
     """
     An implementation of an imap4 Account
     that is backed by Soledad Encrypted Documents.
@@ -57,6 +48,7 @@ class IMAPAccount(object):
     implements(imap4.IAccount, imap4.INamespacePresenter)
 
     selected = None
+    log = Logger()
 
     def __init__(self, store, user_id, d=defer.Deferred()):
         """
@@ -246,7 +238,7 @@ class IMAPAccount(object):
 
         def check_it_exists(mailboxes):
             if name not in mailboxes:
-                logger.warn('SELECT: No such mailbox!')
+                self.log.warn('SELECT: No such mailbox!')
                 return None
             return name
 
diff --git a/src/leap/bitmask/mail/imap/mailbox.py b/src/leap/bitmask/mail/imap/mailbox.py
index 836b38fd..cc5d5df6 100644
--- a/src/leap/bitmask/mail/imap/mailbox.py
+++ b/src/leap/bitmask/mail/imap/mailbox.py
@@ -39,38 +39,11 @@ from leap.common.check import leap_assert_type
 from leap.bitmask.mail.constants import INBOX_NAME, MessageFlags
 from leap.bitmask.mail.imap.messages import IMAPMessage
 
-logger = Logger()
-
 # TODO LIST
-# [ ] Restore profile_cmd instrumentation
 # [ ] finish the implementation of IMailboxListener
 # [ ] implement the rest of ISearchableMailbox
 
 
-"""
-If the environment variable `LEAP_SKIPNOTIFY` is set, we avoid
-notifying clients of new messages. Use during stress tests.
-"""
-NOTIFY_NEW = not os.environ.get('LEAP_SKIPNOTIFY', False)
-PROFILE_CMD = os.environ.get('LEAP_PROFILE_IMAPCMD', False)
-
-if PROFILE_CMD:
-
-    def _debugProfiling(result, cmdname, start):
-        took = (time.time() - start) * 1000
-        logger.debug("CMD " + cmdname + " TOOK: " + str(took) + " msec")
-        return result
-
-    def do_profile_cmd(d, name):
-        """
-        Add the profiling debug to the passed callback.
-        :param d: deferred
-        :param name: name of the command
-        :type name: str
-        """
-        d.addCallback(_debugProfiling, name, time.time())
-        d.addErrback(lambda f: logger.error(f.getTraceback()))
-
 INIT_FLAGS = (MessageFlags.SEEN_FLAG, MessageFlags.ANSWERED_FLAG,
               MessageFlags.FLAGGED_FLAG, MessageFlags.DELETED_FLAG,
               MessageFlags.DRAFT_FLAG, MessageFlags.RECENT_FLAG,
@@ -107,6 +80,7 @@ def make_collection_listener(mailbox):
 
 
 class IMAPMailbox(object):
+
     """
     A Soledad-backed IMAP mailbox.
 
@@ -115,6 +89,7 @@ class IMAPMailbox(object):
     MessageCollection class. We receive an instance of it and it is made
     accessible in the `collection` attribute.
     """
+
     implements(
         imap4.IMailbox,
         imap4.IMailboxInfo,
@@ -133,6 +108,8 @@ class IMAPMailbox(object):
     CMD_UIDVALIDITY = "UIDVALIDITY"
     CMD_UNSEEN = "UNSEEN"
 
+    log = Logger()
+
     # TODO we should turn this into a datastructure with limited capacity
     _listeners = defaultdict(set)
 
@@ -184,12 +161,10 @@ class IMAPMailbox(object):
         :param listener: listener to add
         :type listener: an object that implements IMailboxListener
         """
-        if not NOTIFY_NEW:
-            return
 
         listeners = self.listeners
-        logger.debug('adding mailbox listener: %s. Total: %s' % (
-            listener, len(listeners)))
+        self.log.debug('Adding mailbox listener: %s. Total: %s' % (
+                       listener, len(listeners)))
         listeners.add(listener)
 
     def removeListener(self, listener):
@@ -407,7 +382,8 @@ class IMAPMailbox(object):
 
         d = self.collection.add_msg(message, flags, date=date,
                                     notify_just_mdoc=notify_just_mdoc)
-        d.addErrback(lambda failure: logger.error(failure))
+        d.addErrback(
+            lambda failure: self.log.failure('Error while adding msg'))
         return d
 
     def notify_new(self, *args):
@@ -432,7 +408,7 @@ class IMAPMailbox(object):
         d = self._get_notify_count()
         d.addCallback(cbNotifyNew)
         d.addCallback(self.collection.cb_signal_unread_to_ui)
-        d.addErrback(lambda failure: logger.error(failure))
+        d.addErrback(lambda failure: self.log.failure('Error while notify'))
 
     def _get_notify_count(self):
         """
@@ -451,7 +427,7 @@ class IMAPMailbox(object):
 
         def log_num_msg(result):
             exists, recent = tuple(result)
-            logger.debug("NOTIFY (%r): there are %s messages, %s recent" % (
+            self.log.debug("NOTIFY (%r): there are %s messages, %s recent" % (
                          self.mbox_name, exists, recent))
             return result
 
@@ -515,7 +491,8 @@ class IMAPMailbox(object):
         d = self._bound_seq(messages_asked, uid)
         if uid:
             d.addCallback(get_range)
-        d.addErrback(lambda f: logger.error(f))
+        d.addErrback(
+            lambda f: self.log.failure('Error getting msg range'))
         return d
 
     def _bound_seq(self, messages_asked, uid):
@@ -619,12 +596,15 @@ class IMAPMailbox(object):
             d = defer.gatherResults(d_msg, consumeErrors=True)
             d.addCallback(_get_imap_msg)
             d.addCallback(_zip_msgid)
-            d.addErrback(lambda failure: logger.error(failure))
+            d.addErrback(
+                lambda failure: self.log.error(
+                    'Error getting msg for range'))
             return d
 
         d = self._get_messages_range(messages_asked, uid)
         d.addCallback(get_imap_messages_for_range)
-        d.addErrback(lambda failure: logger.error(failure))
+        d.addErrback(
+            lambda failure: self.log.failure('Error on fetch'))
         return d
 
     def fetch_flags(self, messages_asked, uid):
@@ -802,17 +782,15 @@ class IMAPMailbox(object):
                                 read-write.
         """
         if not self.isWriteable():
-            logger.info('read only mailbox!')
+            self.log.info('Read only mailbox!')
             raise imap4.ReadOnlyMailbox
 
         d = defer.Deferred()
         reactor.callLater(0, self._do_store, messages_asked, flags,
                           mode, uid, d)
-        if PROFILE_CMD:
-            do_profile_cmd(d, "STORE")
 
         d.addCallback(self.collection.cb_signal_unread_to_ui)
-        d.addErrback(lambda f: logger.error(f))
+        d.addErrback(lambda f: self.log.error('Error on store'))
         return d
 
     def _do_store(self, messages_asked, flags, mode, uid, observer):
@@ -888,14 +866,14 @@ class IMAPMailbox(object):
         if len(query) > 2:
             if query[1] == 'HEADER' and query[2].lower() == "message-id":
                 msgid = str(query[3]).strip()
-                logger.debug("Searching for %s" % (msgid,))
+                self.log.debug('Searching for %s' % (msgid,))
 
                 d = self.collection.get_uid_from_msgid(str(msgid))
                 d.addCallback(lambda result: [result])
                 return d
 
         # nothing implemented for any other query
-        logger.warn("Cannot process query: %s" % (query,))
+        self.log.warn('Cannot process query: %s' % (query,))
         return []
 
     # IMessageCopier
diff --git a/src/leap/bitmask/mail/imap/server.py b/src/leap/bitmask/mail/imap/server.py
index 897e1f05..9eef6e83 100644
--- a/src/leap/bitmask/mail/imap/server.py
+++ b/src/leap/bitmask/mail/imap/server.py
@@ -32,10 +32,8 @@ from twisted.mail.imap4 import LiteralString, LiteralFile
 from leap.common.events import emit_async, catalog
 
 
-logger = Logger()
-
-
 def _getContentType(msg):
+
     """
     Return a two-tuple of the main and subtype of the given message.
     """
@@ -62,16 +60,21 @@ def _getContentType(msg):
         major = minor = None
     return major, minor, attrs
 
+
 # Monkey-patch _getContentType to avoid bug that passes lower-case boundary in
 # BODYSTRUCTURE response.
+
 imap4._getContentType = _getContentType
 
 
 class LEAPIMAPServer(imap4.IMAP4Server):
+
     """
     An IMAP4 Server with a LEAP Storage Backend.
     """
 
+    log = Logger()
+
     #############################################################
     #
     # Twisted imap4 patch to workaround bad mime rendering  in TB.
@@ -167,7 +170,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
             msg = line[:7] + " [...]"
         else:
             msg = copy(line)
-        logger.debug('rcv (%s): %s' % (self.state, msg))
+        self.log.debug('rcv (%s): %s' % (self.state, msg))
         imap4.IMAP4Server.lineReceived(self, line)
 
     def close_server_connection(self):
@@ -452,7 +455,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
 
         def _subscribeEb(failure):
             m = failure.value
-            logger.error()
+            self.log.error('Error on SUBSCRIBE')
             if failure.check(imap4.MailboxException):
                 self.sendNegativeResponse(tag, str(m))
             else:
@@ -477,7 +480,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
 
         def _unsubscribeEb(failure):
             m = failure.value
-            logger.error()
+            self.log.error('Error on UNSUBSCRIPBE')
             if failure.check(imap4.MailboxException):
                 self.sendNegativeResponse(tag, str(m))
             else:
@@ -512,7 +515,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
             elif failure.check(imap4.MailboxException):
                 self.sendNegativeResponse(tag, str(m))
             else:
-                logger.error()
+                self.log.error('Error on RENAME')
                 self.sendBadResponse(
                     tag,
                     "Server error encountered while "
@@ -539,7 +542,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
             if failure.check(imap4.MailboxException):
                 self.sendNegativeResponse(tag, str(c))
             else:
-                logger.error()
+                self.log.error('Error on CREATE')
                 self.sendBadResponse(
                     tag, "Server error encountered while creating mailbox")
 
@@ -564,7 +567,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
             if failure.check(imap4.MailboxException):
                 self.sendNegativeResponse(tag, str(m))
             else:
-                logger.error()
+                self.log.error('Error on DELETE')
                 self.sendBadResponse(
                     tag,
                     "Server error encountered while deleting mailbox")
@@ -600,7 +603,7 @@ class LEAPIMAPServer(imap4.IMAP4Server):
     def _ebAppendGotMailbox(self, failure, tag):
         self.sendBadResponse(
             tag, "Server error encountered while opening mailbox.")
-        logger.error(failure)
+        self.log.failure('Error appending')
 
     def __cbAppend(self, result, tag, mbox):
 
diff --git a/src/leap/bitmask/mail/imap/service/__init__.py b/src/leap/bitmask/mail/imap/service/__init__.py
index 880ff238..b3673c2e 100644
--- a/src/leap/bitmask/mail/imap/service/__init__.py
+++ b/src/leap/bitmask/mail/imap/service/__init__.py
@@ -37,7 +37,7 @@ from leap.bitmask.mail.imap.server import LEAPIMAPServer
 
 # TODO: leave only an implementor of IService in here
 
-logger = Logger()
+log = Logger()
 
 DO_MANHOLE = os.environ.get("LEAP_MAIL_MANHOLE", None)
 if DO_MANHOLE:
@@ -137,23 +137,15 @@ class LeapIMAPFactory(ServerFactory):
         :param addr: remote ip address
         :type addr:  str
         """
-        # TODO should reject anything from addr != localhost,
-        # just in case.
-        logger.debug("Building protocol for connection %s" % addr)
         imapProtocol = self.protocol(self._soledad_sessions)
         self._connections[addr] = imapProtocol
         return imapProtocol
 
     def stopFactory(self):
-        # say bye!
         for conn, proto in self._connections.items():
-            logger.debug("Closing connections for %s" % conn)
             proto.close_server_connection()
 
     def doStop(self):
-        """
-        Stops imap service (fetcher, factory and port).
-        """
         return ServerFactory.doStop(self)
 
 
@@ -182,10 +174,10 @@ def run_service(soledad_sessions, port=IMAP_PORT, factory=None):
         tport = reactor.listenTCP(port, factory,
                                   interface=interface)
     except CannotListenError:
-        logger.error("IMAP Service failed to start: "
-                     "cannot listen in port %s" % (port,))
+        log.error('IMAP Service failed to start: '
+                  'cannot listen in port %s' % (port,))
     except Exception as exc:
-        logger.error("Error launching IMAP service: %r" % (exc,))
+        log.error("Error launching IMAP service: %r" % (exc,))
     else:
         # all good.
 
@@ -198,7 +190,7 @@ def run_service(soledad_sessions, port=IMAP_PORT, factory=None):
             # TODO  use Endpoints !!!
             reactor.listenTCP(manhole.MANHOLE_PORT, manhole_factory,
                               interface="127.0.0.1")
-        logger.debug("IMAP4 Server is RUNNING in port  %s" % (port,))
+        log.debug('IMAP4 Server is RUNNING in port  %s' % (port,))
         emit_async(catalog.IMAP_SERVICE_STARTED, str(port))
 
         # FIXME -- change service signature