[feat] centralize logging and use twisted.logger by default

15 files changed, 84 insertions, 47 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 fbf605a9..f620f1bc 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
diff --git a/client/src/leap/soledad/client/crypto.py b/client/src/leap/soledad/client/crypto.py
index f7d92372..9f5fe28e 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
@@ -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 74a40931..c1a7f651 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__)
 
 
 #
@@ -393,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
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..3c3e7aab 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()
diff --git a/client/src/leap/soledad/client/secrets.py b/client/src/leap/soledad/client/secrets.py
index 3547a711..b7bcdd0a 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__)
 
 
 #
@@ -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..14d6f5ae 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
@@ -595,7 +595,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..335daaef 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
diff --git a/common/src/leap/soledad/common/couch/state.py b/common/src/leap/soledad/common/couch/state.py
index 9ff9fe55..e3cd1a24 100644
--- a/common/src/leap/soledad/common/couch/state.py
+++ b/common/src/leap/soledad/common/couch/state.py
@@ -17,12 +17,12 @@
 """
 Server state using CouchDatabase as backend.
 """
-import logging
 import re
 import time
 from urlparse import urljoin
 from hashlib import sha512
 
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.couch import CouchDatabase
 from leap.soledad.common.couch import couch_server
 from leap.soledad.common.command import exec_validated_cmd
@@ -30,7 +30,7 @@ from leap.soledad.common.l2db.remote.server_state import ServerState
 from leap.soledad.common.l2db.errors import Unauthorized
 
 
-logger = logging.getLogger(__name__)
+logger = getLogger(__name__)
 
 
 def is_db_name_valid(name):
diff --git a/common/src/leap/soledad/common/log.py b/common/src/leap/soledad/common/log.py
new file mode 100644
index 00000000..3f026045
--- /dev/null
+++ b/common/src/leap/soledad/common/log.py
@@ -0,0 +1,45 @@
+# -*- coding: utf-8 -*-
+# log.py
+# Copyright (C) 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/>.
+
+
+"""
+This module centralizes logging facilities and allows for different behaviours,
+as using the python logging module instead of twisted logger, and to print logs
+to stdout, mainly for development purposes.
+"""
+
+
+import os
+import sys
+
+from twisted.logger import Logger
+from twisted.logger import textFileLogObserver
+
+
+def getLogger(*args, **kwargs):
+
+    if os.environ.get('SOLEDAD_USE_PYTHON_LOGGING'):
+        import logging
+        return logging.getLogger(__name__)
+
+    if os.environ.get('SOLEDAD_LOG_TO_STDOUT'):
+        kwargs({'observer': textFileLogObserver(sys.stdout)})
+
+    return Logger(*args, **kwargs)
+
+
+__all__ = ['getLogger']
diff --git a/server/src/leap/soledad/server/auth.py b/server/src/leap/soledad/server/auth.py
index ecee2d5d..b7186b3b 100644
--- a/server/src/leap/soledad/server/auth.py
+++ b/server/src/leap/soledad/server/auth.py
@@ -22,13 +22,16 @@ import json
 
 from abc import ABCMeta, abstractmethod
 from routes.mapper import Mapper
-from twisted.python import log
 
+from leap.soledad.common.log import getLogger
 from leap.soledad.common.l2db import DBNAME_CONSTRAINTS, errors as u1db_errors
 from leap.soledad.common import SHARED_DB_NAME
 from leap.soledad.common import USER_DB_PREFIX
 
 
+logger = getLogger(__name__)
+
+
 class URLToAuthorization(object):
     """
     Verify if actions can be performed by a user.
@@ -378,7 +381,7 @@ class SoledadTokenAuthMiddleware(SoledadAuthMiddleware):
         try:
             return self._state.verify_token(uuid, token)
         except Exception as e:
-            log.err(e)
+            logger.error(e)
             return False
 
     def _get_auth_error_string(self):