commit a3e522efd968686a32cbf715e4ac91f531c5deca parent ec6f4e9f1cafbeb3cd16cb053183f1dc654632b9 Author: ThomasV <thomasv@electrum.org> Date: Thu, 2 May 2019 15:33:29 +0200 Merge pull request #5296 from SomberNight/logging_20190328 use stdlib logging module instead of print_error Diffstat:
71 files changed, 792 insertions(+), 520 deletions(-)
diff --git a/electrum/__init__.py b/electrum/__init__.py @@ -1,5 +1,5 @@ from .version import ELECTRUM_VERSION -from .util import format_satoshis, print_msg, print_error, set_verbosity +from .util import format_satoshis from .wallet import Wallet from .storage import WalletStorage from .coinchooser import COIN_CHOOSERS diff --git a/electrum/address_synchronizer.py b/electrum/address_synchronizer.py @@ -29,12 +29,13 @@ from typing import TYPE_CHECKING, Dict, Optional, Set, Tuple from . import bitcoin from .bitcoin import COINBASE_MATURITY, TYPE_ADDRESS, TYPE_PUBKEY -from .util import PrintError, profiler, bfh, TxMinedInfo +from .util import profiler, bfh, TxMinedInfo from .transaction import Transaction, TxOutput from .synchronizer import Synchronizer from .verifier import SPV from .blockchain import hash_header from .i18n import _ +from .logging import Logger if TYPE_CHECKING: from .storage import WalletStorage @@ -54,7 +55,7 @@ class UnrelatedTransactionException(AddTransactionException): return _("Transaction is unrelated to this wallet.") -class AddressSynchronizer(PrintError): +class AddressSynchronizer(Logger): """ inherited by wallet """ @@ -63,6 +64,7 @@ class AddressSynchronizer(PrintError): self.storage = storage self.db = self.storage.db self.network = None # type: Network + Logger.__init__(self) # verifier (SPV) and synchronizer are started in start_network self.synchronizer = None # type: Synchronizer self.verifier = None # type: SPV @@ -307,7 +309,7 @@ class AddressSynchronizer(PrintError): self.db.remove_spent_outpoint(prevout_hash, prevout_n) with self.transaction_lock: - self.print_error("removing tx from history", tx_hash) + self.logger.info("removing tx from history", tx_hash) tx = self.db.remove_transaction(tx_hash) remove_from_spent_outpoints() self._remove_tx_from_local_history(tx_hash) @@ -455,7 +457,7 @@ class AddressSynchronizer(PrintError): h2.reverse() # fixme: this may happen if history is incomplete if balance not in [None, 0]: - self.print_error("Error: history not synchronized") + self.logger.info("Error: history not synchronized") return [] return h2 diff --git a/electrum/base_wizard.py b/electrum/base_wizard.py @@ -43,6 +43,7 @@ from .i18n import _ from .util import UserCancelled, InvalidPassword, WalletFileException from .simple_config import SimpleConfig from .plugin import Plugins +from .logging import Logger if TYPE_CHECKING: from .plugin import DeviceInfo @@ -65,10 +66,11 @@ class WizardStackItem(NamedTuple): storage_data: dict -class BaseWizard(object): +class BaseWizard(Logger): def __init__(self, config: SimpleConfig, plugins: Plugins): super(BaseWizard, self).__init__() + Logger.__init__(self) self.config = config self.plugins = plugins self.data = {} @@ -253,7 +255,7 @@ class BaseWizard(object): def failed_getting_device_infos(name, e): nonlocal debug_msg - devmgr.print_error(f'error getting device infos for {name}: {e}') + self.logger.info(f'error getting device infos for {name}: {e}') indented_error_msg = ' '.join([''] + str(e).splitlines(keepends=True)) debug_msg += f' {name}: (error getting device infos)\n{indented_error_msg}\n' @@ -261,7 +263,7 @@ class BaseWizard(object): try: scanned_devices = devmgr.scan_devices() except BaseException as e: - devmgr.print_error('error scanning devices: {}'.format(repr(e))) + self.logger.info('error scanning devices: {}'.format(repr(e))) debug_msg = ' {}:\n {}'.format(_('Error scanning devices'), e) else: for splugin in supported_plugins: @@ -280,7 +282,7 @@ class BaseWizard(object): device_infos = devmgr.unpaired_device_infos(None, plugin, devices=scanned_devices, include_failing_clients=True) except BaseException as e: - traceback.print_exc() + self.logger.exception('') failed_getting_device_infos(name, e) continue device_infos_failing = list(filter(lambda di: di.exception is not None, device_infos)) @@ -333,7 +335,7 @@ class BaseWizard(object): self.choose_hw_device(purpose, storage=storage) return except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.show_error(str(e)) self.choose_hw_device(purpose, storage=storage) return @@ -399,7 +401,7 @@ class BaseWizard(object): except ScriptTypeNotSupported: raise # this is handled in derivation_dialog except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.show_error(e) return d = { @@ -517,7 +519,7 @@ class BaseWizard(object): self.choose_hw_device() return except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.show_error(str(e)) return self.request_storage_encryption( diff --git a/electrum/bip32.py b/electrum/bip32.py @@ -5,13 +5,15 @@ import hashlib from typing import List, Tuple, NamedTuple, Union, Iterable -from .util import bfh, bh2u, BitcoinException, print_error +from .util import bfh, bh2u, BitcoinException from . import constants from . import ecc from .crypto import hash_160, hmac_oneshot from .bitcoin import rev_hex, int_to_hex, EncodeBase58Check, DecodeBase58Check +from .logging import get_logger +_logger = get_logger(__name__) BIP32_PRIME = 0x80000000 UINT32_MAX = (1 << 32) - 1 @@ -24,7 +26,7 @@ def protect_against_invalid_ecpoint(func): try: return func(*args[:-1], child_index=child_index) except ecc.InvalidECPointException: - print_error('bip32 protect_against_invalid_ecpoint: skipping index') + _logger.warning('bip32 protect_against_invalid_ecpoint: skipping index') child_index += 1 is_prime2 = child_index & BIP32_PRIME if is_prime != is_prime2: raise OverflowError() diff --git a/electrum/blockchain.py b/electrum/blockchain.py @@ -30,8 +30,11 @@ from .crypto import sha256d from . import constants from .util import bfh, bh2u from .simple_config import SimpleConfig +from .logging import get_logger, Logger +_logger = get_logger(__name__) + HEADER_SIZE = 80 # bytes MAX_TARGET = 0x00000000FFFF0000000000000000000000000000000000000000000000000000 @@ -96,7 +99,7 @@ def read_blockchains(config: 'SimpleConfig'): if best_chain.height() > constants.net.max_checkpoint(): header_after_cp = best_chain.read_header(constants.net.max_checkpoint()+1) if not header_after_cp or not best_chain.can_connect(header_after_cp, check_height=False): - util.print_error("[blockchain] deleting best chain. cannot connect header after last cp to last cp.") + _logger.info("[blockchain] deleting best chain. cannot connect header after last cp to last cp.") os.unlink(best_chain.path()) best_chain.update_size() # forks @@ -107,7 +110,7 @@ def read_blockchains(config: 'SimpleConfig'): l = sorted(l, key=lambda x: int(x.split('_')[1])) # sort by forkpoint def delete_chain(filename, reason): - util.print_error(f"[blockchain] deleting chain {filename}: {reason}") + _logger.info(f"[blockchain] deleting chain {filename}: {reason}") os.unlink(os.path.join(fdir, filename)) def instantiate_chain(filename): @@ -156,7 +159,7 @@ _CHAINWORK_CACHE = { } # type: Dict[str, int] -class Blockchain(util.PrintError): +class Blockchain(Logger): """ Manages blockchain headers and their verification """ @@ -168,6 +171,7 @@ class Blockchain(util.PrintError): # assert (parent is None) == (forkpoint == 0) if 0 < forkpoint <= constants.net.max_checkpoint(): raise Exception(f"cannot fork below max checkpoint. forkpoint: {forkpoint}") + Logger.__init__(self) self.config = config self.forkpoint = forkpoint # height of first header self.parent = parent @@ -368,7 +372,7 @@ class Blockchain(util.PrintError): return False if self.parent.get_chainwork() >= self.get_chainwork(): return False - self.print_error("swap", self.forkpoint, self.parent.forkpoint) + self.logger.info(f"swapping {self.forkpoint} {self.parent.forkpoint}") parent_branch_size = self.parent.height() - self.forkpoint + 1 forkpoint = self.forkpoint # type: Optional[int] parent = self.parent # type: Optional[Blockchain] @@ -570,7 +574,6 @@ class Blockchain(util.PrintError): return False height = header['block_height'] if check_height and self.height() != height - 1: - #self.print_error("cannot connect at height", height) return False if height == 0: return hash_header(header) == constants.net.GENESIS @@ -595,11 +598,10 @@ class Blockchain(util.PrintError): try: data = bfh(hexdata) self.verify_chunk(idx, data) - #self.print_error("validated chunk %d" % idx) self.save_chunk(idx, data) return True except BaseException as e: - self.print_error(f'verify_chunk idx {idx} failed: {repr(e)}') + self.logger.info(f'verify_chunk idx {idx} failed: {repr(e)}') return False def get_checkpoints(self): diff --git a/electrum/coinchooser.py b/electrum/coinchooser.py @@ -28,7 +28,8 @@ from typing import NamedTuple, List from .bitcoin import sha256, COIN, TYPE_ADDRESS, is_address from .transaction import Transaction, TxOutput -from .util import NotEnoughFunds, PrintError +from .util import NotEnoughFunds +from .logging import Logger # A simple deterministic PRNG. Used to deterministically shuffle a @@ -92,10 +93,13 @@ def strip_unneeded(bkts, sufficient_funds): raise Exception("keeping all buckets is still not enough") -class CoinChooserBase(PrintError): +class CoinChooserBase(Logger): enable_output_value_rounding = False + def __init__(self): + Logger.__init__(self) + def keys(self, coins): raise NotImplementedError @@ -187,9 +191,9 @@ class CoinChooserBase(PrintError): amounts = [amount for amount in amounts if amount >= dust_threshold] change = [TxOutput(TYPE_ADDRESS, addr, amount) for addr, amount in zip(change_addrs, amounts)] - self.print_error('change:', change) + self.logger.info(f'change: {change}') if dust: - self.print_error('not keeping dust', dust) + self.logger.info(f'not keeping dust {dust}') return change def make_tx(self, coins, inputs, outputs, change_addrs, fee_estimator, @@ -268,8 +272,8 @@ class CoinChooserBase(PrintError): change = self.change_outputs(tx, change_addrs, fee, dust_threshold) tx.add_outputs(change) - self.print_error("using %d inputs" % len(tx.inputs())) - self.print_error("using buckets:", [bucket.desc for bucket in buckets]) + self.logger.info(f"using {len(tx.inputs())} inputs") + self.logger.info(f"using buckets: {[bucket.desc for bucket in buckets]}") return tx @@ -357,8 +361,8 @@ class CoinChooserRandom(CoinChooserBase): candidates = self.bucket_candidates_prefer_confirmed(buckets, sufficient_funds) penalties = [penalty_func(cand) for cand in candidates] winner = candidates[penalties.index(min(penalties))] - self.print_error("Bucket sets:", len(buckets)) - self.print_error("Winning penalty:", min(penalties)) + self.logger.info(f"Bucket sets: {len(buckets)}") + self.logger.info(f"Winning penalty: {min(penalties)}") return winner class CoinChooserPrivacy(CoinChooserRandom): diff --git a/electrum/commands.py b/electrum/commands.py @@ -35,7 +35,7 @@ from decimal import Decimal from typing import Optional, TYPE_CHECKING from .import util, ecc -from .util import bfh, bh2u, format_satoshis, json_decode, print_error, json_encode, is_hash256_str +from .util import bfh, bh2u, format_satoshis, json_decode, json_encode, is_hash256_str from . import bitcoin from .bitcoin import is_address, hash_160, COIN, TYPE_ADDRESS from . import bip32 @@ -927,15 +927,14 @@ def add_network_options(parser): def add_global_options(parser): group = parser.add_argument_group('global options') - # const is for when no argument is given to verbosity - # default is for when the flag is missing - group.add_argument("-v", dest="verbosity", help="Set verbosity filter", default='', const='*', nargs='?') + group.add_argument("-v", dest="verbosity", help="Set verbosity filter", default='') group.add_argument("-D", "--dir", dest="electrum_path", help="electrum directory") group.add_argument("-P", "--portable", action="store_true", dest="portable", default=False, help="Use local 'electrum_data' directory") group.add_argument("-w", "--wallet", dest="wallet_path", help="wallet path") group.add_argument("--testnet", action="store_true", dest="testnet", default=False, help="Use Testnet") group.add_argument("--regtest", action="store_true", dest="regtest", default=False, help="Use Regtest") group.add_argument("--simnet", action="store_true", dest="simnet", default=False, help="Use Simnet") + group.add_argument("--disablefilelogging", action="store_true", dest="disablefilelogging", default=False, help="Do not log to file") def get_parser(): # create main parser diff --git a/electrum/contacts.py b/electrum/contacts.py @@ -27,12 +27,14 @@ from dns.exception import DNSException from . import bitcoin from . import dnssec -from .util import export_meta, import_meta, print_error, to_string +from .util import export_meta, import_meta, to_string +from .logging import Logger -class Contacts(dict): +class Contacts(dict, Logger): def __init__(self, storage): + Logger.__init__(self) self.storage = storage d = self.storage.get('contacts', {}) try: @@ -99,7 +101,7 @@ class Contacts(dict): try: records, validated = dnssec.query(url, dns.rdatatype.TXT) except DNSException as e: - print_error(f'Error resolving openalias: {repr(e)}') + self.logger.info(f'Error resolving openalias: {repr(e)}') return None prefix = 'btc' for record in records: diff --git a/electrum/daemon.py b/electrum/daemon.py @@ -36,7 +36,7 @@ import jsonrpclib from .jsonrpc import VerifyingJSONRPCServer from .version import ELECTRUM_VERSION from .network import Network -from .util import (json_decode, DaemonThread, print_error, to_string, +from .util import (json_decode, DaemonThread, to_string, create_and_start_event_loop, profiler, standardize_path) from .wallet import Wallet, Abstract_Wallet from .storage import WalletStorage @@ -44,6 +44,10 @@ from .commands import known_commands, Commands from .simple_config import SimpleConfig from .exchange_rate import FxThread from .plugin import run_hook +from .logging import get_logger + + +_logger = get_logger(__name__) def get_lockfile(config: SimpleConfig): @@ -92,7 +96,7 @@ def get_server(config: SimpleConfig) -> Optional[jsonrpclib.Server]: server.ping() return server except Exception as e: - print_error(f"failed to connect to JSON-RPC server: {e}") + _logger.info(f"failed to connect to JSON-RPC server: {e}") if not create_time or create_time < time.time() - 1.0: return None # Sleep a bit and try again; it might have just been started @@ -114,8 +118,7 @@ def get_rpc_credentials(config: SimpleConfig) -> Tuple[str, str]: config.set_key('rpcuser', rpc_user) config.set_key('rpcpassword', rpc_password, save=True) elif rpc_password == '': - from .util import print_stderr - print_stderr('WARNING: RPC authentication is disabled.') + _logger.warning('RPC authentication is disabled.') return rpc_user, rpc_password @@ -154,7 +157,7 @@ class Daemon(DaemonThread): server = VerifyingJSONRPCServer((host, port), logRequests=False, rpc_user=rpc_user, rpc_password=rpc_password) except Exception as e: - self.print_error('Warning: cannot initialize RPC server on host', host, e) + self.logger.error(f'cannot initialize RPC server on host {host}: {repr(e)}') self.server = None os.close(fd) return @@ -323,7 +326,7 @@ class Daemon(DaemonThread): for k, wallet in self.wallets.items(): wallet.stop_threads() if self.network: - self.print_error("shutting down network") + self.logger.info("shutting down network") self.network.stop() # stop event loop self.asyncio_loop.call_soon_threadsafe(self._stop_loop.set_result, 1) @@ -333,7 +336,7 @@ class Daemon(DaemonThread): def stop(self): if self.gui: self.gui.stop() - self.print_error("stopping, removing lockfile") + self.logger.info("stopping, removing lockfile") remove_lockfile(get_lockfile(self.config)) DaemonThread.stop(self) @@ -347,5 +350,5 @@ class Daemon(DaemonThread): try: self.gui.main() except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') # app will exit now diff --git a/electrum/dnssec.py b/electrum/dnssec.py @@ -173,7 +173,10 @@ dns.dnssec.validate = dns.dnssec._validate -from .util import print_error +from .logging import get_logger + + +_logger = get_logger(__name__) # hard-coded trust anchors (root KSKs) @@ -262,8 +265,7 @@ def query(url, rtype): out = get_and_validate(ns, url, rtype) validated = True except BaseException as e: - #traceback.print_exc(file=sys.stderr) - print_error("DNSSEC error:", str(e)) + _logger.info(f"DNSSEC error: {str(e)}") resolver = dns.resolver.get_default_resolver() out = resolver.query(url, rtype) validated = False diff --git a/electrum/ecc.py b/electrum/ecc.py @@ -33,13 +33,15 @@ from ecdsa.curves import SECP256k1 from ecdsa.ellipticcurve import Point from ecdsa.util import string_to_number, number_to_string -from .util import bfh, bh2u, assert_bytes, print_error, to_bytes, InvalidPassword, profiler +from .util import bfh, bh2u, assert_bytes, to_bytes, InvalidPassword, profiler from .crypto import (sha256d, aes_encrypt_with_iv, aes_decrypt_with_iv, hmac_oneshot) from .ecc_fast import do_monkey_patching_of_python_ecdsa_internals_with_libsecp256k1 from . import msqr from . import constants +from .logging import get_logger +_logger = get_logger(__name__) do_monkey_patching_of_python_ecdsa_internals_with_libsecp256k1() CURVE_ORDER = SECP256k1.order @@ -332,7 +334,7 @@ def verify_message_with_address(address: str, sig65: bytes, message: bytes, *, n public_key.verify_message_hash(sig65[1:], h) return True except Exception as e: - print_error(f"Verification error: {repr(e)}") + _logger.info(f"Verification error: {repr(e)}") return False diff --git a/electrum/ecc_fast.py b/electrum/ecc_fast.py @@ -12,7 +12,10 @@ from ctypes import ( import ecdsa -from .util import print_stderr, print_error +from .logging import get_logger + + +_logger = get_logger(__name__) SECP256K1_FLAGS_TYPE_MASK = ((1 << 8) - 1) @@ -44,7 +47,7 @@ def load_library(): secp256k1 = ctypes.cdll.LoadLibrary(library_path) if not secp256k1: - print_stderr('[ecc] warning: libsecp256k1 library failed to load') + _logger.warning('libsecp256k1 library failed to load') return None try: @@ -86,11 +89,10 @@ def load_library(): if r: return secp256k1 else: - print_stderr('[ecc] warning: secp256k1_context_randomize failed') + _logger.warning('secp256k1_context_randomize failed') return None except (OSError, AttributeError): - #traceback.print_exc(file=sys.stderr) - print_stderr('[ecc] warning: libsecp256k1 library was found and loaded but there was an error when using it') + _logger.warning('libsecp256k1 library was found and loaded but there was an error when using it') return None @@ -184,9 +186,9 @@ def _prepare_monkey_patching_of_python_ecdsa_internals_with_libsecp256k1(): def do_monkey_patching_of_python_ecdsa_internals_with_libsecp256k1(): if not _libsecp256k1: - # FIXME print_error will always print as 'verbosity' is not yet initialised - print_error('[ecc] info: libsecp256k1 library not available, falling back to python-ecdsa. ' - 'This means signing operations will be slower.') + # FIXME logging 'verbosity' is not yet initialised + _logger.info('libsecp256k1 library not available, falling back to python-ecdsa. ' + 'This means signing operations will be slower.') return if not _patched_functions.prepared_to_patch: raise Exception("can't patch python-ecdsa without preparations") @@ -218,6 +220,5 @@ try: _libsecp256k1 = load_library() except: _libsecp256k1 = None - #traceback.print_exc(file=sys.stderr) _prepare_monkey_patching_of_python_ecdsa_internals_with_libsecp256k1() diff --git a/electrum/exchange_rate.py b/electrum/exchange_rate.py @@ -8,17 +8,17 @@ import time import csv import decimal from decimal import Decimal -import traceback from typing import Sequence, Optional from aiorpcx.curio import timeout_after, TaskTimeout, TaskGroup from .bitcoin import COIN from .i18n import _ -from .util import (PrintError, ThreadJob, make_dir, log_exceptions, +from .util import (ThreadJob, make_dir, log_exceptions, make_aiohttp_session, resource_path) from .network import Network from .simple_config import SimpleConfig +from .logging import Logger DEFAULT_ENABLED = False @@ -35,9 +35,10 @@ CCY_PRECISIONS = {'BHD': 3, 'BIF': 0, 'BYR': 0, 'CLF': 4, 'CLP': 0, 'VUV': 0, 'XAF': 0, 'XAU': 4, 'XOF': 0, 'XPF': 0} -class ExchangeBase(PrintError): +class ExchangeBase(Logger): def __init__(self, on_quotes, on_history): + Logger.__init__(self) self.history = {} self.quotes = {} self.on_quotes = on_quotes @@ -74,12 +75,11 @@ class ExchangeBase(PrintError): async def update_safe(self, ccy): try: - self.print_error("getting fx quotes for", ccy) + self.logger.info(f"getting fx quotes for {ccy}") self.quotes = await self.get_rates(ccy) - self.print_error("received fx quotes") + self.logger.info("received fx quotes") except BaseException as e: - self.print_error("failed fx quotes:", repr(e)) - # traceback.print_exc() + self.logger.info(f"failed fx quotes: {repr(e)}") self.quotes = {} self.on_quotes() @@ -103,12 +103,11 @@ class ExchangeBase(PrintError): @log_exceptions async def get_historical_rates_safe(self, ccy, cache_dir): try: - self.print_error(f"requesting fx history for {ccy}") + self.logger.info(f"requesting fx history for {ccy}") h = await self.request_history(ccy) - self.print_error(f"received fx history for {ccy}") + self.logger.info(f"received fx history for {ccy}") except BaseException as e: - self.print_error(f"failed fx history: {repr(e)}") - #traceback.print_exc() + self.logger.info(f"failed fx history: {repr(e)}") return filename = os.path.join(cache_dir, self.name() + '_' + ccy) with open(filename, 'w', encoding='utf-8') as f: @@ -458,6 +457,7 @@ def get_exchanges_by_ccy(history=True): class FxThread(ThreadJob): def __init__(self, config: SimpleConfig, network: Network): + ThreadJob.__init__(self) self.config = config self.network = network if self.network: @@ -560,7 +560,7 @@ class FxThread(ThreadJob): def set_exchange(self, name): class_ = globals().get(name) or globals().get(DEFAULT_EXCHANGE) - self.print_error("using exchange", name) + self.logger.info(f"using exchange {name}") if self.config_exchange() != name: self.config.set_key('use_exchange', name, True) self.exchange = class_(self.on_quotes, self.on_history) diff --git a/electrum/gui/kivy/uix/dialogs/crash_reporter.py b/electrum/gui/kivy/uix/dialogs/crash_reporter.py @@ -13,6 +13,7 @@ from kivy.utils import platform from electrum.gui.kivy.i18n import _ from electrum.base_crash_reporter import BaseCrashReporter +from electrum.logging import Logger Builder.load_string(''' @@ -172,9 +173,10 @@ class CrashReportDetails(Factory.Popup): print(text) -class ExceptionHook(base.ExceptionHandler): +class ExceptionHook(base.ExceptionHandler, Logger): def __init__(self, main_window): - super().__init__() + base.ExceptionHandler.__init__(self) + Logger.__init__(self) self.main_window = main_window if not main_window.electrum_config.get(BaseCrashReporter.config_key, default=True): return @@ -185,6 +187,7 @@ class ExceptionHook(base.ExceptionHandler): def handle_exception(self, _inst): exc_info = sys.exc_info() + self.logger.error('exception caught by crash reporter', exc_info=exc_info) # Check if this is an exception from within the exception handler: import traceback for item in traceback.extract_tb(exc_info[2]): diff --git a/electrum/gui/qt/__init__.py b/electrum/gui/qt/__init__.py @@ -45,9 +45,10 @@ import PyQt5.QtCore as QtCore from electrum.i18n import _, set_language from electrum.plugin import run_hook from electrum.base_wizard import GoBack -from electrum.util import (UserCancelled, PrintError, profiler, +from electrum.util import (UserCancelled, profiler, WalletFileException, BitcoinException, get_new_wallet_name) from electrum.wallet import Wallet, Abstract_Wallet +from electrum.logging import Logger from .installwizard import InstallWizard, WalletAlreadyOpenInMemory @@ -78,11 +79,12 @@ class QNetworkUpdatedSignalObject(QObject): network_updated_signal = pyqtSignal(str, object) -class ElectrumGui(PrintError): +class ElectrumGui(Logger): @profiler def __init__(self, config, daemon, plugins): set_language(config.get('language', get_default_language())) + Logger.__init__(self) # Uncomment this call to verify objects are being properly # GC-ed when windows are closed #network.add_jobs([DebugMem([Abstract_Wallet, SPV, Synchronizer, @@ -129,7 +131,7 @@ class ElectrumGui(PrintError): self.app.setStyleSheet(qdarkstyle.load_stylesheet_pyqt5()) except BaseException as e: use_dark_theme = False - self.print_error('Error setting dark theme: {}'.format(repr(e))) + self.logger.warning(f'Error setting dark theme: {repr(e)}') # Even if we ourselves don't set the dark theme, # the OS/window manager/etc might set *a dark theme*. # Hence, try to choose colors accordingly: @@ -221,7 +223,7 @@ class ElectrumGui(PrintError): try: wallet = self.daemon.load_wallet(path, None) except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') QMessageBox.warning(None, _('Error'), _('Cannot load wallet') + ' (1):\n' + str(e)) # if app is starting, still let wizard to appear @@ -239,7 +241,7 @@ class ElectrumGui(PrintError): else: window = self._create_window_for_wallet(wallet) except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') QMessageBox.warning(None, _('Error'), _('Cannot create window for wallet') + ':\n' + str(e)) if app_is_starting: @@ -271,7 +273,7 @@ class ElectrumGui(PrintError): except WalletAlreadyOpenInMemory as e: return e.wallet except (WalletFileException, BitcoinException) as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') QMessageBox.warning(None, _('Error'), _('Cannot load wallet') + ' (2):\n' + str(e)) return @@ -311,7 +313,7 @@ class ElectrumGui(PrintError): except GoBack: return except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') return self.timer.start() self.config.open_last_wallet() @@ -346,5 +348,5 @@ class ElectrumGui(PrintError): # on some platforms the exec_ call may not return, so use clean_up() def stop(self): - self.print_error('closing GUI') + self.logger.info('closing GUI') self.app.quit() diff --git a/electrum/gui/qt/exception_window.py b/electrum/gui/qt/exception_window.py @@ -32,10 +32,11 @@ from PyQt5.QtWidgets import (QWidget, QLabel, QPushButton, QTextEdit, from electrum.i18n import _ from electrum.base_crash_reporter import BaseCrashReporter +from electrum.logging import Logger from .util import MessageBoxMixin, read_QIcon -class Exception_Window(BaseCrashReporter, QWidget, MessageBoxMixin): +class Exception_Window(BaseCrashReporter, QWidget, MessageBoxMixin, Logger): _active_window = None def __init__(self, main_window, exctype, value, tb): @@ -46,6 +47,8 @@ class Exception_Window(BaseCrashReporter, QWidget, MessageBoxMixin): self.setWindowTitle('Electrum - ' + _('An Error Occurred')) self.setMinimumSize(600, 300) + Logger.__init__(self) + main_box = QVBoxLayout() heading = QLabel('<h2>' + BaseCrashReporter.CRASH_TITLE + '</h2>') @@ -95,7 +98,7 @@ class Exception_Window(BaseCrashReporter, QWidget, MessageBoxMixin): proxy = self.main_window.network.proxy response = BaseCrashReporter.send_report(self, self.main_window.network.asyncio_loop, proxy) except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('There was a problem with the automatic reporting') self.main_window.show_critical(_('There was a problem with the automatic reporting:') + '\n' + str(e) + '\n' + _("Please report this issue manually.")) @@ -105,7 +108,6 @@ class Exception_Window(BaseCrashReporter, QWidget, MessageBoxMixin): def on_close(self): Exception_Window._active_window = None - sys.__excepthook__(*self.exc_args) self.close() def show_never(self): @@ -131,16 +133,18 @@ def _show_window(*args): Exception_Window._active_window = Exception_Window(*args) -class Exception_Hook(QObject): +class Exception_Hook(QObject, Logger): _report_exception = QtCore.pyqtSignal(object, object, object, object) def __init__(self, main_window, *args, **kwargs): - super(Exception_Hook, self).__init__(*args, **kwargs) + QObject.__init__(self, *args, **kwargs) + Logger.__init__(self) if not main_window.config.get(BaseCrashReporter.config_key, default=True): return self.main_window = main_window sys.excepthook = self.handler self._report_exception.connect(_show_window) - def handler(self, *args): - self._report_exception.emit(self.main_window, *args) + def handler(self, *exc_info): + self.logger.error('exception caught by crash reporter', exc_info=exc_info) + self._report_exception.emit(self.main_window, *exc_info) diff --git a/electrum/gui/qt/history_list.py b/electrum/gui/qt/history_list.py @@ -41,8 +41,9 @@ from PyQt5.QtWidgets import (QMenu, QHeaderView, QLabel, QMessageBox, from electrum.address_synchronizer import TX_HEIGHT_LOCAL from electrum.i18n import _ -from electrum.util import (block_explorer_URL, profiler, print_error, TxMinedInfo, - OrderedDictWithIndex, PrintError, timestamp_to_datetime) +from electrum.util import (block_explorer_URL, profiler, TxMinedInfo, + OrderedDictWithIndex, timestamp_to_datetime) +from electrum.logging import get_logger, Logger from .util import (read_QIcon, MONOSPACE_FONT, Buttons, CancelButton, OkButton, filename_field, MyTreeView, AcceptFileDragDrop, WindowModalDialog, @@ -51,10 +52,14 @@ from .util import (read_QIcon, MONOSPACE_FONT, Buttons, CancelButton, OkButton, if TYPE_CHECKING: from electrum.wallet import Abstract_Wallet + +_logger = get_logger(__name__) + + try: from electrum.plot import plot_history, NothingToPlotException except: - print_error("qt/history_list: could not import electrum.plot. This feature needs matplotlib to be installed.") + _logger.info("could not import electrum.plot. This feature needs matplotlib to be installed.") plot_history = None # note: this list needs to be kept in sync with another in kivy @@ -97,10 +102,11 @@ class HistorySortModel(QSortFilterProxyModel): except: return False -class HistoryModel(QAbstractItemModel, PrintError): +class HistoryModel(QAbstractItemModel, Logger): def __init__(self, parent): - super().__init__(parent) + QAbstractItemModel.__init__(self, parent) + Logger.__init__(self) self.parent = parent self.view = None # type: HistoryList self.transactions = OrderedDictWithIndex() @@ -224,7 +230,7 @@ class HistoryModel(QAbstractItemModel, PrintError): @profiler def refresh(self, reason: str): - self.print_error(f"refreshing... reason: {reason}") + self.logger.info(f"refreshing... reason: {reason}") assert self.parent.gui_thread == threading.current_thread(), 'must be called from GUI thread' assert self.view, 'view not set' selected = self.view.selectionModel().currentIndex() diff --git a/electrum/gui/qt/installwizard.py b/electrum/gui/qt/installwizard.py @@ -116,8 +116,8 @@ class InstallWizard(QDialog, MessageBoxMixin, BaseWizard): accept_signal = pyqtSignal() def __init__(self, config, app, plugins): - BaseWizard.__init__(self, config, plugins) QDialog.__init__(self, None) + BaseWizard.__init__(self, config, plugins) self.setWindowTitle('Electrum - ' + _('Install Wizard')) self.app = app self.config = config @@ -209,7 +209,7 @@ class InstallWizard(QDialog, MessageBoxMixin, BaseWizard): self.temp_storage = WalletStorage(path, manual_upgrades=True) self.next_button.setEnabled(True) except BaseException: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.temp_storage = None self.next_button.setEnabled(False) user_needs_to_enter_password = False @@ -266,7 +266,7 @@ class InstallWizard(QDialog, MessageBoxMixin, BaseWizard): QMessageBox.information(None, _('Error'), str(e)) continue except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') QMessageBox.information(None, _('Error'), str(e)) raise UserCancelled() elif self.temp_storage.is_encrypted_with_hw_device(): @@ -280,7 +280,7 @@ class InstallWizard(QDialog, MessageBoxMixin, BaseWizard): self.reset_stack() return self.select_storage(path, get_wallet_from_daemon) except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') QMessageBox.information(None, _('Error'), str(e)) raise UserCancelled() if self.temp_storage.is_past_initial_decryption(): @@ -337,7 +337,7 @@ class InstallWizard(QDialog, MessageBoxMixin, BaseWizard): def on_error(self, exc_info): if not isinstance(exc_info[1], UserCancelled): - traceback.print_exception(*exc_info) + self.logger.error("on_error", exc_info=exc_info) self.show_error(str(exc_info[1])) def set_icon(self, filename): diff --git a/electrum/gui/qt/main_window.py b/electrum/gui/qt/main_window.py @@ -54,7 +54,7 @@ from electrum.bitcoin import COIN, is_address, TYPE_ADDRESS from electrum.plugin import run_hook from electrum.i18n import _ from electrum.util import (format_time, format_satoshis, format_fee_satoshis, - format_satoshis_plain, NotEnoughFunds, PrintError, + format_satoshis_plain, NotEnoughFunds, UserCancelled, NoDynamicFeeEstimates, profiler, export_meta, import_meta, bh2u, bfh, InvalidPassword, base_units, base_units_list, base_unit_name_to_decimal_point, @@ -69,6 +69,7 @@ from electrum.version import ELECTRUM_VERSION from electrum.network import Network, TxBroadcastError, BestEffortRequestFailed from electrum.exchange_rate import FxThread from electrum.simple_config import SimpleConfig +from electrum.logging import Logger from .exception_window import Exception_Hook from .amountedit import AmountEdit, BTCAmountEdit, MyLineEdit, FeerateEdit @@ -110,7 +111,7 @@ class StatusBarButton(QPushButton): from electrum.paymentrequest import PR_PAID -class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): +class ElectrumWindow(QMainWindow, MessageBoxMixin, Logger): payment_request_ok_signal = pyqtSignal() payment_request_error_signal = pyqtSignal() @@ -147,6 +148,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): self.require_fee_update = False self.tl_windows = [] self.tx_external_keypairs = {} + Logger.__init__(self) self.tx_notification_queue = queue.Queue() self.tx_notification_last_time = 0 @@ -320,8 +322,8 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): return self.top_level_window_recurse(override, test_func) def diagnostic_name(self): - return "%s/%s" % (PrintError.diagnostic_name(self), - self.wallet.basename() if self.wallet else "None") + #return '{}:{}'.format(self.__class__.__name__, self.wallet.diagnostic_name()) + return self.wallet.diagnostic_name() def is_hidden(self): return self.isMinimized() or self.isHidden() @@ -344,7 +346,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): self.show_error(str(e)) else: try: - traceback.print_exception(*exc_info) + self.logger.error("on_error", exc_info=exc_info) except OSError: pass # see #4418 self.show_error(str(e)) @@ -369,7 +371,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): # Handle in GUI thread self.network_signal.emit(event, args) else: - self.print_error("unexpected network message:", event, args) + self.logger.info(f"unexpected network message: {event} {args}") def on_network_qt(self, event, args=None): # Handle a network message in the GUI thread @@ -391,7 +393,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): self.require_fee_update = True self.history_model.on_fee_histogram() else: - self.print_error("unexpected network_qt signal:", event, args) + self.logger.info(f"unexpected network_qt signal: {event} {args}") def fetch_alias(self): self.alias_info = None @@ -407,7 +409,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): def close_wallet(self): if self.wallet: - self.print_error('close_wallet', self.wallet.storage.path) + self.logger.info(f'close_wallet {self.wallet.storage.path}') run_hook('close_wallet', self.wallet) @profiler @@ -444,7 +446,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): assert screen.contains(QRect(*winpos)) self.setGeometry(*winpos) except: - self.print_error("using default geometry") + self.logger.info("using default geometry") self.setGeometry(100, 100, 840, 400) def watching_only_changed(self): @@ -683,7 +685,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): if self.tx_notification_last_time + rate_limit > now: return self.tx_notification_last_time = now - self.print_error("Notifying GUI about new transactions") + self.logger.info("Notifying GUI about new transactions") txns = [] while True: try: @@ -1040,7 +1042,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): try: self.wallet.add_payment_request(req, self.config) except Exception as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('Error adding payment request') self.show_error(_('Error adding payment request') + ':\n' + str(e)) else: self.sign_payment_request(addr) @@ -1447,7 +1449,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): pass return except BaseException: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') return size = tx.estimated_size() @@ -1636,7 +1638,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): self.show_error(str(e)) raise except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') self.show_message(str(e)) return @@ -1745,7 +1747,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): coro = pr.send_payment_and_receive_paymentack(str(tx), refund_address) fut = asyncio.run_coroutine_threadsafe(coro, self.network.asyncio_loop) ack_status, ack_msg = fut.result(timeout=20) - self.print_error(f"Payment ACK: {ack_status}. Ack message: {ack_msg}") + self.logger.info(f"Payment ACK: {ack_status}. Ack message: {ack_msg}") return status, msg # Capture current TL window; override might be removed on return @@ -2123,7 +2125,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): except UserCancelled: return except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.show_error(str(e)) return old_password = hw_dev_pw if self.wallet.has_password() else None @@ -2141,7 +2143,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): self.show_error(str(e)) return except BaseException: - traceback.print_exc(file=sys.stdout) + self.logger.exception('Failed to update password') self.show_error(_('Failed to update password')) return msg = _('Password was updated successfully') if self.wallet.has_password() else _('Password is disabled, this wallet is not protected') @@ -2279,7 +2281,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): try: pk, redeem_script = self.wallet.export_private_key(address, password) except Exception as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') self.show_message(str(e)) return xtype = bitcoin.deserialize_privkey(pk)[0] @@ -2415,7 +2417,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): try: public_key = ecc.ECPubkey(bfh(pubkey_e.text())) except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('Invalid Public key') self.show_warning(_('Invalid Public key')) return encrypted = public_key.encrypt_message(message) @@ -2725,7 +2727,6 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): try: coins, keypairs = sweep_preparations(get_pk(), self.network) except Exception as e: # FIXME too broad... - #traceback.print_exc(file=sys.stderr) self.show_message(str(e)) return self.do_clear() @@ -3299,8 +3300,7 @@ class ElectrumWindow(QMainWindow, MessageBoxMixin, PrintError): msg += '\n\n' + _('Requires') + ':\n' + '\n'.join(map(lambda x: x[1], descr.get('requires'))) grid.addWidget(HelpButton(msg), i, 2) except Exception: - self.print_msg("error: cannot display plugin", name) - traceback.print_exc(file=sys.stdout) + self.logger.exception(f"cannot display plugin {name}") grid.setRowStretch(len(plugins.descriptions.values()), 1) vbox.addLayout(Buttons(CloseButton(d))) d.exec_() diff --git a/electrum/gui/qt/network_dialog.py b/electrum/gui/qt/network_dialog.py @@ -34,12 +34,15 @@ from PyQt5.QtWidgets import (QTreeWidget, QTreeWidgetItem, QMenu, QGridLayout, Q from electrum.i18n import _ from electrum import constants, blockchain -from electrum.util import print_error from electrum.interface import serialize_server, deserialize_server from electrum.network import Network +from electrum.logging import get_logger from .util import Buttons, CloseButton, HelpButton, read_QIcon + +_logger = get_logger(__name__) + protocol_names = ['TCP', 'SSL'] protocol_letters = 'ts' @@ -491,7 +494,7 @@ class NetworkChoiceLayout(object): else: socks5_mode_index = self.proxy_mode.findText('SOCKS5') if socks5_mode_index == -1: - print_error("[network_dialog] can't find proxy_mode 'SOCKS5'") + _logger.info("can't find proxy_mode 'SOCKS5'") return self.proxy_mode.setCurrentIndex(socks5_mode_index) self.proxy_host.setText("127.0.0.1") diff --git a/electrum/gui/qt/paytoedit.py b/electrum/gui/qt/paytoedit.py @@ -29,9 +29,10 @@ from decimal import Decimal from PyQt5.QtGui import QFontMetrics from electrum import bitcoin -from electrum.util import bfh, PrintError +from electrum.util import bfh from electrum.transaction import TxOutput, push_script from electrum.bitcoin import opcodes +from electrum.logging import Logger from .qrtextedit import ScanQRTextEdit from .completion_text_edit import CompletionTextEdit @@ -43,11 +44,12 @@ frozen_style = "QWidget { background-color:none; border:none;}" normal_style = "QPlainTextEdit { }" -class PayToEdit(CompletionTextEdit, ScanQRTextEdit, PrintError): +class PayToEdit(CompletionTextEdit, ScanQRTextEdit, Logger): def __init__(self, win): CompletionTextEdit.__init__(self) ScanQRTextEdit.__init__(self) + Logger.__init__(self) self.win = win self.amount_edit = win.amount_e self.document().contentsChanged.connect(self.update_size) @@ -226,7 +228,7 @@ class PayToEdit(CompletionTextEdit, ScanQRTextEdit, PrintError): try: data = self.win.contacts.resolve(key) except Exception as e: - self.print_error(f'error resolving address/alias: {repr(e)}') + self.logger.info(f'error resolving address/alias: {repr(e)}') return if not data: return diff --git a/electrum/gui/qt/transaction_dialog.py b/electrum/gui/qt/transaction_dialog.py @@ -42,6 +42,7 @@ from electrum.plugin import run_hook from electrum import simple_config from electrum.util import bfh from electrum.transaction import SerializationError, Transaction +from electrum.logging import get_logger from .util import (MessageBoxMixin, read_QIcon, Buttons, CopyButton, MONOSPACE_FONT, ColorScheme, ButtonsLineEdit) @@ -51,6 +52,7 @@ SAVE_BUTTON_ENABLED_TOOLTIP = _("Save transaction offline") SAVE_BUTTON_DISABLED_TOOLTIP = _("Please sign this transaction in order to save it") +_logger = get_logger(__name__) dialogs = [] # Otherwise python randomly garbage collects the dialogs... @@ -58,7 +60,7 @@ def show_transaction(tx, parent, desc=None, prompt_if_unsaved=False): try: d = TxDialog(tx, parent, desc, prompt_if_unsaved) except SerializationError as e: - traceback.print_exc(file=sys.stderr) + _logger.exception('unable to deserialize the transaction') parent.show_critical(_("Electrum was unable to deserialize the transaction:") + "\n" + str(e)) else: dialogs.append(d) diff --git a/electrum/gui/qt/update_checker.py b/electrum/gui/qt/update_checker.py @@ -14,10 +14,11 @@ from electrum import version from electrum import constants from electrum import ecc from electrum.i18n import _ -from electrum.util import PrintError, make_aiohttp_session +from electrum.util import make_aiohttp_session +from electrum.logging import Logger -class UpdateCheck(QWidget, PrintError): +class UpdateCheck(QWidget, Logger): url = "https://electrum.org/version" download_url = "https://electrum.org/#download" @@ -92,12 +93,13 @@ class UpdateCheck(QWidget, PrintError): self.detail_label.setText(_("Please wait while Electrum checks for available updates.")) -class UpdateCheckThread(QThread, PrintError): +class UpdateCheckThread(QThread, Logger): checked = pyqtSignal(object) failed = pyqtSignal() def __init__(self, main_window): - super().__init__() + QThread.__init__(self) + Logger.__init__(self) self.main_window = main_window async def get_update_info(self): @@ -120,7 +122,7 @@ class UpdateCheckThread(QThread, PrintError): msg = version_num.encode('utf-8') if ecc.verify_message_with_address(address=address, sig65=sig, message=msg, net=constants.BitcoinMainnet): - self.print_error(f"valid sig for version announcement '{version_num}' from address '{address}'") + self.logger.info(f"valid sig for version announcement '{version_num}' from address '{address}'") break else: raise Exception('no valid signature for version announcement') @@ -134,8 +136,7 @@ class UpdateCheckThread(QThread, PrintError): try: update_info = asyncio.run_coroutine_threadsafe(self.get_update_info(), network.asyncio_loop).result() except Exception as e: - #self.print_error(traceback.format_exc()) - self.print_error(f"got exception: '{repr(e)}'") + self.logger.info(f"got exception: '{repr(e)}'") self.failed.emit() else: self.checked.emit(update_info) diff --git a/electrum/gui/stdio.py b/electrum/gui/stdio.py @@ -1,12 +1,14 @@ from decimal import Decimal import getpass import datetime +import logging from electrum import WalletStorage, Wallet -from electrum.util import format_satoshis, set_verbosity +from electrum.util import format_satoshis from electrum.bitcoin import is_address, COIN, TYPE_ADDRESS from electrum.transaction import TxOutput from electrum.network import TxBroadcastError, BestEffortRequestFailed +from electrum.logging import console_stderr_handler _ = lambda x:x # i18n @@ -30,7 +32,7 @@ class ElectrumGui: self.done = 0 self.last_balance = "" - set_verbosity(False) + console_stderr_handler.setLevel(logging.CRITICAL) self.str_recipient = "" self.str_description = "" diff --git a/electrum/gui/text.py b/electrum/gui/text.py @@ -5,15 +5,17 @@ import datetime import locale from decimal import Decimal import getpass +import logging import electrum -from electrum.util import format_satoshis, set_verbosity +from electrum.util import format_satoshis from electrum.bitcoin import is_address, COIN, TYPE_ADDRESS from electrum.transaction import TxOutput from electrum.wallet import Wallet from electrum.storage import WalletStorage from electrum.network import NetworkParameters, TxBroadcastError, BestEffortRequestFailed from electrum.interface import deserialize_server +from electrum.logging import console_stderr_handler _ = lambda x:x # i18n @@ -52,7 +54,7 @@ class ElectrumGui: self.set_cursor(0) self.w = curses.newwin(10, 50, 5, 5) - set_verbosity(False) + console_stderr_handler.setLevel(logging.CRITICAL) self.tab = 0 self.pos = 0 self.popup_pos = 0 diff --git a/electrum/interface.py b/electrum/interface.py @@ -37,7 +37,7 @@ from aiorpcx import RPCSession, Notification, NetAddress from aiorpcx.curio import timeout_after, TaskTimeout import certifi -from .util import PrintError, ignore_exceptions, log_exceptions, bfh, SilentTaskGroup +from .util import ignore_exceptions, log_exceptions, bfh, SilentTaskGroup from . import util from . import x509 from . import pem @@ -46,6 +46,7 @@ from . import blockchain from .blockchain import Blockchain from . import constants from .i18n import _ +from .logging import Logger if TYPE_CHECKING: from .network import Network @@ -98,7 +99,7 @@ class NotificationSession(RPCSession): else: raise Exception(f'unexpected request. not a notification') except Exception as e: - self.interface.print_error(f"error handling request {request}. exc: {repr(e)}") + self.interface.logger.info(f"error handling request {request}. exc: {repr(e)}") await self.close() async def send_request(self, *args, timeout=None, **kwargs): @@ -148,7 +149,7 @@ class NotificationSession(RPCSession): def maybe_log(self, msg: str) -> None: if not self.interface: return if self.interface.debug or self.interface.network.debug: - self.interface.print_error(msg) + self.interface.logger.debug(msg) class GracefulDisconnect(Exception): pass @@ -180,8 +181,7 @@ def serialize_server(host: str, port: Union[str, int], protocol: str) -> str: return str(':'.join([host, str(port), protocol])) -class Interface(PrintError): - verbosity_filter = 'i' +class Interface(Logger): def __init__(self, network: 'Network', server: str, proxy: Optional[dict]): self.ready = asyncio.Future() @@ -189,6 +189,7 @@ class Interface(PrintError): self.server = server self.host, self.port, self.protocol = deserialize_server(self.server) self.port = int(self.port) + Logger.__init__(self) assert network.config.path self.cert_path = os.path.join(network.config.path, 'certs', self.host) self.blockchain = None @@ -209,7 +210,7 @@ class Interface(PrintError): self.group = SilentTaskGroup() def diagnostic_name(self): - return self.host + return f"{self.host}:{self.port}" def _set_proxy(self, proxy: dict): if proxy: @@ -263,18 +264,18 @@ class Interface(PrintError): try: b = pem.dePem(contents, 'CERTIFICATE') except SyntaxError as e: - self.print_error("error parsing already saved cert:", e) + self.logger.info(f"error parsing already saved cert: {e}") raise ErrorParsingSSLCert(e) from e try: x = x509.X509(b) except Exception as e: - self.print_error("error parsing already saved cert:", e) + self.logger.info(f"error parsing already saved cert: {e}") raise ErrorParsingSSLCert(e) from e try: x.check_date() return True except x509.CertificateError as e: - self.print_error("certificate has expired:", e) + self.logger.info(f"certificate has expired: {e}") os.unlink(self.cert_path) # delete pinned cert only in this case return False @@ -306,7 +307,7 @@ class Interface(PrintError): try: return await func(self, *args, **kwargs) except GracefulDisconnect as e: - self.print_error("disconnecting gracefully. {}".format(repr(e))) + self.logger.info(f"disconnecting gracefully. {repr(e)}") finally: await self.network.connection_down(self) self.got_disconnected.set_result(1) @@ -321,12 +322,12 @@ class Interface(PrintError): try: ssl_context = await self._get_ssl_context() except (ErrorParsingSSLCert, ErrorGettingSSLCertFromServer) as e: - self.print_error('disconnecting due to: {}'.format(repr(e))) + self.logger.info(f'disconnecting due to: {repr(e)}') return try: await self.open_session(ssl_context) except (asyncio.CancelledError, OSError, aiorpcx.socks.SOCKSError) as e: - self.print_error('disconnecting due to: {}'.format(repr(e))) + self.logger.info(f'disconnecting due to: {repr(e)}') return def mark_ready(self): @@ -343,7 +344,7 @@ class Interface(PrintError): self.blockchain = chain assert self.blockchain is not None - self.print_error("set blockchain with height", self.blockchain.height()) + self.logger.info(f"set blockchain with height {self.blockchain.height()}") self.ready.set_result(1) @@ -353,7 +354,7 @@ class Interface(PrintError): for _ in range(10): dercert = await self.get_certificate() if dercert: - self.print_error("succeeded in getting cert") + self.logger.info("succeeded in getting cert") with open(self.cert_path, 'w') as f: cert = ssl.DER_cert_to_PEM_cert(dercert) # workaround android bug @@ -380,7 +381,7 @@ class Interface(PrintError): return None async def get_block_header(self, height, assert_mode): - self.print_error('requesting block header {} in mode {}'.format(height, assert_mode)) + self.logger.info(f'requesting block header {height} in mode {assert_mode}') # use lower timeout as we usually have network.bhi_lock here timeout = self.network.get_network_timeout_seconds(NetworkTimeout.Urgent) res = await self.session.send_request('blockchain.block.header', [height], timeout=timeout) @@ -390,7 +391,7 @@ class Interface(PrintError): index = height // 2016 if can_return_early and index in self._requested_chunks: return - self.print_error("requesting chunk from height {}".format(height)) + self.logger.info(f"requesting chunk from height {height}") size = 2016 if tip is not None: size = min(size, tip - index * 2016 + 1) @@ -425,7 +426,7 @@ class Interface(PrintError): if not self.network.check_interface_against_healthy_spread_of_connected_servers(self): raise GracefulDisconnect(f'too many connected servers already ' f'in bucket {self.bucket_based_on_ipaddress()}') - self.print_error("connection established. version: {}".format(ver)) + self.logger.info(f"connection established. version: {ver}") async with self.group as group: await group.spawn(self.ping) @@ -472,7 +473,7 @@ class Interface(PrintError): async with self.network.bhi_lock: if self.blockchain.height() >= height and self.blockchain.check_header(header): # another interface amended the blockchain - self.print_error("skipping header", height) + self.logger.info(f"skipping header {height}") return _, height = await self.step(height, header) # in the simple case, height == self.tip+1 @@ -518,13 +519,13 @@ class Interface(PrintError): can_connect = blockchain.can_connect(header) if 'mock' not in header else header['mock']['connect'](height) if not can_connect: - self.print_error("can't connect", height) + self.logger.info(f"can't connect {height}") height, header, bad, bad_header = await self._search_headers_backwards(height, header) chain = blockchain.check_header(header) if 'mock' not in header else header['mock']['check'](header) can_connect = blockchain.can_connect(header) if 'mock' not in header else header['mock']['connect'](height) assert chain or can_connect if can_connect: - self.print_error("could connect", height) + self.logger.info(f"could connect {height}") height += 1 if isinstance(can_connect, Blockchain): # not when mocking self.blockchain = can_connect @@ -543,7 +544,7 @@ class Interface(PrintError): while True: assert good < bad, (good, bad) height = (good + bad) // 2 - self.print_error("binary step. good {}, bad {}, height {}".format(good, bad, height)) + self.logger.info(f"binary step. good {good}, bad {bad}, height {height}") header = await self.get_block_header(height, 'binary') chain = blockchain.check_header(header) if 'mock' not in header else header['mock']['check'](header) if chain: @@ -561,7 +562,7 @@ class Interface(PrintError): raise Exception('unexpected bad header during binary: {}'.format(bad_header)) _assert_header_does_not_check_against_any_chain(bad_header) - self.print_error("binary search exited. good {}, bad {}".format(good, bad)) + self.logger.info(f"binary search exited. good {good}, bad {bad}") return good, bad, bad_header async def _resolve_potential_chain_fork_given_forkpoint(self, good, bad, bad_header): @@ -575,12 +576,12 @@ class Interface(PrintError): assert bh >= good, (bh, good) if bh == good: height = good + 1 - self.print_error("catching up from {}".format(height)) + self.logger.info(f"catching up from {height}") return 'no_fork', height # this is a new fork we don't yet have height = bad + 1 - self.print_error(f"new fork at bad height {bad}") + self.logger.info(f"new fork at bad height {bad}") forkfun = self.blockchain.fork if 'mock' not in bad_header else bad_header['mock']['fork'] b = forkfun(bad_header) # type: Blockchain self.blockchain = b @@ -614,7 +615,7 @@ class Interface(PrintError): height = self.tip - 2 * delta _assert_header_does_not_check_against_any_chain(bad_header) - self.print_error("exiting backward mode at", height) + self.logger.info(f"exiting backward mode at {height}") return height, header, bad, bad_header @classmethod diff --git a/electrum/json_db.py b/electrum/json_db.py @@ -31,9 +31,10 @@ from collections import defaultdict from typing import Dict, Optional from . import util, bitcoin -from .util import PrintError, profiler, WalletFileException, multisig_type, TxMinedInfo +from .util import profiler, WalletFileException, multisig_type, TxMinedInfo from .keystore import bip44_derivation from .transaction import Transaction +from .logging import Logger # seed_version is now used for the version of the wallet file @@ -50,9 +51,10 @@ class JsonDBJsonEncoder(util.MyEncoder): return super().default(obj) -class JsonDB(PrintError): +class JsonDB(Logger): def __init__(self, raw, *, manual_upgrades): + Logger.__init__(self) self.lock = threading.RLock() self.data = {} self._modified = False @@ -98,7 +100,7 @@ class JsonDB(PrintError): json.dumps(key, cls=JsonDBJsonEncoder) json.dumps(value, cls=JsonDBJsonEncoder) except: - self.print_error(f"json error: cannot save {repr(key)} ({repr(value)})") + self.logger.info(f"json error: cannot save {repr(key)} ({repr(value)})") return False if value is not None: if self.data.get(key) != value: @@ -137,7 +139,7 @@ class JsonDB(PrintError): json.dumps(key) json.dumps(value) except: - self.print_error('Failed to convert label to json format', key) + self.logger.info(f'Failed to convert label to json format: {key}') continue self.data[key] = value if not isinstance(self.data, dict): @@ -198,7 +200,7 @@ class JsonDB(PrintError): @profiler def upgrade(self): - self.print_error('upgrading wallet format') + self.logger.info('upgrading wallet format') self._convert_imported() self._convert_wallet_type() self._convert_account() @@ -755,14 +757,14 @@ class JsonDB(PrintError): # remove unreferenced tx for tx_hash in list(self.transactions.keys()): if not self.get_txi(tx_hash) and not self.get_txo(tx_hash): - self.print_error("removing unreferenced tx", tx_hash) + self.logger.info(f"removing unreferenced tx: {tx_hash}") self.transactions.pop(tx_hash) # remove unreferenced outpoints for prevout_hash in self.spent_outpoints.keys(): d = self.spent_outpoints[prevout_hash] for prevout_n, spending_txid in list(d.items()): if spending_txid not in self.transactions: - self.print_error("removing unreferenced spent outpoint") + self.logger.info("removing unreferenced spent outpoint") d.pop(prevout_n) @modifier diff --git a/electrum/jsonrpc.py b/electrum/jsonrpc.py @@ -29,6 +29,7 @@ import time from jsonrpclib.SimpleJSONRPCServer import SimpleJSONRPCServer, SimpleJSONRPCRequestHandler from . import util +from .logging import Logger class RPCAuthCredentialsInvalid(Exception): @@ -47,10 +48,10 @@ class RPCAuthUnsupportedType(Exception): # based on http://acooke.org/cute/BasicHTTPA0.html by andrew cooke -class VerifyingJSONRPCServer(SimpleJSONRPCServer): +class VerifyingJSONRPCServer(SimpleJSONRPCServer, Logger): def __init__(self, *args, rpc_user, rpc_password, **kargs): - + Logger.__init__(self) self.rpc_user = rpc_user self.rpc_password = rpc_password @@ -69,8 +70,7 @@ class VerifyingJSONRPCServer(SimpleJSONRPCServer): RPCAuthUnsupportedType) as e: myself.send_error(401, str(e)) except BaseException as e: - import traceback, sys - traceback.print_exc(file=sys.stderr) + self.logger.exception('') myself.send_error(500, str(e)) return False diff --git a/electrum/keystore.py b/electrum/keystore.py @@ -36,13 +36,17 @@ from .bip32 import (convert_bip32_path_to_list_of_uint32, BIP32_PRIME, from .ecc import string_to_number, number_to_string from .crypto import (pw_decode, pw_encode, sha256, sha256d, PW_HASH_VERSION_LATEST, SUPPORTED_PW_HASH_VERSIONS, UnsupportedPasswordHashVersion) -from .util import (PrintError, InvalidPassword, WalletFileException, - BitcoinException, bh2u, bfh, print_error, inv_dict) +from .util import (InvalidPassword, WalletFileException, + BitcoinException, bh2u, bfh, inv_dict) from .mnemonic import Mnemonic, load_wordlist, seed_type, is_seed from .plugin import run_hook +from .logging import Logger -class KeyStore(PrintError): +class KeyStore(Logger): + + def __init__(self): + Logger.__init__(self) def has_seed(self): return False @@ -463,7 +467,6 @@ class Old_KeyStore(Deterministic_KeyStore): master_private_key = ecc.ECPrivkey.from_secret_scalar(secexp) master_public_key = master_private_key.get_public_key_bytes(compressed=False)[1:] if master_public_key != bfh(self.mpk): - print_error('invalid password (mpk)', self.mpk, bh2u(master_public_key)) raise InvalidPassword() def check_password(self, password): @@ -554,12 +557,12 @@ class Hardware_KeyStore(KeyStore, Xpub): def unpaired(self): '''A device paired with the wallet was disconnected. This can be called in any thread context.''' - self.print_error("unpaired") + self.logger.info("unpaired") def paired(self): '''A device paired with the wallet was (re-)connected. This can be called in any thread context.''' - self.print_error("paired") + self.logger.info("paired") def can_export(self): return False diff --git a/electrum/logging.py b/electrum/logging.py @@ -0,0 +1,164 @@ +# Copyright (C) 2019 The Electrum developers +# Distributed under the MIT software license, see the accompanying +# file LICENCE or http://www.opensource.org/licenses/mit-license.php + +import logging +import datetime +import sys +import pathlib +import os +import platform +from typing import Optional + + +class LogFormatterForFiles(logging.Formatter): + + def formatTime(self, record, datefmt=None): + # timestamps follow ISO 8601 UTC + date = datetime.datetime.fromtimestamp(record.created).astimezone(datetime.timezone.utc) + if not datefmt: + datefmt = "%Y%m%dT%H%M%S.%fZ" + return date.strftime(datefmt) + + +file_formatter = LogFormatterForFiles(fmt="%(asctime)22s | %(levelname)8s | %(name)s | %(message)s") + + +class LogFormatterForConsole(logging.Formatter): + + def format(self, record): + # strip the main module name from the logger name + if record.name.startswith("electrum."): + record.name = record.name[9:] + # manual map to shorten common module names + record.name = record.name.replace("interface.Interface", "interface", 1) + record.name = record.name.replace("network.Network", "network", 1) + record.name = record.name.replace("synchronizer.Synchronizer", "synchronizer", 1) + record.name = record.name.replace("verifier.SPV", "verifier", 1) + record.name = record.name.replace("gui.qt.main_window.ElectrumWindow", "gui.qt.main_window", 1) + return super().format(record) + + +# try to make console log lines short... no timestamp, short levelname, no "electrum." +console_formatter = LogFormatterForConsole(fmt="%(levelname).1s | %(name)s | %(message)s") + + +# enable logs universally (including for other libraries) +root_logger = logging.getLogger() +root_logger.setLevel(logging.WARNING) + +# log to stderr; by default only WARNING and higher +console_stderr_handler = logging.StreamHandler(sys.stderr) +console_stderr_handler.setFormatter(console_formatter) +console_stderr_handler.setLevel(logging.WARNING) +root_logger.addHandler(console_stderr_handler) + +# creates a logger specifically for electrum library +electrum_logger = logging.getLogger("electrum") +electrum_logger.setLevel(logging.DEBUG) + + +def _delete_old_logs(path, keep=10): + files = sorted(list(pathlib.Path(path).glob("electrum_log_*.log")), reverse=True) + for f in files[keep:]: + os.remove(str(f)) + + +_logfile_path = None +def _configure_file_logging(log_directory: pathlib.Path): + global _logfile_path + assert _logfile_path is None, 'file logging already initialized' + log_directory.mkdir(exist_ok=True) + + _delete_old_logs(log_directory) + + timestamp = datetime.datetime.utcnow().strftime("%Y%m%dT%H%M%SZ") + PID = os.getpid() + _logfile_path = log_directory / f"electrum_log_{timestamp}_{PID}.log" + + file_handler = logging.FileHandler(_logfile_path) + file_handler.setFormatter(file_formatter) + file_handler.setLevel(logging.DEBUG) + root_logger.addHandler(file_handler) + + +def _configure_verbosity(config): + verbosity = config.get('verbosity') + if not verbosity: + return + console_stderr_handler.setLevel(logging.DEBUG) + if verbosity == '*' or not isinstance(verbosity, str): + return + # example verbosity: + # debug,network=error,interface=error // effectively blacklists network and interface + # warning,network=debug,interface=debug // effectively whitelists network and interface + filters = verbosity.split(',') + for filt in filters: + if not filt: continue + items = filt.split('=') + if len(items) == 1: + level = items[0] + electrum_logger.setLevel(level.upper()) + elif len(items) == 2: + logger_name, level = items + logger = get_logger(logger_name) + logger.setLevel(level.upper()) + else: + raise Exception(f"invalid log filter: {filt}") + + +# --- External API + +def get_logger(name: str) -> logging.Logger: + if name.startswith("electrum."): + name = name[9:] + return electrum_logger.getChild(name) + + +_logger = get_logger(__name__) +_logger.setLevel(logging.INFO) + + +class Logger: + def __init__(self): + self.logger = self.__get_logger_for_obj() + + def __get_logger_for_obj(self) -> logging.Logger: + cls = self.__class__ + if cls.__module__: + name = f"{cls.__module__}.{cls.__name__}" + else: + name = cls.__name__ + try: + diag_name = self.diagnostic_name() + except Exception as e: + raise Exception("diagnostic name not yet available?") from e + if diag_name: + name += f".[{diag_name}]" + return get_logger(name) + + def diagnostic_name(self): + return '' + + +def configure_logging(config): + _configure_verbosity(config) + + is_android = 'ANDROID_DATA' in os.environ + if is_android or config.get('disablefilelogging'): + pass # disable file logging + else: + log_directory = pathlib.Path(config.path) / "logs" + _configure_file_logging(log_directory) + + # if using kivy, avoid kivy's own logs to get printed twice + logging.getLogger('kivy').propagate = False + + from . import ELECTRUM_VERSION + _logger.info(f"Electrum version: {ELECTRUM_VERSION} - https://electrum.org - https://github.com/spesmilo/electrum") + _logger.info(f"Python version: {sys.version}. On platform: {platform.platform()}") + _logger.info(f"Logging to file: {str(_logfile_path)}") + + +def get_logfile_path() -> Optional[pathlib.Path]: + return _logfile_path diff --git a/electrum/mnemonic.py b/electrum/mnemonic.py @@ -30,9 +30,11 @@ import string import ecdsa -from .util import print_error, resource_path, bfh, bh2u +from .util import resource_path, bfh, bh2u from .crypto import hmac_oneshot from . import version +from .logging import Logger + # http://www.asahi-net.or.jp/~ax2s-kmtn/ref/unicode/e_asia.html CJK_INTERVALS = [ @@ -114,16 +116,17 @@ filenames = { # FIXME every time we instantiate this class, we read the wordlist from disk # and store a new copy of it in memory -class Mnemonic(object): +class Mnemonic(Logger): # Seed derivation does not follow BIP39 # Mnemonic phrase uses a hash based checksum, instead of a wordlist-dependent checksum def __init__(self, lang=None): + Logger.__init__(self) lang = lang or 'en' - print_error('language', lang) + self.logger.info(f'language {lang}') filename = filenames.get(lang[0:2], 'english.txt') self.wordlist = load_wordlist(filename) - print_error("wordlist has %d words"%len(self.wordlist)) + self.logger.info(f"wordlist has {len(self.wordlist)} words") @classmethod def mnemonic_to_seed(self, mnemonic, passphrase) -> bytes: @@ -163,7 +166,7 @@ class Mnemonic(object): bpw = math.log(len(self.wordlist), 2) # rounding n = int(math.ceil(num_bits/bpw) * bpw) - print_error("make_seed. prefix: '%s'"%prefix, "entropy: %d bits"%n) + self.logger.info(f"make_seed. prefix: '{prefix}', entropy: {n} bits") entropy = 1 while entropy < pow(2, n - bpw): # try again if seed would not contain enough words @@ -179,7 +182,7 @@ class Mnemonic(object): continue if is_new_seed(seed, prefix): break - print_error('%d words'%len(seed.split())) + self.logger.info(f'{len(seed.split())} words') return seed diff --git a/electrum/network.py b/electrum/network.py @@ -42,7 +42,7 @@ from aiorpcx import TaskGroup from aiohttp import ClientResponse from . import util -from .util import (PrintError, print_error, log_exceptions, ignore_exceptions, +from .util import (log_exceptions, ignore_exceptions, bfh, SilentTaskGroup, make_aiohttp_session, send_exception_to_crash_reporter, is_hash256_str, is_non_negative_integer) @@ -56,6 +56,11 @@ from .interface import (Interface, serialize_server, deserialize_server, from .version import PROTOCOL_VERSION from .simple_config import SimpleConfig from .i18n import _ +from .logging import get_logger, Logger + + +_logger = get_logger(__name__) + NODES_RETRY_INTERVAL = 60 SERVER_RETRY_INTERVAL = 10 @@ -214,16 +219,17 @@ class UntrustedServerReturnedError(Exception): INSTANCE = None -class Network(PrintError): +class Network(Logger): """The Network class manages a set of connections to remote electrum servers, each connected socket is handled by an Interface() object. """ - verbosity_filter = 'n' def __init__(self, config: SimpleConfig=None): global INSTANCE INSTANCE = self + Logger.__init__(self) + self.asyncio_loop = asyncio.get_event_loop() assert self.asyncio_loop.is_running(), "event loop not running" self._loop_thread = None # type: threading.Thread # set by caller; only used for sanity checks @@ -232,7 +238,7 @@ class Network(PrintError): config = {} # Do not use mutables as default values! self.config = SimpleConfig(config) if isinstance(config, dict) else config # type: SimpleConfig blockchain.read_blockchains(self.config) - self.print_error("blockchains", list(map(lambda b: b.forkpoint, blockchain.blockchains.values()))) + self.logger.info(f"blockchains {list(map(lambda b: b.forkpoint, blockchain.blockchains.values()))}") self._blockchain_preferred_block = self.config.get('blockchain_preferred_block', None) # type: Optional[Dict] self._blockchain = blockchain.get_best_chain() # Server for addresses and transactions @@ -242,7 +248,7 @@ class Network(PrintError): try: deserialize_server(self.default_server) except: - self.print_error('Warning: failed to parse server-string; falling back to random.') + self.logger.warning('failed to parse server-string; falling back to random.') self.default_server = None if not self.default_server: self.default_server = pick_random_server() @@ -351,12 +357,12 @@ class Network(PrintError): async def _server_is_lagging(self): sh = self.get_server_height() if not sh: - self.print_error('no height for main interface') + self.logger.info('no height for main interface') return True lh = self.get_local_height() result = (lh - sh) > 1 if result: - self.print_error(f'{self.default_server} is lagging ({sh} vs {lh})') + self.logger.info(f'{self.default_server} is lagging ({sh} vs {lh})') return result def _set_status(self, status): @@ -381,7 +387,7 @@ class Network(PrintError): addr = await session.send_request('server.donation_address') if not bitcoin.is_address(addr): if addr: # ignore empty string - self.print_error(f"invalid donation address from server: {repr(addr)}") + self.logger.info(f"invalid donation address from server: {repr(addr)}") addr = '' self.donation_address = addr async def get_server_peers(): @@ -416,7 +422,7 @@ class Network(PrintError): for i in FEE_ETA_TARGETS: fee_tasks.append((i, await group.spawn(session.send_request('blockchain.estimatefee', [i])))) self.config.mempool_fees = histogram = histogram_task.result() - self.print_error(f'fee_histogram {histogram}') + self.logger.info(f'fee_histogram {histogram}') self.notify('fee_histogram') fee_estimates_eta = {} for nblock_target, task in fee_tasks: @@ -424,7 +430,7 @@ class Network(PrintError): fee_estimates_eta[nblock_target] = fee if fee < 0: continue self.config.update_fee_estimates(nblock_target, fee) - self.print_error(f'fee_estimates {fee_estimates_eta}') + self.logger.info(f'fee_estimates {fee_estimates_eta}') self.notify('fee') def get_status_value(self, key): @@ -490,7 +496,7 @@ class Network(PrintError): def _start_interface(self, server: str): if server not in self.interfaces and server not in self.connecting: if server == self.default_server: - self.print_error(f"connecting to {server} as new interface") + self.logger.info(f"connecting to {server} as new interface") self._set_status('connecting') self.connecting.add(server) self.server_queue.put(server) @@ -509,7 +515,7 @@ class Network(PrintError): if not hasattr(socket, "_getaddrinfo"): socket._getaddrinfo = socket.getaddrinfo if proxy: - self.print_error('setting proxy', proxy) + self.logger.info(f'setting proxy {proxy}') # prevent dns leaks, see http://stackoverflow.com/questions/13184205/dns-over-proxy socket.getaddrinfo = lambda *args: [(socket.AF_INET, socket.SOCK_STREAM, 6, '', (args[0], args[1]))] else: @@ -542,7 +548,7 @@ class Network(PrintError): except dns.exception.DNSException as e: pass except BaseException as e: - print_error(f'dnspython failed to resolve dns (AAAA) with error: {e}') + _logger.info(f'dnspython failed to resolve dns (AAAA) with error: {e}') # try IPv4 try: answers = dns.resolver.query(host, dns.rdatatype.A) @@ -554,7 +560,7 @@ class Network(PrintError): raise socket.gaierror(11001, 'getaddrinfo failed') from e except BaseException as e: # Possibly internal error in dnspython :( see #4483 - print_error(f'dnspython failed to resolve dns (A) with error: {e}') + _logger.info(f'dnspython failed to resolve dns (A) with error: {e}') if addrs: return addrs # Fall back to original socket.getaddrinfo to resolve dns. @@ -641,24 +647,24 @@ class Network(PrintError): filtered = list(filter(lambda iface: iface.blockchain.check_hash(pref_height, pref_hash), interfaces)) if filtered: - self.print_error("switching to preferred fork") + self.logger.info("switching to preferred fork") chosen_iface = random.choice(filtered) await self.switch_to_interface(chosen_iface.server) return else: - self.print_error("tried to switch to preferred fork but no interfaces are on it") + self.logger.info("tried to switch to preferred fork but no interfaces are on it") # try to switch to best chain if self.blockchain().parent is None: return # already on best chain filtered = list(filter(lambda iface: iface.blockchain.parent is None, interfaces)) if filtered: - self.print_error("switching to best chain") + self.logger.info("switching to best chain") chosen_iface = random.choice(filtered) await self.switch_to_interface(chosen_iface.server) else: # FIXME switch to best available? - self.print_error("tried to switch to best chain but no interfaces are on it") + self.logger.info("tried to switch to best chain but no interfaces are on it") async def switch_to_interface(self, server: str): """Switch to server as our main interface. If no connection exists, @@ -685,7 +691,7 @@ class Network(PrintError): i = self.interfaces[server] if old_interface != i: - self.print_error("switching to", server) + self.logger.info(f"switching to {server}") blockchain_updated = i.blockchain != self.blockchain() self.interface = i await i.group.spawn(self._request_server_info(i)) @@ -739,8 +745,7 @@ class Network(PrintError): try: await asyncio.wait_for(interface.ready, timeout) except BaseException as e: - #traceback.print_exc() - self.print_error(f"couldn't launch iface {server} -- {repr(e)}") + self.logger.info(f"couldn't launch iface {server} -- {repr(e)}") await interface.close() return else: @@ -854,14 +859,14 @@ class Network(PrintError): except (RequestTimedOut, asyncio.CancelledError, asyncio.TimeoutError): raise # pass-through except aiorpcx.jsonrpc.CodeMessageError as e: - self.print_error(f"broadcast_transaction error: {repr(e)}") + self.logger.info(f"broadcast_transaction error: {repr(e)}") raise TxBroadcastServerReturnedError(self.sanitize_tx_broadcast_response(e.message)) from e except BaseException as e: # intentional BaseException for sanity! - self.print_error(f"broadcast_transaction error2: {repr(e)}") + self.logger.info(f"broadcast_transaction error2: {repr(e)}") send_exception_to_crash_reporter(e) raise TxBroadcastUnknownError() from e if out != tx.txid(): - self.print_error(f"unexpected txid for broadcast_transaction: {out} != {tx.txid()}") + self.logger.info(f"unexpected txid for broadcast_transaction: {out} != {tx.txid()}") raise TxBroadcastHashMismatch(_("Server returned unexpected transaction ID.")) @staticmethod @@ -1103,7 +1108,7 @@ class Network(PrintError): self.main_taskgroup = main_taskgroup = SilentTaskGroup() assert not self.interface and not self.interfaces assert not self.connecting and not self.server_queue - self.print_error('starting network') + self.logger.info('starting network') self.disconnected_servers = set([]) self.protocol = deserialize_server(self.default_server)[2] self.server_queue = queue.Queue() @@ -1120,7 +1125,7 @@ class Network(PrintError): await group.spawn(self._maintain_sessions()) [await group.spawn(job) for job in self._jobs] except Exception as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') raise e asyncio.run_coroutine_threadsafe(main(), self.asyncio_loop) @@ -1132,11 +1137,11 @@ class Network(PrintError): @log_exceptions async def _stop(self, full_shutdown=False): - self.print_error("stopping network") + self.logger.info("stopping network") try: await asyncio.wait_for(self.main_taskgroup.cancel_remaining(), timeout=2) except (asyncio.TimeoutError, asyncio.CancelledError) as e: - self.print_error(f"exc during main_taskgroup cancellation: {repr(e)}") + self.logger.info(f"exc during main_taskgroup cancellation: {repr(e)}") self.main_taskgroup = None # type: TaskGroup self.interface = None # type: Interface self.interfaces = {} # type: Dict[str, Interface] @@ -1179,7 +1184,7 @@ class Network(PrintError): # FIXME this should try to honour "healthy spread of connected servers" self._start_random_interface() if now - self.nodes_retry_time > NODES_RETRY_INTERVAL: - self.print_error('network: retrying connections') + self.logger.info('network: retrying connections') self.disconnected_servers = set([]) self.nodes_retry_time = now async def maintain_healthy_spread_of_connected_servers(): @@ -1187,7 +1192,7 @@ class Network(PrintError): random.shuffle(interfaces) for iface in interfaces: if not self.check_interface_against_healthy_spread_of_connected_servers(iface): - self.print_error(f"disconnecting from {iface.server}. too many connected " + self.logger.info(f"disconnecting from {iface.server}. too many connected " f"servers already in bucket {iface.bucket_based_on_ipaddress()}") await self._close_interface(iface) async def maintain_main_interface(): diff --git a/electrum/paymentrequest.py b/electrum/paymentrequest.py @@ -39,11 +39,15 @@ except ImportError: sys.exit("Error: could not find paymentrequest_pb2.py. Create it with 'protoc --proto_path=electrum/ --python_out=electrum/ electrum/paymentrequest.proto'") from . import bitcoin, ecc, util, transaction, x509, rsakey -from .util import print_error, bh2u, bfh, export_meta, import_meta, make_aiohttp_session +from .util import bh2u, bfh, export_meta, import_meta, make_aiohttp_session from .crypto import sha256 from .bitcoin import TYPE_ADDRESS from .transaction import TxOutput from .network import Network +from .logging import get_logger, Logger + + +_logger = get_logger(__name__) REQUEST_HEADERS = {'Accept': 'application/bitcoin-paymentrequest', 'User-Agent': 'Electrum'} @@ -86,7 +90,7 @@ async def get_payment_request(url: str) -> 'PaymentRequest': else: data = resp_content data_len = len(data) if data is not None else None - print_error('fetched payment request', url, data_len) + _logger.info(f'fetched payment request {url} {data_len}') except aiohttp.ClientError as e: error = f"Error while contacting payment URL:\n{repr(e)}" if isinstance(e, aiohttp.ClientResponseError) and e.status == 400 and resp_content: @@ -180,7 +184,7 @@ class PaymentRequest: try: x, ca = verify_cert_chain(cert.certificate) except BaseException as e: - traceback.print_exc(file=sys.stderr) + _logger.exception('') self.error = str(e) return False # get requestor name @@ -454,9 +458,10 @@ def make_request(config, req): -class InvoiceStore(object): +class InvoiceStore(Logger): def __init__(self, storage): + Logger.__init__(self) self.storage = storage self.invoices = {} self.paid = {} @@ -511,7 +516,7 @@ class InvoiceStore(object): def get_status(self, key): pr = self.get(key) if pr is None: - print_error("[InvoiceStore] get_status() can't find pr for", key) + self.logger.info(f"get_status() can't find pr for {key}") return if pr.tx is not None: return PR_PAID diff --git a/electrum/plugin.py b/electrum/plugin.py @@ -22,8 +22,6 @@ # ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN # CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE # SOFTWARE. -import traceback -import sys import os import pkgutil import importlib.util @@ -32,23 +30,23 @@ import threading from typing import NamedTuple, Any, Union, TYPE_CHECKING, Optional from .i18n import _ -from .util import (profiler, PrintError, DaemonThread, UserCancelled, - ThreadJob, print_error, UserFacingException) +from .util import (profiler, DaemonThread, UserCancelled, ThreadJob) from . import bip32 from . import plugins from .simple_config import SimpleConfig +from .logging import get_logger, Logger if TYPE_CHECKING: from .plugins.hw_wallet import HW_PluginBase +_logger = get_logger(__name__) plugin_loaders = {} hook_names = set() hooks = {} class Plugins(DaemonThread): - verbosity_filter = 'p' @profiler def __init__(self, config: SimpleConfig, gui_name): @@ -91,8 +89,7 @@ class Plugins(DaemonThread): try: self.load_plugin(name) except BaseException as e: - traceback.print_exc(file=sys.stdout) - self.print_error("cannot initialize plugin %s:" % name, str(e)) + self.logger.exception(f"cannot initialize plugin {name}: {e}") def get(self, name): return self.plugins.get(name) @@ -116,7 +113,7 @@ class Plugins(DaemonThread): raise Exception(f"Error loading {name} plugin: {repr(e)}") from e self.add_jobs(plugin.thread_jobs()) self.plugins[name] = plugin - self.print_error("loaded", name) + self.logger.info(f"loaded {name}") return plugin def close_plugin(self, plugin): @@ -136,7 +133,7 @@ class Plugins(DaemonThread): return self.plugins.pop(name) p.close() - self.print_error("closed", name) + self.logger.info(f"closed {name}") def toggle(self, name): p = self.get(name) @@ -151,7 +148,7 @@ class Plugins(DaemonThread): try: __import__(dep) except ImportError as e: - self.print_error('Plugin', name, 'unavailable:', repr(e)) + self.logger.warning(f'Plugin {name} unavailable: {repr(e)}') return False requires = d.get('requires_wallet_type', []) return not requires or w.wallet_type in requires @@ -168,8 +165,7 @@ class Plugins(DaemonThread): plugin=p, exception=None)) except Exception as e: - traceback.print_exc() - self.print_error("cannot load plugin for:", name) + self.logger.exception(f"cannot load plugin for: {name}") out.append(HardwarePluginToScan(name=name, description=details[2], plugin=None, @@ -178,7 +174,7 @@ class Plugins(DaemonThread): def register_wallet_type(self, name, gui_good, wallet_type): from .wallet import register_wallet_type, register_constructor - self.print_error("registering wallet type", (wallet_type, name)) + self.logger.info(f"registering wallet type {(wallet_type, name)}") def loader(): plugin = self.get_plugin(name) register_constructor(wallet_type, plugin.wallet_class) @@ -191,7 +187,7 @@ class Plugins(DaemonThread): return self.get_plugin(name).keystore_class(d) if details[0] == 'hardware': self.hw_wallets[name] = (gui_good, details) - self.print_error("registering hardware %s: %s" %(name, details)) + self.logger.info(f"registering hardware {name}: {details}") register_keystore(details[1], dynamic_constructor) def get_plugin(self, name): @@ -218,8 +214,7 @@ def run_hook(name, *args): try: r = f(*args) except Exception: - print_error("Plugin error") - traceback.print_exc(file=sys.stdout) + _logger.exception(f"Plugin error. plugin: {p}, hook: {name}") r = False if r: results.append(r) @@ -229,13 +224,14 @@ def run_hook(name, *args): return results[0] -class BasePlugin(PrintError): +class BasePlugin(Logger): def __init__(self, parent, config, name): self.parent = parent # The plugins object self.name = name self.config = config self.wallet = None + Logger.__init__(self) # add self to hooks for k in dir(self): if k in hook_names: @@ -243,9 +239,6 @@ class BasePlugin(PrintError): l.append((self, getattr(self, k))) hooks[k] = l - def diagnostic_name(self): - return self.name - def __str__(self): return self.name @@ -313,7 +306,7 @@ class HardwarePluginToScan(NamedTuple): exception: Optional[Exception] -class DeviceMgr(ThreadJob, PrintError): +class DeviceMgr(ThreadJob): '''Manages hardware clients. A client communicates over a hardware channel with the device. @@ -345,7 +338,7 @@ class DeviceMgr(ThreadJob, PrintError): hidapi are implemented.''' def __init__(self, config): - super(DeviceMgr, self).__init__() + ThreadJob.__init__(self) # Keyed by xpub. The value is the device id # has been paired, and None otherwise. self.xpub_ids = {} @@ -389,7 +382,7 @@ class DeviceMgr(ThreadJob, PrintError): return client client = plugin.create_client(device, handler) if client: - self.print_error("Registering", client) + self.logger.info(f"Registering {client}") with self.lock: self.clients[client] = (device.path, device.id_) return client @@ -444,7 +437,7 @@ class DeviceMgr(ThreadJob, PrintError): return self.client_lookup(id_) def client_for_keystore(self, plugin, handler, keystore, force_pair): - self.print_error("getting client for keystore") + self.logger.info("getting client for keystore") if handler is None: raise Exception(_("Handler not found for") + ' ' + plugin.name + '\n' + _("A library is probably missing.")) handler.update_status(False) @@ -457,7 +450,7 @@ class DeviceMgr(ThreadJob, PrintError): client = self.force_pair_xpub(plugin, handler, info, xpub, derivation, devices) if client: handler.update_status(True) - self.print_error("end client for keystore") + self.logger.info("end client for keystore") return client def client_by_xpub(self, plugin, xpub, handler, devices): @@ -518,7 +511,7 @@ class DeviceMgr(ThreadJob, PrintError): try: client = self.create_client(device, handler, plugin) except Exception as e: - self.print_error(f'failed to create client for {plugin.name} at {device.path}: {repr(e)}') + self.logger.error(f'failed to create client for {plugin.name} at {device.path}: {repr(e)}') if include_failing_clients: infos.append(DeviceInfo(device=device, exception=e)) continue @@ -595,7 +588,7 @@ class DeviceMgr(ThreadJob, PrintError): return devices def scan_devices(self): - self.print_error("scanning devices...") + self.logger.info("scanning devices...") # First see what's connected that we know about devices = self._scan_devices_with_hid() @@ -605,8 +598,8 @@ class DeviceMgr(ThreadJob, PrintError): try: new_devices = f() except BaseException as e: - self.print_error('custom device enum failed. func {}, error {}' - .format(str(f), str(e))) + self.logger.error('custom device enum failed. func {}, error {}' + .format(str(f), str(e))) else: devices.extend(new_devices) diff --git a/electrum/plugins/audio_modem/qt.py b/electrum/plugins/audio_modem/qt.py @@ -9,19 +9,23 @@ from PyQt5.QtWidgets import (QComboBox, QGridLayout, QLabel, QPushButton) from electrum.plugin import BasePlugin, hook from electrum.gui.qt.util import WaitingDialog, EnterButton, WindowModalDialog, read_QIcon -from electrum.util import print_msg, print_error from electrum.i18n import _ +from electrum.logging import get_logger + + +_logger = get_logger(__name__) + try: import amodem.audio import amodem.main import amodem.config - print_error('Audio MODEM is available.') + _logger.info('Audio MODEM is available.') amodem.log.addHandler(amodem.logging.StreamHandler(sys.stderr)) amodem.log.setLevel(amodem.logging.INFO) except ImportError: amodem = None - print_error('Audio MODEM is not found.') + _logger.info('Audio MODEM is not found.') class Plugin(BasePlugin): @@ -100,7 +104,7 @@ class Plugin(BasePlugin): dst = interface.player() amodem.main.send(config=self.modem_config, src=src, dst=dst) - print_msg('Sending:', repr(blob)) + _logger.info(f'Sending: {repr(blob)}') blob = zlib.compress(blob.encode('ascii')) kbps = self.modem_config.modem_bps / 1e3 @@ -118,7 +122,7 @@ class Plugin(BasePlugin): def on_finished(blob): if blob: blob = zlib.decompress(blob).decode('ascii') - print_msg('Received:', repr(blob)) + _logger.info(f'Received: {repr(blob)}') parent.setText(blob) kbps = self.modem_config.modem_bps / 1e3 diff --git a/electrum/plugins/coldcard/cmdline.py b/electrum/plugins/coldcard/cmdline.py @@ -1,6 +1,12 @@ from electrum.plugin import hook +from electrum.util import print_msg, raw_input, print_stderr +from electrum.logging import get_logger + from .coldcard import ColdcardPlugin -from electrum.util import print_msg, print_error, raw_input, print_stderr + + +_logger = get_logger(__name__) + class ColdcardCmdLineHandler: @@ -24,10 +30,10 @@ class ColdcardCmdLineHandler: print_stderr(msg) def show_error(self, msg, blocking=False): - print_error(msg) + print_stderr(msg) def update_status(self, b): - print_error('hw device status', b) + _logger.info(f'hw device status {b}') def finished(self): pass diff --git a/electrum/plugins/coldcard/coldcard.py b/electrum/plugins/coldcard/coldcard.py @@ -13,12 +13,17 @@ from electrum.keystore import Hardware_KeyStore, xpubkey_to_pubkey, Xpub from electrum.transaction import Transaction from electrum.wallet import Standard_Wallet from electrum.crypto import hash_160 -from electrum.util import print_error, bfh, bh2u, versiontuple, UserFacingException +from electrum.util import bfh, bh2u, versiontuple, UserFacingException from electrum.base_wizard import ScriptTypeNotSupported +from electrum.logging import get_logger from ..hw_wallet import HW_PluginBase from ..hw_wallet.plugin import LibraryFoundButUnusable + +_logger = get_logger(__name__) + + try: import hid from ckcc.protocol import CCProtocolPacker, CCProtocolUnpacker @@ -114,10 +119,10 @@ class CKCCClient: or (self.dev.master_fingerprint != expected_xfp) or (self.dev.master_xpub != expected_xpub)): # probably indicating programing error, not hacking - print_error("[coldcard]", f"xpubs. reported by device: {self.dev.master_xpub}. " - f"stored in file: {expected_xpub}") - raise RuntimeError("Expecting 0x%08x but that's not whats connected?!" % - expected_xfp) + _logger.info(f"xpubs. reported by device: {self.dev.master_xpub}. " + f"stored in file: {expected_xpub}") + raise RuntimeError("Expecting 0x%08x but that's not what's connected?!" % + expected_xfp) # check signature over session key # - mitm might have lied about xfp and xpub up to here @@ -127,7 +132,7 @@ class CKCCClient: self._expected_device = ex - print_error("[coldcard]", "Successfully verified against MiTM") + _logger.info("Successfully verified against MiTM") def is_pairable(self): # can't do anything w/ devices that aren't setup (but not normally reachable) @@ -181,7 +186,7 @@ class CKCCClient: def get_xpub(self, bip32_path, xtype): assert xtype in ColdcardPlugin.SUPPORTED_XTYPES - print_error('[coldcard]', 'Derive xtype = %r' % xtype) + _logger.info('Derive xtype = %r' % xtype) xpub = self.dev.send_recv(CCProtocolPacker.get_xpub(bip32_path), timeout=5000) # TODO handle timeout? # change type of xpub to the requested type @@ -296,7 +301,7 @@ class Coldcard_KeyStore(Hardware_KeyStore): return rv def give_error(self, message, clear_client=False): - print_error(message) + self.logger.info(message) if not self.ux_busy: self.handler.show_error(message) else: @@ -363,7 +368,7 @@ class Coldcard_KeyStore(Hardware_KeyStore): except (CCUserRefused, CCBusyError) as exc: self.handler.show_error(str(exc)) except CCProtoError as exc: - traceback.print_exc(file=sys.stderr) + self.logger.exception('Error showing address') self.handler.show_error('{}\n\n{}'.format( _('Error showing address') + ':', str(exc))) except Exception as e: @@ -546,11 +551,11 @@ class Coldcard_KeyStore(Hardware_KeyStore): self.handler.finished() except (CCUserRefused, CCBusyError) as exc: - print_error('[coldcard]', 'Did not sign:', str(exc)) + self.logger.info(f'Did not sign: {exc}') self.handler.show_error(str(exc)) return except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.give_error(e, True) return @@ -581,11 +586,11 @@ class Coldcard_KeyStore(Hardware_KeyStore): finally: self.handler.finished() except CCProtoError as exc: - traceback.print_exc(file=sys.stderr) + self.logger.exception('Error showing address') self.handler.show_error('{}\n\n{}'.format( _('Error showing address') + ':', str(exc))) except BaseException as exc: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.handler.show_error(exc) @@ -651,7 +656,7 @@ class ColdcardPlugin(HW_PluginBase): is_simulator=(device.product_key[1] == CKCC_SIMULATED_PID)) return rv except: - self.print_error('late failure connecting to device?') + self.logger.info('late failure connecting to device?') return None def setup_device(self, device_info, wizard, purpose): diff --git a/electrum/plugins/cosigner_pool/qt.py b/electrum/plugins/cosigner_pool/qt.py @@ -74,12 +74,12 @@ class Listener(util.DaemonThread): try: message = server.get(keyhash) except Exception as e: - self.print_error("cannot contact cosigner pool") + self.logger.info("cannot contact cosigner pool") time.sleep(30) continue if message: self.received.add(keyhash) - self.print_error("received message for", keyhash) + self.logger.info(f"received message for {keyhash}") self.parent.obj.cosigner_receive_signal.emit( keyhash, message) # poll every 30 seconds @@ -121,11 +121,11 @@ class Plugin(BasePlugin): if type(wallet) != Multisig_Wallet: return if self.listener is None: - self.print_error("starting listener") + self.logger.info("starting listener") self.listener = Listener(self) self.listener.start() elif self.listener: - self.print_error("shutting down listener") + self.logger.info("shutting down listener") self.listener.stop() self.listener = None self.keys = [] @@ -176,7 +176,7 @@ class Plugin(BasePlugin): _("Open your cosigner wallet to retrieve it.")) def on_failure(exc_info): e = exc_info[1] - try: traceback.print_exception(*exc_info) + try: self.logger.error("on_failure", exc_info=exc_info) except OSError: pass window.show_error(_("Failed to send transaction to cosigning pool") + ':\n' + str(e)) @@ -193,12 +193,12 @@ class Plugin(BasePlugin): WaitingDialog(window, msg, task, on_success, on_failure) def on_receive(self, keyhash, message): - self.print_error("signal arrived for", keyhash) + self.logger.info("signal arrived for", keyhash) for key, _hash, window in self.keys: if _hash == keyhash: break else: - self.print_error("keyhash not found") + self.logger.info("keyhash not found") return wallet = window.wallet @@ -225,7 +225,7 @@ class Plugin(BasePlugin): privkey = BIP32Node.from_xkey(xprv).eckey message = bh2u(privkey.decrypt_message(message)) except Exception as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') window.show_error(_('Error decrypting message') + ':\n' + str(e)) return diff --git a/electrum/plugins/digitalbitbox/digitalbitbox.py b/electrum/plugins/digitalbitbox/digitalbitbox.py @@ -27,9 +27,14 @@ from electrum.transaction import Transaction from electrum.i18n import _ from electrum.keystore import Hardware_KeyStore from ..hw_wallet import HW_PluginBase -from electrum.util import print_error, to_string, UserCancelled, UserFacingException +from electrum.util import to_string, UserCancelled, UserFacingException from electrum.base_wizard import ScriptTypeNotSupported, HWD_SETUP_NEW_WALLET from electrum.network import Network +from electrum.logging import get_logger + + +_logger = get_logger(__name__) + try: import hid @@ -406,7 +411,7 @@ class DigitalBitbox_Client(): r = to_string(r, 'utf8') reply = json.loads(r) except Exception as e: - print_error('Exception caught ' + repr(e)) + _logger.info(f'Exception caught {repr(e)}') return reply @@ -431,7 +436,7 @@ class DigitalBitbox_Client(): if 'error' in reply: self.password = None except Exception as e: - print_error('Exception caught ' + repr(e)) + _logger.info(f'Exception caught {repr(e)}') return reply @@ -679,7 +684,7 @@ class DigitalBitbox_KeyStore(Hardware_KeyStore): except BaseException as e: self.give_error(e, True) else: - print_error("Transaction is_complete", tx.is_complete()) + _logger.info("Transaction is_complete {tx.is_complete()}") tx.raw = tx.serialize() @@ -746,7 +751,7 @@ class DigitalBitboxPlugin(HW_PluginBase): ) try: text = Network.send_http_on_proxy('post', url, body=args.encode('ascii'), headers={'content-type': 'application/x-www-form-urlencoded'}) - print_error('digitalbitbox reply from server', text) + _logger.info(f'digitalbitbox reply from server {text}') except Exception as e: self.handler.show_error(repr(e)) # repr because str(Exception()) == '' diff --git a/electrum/plugins/email_requests/qt.py b/electrum/plugins/email_requests/qt.py @@ -41,19 +41,21 @@ from PyQt5.QtCore import QObject, pyqtSignal, QThread from PyQt5.QtWidgets import (QVBoxLayout, QLabel, QGridLayout, QLineEdit, QInputDialog) +from electrum.gui.qt.util import (EnterButton, Buttons, CloseButton, OkButton, + WindowModalDialog, get_parent_main_window) + from electrum.plugin import BasePlugin, hook from electrum.paymentrequest import PaymentRequest from electrum.i18n import _ -from electrum.util import PrintError -from ...gui.qt.util import (EnterButton, Buttons, CloseButton, OkButton, - WindowModalDialog, get_parent_main_window) +from electrum.logging import Logger -class Processor(threading.Thread, PrintError): +class Processor(threading.Thread, Logger): polling_interval = 5*60 def __init__(self, imap_server, username, password, callback): threading.Thread.__init__(self) + Logger.__init__(self) self.daemon = True self.username = username self.password = password @@ -90,7 +92,7 @@ class Processor(threading.Thread, PrintError): self.M = imaplib.IMAP4_SSL(self.imap_server) self.M.login(self.username, self.password) except BaseException as e: - self.print_error('connecting failed: {}'.format(repr(e))) + self.logger.info(f'connecting failed: {repr(e)}') self.connect_wait *= 2 else: self.reset_connect_wait() @@ -99,7 +101,7 @@ class Processor(threading.Thread, PrintError): try: self.poll() except BaseException as e: - self.print_error('polling failed: {}'.format(repr(e))) + self.logger.info(f'polling failed: {repr(e)}') break time.sleep(self.polling_interval) time.sleep(random.randint(0, self.connect_wait)) @@ -120,7 +122,7 @@ class Processor(threading.Thread, PrintError): s.sendmail(self.username, [recipient], msg.as_string()) s.quit() except BaseException as e: - self.print_error(e) + self.logger.info(e) class QEmailSignalObject(QObject): @@ -151,7 +153,7 @@ class Plugin(BasePlugin): self.wallets = set() def on_receive(self, pr_str): - self.print_error('received payment request') + self.logger.info('received payment request') self.pr = PaymentRequest(pr_str) self.obj.email_new_invoice_signal.emit() @@ -188,12 +190,12 @@ class Plugin(BasePlugin): return recipient = str(recipient) payload = pr.SerializeToString() - self.print_error('sending mail to', recipient) + self.logger.info(f'sending mail to {recipient}') try: # FIXME this runs in the GUI thread and blocks it... self.processor.send(recipient, message, payload) except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') window.show_message(str(e)) else: window.show_message(_('Request sent.')) diff --git a/electrum/plugins/greenaddress_instant/qt.py b/electrum/plugins/greenaddress_instant/qt.py @@ -105,8 +105,7 @@ class Plugin(BasePlugin): else: d.show_warning(_('{} is not covered by GreenAddress instant confirmation').format(tx.txid()), title=_('Verification failed!')) except BaseException as e: - import traceback - traceback.print_exc(file=sys.stdout) + self.logger.exception('') d.show_error(str(e)) finally: d.verify_button.setText(self.button_label) diff --git a/electrum/plugins/hw_wallet/cmdline.py b/electrum/plugins/hw_wallet/cmdline.py @@ -1,4 +1,8 @@ -from electrum.util import print_error, print_stderr, raw_input +from electrum.util import print_stderr, raw_input +from electrum.logging import get_logger + + +_logger = get_logger(__name__) class CmdLineHandler: @@ -40,7 +44,7 @@ class CmdLineHandler: print_stderr(msg) def update_status(self, b): - print_error('hw device status', b) + _logger.info(f'hw device status {b}') def finished(self): pass diff --git a/electrum/plugins/hw_wallet/plugin.py b/electrum/plugins/hw_wallet/plugin.py @@ -111,7 +111,7 @@ class HW_PluginBase(BasePlugin): _("Library version for '{}' is incompatible.").format(self.name) + '\nInstalled: {}, Needed: {} <= x < {}' .format(library_version, version_str(self.minimum_library), max_version_str)) - self.print_stderr(self.libraries_available_message) + self.logger.warning(self.libraries_available_message) return False return True diff --git a/electrum/plugins/hw_wallet/qt.py b/electrum/plugins/hw_wallet/qt.py @@ -35,11 +35,12 @@ from electrum.gui.qt.util import (read_QIcon, WWLabel, OkButton, WindowModalDial Buttons, CancelButton, TaskThread) from electrum.i18n import _ -from electrum.util import PrintError +from electrum.logging import Logger + # The trickiest thing about this handler was getting windows properly # parented on macOS. -class QtHandlerBase(QObject, PrintError): +class QtHandlerBase(QObject, Logger): '''An interface between the GUI (here, QT) and the device handling logic for handling I/O.''' @@ -53,7 +54,8 @@ class QtHandlerBase(QObject, PrintError): status_signal = pyqtSignal(object) def __init__(self, win, device): - super(QtHandlerBase, self).__init__() + QObject.__init__(self) + Logger.__init__(self) self.clear_signal.connect(self.clear_dialog) self.error_signal.connect(self.error_dialog) self.message_signal.connect(self.message_dialog) diff --git a/electrum/plugins/keepkey/clientbase.py b/electrum/plugins/keepkey/clientbase.py @@ -3,9 +3,10 @@ from struct import pack from electrum import ecc from electrum.i18n import _ -from electrum.util import PrintError, UserCancelled +from electrum.util import UserCancelled from electrum.keystore import bip39_normalize_passphrase from electrum.bip32 import BIP32Node, convert_bip32_path_to_list_of_uint32 +from electrum.logging import Logger class GuiMixin(object): @@ -93,7 +94,7 @@ class GuiMixin(object): return self.proto.CharacterAck(**char_info) -class KeepKeyClientBase(GuiMixin, PrintError): +class KeepKeyClientBase(GuiMixin, Logger): def __init__(self, handler, plugin, proto): assert hasattr(self, 'tx_api') # ProtocolMixin already constructed? @@ -104,6 +105,7 @@ class KeepKeyClientBase(GuiMixin, PrintError): self.types = plugin.types self.msg = None self.creating_wallet = False + Logger.__init__(self) self.used() def __str__(self): @@ -137,7 +139,7 @@ class KeepKeyClientBase(GuiMixin, PrintError): def timeout(self, cutoff): '''Time out the client if the last operation was before cutoff.''' if self.last_operation < cutoff: - self.print_error("timed out") + self.logger.info("timed out") self.clear_session() @staticmethod @@ -190,13 +192,13 @@ class KeepKeyClientBase(GuiMixin, PrintError): def clear_session(self): '''Clear the session to force pin (and passphrase if enabled) re-entry. Does not leak exceptions.''' - self.print_error("clear session:", self) + self.logger.info(f"clear session: {self}") self.prevent_timeouts() try: super(KeepKeyClientBase, self).clear_session() except BaseException as e: # If the device was removed it has the same effect... - self.print_error("clear_session: ignoring error", str(e)) + self.logger.info(f"clear_session: ignoring error {e}") def get_public_node(self, address_n, creating): self.creating_wallet = creating @@ -204,7 +206,7 @@ class KeepKeyClientBase(GuiMixin, PrintError): def close(self): '''Called when Our wallet was closed or the device removed.''' - self.print_error("closing client") + self.logger.info("closing client") self.clear_session() # Release the device self.transport.close() diff --git a/electrum/plugins/keepkey/keepkey.py b/electrum/plugins/keepkey/keepkey.py @@ -108,7 +108,7 @@ class KeepKeyPlugin(HW_PluginBase): return WebUsbTransport(device) def _try_hid(self, device): - self.print_error("Trying to connect over USB...") + self.logger.info("Trying to connect over USB...") if device.interface_number == 1: pair = [None, device.path] else: @@ -119,15 +119,15 @@ class KeepKeyPlugin(HW_PluginBase): except BaseException as e: # see fdb810ba622dc7dbe1259cbafb5b28e19d2ab114 # raise - self.print_error("cannot connect at", device.path, str(e)) + self.logger.info(f"cannot connect at {device.path} {e}") return None def _try_webusb(self, device): - self.print_error("Trying to connect over WebUSB...") + self.logger.info("Trying to connect over WebUSB...") try: return self.webusb_transport(device) except BaseException as e: - self.print_error("cannot connect at", device.path, str(e)) + self.logger.info(f"cannot connect at {device.path} {e}") return None def create_client(self, device, handler): @@ -137,10 +137,10 @@ class KeepKeyPlugin(HW_PluginBase): transport = self._try_hid(device) if not transport: - self.print_error("cannot connect to device") + self.logger.info("cannot connect to device") return - self.print_error("connected to device at", device.path) + self.logger.info(f"connected to device at {device.path}") client = self.client_class(transport, handler, self) @@ -148,14 +148,14 @@ class KeepKeyPlugin(HW_PluginBase): try: client.ping('t') except BaseException as e: - self.print_error("ping failed", str(e)) + self.logger.info(f"ping failed {e}") return None if not client.atleast_version(*self.minimum_firmware): msg = (_('Outdated {} firmware for device labelled {}. Please ' 'download the updated firmware from {}') .format(self.device, client.label(), self.firmware_URL)) - self.print_error(msg) + self.logger.info(msg) if handler: handler.show_error(msg) else: @@ -215,7 +215,7 @@ class KeepKeyPlugin(HW_PluginBase): except UserCancelled: exit_code = 1 except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') handler.show_error(str(e)) exit_code = 1 finally: diff --git a/electrum/plugins/labels/cmdline.py b/electrum/plugins/labels/cmdline.py @@ -8,4 +8,4 @@ class Plugin(LabelsPlugin): self.start_wallet(wallet) def on_pulled(self, wallet): - self.print_error('labels pulled from server') + self.logger.info('labels pulled from server') diff --git a/electrum/plugins/labels/kivy.py b/electrum/plugins/labels/kivy.py @@ -9,6 +9,6 @@ class Plugin(LabelsPlugin): self.start_wallet(wallet) def on_pulled(self, wallet): - self.print_error('on pulled') + self.logger.info('on pulled') self.window._trigger_update_history() diff --git a/electrum/plugins/labels/labels.py b/electrum/plugins/labels/labels.py @@ -53,7 +53,7 @@ class LabelsPlugin(BasePlugin): return nonce def set_nonce(self, wallet, nonce): - self.print_error("set", wallet.basename(), "nonce to", nonce) + self.logger.info(f"set {wallet.basename()} nonce to {nonce}") wallet.storage.put("wallet_nonce", nonce) @hook @@ -109,7 +109,7 @@ class LabelsPlugin(BasePlugin): encoded_key = self.encode(wallet, key) encoded_value = self.encode(wallet, value) except: - self.print_error('cannot encode', repr(key), repr(value)) + self.logger.info(f'cannot encode {repr(key)} {repr(value)}') continue bundle["labels"].append({'encryptedLabel': encoded_value, 'externalId': encoded_key}) @@ -121,13 +121,13 @@ class LabelsPlugin(BasePlugin): raise Exception('Wallet {} not loaded'.format(wallet)) wallet_id = wallet_data[2] nonce = 1 if force else self.get_nonce(wallet) - 1 - self.print_error("asking for labels since nonce", nonce) + self.logger.info(f"asking for labels since nonce {nonce}") try: response = await self.do_get("/labels/since/%d/for/%s" % (nonce, wallet_id)) except Exception as e: raise ErrorConnectingServer(e) from e if response["labels"] is None: - self.print_error('no new labels') + self.logger.info('no new labels') return result = {} for label in response["labels"]: @@ -140,7 +140,7 @@ class LabelsPlugin(BasePlugin): json.dumps(key) json.dumps(value) except: - self.print_error('error: no json', key) + self.logger.info(f'error: no json {key}') continue result[key] = value @@ -148,7 +148,7 @@ class LabelsPlugin(BasePlugin): if force or not wallet.labels.get(key): wallet.labels[key] = value - self.print_error("received %d labels" % len(response)) + self.logger.info(f"received {len(response)} labels") # do not write to disk because we're in a daemon thread wallet.storage.put('labels', wallet.labels) self.set_nonce(wallet, response["nonce"] + 1) @@ -160,7 +160,7 @@ class LabelsPlugin(BasePlugin): try: await self.pull_thread(wallet, force) except ErrorConnectingServer as e: - self.print_error(str(e)) + self.logger.info(str(e)) def pull(self, wallet, force): if not wallet.network: raise Exception(_('You are offline.')) @@ -173,7 +173,7 @@ class LabelsPlugin(BasePlugin): def start_wallet(self, wallet): if not wallet.network: return # 'offline' mode nonce = self.get_nonce(wallet) - self.print_error("wallet", wallet.basename(), "nonce is", nonce) + self.logger.info(f"wallet {wallet.basename()} nonce is {nonce}") mpk = wallet.get_fingerprint() if not mpk: return diff --git a/electrum/plugins/labels/qt.py b/electrum/plugins/labels/qt.py @@ -58,9 +58,9 @@ class Plugin(LabelsPlugin): def done_processing_success(self, dialog, result): dialog.show_message(_("Your labels have been synchronised.")) - def done_processing_error(self, dialog, result): - traceback.print_exception(*result, file=sys.stderr) - dialog.show_error(_("Error synchronising labels") + ':\n' + str(result[:2])) + def done_processing_error(self, dialog, exc_info): + self.logger.error("Error synchronising labels", exc_info=exc_info) + dialog.show_error(_("Error synchronising labels") + f':\n{repr(exc_info[1])}') @hook def load_wallet(self, wallet, window): diff --git a/electrum/plugins/ledger/auth2fa.py b/electrum/plugins/ledger/auth2fa.py @@ -13,10 +13,13 @@ from PyQt5.QtCore import QThread, pyqtSignal from btchip.btchip import BTChipException +from electrum.gui.qt.qrcodewidget import QRCodeWidget from electrum.i18n import _ -from electrum.util import print_msg from electrum import constants, bitcoin -from electrum.gui.qt.qrcodewidget import QRCodeWidget +from electrum.logging import get_logger + + +_logger = get_logger(__name__) DEBUG = False @@ -354,4 +357,5 @@ class LedgerWebSocket(QThread): def debug_msg(*args): if DEBUG: - print_msg(*args) + str_ = " ".join([str(item) for item in args]) + _logger.debug(str_) diff --git a/electrum/plugins/ledger/ledger.py b/electrum/plugins/ledger/ledger.py @@ -10,12 +10,17 @@ from electrum.i18n import _ from electrum.keystore import Hardware_KeyStore from electrum.transaction import Transaction from electrum.wallet import Standard_Wallet -from electrum.util import print_error, bfh, bh2u, versiontuple, UserFacingException +from electrum.util import bfh, bh2u, versiontuple, UserFacingException from electrum.base_wizard import ScriptTypeNotSupported +from electrum.logging import get_logger from ..hw_wallet import HW_PluginBase from ..hw_wallet.plugin import is_any_tx_output_on_change_branch + +_logger = get_logger(__name__) + + try: import hid from btchip.btchipComm import HIDDongleHIDAPI, DongleWait @@ -236,7 +241,7 @@ class Ledger_KeyStore(Hardware_KeyStore): return self.plugin.get_client(self) def give_error(self, message, clear_client = False): - print_error(message) + _logger.info(message) if not self.signing: self.handler.show_error(message) else: @@ -499,10 +504,10 @@ class Ledger_KeyStore(Hardware_KeyStore): elif e.sw == 0x6982: raise # pin lock. decorator will catch it else: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.give_error(e, True) except BaseException as e: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') self.give_error(e, True) finally: self.handler.finished() @@ -533,10 +538,10 @@ class Ledger_KeyStore(Hardware_KeyStore): e, _('Your device might not have support for this functionality.'))) else: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.handler.show_error(e) except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') self.handler.show_error(e) finally: self.handler.finished() diff --git a/electrum/plugins/revealer/qt.py b/electrum/plugins/revealer/qt.py @@ -137,7 +137,7 @@ class Plugin(RevealerPlugin): try: self.make_digital(self.d) except Exception: - traceback.print_exc(file=sys.stdout) + self.logger.exception('') else: self.cypherseed_dialog(window) diff --git a/electrum/plugins/safe_t/clientbase.py b/electrum/plugins/safe_t/clientbase.py @@ -3,9 +3,10 @@ from struct import pack from electrum import ecc from electrum.i18n import _ -from electrum.util import PrintError, UserCancelled +from electrum.util import UserCancelled from electrum.keystore import bip39_normalize_passphrase from electrum.bip32 import BIP32Node, convert_bip32_path_to_list_of_uint32 +from electrum.logging import Logger class GuiMixin(object): @@ -95,7 +96,7 @@ class GuiMixin(object): return self.proto.WordAck(word=word) -class SafeTClientBase(GuiMixin, PrintError): +class SafeTClientBase(GuiMixin, Logger): def __init__(self, handler, plugin, proto): assert hasattr(self, 'tx_api') # ProtocolMixin already constructed? @@ -106,6 +107,7 @@ class SafeTClientBase(GuiMixin, PrintError): self.types = plugin.types self.msg = None self.creating_wallet = False + Logger.__init__(self) self.used() def __str__(self): @@ -139,7 +141,7 @@ class SafeTClientBase(GuiMixin, PrintError): def timeout(self, cutoff): '''Time out the client if the last operation was before cutoff.''' if self.last_operation < cutoff: - self.print_error("timed out") + self.logger.info("timed out") self.clear_session() @staticmethod @@ -192,13 +194,13 @@ class SafeTClientBase(GuiMixin, PrintError): def clear_session(self): '''Clear the session to force pin (and passphrase if enabled) re-entry. Does not leak exceptions.''' - self.print_error("clear session:", self) + self.logger.info(f"clear session: {self}") self.prevent_timeouts() try: super(SafeTClientBase, self).clear_session() except BaseException as e: # If the device was removed it has the same effect... - self.print_error("clear_session: ignoring error", str(e)) + self.logger.info(f"clear_session: ignoring error {e}") def get_public_node(self, address_n, creating): self.creating_wallet = creating @@ -206,7 +208,7 @@ class SafeTClientBase(GuiMixin, PrintError): def close(self): '''Called when Our wallet was closed or the device removed.''' - self.print_error("closing client") + self.logger.info("closing client") self.clear_session() # Release the device self.transport.close() diff --git a/electrum/plugins/safe_t/safe_t.py b/electrum/plugins/safe_t/safe_t.py @@ -115,31 +115,31 @@ class SafeTPlugin(HW_PluginBase): def create_client(self, device, handler): try: - self.print_error("connecting to device at", device.path) + self.logger.info(f"connecting to device at {device.path}") transport = self.transport_handler.get_transport(device.path) except BaseException as e: - self.print_error("cannot connect at", device.path, str(e)) + self.logger.info(f"cannot connect at {device.path} {e}") return None if not transport: - self.print_error("cannot connect at", device.path) + self.logger.info(f"cannot connect at {device.path}") return - self.print_error("connected to device at", device.path) + self.logger.info(f"connected to device at {device.path}") client = self.client_class(transport, handler, self) # Try a ping for device sanity try: client.ping('t') except BaseException as e: - self.print_error("ping failed", str(e)) + self.logger.info(f"ping failed {e}") return None if not client.atleast_version(*self.minimum_firmware): msg = (_('Outdated {} firmware for device labelled {}. Please ' 'download the updated firmware from {}') .format(self.device, client.label(), self.firmware_URL)) - self.print_error(msg) + self.logger.info(msg) if handler: handler.show_error(msg) else: @@ -199,7 +199,7 @@ class SafeTPlugin(HW_PluginBase): except UserCancelled: exit_code = 1 except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') handler.show_error(str(e)) exit_code = 1 finally: diff --git a/electrum/plugins/safe_t/transport.py b/electrum/plugins/safe_t/transport.py @@ -1,7 +1,10 @@ -from electrum.util import PrintError +from electrum.logging import get_logger -class SafeTTransport(PrintError): +_logger = get_logger(__name__) + + +class SafeTTransport: @staticmethod def all_transports(): @@ -71,8 +74,7 @@ class SafeTTransport(PrintError): try: new_devices = transport.enumerate() except BaseException as e: - self.print_error('enumerate failed for {}. error {}' - .format(transport.__name__, str(e))) + _logger.info(f'enumerate failed for {transport.__name__}. error {e}') else: devices.extend(new_devices) return devices diff --git a/electrum/plugins/trezor/clientbase.py b/electrum/plugins/trezor/clientbase.py @@ -3,9 +3,10 @@ from struct import pack from electrum import ecc from electrum.i18n import _ -from electrum.util import PrintError, UserCancelled, UserFacingException +from electrum.util import UserCancelled, UserFacingException from electrum.keystore import bip39_normalize_passphrase from electrum.bip32 import BIP32Node, convert_bip32_path_to_list_of_uint32 as parse_path +from electrum.logging import Logger from trezorlib.client import TrezorClient from trezorlib.exceptions import TrezorFailure, Cancelled, OutdatedFirmwareError @@ -26,12 +27,13 @@ MESSAGES = { } -class TrezorClientBase(PrintError): +class TrezorClientBase(Logger): def __init__(self, transport, handler, plugin): self.client = TrezorClient(transport, ui=self) self.plugin = plugin self.device = plugin.device self.handler = handler + Logger.__init__(self) self.msg = None self.creating_wallet = False @@ -111,7 +113,7 @@ class TrezorClientBase(PrintError): def timeout(self, cutoff): '''Time out the client if the last operation was before cutoff.''' if self.last_operation < cutoff: - self.print_error("timed out") + self.logger.info("timed out") self.clear_session() def i4b(self, x): @@ -158,17 +160,17 @@ class TrezorClientBase(PrintError): def clear_session(self): '''Clear the session to force pin (and passphrase if enabled) re-entry. Does not leak exceptions.''' - self.print_error("clear session:", self) + self.logger.info(f"clear session: {self}") self.prevent_timeouts() try: self.client.clear_session() except BaseException as e: # If the device was removed it has the same effect... - self.print_error("clear_session: ignoring error", str(e)) + self.logger.info(f"clear_session: ignoring error {e}") def close(self): '''Called when Our wallet was closed or the device removed.''' - self.print_error("closing client") + self.logger.info("closing client") self.clear_session() def is_uptodate(self): diff --git a/electrum/plugins/trezor/trezor.py b/electrum/plugins/trezor/trezor.py @@ -11,11 +11,15 @@ from electrum.plugin import Device from electrum.transaction import deserialize, Transaction from electrum.keystore import Hardware_KeyStore, is_xpubkey, parse_xpubkey from electrum.base_wizard import ScriptTypeNotSupported, HWD_SETUP_NEW_WALLET +from electrum.logging import get_logger from ..hw_wallet import HW_PluginBase from ..hw_wallet.plugin import (is_any_tx_output_on_change_branch, trezor_validate_op_return_output_and_get_data, LibraryFoundButUnusable) +_logger = get_logger(__name__) + + try: import trezorlib import trezorlib.transport @@ -32,8 +36,7 @@ try: TREZORLIB = True except Exception as e: - import traceback - traceback.print_exc() + _logger.exception('error importing trezorlib') TREZORLIB = False RECOVERY_TYPE_SCRAMBLED_WORDS, RECOVERY_TYPE_MATRIX = range(2) @@ -145,17 +148,17 @@ class TrezorPlugin(HW_PluginBase): def create_client(self, device, handler): try: - self.print_error("connecting to device at", device.path) + self.logger.info(f"connecting to device at {device.path}") transport = trezorlib.transport.get_transport(device.path) except BaseException as e: - self.print_error("cannot connect at", device.path, str(e)) + self.logger.info(f"cannot connect at {device.path} {e}") return None if not transport: - self.print_error("cannot connect at", device.path) + self.logger.info(f"cannot connect at {device.path}") return - self.print_error("connected to device at", device.path) + self.logger.info(f"connected to device at {device.path}") # note that this call can still raise! return TrezorClientBase(transport, handler, self) @@ -208,7 +211,7 @@ class TrezorPlugin(HW_PluginBase): except UserCancelled: exit_code = 1 except BaseException as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') handler.show_error(str(e)) exit_code = 1 finally: diff --git a/electrum/plugins/trustedcoin/cmdline.py b/electrum/plugins/trustedcoin/cmdline.py @@ -34,12 +34,12 @@ class Plugin(TrustedCoinPlugin): if not isinstance(wallet, self.wallet_class): return if not wallet.can_sign_without_server(): - self.print_error("twofactor:sign_tx") + self.logger.info("twofactor:sign_tx") auth_code = None if wallet.keystores['x3/'].get_tx_derivations(tx): msg = _('Please enter your Google Authenticator code:') auth_code = int(input(msg)) else: - self.print_error("twofactor: xpub3 not needed") + self.logger.info("twofactor: xpub3 not needed") wallet.auth_code = auth_code diff --git a/electrum/plugins/trustedcoin/qt.py b/electrum/plugins/trustedcoin/qt.py @@ -41,7 +41,9 @@ from electrum.gui.qt.main_window import StatusBarButton from electrum.gui.qt.installwizard import InstallWizard from electrum.i18n import _ from electrum.plugin import hook -from electrum.util import PrintError, is_valid_email +from electrum.util import is_valid_email +from electrum.logging import Logger + from .trustedcoin import TrustedCoinPlugin, server @@ -50,12 +52,13 @@ class TOS(QTextEdit): error_signal = pyqtSignal(object) -class HandlerTwoFactor(QObject, PrintError): +class HandlerTwoFactor(QObject, Logger): def __init__(self, plugin, window): - super().__init__() + QObject.__init__(self) self.plugin = plugin self.window = window + Logger.__init__(self) def prompt_user_for_otp(self, wallet, tx, on_success, on_failure): if not isinstance(wallet, self.plugin.wallet_class): @@ -63,7 +66,7 @@ class HandlerTwoFactor(QObject, PrintError): if wallet.can_sign_without_server(): return if not wallet.keystores['x3/'].get_tx_derivations(tx): - self.print_error("twofactor: xpub3 not needed") + self.logger.info("twofactor: xpub3 not needed") return window = self.window.top_level_window() auth_code = self.plugin.auth_dialog(window) @@ -243,8 +246,7 @@ class Plugin(TrustedCoinPlugin): try: tos = server.get_terms_of_service() except Exception as e: - import traceback - traceback.print_exc(file=sys.stderr) + self.logger.exception('Could not retrieve Terms of Service') tos_e.error_signal.emit(_('Could not retrieve Terms of Service:') + '\n' + str(e)) return diff --git a/electrum/plugins/trustedcoin/trustedcoin.py b/electrum/plugins/trustedcoin/trustedcoin.py @@ -37,17 +37,19 @@ from aiohttp import ClientResponse from electrum import ecc, constants, keystore, version, bip32, bitcoin from electrum.bitcoin import TYPE_ADDRESS -from electrum.bip32 import CKD_pub, BIP32Node, xpub_type +from electrum.bip32 import BIP32Node, xpub_type from electrum.crypto import sha256 from electrum.transaction import TxOutput from electrum.mnemonic import Mnemonic, seed_type, is_any_2fa_seed_type from electrum.wallet import Multisig_Wallet, Deterministic_Wallet from electrum.i18n import _ from electrum.plugin import BasePlugin, hook -from electrum.util import NotEnoughFunds, UserFacingException, PrintError +from electrum.util import NotEnoughFunds, UserFacingException from electrum.storage import STO_EV_USER_PW from electrum.network import Network from electrum.base_wizard import BaseWizard +from electrum.logging import Logger + def get_signing_xpub(xtype): if not constants.net.TESTNET: @@ -117,11 +119,12 @@ class ErrorConnectingServer(Exception): return f"{header}:\n{reason}" if reason else header -class TrustedCoinCosignerClient(PrintError): +class TrustedCoinCosignerClient(Logger): def __init__(self, user_agent=None, base_url='https://api.trustedcoin.com/2/'): self.base_url = base_url self.debug = False self.user_agent = user_agent + Logger.__init__(self) async def handle_response(self, resp: ClientResponse): if resp.status != 200: @@ -142,7 +145,7 @@ class TrustedCoinCosignerClient(PrintError): raise ErrorConnectingServer('You are offline.') url = urljoin(self.base_url, relative_url) if self.debug: - self.print_error(f'<-- {method} {url} {data}') + self.logger.debug(f'<-- {method} {url} {data}') headers = {} if self.user_agent: headers['user-agent'] = self.user_agent @@ -167,7 +170,7 @@ class TrustedCoinCosignerClient(PrintError): raise ErrorConnectingServer(e) else: if self.debug: - self.print_error(f'--> {response}') + self.logger.debug(f'--> {response}') return response def get_terms_of_service(self, billing_plan='electrum-per-tx-otp'): @@ -327,14 +330,14 @@ class Wallet_2fa(Multisig_Wallet): tx = mk_tx(outputs) if tx.input_value() >= fee: raise - self.print_error("not charging for this tx") + self.logger.info("not charging for this tx") else: tx = mk_tx(outputs) return tx def on_otp(self, tx, otp): if not otp: - self.print_error("sign_transaction: no auth code") + self.logger.info("sign_transaction: no auth code") return otp = int(otp) long_user_id, short_id = self.get_user_id() @@ -349,7 +352,7 @@ class Wallet_2fa(Multisig_Wallet): if r: raw_tx = r.get('transaction') tx.update(raw_tx) - self.print_error("twofactor: is complete", tx.is_complete()) + self.logger.info(f"twofactor: is complete {tx.is_complete()}") # reset billing_info self.billing_info = None self.plugin.start_request_thread(self) @@ -451,7 +454,7 @@ class TrustedCoinPlugin(BasePlugin): if wallet.can_sign_without_server(): return if not wallet.keystores['x3/'].get_tx_derivations(tx): - self.print_error("twofactor: xpub3 not needed") + self.logger.info("twofactor: xpub3 not needed") return def wrapper(tx): self.prompt_user_for_otp(wallet, tx, on_success, on_failure) @@ -477,12 +480,12 @@ class TrustedCoinPlugin(BasePlugin): def request_billing_info(self, wallet: 'Wallet_2fa', *, suppress_connection_error=True): if wallet.can_sign_without_server(): return - self.print_error("request billing info") + self.logger.info("request billing info") try: billing_info = server.get(wallet.get_user_id()[1]) except ErrorConnectingServer as e: if suppress_connection_error: - self.print_error(str(e)) + self.logger.info(str(e)) return raise billing_index = billing_info['billing_index'] diff --git a/electrum/simple_config.py b/electrum/simple_config.py @@ -10,9 +10,11 @@ from numbers import Real from copy import deepcopy from . import util -from .util import (user_dir, print_error, PrintError, make_dir, +from .util import (user_dir, make_dir, NoDynamicFeeEstimates, format_fee_satoshis, quantize_feerate) from .i18n import _ +from .logging import get_logger, Logger + FEE_ETA_TARGETS = [25, 10, 5, 2] FEE_DEPTH_TARGETS = [10000000, 5000000, 2000000, 1000000, 500000, 200000, 100000] @@ -27,6 +29,7 @@ FEERATE_STATIC_VALUES = [1000, 2000, 5000, 10000, 20000, 30000, config = None +_logger = get_logger(__name__) def get_config(): @@ -42,7 +45,7 @@ def set_config(c): FINAL_CONFIG_VERSION = 3 -class SimpleConfig(PrintError): +class SimpleConfig(Logger): """ The SimpleConfig class is responsible for handling operations involving configuration files. @@ -59,6 +62,8 @@ class SimpleConfig(PrintError): if options is None: options = {} + Logger.__init__(self) + # This lock needs to be acquired for updating and reading the config in # a thread-safe way. self.lock = threading.RLock() @@ -119,7 +124,7 @@ class SimpleConfig(PrintError): path = os.path.join(path, 'simnet') make_dir(path, allow_symlink=False) - self.print_error("electrum directory", path) + self.logger.info(f"electrum directory {path}") return path def rename_config_keys(self, config, keypairs, deprecation_warning=False): @@ -130,21 +135,21 @@ class SimpleConfig(PrintError): if new_key not in config: config[new_key] = config[old_key] if deprecation_warning: - self.print_stderr('Note that the {} variable has been deprecated. ' - 'You should use {} instead.'.format(old_key, new_key)) + self.logger.warning('Note that the {} variable has been deprecated. ' + 'You should use {} instead.'.format(old_key, new_key)) del config[old_key] updated = True return updated def set_key(self, key, value, save=True): if not self.is_modifiable(key): - self.print_stderr("Warning: not changing config key '%s' set on the command line" % key) + self.logger.warning(f"not changing config key '{key}' set on the command line") return try: json.dumps(key) json.dumps(value) except: - self.print_error(f"json error: cannot save {repr(key)} ({repr(value)})") + self.logger.info(f"json error: cannot save {repr(key)} ({repr(value)})") return self._set_key_in_user_config(key, value, save) @@ -169,7 +174,7 @@ class SimpleConfig(PrintError): def upgrade(self): with self.lock: - self.print_error('upgrading config') + self.logger.info('upgrading config') self.convert_version_2() self.convert_version_3() @@ -222,8 +227,8 @@ class SimpleConfig(PrintError): def get_config_version(self): config_version = self.get('config_version', 1) if config_version > FINAL_CONFIG_VERSION: - self.print_stderr('WARNING: config version ({}) is higher than ours ({})' - .format(config_version, FINAL_CONFIG_VERSION)) + self.logger.warning('config version ({}) is higher than latest ({})' + .format(config_version, FINAL_CONFIG_VERSION)) return config_version def is_modifiable(self, key): @@ -276,7 +281,7 @@ class SimpleConfig(PrintError): self.set_key('recently_open', recent) def set_session_timeout(self, seconds): - self.print_error("session timeout -> %d seconds" % seconds) + self.logger.info(f"session timeout -> {seconds} seconds") self.set_key('session_timeout', seconds) def get_session_timeout(self): @@ -576,7 +581,7 @@ def read_user_config(path): data = f.read() result = json.loads(data) except: - print_error("Warning: Cannot read config file.", config_path) + _logger.warning(f"Cannot read config file. {config_path}") return {} if not type(result) is dict: return {} diff --git a/electrum/storage.py b/electrum/storage.py @@ -30,10 +30,11 @@ import base64 import zlib from . import ecc -from .util import PrintError, profiler, InvalidPassword, WalletFileException, bfh, standardize_path +from .util import profiler, InvalidPassword, WalletFileException, bfh, standardize_path from .plugin import run_hook, plugin_loaders from .json_db import JsonDB +from .logging import Logger def get_derivation_used_for_hw_device_encryption(): @@ -46,15 +47,16 @@ STO_EV_PLAINTEXT, STO_EV_USER_PW, STO_EV_XPUB_PW = range(0, 3) -class WalletStorage(PrintError): +class WalletStorage(Logger): def __init__(self, path, *, manual_upgrades=False): + Logger.__init__(self) self.lock = threading.RLock() self.path = standardize_path(path) self._file_exists = self.path and os.path.exists(self.path) DB_Class = JsonDB - self.print_error("wallet path", self.path) + self.logger.info(f"wallet path {self.path}") self.pubkey = None if self.file_exists(): with open(self.path, "r", encoding='utf-8') as f: @@ -87,7 +89,7 @@ class WalletStorage(PrintError): def _write(self): if threading.currentThread().isDaemon(): - self.print_error('warning: daemon thread cannot write db') + self.logger.warning('daemon thread cannot write db') return if not self.db.modified(): return @@ -105,7 +107,7 @@ class WalletStorage(PrintError): os.replace(temp_path, self.path) os.chmod(self.path, mode) self._file_exists = True - self.print_error("saved", self.path) + self.logger.info(f"saved {self.path}") self.db.set_modified(False) def file_exists(self): diff --git a/electrum/synchronizer.py b/electrum/synchronizer.py @@ -33,6 +33,7 @@ from .transaction import Transaction from .util import bh2u, make_aiohttp_session, NetworkJobOnDefaultServer from .bitcoin import address_to_scripthash, is_address from .network import UntrustedServerReturnedError +from .logging import Logger if TYPE_CHECKING: from .network import Network @@ -131,7 +132,7 @@ class Synchronizer(SynchronizerBase): self.requested_histories = {} def diagnostic_name(self): - return '{}:{}'.format(self.__class__.__name__, self.wallet.diagnostic_name()) + return self.wallet.diagnostic_name() def is_up_to_date(self): return (not self.requested_addrs @@ -148,7 +149,7 @@ class Synchronizer(SynchronizerBase): self.requested_histories[addr] = status h = address_to_scripthash(addr) result = await self.network.get_history_for_scripthash(h) - self.print_error("receiving history", addr, len(result)) + self.logger.info(f"receiving history {addr} {len(result)}") hashes = set(map(lambda item: item['tx_hash'], result)) hist = list(map(lambda item: (item['tx_hash'], item['height']), result)) # tx_fees @@ -156,10 +157,10 @@ class Synchronizer(SynchronizerBase): tx_fees = dict(filter(lambda x:x[1] is not None, tx_fees)) # Check that txids are unique if len(hashes) != len(result): - self.print_error("error: server history has non-unique txids: %s"% addr) + self.logger.info(f"error: server history has non-unique txids: {addr}") # Check that the status corresponds to what was announced elif history_status(hist) != status: - self.print_error("error: status mismatch: %s" % addr) + self.logger.info(f"error: status mismatch: {addr}") else: # Store received history self.wallet.receive_history_callback(addr, hist, tx_fees) @@ -209,7 +210,7 @@ class Synchronizer(SynchronizerBase): raise SynchronizerFailure(f"received tx does not match expected txid ({tx_hash} != {tx.txid()})") tx_height = self.requested_tx.pop(tx_hash) self.wallet.receive_tx_callback(tx_hash, tx, tx_height) - self.print_error(f"received tx {tx_hash} height: {tx_height} bytes: {len(tx.raw)}") + self.logger.info(f"received tx {tx_hash} height: {tx_height} bytes: {len(tx.raw)}") # callbacks self.wallet.network.trigger_callback('new_transaction', self.wallet, tx) @@ -257,7 +258,7 @@ class Notifier(SynchronizerBase): await self._add_address(addr) async def _on_address_status(self, addr, status): - self.print_error('new status for addr {}'.format(addr)) + self.logger.info(f'new status for addr {addr}') headers = {'content-type': 'application/json'} data = {'address': addr, 'status': status} for url in self.watched_addresses[addr]: @@ -266,6 +267,6 @@ class Notifier(SynchronizerBase): async with session.post(url, json=data, headers=headers) as resp: await resp.text() except Exception as e: - self.print_error(str(e)) + self.logger.info(str(e)) else: - self.print_error('Got Response for {}'.format(addr)) + self.logger.info(f'Got Response for {addr}') diff --git a/electrum/transaction.py b/electrum/transaction.py @@ -34,7 +34,7 @@ from typing import (Sequence, Union, NamedTuple, Tuple, Optional, Iterable, Callable, List, Dict) from . import ecc, bitcoin, constants, segwit_addr -from .util import print_error, profiler, to_bytes, bh2u, bfh +from .util import profiler, to_bytes, bh2u, bfh from .bitcoin import (TYPE_ADDRESS, TYPE_PUBKEY, TYPE_SCRIPT, hash_160, hash160_to_p2sh, hash160_to_p2pkh, hash_to_segwit_addr, hash_encode, var_int, TOTAL_COIN_SUPPLY_LIMIT_IN_BTC, COIN, @@ -42,6 +42,10 @@ from .bitcoin import (TYPE_ADDRESS, TYPE_PUBKEY, TYPE_SCRIPT, hash_160, opcodes, add_number_to_script, base_decode, is_segwit_script_type) from .crypto import sha256d from .keystore import xpubkey_to_address, xpubkey_to_pubkey +from .logging import get_logger + + +_logger = get_logger(__name__) NO_SIGNATURE = 'ff' @@ -269,8 +273,7 @@ def parse_scriptSig(d, _bytes): decoded = [ x for x in script_GetOp(_bytes) ] except Exception as e: # coinbase transactions raise an exception - print_error("parse_scriptSig: cannot find address in input script (coinbase?)", - bh2u(_bytes)) + _logger.info(f"parse_scriptSig: cannot find address in input script (coinbase?) {bh2u(_bytes)}") return match = [OPPushDataGeneric] @@ -285,7 +288,7 @@ def parse_scriptSig(d, _bytes): elif len(item) == 34: d['type'] = 'p2wsh-p2sh' else: - print_error("unrecognized txin type", bh2u(item)) + _logger.info(f"unrecognized txin type {bh2u(item)}") elif opcodes.OP_1 <= item[0] <= opcodes.OP_16: # segwit embedded into p2sh # witness version 1-16 @@ -312,8 +315,7 @@ def parse_scriptSig(d, _bytes): signatures = parse_sig([sig]) pubkey, address = xpubkey_to_address(x_pubkey) except: - print_error("parse_scriptSig: cannot find address in input script (p2pkh?)", - bh2u(_bytes)) + _logger.info(f"parse_scriptSig: cannot find address in input script (p2pkh?) {bh2u(_bytes)}") return d['type'] = 'p2pkh' d['signatures'] = signatures @@ -331,8 +333,8 @@ def parse_scriptSig(d, _bytes): try: m, n, x_pubkeys, pubkeys, redeem_script = parse_redeemScript_multisig(redeem_script_unsanitized) except NotRecognizedRedeemScript: - print_error("parse_scriptSig: cannot find address in input script (p2sh?)", - bh2u(_bytes)) + _logger.info(f"parse_scriptSig: cannot find address in input script (p2sh?) {bh2u(_bytes)}") + # we could still guess: # d['address'] = hash160_to_p2sh(hash_160(decoded[-1][1])) return @@ -359,8 +361,7 @@ def parse_scriptSig(d, _bytes): d['signatures'] = [None] return - print_error("parse_scriptSig: cannot find address in input script (unknown)", - bh2u(_bytes)) + _logger.info(f"parse_scriptSig: cannot find address in input script (unknown) {bh2u(_bytes)}") def parse_redeemScript_multisig(redeem_script: bytes): @@ -445,8 +446,7 @@ def parse_input(vds, full_parse: bool): try: parse_scriptSig(d, scriptSig) except BaseException: - traceback.print_exc(file=sys.stderr) - print_error('failed to parse scriptSig', bh2u(scriptSig)) + _logger.exception(f'failed to parse scriptSig {bh2u(scriptSig)}') return d @@ -512,8 +512,7 @@ def parse_witness(vds, txin, full_parse: bool): txin['type'] = 'unknown' except BaseException: txin['type'] = 'unknown' - traceback.print_exc(file=sys.stderr) - print_error('failed to parse witness', txin.get('witness')) + _logger.exception(f"failed to parse witness {txin.get('witness')}") def parse_output(vds, i): @@ -664,10 +663,10 @@ class Transaction: try: public_key.verify_message_hash(sig_string, pre_hash) except Exception: - traceback.print_exc(file=sys.stderr) + _logger.exception('') continue j = pubkeys.index(pubkey_hex) - print_error("adding sig", i, j, pubkey_hex, sig) + _logger.info(f"adding sig {i} {j} {pubkey_hex} {sig}") self.add_signature_to_txin(i, j, sig) break # redo raw @@ -1138,12 +1137,12 @@ class Transaction: _pubkey = x_pubkey else: continue - print_error("adding signature for", _pubkey) + _logger.info(f"adding signature for {_pubkey}") sec, compressed = keypairs.get(_pubkey) sig = self.sign_txin(i, sec) self.add_signature_to_txin(i, j, sig) - print_error("is_complete", self.is_complete()) + _logger.info(f"is_complete {self.is_complete()}") self.raw = self.serialize() def sign_txin(self, txin_index, privkey_bytes) -> str: diff --git a/electrum/util.py b/electrum/util.py @@ -47,6 +47,7 @@ from aiorpcx import TaskGroup import certifi from .i18n import _ +from .logging import get_logger, Logger if TYPE_CHECKING: from .network import Network @@ -54,6 +55,9 @@ if TYPE_CHECKING: from .simple_config import SimpleConfig +_logger = get_logger(__name__) + + def inv_dict(d): return {v: k for k, v in d.items()} @@ -214,34 +218,15 @@ class MyEncoder(json.JSONEncoder): return list(obj) return super().default(obj) -class PrintError(object): - '''A handy base class''' - verbosity_filter = '' - - def diagnostic_name(self): - return '' - - def log_name(self): - msg = self.verbosity_filter or self.__class__.__name__ - d = self.diagnostic_name() - if d: msg += "][" + d - return "[%s]" % msg - - def print_error(self, *msg): - if self.verbosity_filter in verbosity or verbosity == '*': - print_error(self.log_name(), *msg) - - def print_stderr(self, *msg): - print_stderr(self.log_name(), *msg) - - def print_msg(self, *msg): - print_msg(self.log_name(), *msg) -class ThreadJob(PrintError): +class ThreadJob(Logger): """A job that is run periodically from a thread's main loop. run() is called from that thread's context. """ + def __init__(self): + Logger.__init__(self) + def run(self): """Called periodically from the thread""" pass @@ -249,13 +234,14 @@ class ThreadJob(PrintError): class DebugMem(ThreadJob): '''A handy class for debugging GC memory leaks''' def __init__(self, classes, interval=30): + ThreadJob.__init__(self) self.next_time = 0 self.classes = classes self.interval = interval def mem_stats(self): import gc - self.print_error("Start memscan") + self.logger.info("Start memscan") gc.collect() objmap = defaultdict(list) for obj in gc.get_objects(): @@ -263,20 +249,20 @@ class DebugMem(ThreadJob): if isinstance(obj, class_): objmap[class_].append(obj) for class_, objs in objmap.items(): - self.print_error("%s: %d" % (class_.__name__, len(objs))) - self.print_error("Finish memscan") + self.logger.info(f"{class_.__name__}: {len(objs)}") + self.logger.info("Finish memscan") def run(self): if time.time() > self.next_time: self.mem_stats() self.next_time = time.time() + self.interval -class DaemonThread(threading.Thread, PrintError): +class DaemonThread(threading.Thread, Logger): """ daemon thread that terminates cleanly """ - verbosity_filter = 'd' def __init__(self): threading.Thread.__init__(self) + Logger.__init__(self) self.parent_thread = threading.currentThread() self.running = False self.running_lock = threading.Lock() @@ -296,7 +282,7 @@ class DaemonThread(threading.Thread, PrintError): try: job.run() except Exception as e: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') def remove_jobs(self, jobs): with self.job_lock: @@ -320,22 +306,9 @@ class DaemonThread(threading.Thread, PrintError): if 'ANDROID_DATA' in os.environ: import jnius jnius.detach() - self.print_error("jnius detach") - self.print_error("stopped") - - -verbosity = '' -def set_verbosity(filters: Union[str, bool]): - global verbosity - if type(filters) is bool: # backwards compat - verbosity = '*' if filters else '' - return - verbosity = filters - + self.logger.info("jnius detach") + self.logger.info("stopped") -def print_error(*args): - if not verbosity: return - print_stderr(*args) def print_stderr(*args): args = [str(item) for item in args] @@ -369,13 +342,14 @@ def constant_time_compare(val1, val2): # decorator that prints execution time +_profiler_logger = _logger.getChild('profiler') def profiler(func): def do_profile(args, kw_args): name = func.__qualname__ t0 = time.time() o = func(*args, **kw_args) t = time.time() - t0 - print_error("[profiler]", name, "%.4f"%t) + _profiler_logger.debug(f"{name} {t:,.4f}") return o return lambda *args, **kw_args: do_profile(args, kw_args) @@ -393,7 +367,7 @@ def ensure_sparse_file(filename): try: os.system('fsutil sparse setflag "{}" 1'.format(filename)) except Exception as e: - print_error('error marking file {} as sparse: {}'.format(filename, e)) + _logger.info(f'error marking file {filename} as sparse: {e}') def get_headers_dir(config): @@ -893,10 +867,10 @@ def import_meta(path, validater, load_meta): load_meta(d) #backwards compatibility for JSONDecodeError except ValueError: - traceback.print_exc(file=sys.stderr) + _logger.exception('') raise FileImportFailed(_("Invalid JSON code.")) except BaseException as e: - traceback.print_exc(file=sys.stdout) + _logger.exception('') raise FileImportFailed(e) @@ -905,7 +879,7 @@ def export_meta(meta, fileName): with open(fileName, 'w+', encoding='utf-8') as f: json.dump(meta, f, indent=4, sort_keys=True) except (IOError, os.error) as e: - traceback.print_exc(file=sys.stderr) + _logger.exception('') raise FileExportFailed(e) @@ -928,12 +902,11 @@ def log_exceptions(func): except asyncio.CancelledError as e: raise except BaseException as e: - print_ = self.print_error if hasattr(self, 'print_error') else print_error - print_("Exception in", func.__name__, ":", repr(e)) + mylogger = self.logger if hasattr(self, 'logger') else _logger try: - traceback.print_exc(file=sys.stderr) + mylogger.exception(f"Exception in {func.__name__}: {repr(e)}") except BaseException as e2: - print_error("traceback.print_exc raised: {}...".format(e2)) + print(f"logging exception raised: {repr(e2)}... orig exc: {repr(e)} in {func.__name__}") raise return wrapper @@ -991,12 +964,13 @@ class SilentTaskGroup(TaskGroup): return super().spawn(*args, **kwargs) -class NetworkJobOnDefaultServer(PrintError): +class NetworkJobOnDefaultServer(Logger): """An abstract base class for a job that runs on the main network interface. Every time the main interface changes, the job is restarted, and some of its internals are reset. """ def __init__(self, network: 'Network'): + Logger.__init__(self) asyncio.set_event_loop(network.asyncio_loop) self.network = network self.interface = None # type: Interface diff --git a/electrum/verifier.py b/electrum/verifier.py @@ -63,7 +63,7 @@ class SPV(NetworkJobOnDefaultServer): await group.spawn(self.main) def diagnostic_name(self): - return '{}:{}'.format(self.__class__.__name__, self.wallet.diagnostic_name()) + return self.wallet.diagnostic_name() async def main(self): self.blockchain = self.network.blockchain() @@ -90,7 +90,7 @@ class SPV(NetworkJobOnDefaultServer): await self.group.spawn(self.network.request_chunk(tx_height, None, can_return_early=True)) continue # request now - self.print_error('requested merkle', tx_hash) + self.logger.info(f'requested merkle {tx_hash}') self.requested_merkle.add(tx_hash) await self.group.spawn(self._request_and_verify_single_proof, tx_hash, tx_height) @@ -100,14 +100,14 @@ class SPV(NetworkJobOnDefaultServer): except UntrustedServerReturnedError as e: if not isinstance(e.original_exception, aiorpcx.jsonrpc.RPCError): raise - self.print_error('tx {} not at height {}'.format(tx_hash, tx_height)) + self.logger.info(f'tx {tx_hash} not at height {tx_height}') self.wallet.remove_unverified_tx(tx_hash, tx_height) self.requested_merkle.discard(tx_hash) return # Verify the hash of the server-provided merkle branch to a # transaction matches the merkle root of its block if tx_height != merkle.get('block_height'): - self.print_error('requested tx_height {} differs from received tx_height {} for txid {}' + self.logger.info('requested tx_height {} differs from received tx_height {} for txid {}' .format(tx_height, merkle.get('block_height'), tx_hash)) tx_height = merkle.get('block_height') pos = merkle.get('pos') @@ -119,14 +119,14 @@ class SPV(NetworkJobOnDefaultServer): verify_tx_is_in_block(tx_hash, merkle_branch, pos, header, tx_height) except MerkleVerificationFailure as e: if self.network.config.get("skipmerklecheck"): - self.print_error("skipping merkle proof check %s" % tx_hash) + self.logger.info(f"skipping merkle proof check {tx_hash}") else: - self.print_error(str(e)) + self.logger.info(str(e)) raise GracefulDisconnect(e) # we passed all the tests self.merkle_roots[tx_hash] = header.get('merkle_root') self.requested_merkle.discard(tx_hash) - self.print_error("verified %s" % tx_hash) + self.logger.info(f"verified {tx_hash}") header_hash = hash_header(header) tx_info = TxMinedInfo(height=tx_height, timestamp=header.get('timestamp'), @@ -171,10 +171,10 @@ class SPV(NetworkJobOnDefaultServer): if cur_chain != old_chain: self.blockchain = cur_chain above_height = cur_chain.get_height_of_last_common_block_with_chain(old_chain) - self.print_error(f"undoing verifications above height {above_height}") + self.logger.info(f"undoing verifications above height {above_height}") tx_hashes = self.wallet.undo_verifications(self.blockchain, above_height) for tx_hash in tx_hashes: - self.print_error("redoing", tx_hash) + self.logger.info(f"redoing {tx_hash}") self.remove_spv_proof_for_tx(tx_hash) def remove_spv_proof_for_tx(self, tx_hash): diff --git a/electrum/wallet.py b/electrum/wallet.py @@ -41,11 +41,11 @@ from decimal import Decimal from typing import TYPE_CHECKING, List, Optional, Tuple, Union, NamedTuple from .i18n import _ -from .util import (NotEnoughFunds, PrintError, UserCancelled, profiler, +from .util import (NotEnoughFunds, UserCancelled, profiler, format_satoshis, format_fee_satoshis, NoDynamicFeeEstimates, WalletFileException, BitcoinException, InvalidPassword, format_time, timestamp_to_datetime, Satoshis, - Fiat, bfh, bh2u, TxMinedInfo, print_error) + Fiat, bfh, bh2u, TxMinedInfo) from .bitcoin import (COIN, TYPE_ADDRESS, is_address, address_to_script, is_minikey, relayfee, dust_threshold) from .crypto import sha256d @@ -64,12 +64,15 @@ from .contacts import Contacts from .interface import RequestTimedOut from .ecc_fast import is_using_fast_ecc from .mnemonic import Mnemonic +from .logging import get_logger if TYPE_CHECKING: from .network import Network from .simple_config import SimpleConfig +_logger = get_logger(__name__) + TX_STATUS = [ _('Unconfirmed'), _('Unconfirmed parent'), @@ -200,7 +203,6 @@ class Abstract_Wallet(AddressSynchronizer): max_change_outputs = 3 gap_limit_for_change = 6 - verbosity_filter = 'w' def __init__(self, storage: WalletStorage): if storage.requires_upgrade(): @@ -825,9 +827,9 @@ class Abstract_Wallet(AddressSynchronizer): # wait until we are connected, because the user # might have selected another server if self.network: - self.print_error("waiting for network...") + self.logger.info("waiting for network...") wait_for_network() - self.print_error("waiting while wallet is syncing...") + self.logger.info("waiting while wallet is syncing...") wait_for_wallet() else: self.synchronize() @@ -940,7 +942,7 @@ class Abstract_Wallet(AddressSynchronizer): raw_tx = self.network.run_from_another_thread( self.network.get_transaction(tx_hash, timeout=10)) except RequestTimedOut as e: - self.print_error(f'getting input txn from network timed out for {tx_hash}') + self.logger.info(f'getting input txn from network timed out for {tx_hash}') if not ignore_timeout: raise e else: @@ -1066,7 +1068,7 @@ class Abstract_Wallet(AddressSynchronizer): try: baseurl = baseurl.replace(*rewrite) except BaseException as e: - self.print_stderr('Invalid config setting for "url_rewrite". err:', e) + self.logger.info(f'Invalid config setting for "url_rewrite". err: {e}') out['request_url'] = os.path.join(baseurl, 'req', key[0], key[1], key, key) out['URI'] += '&r=' + out['request_url'] out['index_url'] = os.path.join(baseurl, 'index.html') + '?id=' + key @@ -1569,7 +1571,7 @@ class Deterministic_Wallet(Abstract_Wallet): @profiler def try_detecting_internal_addresses_corruption(self): if not is_using_fast_ecc(): - self.print_error("internal address corruption test skipped due to missing libsecp256k1") + self.logger.info("internal address corruption test skipped due to missing libsecp256k1") return addresses_all = self.get_addresses() # sample 1: first few @@ -1929,7 +1931,7 @@ def restore_wallet_from_text(text, *, path, network, passphrase=None, password=N if network: wallet.start_network(network) - print_error("Recovering wallet...") + _logger.info("Recovering wallet...") wallet.wait_until_synchronized() wallet.stop_threads() # note: we don't wait for SPV diff --git a/electrum/websockets.py b/electrum/websockets.py @@ -36,9 +36,9 @@ try: except ImportError: sys.exit("install SimpleWebSocketServer") -from .util import PrintError from . import bitcoin from .synchronizer import SynchronizerBase +from .logging import Logger if TYPE_CHECKING: from .network import Network @@ -48,20 +48,24 @@ if TYPE_CHECKING: request_queue = asyncio.Queue() -class ElectrumWebSocket(WebSocket, PrintError): +class ElectrumWebSocket(WebSocket, Logger): + + def __init__(self): + WebSocket.__init__(self) + Logger.__init__(self) def handleMessage(self): assert self.data[0:3] == 'id:' - self.print_error("message received", self.data) + self.logger.info(f"message received {self.data}") request_id = self.data[3:] asyncio.run_coroutine_threadsafe( request_queue.put((self, request_id)), asyncio.get_event_loop()) def handleConnected(self): - self.print_error("connected", self.address) + self.logger.info(f"connected {self.address}") def handleClose(self): - self.print_error("closed", self.address) + self.logger.info(f"closed {self.address}") class BalanceMonitor(SynchronizerBase): @@ -92,13 +96,13 @@ class BalanceMonitor(SynchronizerBase): try: addr, amount = self.make_request(request_id) except Exception: - traceback.print_exc(file=sys.stderr) + self.logger.exception('') continue self.expected_payments[addr].append((ws, amount)) await self._add_address(addr) async def _on_address_status(self, addr, status): - self.print_error('new status for addr {}'.format(addr)) + self.logger.info(f'new status for addr {addr}') sh = bitcoin.address_to_scripthash(addr) balance = await self.network.get_balance_for_scripthash(sh) for ws, amount in self.expected_payments[addr]: diff --git a/electrum/x509.py b/electrum/x509.py @@ -31,6 +31,10 @@ import ecdsa from . import util from .util import profiler, bh2u +from .logging import get_logger + + +_logger = get_logger(__name__) # algo OIDs @@ -328,7 +332,7 @@ def load_certificates(ca_path): except BaseException as e: # with open('/tmp/tmp.txt', 'w') as f: # f.write(pem.pem(b, 'CERTIFICATE').decode('ascii')) - util.print_error("cert error:", e) + _logger.info(f"cert error: {e}") continue fp = x.getFingerprint() @@ -341,6 +345,5 @@ def load_certificates(ca_path): if __name__ == "__main__": import certifi - util.set_verbosity(True) ca_path = certifi.where() ca_list, ca_keyID = load_certificates(ca_path) diff --git a/run_electrum b/run_electrum @@ -76,17 +76,21 @@ if not is_android: check_imports() +from electrum.logging import get_logger, configure_logging from electrum import util from electrum import constants from electrum import SimpleConfig from electrum.wallet import Wallet from electrum.storage import WalletStorage, get_derivation_used_for_hw_device_encryption from electrum.util import print_msg, print_stderr, json_encode, json_decode, UserCancelled -from electrum.util import set_verbosity, InvalidPassword +from electrum.util import InvalidPassword from electrum.commands import get_parser, known_commands, Commands, config_variables from electrum import daemon from electrum import keystore +_logger = get_logger(__name__) + + # get password routine def prompt_password(prompt, confirm=True): import getpass @@ -184,12 +188,12 @@ def get_connected_hw_devices(plugins): name, plugin = splugin.name, splugin.plugin if not plugin: e = splugin.exception - print_stderr(f"{name}: error during plugin init: {repr(e)}") + _logger.error(f"{name}: error during plugin init: {repr(e)}") continue try: u = devmgr.unpaired_device_infos(None, plugin) - except: - devmgr.print_error(f'error getting device infos for {name}: {e}') + except Exception as e: + _logger.error(f'error getting device infos for {name}: {repr(e)}') continue devices += list(map(lambda x: (name, x), u)) return devices @@ -273,6 +277,9 @@ if __name__ == '__main__': sys.argv.append('-h') # old '-v' syntax + # Due to this workaround that keeps old -v working, + # more advanced usages of -v need to use '-v='. + # e.g. -v=debug,network=warning,interface=error try: i = sys.argv.index('-v') except ValueError: @@ -320,10 +327,7 @@ if __name__ == '__main__': if config_options.get('portable'): config_options['electrum_path'] = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'electrum_data') - # kivy sometimes freezes when we write to sys.stderr - log_verbosity = config_options.get('verbosity') if config_options.get('gui') != 'kivy' else '' - set_verbosity(log_verbosity) - if not log_verbosity: + if not config_options.get('verbosity'): warnings.simplefilter('ignore', DeprecationWarning) # check uri @@ -336,6 +340,8 @@ if __name__ == '__main__': # todo: defer this to gui config = SimpleConfig(config_options) + configure_logging(config) + cmdname = config.get('cmd') if config.get('testnet'):