Merge pull request #2384 from freqtrade/improve_buy_timeout_handling

Improve buy timeout handling

freqtrade/constants.py

@@ -266,6 +266,6 @@ CONF_SCHEMA = {
         'stake_amount',
         'dry_run',
         'bid_strategy',
-        'telegram'
+        'unfilledtimeout',
     ]
 }

freqtrade/freqtradebot.py

@@ -11,7 +11,7 @@ from typing import Any, Dict, List, Optional, Tuple
 import arrow
 from requests.exceptions import RequestException
 
-from freqtrade import (DependencyException, OperationalException, InvalidOrderException,
+from freqtrade import (DependencyException, InvalidOrderException,
                        __version__, constants, persistence)
 from freqtrade.data.converter import order_book_to_dataframe
 from freqtrade.data.dataprovider import DataProvider
@@ -466,11 +466,12 @@ class FreqtradeBot:
         if result:
             self.wallets.update()
 
-    def get_real_amount(self, trade: Trade, order: Dict) -> float:
+    def get_real_amount(self, trade: Trade, order: Dict, order_amount: float = None) -> float:
         """
         Get real amount for the trade
         Necessary for exchanges which charge fees in base currency (e.g. binance)
         """
+        if order_amount is None:
             order_amount = order['amount']
         # Only run for closed orders
         if trade.fee_open == 0 or order['status'] == 'open':
@@ -508,7 +509,7 @@ class FreqtradeBot:
 
         if not isclose(amount, order_amount, abs_tol=constants.MATH_CLOSE_PREC):
             logger.warning(f"Amount {amount} does not match amount {trade.amount}")
-            raise OperationalException("Half bought? Amounts don't match")
+            raise DependencyException("Half bought? Amounts don't match")
         real_amount = amount - fee_abs
         if fee_abs != 0:
             logger.info(f"Applying fee on amount for {trade} "
@@ -536,7 +537,7 @@ class FreqtradeBot:
                     # Fee was applied, so set to 0
                     trade.fee_open = 0
 
-            except OperationalException as exception:
+            except DependencyException as exception:
                 logger.warning("Could not update trade amount: %s", exception)
 
             trade.update(order)
@@ -772,19 +773,17 @@ class FreqtradeBot:
                 self.wallets.update()
                 continue
 
-            # Handle cancelled on exchange
+            if (order['side'] == 'buy'
-            if order['status'] == 'canceled':
+                and order['status'] == 'canceled'
-                if order['side'] == 'buy':
+                or (order['status'] == 'open'
-                    self.handle_buy_order_full_cancel(trade, "canceled on Exchange")
+                    and order['side'] == 'buy' and ordertime < buy_timeoutthreashold)):
-                elif order['side'] == 'sell':
+
-                    self.handle_timedout_limit_sell(trade, order)
-                    self.wallets.update()
-            # Check if order is still actually open
-            elif order['status'] == 'open':
-                if order['side'] == 'buy' and ordertime < buy_timeoutthreashold:
                 self.handle_timedout_limit_buy(trade, order)
                 self.wallets.update()
-                elif order['side'] == 'sell' and ordertime < sell_timeoutthreashold:
+
+            elif (order['side'] == 'sell' and order['status'] == 'canceled'
+                  or (order['status'] == 'open'
+                      and order['side'] == 'sell' and ordertime < sell_timeoutthreashold)):
                 self.handle_timedout_limit_sell(trade, order)
                 self.wallets.update()
 
@@ -802,16 +801,33 @@ class FreqtradeBot:
         """Buy timeout - cancel order
         :return: True if order was fully cancelled
         """
-        self.exchange.cancel_order(trade.open_order_id, trade.pair)
+        reason = "cancelled due to timeout"
-        if order['remaining'] == order['amount']:
+        if order['status'] != 'canceled':
+            corder = self.exchange.cancel_order(trade.open_order_id, trade.pair)
+        else:
+            # Order was cancelled already, so we can reuse the existing dict
+            corder = order
+            reason = "canceled on Exchange"
+
+        if corder['remaining'] == corder['amount']:
             # if trade is not partially completed, just delete the trade
-            self.handle_buy_order_full_cancel(trade, "cancelled due to timeout")
+            self.handle_buy_order_full_cancel(trade, reason)
             return True
 
         # if trade is partially complete, edit the stake details for the trade
         # and close the order
-        trade.amount = order['amount'] - order['remaining']
+        trade.amount = corder['amount'] - corder['remaining']
         trade.stake_amount = trade.amount * trade.open_rate
+        # verify if fees were taken from amount to avoid problems during selling
+        try:
+            new_amount = self.get_real_amount(trade, corder, trade.amount)
+            if not isclose(order['amount'], new_amount, abs_tol=constants.MATH_CLOSE_PREC):
+                trade.amount = new_amount
+                # Fee was applied, so set to 0
+                trade.fee_open = 0
+        except DependencyException as e:
+            logger.warning("Could not update trade amount: %s", e)
+
         trade.open_order_id = None
         logger.info('Partial buy order timeout for %s.', trade)
         self.rpc.send_msg({

freqtrade/rpc/rpc_manager.py

@@ -18,7 +18,7 @@ class RPCManager:
         self.registered_modules: List[RPC] = []
 
         # Enable telegram
-        if freqtrade.config['telegram'].get('enabled', False):
+        if freqtrade.config.get('telegram', {}).get('enabled', False):
             logger.info('Enabling rpc.telegram ...')
             from freqtrade.rpc.telegram import Telegram
             self.registered_modules.append(Telegram(freqtrade))

tests/conftest.py

@@ -9,8 +9,8 @@ from pathlib import Path
 from unittest.mock import MagicMock, PropertyMock
 
 import arrow
-import pytest
 import numpy as np
+import pytest
 from telegram import Chat, Message, Update
 
 from freqtrade import constants, persistence
@@ -19,10 +19,10 @@ from freqtrade.data.converter import parse_ticker_dataframe
 from freqtrade.edge import Edge, PairInfo
 from freqtrade.exchange import Exchange
 from freqtrade.freqtradebot import FreqtradeBot
+from freqtrade.persistence import Trade
 from freqtrade.resolvers import ExchangeResolver
 from freqtrade.worker import Worker
 
-
 logging.getLogger('').setLevel(logging.INFO)
 
 
@@ -608,6 +608,14 @@ def limit_buy_order_old_partial():
     }
 
 
+@pytest.fixture
+def limit_buy_order_old_partial_canceled(limit_buy_order_old_partial):
+    res = deepcopy(limit_buy_order_old_partial)
+    res['status'] = 'canceled'
+    res['fee'] = {'cost': 0.0001, 'currency': 'ETH'}
+    return res
+
+
 @pytest.fixture
 def limit_sell_order():
     return {
@@ -896,12 +904,6 @@ def result(testdatadir):
         return parse_ticker_dataframe(json.load(data_file), '1m', pair="UNITTEST/BTC",
                                       fill_missing=True)
 
-# FIX:
-# Create an fixture/function
-# that inserts a trade of some type and open-status
-# return the open-order-id
-# See tests in rpc/main that could use this
-
 
 @pytest.fixture(scope="function")
 def trades_for_order():
@@ -1075,3 +1077,19 @@ def import_fails() -> None:
 
     # restore previous importfunction
     builtins.__import__ = realimport
+
+
+@pytest.fixture(scope="function")
+def open_trade():
+    return Trade(
+        pair='ETH/BTC',
+        open_rate=0.00001099,
+        exchange='bittrex',
+        open_order_id='123456789',
+        amount=90.99181073,
+        fee_open=0.0,
+        fee_close=0.0,
+        stake_amount=1,
+        open_date=arrow.utcnow().shift(minutes=-601).datetime,
+        is_open=True
+    )

tests/test_freqtradebot.py

@@ -1678,7 +1678,7 @@ def test_update_trade_state_exception(mocker, default_conf,
     # Test raise of OperationalException exception
     mocker.patch(
         'freqtrade.freqtradebot.FreqtradeBot.get_real_amount',
-        side_effect=OperationalException()
+        side_effect=DependencyException()
     )
     freqtrade.update_trade_state(trade)
     assert log_has('Could not update trade amount: ', caplog)
@@ -1916,7 +1916,8 @@ def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order,
         freqtrade.handle_trade(trade)
 
 
-def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, fee, mocker) -> None:
+def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, open_trade,
+                                   fee, mocker) -> None:
     rpc_mock = patch_RPCManager(mocker)
     cancel_order_mock = MagicMock()
     patch_exchange(mocker)
@@ -1929,31 +1930,18 @@ def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, fe
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_buy = Trade(
+    Trade.session.add(open_trade)
-        pair='ETH/BTC',
-        open_rate=0.00001099,
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    Trade.session.add(trade_buy)
 
     # check it does cancel buy orders over the time limit
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 1
     assert rpc_mock.call_count == 1
-    trades = Trade.query.filter(Trade.open_order_id.is_(trade_buy.open_order_id)).all()
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
     nb_trades = len(trades)
     assert nb_trades == 0
 
 
-def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old,
+def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old, open_trade,
                                     fee, mocker, caplog) -> None:
     """ Handle Buy order cancelled on exchange"""
     rpc_mock = patch_RPCManager(mocker)
@@ -1969,32 +1957,19 @@ def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old,
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_buy = Trade(
+    Trade.session.add(open_trade)
-        pair='ETH/BTC',
-        open_rate=0.00001099,
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    Trade.session.add(trade_buy)
 
     # check it does cancel buy orders over the time limit
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 0
     assert rpc_mock.call_count == 1
-    trades = Trade.query.filter(Trade.open_order_id.is_(trade_buy.open_order_id)).all()
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
     nb_trades = len(trades)
     assert nb_trades == 0
     assert log_has_re("Buy order canceled on Exchange for Trade.*", caplog)
 
 
-def test_check_handle_timedout_buy_exception(default_conf, ticker, limit_buy_order_old,
+def test_check_handle_timedout_buy_exception(default_conf, ticker, limit_buy_order_old, open_trade,
                                              fee, mocker) -> None:
     rpc_mock = patch_RPCManager(mocker)
     cancel_order_mock = MagicMock()
@@ -2009,31 +1984,19 @@ def test_check_handle_timedout_buy_exception(default_conf, ticker, limit_buy_ord
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_buy = Trade(
+    Trade.session.add(open_trade)
-        pair='ETH/BTC',
-        open_rate=0.00001099,
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    Trade.session.add(trade_buy)
 
     # check it does cancel buy orders over the time limit
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 0
     assert rpc_mock.call_count == 0
-    trades = Trade.query.filter(Trade.open_order_id.is_(trade_buy.open_order_id)).all()
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
     nb_trades = len(trades)
     assert nb_trades == 1
 
 
-def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old, mocker) -> None:
+def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old, mocker,
+                                    open_trade) -> None:
     rpc_mock = patch_RPCManager(mocker)
     cancel_order_mock = MagicMock()
     patch_exchange(mocker)
@@ -2045,30 +2008,20 @@ def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old,
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_sell = Trade(
+    open_trade.open_date = arrow.utcnow().shift(hours=-5).datetime
-        pair='ETH/BTC',
+    open_trade.close_date = arrow.utcnow().shift(minutes=-601).datetime
-        open_rate=0.00001099,
+    open_trade.is_open = False
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(hours=-5).datetime,
-        close_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=False
-    )
 
-    Trade.session.add(trade_sell)
+    Trade.session.add(open_trade)
 
     # check it does cancel sell orders over the time limit
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 1
     assert rpc_mock.call_count == 1
-    assert trade_sell.is_open is True
+    assert open_trade.is_open is True
 
 
-def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old,
+def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old, open_trade,
                                      mocker, caplog) -> None:
     """ Handle sell order cancelled on exchange"""
     rpc_mock = patch_RPCManager(mocker)
@@ -2083,34 +2036,24 @@ def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old,
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_sell = Trade(
+    open_trade.open_date = arrow.utcnow().shift(hours=-5).datetime
-        pair='ETH/BTC',
+    open_trade.close_date = arrow.utcnow().shift(minutes=-601).datetime
-        open_rate=0.00001099,
+    open_trade.is_open = False
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(hours=-5).datetime,
-        close_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=False
-    )
 
-    Trade.session.add(trade_sell)
+    Trade.session.add(open_trade)
 
     # check it does cancel sell orders over the time limit
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 0
     assert rpc_mock.call_count == 1
-    assert trade_sell.is_open is True
+    assert open_trade.is_open is True
     assert log_has_re("Sell order canceled on exchange for Trade.*", caplog)
 
 
 def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old_partial,
-                                       mocker) -> None:
+                                       open_trade, mocker) -> None:
     rpc_mock = patch_RPCManager(mocker)
-    cancel_order_mock = MagicMock()
+    cancel_order_mock = MagicMock(return_value=limit_buy_order_old_partial)
     patch_exchange(mocker)
     mocker.patch.multiple(
         'freqtrade.exchange.Exchange',
@@ -2120,33 +2063,97 @@ def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    trade_buy = Trade(
+    Trade.session.add(open_trade)
-        pair='ETH/BTC',
-        open_rate=0.00001099,
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    Trade.session.add(trade_buy)
 
     # check it does cancel buy orders over the time limit
     # note this is for a partially-complete buy order
     freqtrade.check_handle_timedout()
     assert cancel_order_mock.call_count == 1
     assert rpc_mock.call_count == 1
-    trades = Trade.query.filter(Trade.open_order_id.is_(trade_buy.open_order_id)).all()
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
     assert len(trades) == 1
     assert trades[0].amount == 23.0
-    assert trades[0].stake_amount == trade_buy.open_rate * trades[0].amount
+    assert trades[0].stake_amount == open_trade.open_rate * trades[0].amount
 
 
-def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) -> None:
+def test_check_handle_timedout_partial_fee(default_conf, ticker, open_trade, caplog, fee,
+                                           limit_buy_order_old_partial, trades_for_order,
+                                           limit_buy_order_old_partial_canceled, mocker) -> None:
+    rpc_mock = patch_RPCManager(mocker)
+    cancel_order_mock = MagicMock(return_value=limit_buy_order_old_partial_canceled)
+    patch_exchange(mocker)
+    mocker.patch.multiple(
+        'freqtrade.exchange.Exchange',
+        get_ticker=ticker,
+        get_order=MagicMock(return_value=limit_buy_order_old_partial),
+        cancel_order=cancel_order_mock,
+        get_trades_for_order=MagicMock(return_value=trades_for_order),
+    )
+    freqtrade = FreqtradeBot(default_conf)
+
+    assert open_trade.amount == limit_buy_order_old_partial['amount']
+
+    open_trade.fee_open = fee()
+    open_trade.fee_close = fee()
+    Trade.session.add(open_trade)
+    # cancelling a half-filled order should update the amount to the bought amount
+    # and apply fees if necessary.
+    freqtrade.check_handle_timedout()
+
+    assert log_has_re(r"Applying fee on amount for Trade.* Order", caplog)
+
+    assert cancel_order_mock.call_count == 1
+    assert rpc_mock.call_count == 1
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
+    assert len(trades) == 1
+    # Verify that tradehas been updated
+    assert trades[0].amount == (limit_buy_order_old_partial['amount'] -
+                                limit_buy_order_old_partial['remaining']) - 0.0001
+    assert trades[0].open_order_id is None
+    assert trades[0].fee_open == 0
+
+
+def test_check_handle_timedout_partial_except(default_conf, ticker, open_trade, caplog, fee,
+                                              limit_buy_order_old_partial, trades_for_order,
+                                              limit_buy_order_old_partial_canceled, mocker) -> None:
+    rpc_mock = patch_RPCManager(mocker)
+    cancel_order_mock = MagicMock(return_value=limit_buy_order_old_partial_canceled)
+    patch_exchange(mocker)
+    mocker.patch.multiple(
+        'freqtrade.exchange.Exchange',
+        get_ticker=ticker,
+        get_order=MagicMock(return_value=limit_buy_order_old_partial),
+        cancel_order=cancel_order_mock,
+        get_trades_for_order=MagicMock(return_value=trades_for_order),
+    )
+    mocker.patch('freqtrade.freqtradebot.FreqtradeBot.get_real_amount',
+                 MagicMock(side_effect=DependencyException))
+    freqtrade = FreqtradeBot(default_conf)
+
+    assert open_trade.amount == limit_buy_order_old_partial['amount']
+
+    open_trade.fee_open = fee()
+    open_trade.fee_close = fee()
+    Trade.session.add(open_trade)
+    # cancelling a half-filled order should update the amount to the bought amount
+    # and apply fees if necessary.
+    freqtrade.check_handle_timedout()
+
+    assert log_has_re(r"Could not update trade amount: .*", caplog)
+
+    assert cancel_order_mock.call_count == 1
+    assert rpc_mock.call_count == 1
+    trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all()
+    assert len(trades) == 1
+    # Verify that tradehas been updated
+
+    assert trades[0].amount == (limit_buy_order_old_partial['amount'] -
+                                limit_buy_order_old_partial['remaining'])
+    assert trades[0].open_order_id is None
+    assert trades[0].fee_open == fee()
+
+
+def test_check_handle_timedout_exception(default_conf, ticker, open_trade, mocker, caplog) -> None:
     patch_RPCManager(mocker)
     patch_exchange(mocker)
     cancel_order_mock = MagicMock()
@@ -2164,34 +2171,20 @@ def test_check_handle_timedout_exception(default_conf, ticker, mocker, caplog) -
     )
     freqtrade = FreqtradeBot(default_conf)
 
-    open_date = arrow.utcnow().shift(minutes=-601)
+    Trade.session.add(open_trade)
-    trade_buy = Trade(
-        pair='ETH/BTC',
-        open_rate=0.00001099,
-        exchange='bittrex',
-        open_order_id='123456789',
-        amount=90.99181073,
-        fee_open=0.0,
-        fee_close=0.0,
-        stake_amount=1,
-        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="
-                      f"{open_date.strftime('%Y-%m-%d %H:%M:%S')}"
+                      f"{open_trade.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:
+def test_handle_timedout_limit_buy(mocker, default_conf, limit_buy_order) -> None:
     patch_RPCManager(mocker)
     patch_exchange(mocker)
-    cancel_order_mock = MagicMock()
+    cancel_order_mock = MagicMock(return_value=limit_buy_order)
     mocker.patch.multiple(
         'freqtrade.exchange.Exchange',
         cancel_order=cancel_order_mock
@@ -2201,13 +2194,14 @@ def test_handle_timedout_limit_buy(mocker, default_conf) -> None:
 
     Trade.session = MagicMock()
     trade = MagicMock()
-    order = {'remaining': 1,
+    limit_buy_order['remaining'] = limit_buy_order['amount']
-             'amount': 1}
+    assert freqtrade.handle_timedout_limit_buy(trade, limit_buy_order)
-    assert freqtrade.handle_timedout_limit_buy(trade, order)
+    assert cancel_order_mock.call_count == 1
+
+    cancel_order_mock.reset_mock()
+    limit_buy_order['amount'] = 2
+    assert not freqtrade.handle_timedout_limit_buy(trade, limit_buy_order)
     assert cancel_order_mock.call_count == 1
-    order['amount'] = 2
-    assert not freqtrade.handle_timedout_limit_buy(trade, order)
-    assert cancel_order_mock.call_count == 2
 
 
 def test_handle_timedout_limit_sell(mocker, default_conf) -> None:
@@ -3361,7 +3355,7 @@ def test_get_real_amount_wrong_amount(default_conf, trades_for_order, buy_order_
     patch_get_signal(freqtrade)
 
     # Amount does not change
-    with pytest.raises(OperationalException, match=r"Half bought\? Amounts don't match"):
+    with pytest.raises(DependencyException, match=r"Half bought\? Amounts don't match"):
         freqtrade.get_real_amount(trade, limit_buy_order)