diff --git a/freqtrade/analyze.py b/freqtrade/analyze.py index 8bc552d74..076d3d265 100644 --- a/freqtrade/analyze.py +++ b/freqtrade/analyze.py @@ -1,6 +1,7 @@ """ Functions to analyze ticker data with indicators and produce buy and sell signals """ +import logging from datetime import datetime, timedelta from enum import Enum from typing import Dict, List, Tuple @@ -9,11 +10,13 @@ import arrow from pandas import DataFrame, to_datetime from freqtrade.exchange import get_ticker_history -from freqtrade.logger import Logger from freqtrade.persistence import Trade from freqtrade.strategy.strategy import Strategy +logger = logging.getLogger(__name__) + + class SignalType(Enum): """ Enum to distinguish between buy and sell signals @@ -32,8 +35,6 @@ class Analyze(object): Init Analyze :param config: Bot configuration (use the one from Configuration()) """ - self.logger = Logger(name=__name__, level=config.get('loglevel')).get_logger() - self.config = config self.strategy = Strategy(self.config) @@ -107,20 +108,20 @@ class Analyze(object): """ ticker_hist = get_ticker_history(pair, interval) if not ticker_hist: - self.logger.warning('Empty ticker history for pair %s', pair) + logger.warning('Empty ticker history for pair %s', pair) return False, False try: dataframe = self.analyze_ticker(ticker_hist) except ValueError as error: - self.logger.warning( + logger.warning( 'Unable to analyze ticker for pair %s: %s', pair, str(error) ) return False, False except Exception as error: - self.logger.exception( + logger.exception( 'Unexpected error when analyzing ticker for pair %s: %s', pair, str(error) @@ -128,7 +129,7 @@ class Analyze(object): return False, False if dataframe.empty: - self.logger.warning('Empty dataframe for pair %s', pair) + logger.warning('Empty dataframe for pair %s', pair) return False, False latest = dataframe.iloc[-1] @@ -136,7 +137,7 @@ class Analyze(object): # Check if dataframe is out of date signal_date = arrow.get(latest['date']) if signal_date < arrow.utcnow() - timedelta(minutes=(interval + 5)): - self.logger.warning( + logger.warning( 'Outdated history for pair %s. Last tick is %s minutes old', pair, (arrow.utcnow() - signal_date).seconds // 60 @@ -144,7 +145,7 @@ class Analyze(object): return False, False (buy, sell) = latest[SignalType.BUY.value] == 1, latest[SignalType.SELL.value] == 1 - self.logger.debug( + logger.debug( 'trigger: %s (pair=%s) buy=%s sell=%s', latest['date'], pair, @@ -161,17 +162,17 @@ class Analyze(object): """ # Check if minimal roi has been reached and no longer in buy conditions (avoiding a fee) if self.min_roi_reached(trade=trade, current_rate=rate, current_time=date): - self.logger.debug('Required profit reached. Selling..') + logger.debug('Required profit reached. Selling..') return True # Experimental: Check if the trade is profitable before selling it (avoid selling at loss) if self.config.get('experimental', {}).get('sell_profit_only', False): - self.logger.debug('Checking if trade is profitable..') + logger.debug('Checking if trade is profitable..') if trade.calc_profit(rate=rate) <= 0: return False if sell and not buy and self.config.get('experimental', {}).get('use_sell_signal', False): - self.logger.debug('Sell signal received. Selling..') + logger.debug('Sell signal received. Selling..') return True return False @@ -184,7 +185,7 @@ class Analyze(object): """ current_profit = trade.calc_profit_percent(current_rate) if self.strategy.stoploss is not None and current_profit < self.strategy.stoploss: - self.logger.debug('Stop loss hit.') + logger.debug('Stop loss hit.') return True # Check if time matches and current rate is above threshold diff --git a/freqtrade/configuration.py b/freqtrade/configuration.py index 1f6cea4e6..1314f624e 100644 --- a/freqtrade/configuration.py +++ b/freqtrade/configuration.py @@ -3,6 +3,7 @@ This module contains the configuration class """ import json +import logging from argparse import Namespace from typing import Dict, Any @@ -10,7 +11,9 @@ from jsonschema import Draft4Validator, validate from jsonschema.exceptions import ValidationError, best_match from freqtrade.constants import Constants -from freqtrade.logger import Logger + + +logger = logging.getLogger(__name__) class Configuration(object): @@ -20,8 +23,6 @@ class Configuration(object): """ def __init__(self, args: Namespace) -> None: self.args = args - self.logging = Logger(name=__name__) - self.logger = self.logging.get_logger() self.config = None def load_config(self) -> Dict[str, Any]: @@ -29,7 +30,7 @@ class Configuration(object): Extract information for sys.argv and load the bot configuration :return: Configuration dictionary """ - self.logger.info('Using config: %s ...', self.args.config) + logger.info('Using config: %s ...', self.args.config) config = self._load_config_file(self.args.config) # Add the strategy file to use @@ -56,7 +57,7 @@ class Configuration(object): with open(path) as file: conf = json.load(file) except FileNotFoundError: - self.logger.critical( + logger.critical( 'Config file "%s" not found. Please create your config file', path ) @@ -64,7 +65,7 @@ class Configuration(object): if 'internals' not in conf: conf['internals'] = {} - self.logger.info('Validating configuration ...') + logger.info('Validating configuration ...') return self._validate_config(conf) @@ -77,13 +78,16 @@ class Configuration(object): # Log level if 'loglevel' in self.args and self.args.loglevel: config.update({'loglevel': self.args.loglevel}) - self.logging.set_level(self.args.loglevel) - self.logger.info('Log level set at %s', config['loglevel']) + logging.basicConfig( + level=config['loglevel'], + format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', + ) + logger.info('Log level set to %s', logging.getLevelName(config['loglevel'])) # Add dynamic_whitelist if found if 'dynamic_whitelist' in self.args and self.args.dynamic_whitelist: config.update({'dynamic_whitelist': self.args.dynamic_whitelist}) - self.logger.info( + logger.info( 'Parameter --dynamic-whitelist detected. ' 'Using dynamically generated whitelist. ' '(not applicable with Backtesting and Hyperopt)' @@ -92,13 +96,13 @@ class Configuration(object): # Add dry_run_db if found and the bot in dry run if self.args.dry_run_db and config.get('dry_run', False): config.update({'dry_run_db': True}) - self.logger.info('Parameter --dry-run-db detected ...') + logger.info('Parameter --dry-run-db detected ...') if config.get('dry_run_db', False): if config.get('dry_run', False): - self.logger.info('Dry_run will use the DB file: "tradesv3.dry_run.sqlite"') + logger.info('Dry_run will use the DB file: "tradesv3.dry_run.sqlite"') else: - self.logger.info('Dry run is disabled. (--dry_run_db ignored)') + logger.info('Dry run is disabled. (--dry_run_db ignored)') return config @@ -112,39 +116,39 @@ class Configuration(object): # (that will override the strategy configuration) if 'ticker_interval' in self.args and self.args.ticker_interval: config.update({'ticker_interval': self.args.ticker_interval}) - self.logger.info('Parameter -i/--ticker-interval detected ...') - self.logger.info('Using ticker_interval: %d ...', config.get('ticker_interval')) + logger.info('Parameter -i/--ticker-interval detected ...') + logger.info('Using ticker_interval: %d ...', config.get('ticker_interval')) # If -l/--live is used we add it to the configuration if 'live' in self.args and self.args.live: config.update({'live': True}) - self.logger.info('Parameter -l/--live detected ...') + logger.info('Parameter -l/--live detected ...') # If --realistic-simulation is used we add it to the configuration if 'realistic_simulation' in self.args and self.args.realistic_simulation: config.update({'realistic_simulation': True}) - self.logger.info('Parameter --realistic-simulation detected ...') - self.logger.info('Using max_open_trades: %s ...', config.get('max_open_trades')) + logger.info('Parameter --realistic-simulation detected ...') + logger.info('Using max_open_trades: %s ...', config.get('max_open_trades')) # If --timerange is used we add it to the configuration if 'timerange' in self.args and self.args.timerange: config.update({'timerange': self.args.timerange}) - self.logger.info('Parameter --timerange detected: %s ...', self.args.timerange) + logger.info('Parameter --timerange detected: %s ...', self.args.timerange) # If --datadir is used we add it to the configuration if 'datadir' in self.args and self.args.datadir: config.update({'datadir': self.args.datadir}) - self.logger.info('Parameter --datadir detected: %s ...', self.args.datadir) + logger.info('Parameter --datadir detected: %s ...', self.args.datadir) # If -r/--refresh-pairs-cached is used we add it to the configuration if 'refresh_pairs' in self.args and self.args.refresh_pairs: config.update({'refresh_pairs': True}) - self.logger.info('Parameter -r/--refresh-pairs-cached detected ...') + logger.info('Parameter -r/--refresh-pairs-cached detected ...') # If --export is used we add it to the configuration if 'export' in self.args and self.args.export: config.update({'export': self.args.export}) - self.logger.info('Parameter --export detected: %s ...', self.args.export) + logger.info('Parameter --export detected: %s ...', self.args.export) return config @@ -156,18 +160,18 @@ class Configuration(object): # If --realistic-simulation is used we add it to the configuration if 'epochs' in self.args and self.args.epochs: config.update({'epochs': self.args.epochs}) - self.logger.info('Parameter --epochs detected ...') - self.logger.info('Will run Hyperopt with for %s epochs ...', config.get('epochs')) + logger.info('Parameter --epochs detected ...') + logger.info('Will run Hyperopt with for %s epochs ...', config.get('epochs')) # If --mongodb is used we add it to the configuration if 'mongodb' in self.args and self.args.mongodb: config.update({'mongodb': self.args.mongodb}) - self.logger.info('Parameter --use-mongodb detected ...') + logger.info('Parameter --use-mongodb detected ...') # If --spaces is used we add it to the configuration if 'spaces' in self.args and self.args.spaces: config.update({'spaces': self.args.spaces}) - self.logger.info('Parameter -s/--spaces detected: %s', config.get('spaces')) + logger.info('Parameter -s/--spaces detected: %s', config.get('spaces')) return config @@ -181,7 +185,7 @@ class Configuration(object): validate(conf, Constants.CONF_SCHEMA) return conf except ValidationError as exception: - self.logger.fatal( + logger.fatal( 'Invalid configuration. See config.json.example. Reason: %s', exception ) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 29790515e..3972a4382 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -4,6 +4,7 @@ Freqtrade is the main module of this bot. It contains the class Freqtrade() import copy import json +import logging import time import traceback from datetime import datetime @@ -13,16 +14,20 @@ import arrow import requests from cachetools import cached, TTLCache -from freqtrade import (DependencyException, OperationalException, exchange, persistence) +from freqtrade import ( + DependencyException, OperationalException, exchange, persistence, __version__ +) from freqtrade.analyze import Analyze from freqtrade.constants import Constants from freqtrade.fiat_convert import CryptoToFiatConverter -from freqtrade.logger import Logger from freqtrade.persistence import Trade from freqtrade.rpc.rpc_manager import RPCManager from freqtrade.state import State +logger = logging.getLogger(__name__) + + class FreqtradeBot(object): """ Freqtrade is the main class of the bot. @@ -37,8 +42,10 @@ class FreqtradeBot(object): :param db_url: database connector string for sqlalchemy (Optional) """ - # Init the logger - self.logger = Logger(name=__name__, level=config.get('loglevel')).get_logger() + logger.info( + 'Starting freqtrade %s', + __version__, + ) # Init bot states self.state = State.STOPPED @@ -81,7 +88,7 @@ class FreqtradeBot(object): :return: None """ self.rpc.send_msg('*Status:* `Stopping trader...`') - self.logger.info('Stopping trader and cleaning up modules...') + logger.info('Stopping trader and cleaning up modules...') self.state = State.STOPPED self.rpc.cleanup() persistence.cleanup() @@ -97,7 +104,7 @@ class FreqtradeBot(object): state = self.state if state != old_state: self.rpc.send_msg('*Status:* `{}`'.format(state.name.lower())) - self.logger.info('Changing state to: %s', state.name) + logger.info('Changing state to: %s', state.name) if state == State.STOPPED: time.sleep(1) @@ -129,7 +136,7 @@ class FreqtradeBot(object): result = func(*args, **kwargs) end = time.time() duration = max(min_secs - (end - start), 0.0) - self.logger.debug('Throttling %s for %.2f seconds', func.__name__, duration) + logger.debug('Throttling %s for %.2f seconds', func.__name__, duration) time.sleep(duration) return result @@ -170,7 +177,7 @@ class FreqtradeBot(object): Trade.session.flush() except (requests.exceptions.RequestException, json.JSONDecodeError) as error: - self.logger.warning('%s, retrying in 30 seconds...', error) + logger.warning('%s, retrying in 30 seconds...', error) time.sleep(Constants.RETRY_TIMEOUT) except OperationalException: self.rpc.send_msg( @@ -180,7 +187,7 @@ class FreqtradeBot(object): hint='Issue `/start` if you think it is safe to restart.' ) ) - self.logger.exception('OperationalException. Stopping trader ...') + logger.exception('OperationalException. Stopping trader ...') self.state = State.STOPPED return state_changed @@ -222,7 +229,7 @@ class FreqtradeBot(object): # Market is not active if not status['IsActive']: sanitized_whitelist.remove(pair) - self.logger.info( + logger.info( 'Ignoring %s from whitelist (reason: %s).', pair, status.get('Notice') or 'wallet is not active' ) @@ -253,7 +260,7 @@ class FreqtradeBot(object): stake_amount = self.config['stake_amount'] interval = self.analyze.get_ticker_interval() - self.logger.info( + logger.info( 'Checking buy signals to create a new trade with stake_amount: %f ...', stake_amount ) @@ -268,7 +275,7 @@ class FreqtradeBot(object): for trade in Trade.query.filter(Trade.is_open.is_(True)).all(): if trade.pair in whitelist: whitelist.remove(trade.pair) - self.logger.debug('Ignoring %s in pair whitelist', trade.pair) + logger.debug('Ignoring %s in pair whitelist', trade.pair) if not whitelist: raise DependencyException('No currency pairs in whitelist') @@ -333,10 +340,10 @@ class FreqtradeBot(object): if self.create_trade(): return True - self.logger.info('Found no buy signals for whitelisted currencies. Trying again..') + logger.info('Found no buy signals for whitelisted currencies. Trying again..') return False except DependencyException as exception: - self.logger.warning('Unable to create trade: %s', exception) + logger.warning('Unable to create trade: %s', exception) return False def process_maybe_execute_sell(self, trade: Trade) -> bool: @@ -347,7 +354,7 @@ class FreqtradeBot(object): # Get order details for actual price per unit if trade.open_order_id: # Update trade with order values - self.logger.info('Found open order for %s', trade) + logger.info('Found open order for %s', trade) trade.update(exchange.get_order(trade.open_order_id)) if trade.is_open and trade.open_order_id is None: @@ -363,7 +370,7 @@ class FreqtradeBot(object): if not trade.is_open: raise ValueError('attempt to handle closed trade: {}'.format(trade)) - self.logger.debug('Handling %s ...', trade) + logger.debug('Handling %s ...', trade) current_rate = exchange.get_ticker(trade.pair)['bid'] (buy, sell) = (False, False) @@ -389,7 +396,7 @@ class FreqtradeBot(object): try: order = exchange.get_order(trade.open_order_id) except requests.exceptions.RequestException: - self.logger.info( + logger.info( 'Cannot query order for %s due to %s', trade, traceback.format_exc()) @@ -419,7 +426,7 @@ class FreqtradeBot(object): # FIX? do we really need to flush, caller of # check_handle_timedout will flush afterwards Trade.session.flush() - self.logger.info('Buy order timeout for %s.', trade) + logger.info('Buy order timeout for %s.', trade) self.rpc.send_msg('*Timeout:* Unfilled buy order for {} cancelled'.format( trade.pair.replace('_', '/'))) return True @@ -429,7 +436,7 @@ class FreqtradeBot(object): trade.amount = order['amount'] - order['remaining'] trade.stake_amount = trade.amount * trade.open_rate trade.open_order_id = None - self.logger.info('Partial buy order timeout for %s.', trade) + logger.info('Partial buy order timeout for %s.', trade) self.rpc.send_msg('*Timeout:* Remaining buy order for {} cancelled'.format( trade.pair.replace('_', '/'))) return False @@ -450,7 +457,7 @@ class FreqtradeBot(object): trade.open_order_id = None self.rpc.send_msg('*Timeout:* Unfilled sell order for {} cancelled'.format( trade.pair.replace('_', '/'))) - self.logger.info('Sell order timeout for %s.', trade) + logger.info('Sell order timeout for %s.', trade) return True # TODO: figure out how to handle partially complete sell orders diff --git a/freqtrade/logger.py b/freqtrade/logger.py deleted file mode 100644 index 95e55e477..000000000 --- a/freqtrade/logger.py +++ /dev/null @@ -1,83 +0,0 @@ -# pragma pylint: disable=too-few-public-methods - -""" -This module contains the class for logger and logging messages -""" - -import logging - - -class Logger(object): - """ - Logging class - """ - def __init__(self, name='', level=logging.INFO) -> None: - """ - Init the logger class - :param name: Name of the Logger scope - :param level: Logger level that should be used - :return: None - """ - self.name = name - self.logger = None - - if level is None: - level = logging.INFO - self.level = level - - self._init_logger() - - def _init_logger(self) -> None: - """ - Setup the bot logger configuration - :return: None - """ - logging.basicConfig( - level=self.level, - format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', - ) - - self.logger = self.get_logger() - self.set_level(self.level) - - def get_logger(self) -> logging.RootLogger: - """ - Return the logger instance to use for sending message - :return: the logger instance - """ - return logging.getLogger(self.name) - - def set_name(self, name: str) -> logging.RootLogger: - """ - Set the name of the logger - :param name: Name of the logger - :return: None - """ - self.name = name - self.logger = self.get_logger() - return self.logger - - def set_level(self, level) -> None: - """ - Set the level of the logger - :param level: - :return: None - """ - self.level = level - self.logger.setLevel(self.level) - - def set_format(self, log_format: str, propagate: bool = False) -> None: - """ - Set a new logging format - :return: None - """ - handler = logging.StreamHandler() - - len_handlers = len(self.logger.handlers) - if len_handlers: - self.logger.removeHandler(handler) - - handler.setFormatter(logging.Formatter(log_format)) - self.logger.addHandler(handler) - - self.logger.propagate = propagate diff --git a/freqtrade/main.py b/freqtrade/main.py index 556b70708..d62c92b9f 100755 --- a/freqtrade/main.py +++ b/freqtrade/main.py @@ -8,13 +8,11 @@ import logging import sys from typing import List -from freqtrade import (__version__) from freqtrade.arguments import Arguments from freqtrade.configuration import Configuration from freqtrade.freqtradebot import FreqtradeBot -from freqtrade.logger import Logger -logger = Logger(name='freqtrade').get_logger() +logger = logging.getLogger('freqtrade') def main(sysargv: List[str]) -> None: @@ -34,20 +32,14 @@ def main(sysargv: List[str]) -> None: args.func(args) return - logger.info( - 'Starting freqtrade %s (loglevel=%s)', - __version__, - logging.getLevelName(args.loglevel) - ) - freqtrade = None return_code = 1 try: # Load and validate configuration - configuration = Configuration(args) + config = Configuration(args).get_config() # Init the bot - freqtrade = FreqtradeBot(configuration.get_config()) + freqtrade = FreqtradeBot(config) state = None while 1: diff --git a/freqtrade/optimize/__init__.py b/freqtrade/optimize/__init__.py index a26744691..fff4b72d9 100644 --- a/freqtrade/optimize/__init__.py +++ b/freqtrade/optimize/__init__.py @@ -2,15 +2,15 @@ import gzip import json +import logging import os from typing import Optional, List, Dict, Tuple from freqtrade import misc from freqtrade.exchange import get_ticker_history -from freqtrade.logger import Logger from user_data.hyperopt_conf import hyperopt_optimize_conf -logger = Logger(name=__name__).get_logger() +logger = logging.getLogger(__name__) def trim_tickerlist(tickerlist: List[Dict], timerange: Tuple[Tuple, int, int]) -> List[Dict]: diff --git a/freqtrade/optimize/backtesting.py b/freqtrade/optimize/backtesting.py index d8af47326..146b69d83 100644 --- a/freqtrade/optimize/backtesting.py +++ b/freqtrade/optimize/backtesting.py @@ -3,6 +3,7 @@ """ This module contains the backtesting logic """ +import logging from argparse import Namespace from typing import Dict, Tuple, Any, List, Optional @@ -16,11 +17,13 @@ from freqtrade.analyze import Analyze from freqtrade.arguments import Arguments from freqtrade.configuration import Configuration from freqtrade.exchange import Bittrex -from freqtrade.logger import Logger from freqtrade.misc import file_dump_json from freqtrade.persistence import Trade +logger = logging.getLogger(__name__) + + class Backtesting(object): """ Backtesting class, this class contains all the logic to run a backtest @@ -30,10 +33,6 @@ class Backtesting(object): backtesting.start() """ def __init__(self, config: Dict[str, Any]) -> None: - - # Init the logger - self.logging = Logger(name=__name__, level=config['loglevel']) - self.logger = self.logging.get_logger() self.config = config self.analyze = None self.ticker_interval = None @@ -200,7 +199,7 @@ class Backtesting(object): # For now export inside backtest(), maybe change so that backtest() # returns a tuple like: (dataframe, records, logs, etc) if record and record.find('trades') >= 0: - self.logger.info('Dumping backtest results') + logger.info('Dumping backtest results') file_dump_json('backtest-result.json', records) labels = ['currency', 'profit_percent', 'profit_BTC', 'duration'] return DataFrame.from_records(trades, columns=labels) @@ -212,15 +211,15 @@ class Backtesting(object): """ data = {} pairs = self.config['exchange']['pair_whitelist'] - self.logger.info('Using stake_currency: %s ...', self.config['stake_currency']) - self.logger.info('Using stake_amount: %s ...', self.config['stake_amount']) + logger.info('Using stake_currency: %s ...', self.config['stake_currency']) + logger.info('Using stake_amount: %s ...', self.config['stake_amount']) if self.config.get('live'): - self.logger.info('Downloading data for all pairs in whitelist ...') + logger.info('Downloading data for all pairs in whitelist ...') for pair in pairs: data[pair] = exchange.get_ticker_history(pair, self.ticker_interval) else: - self.logger.info('Using local backtesting data (using whitelist in given config) ...') + logger.info('Using local backtesting data (using whitelist in given config) ...') timerange = Arguments.parse_timerange(self.config.get('timerange')) data = optimize.load_data( @@ -235,14 +234,14 @@ class Backtesting(object): if self.config.get('realistic_simulation', False): max_open_trades = self.config['max_open_trades'] else: - self.logger.info('Ignoring max_open_trades (realistic_simulation not set) ...') + logger.info('Ignoring max_open_trades (realistic_simulation not set) ...') max_open_trades = 0 preprocessed = self.tickerdata_to_dataframe(data) # Print timeframe min_date, max_date = self.get_timeframe(preprocessed) - self.logger.info( + logger.info( 'Measuring data from %s up to %s (%s days)..', min_date.isoformat(), max_date.isoformat(), @@ -263,9 +262,7 @@ class Backtesting(object): 'record': self.config.get('export') } ) - - self.logging.set_format('%(message)s') - self.logger.info( + logger.info( '\n==================================== ' 'BACKTESTING REPORT' ' ====================================\n' @@ -299,13 +296,9 @@ def start(args: Namespace) -> None: :param args: Cli args from Arguments() :return: None """ - - # Initialize logger - logger = Logger(name=__name__).get_logger() - logger.info('Starting freqtrade in Backtesting mode') - # Initialize configuration config = setup_configuration(args) + logger.info('Starting freqtrade in Backtesting mode') # Initialize backtesting object backtesting = Backtesting(config) diff --git a/freqtrade/optimize/hyperopt.py b/freqtrade/optimize/hyperopt.py index 7dcd46fd2..fb1d882be 100644 --- a/freqtrade/optimize/hyperopt.py +++ b/freqtrade/optimize/hyperopt.py @@ -25,12 +25,14 @@ from pandas import DataFrame import freqtrade.vendor.qtpylib.indicators as qtpylib from freqtrade.arguments import Arguments from freqtrade.configuration import Configuration -from freqtrade.logger import Logger from freqtrade.optimize import load_data from freqtrade.optimize.backtesting import Backtesting from user_data.hyperopt_conf import hyperopt_optimize_conf +logger = logging.getLogger(__name__) + + class Hyperopt(Backtesting): """ Hyperopt class, this class contains all the logic to run a hyperopt simulation @@ -42,11 +44,6 @@ class Hyperopt(Backtesting): def __init__(self, config: Dict[str, Any]) -> None: super().__init__(config) - - # Rename the logging to display Hyperopt file instead of Backtesting - self.logging = Logger(name=__name__, level=config['loglevel']) - self.logger = self.logging.get_logger() - # set TARGET_TRADES to suit your number concurrent trades so its realistic # to the number of days self.target_trades = 600 @@ -194,14 +191,14 @@ class Hyperopt(Backtesting): """ Save hyperopt trials to file """ - self.logger.info('Saving Trials to \'%s\'', self.trials_file) + logger.info('Saving Trials to \'%s\'', self.trials_file) pickle.dump(self.trials, open(self.trials_file, 'wb')) def read_trials(self) -> Trials: """ Read hyperopt trials file """ - self.logger.info('Reading Trials from \'%s\'', self.trials_file) + logger.info('Reading Trials from \'%s\'', self.trials_file) trials = pickle.load(open(self.trials_file, 'rb')) os.remove(self.trials_file) return trials @@ -212,7 +209,7 @@ class Hyperopt(Backtesting): """ vals = json.dumps(self.trials.best_trial['misc']['vals'], indent=4) results = self.trials.best_trial['result']['result'] - self.logger.info('Best result:\n%s\nwith values:\n%s', results, vals) + logger.info('Best result:\n%s\nwith values:\n%s', results, vals) def log_results(self, results) -> None: """ @@ -220,13 +217,13 @@ class Hyperopt(Backtesting): """ if results['loss'] < self.current_best_loss: self.current_best_loss = results['loss'] - log_msg = '{:5d}/{}: {}. Loss {:.5f}'.format( + log_msg = '\n{:5d}/{}: {}. Loss {:.5f}'.format( results['current_tries'], results['total_tries'], results['result'], results['loss'] ) - self.logger.info(log_msg) + print(log_msg) else: print('.', end='') sys.stdout.flush() @@ -511,8 +508,8 @@ class Hyperopt(Backtesting): self.processed = self.tickerdata_to_dataframe(data) if self.config.get('mongodb'): - self.logger.info('Using mongodb ...') - self.logger.info( + logger.info('Using mongodb ...') + logger.info( 'Start scripts/start-mongodb.sh and start-hyperopt-worker.sh manually!' ) @@ -522,7 +519,7 @@ class Hyperopt(Backtesting): exp_key='exp1' ) else: - self.logger.info('Preparing Trials..') + logger.info('Preparing Trials..') signal.signal(signal.SIGINT, self.signal_handler) # read trials file if we have one if os.path.exists(self.trials_file) and os.path.getsize(self.trials_file) > 0: @@ -530,16 +527,13 @@ class Hyperopt(Backtesting): self.current_tries = len(self.trials.results) self.total_tries += self.current_tries - self.logger.info( + logger.info( 'Continuing with trials. Current: %d, Total: %d', self.current_tries, self.total_tries ) try: - # change the Logging format - self.logging.set_format('\n%(message)s') - best_parameters = fmin( fn=self.generate_optimizer, space=self.hyperopt_space(), @@ -563,11 +557,11 @@ class Hyperopt(Backtesting): best_parameters ) - self.logger.info('Best parameters:\n%s', json.dumps(best_parameters, indent=4)) + logger.info('Best parameters:\n%s', json.dumps(best_parameters, indent=4)) if 'roi_t1' in best_parameters: - self.logger.info('ROI table:\n%s', self.generate_roi_table(best_parameters)) + logger.info('ROI table:\n%s', self.generate_roi_table(best_parameters)) - self.logger.info('Best Result:\n%s', best_result) + logger.info('Best Result:\n%s', best_result) # Store trials result to file to resume next time self.save_trials() @@ -576,7 +570,7 @@ class Hyperopt(Backtesting): """ Hyperopt SIGINT handler """ - self.logger.info( + logger.info( 'Hyperopt received %s', signal.Signals(sig).name ) @@ -597,13 +591,11 @@ def start(args: Namespace) -> None: logging.getLogger('hyperopt.mongoexp').setLevel(logging.WARNING) logging.getLogger('hyperopt.tpe').setLevel(logging.WARNING) - # Initialize logger - logger = Logger(name=__name__).get_logger() - logger.info('Starting freqtrade in Hyperopt mode') - # Initialize configuration # Monkey patch the configuration with hyperopt_conf.py configuration = Configuration(args) + logger.info('Starting freqtrade in Hyperopt mode') + optimize_config = hyperopt_optimize_conf() config = configuration._load_common_config(optimize_config) config = configuration._load_backtesting_config(config) diff --git a/freqtrade/rpc/rpc.py b/freqtrade/rpc/rpc.py index db6ff69d1..860d3ba43 100644 --- a/freqtrade/rpc/rpc.py +++ b/freqtrade/rpc/rpc.py @@ -1,7 +1,7 @@ """ This module contains class to define a RPC communications """ - +import logging from datetime import datetime, timedelta from decimal import Decimal from typing import Tuple, Any @@ -11,12 +11,14 @@ import sqlalchemy as sql from pandas import DataFrame from freqtrade import exchange -from freqtrade.logger import Logger from freqtrade.misc import shorten_date from freqtrade.persistence import Trade from freqtrade.state import State +logger = logging.getLogger(__name__) + + class RPC(object): """ RPC class can be used to have extra feature, like bot data, and access to DB data @@ -28,10 +30,6 @@ class RPC(object): :return: None """ self.freqtrade = freqtrade - self.logger = Logger( - name=__name__, - level=self.freqtrade.config.get('loglevel') - ).get_logger() def rpc_trade_status(self) -> Tuple[bool, Any]: """ @@ -346,7 +344,7 @@ class RPC(object): ) ).first() if not trade: - self.logger.warning('forcesell: Invalid argument received') + logger.warning('forcesell: Invalid argument received') return True, 'Invalid argument.' _exec_forcesell(trade) diff --git a/freqtrade/rpc/rpc_manager.py b/freqtrade/rpc/rpc_manager.py index fb18a8d73..0299c793a 100644 --- a/freqtrade/rpc/rpc_manager.py +++ b/freqtrade/rpc/rpc_manager.py @@ -1,11 +1,14 @@ """ This module contains class to manage RPC communications (Telegram, Slack, ...) """ +import logging -from freqtrade.logger import Logger from freqtrade.rpc.telegram import Telegram +logger = logging.getLogger(__name__) + + class RPCManager(object): """ Class to manage RPC objects (Telegram, Slack, ...) @@ -18,12 +21,6 @@ class RPCManager(object): """ self.freqtrade = freqtrade - # Init the logger - self.logger = Logger( - name=__name__, - level=self.freqtrade.config.get('loglevel') - ).get_logger() - self.registered_modules = [] self.telegram = None self._init() @@ -34,7 +31,7 @@ class RPCManager(object): :return: """ if self.freqtrade.config['telegram'].get('enabled', False): - self.logger.info('Enabling rpc.telegram ...') + logger.info('Enabling rpc.telegram ...') self.registered_modules.append('telegram') self.telegram = Telegram(self.freqtrade) @@ -44,7 +41,7 @@ class RPCManager(object): :return: None """ if 'telegram' in self.registered_modules: - self.logger.info('Cleaning up rpc.telegram ...') + logger.info('Cleaning up rpc.telegram ...') self.registered_modules.remove('telegram') self.telegram.cleanup() @@ -54,6 +51,6 @@ class RPCManager(object): :param msg: message :return: None """ - self.logger.info(msg) + logger.info(msg) if 'telegram' in self.registered_modules: self.telegram.send_msg(msg) diff --git a/freqtrade/rpc/telegram.py b/freqtrade/rpc/telegram.py index fce7a81f9..81749d778 100644 --- a/freqtrade/rpc/telegram.py +++ b/freqtrade/rpc/telegram.py @@ -3,7 +3,7 @@ """ This module manage Telegram communication """ - +import logging from typing import Any, Callable from tabulate import tabulate @@ -15,6 +15,9 @@ from freqtrade.__init__ import __version__ from freqtrade.rpc.rpc import RPC +logger = logging.getLogger(__name__) + + def authorized_only(command_handler: Callable[[Bot, Update], None]) -> Callable[..., Any]: """ Decorator to check if the message comes from the correct chat_id @@ -31,13 +34,13 @@ def authorized_only(command_handler: Callable[[Bot, Update], None]) -> Callable[ chat_id = int(self._config['telegram']['chat_id']) if int(update.message.chat_id) != chat_id: - self.logger.info( + logger.info( 'Rejected unauthorized message from: %s', update.message.chat_id ) return wrapper - self.logger.info( + logger.info( 'Executing handler: %s for chat_id: %s', command_handler.__name__, chat_id @@ -45,7 +48,7 @@ def authorized_only(command_handler: Callable[[Bot, Update], None]) -> Callable[ try: return command_handler(self, *args, **kwargs) except BaseException: - self.logger.exception('Exception occurred within Telegram module') + logger.exception('Exception occurred within Telegram module') return wrapper @@ -101,7 +104,7 @@ class Telegram(RPC): timeout=30, read_latency=60, ) - self.logger.info( + logger.info( 'rpc.telegram is listening for following commands: %s', [h.command for h in handles] ) @@ -357,7 +360,7 @@ class Telegram(RPC): 'max': [self._config['max_open_trades']] }, headers=['current', 'max'], tablefmt='simple') message = "
{}".format(message) - self.logger.debug(message) + logger.debug(message) self.send_msg(message, parse_mode=ParseMode.HTML) @authorized_only @@ -428,7 +431,7 @@ class Telegram(RPC): except NetworkError as network_err: # Sometimes the telegram server resets the current connection, # if this is the case we send the message again. - self.logger.warning( + logger.warning( 'Telegram NetworkError: %s! Trying one more time.', network_err.message ) @@ -439,7 +442,7 @@ class Telegram(RPC): reply_markup=reply_markup ) except TelegramError as telegram_err: - self.logger.warning( + logger.warning( 'TelegramError: %s! Giving up on that message.', telegram_err.message ) diff --git a/freqtrade/strategy/strategy.py b/freqtrade/strategy/strategy.py index d7a89d1de..7840765bb 100644 --- a/freqtrade/strategy/strategy.py +++ b/freqtrade/strategy/strategy.py @@ -4,6 +4,7 @@ This module load custom strategies """ import importlib +import logging import os import sys from collections import OrderedDict @@ -11,12 +12,14 @@ from collections import OrderedDict from pandas import DataFrame from freqtrade.constants import Constants -from freqtrade.logger import Logger from freqtrade.strategy.interface import IStrategy sys.path.insert(0, r'../../user_data/strategies') +logger = logging.getLogger(__name__) + + class Strategy(object): """ This class contains all the logic to load custom strategy class @@ -27,8 +30,6 @@ class Strategy(object): :param config: :return: """ - self.logger = Logger(name=__name__).get_logger() - # Verify the strategy is in the configuration, otherwise fallback to the default strategy if 'strategy' in config: strategy = config['strategy'] @@ -42,17 +43,17 @@ class Strategy(object): # Check if we need to override configuration if 'minimal_roi' in config: self.custom_strategy.minimal_roi = config['minimal_roi'] - self.logger.info("Override strategy \'minimal_roi\' with value in config file.") + logger.info("Override strategy \'minimal_roi\' with value in config file.") if 'stoploss' in config: self.custom_strategy.stoploss = config['stoploss'] - self.logger.info( + logger.info( "Override strategy \'stoploss\' with value in config file: %s.", config['stoploss'] ) if 'ticker_interval' in config: self.custom_strategy.ticker_interval = config['ticker_interval'] - self.logger.info( + logger.info( "Override strategy \'ticker_interval\' with value in config file: %s.", config['ticker_interval'] ) @@ -87,12 +88,12 @@ class Strategy(object): # Fallback to the default strategy except (ImportError, TypeError) as error: - self.logger.error( + logger.error( "Impossible to load Strategy 'user_data/strategies/%s.py'. This file does not exist" " or contains Python code errors", strategy_name ) - self.logger.error( + logger.error( "The error is:\n%s.", error ) @@ -106,7 +107,7 @@ class Strategy(object): module = importlib.import_module(filename, __package__) custom_strategy = getattr(module, module.class_name) - self.logger.info("Load strategy class: %s (%s.py)", module.class_name, filename) + logger.info("Load strategy class: %s (%s.py)", module.class_name, filename) return custom_strategy() @staticmethod diff --git a/freqtrade/tests/optimize/test_hyperopt.py b/freqtrade/tests/optimize/test_hyperopt.py index 6d376471a..20e29c2d7 100644 --- a/freqtrade/tests/optimize/test_hyperopt.py +++ b/freqtrade/tests/optimize/test_hyperopt.py @@ -50,7 +50,6 @@ def test_start(mocker, default_conf, caplog) -> None: Test start() function """ start_mock = MagicMock() - mocker.patch('freqtrade.logger.Logger.set_format', MagicMock()) mocker.patch('freqtrade.optimize.hyperopt.Hyperopt.start', start_mock) mocker.patch('freqtrade.configuration.open', mocker.mock_open( read_data=json.dumps(default_conf) @@ -110,7 +109,7 @@ def test_loss_calculation_has_limited_profit() -> None: assert under > correct -def test_log_results_if_loss_improves(caplog) -> None: +def test_log_results_if_loss_improves(capsys) -> None: hyperopt = _HYPEROPT hyperopt.current_best_loss = 2 hyperopt.log_results( @@ -121,7 +120,8 @@ def test_log_results_if_loss_improves(caplog) -> None: 'result': 'foo' } ) - assert log_has(' 1/2: foo. Loss 1.00000', caplog.record_tuples) + out, err = capsys.readouterr() + assert ' 1/2: foo. Loss 1.00000'in out def test_no_log_if_loss_does_not_improve(caplog) -> None: @@ -169,7 +169,6 @@ def test_fmin_best_results(mocker, default_conf, caplog) -> None: mocker.patch('freqtrade.optimize.hyperopt.load_data', MagicMock()) mocker.patch('freqtrade.optimize.hyperopt.fmin', return_value=fmin_result) mocker.patch('freqtrade.optimize.hyperopt.hyperopt_optimize_conf', return_value=conf) - mocker.patch('freqtrade.logger.Logger.set_format', MagicMock()) Strategy({'strategy': 'default_strategy'}) hyperopt = Hyperopt(conf) @@ -214,7 +213,6 @@ def test_fmin_throw_value_error(mocker, default_conf, caplog) -> None: conf.update({'timerange': None}) conf.update({'spaces': 'all'}) mocker.patch('freqtrade.optimize.hyperopt.hyperopt_optimize_conf', return_value=conf) - mocker.patch('freqtrade.logger.Logger.set_format', MagicMock()) Strategy({'strategy': 'default_strategy'}) hyperopt = Hyperopt(conf) hyperopt.trials = create_trials(mocker) @@ -256,7 +254,6 @@ def test_resuming_previous_hyperopt_results_succeeds(mocker, default_conf) -> No mocker.patch('freqtrade.optimize.hyperopt.load_data', MagicMock()) mocker.patch('freqtrade.optimize.hyperopt.fmin', return_value={}) mocker.patch('freqtrade.optimize.hyperopt.hyperopt_optimize_conf', return_value=conf) - mocker.patch('freqtrade.logger.Logger.set_format', MagicMock()) Strategy({'strategy': 'default_strategy'}) hyperopt = Hyperopt(conf) diff --git a/freqtrade/tests/strategy/test_strategy.py b/freqtrade/tests/strategy/test_strategy.py index 7ce9ae0ef..a364a59fe 100644 --- a/freqtrade/tests/strategy/test_strategy.py +++ b/freqtrade/tests/strategy/test_strategy.py @@ -29,7 +29,6 @@ def test_strategy_structure(): def test_load_strategy(result): strategy = Strategy() - strategy.logger = logging.getLogger(__name__) assert not hasattr(Strategy, 'custom_strategy') strategy._load_strategy('test_strategy') @@ -42,14 +41,13 @@ def test_load_strategy(result): def test_load_not_found_strategy(caplog): strategy = Strategy() - strategy.logger = logging.getLogger(__name__) assert not hasattr(Strategy, 'custom_strategy') strategy._load_strategy('NotFoundStrategy') error_msg = "Impossible to load Strategy 'user_data/strategies/{}.py'. This file does not " \ "exist or contains Python code errors".format('NotFoundStrategy') - assert ('test_strategy', logging.ERROR, error_msg) in caplog.record_tuples + assert ('freqtrade.strategy.strategy', logging.ERROR, error_msg) in caplog.record_tuples def test_strategy(result): diff --git a/freqtrade/tests/test_logger.py b/freqtrade/tests/test_logger.py deleted file mode 100644 index 8e094b2d1..000000000 --- a/freqtrade/tests/test_logger.py +++ /dev/null @@ -1,97 +0,0 @@ -""" -Unit test file for logger.py -""" - -import logging - -from freqtrade.logger import Logger - - -def test_logger_object() -> None: - """ - Test the Constants object has the mandatory Constants - :return: None - """ - logger = Logger() - assert logger.name == '' - assert logger.level == 20 - assert logger.level is logging.INFO - assert hasattr(logger, 'get_logger') - - logger = Logger(name='Foo', level=logging.WARNING) - assert logger.name == 'Foo' - assert logger.name != '' - assert logger.level == 30 - assert logger.level is logging.WARNING - - -def test_get_logger() -> None: - """ - Test Logger.get_logger() and Logger._init_logger() - :return: None - """ - logger = Logger(name='get_logger', level=logging.WARNING) - get_logger = logger.get_logger() - assert logger.logger is get_logger - assert get_logger is not None - assert hasattr(get_logger, 'debug') - assert hasattr(get_logger, 'info') - assert hasattr(get_logger, 'warning') - assert hasattr(get_logger, 'critical') - assert hasattr(get_logger, 'exception') - - -def test_set_name() -> None: - """ - Test Logger.set_name() - :return: None - """ - logger = Logger(name='set_name') - assert logger.name == 'set_name' - - logger.set_name('set_name_new') - assert logger.name == 'set_name_new' - - -def test_set_level() -> None: - """ - Test Logger.set_name() - :return: None - """ - logger = Logger(name='Foo', level=logging.WARNING) - assert logger.level == logging.WARNING - assert logger.get_logger().level == logging.WARNING - - logger.set_level(logging.INFO) - assert logger.level == logging.INFO - assert logger.get_logger().level == logging.INFO - - -def test_sending_msg(caplog) -> None: - """ - Test send a logging message - :return: None - """ - logger = Logger(name='sending_msg', level=logging.WARNING).get_logger() - - logger.info('I am an INFO message') - assert('sending_msg', logging.INFO, 'I am an INFO message') not in caplog.record_tuples - - logger.warning('I am an WARNING message') - assert ('sending_msg', logging.WARNING, 'I am an WARNING message') in caplog.record_tuples - - -def test_set_format(caplog) -> None: - """ - Test Logger.set_format() - :return: None - """ - log = Logger(name='set_format') - logger = log.get_logger() - - logger.info('I am the first message') - assert ('set_format', logging.INFO, 'I am the first message') in caplog.record_tuples - - log.set_format(log_format='%(message)s', propagate=True) - logger.info('I am the second message') - assert ('set_format', logging.INFO, 'I am the second message') in caplog.record_tuples diff --git a/scripts/plot_dataframe.py b/scripts/plot_dataframe.py index 285ba6d97..aa61fc172 100755 --- a/scripts/plot_dataframe.py +++ b/scripts/plot_dataframe.py @@ -11,7 +11,7 @@ Optional Cli parameters --timerange: specify what timerange of data to use. -l / --live: Live, to download the latest ticker for the pair """ - +import logging import sys from argparse import Namespace @@ -24,11 +24,10 @@ import plotly.graph_objs as go from freqtrade.arguments import Arguments from freqtrade.analyze import Analyze from freqtrade import exchange -from freqtrade.logger import Logger import freqtrade.optimize as optimize -logger = Logger(name="Graph dataframe").get_logger() +logger = logging.getLogger(__name__) def plot_analyzed_dataframe(args: Namespace) -> None: diff --git a/scripts/plot_profit.py b/scripts/plot_profit.py index 022bbf33c..4bf220dd9 100755 --- a/scripts/plot_profit.py +++ b/scripts/plot_profit.py @@ -10,7 +10,7 @@ Optional Cli parameters -s / --strategy: strategy to use --timerange: specify what timerange of data to use. """ - +import logging import sys import json from argparse import Namespace @@ -24,13 +24,12 @@ import plotly.graph_objs as go from freqtrade.arguments import Arguments from freqtrade.configuration import Configuration from freqtrade.analyze import Analyze -from freqtrade.logger import Logger import freqtrade.optimize as optimize import freqtrade.misc as misc -logger = Logger(name="Graph profits").get_logger() +logger = logging.getLogger(__name__) # data:: [ pair, profit-%, enter, exit, time, duration]