Do the soledad sync the twisted way

This closes: #6658 and #6691

2 files changed, 174 insertions, 208 deletions

diff --git a/src/leap/bitmask/backend/components.py b/src/leap/bitmask/backend/components.py
index a843147e..1efcda6c 100644
--- a/src/leap/bitmask/backend/components.py
+++ b/src/leap/bitmask/backend/components.py
@@ -779,10 +779,8 @@ class Soledad(object):
         """
         provider_config = ProviderConfig.get_provider_config(domain)
         if provider_config is not None:
-            # XXX FIXME --- remove defer-to-thread or at least put it in a
-            # separate threadpool.
-            self._soledad_defer = threads.deferToThread(
-                self._soledad_bootstrapper.run_soledad_setup_checks,
+            sb = self._soledad_bootstrapper
+            self._soledad_defer = sb.run_soledad_setup_checks(
                 provider_config, username, password,
                 download_if_needed=True)
             self._soledad_defer.addCallback(self._set_proxies_cb)
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"))