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/account.py | 14 ++---- src/leap/bitmask/mail/imap/mailbox.py | 64 +++++++++----------------- src/leap/bitmask/mail/imap/server.py | 23 +++++---- src/leap/bitmask/mail/imap/service/__init__.py | 18 ++------ 4 files changed, 42 insertions(+), 77 deletions(-) (limited to 'src/leap/bitmask/mail/imap') 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 -- cgit v1.2.3