From 82652e174b4f38a29ce488421eb6c0067d0c657f Mon Sep 17 00:00:00 2001 From: Ruben Pollan Date: Sat, 14 Feb 2015 17:52:27 -0600 Subject: Do the soledad sync the twisted way This closes: #6658 and #6691 --- .../services/soledad/soledadbootstrapper.py | 376 ++++++++++----------- 1 file changed, 172 insertions(+), 204 deletions(-) (limited to 'src/leap/bitmask/services') diff --git a/src/leap/bitmask/services/soledad/soledadbootstrapper.py b/src/leap/bitmask/services/soledad/soledadbootstrapper.py index e8946fa4..f079b0cd 100644 --- a/src/leap/bitmask/services/soledad/soledadbootstrapper.py +++ b/src/leap/bitmask/services/soledad/soledadbootstrapper.py @@ -21,14 +21,12 @@ import logging import os import socket import sys -import time from ssl import SSLError from sqlite3 import ProgrammingError as sqlite_ProgrammingError from u1db import errors as u1db_errors -from twisted.internet import threads, defer -import zope.proxy +from twisted.internet import defer, reactor from zope.proxy import sameProxiedObjects from pysqlcipher.dbapi2 import ProgrammingError as sqlcipher_ProgrammingError @@ -60,9 +58,6 @@ They should not be needed after we allow a null remote initialization in the soledad client, and a switch to remote sync-able mode during runtime. """ -# TODO these exceptions could be moved to soledad itself -# after settling this down. - class SoledadSyncError(Exception): message = "Error while syncing Soledad" @@ -109,10 +104,6 @@ class SoledadBootstrapper(AbstractBootstrapper): PUBKEY_KEY = "user[public_key]" MAX_INIT_RETRIES = 10 - MAX_SYNC_RETRIES = 10 - WAIT_MAX_SECONDS = 600 - # WAIT_STEP_SECONDS = 1 - WAIT_STEP_SECONDS = 5 def __init__(self, signaler=None): AbstractBootstrapper.__init__(self, signaler) @@ -125,30 +116,24 @@ class SoledadBootstrapper(AbstractBootstrapper): self._download_if_needed = False self._user = "" - self._password = "" + self._password = u"" self._address = "" self._uuid = "" self._srpauth = None - self._soledad = zope.proxy.ProxyBase(None) - self._keymanager = zope.proxy.ProxyBase(None) - - @property - def keymanager(self): - return self._keymanager - - @property - def soledad(self): - return self._soledad + self._soledad = None + self._keymanager = None @property def srpauth(self): if flags.OFFLINE is True: return None - leap_assert(self._provider_config is not None, - "We need a provider config") - return SRPAuth(self._provider_config) + if self._srpauth is None: + leap_assert(self._provider_config is not None, + "We need a provider config") + self._srpauth = SRPAuth(self._provider_config) + return self._srpauth # initialization @@ -166,18 +151,19 @@ class SoledadBootstrapper(AbstractBootstrapper): self._address = username self._password = password self._uuid = uuid - try: - d = self.load_and_sync_soledad(uuid, offline=True) - d.addCallback( - lambda _: self._signaler.signal( - self._signaler.soledad_offline_finished)) - return d - except Exception as e: - # XXX convert exception into failure.trap + + def error(failure): # TODO: we should handle more specific exceptions in here - logger.exception(e) + logger.exception(failure.value) self._signaler.signal(self._signaler.soledad_offline_failed) + d = self.load_and_sync_soledad(uuid, offline=True) + d.addCallback( + lambda _: self._signaler.signal( + self._signaler.soledad_offline_finished)) + d.addErrback(error) + return d + def _get_soledad_local_params(self, uuid, offline=False): """ Return the locals parameters needed for the soledad initialization. @@ -211,23 +197,17 @@ class SoledadBootstrapper(AbstractBootstrapper): :return: server_url, cert_file :rtype: tuple """ - if uuid is None: - uuid = self.srpauth.get_uuid() - if offline is True: server_url = "http://localhost:9999/" cert_file = "" else: + if uuid is None: + uuid = self.srpauth.get_uuid() server_url = self._pick_server(uuid) cert_file = self._provider_config.get_ca_cert_path() return server_url, cert_file - def _soledad_sync_errback(self, failure): - failure.trap(InvalidAuthTokenError) - # in the case of an invalid token we have already turned off mail and - # warned the user in _do_soledad_sync() - def _do_soledad_init(self, uuid, secrets_path, local_db_path, server_url, cert_file, token, syncable): """ @@ -268,16 +248,18 @@ class SoledadBootstrapper(AbstractBootstrapper): logger.exception(exc) raise SoledadInitError() - def load_and_sync_soledad(self, uuid=None, offline=False): + def load_and_sync_soledad(self, uuid=u"", offline=False): """ Once everthing is in the right place, we instantiate and sync Soledad :param uuid: the uuid of the user, used in offline mode. - :type uuid: unicode, or None. + :type uuid: unicode. :param offline: whether to instantiate soledad for offline use. :type offline: bool + :return: A Deferred which fires when soledad is sync, or which fails + with SoledadInitError or SoledadSyncError :rtype: defer.Deferred """ local_param = self._get_soledad_local_params(uuid, offline) @@ -291,54 +273,46 @@ class SoledadBootstrapper(AbstractBootstrapper): uuid, secrets_path, local_db_path, cert_file, token) else: - # We assume online operation from here on. - # XXX split in subfunction - syncable = True - try: - self._do_soledad_init(uuid, secrets_path, local_db_path, - server_url, cert_file, token, syncable) - except SoledadInitError: - # re-raise the exceptions from try_init, - # we're currently handling the retries from the - # soledad-launcher in the gui. - raise + return self._load_soledad_online(uuid, secrets_path, local_db_path, + server_url, cert_file, token) - leap_assert(not sameProxiedObjects(self._soledad, None), - "Null soledad, error while initializing") + def _load_soledad_online(self, uuid, secrets_path, local_db_path, + server_url, cert_file, token): + syncable = True + try: + self._do_soledad_init(uuid, secrets_path, local_db_path, + server_url, cert_file, token, syncable) + except SoledadInitError as e: + # re-raise the exceptions from try_init, + # we're currently handling the retries from the + # soledad-launcher in the gui. + return defer.fail(e) - address = make_address( - self._user, self._provider_config.get_domain()) + leap_assert(not sameProxiedObjects(self._soledad, None), + "Null soledad, error while initializing") - def key_not_found(failure): - if failure.check(KeyNotFound): - logger.debug("Key not found. Generating key for %s" % - (address,)) - self._do_soledad_sync() - else: - return failure + address = make_address( + self._user, self._provider_config.get_domain()) + syncer = Syncer(self._soledad, self._signaler) - d = self._init_keymanager(address, token) - d.addCallback( - lambda _: self._keymanager.get_key( - address, openpgp.OpenPGPKey, - private=True, fetch_remote=False)) - d.addCallbacks( - # XXX WTF --- FIXME remove this call to thread, soledad already - # does the sync in its own threadpool. -- kali - lambda _: threads.deferToThread(self._do_soledad_sync), - key_not_found) - d.addErrback(self._soledad_sync_errback) - return d + d = self._init_keymanager(address, token) + d.addCallback(lambda _: syncer.sync()) + d.addErrback(self._soledad_sync_errback) + return d def _load_soledad_nosync(self, uuid, secrets_path, local_db_path, cert_file, token): - syncable = False self._do_soledad_init(uuid, secrets_path, local_db_path, "", cert_file, token, syncable) d = self._init_keymanager(self._address, token) return d + def _soledad_sync_errback(self, failure): + failure.trap(InvalidAuthTokenError) + # in the case of an invalid token we have already turned off mail and + # warned the user + def _pick_server(self, uuid): """ Choose a soledad server to sync against. @@ -363,52 +337,6 @@ class SoledadBootstrapper(AbstractBootstrapper): logger.debug("Using soledad server url: %s" % (server_url,)) return server_url - def _do_soledad_sync(self): - """ - Do several retries to get an initial soledad sync. - """ - # and now, let's sync - sync_tries = self.MAX_SYNC_RETRIES - step = self.WAIT_STEP_SECONDS - max_wait = self.WAIT_MAX_SECONDS - while sync_tries > 0: - wait = 0 - try: - logger.debug("Trying to sync soledad....") - self._try_soledad_sync() - while self.soledad.syncing: - time.sleep(step) - wait += step - if wait >= max_wait: - raise SoledadSyncError("timeout!") - logger.debug("Soledad has been synced!") - # so long, and thanks for all the fish - return - except SoledadSyncError: - # maybe it's my connection, but I'm getting - # ssl handshake timeouts and read errors quite often. - # A particularly big sync is a disaster. - # This deserves further investigation, maybe the - # retry strategy can be pushed to u1db, or at least - # it's something worthy to talk about with the - # ubuntu folks. - sync_tries += 1 - msg = "Sync failed, retrying... (retry {0} of {1})".format( - sync_tries, self.MAX_SYNC_RETRIES) - logger.warning(msg) - continue - except InvalidAuthTokenError: - self._signaler.signal( - self._signaler.soledad_invalid_auth_token) - raise - except Exception as e: - # XXX release syncing lock - logger.exception("Unhandled error while syncing " - "soledad: %r" % (e,)) - break - - raise SoledadSyncError() - def _try_soledad_init(self, uuid, secrets_path, local_db_path, server_url, cert_file, auth_token, syncable): """ @@ -462,34 +390,6 @@ class SoledadBootstrapper(AbstractBootstrapper): "Soledad: %r" % (exc,)) raise - def _try_soledad_sync(self): - """ - Try to sync soledad. - Raises SoledadSyncError if not successful. - """ - try: - logger.debug("BOOTSTRAPPER: trying to sync Soledad....") - # pass defer_decryption=False to get inline decryption - # for debugging. - self._soledad.sync(defer_decryption=True) - except SSLError as exc: - logger.error("%r" % (exc,)) - raise SoledadSyncError("Failed to sync soledad") - except u1db_errors.InvalidGeneration as exc: - logger.error("%r" % (exc,)) - raise SoledadSyncError("u1db: InvalidGeneration") - except (sqlite_ProgrammingError, sqlcipher_ProgrammingError) as e: - logger.exception("%r" % (e,)) - raise - except InvalidAuthTokenError: - # token is invalid, probably expired - logger.error('Invalid auth token while trying to sync Soledad') - raise - except Exception as exc: - logger.exception("Unhandled error while syncing " - "soledad: %r" % (exc,)) - raise SoledadSyncError("Failed to sync soledad") - def _download_config(self): """ Download the Soledad config for the given provider @@ -545,11 +445,10 @@ class SoledadBootstrapper(AbstractBootstrapper): :type token: str :rtype: Deferred """ - srp_auth = self.srpauth logger.debug('initializing keymanager...') - if flags.OFFLINE is True: - args = (address, "https://localhost", self._soledad) + if flags.OFFLINE: + nickserver_uri = "https://localhost" kwargs = { "ca_cert_path": "", "api_uri": "", @@ -558,27 +457,18 @@ class SoledadBootstrapper(AbstractBootstrapper): "gpgbinary": self._get_gpg_bin_path() } else: - args = ( - address, - "https://nicknym.%s:6425" % ( - self._provider_config.get_domain(),), - self._soledad - ) + nickserver_uri = "https://nicknym.%s:6425" % ( + self._provider_config.get_domain(),) kwargs = { "token": token, "ca_cert_path": self._provider_config.get_ca_cert_path(), "api_uri": self._provider_config.get_api_uri(), "api_version": self._provider_config.get_api_version(), - "uid": srp_auth.get_uuid(), + "uid": self.srpauth.get_uuid(), "gpgbinary": self._get_gpg_bin_path() } - try: - self._keymanager = KeyManager(*args, **kwargs) - except KeyNotFound: - logger.debug('key for %s not found.' % address) - except Exception as exc: - logger.exception(exc) - raise + self._keymanager = KeyManager(address, nickserver_uri, self._soledad, + **kwargs) if flags.OFFLINE is False: # make sure key is in server @@ -586,8 +476,9 @@ class SoledadBootstrapper(AbstractBootstrapper): def send_errback(failure): if failure.check(KeyNotFound): - logger.debug('No key found for %s, will generate soon.' - % address) + logger.debug( + 'No key found for %s, it might be because soledad not ' + 'synced yet or it will generate it soon.' % address) else: logger.error("Error sending key to server.") logger.exception(failure.value) @@ -615,14 +506,12 @@ class SoledadBootstrapper(AbstractBootstrapper): logger.debug("Retrieving key for %s" % (address,)) def if_not_found_generate(failure): - if failure.check(KeyNotFound): - logger.debug("Key not found. Generating key for %s" - % (address,)) - d = self._keymanager.gen_key(openpgp.OpenPGPKey) - d.addCallbacks(send_key, log_key_error("generating")) - return d - else: - return failure + failure.trap(KeyNotFound) + logger.debug("Key not found. Generating key for %s" + % (address,)) + d = self._keymanager.gen_key(openpgp.OpenPGPKey) + d.addCallbacks(send_key, log_key_error("generating")) + return d def send_key(_): d = self._keymanager.send_key(openpgp.OpenPGPKey) @@ -657,6 +546,8 @@ class SoledadBootstrapper(AbstractBootstrapper): files if the have changed since the time it was previously downloaded. :type download_if_needed: bool + + :return: Deferred """ leap_assert_type(provider_config, ProviderConfig) @@ -666,36 +557,113 @@ class SoledadBootstrapper(AbstractBootstrapper): self._user = user self._password = password - is_offline = flags.OFFLINE - - if is_offline: + if flags.OFFLINE: signal_finished = self._signaler.soledad_offline_finished - signal_failed = self._signaler.soledad_offline_failed - else: - signal_finished = self._signaler.soledad_bootstrap_finished - signal_failed = self._signaler.soledad_bootstrap_failed + self._signaler.signal(signal_finished) + return defer.succeed(True) + + signal_finished = self._signaler.soledad_bootstrap_finished + signal_failed = self._signaler.soledad_bootstrap_failed try: - if not is_offline: - # XXX FIXME make this async too! (use txrequests) - # Also, why the fuck would we want to download it *every time*? - # We should be fine by using last-time config, or at least - # trying it. - self._download_config() - - # soledad config is ok, let's proceed to load and sync soledad - uuid = self.srpauth.get_uuid() - self.load_and_sync_soledad(uuid) - - d = self._gen_key() - d.addCallback(lambda _: self._signaler.signal(signal_finished)) - return d - else: - self._signaler.signal(signal_finished) - return defer.succeed(True) + # XXX FIXME make this async too! (use txrequests) + # Also, why the fuck would we want to download it *every time*? + # We should be fine by using last-time config, or at least + # trying it. + self._download_config() + uuid = self.srpauth.get_uuid() except Exception as e: # TODO: we should handle more specific exceptions in here self._soledad = None self._keymanager = None - logger.exception("Error while bootstrapping Soledad: %r" % (e, )) + logger.exception("Error while bootstrapping Soledad: %r" % (e,)) self._signaler.signal(signal_failed) + return defer.succeed(None) + + # soledad config is ok, let's proceed to load and sync soledad + d = self.load_and_sync_soledad(uuid) + d.addCallback(lambda _: self._gen_key()) + d.addCallback(lambda _: self._signaler.signal(signal_finished)) + return d + + +class Syncer(object): + """ + Takes care of retries, timeouts and other issues while syncing + """ + # XXX: the timeout and proably all the stuff here should be moved to + # soledad + + MAX_SYNC_RETRIES = 10 + WAIT_MAX_SECONDS = 600 + + def __init__(self, soledad, signaler): + self._tries = 0 + self._soledad = soledad + self._signaler = signaler + + def sync(self): + self._callback_deferred = defer.Deferred() + self._try_sync() + return self._callback_deferred + + def _try_sync(self): + logger.debug("BOOTSTRAPPER: trying to self Soledad....") + # pass defer_decryption=False to get inline decryption + # for debugging. + self._sync_deferred = self._soledad.sync(defer_decryption=True) + self._sync_deferred.addCallbacks(self._success, self._error) + reactor.callLater(self.WAIT_MAX_SECONDS, self._timeout) + + def _success(self, result): + logger.debug("Soledad has been synced!") + self._callback_deferred.callback(result) + # so long, and thanks for all the fish + + def _error(self, failure): + if failure.check(InvalidAuthTokenError): + logger.error('Invalid auth token while trying to self Soledad') + self._signaler.signal( + self._signaler.soledad_invalid_auth_token) + self._callback_deferred.fail(failure) + elif failure.check(sqlite_ProgrammingError, + sqlcipher_ProgrammingError): + logger.exception("%r" % (failure.value,)) + self._callback_deferred.fail(failure) + elif failure.check(SSLError): + logger.error("%r" % (failure.value,)) + self._retry() + elif failure.check(u1db_errors.InvalidGeneration): + logger.error("%r" % (failure.value,)) + self._retry() + else: + logger.exception("Unhandled error while syncing " + "soledad: %r" % (failure.value,)) + self._retry() + + def _timeout(self): + if not self._soledad.syncing: + # timeout only if is still syncing + return + + # maybe it's my connection, but I'm getting + # ssl handshake timeouts and read errors quite often. + # A particularly big sync is a disaster. + # This deserves further investigation, maybe the + # retry strategy can be pushed to u1db, or at least + # it's something worthy to talk about with the + # ubuntu folks. + self._sync_deferred.cancel() + self._retry() + + def _retry(self): + self._tries += 1 + if self._tries > self.MAX_SYNC_RETRIES: + msg = "Sync failed, retrying... (retry {0} of {1})".format( + self._tries, self.MAX_SYNC_RETRIES) + logger.warning(msg) + self._try_sync() + else: + logger.error("Sync failed {0} times".format(self._tries)) + self._callback_deferred.fail( + SoledadSyncError("Too many retries")) -- cgit v1.2.3