diff options
37 files changed, 378 insertions, 488 deletions
diff --git a/src/leap/bitmask/bonafide/_protocol.py b/src/leap/bitmask/bonafide/_protocol.py index 391aa8df..674634d9 100644 --- a/src/leap/bitmask/bonafide/_protocol.py +++ b/src/leap/bitmask/bonafide/_protocol.py @@ -38,8 +38,6 @@ from twisted.logger import Logger # TODO [ ] enable-disable services # TODO [ ] read provider info -logger = Logger() - COMMANDS = 'signup', 'authenticate', 'logout', 'stats' _preffix = get_path_prefix() @@ -53,6 +51,8 @@ class BonafideProtocol(object): _apis = defaultdict(None) _sessions = defaultdict(None) + log = Logger() + def _get_api(self, provider): # TODO should get deferred if provider.domain in self._apis: @@ -85,7 +85,7 @@ class BonafideProtocol(object): # Service public methods def do_signup(self, full_id, password, invite=None, autoconf=False): - logger.debug('SIGNUP for %s' % full_id) + self.log.debug('SIGNUP for %s' % full_id) _, provider_id = config.get_username_and_provider(full_id) provider = config.Provider(provider_id, autoconf=autoconf) @@ -132,7 +132,7 @@ class BonafideProtocol(object): # TODO -- turn this into JSON response return str(_session.token), str(_session.uuid) - logger.debug('AUTH for %s' % full_id) + self.log.debug('AUTH for %s' % full_id) # XXX get deferred? session = self._get_session(provider, full_id, password) @@ -143,7 +143,7 @@ class BonafideProtocol(object): def do_logout(self, full_id): # XXX use the AVATAR here - logger.debug('LOGOUT for %s' % full_id) + self.log.debug('LOGOUT for %s' % full_id) if (full_id not in self._sessions or not self._sessions[full_id].is_authenticated): return fail(RuntimeError("There is no session for such user")) @@ -162,7 +162,7 @@ class BonafideProtocol(object): return users def do_change_password(self, full_id, current_password, new_password): - logger.debug('change password for %s' % full_id) + self.log.debug('Change password for %s' % full_id) if (full_id not in self._sessions or not self._sessions[full_id].is_authenticated): return fail(RuntimeError("There is no session for such user")) @@ -208,7 +208,7 @@ class BonafideProtocol(object): pass def do_stats(self): - logger.debug('calculating Bonafide Service STATS') + self.log.debug('Calculating Bonafide Service STATS') mem = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss return {'sessions': len(self._sessions), 'mem': '%s KB' % (mem / 1024)} diff --git a/src/leap/bitmask/bonafide/config.py b/src/leap/bitmask/bonafide/config.py index 1002edbd..b3c35ba1 100644 --- a/src/leap/bitmask/bonafide/config.py +++ b/src/leap/bitmask/bonafide/config.py @@ -40,8 +40,6 @@ from leap.common.check import leap_assert from leap.common.config import get_path_prefix as common_get_path_prefix from leap.common.files import mkdir_p -logger = Logger() - APPNAME = "bonafide" if platform.system() == 'Windows': @@ -158,6 +156,7 @@ def delete_provider(domain): class Provider(object): + # TODO add validation SERVICES_MAP = { @@ -168,6 +167,8 @@ class Provider(object): ongoing_bootstrap = defaultdict(None) stuck_bootstrap = defaultdict(None) + log = Logger() + def __init__(self, domain, autoconf=False, basedir=None, check_certificate=True): # TODO: I need a way to know if it was already configured @@ -196,7 +197,7 @@ class Provider(object): if not is_configured: if autoconf: - logger.debug( + self.log.debug( 'provider %s not configured: downloading files...' % domain) self.bootstrap() @@ -204,7 +205,7 @@ class Provider(object): raise NotConfiguredError("Provider %s is not configured" % (domain,)) else: - logger.debug('provider already initialized') + self.log.debug('Provider already initialized') self.first_bootstrap[self._domain] = defer.succeed( 'already_initialized') self.ongoing_bootstrap[self._domain] = defer.succeed( @@ -251,10 +252,10 @@ class Provider(object): def bootstrap(self): domain = self._domain - logger.debug("bootstrapping provider %s" % domain) + self.log.debug('Bootstrapping provider %s' % domain) ongoing = self.ongoing_bootstrap.get(domain) if ongoing: - logger.debug('already bootstrapping this provider...') + self.log.debug('Already bootstrapping this provider...') return self.first_bootstrap[self._domain] = defer.Deferred() @@ -359,7 +360,7 @@ class Provider(object): # See: # https://leap.se/code/issues/7906 def further_bootstrap_needs_auth(ignored): - logger.warn('cannot download services config yet, need auth') + self.log.warn('Cannot download services config yet, need auth') pending_deferred = defer.Deferred() self.stuck_bootstrap[self._domain] = pending_deferred return defer.succeed('ok for now') @@ -382,9 +383,8 @@ class Provider(object): def workaround_for_config_fetch(failure): # FIXME --- configs.json raises 500, see #7914. # This is a workaround until that's fixed. - logger.error(failure) - logger.debug( - "COULD NOT VERIFY CONFIGS.JSON, WORKAROUND: DIRECT DOWNLOAD") + self.log.debug( + 'COULD NOT VERIFY CONFIGS.JSON, WORKAROUND: DIRECT DOWNLOAD') if 'mx' in self._provider_config.services: soledad_uri = '/1/config/soledad-service.json' @@ -412,7 +412,6 @@ class Provider(object): if stuck: d = self._get_config_for_all_services(session) d.addCallback(lambda _: stuck.callback('continue!')) - d.addErrback(logger.error) return d if not self.has_fetched_services_config(): @@ -497,7 +496,7 @@ class Provider(object): def _load_provider_json(self): path = self._get_provider_json_path() if not is_file(path): - logger.debug("cannot LOAD provider config path %s" % path) + self.log.debug('cannot LOAD provider config path %s' % path) return with open(path, 'r') as config: @@ -535,7 +534,7 @@ class Provider(object): return services_dict def _fetch_provider_configs_unauthenticated(self, uri, path): - logger.info('downloading config for %s...' % uri) + self.log.info('Downloading config for %s...' % uri) d = downloadPage(uri, path, method='GET') return d diff --git a/src/leap/bitmask/bonafide/service.py b/src/leap/bitmask/bonafide/service.py index 0f9c6281..b9aaf1af 100644 --- a/src/leap/bitmask/bonafide/service.py +++ b/src/leap/bitmask/bonafide/service.py @@ -30,12 +30,13 @@ from twisted.internet import defer from twisted.logger import Logger -logger = Logger() _preffix = get_path_prefix() class BonafideService(HookableService): + log = Logger() + def __init__(self, basedir=None): if not basedir: basedir = os.path.join(_preffix, 'leap') @@ -44,7 +45,7 @@ class BonafideService(HookableService): self.service_hooks = defaultdict(list) def startService(self): - logger.debug('starting Bonafide Service') + self.log.debug('Starting Bonafide Service') super(BonafideService, self).startService() # Commands @@ -58,7 +59,7 @@ class BonafideService(HookableService): def notify_bonafide_auth(result): if not result: msg = "authentication hook did not return anything" - logger.debug(msg) + self.log.debug(msg) raise RuntimeError(msg) token, uuid = result diff --git a/src/leap/bitmask/bonafide/session.py b/src/leap/bitmask/bonafide/session.py index 732afe53..551bfa2e 100644 --- a/src/leap/bitmask/bonafide/session.py +++ b/src/leap/bitmask/bonafide/session.py @@ -24,7 +24,6 @@ from leap.bitmask.bonafide import _srp from leap.bitmask.bonafide import provider from leap.bitmask.bonafide._http import httpRequest, cookieAgentFactory -logger = Logger() OK = 'ok' @@ -45,6 +44,8 @@ def _auth_required(func): class Session(object): + log = Logger() + def __init__(self, credentials, api, provider_cert): # TODO check if an anonymous credentials is passed. # TODO move provider_cert to api object. @@ -91,7 +92,7 @@ class Session(object): def authenticate(self): uri = self._api.get_handshake_uri() met = self._api.get_handshake_method() - logger.debug("%s to %s" % (met, uri)) + self.log.debug('%s to %s' % (met, uri)) params = self._srp_auth.get_handshake_params() handshake = yield self._request(self._agent, uri, values=params, @@ -101,7 +102,7 @@ class Session(object): uri = self._api.get_authenticate_uri(login=self.username) met = self._api.get_authenticate_method() - logger.debug("%s to %s" % (met, uri)) + self.log.debug('%s to %s' % (met, uri)) params = self._srp_auth.get_authentication_params() auth = yield self._request(self._agent, uri, values=params, @@ -119,9 +120,7 @@ class Session(object): def logout(self): uri = self._api.get_logout_uri() met = self._api.get_logout_method() - auth = yield self._request(self._agent, uri, method=met) - print 'AUTH', auth - print 'resetting user/pass' + yield self._request(self._agent, uri, method=met) self.username = None self.password = None self._initialize_session() @@ -211,6 +210,8 @@ if __name__ == "__main__": import sys from twisted.cred.credentials import UsernamePassword + log = Logger() + if len(sys.argv) != 4: print "Usage:", sys.argv[0], "provider", "username", "password" sys.exit() @@ -229,7 +230,7 @@ if __name__ == "__main__": reactor.stop() def auth_eb(failure): - logger.error(failure) + log.error(failure) d = session.authenticate() d.addCallback(print_result) diff --git a/src/leap/bitmask/core/_session.py b/src/leap/bitmask/core/_session.py index 9b22f154..ae992f4a 100644 --- a/src/leap/bitmask/core/_session.py +++ b/src/leap/bitmask/core/_session.py @@ -27,9 +27,6 @@ from twisted.logger import Logger from leap.bitmask.hooks import HookableService -logger = Logger() - - class SessionService(HookableService): """ @@ -49,6 +46,7 @@ class SessionService(HookableService): """ name = 'sessions' + log = Logger() def __init__(self, basedir, tokens): service.Service.__init__(self) @@ -56,7 +54,7 @@ class SessionService(HookableService): self._tokens = tokens def startService(self): - logger.info('starting Session Service') + self.log.info('Starting Session Service') super(SessionService, self).startService() def stopService(self): diff --git a/src/leap/bitmask/core/_zmq.py b/src/leap/bitmask/core/_zmq.py index 30ac743d..af1da9ff 100644 --- a/src/leap/bitmask/core/_zmq.py +++ b/src/leap/bitmask/core/_zmq.py @@ -29,7 +29,7 @@ from leap.bitmask.core import ENDPOINT from leap.bitmask.core.dispatcher import CommandDispatcher -logger = Logger() +log = Logger() class ZMQServerService(service.Service): @@ -64,8 +64,8 @@ class _DispatcherREPConnection(ZmqREPConnection): reactor.callLater(0, self.reply, msgId, str(response)) def log_err(self, failure, msgId): - logger.error(failure) + log.failure('Error on dispatcher') self.defer_reply("ERROR: %r" % failure, msgId) def do_greet(self): - logger.info('starting ZMQ dispatcher') + log.info('Starting ZMQ dispatcher') diff --git a/src/leap/bitmask/core/dispatcher.py b/src/leap/bitmask/core/dispatcher.py index fc17b76a..187ebfd5 100644 --- a/src/leap/bitmask/core/dispatcher.py +++ b/src/leap/bitmask/core/dispatcher.py @@ -35,7 +35,7 @@ from leap.common.events import catalog from .api import APICommand, register_method -logger = Logger() +log = Logger() class DispatchError(Exception): @@ -546,11 +546,9 @@ def _format_error(failure): expected = getattr(failure.value, 'expected', False) if not expected: - try: - logger.failure('[DISPATCHER] Unexpected error:') - except: - logger.debug('[DISPATCHER] Unexpected error: %r' % failure.value) - logger.warn(failure.getTraceback()) + log.error('[DISPATCHER] Unexpected error!') + log.error('{0!r}'.format(failure.value)) + log.error(failure.getTraceback()) # if needed, we could add here the exception type as an extra field return json.dumps({'error': failure.value.message, 'result': None}) diff --git a/src/leap/bitmask/core/mail_services.py b/src/leap/bitmask/core/mail_services.py index 70e7b490..eefbbc5c 100644 --- a/src/leap/bitmask/core/mail_services.py +++ b/src/leap/bitmask/core/mail_services.py @@ -54,9 +54,6 @@ from leap.bitmask.core.uuid_map import UserMap from leap.bitmask.core.configurable import DEFAULT_BASEDIR -logger = Logger() - - class Container(object): def __init__(self, service=None): @@ -152,12 +149,14 @@ def is_service_ready(service, provider): class SoledadService(HookableService): + log = Logger() + def __init__(self, basedir): service.Service.__init__(self) self._basedir = basedir def startService(self): - logger.info('starting Soledad Service') + self.log.info('Starting Soledad Service') self._container = SoledadContainer(service=self) super(SoledadService, self).startService() @@ -174,12 +173,12 @@ class SoledadService(HookableService): password = kw.get('password') uuid = kw.get('uuid') container = self._container - logger.debug("on_passphrase_entry: " - "New Soledad Instance: %s" % userid) + self.log.debug('On_passphrase_entry: ' + 'New Soledad Instance: %s' % userid) if not container.get_instance(userid): container.add_instance(userid, password, uuid=uuid, token=None) else: - logger.debug('service MX is not ready...') + self.log.debug('Service MX is not ready...') def hook_on_bonafide_auth(self, **kw): userid = kw['username'] @@ -195,10 +194,10 @@ class SoledadService(HookableService): container = self._container if container.get_instance(userid): - logger.debug("passing a new SRP Token to Soledad: %s" % userid) + self.log.debug('Passing a new SRP Token to Soledad: %s' % userid) container.set_remote_auth_token(userid, token) else: - logger.debug("adding a new Soledad Instance: %s" % userid) + self.log.debug('Adding a new Soledad Instance: %s' % userid) container.add_instance( userid, password, uuid=uuid, token=token) @@ -210,19 +209,21 @@ class SoledadService(HookableService): password = kw['password'] soledad = self._container.get_instance(userid) if soledad is not None: - logger.info("Change soledad passphrase for %s" % userid) + self.log.info('Change soledad passphrase for %s' % userid) soledad.change_passphrase(unicode(password)) class KeymanagerContainer(Container): + log = Logger() + def __init__(self, service=None, basedir=DEFAULT_BASEDIR): self._basedir = os.path.expanduser(basedir) self._status = {} super(KeymanagerContainer, self).__init__(service=service) def add_instance(self, userid, token, uuid, soledad): - logger.debug("adding Keymanager instance for: %s" % userid) + self.log.debug('Adding Keymanager instance for: %s' % userid) self._set_status(userid, "starting") keymanager = self._create_keymanager_instance( userid, token, uuid, soledad) @@ -252,15 +253,15 @@ class KeymanagerContainer(Container): def _get_or_generate_keys(self, keymanager, userid): def _get_key(_): - logger.info("looking up private key for %s" % userid) + self.log.info('Looking up private key for %s' % userid) return keymanager.get_key(userid, private=True, fetch_remote=False) def _found_key(key): - logger.info("found key: %r" % key) + self.log.info('Found key: %r' % key) def _if_not_found_generate(failure): failure.trap(KeyNotFound) - logger.info("key not found, generating key for %s" % (userid,)) + self.log.info('Key not found, generating key for %s' % (userid,)) self._set_status(userid, "starting", keys="generating") d = keymanager.gen_key() d.addCallbacks(_send_key, _log_key_error("generating")) @@ -272,25 +273,25 @@ class KeymanagerContainer(Container): # but this hasn't been successfully uploaded. How do we know that? # XXX Should this be a method of bonafide instead? # ----------------------------------------------------------------- - logger.info("key generated for %s" % userid) + self.log.info('Key generated for %s' % userid) if not keymanager.token: - logger.debug( - "token not available, scheduling " - "a new key sending attempt...") + self.log.debug( + 'Token not available, scheduling ' + 'a new key sending attempt...') return task.deferLater(reactor, 5, _send_key, None) - logger.info("sending public key to server") + self.log.info('Sending public key to server') d = keymanager.send_key() d.addCallbacks( - lambda _: logger.info("key sent to server"), + lambda _: self.log.info('Key sent to server'), _log_key_error("sending")) return d def _log_key_error(step): def log_error(failure): - logger.error("Error while %s key!" % step) - logger.error(failure) + self.log.error('Error while %s key!' % step) + self.log.failure('error!') error = "Error generating key: %s" % failure.getErrorMessage() self._set_status(userid, "failure", error=error) return failure @@ -298,22 +299,22 @@ class KeymanagerContainer(Container): def _sync_if_never_synced(ever_synced): if ever_synced: - logger.debug("soledad has synced in the past") + self.log.debug('Soledad has synced in the past') return defer.succeed(None) - logger.debug("soledad has never synced") + self.log.debug('Soledad has never synced') if not keymanager.token: - logger.debug("no token to sync now, scheduling a new check") + self.log.debug('No token to sync now, scheduling a new check') d = task.deferLater(reactor, 5, keymanager.ever_synced) d.addCallback(_sync_if_never_synced) return d - logger.debug("syncing soledad for the first time...") + self.log.debug('Syncing soledad for the first time...') self._set_status(userid, "starting", keys="sync") return keymanager._soledad.sync() - logger.debug("checking if soledad has ever synced...") + self.log.debug('Checking if soledad has ever synced...') d = keymanager.ever_synced() d.addCallback(_sync_if_never_synced) d.addCallback(_get_key) @@ -355,13 +356,15 @@ class KeymanagerContainer(Container): class KeymanagerService(HookableService): + log = Logger() + def __init__(self, basedir=DEFAULT_BASEDIR): service.Service.__init__(self) self._basedir = basedir self._container = None def startService(self): - logger.debug('starting Keymanager Service') + self.log.debug('Starting Keymanager Service') self._container = KeymanagerContainer(self._basedir) self._container.service = self self.tokens = {} @@ -376,7 +379,7 @@ class KeymanagerService(HookableService): uuid = kw['uuid'] soledad = kw['soledad'] if not container.get_instance(user): - logger.debug('Adding a new Keymanager instance for %s' % user) + self.log.debug('Adding a new Keymanager instance for %s' % user) if not token: token = self.tokens.get(user) container.add_instance(user, token, uuid, soledad) @@ -393,12 +396,12 @@ class KeymanagerService(HookableService): container = self._container if container.get_instance(userid): - logger.debug( - 'passing a new SRP Token ' + self.log.debug( + 'Passing a new SRP Token ' 'to Keymanager: %s' % userid) container.set_remote_auth_token(userid, token) else: - logger.debug('storing the keymanager token... %s ' % token) + self.log.debug('Storing the keymanager token... %s ' % token) self.tokens[userid] = token # commands @@ -464,6 +467,7 @@ class StandardMailService(service.MultiService, HookableService): """ name = 'mail' + log = Logger() # TODO factor out Mail Service to inside mail package. @@ -487,11 +491,11 @@ class StandardMailService(service.MultiService, HookableService): self.addService(IncomingMailService(self)) def startService(self): - logger.info('starting mail service') + self.log.info('Starting Mail Service') super(StandardMailService, self).startService() def stopService(self): - logger.info('stopping mail service') + self.log.info('Stopping Mail service') super(StandardMailService, self).stopService() def startInstance(self, userid, soledad, keymanager): @@ -541,14 +545,14 @@ class StandardMailService(service.MultiService, HookableService): """ try to turn on incoming mail service for the user that just logged in """ - logger.debug( - 'looking for incoming mail service for auth: %s' % userid) + self.log.debug( + 'Looking for incoming mail service for auth: %s' % userid) multiservice = self.getServiceNamed('incoming_mail') try: incoming = multiservice.getServiceNamed(userid) incoming.startService() except KeyError: - logger.debug('no incoming service for %s' % userid) + self.log.debug('No incoming service for %s' % userid) @defer.inlineCallbacks def _maybe_fetch_smtp_certificate(self, userid): @@ -579,7 +583,7 @@ class StandardMailService(service.MultiService, HookableService): except KeyError: incoming = None if incoming: - logger.debug( + self.log.debug( 'looking for incoming mail service ' 'for logout: %s' % username) incoming.stopService() @@ -624,8 +628,8 @@ class StandardMailService(service.MultiService, HookableService): try: shutil.rmtree(tokens_folder) except OSError as e: - logger.warn("Can't remove tokens folder %s: %s" - % (tokens_folder, e)) + self.log.warn("Can't remove tokens folder %s: %s" + % (tokens_folder, e)) return os.mkdir(tokens_folder, 0700) @@ -646,6 +650,7 @@ class StandardMailService(service.MultiService, HookableService): class IMAPService(service.Service): name = 'imap' + log = Logger() def __init__(self, soledad_sessions): self._soledad_sessions = soledad_sessions @@ -654,7 +659,7 @@ class IMAPService(service.Service): super(IMAPService, self).__init__() def startService(self): - logger.info('starting imap service') + self.log.info('Starting IMAP Service') port, factory = imap_service.run_service( self._soledad_sessions, factory=self._factory) self._port = port @@ -662,7 +667,7 @@ class IMAPService(service.Service): super(IMAPService, self).startService() def stopService(self): - logger.info("stopping imap service") + self.log.info('Stopping IMAP Service') if self._port: self._port.stopListening() self._port = None @@ -680,6 +685,7 @@ class IMAPService(service.Service): class SMTPService(service.Service): name = 'smtp' + log = Logger() def __init__(self, soledad_sessions, keymanager_sessions, sendmail_opts, basedir=DEFAULT_BASEDIR): @@ -693,7 +699,7 @@ class SMTPService(service.Service): super(SMTPService, self).__init__() def startService(self): - logger.info('starting smtp service') + self.log.info('starting smtp service') port, factory = smtp_service.run_service( self._soledad_sessions, self._keymanager_sessions, @@ -704,7 +710,7 @@ class SMTPService(service.Service): super(SMTPService, self).startService() def stopService(self): - logger.info('stopping smtp service') + self.log.info('Stopping SMTP Service') if self._port: self._port.stopListening() self._port = None @@ -725,6 +731,7 @@ class IncomingMailService(service.MultiService): """ name = 'incoming_mail' + log = Logger() def __init__(self, mail_service): super(IncomingMailService, self).__init__() @@ -732,7 +739,7 @@ class IncomingMailService(service.MultiService): self._status = {} def startService(self): - logger.info('starting incoming mail service') + self.log.info('Starting Incoming Mail Service') super(IncomingMailService, self).startService() def stopService(self): @@ -745,7 +752,7 @@ class IncomingMailService(service.MultiService): soledad = self._mail.get_soledad_session(userid) keymanager = self._mail.get_keymanager_session(userid) - logger.info('setting up incoming mail service for %s' % userid) + self.log.info('Setting up Incoming Mail Service for %s' % userid) self._start_incoming_mail_instance( keymanager, soledad, userid) @@ -773,7 +780,7 @@ class IncomingMailService(service.MultiService): keymanager, soledad, inbox, userid, check_period=INCOMING_CHECK_PERIOD) - logger.debug('setting incoming mail service for %s' % userid) + self.log.debug('Setting Incoming Mail Service for %s' % userid) incoming_mail.setName(userid) self.addService(incoming_mail) @@ -791,7 +798,7 @@ class IncomingMailService(service.MultiService): def _errback(self, failure, userid): self._set_status(userid, "failure", error=str(failure)) - logger.error(str(failure)) + self.log.failure('failure!') # -------------------------------------------------------------------- # diff --git a/src/leap/bitmask/core/service.py b/src/leap/bitmask/core/service.py index c06a5343..2972a51c 100644 --- a/src/leap/bitmask/core/service.py +++ b/src/leap/bitmask/core/service.py @@ -37,9 +37,6 @@ from leap.bitmask.core.web.service import HTTPDispatcherService from leap.bitmask.vpn.service import VPNService from leap.common.events import server as event_server -logger = Logger() - - backend = flags.BACKEND if backend == 'default': @@ -52,6 +49,9 @@ else: raise RuntimeError('Backend not supported') +log = Logger() + + class BitmaskBackend(configurable.ConfigurableService): """ @@ -68,7 +68,8 @@ class BitmaskBackend(configurable.ConfigurableService): # The global token is used for authenticating some of the channels that # expose the dispatcher. For the moment being, this is the REST API. self.global_tokens = [uuid.uuid4().hex] - logger.info('Global token: {0}'.format(self.global_tokens[0])) + log.debug( + 'Global token: {0}'.format(self.global_tokens[0])) self._touch_token_file() # These tokens are user-session tokens. Implemented and rolled back, @@ -129,13 +130,13 @@ class BitmaskBackend(configurable.ConfigurableService): sessions.setServiceParent(self) def _start_child_service(self, name): - logger.debug('starting backend child service: %s' % name) + log.debug('Starting backend child service: %s' % name) service = self.getServiceNamed(name) if service: service.startService() def _stop_child_service(self, name): - logger.debug('stopping backend child service: %s' % name) + log.debug('Stopping backend child service: %s' % name) service = self.getServiceNamed(name) if service: service.stopService() @@ -203,7 +204,6 @@ class BitmaskBackend(configurable.ConfigurableService): try: service = self.getServiceNamed(label) except KeyError: - logger.debug("initializing service: %s" % label) service = klass(*args, **kw) service.setName(label) service.setServiceParent(self) @@ -282,8 +282,6 @@ class BackendCommands(object): return {'version_core': __version__} def do_stats(self): - print "DO STATS" - logger.debug('BitmaskCore Service STATS') mem = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss return {'mem_usage': '%s MB' % (mem / 1024)} diff --git a/src/leap/bitmask/core/web/api.py b/src/leap/bitmask/core/web/api.py index 01c65bae..7f871711 100644 --- a/src/leap/bitmask/core/web/api.py +++ b/src/leap/bitmask/core/web/api.py @@ -40,7 +40,8 @@ class Api(Resource): d = self.dispatcher.dispatch(command) d.addCallback(self._write_response, request) - d.addErrback(log.error) + d.addErrback( + lambda f: log.error('Error on POST: {0!r}'.format(f))) return NOT_DONE_YET def _write_response(self, response, request): diff --git a/src/leap/bitmask/hooks.py b/src/leap/bitmask/hooks.py index fb9771e9..3e9324e0 100644 --- a/src/leap/bitmask/hooks.py +++ b/src/leap/bitmask/hooks.py @@ -25,7 +25,7 @@ from twisted.logger import Logger from zope.interface import implementer -logger = Logger() +log = Logger() @implementer(IService) @@ -47,7 +47,7 @@ class HookableService(Service): def register_hook(self, name, listener): if not hasattr(self, 'event_listeners'): self.event_listeners = defaultdict(list) - logger.debug('registering hook %s->%s' % (name, listener)) + log.debug('registering hook %s->%s' % (name, listener)) self.event_listeners[name].append(listener) def trigger_hook(self, name, **data): @@ -55,8 +55,8 @@ class HookableService(Service): def react_to_hook(listener, name, **kw): try: getattr(listener, 'hook_' + name)(**kw) - except AttributeError as exc: - logger.failure('Error while triggering hook') + except AttributeError: + log.failure('Error while triggering hook') raise RuntimeError( "Tried to notify a hook, but the listener " "service class %s does not seem to have " 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) diff --git a/src/leap/bitmask/mail/adaptors/soledad.py b/src/leap/bitmask/mail/adaptors/soledad.py index 6a057d65..a3e011a3 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 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 diff --git a/src/leap/bitmask/mail/incoming/service.py b/src/leap/bitmask/mail/incoming/service.py index 9ed76a09..45d0e398 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 9f60ff00..8cc01e27 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 bd578ed2..a3b8d005 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 e602b6b6..cb592689 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 90baf668..e69de29b 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 <http://www.gnu.org/licenses/>. -""" -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 b1fafadd..08d59e11 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 48e6865b..6fd000ce 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 de3a0c1a..e8f25e88 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 <http://www.gnu.org/licenses/>. + """ 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 92bf4d34..fa4c08eb 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) diff --git a/src/leap/bitmask/util.py b/src/leap/bitmask/util.py index 05f1c5b3..c5154cd0 100644 --- a/src/leap/bitmask/util.py +++ b/src/leap/bitmask/util.py @@ -28,7 +28,7 @@ from leap.common.files import which STANDALONE = getattr(sys, 'frozen', False) -logger = Logger() +log = Logger() def here(module=None): @@ -108,7 +108,7 @@ def get_gpg_bin_path(): gpgbin = path break except IndexError as e: - logger.debug("couldn't find the gpg binary!: %s" % (e,)) + log.debug("Couldn't find the gpg binary!: %s" % (e,)) if gpgbin is not None: return gpgbin @@ -124,8 +124,8 @@ def get_gpg_bin_path(): gpgbin = opt break except IndexError as e: - logger.debug("couldn't find the gpg1 binary!: %s" % (e,)) + log.debug("Couldn't find the gpg1 binary!: %s" % (e,)) if gpgbin is None: - logger.debug("Could not find gpg1 binary") + log.debug("Could not find gpg1 binary") return gpgbin diff --git a/src/leap/bitmask/vpn/_control.py b/src/leap/bitmask/vpn/_control.py index 6d4db965..85e4911c 100644 --- a/src/leap/bitmask/vpn/_control.py +++ b/src/leap/bitmask/vpn/_control.py @@ -8,7 +8,7 @@ from twisted.logger import Logger from .process import VPNProcess from .constants import IS_MAC -logger = Logger() +log = Logger() # NOTE: We need to set a bigger poll time in OSX because it seems # openvpn malfunctions when you ask it a lot of things in a short @@ -47,7 +47,7 @@ class VPNControl(object): self._port = socket_port def start(self): - logger.debug('VPN: start') + log.debug('VPN: start') self._user_stopped = False self._stop_pollers() @@ -58,13 +58,13 @@ class VPNControl(object): restartfun=self.restart) if vpnproc.get_openvpn_process(): - logger.info("Another vpn process is running. Will try to stop it.") + log.info('Another vpn process is running. Will try to stop it.') vpnproc.stop_if_already_running() try: cmd = vpnproc.getCommand() except Exception as e: - logger.error("Error while getting vpn command... {0!r}".format(e)) + log.error('Error while getting vpn command... {0!r}'.format(e)) raise env = os.environ @@ -118,7 +118,7 @@ class VPNControl(object): reactor.callLater( self.TERMINATE_WAIT, self._kill_if_left_alive) else: - logger.debug("VPN is not running.") + log.debug('VPN is not running.') return True @@ -153,7 +153,7 @@ class VPNControl(object): """ self._stop_pollers() if self._vpnproc is None: - logger.debug("There's no vpn process running to kill.") + log.debug("There's no vpn process running to kill.") else: self._vpnproc.aborted = True self._vpnproc.killProcess() @@ -168,10 +168,9 @@ class VPNControl(object): """ while tries < self.TERMINATE_MAXTRIES: if self._vpnproc.transport.pid is None: - logger.debug("Process has been happily terminated.") return else: - logger.debug("Process did not die, waiting...") + log.debug('Process did not die, waiting...') tries += 1 reactor.callLater(self.TERMINATE_WAIT, @@ -179,11 +178,11 @@ class VPNControl(object): return # after running out of patience, we try a killProcess - logger.debug("Process did not died. Sending a SIGKILL.") + log.debug('Process did not die. Sending a SIGKILL.') try: self._killit() except OSError: - logger.error("Could not kill process!") + log.error('Could not kill process!') def _start_pollers(self): """ diff --git a/src/leap/bitmask/vpn/_management.py b/src/leap/bitmask/vpn/_management.py index 8bf3cc78..453b042c 100644 --- a/src/leap/bitmask/vpn/_management.py +++ b/src/leap/bitmask/vpn/_management.py @@ -18,9 +18,6 @@ except ImportError: from ._telnet import UDSTelnet -logger = Logger() - - class OpenVPNAlreadyRunning(Exception): message = ("Another openvpn instance is already running, and could " "not be stopped.") @@ -41,6 +38,7 @@ class VPNManagement(object): zcat `dpkg -L openvpn | grep management` """ + log = Logger() # Timers, in secs CONNECTION_RETRY_TIME = 1 @@ -56,7 +54,7 @@ class VPNManagement(object): try: self._tn.read_eager() except EOFError: - logger.debug("Could not read from socket. Assuming it died.") + self.log.debug('Could not read from socket. Assuming it died.') return def _send_command(self, command, until=b"END"): @@ -89,23 +87,21 @@ class VPNManagement(object): except socket.error: # XXX should get a counter and repeat only # after mod X times. - logger.warn('socket error (command was: "%s")' % (command,)) + self.log.warn('Socket error (command was: "%s")' % (command,)) self._close_management_socket(announce=False) - logger.debug('trying to connect to management again') + self.log.debug('Trying to connect to management again') self.try_to_connect_to_management(max_retries=5) return [] - # XXX should move this to a errBack! except Exception as e: - logger.warn("Error sending command %s: %r" % - (command, e)) + self.log.warn("Error sending command %s: %r" % + (command, e)) return [] def _close_management_socket(self, announce=True): """ Close connection to openvpn management interface. """ - logger.debug('closing socket') if announce: self._tn.write("quit\n") self._tn.read_all() @@ -141,9 +137,8 @@ class VPNManagement(object): if self._tn: self._tn.read_eager() - # XXX move this to the Errback except Exception as e: - logger.warn("Could not connect to OpenVPN yet: %r" % (e,)) + self.log.warn('Could not connect to OpenVPN yet: %r' % (e,)) self._tn = None def _connectCb(self, *args): @@ -152,10 +147,8 @@ class VPNManagement(object): :param args: not used """ - if self._tn: - logger.info('Connected to management') - else: - logger.debug('Cannot connect to management...') + if not self._tn: + self.log.warn('Cannot connect to management...') def _connectErr(self, failure): """ @@ -163,7 +156,7 @@ class VPNManagement(object): :param failure: Failure """ - logger.warn(failure) + self.log.failure('Error while connecting to management!') def connect_to_management(self, host, port): """ @@ -200,17 +193,17 @@ class VPNManagement(object): :type retry: int """ if max_retries and retry > max_retries: - logger.warn("Max retries reached while attempting to connect " - "to management. Aborting.") + self.log.warn( + 'Max retries reached while attempting to connect ' + 'to management. Aborting.') self.aborted = True return # _alive flag is set in the VPNProcess class. if not self._alive: - logger.debug('Tried to connect to management but process is ' - 'not alive.') + self.log.debug('Tried to connect to management but process is ' + 'not alive.') return - logger.debug('trying to connect to management') if not self.aborted and not self.is_connected(): self.connect_to_management(self._socket_host, self._socket_port) reactor.callLater( @@ -268,7 +261,7 @@ class VPNManagement(object): try: text, value = parts except ValueError: - logger.debug("Could not parse %s" % parts) + self.log.debug('Could not parse %s' % parts) return # text can be: # "TUN/TAP read bytes" @@ -329,13 +322,14 @@ class VPNManagement(object): under normal circumstances, we should be able to delete. """ if self._socket_port == "unix": - logger.debug('cleaning socket file temp folder') + self.log.debug('Cleaning socket file temp folder') tempfolder = _first(os.path.split(self._socket_host)) if tempfolder and os.path.isdir(tempfolder): try: shutil.rmtree(tempfolder) except OSError: - logger.error('could not delete tmpfolder %s' % tempfolder) + self.log.error( + 'Could not delete tmpfolder %s' % tempfolder) def get_openvpn_process(self): """ @@ -380,11 +374,11 @@ class VPNManagement(object): """ process = self.get_openvpn_process() if not process: - logger.debug('Could not find openvpn process while ' - 'trying to stop it.') + self.log.debug('Could not find openvpn process while ' + 'trying to stop it.') return - logger.debug("OpenVPN is already running, trying to stop it...") + self.log.debug('OpenVPN is already running, trying to stop it...') cmdline = process.cmdline manag_flag = "--management" @@ -400,16 +394,16 @@ class VPNManagement(object): return "leap" in s and "providers" in s if not any(map(smellslikeleap, cmdline)): - logger.debug("We cannot stop this instance since we do not " - "recognise it as a leap invocation.") + self.log.debug("We cannot stop this instance since we do not " + "recognise it as a leap invocation.") raise AlienOpenVPNAlreadyRunning try: index = cmdline.index(manag_flag) host = cmdline[index + 1] port = cmdline[index + 2] - logger.debug("Trying to connect to %s:%s" - % (host, port)) + self.log.debug("Trying to connect to %s:%s" + % (host, port)) self.connect_to_management(host, port) # XXX this has a problem with connections to different @@ -421,19 +415,18 @@ class VPNManagement(object): # However, that should be a rare case right now. self._send_command("signal SIGTERM") self._close_management_socket(announce=True) - except (Exception, AssertionError) as e: - logger.warn("Problem trying to terminate OpenVPN: %r" - % (e,)) + except (Exception, AssertionError): + self.log.failure('Problem trying to terminate OpenVPN') else: - logger.debug("Could not find the expected openvpn command line.") + self.log.debug('Could not find the expected openvpn command line.') process = self.get_openvpn_process() if process is None: - logger.debug("Successfully finished already running " - "openvpn process.") + self.log.debug('Successfully finished already running ' + 'openvpn process.') return True else: - logger.warn("Unable to terminate OpenVPN") + self.log.warn('Unable to terminate OpenVPN') raise OpenVPNAlreadyRunning diff --git a/src/leap/bitmask/vpn/launcher.py b/src/leap/bitmask/vpn/launcher.py index 3006d6da..fa9923a8 100644 --- a/src/leap/bitmask/vpn/launcher.py +++ b/src/leap/bitmask/vpn/launcher.py @@ -33,7 +33,7 @@ from leap.bitmask.vpn.constants import IS_LINUX from leap.bitmask.vpn.utils import force_eval -logger = Logger() +log = Logger() flags_STANDALONE = False @@ -62,18 +62,18 @@ def _has_updown_scripts(path, warn=True): """ is_file = os.path.isfile(path) if warn and not is_file: - logger.error("Could not find up/down script %s. " - "Might produce DNS leaks." % (path,)) + log.error('Could not find up/down script %s. ' + 'Might produce DNS leaks.' % (path,)) # XXX check if applies in win is_exe = False try: is_exe = (stat.S_IXUSR & os.stat(path)[stat.ST_MODE] != 0) except OSError as e: - logger.warn("%s" % (e,)) + log.warn("%s" % (e,)) if warn and not is_exe: - logger.error("Up/down script %s is not executable. " - "Might produce DNS leaks." % (path,)) + log.error('Up/down script %s is not executable. ' + 'Might produce DNS leaks.' % (path,)) return is_file and is_exe @@ -91,8 +91,8 @@ def _has_other_files(path, warn=True): """ is_file = os.path.isfile(path) if warn and not is_file: - logger.warning("Could not find file during checks: %s. " % ( - path,)) + log.warn('Could not find file during checks: %s. ' % ( + path,)) return is_file @@ -109,6 +109,7 @@ class VPNLauncher(object): PREFERRED_PORTS = ("443", "80", "53", "1194") + # FIXME -- dead code? @classmethod @abstractmethod def get_gateways(kls, vpnconfig, providerconfig): @@ -138,7 +139,7 @@ class VPNLauncher(object): gws = [gateway_conf] if not gws: - logger.error('No gateway was found!') + log.error('No gateway was found!') raise VPNLauncherException('No gateway was found!') for idx, gw in enumerate(gws): @@ -156,7 +157,7 @@ class VPNLauncher(object): gateways.append((gw, the_port)) - logger.debug("Using gateways (ip, port): {0!r}".format(gateways)) + log.debug('Using gateways (ip, port): {0!r}'.format(gateways)) return gateways @classmethod @@ -198,8 +199,8 @@ class VPNLauncher(object): openvpn_path = force_eval(kls.OPENVPN_BIN_PATH) if not os.path.isfile(openvpn_path): - logger.warning("Could not find openvpn bin in path %s" % ( - openvpn_path)) + log.warn('Could not find openvpn bin in path %s' % ( + openvpn_path)) raise OpenVPNNotFoundException() args = [] @@ -321,11 +322,6 @@ class VPNLauncher(object): :rtype: list """ - # leap_assert(kls.OTHER_FILES is not None, - # "Need to define OTHER_FILES for this particular " - # "auncher before calling this method") - - # TODO assert vs except? if kls.OTHER_FILES is None: raise Exception( "Need to define OTHER_FILES for this particular " diff --git a/src/leap/bitmask/vpn/privilege.py b/src/leap/bitmask/vpn/privilege.py index 135acbb8..9666a943 100644 --- a/src/leap/bitmask/vpn/privilege.py +++ b/src/leap/bitmask/vpn/privilege.py @@ -31,7 +31,7 @@ from abc import ABCMeta, abstractmethod from twisted.logger import Logger from twisted.python.procutils import which -logger = Logger() +log = Logger() flags_STANDALONE = False @@ -71,8 +71,8 @@ def is_missing_policy_permissions(): if not policy_checker: # it is true that we miss permission to escalate # privileges without asking for password each time. - logger.debug("we could not find a policy checker implementation " - "for %s" % (_system,)) + log.debug('we could not find a policy checker implementation ' + 'for %s' % (_system,)) return True return policy_checker().is_missing_policy_permissions() @@ -146,18 +146,15 @@ class LinuxPolicyChecker(PolicyChecker): time.sleep(2) if self.is_up(): pkexec_possibilities = which(self.PKEXEC_BIN) - # leap_assert(len(pkexec_possibilities) > 0, - # "We couldn't find pkexec") if not pkexec_possibilities: - logger.error("We couldn't find pkexec") raise Exception("We couldn't find pkexec") return pkexec_possibilities else: - logger.warn("No polkit auth agent found. pkexec " + - "will use its own auth agent.") + log.warn('No polkit auth agent found. pkexec ' + + 'will use its own auth agent.') raise NoPolkitAuthAgentAvailable() else: - logger.warn("System has no pkexec") + log.warn('System has no pkexec') raise NoPkexecAvailable() @classmethod @@ -178,11 +175,11 @@ class LinuxPolicyChecker(PolicyChecker): # will do "sh -c 'foo'", so if we do not quoute it we'll end # up with a invocation to the python interpreter. And that # is bad. - logger.debug("Trying to launch polkit agent") + log.debug('Trying to launch polkit agent') subprocess.call(["python -m leap.bitmask.util.polkit_agent"], shell=True, env=env) - except Exception as exc: - logger.error(str(exc)) + except Exception: + log.failure('Error while launching vpn') @classmethod def is_up(self): diff --git a/src/leap/bitmask/vpn/process.py b/src/leap/bitmask/vpn/process.py index 6096a473..e136e5bb 100644 --- a/src/leap/bitmask/vpn/process.py +++ b/src/leap/bitmask/vpn/process.py @@ -32,20 +32,21 @@ from leap.bitmask.vpn.utils import get_vpn_launcher from leap.bitmask.vpn import _status from leap.bitmask.vpn import _management -logger = Logger() - # OpenVPN verbosity level - from flags.py OPENVPN_VERBOSITY = 1 class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): + """ A ProcessProtocol class that can be used to spawn a process that will launch openvpn and connect to its management interface to control it programmatically. """ + log = Logger() + # TODO do we really need the vpnconfig/providerconfig objects in here??? def __init__(self, vpnconfig, providerconfig, socket_host, socket_port, @@ -123,7 +124,7 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): line = data[:-1] if 'SIGTERM[soft,ping-restart]' in line: self.restarting = True - logger.info(line) + self.log.info(line) self._status.watch(line) def processExited(self, failure): @@ -140,9 +141,9 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): elif err == internet_error.ProcessTerminated: status, errmsg = 'failure', failure.value.exitCode if errmsg: - logger.debug("processExited, status %d" % (errmsg,)) + self.log.debug('processExited, status %d' % (errmsg,)) else: - logger.warn('%r' % failure.value) + self.log.warn('%r' % failure.value) self._status.set_status(status, errmsg) self._alive = False @@ -156,9 +157,9 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): """ exit_code = reason.value.exitCode if isinstance(exit_code, int): - logger.debug("processEnded, status %d" % (exit_code,)) + self.log.debug('processEnded, status %d' % (exit_code,)) if self.restarting: - logger.debug('Restarting VPN process') + self.log.debug('Restarting VPN process') reactor.callLater(2, self._restartfun) # polling @@ -202,8 +203,8 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): if not isinstance(c, str): command[i] = c.encode(encoding) - logger.debug("Running VPN with command: ") - logger.debug("{0}".format(" ".join(command))) + self.log.debug("Running VPN with command: ") + self.log.debug("{0}".format(" ".join(command))) return command def getGateways(self): @@ -227,4 +228,4 @@ class VPNProcess(protocol.ProcessProtocol, _management.VPNManagement): try: self.transport.signalProcess('KILL') except internet_error.ProcessExitedAlready: - logger.debug('Process Exited Already') + self.log.debug('Process Exited Already') |