From 9f95446a55533c8cdceec7c4430be5cad752ecb1 Mon Sep 17 00:00:00 2001 From: "Kali Kaneko (leap communications)" Date: Tue, 25 Apr 2017 18:00:12 +0200 Subject: [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. --- src/leap/bitmask/mail/imap/mailbox.py | 64 ++++++++++++----------------------- 1 file changed, 21 insertions(+), 43 deletions(-) (limited to 'src/leap/bitmask/mail/imap/mailbox.py') diff --git a/src/leap/bitmask/mail/imap/mailbox.py b/src/leap/bitmask/mail/imap/mailbox.py index 836b38f..cc5d5df 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 -- cgit v1.2.3