From 9f95446a55533c8cdceec7c4430be5cad752ecb1 Mon Sep 17 00:00:00 2001 From: "Kali Kaneko (leap communications)" Date: Tue, 25 Apr 2017 18:00:12 +0200 Subject: [bug] unify logging style using class attr I changed most of the logger statements to use a class attribute, in this way it's easier to identify which class it's logging them. in some cases I leave a module-level logger, when we're either using functions or when the module it's too small. at the same time I did a general review and cleanup of the logging statements. --- src/leap/bitmask/keymanager/__init__.py | 28 +++++++---------- src/leap/bitmask/keymanager/keys.py | 12 ++++--- src/leap/bitmask/keymanager/nicknym.py | 26 +++++++-------- src/leap/bitmask/keymanager/openpgp.py | 54 ++++++++++++++++---------------- src/leap/bitmask/keymanager/refresher.py | 16 +++++----- src/leap/bitmask/keymanager/wrapper.py | 4 +-- 6 files changed, 67 insertions(+), 73 deletions(-) (limited to 'src/leap/bitmask/keymanager') diff --git a/src/leap/bitmask/keymanager/__init__.py b/src/leap/bitmask/keymanager/__init__.py index fb4668c..190e26f 100644 --- a/src/leap/bitmask/keymanager/__init__.py +++ b/src/leap/bitmask/keymanager/__init__.py @@ -40,12 +40,6 @@ from leap.bitmask.keymanager.refresher import RandomRefreshPublicKey from leap.bitmask.keymanager.validation import ValidationLevels, can_upgrade from leap.bitmask.keymanager.openpgp import OpenPGPScheme -logger = Logger() - - -# -# The Key Manager -# class KeyManager(object): @@ -53,6 +47,8 @@ class KeyManager(object): # server's key storage constants # + log = Logger() + OPENPGP_KEY = 'openpgp' PUBKEY_KEY = "user[public_key]" @@ -94,7 +90,7 @@ class KeyManager(object): try: self._combined_ca_bundle = combined_ca_bundle or create() except Exception: - logger.warn('error while creating combined ca bundle') + self.log.warn('Error while creating combined ca bundle') self._combined_ca_bundle = '' self._async_client = HTTPClient(self._combined_ca_bundle) @@ -155,17 +151,17 @@ class KeyManager(object): except keymanager_errors.KeyNotFound: raise except IOError as e: - logger.warn("HTTP error retrieving key: %r" % (e,)) - logger.warn("%s" % (content,)) + self.log.warn("HTTP error retrieving key: %r" % (e,)) + self.log.warn("%s" % (content,)) raise keymanager_errors.KeyNotFound(e.message), \ None, sys.exc_info()[2] except ValueError as v: - logger.warn("invalid JSON data from key: %s" % (uri,)) + self.log.warn("Invalid JSON data from key: %s" % (uri,)) raise keymanager_errors.KeyNotFound(v.message + ' - ' + uri), \ None, sys.exc_info()[2] except Exception as e: - logger.warn("error retrieving key: %r" % (e,)) + self.log.warn("Error retrieving key: %r" % (e,)) raise keymanager_errors.KeyNotFound(e.message), \ None, sys.exc_info()[2] # Responses are now text/plain, although it's json anyway, but @@ -190,7 +186,7 @@ class KeyManager(object): def check_404(response): if response.code == NOT_FOUND: message = '%s: %s key not found.' % (response.code, address) - logger.warn(message) + self.log.warn(message) raise KeyNotFound(message), None, sys.exc_info()[2] return response @@ -218,7 +214,7 @@ class KeyManager(object): try: content = yield self._async_client.request(str(uri), 'GET') except Exception as e: - logger.warn("There was a problem fetching key: %s" % (e,)) + self.log.warn("There was a problem fetching key: %s" % (e,)) raise keymanager_errors.KeyNotFound(uri) if not content: raise keymanager_errors.KeyNotFound(uri) @@ -307,8 +303,7 @@ class KeyManager(object): :raise UnsupportedKeyTypeError: if invalid key type """ - logger.debug("getting key for %s" % (address,)) - + self.log.debug('Getting key for %s' % (address,)) emit_async(catalog.KEYMANAGER_LOOKING_FOR_KEY, address) def key_found(key): @@ -455,7 +450,6 @@ class KeyManager(object): :raise UnsupportedKeyTypeError: if invalid key type """ - @defer.inlineCallbacks def encrypt(keys): pubkey, signkey = keys @@ -726,7 +720,7 @@ class KeyManager(object): :raise UnsupportedKeyTypeError: if invalid key type """ - logger.info("fetch key for %s from %s" % (address, uri)) + self.log.info('Fetch key for %s from %s' % (address, uri)) key_content = yield self._get_with_combined_ca_bundle(uri) # XXX parse binary keys diff --git a/src/leap/bitmask/keymanager/keys.py b/src/leap/bitmask/keymanager/keys.py index 622c1c6..54609c0 100644 --- a/src/leap/bitmask/keymanager/keys.py +++ b/src/leap/bitmask/keymanager/keys.py @@ -30,7 +30,7 @@ from leap.bitmask.keymanager.wrapper import TempGPGWrapper from leap.bitmask.keymanager.validation import ValidationLevels from leap.bitmask.keymanager import documents as doc -logger = Logger() +log = Logger() # @@ -71,9 +71,9 @@ def build_key_from_dict(key, active=None): try: validation = ValidationLevels.get(active[doc.KEY_VALIDATION_KEY]) except ValueError: - logger.error("Not valid validation level (%s) for key %s", - (active[doc.KEY_VALIDATION_KEY], - active[doc.KEY_FINGERPRINT_KEY])) + log.error('Not valid validation level (%s) for key %s', + (active[doc.KEY_VALIDATION_KEY], + active[doc.KEY_FINGERPRINT_KEY])) last_audited_at = _to_datetime(active[doc.KEY_LAST_AUDITED_AT_KEY]) encr_used = active[doc.KEY_ENCR_USED_KEY] sign_used = active[doc.KEY_SIGN_USED_KEY] @@ -112,6 +112,7 @@ def _to_unix_time(date): class OpenPGPKey(object): + """ Base class for OpenPGP keys. """ @@ -120,6 +121,7 @@ class OpenPGPKey(object): 'private', 'length', 'expiry_date', 'validation', 'last_audited_at', 'refreshed_at', 'encr_used', 'sign_used', '_index', '_gpgbinary') + log = Logger() def __init__(self, address=None, gpgbinary=None, uids=[], fingerprint="", key_data="", private=False, length=0, expiry_date=None, @@ -184,7 +186,7 @@ class OpenPGPKey(object): def merge(self, newkey): if newkey.fingerprint != self.fingerprint: - logger.critical( + self.log.critical( "Can't put a key whith the same key_id and different " "fingerprint: %s, %s" % (newkey.fingerprint, self.fingerprint)) diff --git a/src/leap/bitmask/keymanager/nicknym.py b/src/leap/bitmask/keymanager/nicknym.py index 7c738da..8e3a08f 100644 --- a/src/leap/bitmask/keymanager/nicknym.py +++ b/src/leap/bitmask/keymanager/nicknym.py @@ -1,6 +1,6 @@ # -*- coding: utf-8 -*- # nicknym.py -# Copyright (C) 2016 LEAP +# Copyright (C) 2016-2017 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 @@ -17,10 +17,10 @@ import json import sys -import logging import urllib from twisted.internet import defer +from twisted.logger import Logger from twisted.web import client from twisted.web._responses import NOT_FOUND @@ -30,14 +30,14 @@ from leap.common.http import HTTPClient from leap.common.decorators import memoized_method -logger = logging.getLogger(__name__) - - class Nicknym(object): + """ Responsible for communication to the nicknym server. """ + log = Logger() + PUBKEY_KEY = "user[public_key]" def __init__(self, nickserver_uri, ca_cert_path, token): @@ -83,12 +83,12 @@ class Nicknym(object): body=str(data), headers=headers) except Exception as e: - logger.warning("Error uploading key: %r" % (e,)) + self.log.warn('Error uploading key: %r' % (e,)) raise e if 'error' in res: # FIXME: That's a workaround for 500, # we need to implement a readBody to assert response code - logger.warning("Error uploading key: %r" % (res,)) + self.log.warn('Error uploading key: %r' % (res,)) raise Exception(res) @defer.inlineCallbacks @@ -105,19 +105,17 @@ class Nicknym(object): try: content = yield self._fetch_and_handle_404_from_nicknym(uri) json_content = json.loads(content) - except KeyNotFound: raise except IOError as e: - logger.warning("HTTP error retrieving key: %r" % (e,)) - logger.warning("%s" % (content,)) + self.log.warn('HTTP error retrieving key: %r' % (e,)) + self.log.warn("%s" % (content,)) raise KeyNotFound(e.message), None, sys.exc_info()[2] except ValueError as v: - logger.warning("Invalid JSON data from key: %s" % (uri,)) + self.log.warn('Invalid JSON data from key: %s' % (uri,)) raise KeyNotFound(v.message + ' - ' + uri), None, sys.exc_info()[2] - except Exception as e: - logger.warning("Error retrieving key: %r" % (e,)) + self.log.warn('Error retrieving key: %r' % (e,)) raise KeyNotFound(e.message), None, sys.exc_info()[2] # Responses are now text/plain, although it's json anyway, but # this will fail when it shouldn't @@ -141,7 +139,7 @@ class Nicknym(object): if response.code == NOT_FOUND: message = ' %s: Key not found. Request: %s' \ % (response.code, uri) - logger.warning(message) + self.log.warn(message) raise KeyNotFound(message), None, sys.exc_info()[2] return response diff --git a/src/leap/bitmask/keymanager/openpgp.py b/src/leap/bitmask/keymanager/openpgp.py index b72c62c..8c9dc1e 100644 --- a/src/leap/bitmask/keymanager/openpgp.py +++ b/src/leap/bitmask/keymanager/openpgp.py @@ -1,6 +1,6 @@ # -*- coding: utf-8 -*- # openpgp.py -# Copyright (C) 2013-2016 LEAP +# Copyright (C) 2013-2017 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 @@ -14,9 +14,11 @@ # # You should have received a copy of the GNU General Public License # along with this program. If not, see . + """ Infrastructure for using OpenPGP keys in Key Manager. """ + import os import re import tempfile @@ -74,13 +76,6 @@ except ImportError: return bool(result.key) -logger = Logger() - - -# -# A temporary GPG keyring wrapped to provide OpenPGP functionality. -# - # This function will be used to call blocking GPG functions outside # of Twisted reactor and match the concurrent calls to the amount of CPU cores cpu_core_semaphore = defer.DeferredSemaphore(cpu_count()) @@ -91,16 +86,22 @@ def from_thread(func, *args, **kwargs): return cpu_core_semaphore.run(call) +log = Logger() + + # # The OpenPGP wrapper # class OpenPGPScheme(object): + """ A wrapper for OpenPGP keys management and use (encryption, decyption, signing and verification). """ + log = Logger() + # type used on the soledad documents KEY_TYPE = OpenPGPKey.__name__ ACTIVE_TYPE = KEY_TYPE + KEYMANAGER_ACTIVE_TYPE @@ -186,11 +187,11 @@ class OpenPGPScheme(object): name_real=address, name_email=address, name_comment='') - logger.info("About to generate keys... " - "This might take SOME time.") + self.log.info('About to generate keys... ' + 'This might take SOME time.') yield from_thread(gpg.gen_key, params) - logger.info("Keys for %s have been successfully " - "generated." % (address,)) + self.log.info('Keys for %s have been successfully ' + 'generated.' % (address,)) pubkeys = gpg.list_keys() # assert for new key characteristics @@ -509,8 +510,8 @@ class OpenPGPScheme(object): if len(docs) == 0: raise errors.KeyNotFound(key) elif len(docs) > 1: - logger.warn("There is more than one key for fingerprint %s" - % key.fingerprint) + self.log.warn('There is more than one key for fingerprint %s' + % key.fingerprint) has_deleted = False deferreds = [] @@ -559,7 +560,7 @@ class OpenPGPScheme(object): """ stderr = getattr(result, 'stderr', None) if stderr: - logger.debug("%s" % (stderr,)) + log.debug("%s" % (stderr,)) if getattr(result, 'ok', None) is not True: raise errors.GPGError( 'Failed to encrypt/decrypt: %s' % stderr) @@ -612,7 +613,7 @@ class OpenPGPScheme(object): self._assert_gpg_result_ok(result) defer.returnValue(result.data) except errors.GPGError as e: - logger.warn('Failed to encrypt: %s.' % str(e)) + self.log.warn('Failed to encrypt: %s.' % str(e)) raise errors.EncryptError() @defer.inlineCallbacks @@ -658,7 +659,7 @@ class OpenPGPScheme(object): defer.returnValue((result.data, sign_valid)) except errors.GPGError as e: - logger.warn('Failed to decrypt: %s.' % str(e)) + self.log.warn('Failed to decrypt: %s.' % str(e)) raise errors.DecryptError(str(e)) def is_encrypted(self, data): @@ -803,8 +804,8 @@ class OpenPGPScheme(object): :rtype: Deferred """ def log_key_doc(doc): - logger.error("\t%s: %s" % (doc.content[KEY_UIDS_KEY], - doc.content[KEY_FINGERPRINT_KEY])) + self.log.error("\t%s: %s" % (doc.content[KEY_UIDS_KEY], + doc.content[KEY_FINGERPRINT_KEY])) def cmp_key(d1, d2): return cmp(d1.content[KEY_REFRESHED_AT_KEY], @@ -833,8 +834,8 @@ class OpenPGPScheme(object): pass def log_active_doc(doc): - logger.error("\t%s: %s" % (doc.content[KEY_ADDRESS_KEY], - doc.content[KEY_FINGERPRINT_KEY])) + self.log.error("\t%s: %s" % (doc.content[KEY_ADDRESS_KEY], + doc.content[KEY_FINGERPRINT_KEY])) def cmp_active(d1, d2): # XXX: for private keys it will be nice to check which key is known @@ -857,9 +858,9 @@ class OpenPGPScheme(object): defer.returnValue(doc) def _repair_docs(self, doclist, cmp_func, log_func): - logger.error("BUG ---------------------------------------------------") - logger.error("There is more than one doc of type %s:" - % (doclist[0].content[KEY_TYPE_KEY],)) + self.log.error("BUG -------------------------------------------------") + self.log.error("There is more than one doc of type %s:" + % (doclist[0].content[KEY_TYPE_KEY],)) doclist.sort(cmp=cmp_func, reverse=True) log_func(doclist[0]) @@ -869,9 +870,8 @@ class OpenPGPScheme(object): d = self._soledad.delete_doc(doc) deferreds.append(d) - logger.error("") - logger.error(traceback.extract_stack()) - logger.error("BUG (please report above info) ------------------------") + self.log.error('Error repairing') + self.log.error("BUG (please report above info) ----------------------") d = defer.gatherResults(deferreds, consumeErrors=True) d.addCallback(lambda _: doclist[0]) return d diff --git a/src/leap/bitmask/keymanager/refresher.py b/src/leap/bitmask/keymanager/refresher.py index 694a537..d1ae9f8 100644 --- a/src/leap/bitmask/keymanager/refresher.py +++ b/src/leap/bitmask/keymanager/refresher.py @@ -28,18 +28,18 @@ from random import choice, randrange DEBUG_STOP_REFRESH = "Stop to refresh the key directory ..." DEBUG_START_REFRESH = "Start to refresh the key directory ..." -ERROR_UNEQUAL_FINGERPRINTS = "[WARNING] Your provider might be cheat " \ - "on you, and gave a wrong key back. " \ - "Fingerprints are unequal, old %s new %s " +ERROR_UNEQUAL_FINGERPRINTS = "[WARNING] Your provider *might* be cheating " \ + "on you, and given a wrong key back. " \ + "Fingerprints do not match: old-> %s, new-> %s " MIN_RANDOM_INTERVAL_RANGE = 4 * 60 # four minutes MAX_RANDOM_INTERVAL_RANGE = 6 * 60 # six minutes -logger = Logger() - class RandomRefreshPublicKey(object): + log = Logger() + def __init__(self, openpgp, keymanager): """ Initialize the RandomRefreshPublicKey. @@ -59,14 +59,14 @@ class RandomRefreshPublicKey(object): :rtype: A deferred. """ self._loop.start(self._get_random_interval_to_refresh(), False) - logger.debug(DEBUG_START_REFRESH) + self.log.debug(DEBUG_START_REFRESH) def stop(self): """ Stop the looping call with random interval. """ self._loop.stop() - logger.debug(DEBUG_STOP_REFRESH) + self.log.debug(DEBUG_STOP_REFRESH) @defer.inlineCallbacks def _get_random_key(self): @@ -110,7 +110,7 @@ class RandomRefreshPublicKey(object): fetch_key_with_fingerprint(old_key.fingerprint) if old_updated_key.fingerprint != old_key.fingerprint: - logger.error(ERROR_UNEQUAL_FINGERPRINTS % + self.log.error(ERROR_UNEQUAL_FINGERPRINTS % (old_key.fingerprint, old_updated_key.fingerprint)) defer.returnValue(None) diff --git a/src/leap/bitmask/keymanager/wrapper.py b/src/leap/bitmask/keymanager/wrapper.py index ef8e664..eb5074f 100644 --- a/src/leap/bitmask/keymanager/wrapper.py +++ b/src/leap/bitmask/keymanager/wrapper.py @@ -35,7 +35,6 @@ except ImportError: GNUPG_NG = False -logger = Logger() class TempGPGWrapper(object): @@ -43,6 +42,7 @@ class TempGPGWrapper(object): A context manager that wraps a temporary GPG keyring which only contains the keys given at object creation. """ + log = Logger() def __init__(self, keys=None, gpgbinary=None): """ @@ -160,6 +160,6 @@ class TempGPGWrapper(object): homedir = os.path.normpath(homedir).replace("\\", "/") homedir = str(homedir.replace("c:/", "c://")) if platform.system() == "Windows": - logger.error("BUG! Not erasing folder in Windows") + self.log.error("BUG! Not erasing folder in Windows") return shutil.rmtree(homedir) -- cgit v1.2.3