From f2c68ba96498f8b88e415aaf27ced735c790510e Mon Sep 17 00:00:00 2001 From: Kali Kaneko Date: Fri, 27 Sep 2013 16:07:29 -0400 Subject: Improve error handling during soledad boostrapping in the client. The aim is to have better logs for debugging the different problems behind issues like #3619 and #3867. As I'm finding a good quantity of SSL handshake timeouts, I'm also adding a litte retry subroutine to the load_and_sync. Also, initialization and sync calls are separeted to be able to correlate logs with server-side soledad. --- .../services/soledad/soledadbootstrapper.py | 205 ++++++++++++++++----- src/leap/bitmask/util/__init__.py | 14 ++ 2 files changed, 170 insertions(+), 49 deletions(-) diff --git a/src/leap/bitmask/services/soledad/soledadbootstrapper.py b/src/leap/bitmask/services/soledad/soledadbootstrapper.py index cac91440..afd7d623 100644 --- a/src/leap/bitmask/services/soledad/soledadbootstrapper.py +++ b/src/leap/bitmask/services/soledad/soledadbootstrapper.py @@ -14,15 +14,15 @@ # # You should have received a copy of the GNU General Public License # along with this program. If not, see . - """ Soledad bootstrapping """ - import logging import os import socket +from ssl import SSLError + from PySide import QtCore from u1db import errors as u1db_errors @@ -32,9 +32,10 @@ from leap.bitmask.crypto.srpauth import SRPAuth from leap.bitmask.services.abstractbootstrapper import AbstractBootstrapper from leap.bitmask.services.soledad.soledadconfig import SoledadConfig from leap.bitmask.util.request_helpers import get_content +from leap.bitmask.util import is_file, is_empty_file from leap.bitmask.util import get_path_prefix -from leap.common.check import leap_assert, leap_assert_type from leap.common.files import get_mtime +from leap.common.check import leap_assert, leap_assert_type, leap_check from leap.keymanager import KeyManager, openpgp from leap.keymanager.errors import KeyNotFound from leap.soledad.client import Soledad @@ -42,6 +43,17 @@ from leap.soledad.client import Soledad logger = logging.getLogger(__name__) +# TODO these exceptions could be moved to soledad itself +# after settling this down. + +class SoledadSyncError(Exception): + message = "Error while syncing Soledad" + + +class SoledadInitError(Exception): + message = "Error while initializing Soledad" + + class SoledadBootstrapper(AbstractBootstrapper): """ Soledad init procedure @@ -109,68 +121,159 @@ class SoledadBootstrapper(AbstractBootstrapper): """ self._soledad_retries += 1 + def _get_db_paths(self, uuid): + """ + Returns the secrets and local db paths needed for soledad + initialization + + :param uuid: uuid for user + :type uuid: str + + :return: a tuple with secrets, local_db paths + :rtype: tuple + """ + prefix = os.path.join(get_path_prefix(), "leap", "soledad") + secrets = "%s/%s.secret" % (prefix, uuid) + local_db = "%s/%s.db" % (prefix, uuid) + + # We remove an empty file if found to avoid complains + # about the db not being properly initialized + if is_file(local_db) and is_empty_file(local_db): + try: + os.remove(local_db) + except OSError: + logger.warning("Could not remove empty file %s" + % local_db) + return secrets, local_db + # initialization def load_and_sync_soledad(self): """ Once everthing is in the right place, we instantiate and sync Soledad - - :param srp_auth: SRPAuth object used - :type srp_auth: SRPAuth """ - srp_auth = self.srpauth - uuid = srp_auth.get_uid() + uuid = self.srpauth.get_uid() + token = self.srpauth.get_token() - prefix = os.path.join(get_path_prefix(), "leap", "soledad") - secrets_path = "%s/%s.secret" % (prefix, uuid) - local_db_path = "%s/%s.db" % (prefix, uuid) + secrets_path, local_db_path = self._get_db_paths(uuid) # TODO: Select server based on timezone (issue #3308) server_dict = self._soledad_config.get_hosts() - if server_dict.keys(): - selected_server = server_dict[server_dict.keys()[0]] - server_url = "https://%s:%s/user-%s" % ( - selected_server["hostname"], - selected_server["port"], - uuid) + if not server_dict.keys(): + # XXX raise more specific exception + raise Exception("No soledad server found") + + selected_server = server_dict[server_dict.keys()[0]] + server_url = "https://%s:%s/user-%s" % ( + selected_server["hostname"], + selected_server["port"], + uuid) + + logger.debug("Using soledad server url: %s" % (server_url,)) - logger.debug("Using soledad server url: %s" % (server_url,)) + cert_file = self._provider_config.get_ca_cert_path() - cert_file = self._provider_config.get_ca_cert_path() + logger.debug('local_db:%s' % (local_db_path,)) + logger.debug('secrets_path:%s' % (secrets_path,)) - # TODO: If selected server fails, retry with another host - # (issue #3309) + try: + self._try_soledad_init( + uuid, secrets_path, local_db_path, + server_url, cert_file, token) + except: + # re-raise the exceptions from try_init, + # we're currently handling the retries from the + # soledad-launcher in the gui. + raise + + leap_check(self._soledad is not None, + "Null soledad, error while initializing") + + # and now, let's sync + sync_tries = 10 + while sync_tries > 0: try: - self._soledad = Soledad( - uuid, - self._password.encode("utf-8"), - secrets_path=secrets_path, - local_db_path=local_db_path, - server_url=server_url, - cert_file=cert_file, - auth_token=srp_auth.get_token()) - self._soledad.sync() - - # XXX All these errors should be handled by soledad itself, - # and return a subclass of SoledadInitializationFailed - except socket.timeout: - logger.debug("SOLEDAD TIMED OUT...") - self.soledad_timeout.emit() - except socket.error as exc: - logger.error("Socket error while initializing soledad") - self.soledad_failed.emit() - except u1db_errors.Unauthorized: - logger.error("Error while initializing soledad " - "(unauthorized).") - self.soledad_failed.emit() - except Exception as exc: - logger.error("Unhandled error while initializating " + self._try_soledad_sync() + 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 + continue + + # reached bottom, failed to sync + # and there's nothing we can do... + self.soledad_failed.emit() + raise SoledadSyncError() + + def _try_soledad_init(self, uuid, secrets_path, local_db_path, + server_url, cert_file, auth_token): + """ + Tries to initialize soledad. + + :param uuid: user identifier + :param secrets_path: path to secrets file + :param local_db_path: path to local db file + :param server_url: soledad server uri + :cert_file: + :param auth token: auth token + :type auth_token: str + """ + + # TODO: If selected server fails, retry with another host + # (issue #3309) + try: + self._soledad = Soledad( + uuid, + self._password.encode("utf-8"), + secrets_path=secrets_path, + local_db_path=local_db_path, + server_url=server_url, + cert_file=cert_file, + auth_token=auth_token) + + # XXX All these errors should be handled by soledad itself, + # and return a subclass of SoledadInitializationFailed + except socket.timeout: + logger.debug("SOLEDAD initialization TIMED OUT...") + self.soledad_timeout.emit() + except socket.error as exc: + logger.error("Socket error while initializing soledad") + self.soledad_failed.emit() + except u1db_errors.Unauthorized: + logger.error("Error while initializing soledad " + "(unauthorized).") + self.soledad_failed.emit() + except Exception as exc: + logger.exception("Unhandled error while initializating " "soledad: %r" % (exc,)) - raise - else: - raise Exception("No soledad server found") + self.soledad_failed.emit() + + def _try_soledad_sync(self): + """ + Tries to sync soledad. + Raises SoledadSyncError if not successful. + """ + try: + logger.error("trying to sync soledad....") + self._soledad.sync() + except SSLError as exc: + logger.error("%r" % (exc,)) + raise SoledadSyncError("Failed to sync soledad") + except Exception as exc: + logger.exception("Unhandled error while syncing" + "soledad: %r" % (exc,)) + self.soledad_failed.emit() + raise SoledadSyncError("Failed to sync soledad") def _download_config(self): """ @@ -185,6 +288,8 @@ class SoledadBootstrapper(AbstractBootstrapper): self._soledad_config = SoledadConfig() + # TODO factor out with eip/provider configs. + headers = {} mtime = get_mtime( os.path.join(get_path_prefix(), "leap", "providers", @@ -242,8 +347,10 @@ class SoledadBootstrapper(AbstractBootstrapper): Generates the key pair if needed, uploads it to the webapp and nickserver """ - leap_assert(self._provider_config, + leap_assert(self._provider_config is not None, "We need a provider configuration!") + leap_assert(self._soledad is not None, + "We need a non-null soledad to generate keys") address = "%s@%s" % (self._user, self._provider_config.get_domain()) diff --git a/src/leap/bitmask/util/__init__.py b/src/leap/bitmask/util/__init__.py index f762a350..b58e6e3b 100644 --- a/src/leap/bitmask/util/__init__.py +++ b/src/leap/bitmask/util/__init__.py @@ -62,3 +62,17 @@ def update_modification_ts(path): """ os.utime(path, None) return get_modification_ts(path) + + +def is_file(path): + """ + Returns True if the path exists and is a file. + """ + return os.path.isfile(path) + + +def is_empty_file(path): + """ + Returns True if the file at path is empty. + """ + return os.stat(path).st_size is 0 -- cgit v1.2.3