Merge tag '0.9.0'

Tag version 0.9.0

12 files changed, 83 insertions, 101 deletions

diff --git a/client/src/leap/soledad/client/adbapi.py b/client/src/leap/soledad/client/adbapi.py
index ef0f9066..ce9bec05 100644
--- a/client/src/leap/soledad/client/adbapi.py
+++ b/client/src/leap/soledad/client/adbapi.py
@@ -19,31 +19,25 @@ An asyncrhonous interface to soledad using sqlcipher backend.
 It uses twisted.enterprise.adbapi.
 """
 import re
-import os
 import sys
-import logging
 
 from functools import partial
 
 from twisted.enterprise import adbapi
 from twisted.internet.defer import DeferredSemaphore
-from twisted.python import log
 from zope.proxy import ProxyBase, setProxiedObject
 from pysqlcipher import dbapi2
 
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.errors import DatabaseAccessError
 
 from leap.soledad.client import sqlcipher as soledad_sqlcipher
 from leap.soledad.client.pragmas import set_init_pragmas
 
 
-logger = logging.getLogger(name=__name__)
+logger = getLogger(__name__)
 
 
-DEBUG_SQL = os.environ.get("LEAP_DEBUG_SQL")
-if DEBUG_SQL:
-    log.startLogging(sys.stdout)
-
 """
 How long the SQLCipher connection should wait for the lock to go away until
 raising an exception.
@@ -221,13 +215,12 @@ class U1DBConnectionPool(adbapi.ConnectionPool):
         def _errback(failure):
             failure.trap(dbapi2.OperationalError)
             if failure.getErrorMessage() == "database is locked":
-                logger.warning("Database operation timed out.")
+                logger.warn("database operation timed out")
                 should_retry = semaphore.acquire()
                 if should_retry:
-                    logger.warning(
-                        "Database operation timed out while waiting for "
-                        "lock, trying again...")
+                    logger.warn("trying again...")
                     return _run_interaction()
+                logger.warn("giving up!")
             return failure
 
         d = _run_interaction()
@@ -286,7 +279,7 @@ class U1DBConnectionPool(adbapi.ConnectionPool):
             try:
                 conn.rollback()
             except:
-                log.err(None, "Rollback failed")
+                logger.error(None, "Rollback failed")
             raise excType, excValue, excTraceback
 
     def finalClose(self):
diff --git a/client/src/leap/soledad/client/api.py b/client/src/leap/soledad/client/api.py
index 1bfbed8a..6870d5ba 100644
--- a/client/src/leap/soledad/client/api.py
+++ b/client/src/leap/soledad/client/api.py
@@ -28,7 +28,6 @@ remote storage in the server side.
 import binascii
 import errno
 import httplib
-import logging
 import os
 import socket
 import ssl
@@ -49,6 +48,7 @@ from leap.common.plugins import collect_plugins
 from leap.soledad.common import SHARED_DB_NAME
 from leap.soledad.common import soledad_assert
 from leap.soledad.common import soledad_assert_type
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.l2db.remote import http_client
 from leap.soledad.common.l2db.remote.ssl_match_hostname import match_hostname
 from leap.soledad.common.errors import DatabaseAccessError
@@ -62,7 +62,7 @@ from leap.soledad.client.shared_db import SoledadSharedDatabase
 from leap.soledad.client import sqlcipher
 from leap.soledad.client import encdecpool
 
-logger = logging.getLogger(name=__name__)
+logger = getLogger(__name__)
 
 
 # we may want to collect statistics from the sync process
@@ -337,7 +337,7 @@ class Soledad(object):
         """
         Close underlying U1DB database.
         """
-        logger.debug("Closing soledad")
+        logger.debug("closing soledad")
         self._dbpool.close()
         if getattr(self, '_dbsyncer', None):
             self._dbsyncer.close()
@@ -736,6 +736,8 @@ class Soledad(object):
         :rtype: twisted.internet.defer.Deferred
         """
         sync_url = urlparse.urljoin(self._server_url, 'user-%s' % self.uuid)
+        if not self._dbsyncer:
+            return
         d = self._dbsyncer.sync(
             sync_url,
             creds=self._creds,
@@ -761,7 +763,7 @@ class Soledad(object):
         def _sync_errback(failure):
             s = StringIO()
             failure.printDetailedTraceback(file=s)
-            msg = "Soledad exception when syncing!\n" + s.getvalue()
+            msg = "got exception when syncing!\n" + s.getvalue()
             logger.error(msg)
             return failure
 
@@ -1003,7 +1005,7 @@ class Soledad(object):
 def create_path_if_not_exists(path):
     try:
         if not os.path.isdir(path):
-            logger.info('Creating directory: %s.' % path)
+            logger.info('creating directory: %s.' % path)
         os.makedirs(path)
     except OSError as exc:
         if exc.errno == errno.EEXIST and os.path.isdir(path):
diff --git a/client/src/leap/soledad/client/crypto.py b/client/src/leap/soledad/client/crypto.py
index f7d92372..d81c883b 100644
--- a/client/src/leap/soledad/client/crypto.py
+++ b/client/src/leap/soledad/client/crypto.py
@@ -22,7 +22,6 @@ import binascii
 import hmac
 import hashlib
 import json
-import logging
 
 from cryptography.hazmat.primitives.ciphers import Cipher, algorithms, modes
 from cryptography.hazmat.backends.multibackend import MultiBackend
@@ -32,9 +31,10 @@ from cryptography.hazmat.backends.openssl.backend \
 from leap.soledad.common import soledad_assert
 from leap.soledad.common import soledad_assert_type
 from leap.soledad.common import crypto
+from leap.soledad.common.log import getLogger
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 MAC_KEY_LENGTH = 64
@@ -300,7 +300,7 @@ def encrypt_docstr(docstr, doc_id, doc_rev, key, secret):
     # convert binary data to hexadecimal representation so the JSON
     # serialization does not complain about what it tries to serialize.
     hex_ciphertext = binascii.b2a_hex(ciphertext)
-    logger.debug("Encrypting doc: %s" % doc_id)
+    logger.debug("encrypting doc: %s" % doc_id)
     return json.dumps({
         crypto.ENC_JSON_KEY: hex_ciphertext,
         crypto.ENC_SCHEME_KEY: enc_scheme,
@@ -356,7 +356,7 @@ def _verify_doc_mac(doc_id, doc_rev, ciphertext, enc_scheme, enc_method,
     calculated_mac_hash = hashlib.sha256(calculated_mac).digest()
 
     if doc_mac_hash != calculated_mac_hash:
-        logger.warning("Wrong MAC while decrypting doc...")
+        logger.warn("wrong MAC while decrypting doc...")
         raise crypto.WrongMacError("Could not authenticate document's "
                                    "contents.")
 
diff --git a/client/src/leap/soledad/client/encdecpool.py b/client/src/leap/soledad/client/encdecpool.py
index a6d49b21..056b012f 100644
--- a/client/src/leap/soledad/client/encdecpool.py
+++ b/client/src/leap/soledad/client/encdecpool.py
@@ -23,22 +23,21 @@ during synchronization.
 
 
 import json
-import logging
 from uuid import uuid4
 
 from twisted.internet.task import LoopingCall
 from twisted.internet import threads
 from twisted.internet import defer
-from twisted.python import log
 
 from leap.soledad.common.document import SoledadDocument
 from leap.soledad.common import soledad_assert
+from leap.soledad.common.log import getLogger
 
 from leap.soledad.client.crypto import encrypt_docstr
 from leap.soledad.client.crypto import decrypt_doc_dict
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 #
@@ -155,7 +154,7 @@ class SyncEncrypterPool(SyncEncryptDecryptPool):
         Start the encrypter pool.
         """
         SyncEncryptDecryptPool.start(self)
-        logger.debug("Starting the encryption loop...")
+        logger.debug("starting the encryption loop...")
 
     def stop(self):
         """
@@ -230,10 +229,10 @@ class SyncEncrypterPool(SyncEncryptDecryptPool):
                 % self.TABLE_NAME
         result = yield self._runQuery(query, (doc_id, doc_rev))
         if result:
-            logger.debug("Found doc on sync db: %s" % doc_id)
+            logger.debug("found doc on sync db: %s" % doc_id)
             val = result.pop()
             defer.returnValue(val[0])
-        logger.debug("Did not find doc on sync db: %s" % doc_id)
+        logger.debug("did not find doc on sync db: %s" % doc_id)
         defer.returnValue(None)
 
     def delete_encrypted_doc(self, doc_id, doc_rev):
@@ -344,6 +343,9 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
 
         self._loop = LoopingCall(self._decrypt_and_recurse)
 
+    def _start_pool(self, period):
+        self._loop.start(period)
+
     def start(self, docs_to_process):
         """
         Set the number of documents we expect to process.
@@ -360,7 +362,7 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
         self._docs_to_process = docs_to_process
         self._deferred = defer.Deferred()
         d = self._init_db()
-        d.addCallback(lambda _: self._loop.start(self.DECRYPT_LOOP_PERIOD))
+        d.addCallback(lambda _: self._start_pool(self.DECRYPT_LOOP_PERIOD))
         return d
 
     def stop(self):
@@ -390,7 +392,7 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
         return d
 
     def _errback(self, failure):
-        log.err(failure)
+        logger.error(failure)
         self._deferred.errback(failure)
         self._processed_docs = 0
         self._last_inserted_idx = 0
@@ -503,7 +505,7 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
         :rtype: twisted.internet.defer.Deferred
         """
         doc_id, rev, content, gen, trans_id, idx = result
-        logger.debug("Sync decrypter pool: decrypted doc %s: %s %s %s"
+        logger.debug("sync decrypter pool: decrypted doc %s: %s %s %s"
                      % (doc_id, rev, gen, trans_id))
         return self.insert_received_doc(
             doc_id, rev, content, gen, trans_id, idx)
@@ -553,6 +555,12 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
         while next_index in self._decrypted_docs_indexes:
             sequence.append(str(next_index))
             next_index += 1
+            if len(sequence) > 900:
+                # 999 is the default value of SQLITE_MAX_VARIABLE_NUMBER
+                # if we try to query more, SQLite will refuse
+                # we need to find a way to improve this
+                # being researched in #7669
+                break
         # Then fetch all the ones ready for insertion.
         if sequence:
             insertable_docs = yield self._get_docs(encrypted=False,
@@ -602,7 +610,7 @@ class SyncDecrypterPool(SyncEncryptDecryptPool):
         :type trans_id: str
         """
         # could pass source_replica in params for callback chain
-        logger.debug("Sync decrypter pool: inserting doc in local db: "
+        logger.debug("sync decrypter pool: inserting doc in local db: "
                      "%s:%s %s" % (doc_id, doc_rev, gen))
 
         # convert deleted documents to avoid error on document creation
diff --git a/client/src/leap/soledad/client/http_target/__init__.py b/client/src/leap/soledad/client/http_target/__init__.py
index b7e54aa4..62e8bcf0 100644
--- a/client/src/leap/soledad/client/http_target/__init__.py
+++ b/client/src/leap/soledad/client/http_target/__init__.py
@@ -23,15 +23,15 @@ after receiving.
 
 
 import os
-import logging
 
+from leap.soledad.common.log import getLogger
 from leap.common.http import HTTPClient
 from leap.soledad.client.http_target.send import HTTPDocSender
 from leap.soledad.client.http_target.api import SyncTargetAPI
 from leap.soledad.client.http_target.fetch import HTTPDocFetcher
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 # we may want to collect statistics from the sync process
diff --git a/client/src/leap/soledad/client/http_target/api.py b/client/src/leap/soledad/client/http_target/api.py
index f8de9a15..3c8e3764 100644
--- a/client/src/leap/soledad/client/http_target/api.py
+++ b/client/src/leap/soledad/client/http_target/api.py
@@ -15,7 +15,6 @@
 # You should have received a copy of the GNU General Public License
 # along with this program. If not, see <http://www.gnu.org/licenses/>.
 import os
-import time
 import json
 import base64
 
diff --git a/client/src/leap/soledad/client/http_target/fetch.py b/client/src/leap/soledad/client/http_target/fetch.py
index a3f70b02..184c5883 100644
--- a/client/src/leap/soledad/client/http_target/fetch.py
+++ b/client/src/leap/soledad/client/http_target/fetch.py
@@ -14,7 +14,6 @@
 #
 # You should have received a copy of the GNU General Public License
 # along with this program. If not, see <http://www.gnu.org/licenses/>.
-import logging
 import json
 
 from twisted.internet import defer
@@ -24,11 +23,12 @@ from leap.soledad.client.events import emit_async
 from leap.soledad.client.crypto import is_symmetrically_encrypted
 from leap.soledad.client.encdecpool import SyncDecrypterPool
 from leap.soledad.client.http_target.support import RequestBody
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.document import SoledadDocument
 from leap.soledad.common.l2db import errors
 from leap.soledad.common.l2db.remote import utils
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 class HTTPDocFetcher(object):
diff --git a/client/src/leap/soledad/client/http_target/send.py b/client/src/leap/soledad/client/http_target/send.py
index 13218acf..c7bd057e 100644
--- a/client/src/leap/soledad/client/http_target/send.py
+++ b/client/src/leap/soledad/client/http_target/send.py
@@ -15,15 +15,15 @@
 # You should have received a copy of the GNU General Public License
 # along with this program. If not, see <http://www.gnu.org/licenses/>.
 import json
-import logging
 
 from twisted.internet import defer
 
+from leap.soledad.common.log import getLogger
 from leap.soledad.client.events import emit_async
 from leap.soledad.client.events import SOLEDAD_SYNC_SEND_STATUS
 from leap.soledad.client.http_target.support import RequestBody
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 class HTTPDocSender(object):
@@ -82,7 +82,6 @@ class HTTPDocSender(object):
         if self._defer_encryption:
             self._delete_sent(sent)
 
-        user_data = {'uuid': self.uuid, 'userid': self.userid}
         _emit_send_status(self.uuid, body.consumed, total)
         defer.returnValue(result)
 
diff --git a/client/src/leap/soledad/client/pragmas.py b/client/src/leap/soledad/client/pragmas.py
index 55397d10..870ed63e 100644
--- a/client/src/leap/soledad/client/pragmas.py
+++ b/client/src/leap/soledad/client/pragmas.py
@@ -17,15 +17,15 @@
 """
 Different pragmas used in the initialization of the SQLCipher database.
 """
-import logging
 import string
 import threading
 import os
 
 from leap.soledad.common import soledad_assert
+from leap.soledad.common.log import getLogger
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 _db_init_lock = threading.Lock()
@@ -321,7 +321,7 @@ def set_synchronous_off(db_handle):
     """
     Change the setting of the "synchronous" flag to OFF.
     """
-    logger.debug("SQLCIPHER: SETTING SYNCHRONOUS OFF")
+    logger.debug("sqlcipher: setting synchronous off")
     db_handle.cursor().execute('PRAGMA synchronous=OFF')
 
 
@@ -329,7 +329,7 @@ def set_synchronous_normal(db_handle):
     """
     Change the setting of the "synchronous" flag to NORMAL.
     """
-    logger.debug("SQLCIPHER: SETTING SYNCHRONOUS NORMAL")
+    logger.debug("sqlcipher: setting synchronous normal")
     db_handle.cursor().execute('PRAGMA synchronous=NORMAL')
 
 
@@ -337,7 +337,7 @@ def set_mem_temp_store(db_handle):
     """
     Use a in-memory store for temporary tables.
     """
-    logger.debug("SQLCIPHER: SETTING TEMP_STORE MEMORY")
+    logger.debug("sqlcipher: setting temp_store memory")
     db_handle.cursor().execute('PRAGMA temp_store=MEMORY')
 
 
@@ -362,7 +362,7 @@ def set_write_ahead_logging(db_handle):
     requirements of the application. The default strategy is to run a
     checkpoint once the WAL reaches 1000 pages"
     """
-    logger.debug("SQLCIPHER: SETTING WRITE-AHEAD LOGGING")
+    logger.debug("sqlcipher: setting write-ahead logging")
     db_handle.cursor().execute('PRAGMA journal_mode=WAL')
 
     # The optimum value can still use a little bit of tuning, but we favor
diff --git a/client/src/leap/soledad/client/secrets.py b/client/src/leap/soledad/client/secrets.py
index 3547a711..1eb6f31d 100644
--- a/client/src/leap/soledad/client/secrets.py
+++ b/client/src/leap/soledad/client/secrets.py
@@ -23,7 +23,6 @@ Soledad secrets handling.
 
 import os
 import scrypt
-import logging
 import binascii
 import errno
 import json
@@ -33,11 +32,12 @@ from hashlib import sha256
 from leap.soledad.common import soledad_assert
 from leap.soledad.common import soledad_assert_type
 from leap.soledad.common import document
+from leap.soledad.common.log import getLogger
 from leap.soledad.client import events
 from leap.soledad.client.crypto import encrypt_sym, decrypt_sym
 
 
-logger = logging.getLogger(name=__name__)
+logger = getLogger(__name__)
 
 
 #
@@ -193,42 +193,42 @@ class SoledadSecrets(object):
         """
         # STAGE 1 - verify if secrets exist locally
         try:
-            logger.info("Trying to load secrets from local storage...")
+            logger.info("trying to load secrets from local storage...")
             version = self._load_secrets_from_local_file()
             # eventually migrate local and remote stored documents from old
             # format version
             if version < self.RECOVERY_DOC_VERSION:
                 self._store_secrets()
                 self._upload_crypto_secrets()
-            logger.info("Found secrets in local storage.")
+            logger.info("found secrets in local storage")
             return
 
         except NoStorageSecret:
-            logger.info("Could not find secrets in local storage.")
+            logger.info("could not find secrets in local storage")
 
         # STAGE 2 - there are no secrets in local storage and this is the
         #           first time we are running soledad with the specified
         #           secrets_path. Try to fetch encrypted secrets from
         #           server.
         try:
-            logger.info('Trying to fetch secrets from remote storage...')
+            logger.info('trying to fetch secrets from remote storage...')
             version = self._download_crypto_secrets()
             self._store_secrets()
             # eventually migrate remote stored document from old format
             # version
             if version < self.RECOVERY_DOC_VERSION:
                 self._upload_crypto_secrets()
-            logger.info('Found secrets in remote storage.')
+            logger.info('found secrets in remote storage.')
             return
         except NoStorageSecret:
-            logger.info("Could not find secrets in remote storage.")
+            logger.info("could not find secrets in remote storage.")
 
         # STAGE 3 - there are no secrets in server also, so we want to
         #           generate the secrets and store them in the remote
         #           db.
-        logger.info("Generating secrets...")
+        logger.info("generating secrets...")
         self._gen_crypto_secrets()
-        logger.info("Uploading secrets...")
+        logger.info("uploading secrets...")
         self._upload_crypto_secrets()
 
     def _has_secret(self):
@@ -298,7 +298,7 @@ class SoledadSecrets(object):
         """
         Generate the crypto secrets.
         """
-        logger.info('No cryptographic secrets found, creating new secrets...')
+        logger.info('no cryptographic secrets found, creating new secrets...')
         secret_id = self._gen_secret()
         self.set_secret_id(secret_id)
 
@@ -445,7 +445,7 @@ class SoledadSecrets(object):
                             encrypted_secret)
                     secret_count += 1
                 except SecretsException as e:
-                    logger.error("Failed to decrypt storage secret: %s"
+                    logger.error("failed to decrypt storage secret: %s"
                                  % str(e))
         return secret_count, active_secret
 
@@ -461,7 +461,7 @@ class SoledadSecrets(object):
         events.emit_async(events.SOLEDAD_DOWNLOADING_KEYS, user_data)
         db = self._shared_db
         if not db:
-            logger.warning('No shared db found')
+            logger.warn('no shared db found')
             return
         doc = db.get_doc(self._shared_db_doc_id())
         user_data = {'userid': self._userid, 'uuid': self._uuid}
@@ -492,7 +492,7 @@ class SoledadSecrets(object):
         events.emit_async(events.SOLEDAD_UPLOADING_KEYS, user_data)
         db = self._shared_db
         if not db:
-            logger.warning('No shared db found')
+            logger.warn('no shared db found')
             return
         db.put_doc(doc)
         events.emit_async(events.SOLEDAD_DONE_UPLOADING_KEYS, user_data)
diff --git a/client/src/leap/soledad/client/sqlcipher.py b/client/src/leap/soledad/client/sqlcipher.py
index 166c0783..3921c323 100644
--- a/client/src/leap/soledad/client/sqlcipher.py
+++ b/client/src/leap/soledad/client/sqlcipher.py
@@ -41,7 +41,6 @@ So, as the statements above were introduced for backwards compatibility with
 SQLCipher 1.1 databases, we do not implement them as all SQLCipher databases
 handled by Soledad should be created by SQLCipher >= 2.0.
 """
-import logging
 import os
 import json
 
@@ -55,8 +54,9 @@ from twisted.internet import defer
 from twisted.enterprise import adbapi
 
 from leap.soledad.common.document import SoledadDocument
-from leap.soledad.common import l2db
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.l2db import errors as u1db_errors
+from leap.soledad.common.l2db import Document
 from leap.soledad.common.l2db.backends import sqlite_backend
 from leap.soledad.common.errors import DatabaseAccessError
 
@@ -65,7 +65,7 @@ from leap.soledad.client.sync import SoledadSynchronizer
 from leap.soledad.client import pragmas
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 # Monkey-patch u1db.backends.sqlite_backend with pysqlcipher.dbapi2
@@ -448,7 +448,6 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
         self.received_docs = []
 
         self.running = False
-        self.shutdownID = None
         self._db_handle = None
 
         # initialize the main db before scheduling a start
@@ -465,8 +464,6 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
 
     def _start(self):
         if not self.running:
-            self.shutdownID = self._reactor.addSystemEventTrigger(
-                'during', 'shutdown', self.finalClose)
             self.running = True
 
     def _initialize_main_db(self):
@@ -561,13 +558,6 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
         # XXX this SHOULD BE a callback
         return self._get_generation()
 
-    def finalClose(self):
-        """
-        This should only be called by the shutdown trigger.
-        """
-        self.shutdownID = None
-        self.running = False
-
     def close(self):
         """
         Close the syncer and syncdb orderly
@@ -578,6 +568,7 @@ class SQLCipherU1DBSync(SQLCipherDatabase):
             _, syncer = self._syncers[url]
             syncer.close()
             del self._syncers[url]
+        self.running = False
 
 
 class U1DBSQLiteBackend(sqlite_backend.SQLitePartialExpandDatabase):
@@ -595,7 +586,7 @@ class U1DBSQLiteBackend(sqlite_backend.SQLitePartialExpandDatabase):
         self._db_handle = conn
         self._real_replica_uid = None
         self._ensure_schema()
-        self._factory = l2db.Document
+        self._factory = Document
 
 
 class SoledadSQLCipherWrapper(SQLCipherDatabase):
diff --git a/client/src/leap/soledad/client/sync.py b/client/src/leap/soledad/client/sync.py
index 2656a150..7ed5f693 100644
--- a/client/src/leap/soledad/client/sync.py
+++ b/client/src/leap/soledad/client/sync.py
@@ -18,17 +18,16 @@
 Soledad synchronization utilities.
 """
 import os
-import time
-import logging
 
 from twisted.internet import defer
 
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.l2db import errors
 from leap.soledad.common.l2db.sync import Synchronizer
 from leap.soledad.common.errors import BackendNotReadyError
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 # we may want to collect statistics from the sync process
@@ -97,21 +96,17 @@ class SoledadSynchronizer(Synchronizer):
                 sync_target.get_sync_info(self.source._replica_uid)
         except (errors.DatabaseDoesNotExist, BackendNotReadyError) as e:
             logger.debug("Database isn't ready on server. Will be created.")
-            logger.debug("Reason: %s", e.__class__)
+            logger.debug("Reason: %s" % e.__class__)
             self.target_replica_uid = None
             target_gen, target_trans_id = 0, ''
             target_my_gen, target_my_trans_id = 0, ''
 
-        logger.debug(
-            "Soledad target sync info:\n"
-            "  target replica uid: %s\n"
-            "  target generation: %d\n"
-            "  target trans id: %s\n"
-            "  target my gen: %d\n"
-            "  target my trans_id: %s\n"
-            "  source replica_uid: %s\n"
-            % (self.target_replica_uid, target_gen, target_trans_id,
-               target_my_gen, target_my_trans_id, self.source._replica_uid))
+        logger.debug("target replica uid: %s" % self.target_replica_uid)
+        logger.debug("target generation: %d" % target_gen)
+        logger.debug("target trans id: %s" % target_trans_id)
+        logger.debug("target my gen: %d" % target_my_gen)
+        logger.debug("target my trans_id: %s" % target_my_trans_id)
+        logger.debug("source replica_uid: %s" % self.source._replica_uid)
 
         # make sure we'll have access to target replica uid once it exists
         if self.target_replica_uid is None:
@@ -134,8 +129,7 @@ class SoledadSynchronizer(Synchronizer):
 
         # what's changed since that generation and this current gen
         my_gen, _, changes = self.source.whats_changed(target_my_gen)
-        logger.debug("Soledad sync: there are %d documents to send."
-                     % len(changes))
+        logger.debug("there are %d documents to send" % len(changes))
 
         # get source last-seen database generation for the target
         if self.target_replica_uid is None:
@@ -144,11 +138,10 @@ class SoledadSynchronizer(Synchronizer):
             target_last_known_gen, target_last_known_trans_id = \
                 self.source._get_replica_gen_and_trans_id(
                     self.target_replica_uid)
-        logger.debug(
-            "Soledad source sync info:\n"
-            "  last target gen known to source: %d\n"
-            "  last target trans_id known to source: %s"
-            % (target_last_known_gen, target_last_known_trans_id))
+            logger.debug(
+                "last known target gen: %d" % target_last_known_gen)
+            logger.debug(
+                "last known target trans_id: %s" % target_last_known_trans_id)
 
         # validate transaction ids
         if not changes and target_last_known_gen == target_gen:
@@ -181,11 +174,8 @@ class SoledadSynchronizer(Synchronizer):
             target_last_known_gen, target_last_known_trans_id,
             self._insert_doc_from_target, ensure_callback=ensure_callback,
             defer_decryption=defer_decryption)
-        logger.debug(
-            "Soledad source sync info after sync exchange:\n"
-            "  source known target gen: %d\n"
-            "  source known target trans_id: %s"
-            % (new_gen, new_trans_id))
+        logger.debug("target gen after sync: %d" % new_gen)
+        logger.debug("target trans_id after sync: %s" % new_trans_id)
         info = {
             "target_replica_uid": self.target_replica_uid,
             "new_gen": new_gen,
@@ -224,7 +214,7 @@ class SoledadSynchronizer(Synchronizer):
         :return: A deferred which will fire when the sync has been completed.
         :rtype: twisted.internet.defer.Deferred
         """
-        logger.debug("Completing deferred last step in SYNC...")
+        logger.debug("completing deferred last step in sync...")
 
         # record target synced-up-to generation including applying what we
         # sent