Merge pull request #392 from stephendade/timeoutfix3

Order timeouts - added exception catching and rpc messaging

freqtrade/main.py

@@ -129,9 +129,17 @@ def check_handle_timedout(timeoutvalue: int) -> None:
     timeoutthreashold = arrow.utcnow().shift(minutes=-timeoutvalue).datetime
 
     for trade in Trade.query.filter(Trade.open_order_id.isnot(None)).all():
-        order = exchange.get_order(trade.open_order_id)
+        try:
+            order = exchange.get_order(trade.open_order_id)
+        except requests.exceptions.RequestException:
+            logger.info('Cannot query order for %s due to %s', trade, traceback.format_exc())
+            continue
         ordertime = arrow.get(order['opened'])
 
+        # Check if trade is still actually open
+        if int(order['remaining']) == 0:
+            continue
+
         if order['type'] == "LIMIT_BUY" and ordertime < timeoutthreashold:
             # Buy timeout - cancel order
             exchange.cancel_order(trade.open_order_id)
@@ -140,6 +148,8 @@ def check_handle_timedout(timeoutvalue: int) -> None:
                 Trade.session.delete(trade)
                 Trade.session.flush()
                 logger.info('Buy order timeout for %s.', trade)
+                rpc.send_msg('*Timeout:* Unfilled buy order for {} cancelled'.format(
+                             trade.pair.replace('_', '/')))
             else:
                 # if trade is partially complete, edit the stake details for the trade
                 # and close the order
@@ -147,6 +157,8 @@ def check_handle_timedout(timeoutvalue: int) -> None:
                 trade.stake_amount = trade.amount * trade.open_rate
                 trade.open_order_id = None
                 logger.info('Partial buy order timeout for %s.', trade)
+                rpc.send_msg('*Timeout:* Remaining buy order for {} cancelled'.format(
+                             trade.pair.replace('_', '/')))
         elif order['type'] == "LIMIT_SELL" and ordertime < timeoutthreashold:
             # Sell timeout - cancel order and update trade
             if order['remaining'] == order['amount']:
@@ -157,6 +169,8 @@ def check_handle_timedout(timeoutvalue: int) -> None:
                 trade.close_date = None
                 trade.is_open = True
                 trade.open_order_id = None
+                rpc.send_msg('*Timeout:* Unfilled sell order for {} cancelled'.format(
+                             trade.pair.replace('_', '/')))
                 logger.info('Sell order timeout for %s.', trade)
                 return True
             else:

freqtrade/tests/test_main.py

@@ -355,7 +355,8 @@ def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order, mo
 def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, mocker):
     mocker.patch.dict('freqtrade.main._CONF', default_conf)
     cancel_order_mock = MagicMock()
-    mocker.patch.multiple('freqtrade.rpc', init=MagicMock(), send_msg=MagicMock())
+    mocker.patch('freqtrade.rpc.init', MagicMock())
+    rpc_mock = mocker.patch('freqtrade.main.rpc.send_msg', MagicMock())
     mocker.patch.multiple('freqtrade.main.exchange',
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
@@ -380,6 +381,7 @@ def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, mo
     # check it does cancel buy orders over the time limit
     check_handle_timedout(600)
     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()
     assert len(trades) == 0
 
@@ -387,7 +389,8 @@ def test_check_handle_timedout_buy(default_conf, ticker, limit_buy_order_old, mo
 def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old, mocker):
     mocker.patch.dict('freqtrade.main._CONF', default_conf)
     cancel_order_mock = MagicMock()
-    mocker.patch.multiple('freqtrade.rpc', init=MagicMock(), send_msg=MagicMock())
+    mocker.patch('freqtrade.rpc.init', MagicMock())
+    rpc_mock = mocker.patch('freqtrade.main.rpc.send_msg', MagicMock())
     mocker.patch.multiple('freqtrade.main.exchange',
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
@@ -413,6 +416,7 @@ def test_check_handle_timedout_sell(default_conf, ticker, limit_sell_order_old,
     # check it does cancel sell orders over the time limit
     check_handle_timedout(600)
     assert cancel_order_mock.call_count == 1
+    assert rpc_mock.call_count == 1
     assert trade_sell.is_open is True
 
 
@@ -420,7 +424,8 @@ def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old
                                        mocker):
     mocker.patch.dict('freqtrade.main._CONF', default_conf)
     cancel_order_mock = MagicMock()
-    mocker.patch.multiple('freqtrade.rpc', init=MagicMock(), send_msg=MagicMock())
+    mocker.patch('freqtrade.rpc.init', MagicMock())
+    rpc_mock = mocker.patch('freqtrade.main.rpc.send_msg', MagicMock())
     mocker.patch.multiple('freqtrade.main.exchange',
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
@@ -446,6 +451,7 @@ def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old
     # note this is for a partially-complete buy order
     check_handle_timedout(600)
     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()
     assert len(trades) == 1
     assert trades[0].amount == 23.0