Merge pull request #1535 from freqtrade/fix/cancelled_on_exchange

Fix/cancelled on exchange

freqtrade/freqtradebot.py

@@ -738,8 +738,15 @@ class FreqtradeBot(object):
                 self.wallets.update()
                 continue
 
-            # Check if trade is still actually open
-            if order['status'] == 'open':
+            # Handle cancelled on exchange
+            if order['status'] == 'canceled':
+                if order['side'] == 'buy':
+                    self.handle_buy_order_full_cancel(trade, "canceled on Exchange")
+                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()
@@ -747,24 +754,24 @@ class FreqtradeBot(object):
                     self.handle_timedout_limit_sell(trade, order)
                     self.wallets.update()
 
-    # FIX: 20180110, why is cancel.order unconditionally here, whereas
-    #                it is conditionally called in the
-    #                handle_timedout_limit_sell()?
+    def handle_buy_order_full_cancel(self, trade: Trade, reason: str) -> None:
+        """Close trade in database and send message"""
+        Trade.session.delete(trade)
+        Trade.session.flush()
+        logger.info('Buy order %s for %s.', reason, trade)
+        self.rpc.send_msg({
+            'type': RPCMessageType.STATUS_NOTIFICATION,
+            'status': f'Unfilled buy order for {trade.pair} {reason}'
+        })
+
     def handle_timedout_limit_buy(self, trade: Trade, order: Dict) -> bool:
         """Buy timeout - cancel order
         :return: True if order was fully cancelled
         """
-        pair_s = trade.pair.replace('_', '/')
         self.exchange.cancel_order(trade.open_order_id, trade.pair)
         if order['remaining'] == order['amount']:
             # if trade is not partially completed, just delete the trade
-            Trade.session.delete(trade)
-            Trade.session.flush()
-            logger.info('Buy order timeout for %s.', trade)
-            self.rpc.send_msg({
-                'type': RPCMessageType.STATUS_NOTIFICATION,
-                'status': f'Unfilled buy order for {pair_s} cancelled due to timeout'
-            })
+            self.handle_buy_order_full_cancel(trade, "cancelled due to timeout")
             return True
 
         # if trade is partially complete, edit the stake details for the trade
@@ -775,20 +782,24 @@ class FreqtradeBot(object):
         logger.info('Partial buy order timeout for %s.', trade)
         self.rpc.send_msg({
             'type': RPCMessageType.STATUS_NOTIFICATION,
-            'status': f'Remaining buy order for {pair_s} cancelled due to timeout'
+            'status': f'Remaining buy order for {trade.pair} cancelled due to timeout'
         })
         return False
 
-    # FIX: 20180110, should cancel_order() be cond. or unconditionally called?
     def handle_timedout_limit_sell(self, trade: Trade, order: Dict) -> bool:
         """
         Sell timeout - cancel order and update trade
         :return: True if order was fully cancelled
         """
-        pair_s = trade.pair.replace('_', '/')
         if order['remaining'] == order['amount']:
             # if trade is not partially completed, just cancel the trade
-            self.exchange.cancel_order(trade.open_order_id, trade.pair)
+            if order["status"] != "canceled":
+                reason = "due to timeout"
+                self.exchange.cancel_order(trade.open_order_id, trade.pair)
+                logger.info('Sell order timeout for %s.', trade)
+            else:
+                reason = "on exchange"
+                logger.info('Sell order canceled on exchange for %s.', trade)
             trade.close_rate = None
             trade.close_profit = None
             trade.close_date = None
@@ -796,9 +807,9 @@ class FreqtradeBot(object):
             trade.open_order_id = None
             self.rpc.send_msg({
                 'type': RPCMessageType.STATUS_NOTIFICATION,
-                'status': f'Unfilled sell order for {pair_s} cancelled due to timeout'
+                'status': f'Unfilled sell order for {trade.pair} cancelled {reason}'
             })
-            logger.info('Sell order timeout for %s.', trade)
+
             return True
 
         # TODO: figure out how to handle partially complete sell orders

freqtrade/tests/conftest.py

@@ -1,6 +1,7 @@
 # pragma pylint: disable=missing-docstring
 import json
 import logging
+import re
 from datetime import datetime
 from functools import reduce
 from typing import Dict, Optional
@@ -27,6 +28,12 @@ def log_has(line, logs):
                   False)
 
 
+def log_has_re(line, logs):
+    return reduce(lambda a, b: a or b,
+                  filter(lambda x: re.match(line, x[2]), logs),
+                  False)
+
+
 def patch_exchange(mocker, api_mock=None, id='bittrex') -> None:
     mocker.patch('freqtrade.exchange.Exchange._load_markets', MagicMock(return_value={}))
     mocker.patch('freqtrade.exchange.Exchange.validate_timeframes', MagicMock())

freqtrade/tests/test_freqtradebot.py

@@ -18,7 +18,7 @@ from freqtrade.persistence import Trade
 from freqtrade.rpc import RPCMessageType
 from freqtrade.state import State
 from freqtrade.strategy.interface import SellType, SellCheckTuple
-from freqtrade.tests.conftest import log_has, patch_exchange, patch_edge, patch_wallet
+from freqtrade.tests.conftest import log_has, log_has_re, patch_exchange, patch_edge, patch_wallet
 
 
 # Functions for recurrent object patching
@@ -1554,6 +1554,47 @@ def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, fe
     assert nb_trades == 0
 
 
+def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old,
+                                    fee, mocker, caplog) -> None:
+    """ Handle Buy order cancelled on exchange"""
+    rpc_mock = patch_RPCManager(mocker)
+    cancel_order_mock = MagicMock()
+    patch_exchange(mocker)
+    limit_buy_order_old.update({"status": "canceled"})
+    mocker.patch.multiple(
+        'freqtrade.exchange.Exchange',
+        get_ticker=ticker,
+        get_order=MagicMock(return_value=limit_buy_order_old),
+        cancel_order=cancel_order_mock,
+        get_fee=fee
+    )
+    freqtrade = FreqtradeBot(default_conf)
+
+    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=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()
+    nb_trades = len(trades)
+    assert nb_trades == 0
+    assert log_has_re("Buy order canceled on Exchange for Trade.*", caplog.record_tuples)
+
+
 def test_check_handle_timedout_buy_exception(default_conf, ticker, limit_buy_order_old,
                                              fee, mocker) -> None:
     rpc_mock = patch_RPCManager(mocker)
@@ -1628,6 +1669,45 @@ def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old,
     assert trade_sell.is_open is True
 
 
+def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old,
+                                     mocker, caplog) -> None:
+    """ Handle sell order cancelled on exchange"""
+    rpc_mock = patch_RPCManager(mocker)
+    cancel_order_mock = MagicMock()
+    limit_sell_order_old.update({"status": "canceled"})
+    patch_exchange(mocker)
+    mocker.patch.multiple(
+        'freqtrade.exchange.Exchange',
+        get_ticker=ticker,
+        get_order=MagicMock(return_value=limit_sell_order_old),
+        cancel_order=cancel_order_mock
+    )
+    freqtrade = FreqtradeBot(default_conf)
+
+    trade_sell = 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(hours=-5).datetime,
+        close_date=arrow.utcnow().shift(minutes=-601).datetime,
+        is_open=False
+    )
+
+    Trade.session.add(trade_sell)
+
+    # 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 log_has_re("Sell order canceled on exchange for Trade.*", caplog.record_tuples)
+
+
 def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old_partial,
                                        mocker) -> None:
     rpc_mock = patch_RPCManager(mocker)
@@ -1744,7 +1824,8 @@ def test_handle_timedout_limit_sell(mocker, default_conf) -> None:
 
     trade = MagicMock()
     order = {'remaining': 1,
-             'amount': 1}
+             'amount': 1,
+             'status': "open"}
     assert freqtrade.handle_timedout_limit_sell(trade, order)
     assert cancel_order_mock.call_count == 1
     order['amount'] = 2