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/adaptors/soledad.py | 31 +++++------ 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 ++----- src/leap/bitmask/mail/incoming/service.py | 29 ++++++----- src/leap/bitmask/mail/mail.py | 28 ++++++---- src/leap/bitmask/mail/outgoing/service.py | 19 +++---- src/leap/bitmask/mail/rfc3156.py | 4 +- src/leap/bitmask/mail/smtp/__init__.py | 71 -------------------------- src/leap/bitmask/mail/smtp/gateway.py | 17 +++--- src/leap/bitmask/mail/smtp/service.py | 10 ++-- src/leap/bitmask/mail/sync_hooks.py | 11 ++-- src/leap/bitmask/mail/testing/imap.py | 4 +- 14 files changed, 125 insertions(+), 218 deletions(-) (limited to 'src/leap/bitmask/mail') diff --git a/src/leap/bitmask/mail/adaptors/soledad.py b/src/leap/bitmask/mail/adaptors/soledad.py index 6a057d6..a3e011a 100644 --- a/src/leap/bitmask/mail/adaptors/soledad.py +++ b/src/leap/bitmask/mail/adaptors/soledad.py @@ -41,8 +41,6 @@ from leap.soledad.common import l2db from leap.soledad.common.document import SoledadDocument -logger = Logger() - # TODO # [ ] Convenience function to create mail specifying subject, date, etc? @@ -67,6 +65,7 @@ def cleanup_deferred_locks(): class SoledadDocumentWrapper(models.DocumentWrapper): + """ A Wrapper object that can be manipulated, passed around, and serialized in a format that the Soledad Store understands. @@ -74,6 +73,9 @@ class SoledadDocumentWrapper(models.DocumentWrapper): It ensures atomicity of the document operations on creation, update and deletion. """ + + log = Logger() + # TODO we could also use a _dirty flag (in models) # TODO add a get_count() method ??? -- that is extended over l2db. @@ -186,7 +188,7 @@ class SoledadDocumentWrapper(models.DocumentWrapper): # error, we should mark them in the copy so there is no attempt to # create/update them. failure.trap(l2db.errors.RevisionConflict) - logger.debug("got conflict while putting %s" % doc_id) + self.log.debug('Got conflict while putting %s' % doc_id) def delete(self, store): """ @@ -506,7 +508,7 @@ class MessageWrapper(object): for (key, doc) in cdocs.items()]) for doc_id, cdoc in zip(self.mdoc.cdocs, self.cdocs.values()): if cdoc.raw == "": - logger.warn("Empty raw field in cdoc %s" % doc_id) + self.log.warn('Empty raw field in cdoc %s' % doc_id) cdoc.set_future_doc_id(doc_id) def create(self, store, notify_just_mdoc=False, pending_inserts_dict=None): @@ -588,7 +590,7 @@ class MessageWrapper(object): self.d.append(cdoc.create(store)) def log_all_inserted(result): - logger.debug("All parts inserted for msg!") + self.log.debug('All parts inserted for msg!') return result self.all_inserted_d = defer.gatherResults(self.d, consumeErrors=True) @@ -850,6 +852,8 @@ class SoledadMailAdaptor(SoledadIndexMixin): mboxwrapper_klass = MailboxWrapper + log = Logger() + def __init__(self): SoledadIndexMixin.__init__(self) @@ -948,15 +952,15 @@ class SoledadMailAdaptor(SoledadIndexMixin): # See https://leap.se/code/issues/7495. # This avoids blocks, but the real cause still needs to be # isolated (0.9.0rc3) -- kali - logger.debug("BUG ------------------------------------------") - logger.debug( + self.log.debug("BUG ------------------------------------------") + self.log.debug( "BUG: Error while retrieving part docs for mdoc id %s" % mdoc_id) - logger.debug("BUG (please report above info) ---------------") + self.log.debug("BUG (please report above info) ---------------") return [] def _err_log_cannot_find_msg(failure): - logger.error("BUG: Error while getting msg (uid=%s)" % uid) + self.log.error('BUG: Error while getting msg (uid=%s)' % uid) return None if get_cdocs: @@ -1089,7 +1093,7 @@ class SoledadMailAdaptor(SoledadIndexMixin): unseen_index = indexes.TYPE_MBOX_SEEN_IDX d = store.get_count_from_index(unseen_index, type_, uuid, "0") - d.addErrback(self._errback) + d.addErrback(lambda f: self.log.error('Error on count_unseen')) return d def get_count_recent(self, store, mbox_uuid): @@ -1106,7 +1110,7 @@ class SoledadMailAdaptor(SoledadIndexMixin): recent_index = indexes.TYPE_MBOX_RECENT_IDX d = store.get_count_from_index(recent_index, type_, uuid, "1") - d.addErrback(self._errback) + d.addErrback(lambda f: self.log.error('Error on count_recent')) return d # search api @@ -1124,7 +1128,7 @@ class SoledadMailAdaptor(SoledadIndexMixin): def get_mdoc_id(hdoc): if not hdoc: - logger.warn("Could not find a HDOC with MSGID %s" % msgid) + self.log.warn("Could not find a HDOC with MSGID %s" % msgid) return None hdoc = hdoc[0] mdoc_id = hdoc.doc_id.replace("H-", "M-%s-" % uuid) @@ -1175,9 +1179,6 @@ class SoledadMailAdaptor(SoledadIndexMixin): """ return MailboxWrapper.get_all(store) - def _errback(self, failure): - logger.failure() - def _split_into_parts(raw): # TODO signal that we can delete the original message!----- diff --git a/src/leap/bitmask/mail/imap/account.py b/src/leap/bitmask/mail/imap/account.py index 63d214e..9b26dba 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 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 diff --git a/src/leap/bitmask/mail/imap/server.py b/src/leap/bitmask/mail/imap/server.py index 897e1f0..9eef6e8 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 880ff23..b3673c2 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 diff --git a/src/leap/bitmask/mail/incoming/service.py b/src/leap/bitmask/mail/incoming/service.py index 9ed76a0..45d0e39 100644 --- a/src/leap/bitmask/mail/incoming/service.py +++ b/src/leap/bitmask/mail/incoming/service.py @@ -164,7 +164,8 @@ class IncomingMail(Service): Calls a deferred that will execute the fetch callback. """ def _sync_errback(failure): - self.log.failure('Error while fetching incoming mail') + self.log.error( + 'Error while fetching incoming mail {0!r}'.format(failure)) def syncSoledadCallback(_): # XXX this should be moved to adaptors @@ -219,7 +220,8 @@ class IncomingMail(Service): # synchronize incoming mail def _errback(self, failure): - self.log.failure('Error while processing incoming mail') + self.log.error( + 'Error while processing incoming mail {0!r}'.format(failure)) def _sync_soledad(self): """ @@ -234,7 +236,7 @@ class IncomingMail(Service): def _handle_invalid_auth_token_error(failure): failure.trap(InvalidAuthTokenError) - self.log.warn('sync failed because token is invalid: %r' % failure) + self.log.warn('Sync failed because token is invalid: %r' % failure) self.stopService() emit_async(catalog.SOLEDAD_INVALID_AUTH_TOKEN, self._userid) @@ -338,7 +340,7 @@ class IncomingMail(Service): return self._process_decrypted_doc(doc, decrdata) def log_doc_id_and_call_errback(failure): - self.log.failure( + self.log.error( '_decrypt_doc: Error decrypting document with ' 'ID %s' % doc.doc_id) @@ -368,8 +370,10 @@ class IncomingMail(Service): # the deferreds that would process an individual document try: msg = json_loads(data) - except (UnicodeError, ValueError): - self.log.failure("Error while decrypting %s" % (doc.doc_id,)) + except (UnicodeError, ValueError) as exc: + self.log.error('Error while decrypting %s' % + (doc.doc_id,)) + self.log.error(str(exc)) # we flag the message as "with decrypting errors", # to avoid further decryption attempts during sync @@ -764,12 +768,13 @@ class IncomingMail(Service): % (url,)) elif failure.check(keymanager_errors.KeyAttributesDiffer): self.log.warn("Key from OpenPGP header url %s didn't " - "match the from address %s" - % (url, address)) + "match the from address %s" + % (url, address)) else: - self.log.warn("An error has ocurred adding key from " - "OpenPGP header url %s for %s: %s" % - (url, address, failure.getErrorMessage())) + self.log.warn( + "An error has ocurred adding key from " + "OpenPGP header url %s for %s: %s" % + (url, address, failure.getErrorMessage())) return False d = self._keymanager.fetch_key(address, url) @@ -804,7 +809,7 @@ class IncomingMail(Service): def failed_put_key(failure): self.log.info("An error has ocurred adding attached key for %s: %s" - % (address, failure.getErrorMessage())) + % (address, failure.getErrorMessage())) return False deferreds = [] diff --git a/src/leap/bitmask/mail/mail.py b/src/leap/bitmask/mail/mail.py index 9f60ff0..8cc01e2 100644 --- a/src/leap/bitmask/mail/mail.py +++ b/src/leap/bitmask/mail/mail.py @@ -43,7 +43,7 @@ from leap.bitmask.mail.plugins import soledad_sync_hooks from leap.bitmask.mail.utils import find_charset, CaseInsensitiveDict from leap.bitmask.mail.utils import lowerdict -logger = Logger() +log = Logger() # TODO LIST @@ -98,7 +98,7 @@ def _encode_payload(payload, ctype=""): if isinstance(payload, unicode): payload = payload.encode(charset) except UnicodeError as exc: - logger.error( + log.error( "Unicode error, using 'replace'. {0!r}".format(exc)) payload = payload.encode(charset, 'replace') return payload @@ -122,13 +122,17 @@ def _unpack_headers(headers_dict): class MessagePart(object): + # TODO This class should be better abstracted from the data model. # TODO support arbitrarily nested multiparts (right now we only support # the trivial case) + """ Represents a part of a multipart MIME Message. """ + log = Logger() + def __init__(self, part_map, cdocs=None, nested=False): """ :param part_map: a dictionary mapping the subparts for @@ -191,7 +195,7 @@ class MessagePart(object): try: part_map = sub_pmap[str(part)] except KeyError: - logger.debug("getSubpart for %s: KeyError" % (part,)) + self.log.debug('get_subpart for %s: KeyError' % (part,)) raise IndexError return MessagePart(part_map, cdocs=self._cdocs, nested=True) @@ -203,6 +207,7 @@ class MessagePart(object): class Message(object): + """ Represents a single message, and gives access to all its attributes. """ @@ -325,6 +330,7 @@ class Flagsmode(object): class MessageCollection(object): + """ A generic collection of messages. It can be messages sharing the same mailbox, tag, the result of a given query, or just a bunch of ids for @@ -340,6 +346,8 @@ class MessageCollection(object): instance or proxy, for instance). """ + log = Logger() + # TODO LIST # [ ] look at IMessageSet methods # [ ] make constructor with a per-instance deferredLock to use on @@ -438,7 +446,7 @@ class MessageCollection(object): d.addCallback( lambda uid: self.get_message_by_uid( uid, get_cdocs=get_cdocs)) - d.addErrback(logger.error) + d.addErrback(self.log.error('Error getting msg by seq')) return d def get_message_by_uid(self, uid, absolute=True, get_cdocs=False): @@ -611,7 +619,7 @@ class MessageCollection(object): headers = lowerdict(msg.get_headers()) moz_draft_hdr = "X-Mozilla-Draft-Info" if moz_draft_hdr.lower() in headers: - logger.debug("setting fast notify to False, Draft detected") + self.log.debug('Setting fast notify to False, Draft detected') notify_just_mdoc = False if notify_just_mdoc: @@ -635,9 +643,9 @@ class MessageCollection(object): # --- BUG ----------------------------------------- # XXX watch out, sometimes mdoc doesn't have doc_id # but it has future_id. Should be solved already. - logger.error("BUG: (please report) Null doc_id for " - "document %s" % - (wrapper.mdoc.serialize(),)) + self.log.error('BUG: (please report) Null doc_id for ' + 'document %s' % + (wrapper.mdoc.serialize(),)) return defer.succeed("mdoc_id not inserted") # XXX BUG ----------------------------------------- @@ -656,7 +664,7 @@ class MessageCollection(object): d.addCallback(insert_mdoc_id, wrapper) d.addCallback(self.cb_signal_unread_to_ui) d.addCallback(self.notify_new_to_listeners) - d.addErrback(logger.error) + d.addErrback(lambda f: self.log.error('Error adding msg!')) return d @@ -743,7 +751,6 @@ class MessageCollection(object): def insert_doc(_, mbox_uuid, doc_id): d = self.mbox_indexer.get_uid_from_doc_id(mbox_uuid, doc_id) d.addCallback(insert_conditionally, mbox_uuid, doc_id) - d.addErrback(logger.error) d.addCallback(log_result) return d @@ -801,7 +808,6 @@ class MessageCollection(object): self.store, self.mbox_uuid) mdocs_deleted.addCallback(get_uid_list) mdocs_deleted.addCallback(delete_uid_entries) - mdocs_deleted.addErrback(logger.error) return mdocs_deleted # TODO should add a delete-by-uid to collection? diff --git a/src/leap/bitmask/mail/outgoing/service.py b/src/leap/bitmask/mail/outgoing/service.py index bd578ed..a3b8d00 100644 --- a/src/leap/bitmask/mail/outgoing/service.py +++ b/src/leap/bitmask/mail/outgoing/service.py @@ -55,11 +55,6 @@ from leap.bitmask.mail.rfc3156 import PGPEncrypted # [ ] rename this module to something else, service should be the implementor # of IService -logger = Logger() - - -logger = Logger() - class SSLContextFactory(ssl.ClientContextFactory): def __init__(self, cert, key): @@ -99,6 +94,8 @@ class OutgoingMail(object): Sends Outgoing Mail, encrypting and signing if needed. """ + log = Logger() + def __init__(self, from_address, keymanager, cert, key, host, port, bouncer=None): """ @@ -167,7 +164,7 @@ class OutgoingMail(object): """ dest_addrstr = smtp_sender_result[1][0][0] fromaddr = self._from_address - logger.info('Message sent from %s to %s' % (fromaddr, dest_addrstr)) + self.log.info('Message sent from %s to %s' % (fromaddr, dest_addrstr)) emit_async(catalog.SMTP_SEND_MESSAGE_SUCCESS, fromaddr, dest_addrstr) @@ -190,7 +187,7 @@ class OutgoingMail(object): # temporal error. We might want to notify the permanent errors # differently. - logger.error(failure) + self.log.error('Error while sending: {0!r}'.format(failure)) if self._bouncer: self._bouncer.bounce_message( @@ -208,7 +205,7 @@ class OutgoingMail(object): :type encrypt_and_sign_result: tuple """ message, recipient = encrypt_and_sign_result - logger.info( + self.log.info( 'Connecting to SMTP server %s:%s' % (self._host, self._port)) msg = message.as_string(False) @@ -302,7 +299,7 @@ class OutgoingMail(object): def if_key_not_found_send_unencrypted(failure, message): failure.trap(KeyNotFound, KeyAddressMismatch) - logger.info('Will send unencrypted message to %s.' % to_address) + self.log.info('Will send unencrypted message to %s.' % to_address) emit_async(catalog.SMTP_START_SIGN, self._from_address, to_address) d = self._sign(message, from_address) d.addCallback(signal_sign) @@ -312,8 +309,8 @@ class OutgoingMail(object): emit_async(catalog.SMTP_END_SIGN, self._from_address) return newmsg, recipient - logger.info("Will encrypt the message with %s and sign with %s." - % (to_address, from_address)) + self.log.info("Will encrypt the message with %s and sign with %s." + % (to_address, from_address)) emit_async(catalog.SMTP_START_ENCRYPT_AND_SIGN, self._from_address, "%s,%s" % (self._from_address, to_address)) diff --git a/src/leap/bitmask/mail/rfc3156.py b/src/leap/bitmask/mail/rfc3156.py index e602b6b..cb59268 100644 --- a/src/leap/bitmask/mail/rfc3156.py +++ b/src/leap/bitmask/mail/rfc3156.py @@ -34,7 +34,7 @@ from email.generator import ( _make_boundary, ) -logger = Logger() +log = Logger() # # A generator that solves http://bugs.python.org/issue14983 @@ -166,7 +166,7 @@ def encode_base64(msg): except KeyError: msg['Content-Transfer-Encoding'] = 'base64' elif encoding is not 'base64': - logger.error('Unknown content-transfer-encoding: %s' % encoding) + log.error('Unknown content-transfer-encoding: %s' % encoding) def encode_base64_rec(msg): diff --git a/src/leap/bitmask/mail/smtp/__init__.py b/src/leap/bitmask/mail/smtp/__init__.py index 90baf66..e69de29 100644 --- a/src/leap/bitmask/mail/smtp/__init__.py +++ b/src/leap/bitmask/mail/smtp/__init__.py @@ -1,71 +0,0 @@ -# -*- coding: utf-8 -*- -# __init__.py -# Copyright (C) 2013-2016 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 -# the Free Software Foundation, either version 3 of the License, or -# (at your option) any later version. -# -# This program is distributed in the hope that it will be useful, -# but WITHOUT ANY WARRANTY; without even the implied warranty of -# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the -# GNU General Public License for more details. -# -# You should have received a copy of the GNU General Public License -# along with this program. If not, see . -""" -SMTP gateway helper function. -""" -import os - -from twisted.internet import reactor -from twisted.internet.error import CannotListenError -from twisted.logger import Logger - -from leap.common.events import emit_async, catalog -from leap.bitmask.mail.smtp.gateway import SMTPFactory - -logger = Logger() - -SMTP_PORT = 2013 - - -def run_service(soledad_sessions, keymanager_sessions, sendmail_opts, - port=SMTP_PORT, factory=None): - """ - Main entry point to run the service from the client. - - :param soledad_sessions: a dict-like object, containing instances - of a Store (soledad instances), indexed by userid. - :param keymanager_sessions: a dict-like object, containing instances - of Keymanager, indexed by userid. - :param sendmail_opts: a dict-like object of sendmailOptions. - - :returns: the port as returned by the reactor when starts listening, and - the factory for the protocol. - :rtype: tuple - """ - if not factory: - factory = SMTPFactory(soledad_sessions, keymanager_sessions, - sendmail_opts) - - try: - interface = "localhost" - # don't bind just to localhost if we are running on docker since we - # won't be able to access smtp from the host - if os.environ.get("LEAP_DOCKERIZED"): - interface = '' - - # TODO Use Endpoints instead -------------------------------- - tport = reactor.listenTCP(port, factory, interface=interface) - emit_async(catalog.SMTP_SERVICE_STARTED, str(port)) - - return tport, factory - except CannotListenError: - logger.error("SMTP Service failed to start: " - "cannot listen in port %s" % port) - emit_async(catalog.SMTP_SERVICE_FAILED_TO_START, str(port)) - except Exception as exc: - logger.error("Unhandled error while launching smtp gateway service") - logger.error('%r' % exc) diff --git a/src/leap/bitmask/mail/smtp/gateway.py b/src/leap/bitmask/mail/smtp/gateway.py index b1fafad..08d59e1 100644 --- a/src/leap/bitmask/mail/smtp/gateway.py +++ b/src/leap/bitmask/mail/smtp/gateway.py @@ -56,8 +56,6 @@ generator.Generator = RFC3156CompliantGenerator LOCAL_FQDN = "bitmask.local" -logger = Logger() - @implementer(IRealm) class LocalSMTPRealm(object): @@ -221,10 +219,13 @@ class SMTPFactory(protocol.ServerFactory): @implementer(smtp.IMessageDelivery) class SMTPDelivery(object): + """ Validate email addresses and handle message delivery. """ + log = Logger() + def __init__(self, userid, keymanager, encrypted_only, outgoing_mail): """ Initialize the SMTP delivery object. @@ -298,7 +299,7 @@ class SMTPDelivery(object): # verify if recipient key is available in keyring def found(_): - logger.debug("Accepting mail for %s..." % user.dest.addrstr) + self.log.debug('Accepting mail for %s...' % user.dest.addrstr) emit_async(catalog.SMTP_RECIPIENT_ACCEPTED_ENCRYPTED, self._userid, user.dest.addrstr) @@ -310,7 +311,7 @@ class SMTPDelivery(object): emit_async(catalog.SMTP_RECIPIENT_REJECTED, self._userid, user.dest.addrstr) raise smtp.SMTPBadRcpt(user.dest.addrstr) - logger.warn( + self.log.warn( 'Warning: will send an unencrypted message (because ' '"encrypted_only" is set to False).') emit_async( @@ -344,7 +345,7 @@ class SMTPDelivery(object): # accept mail from anywhere. To reject an address, raise # smtp.SMTPBadSender here. if str(origin) != str(self._userid): - logger.error( + self.log.error( "Rejecting sender {0}, expected {1}".format(origin, self._userid)) raise smtp.SMTPBadSender(origin) @@ -362,6 +363,7 @@ class EncryptedMessage(object): recipient. """ implements(smtp.IMessage) + log = Logger() def __init__(self, user, outgoing_mail): """ @@ -396,7 +398,7 @@ class EncryptedMessage(object): :returns: a deferred """ - logger.debug("Message data complete.") + self.log.debug('Message data complete.') self._lines.append('') # add a trailing newline raw_mail = '\r\n'.join(self._lines) @@ -406,8 +408,7 @@ class EncryptedMessage(object): """ Log an error when the connection is lost. """ - logger.error("Connection lost unexpectedly!") - logger.error() + self.log.error('Connection lost unexpectedly!') emit_async(catalog.SMTP_CONNECTION_LOST, self._userid, self._user.dest.addrstr) # unexpected loss of connection; don't save diff --git a/src/leap/bitmask/mail/smtp/service.py b/src/leap/bitmask/mail/smtp/service.py index 48e6865..6fd000c 100644 --- a/src/leap/bitmask/mail/smtp/service.py +++ b/src/leap/bitmask/mail/smtp/service.py @@ -26,7 +26,7 @@ from twisted.logger import Logger from leap.common.events import emit_async, catalog from leap.bitmask.mail.smtp.gateway import SMTPFactory -logger = Logger() +log = Logger() SMTP_PORT = 2013 @@ -65,9 +65,9 @@ def run_service(soledad_sessions, keymanager_sessions, sendmail_opts, return tport, factory except CannotListenError: - logger.error("STMP Service failed to start: " - "cannot listen in port %s" % port) + log.error('STMP Service failed to start: ' + 'cannot listen in port %s' % port) emit_async(catalog.SMTP_SERVICE_FAILED_TO_START, str(port)) except Exception as exc: - logger.error("Unhandled error while launching smtp gateway service") - logger.error('%r' % exc) + log.error('Unhandled error while launching smtp gateway service') + log.error('%r' % exc) diff --git a/src/leap/bitmask/mail/sync_hooks.py b/src/leap/bitmask/mail/sync_hooks.py index de3a0c1..e8f25e8 100644 --- a/src/leap/bitmask/mail/sync_hooks.py +++ b/src/leap/bitmask/mail/sync_hooks.py @@ -14,12 +14,14 @@ # # You should have received a copy of the GNU General Public License # along with this program. If not, see . + """ Soledad PostSync Hooks. Process every new document of interest after every soledad synchronization, using the hooks that soledad exposes via plugins. """ + from re import compile as regex_compile from zope.interface import implements @@ -30,7 +32,7 @@ from twisted.logger import Logger from leap.bitmask.mail import constants from leap.soledad.client.interfaces import ISoledadPostSyncPlugin -logger = Logger() +log = Logger() def _get_doc_type_preffix(s): @@ -38,6 +40,7 @@ def _get_doc_type_preffix(s): class MailProcessingPostSyncHook(object): + implements(IPlugin, ISoledadPostSyncPlugin) META_DOC_PREFFIX = _get_doc_type_preffix(constants.METAMSGID) @@ -56,7 +59,7 @@ class MailProcessingPostSyncHook(object): for doc_id in doc_id_list: if _get_doc_type_preffix(doc_id) in self.watched_doc_types: - logger.info("Mail post-sync hook: processing %s" % doc_id) + log.info("Mail post-sync hook: processing %s" % doc_id) process_fun(doc_id) return defer.gatherResults(self._processing_deferreds) @@ -77,7 +80,7 @@ class MailProcessingPostSyncHook(object): mbox_uuid = _get_mbox_uuid(mdoc_id) if mbox_uuid: chash = _get_chash_from_mdoc(mdoc_id) - logger.debug('making index table for %s:%s' % (mbox_uuid, chash)) + log.debug('Making index table for %s:%s' % (mbox_uuid, chash)) index_docid = constants.METAMSGID.format( mbox_uuid=mbox_uuid.replace('-', '_'), chash=chash) @@ -91,7 +94,7 @@ class MailProcessingPostSyncHook(object): def _process_queued_docs(self): assert(self._has_configured_account()) pending = self._pending_docs - logger.info("Mail post-sync hook: processing queued docs") + log.info('Mail post-sync hook: processing queued docs') def remove_pending_docs(res): self._pending_docs = [] diff --git a/src/leap/bitmask/mail/testing/imap.py b/src/leap/bitmask/mail/testing/imap.py index 92bf4d3..fa4c08e 100644 --- a/src/leap/bitmask/mail/testing/imap.py +++ b/src/leap/bitmask/mail/testing/imap.py @@ -38,7 +38,7 @@ from leap.bitmask.mail.testing.common import SoledadTestMixin TEST_USER = "testuser@leap.se" TEST_PASSWD = "1234" -logger = Logger() +log = Logger() # @@ -182,7 +182,7 @@ class IMAP4HelperMixin(SoledadTestMixin): self.client.transport.loseConnection() self.server.transport.loseConnection() if hasattr(self, 'function'): - logger.error(failure, "Problem with %r" % (self.function,)) + log.error("Problem with %r" % (self.function,)) def loopback(self): return loopback.loopbackAsync(self.server, self.client) -- cgit v1.2.3