diff --git a/freqtrade/optimize/backtesting.py b/freqtrade/optimize/backtesting.py index d8dc971c7..300cef82f 100644 --- a/freqtrade/optimize/backtesting.py +++ b/freqtrade/optimize/backtesting.py @@ -239,14 +239,16 @@ class Backtesting: stake_amount: float, max_open_trades: int) -> Optional[BacktestResult]: trade = Trade( + pair=pair, open_rate=buy_row.open, open_date=buy_row.date, stake_amount=stake_amount, amount=stake_amount / buy_row.open, fee_open=self.fee, - fee_close=self.fee + fee_close=self.fee, + is_open=True, ) - + logger.debug(f"{pair} - Backtesting emulates creation of new trade: {trade}.") # calculate win/lose forwards from buy point for sell_row in partial_ticker: if max_open_trades > 0: @@ -289,23 +291,25 @@ class Backtesting: if partial_ticker: # no sell condition found - trade stil open at end of backtest period sell_row = partial_ticker[-1] - btr = BacktestResult(pair=pair, - profit_percent=trade.calc_profit_percent(rate=sell_row.open), - profit_abs=trade.calc_profit(rate=sell_row.open), - open_time=buy_row.date, - close_time=sell_row.date, - trade_duration=int(( - sell_row.date - buy_row.date).total_seconds() // 60), - open_index=buy_row.Index, - close_index=sell_row.Index, - open_at_end=True, - open_rate=buy_row.open, - close_rate=sell_row.open, - sell_reason=SellType.FORCE_SELL - ) - logger.debug('Force_selling still open trade %s with %s perc - %s', btr.pair, - btr.profit_percent, btr.profit_abs) - return btr + bt_res = BacktestResult(pair=pair, + profit_percent=trade.calc_profit_percent(rate=sell_row.open), + profit_abs=trade.calc_profit(rate=sell_row.open), + open_time=buy_row.date, + close_time=sell_row.date, + trade_duration=int(( + sell_row.date - buy_row.date).total_seconds() // 60), + open_index=buy_row.Index, + close_index=sell_row.Index, + open_at_end=True, + open_rate=buy_row.open, + close_rate=sell_row.open, + sell_reason=SellType.FORCE_SELL + ) + logger.debug(f"{pair} - Force selling still open trade, " + f"profit percent: {bt_res.profit_percent}, " + f"profit abs: {bt_res.profit_abs}") + + return bt_res return None def backtest(self, args: Dict) -> DataFrame: @@ -384,6 +388,8 @@ class Backtesting: max_open_trades) if trade_entry: + logger.debug(f"{pair} - Locking pair till " + f"close_time={trade_entry.close_time}") lock_pair_until[pair] = trade_entry.close_time trades.append(trade_entry) else: diff --git a/freqtrade/persistence.py b/freqtrade/persistence.py index dff7e4ff6..1850aafd9 100644 --- a/freqtrade/persistence.py +++ b/freqtrade/persistence.py @@ -1,7 +1,6 @@ """ This module contains the class to persist trades into SQLite """ - import logging from datetime import datetime from decimal import Decimal @@ -19,8 +18,10 @@ from sqlalchemy.pool import StaticPool from freqtrade import OperationalException + logger = logging.getLogger(__name__) + _DECL_BASE: Any = declarative_base() _SQL_DOCS_URL = 'http://docs.sqlalchemy.org/en/latest/core/engines.html#database-urls' @@ -209,7 +210,7 @@ class Trade(_DECL_BASE): ticker_interval = Column(Integer, nullable=True) def __repr__(self): - open_since = arrow.get(self.open_date).humanize() if self.is_open else 'closed' + open_since = self.open_date.strftime('%Y-%m-%d %H:%M:%S') if self.is_open else 'closed' return (f'Trade(id={self.id}, pair={self.pair}, amount={self.amount:.8f}, ' f'open_rate={self.open_rate:.8f}, open_since={open_since})') @@ -250,7 +251,6 @@ class Trade(_DECL_BASE): :param initial: Called to initiate stop_loss. Skips everything if self.stop_loss is already set. """ - if initial and not (self.stop_loss is None or self.stop_loss == 0): # Don't modify if called with initial and nothing to do return @@ -259,7 +259,7 @@ class Trade(_DECL_BASE): # no stop loss assigned yet if not self.stop_loss: - logger.debug("assigning new stop loss") + logger.debug(f"{self.pair} - Assigning new stoploss...") self.stop_loss = new_loss self.stop_loss_pct = -1 * abs(stoploss) self.initial_stop_loss = new_loss @@ -269,21 +269,20 @@ class Trade(_DECL_BASE): # evaluate if the stop loss needs to be updated else: if new_loss > self.stop_loss: # stop losses only walk up, never down! + logger.debug(f"{self.pair} - Adjusting stoploss...") self.stop_loss = new_loss self.stop_loss_pct = -1 * abs(stoploss) self.stoploss_last_update = datetime.utcnow() - logger.debug("adjusted stop loss") else: - logger.debug("keeping current stop loss") + logger.debug(f"{self.pair} - Keeping current stoploss...") logger.debug( - f"{self.pair} - current price {current_price:.8f}, " - f"bought at {self.open_rate:.8f} and calculated " - f"stop loss is at: {self.initial_stop_loss:.8f} initial " - f"stop at {self.stop_loss:.8f}. " - f"trailing stop loss saved us: " - f"{float(self.stop_loss) - float(self.initial_stop_loss):.8f} " - f"and max observed rate was {self.max_rate:.8f}") + f"{self.pair} - Stoploss adjusted. current_price={current_price:.8f}, " + f"open_rate={self.open_rate:.8f}, max_rate={self.max_rate:.8f}, " + f"initial_stop_loss={self.initial_stop_loss:.8f}, " + f"stop_loss={self.stop_loss:.8f}. " + f"Trailing stoploss saved us: " + f"{float(self.stop_loss) - float(self.initial_stop_loss):.8f}.") def update(self, order: Dict) -> None: """ @@ -331,24 +330,19 @@ class Trade(_DECL_BASE): self ) - def calc_open_trade_price( - self, - fee: Optional[float] = None) -> float: + def calc_open_trade_price(self, fee: Optional[float] = None) -> float: """ Calculate the open_rate including fee. :param fee: fee to use on the open rate (optional). If rate is not set self.fee will be used :return: Price in of the open trade incl. Fees """ - buy_trade = (Decimal(self.amount) * Decimal(self.open_rate)) fees = buy_trade * Decimal(fee or self.fee_open) return float(buy_trade + fees) - def calc_close_trade_price( - self, - rate: Optional[float] = None, - fee: Optional[float] = None) -> float: + def calc_close_trade_price(self, rate: Optional[float] = None, + fee: Optional[float] = None) -> float: """ Calculate the close_rate including fee :param fee: fee to use on the close rate (optional). @@ -357,7 +351,6 @@ class Trade(_DECL_BASE): If rate is not set self.close_rate will be used :return: Price in BTC of the open trade """ - if rate is None and not self.close_rate: return 0.0 @@ -365,10 +358,8 @@ class Trade(_DECL_BASE): fees = sell_trade * Decimal(fee or self.fee_close) return float(sell_trade - fees) - def calc_profit( - self, - rate: Optional[float] = None, - fee: Optional[float] = None) -> float: + def calc_profit(self, rate: Optional[float] = None, + fee: Optional[float] = None) -> float: """ Calculate the absolute profit in stake currency between Close and Open trade :param fee: fee to use on the close rate (optional). @@ -385,10 +376,8 @@ class Trade(_DECL_BASE): profit = close_trade_price - open_trade_price return float(f"{profit:.8f}") - def calc_profit_percent( - self, - rate: Optional[float] = None, - fee: Optional[float] = None) -> float: + def calc_profit_percent(self, rate: Optional[float] = None, + fee: Optional[float] = None) -> float: """ Calculates the profit in percentage (including fee). :param rate: rate to compare with (optional). @@ -396,7 +385,6 @@ class Trade(_DECL_BASE): :param fee: fee to use on the close rate (optional). :return: profit in percentage as float """ - open_trade_price = self.calc_open_trade_price() close_trade_price = self.calc_close_trade_price( rate=(rate or self.close_rate), @@ -436,8 +424,8 @@ class Trade(_DECL_BASE): and trade.initial_stop_loss_pct != desired_stoploss): # Stoploss value got changed - logger.info(f"Stoploss for {trade} needs adjustment.") + logger.info(f"Stoploss for {trade} needs adjustment...") # Force reset of stoploss trade.stop_loss = None trade.adjust_stop_loss(trade.open_rate, desired_stoploss) - logger.info(f"new stoploss: {trade.stop_loss}, ") + logger.info(f"New stoploss: {trade.stop_loss}.") diff --git a/freqtrade/strategy/interface.py b/freqtrade/strategy/interface.py index 6c6593a53..17246ecf7 100644 --- a/freqtrade/strategy/interface.py +++ b/freqtrade/strategy/interface.py @@ -202,7 +202,6 @@ class IStrategy(ABC): :param metadata: Metadata dictionary with additional data (e.g. 'pair') :return: DataFrame with ticker data and indicator data """ - pair = str(metadata.get('pair')) # Test if seen this pair and last candle before. @@ -292,7 +291,6 @@ class IStrategy(ABC): :param force_stoploss: Externally provided stoploss :return: True if trade should be sold, False otherwise """ - # Set current rate to low for backtesting sell current_rate = low or rate current_profit = trade.calc_profit_percent(current_rate) @@ -304,6 +302,8 @@ class IStrategy(ABC): force_stoploss=force_stoploss, high=high) if stoplossflag.sell_flag: + logger.debug(f"{trade.pair} - Stoploss hit. sell_flag=True, " + f"sell_type={stoplossflag.sell_type}") return stoplossflag # Set current rate to high for backtesting sell @@ -312,22 +312,31 @@ class IStrategy(ABC): experimental = self.config.get('experimental', {}) if buy and experimental.get('ignore_roi_if_buy_signal', False): - logger.debug('Buy signal still active - not selling.') + # This one is noisy, commented out + # logger.debug(f"{trade.pair} - Buy signal still active. sell_flag=False") return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE) # Check if minimal roi has been reached and no longer in buy conditions (avoiding a fee) if self.min_roi_reached(trade=trade, current_profit=current_profit, current_time=date): - logger.debug('Required profit reached. Selling..') + logger.debug(f"{trade.pair} - Required profit reached. sell_flag=True, " + f"sell_type=SellType.ROI") return SellCheckTuple(sell_flag=True, sell_type=SellType.ROI) if experimental.get('sell_profit_only', False): - logger.debug('Checking if trade is profitable..') + # This one is noisy, commented out + # logger.debug(f"{trade.pair} - Checking if trade is profitable...") if trade.calc_profit(rate=rate) <= 0: + # This one is noisy, commented out + # logger.debug(f"{trade.pair} - Trade is not profitable. sell_flag=False") return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE) + if sell and not buy and experimental.get('use_sell_signal', False): - logger.debug('Sell signal received. Selling..') + logger.debug(f"{trade.pair} - Sell signal received. sell_flag=True, " + f"sell_type=SellType.SELL_SIGNAL") return SellCheckTuple(sell_flag=True, sell_type=SellType.SELL_SIGNAL) + # This one is noisy, commented out... + # logger.debug(f"{trade.pair} - No sell signal. sell_flag=False") return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE) def stop_loss_reached(self, current_rate: float, trade: Trade, @@ -338,7 +347,6 @@ class IStrategy(ABC): decides to sell or not :param current_profit: current profit in percent """ - trailing_stop = self.config.get('trailing_stop', False) stop_loss_value = force_stoploss if force_stoploss else self.stoploss @@ -359,7 +367,7 @@ class IStrategy(ABC): if 'trailing_stop_positive' in self.config and high_profit > sl_offset: # Ignore mypy error check in configuration that this is a float stop_loss_value = self.config.get('trailing_stop_positive') # type: ignore - logger.debug(f"using positive stop loss: {stop_loss_value} " + logger.debug(f"{trade.pair} - Using positive stoploss: {stop_loss_value} " f"offset: {sl_offset:.4g} profit: {current_profit:.4f}%") trade.adjust_stop_loss(high or current_rate, stop_loss_value) @@ -369,20 +377,20 @@ class IStrategy(ABC): (trade.stop_loss >= current_rate) and (not self.order_types.get('stoploss_on_exchange'))): - selltype = SellType.STOP_LOSS + sell_type = SellType.STOP_LOSS # If initial stoploss is not the same as current one then it is trailing. if trade.initial_stop_loss != trade.stop_loss: - selltype = SellType.TRAILING_STOP_LOSS + sell_type = SellType.TRAILING_STOP_LOSS logger.debug( - f"HIT STOP: current price at {current_rate:.6f}, " - f"stop loss is {trade.stop_loss:.6f}, " - f"initial stop loss was at {trade.initial_stop_loss:.6f}, " + f"{trade.pair} - HIT STOP: current price at {current_rate:.6f}, " + f"stoploss is {trade.stop_loss:.6f}, " + f"initial stoploss was at {trade.initial_stop_loss:.6f}, " f"trade opened at {trade.open_rate:.6f}") - logger.debug(f"trailing stop saved {trade.stop_loss - trade.initial_stop_loss:.6f}") + logger.debug(f"{trade.pair} - Trailing stop saved " + f"{trade.stop_loss - trade.initial_stop_loss:.6f}") - logger.debug('Stop loss hit.') - return SellCheckTuple(sell_flag=True, sell_type=selltype) + return SellCheckTuple(sell_flag=True, sell_type=sell_type) return SellCheckTuple(sell_flag=False, sell_type=SellType.NONE) diff --git a/tests/test_freqtradebot.py b/tests/test_freqtradebot.py index 2e5014e0c..c26186e9d 100644 --- a/tests/test_freqtradebot.py +++ b/tests/test_freqtradebot.py @@ -1590,6 +1590,8 @@ def test_update_trade_state(mocker, default_conf, limit_buy_order, caplog) -> No Trade.session = MagicMock() trade.open_order_id = '123' trade.open_fee = 0.001 + # Add datetime explicitly since sqlalchemy defaults apply only once written to database + trade.open_date = arrow.utcnow().datetime freqtrade.update_trade_state(trade) # Test amount not modified by fee-logic assert not log_has_re(r'Applying fee to .*', caplog) @@ -1823,7 +1825,8 @@ def test_handle_trade_roi(default_conf, ticker, limit_buy_order, # if ROI is reached we must sell patch_get_signal(freqtrade, value=(False, True)) assert freqtrade.handle_trade(trade) - assert log_has('Required profit reached. Selling..', caplog) + assert log_has("ETH/BTC - Required profit reached. sell_flag=True, sell_type=SellType.ROI", + caplog) def test_handle_trade_experimental( @@ -1853,7 +1856,8 @@ def test_handle_trade_experimental( patch_get_signal(freqtrade, value=(False, True)) assert freqtrade.handle_trade(trade) - assert log_has('Sell signal received. Selling..', caplog) + assert log_has("ETH/BTC - Sell signal received. sell_flag=True, sell_type=SellType.SELL_SIGNAL", + caplog) def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order, @@ -2132,6 +2136,7 @@ def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) - ) freqtrade = FreqtradeBot(default_conf) + open_date = arrow.utcnow().shift(minutes=-601) trade_buy = Trade( pair='ETH/BTC', open_rate=0.00001099, @@ -2141,16 +2146,18 @@ def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) - fee_open=0.0, fee_close=0.0, stake_amount=1, - open_date=arrow.utcnow().shift(minutes=-601).datetime, + open_date=open_date.datetime, is_open=True ) Trade.session.add(trade_buy) freqtrade.check_handle_timedout() - assert log_has_re(r'Cannot query order for Trade\(id=1, pair=ETH/BTC, amount=90.99181073, ' - r'open_rate=0.00001099, open_since=10 hours ago\) due to Traceback \(most ' - r'recent call last\):\n.*', caplog) + assert log_has_re(r"Cannot query order for Trade\(id=1, pair=ETH/BTC, amount=90.99181073, " + r"open_rate=0.00001099, open_since=" + f"{open_date.strftime('%Y-%m-%d %H:%M:%S')}" + r"\) due to Traceback \(most recent call last\):\n*", + caplog) def test_handle_timedout_limit_buy(mocker, default_conf) -> None: @@ -2793,8 +2800,9 @@ def test_trailing_stop_loss(default_conf, limit_buy_order, fee, markets, caplog, # Sell as trailing-stop is reached assert freqtrade.handle_trade(trade) is True assert log_has( - f'HIT STOP: current price at 0.000012, stop loss is 0.000015, ' - f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog) + f"ETH/BTC - HIT STOP: current price at 0.000012, " + f"stoploss is 0.000015, " + f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog) assert trade.sell_reason == SellType.TRAILING_STOP_LOSS.value @@ -2836,8 +2844,8 @@ def test_trailing_stop_loss_positive(default_conf, limit_buy_order, fee, markets })) # stop-loss not reached, adjusted stoploss assert freqtrade.handle_trade(trade) is False - assert log_has(f'using positive stop loss: 0.01 offset: 0 profit: 0.2666%', caplog) - assert log_has(f'adjusted stop loss', caplog) + assert log_has(f"ETH/BTC - Using positive stoploss: 0.01 offset: 0 profit: 0.2666%", caplog) + assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog) assert trade.stop_loss == 0.0000138501 mocker.patch('freqtrade.exchange.Exchange.get_ticker', @@ -2849,9 +2857,9 @@ def test_trailing_stop_loss_positive(default_conf, limit_buy_order, fee, markets # Lower price again (but still positive) assert freqtrade.handle_trade(trade) is True assert log_has( - f'HIT STOP: current price at {buy_price + 0.000002:.6f}, ' - f'stop loss is {trade.stop_loss:.6f}, ' - f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog) + f"ETH/BTC - HIT STOP: current price at {buy_price + 0.000002:.6f}, " + f"stoploss is {trade.stop_loss:.6f}, " + f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog) def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee, @@ -2894,8 +2902,9 @@ def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee, })) # stop-loss not reached, adjusted stoploss assert freqtrade.handle_trade(trade) is False - assert log_has(f'using positive stop loss: 0.01 offset: 0.011 profit: 0.2666%', caplog) - assert log_has(f'adjusted stop loss', caplog) + assert log_has(f"ETH/BTC - Using positive stoploss: 0.01 offset: 0.011 profit: 0.2666%", + caplog) + assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog) assert trade.stop_loss == 0.0000138501 mocker.patch('freqtrade.exchange.Exchange.get_ticker', @@ -2907,9 +2916,9 @@ def test_trailing_stop_loss_offset(default_conf, limit_buy_order, fee, # Lower price again (but still positive) assert freqtrade.handle_trade(trade) is True assert log_has( - f'HIT STOP: current price at {buy_price + 0.000002:.6f}, ' - f'stop loss is {trade.stop_loss:.6f}, ' - f'initial stop loss was at 0.000010, trade opened at 0.000011', caplog) + f"ETH/BTC - HIT STOP: current price at {buy_price + 0.000002:.6f}, " + f"stoploss is {trade.stop_loss:.6f}, " + f"initial stoploss was at 0.000010, trade opened at 0.000011", caplog) assert trade.sell_reason == SellType.TRAILING_STOP_LOSS.value @@ -2960,7 +2969,7 @@ def test_tsl_only_offset_reached(default_conf, limit_buy_order, fee, # stop-loss should not be adjusted as offset is not reached yet assert freqtrade.handle_trade(trade) is False - assert not log_has(f'adjusted stop loss', caplog) + assert not log_has(f"ETH/BTC - Adjusting stoploss...", caplog) assert trade.stop_loss == 0.0000098910 # price rises above the offset (rises 12% when the offset is 5.5%) @@ -2972,8 +2981,9 @@ def test_tsl_only_offset_reached(default_conf, limit_buy_order, fee, })) assert freqtrade.handle_trade(trade) is False - assert log_has(f'using positive stop loss: 0.05 offset: 0.055 profit: 0.1218%', caplog) - assert log_has(f'adjusted stop loss', caplog) + assert log_has(f"ETH/BTC - Using positive stoploss: 0.05 offset: 0.055 profit: 0.1218%", + caplog) + assert log_has(f"ETH/BTC - Adjusting stoploss...", caplog) assert trade.stop_loss == 0.0000117705 @@ -3342,8 +3352,8 @@ def test_order_book_bid_strategy2(mocker, default_conf, order_book_l2, markets) default_conf['telegram']['enabled'] = False freqtrade = FreqtradeBot(default_conf) - # ordrebook shall be used even if tickers would be lower. - assert freqtrade.get_target_bid('ETH/BTC', ) != 0.042 + # orderbook shall be used even if tickers would be lower. + assert freqtrade.get_target_bid('ETH/BTC') != 0.042 assert ticker_mock.call_count == 0