Merge pull request #306 from stephendade/timeoutfix

Unfilled order timeouts - now using timestamps from exchange

freqtrade/main.py

@@ -5,7 +5,8 @@ import logging
 import sys
 import time
 import traceback
-from datetime import datetime, timedelta
+import arrow
+from datetime import datetime
 from typing import Dict, Optional, List
 
 import requests
@@ -98,9 +99,9 @@ def _process(nb_assets: Optional[int] = 0) -> bool:
                 # Check if we can sell our current pair
                 state_changed = handle_trade(trade) or state_changed
 
-            if 'unfilledtimeout' in _CONF and trade.open_order_id:
+        if 'unfilledtimeout' in _CONF:
-                # Check and handle any timed out trades
+            # Check and handle any timed out open orders
-                check_handle_timedout(trade)
+            check_handle_timedout(_CONF['unfilledtimeout'])
 
             Trade.session.flush()
     except (requests.exceptions.RequestException, json.JSONDecodeError) as error:
@@ -119,48 +120,48 @@ def _process(nb_assets: Optional[int] = 0) -> bool:
     return state_changed
 
 
-def check_handle_timedout(trade: Trade) -> bool:
+def check_handle_timedout(timeoutvalue: int) -> None:
     """
-    Check if a trade is timed out and cancel if neccessary
+    Check if any orders are timed out and cancel if neccessary
-    :param trade: Trade instance
+    :param timeoutvalue: Number of minutes until order is considered timed out
-    :return: True if the trade is timed out, false otherwise
+    :return: None
     """
-    timeoutthreashold = datetime.utcnow() - timedelta(minutes=_CONF['unfilledtimeout'])
+    timeoutthreashold = arrow.utcnow().shift(minutes=-timeoutvalue).datetime
-    order = exchange.get_order(trade.open_order_id)
 
-    if trade.open_date < timeoutthreashold:
+    for trade in Trade.query.filter(Trade.open_order_id.isnot(None)).all():
-        # Buy timeout - cancel order
+        order = exchange.get_order(trade.open_order_id)
-        exchange.cancel_order(trade.open_order_id)
+        ordertime = arrow.get(order['opened'])
-        if order['remaining'] == order['amount']:
+
-            # if trade is not partially completed, just delete the trade
+        if order['type'] == "LIMIT_BUY" and ordertime < timeoutthreashold:
-            Trade.session.delete(trade)
+            # Buy timeout - cancel order
-            Trade.session.flush()
-            logger.info('Buy order timeout for %s.', trade)
-        else:
-            # if trade is partially complete, edit the stake details for the trade
-            # and close the order
-            trade.amount = order['amount'] - order['remaining']
-            trade.stake_amount = trade.amount * trade.open_rate
-            trade.open_order_id = None
-            logger.info('Partial buy order timeout for %s.', trade)
-        return True
-    elif trade.close_date is not None and trade.close_date < timeoutthreashold:
-        # Sell timeout - cancel order and update trade
-        if order['remaining'] == order['amount']:
-            # if trade is not partially completed, just cancel the trade
             exchange.cancel_order(trade.open_order_id)
-            trade.close_rate = None
+            if order['remaining'] == order['amount']:
-            trade.close_profit = None
+                # if trade is not partially completed, just delete the trade
-            trade.close_date = None
+                Trade.session.delete(trade)
-            trade.is_open = True
+                Trade.session.flush()
-            trade.open_order_id = None
+                logger.info('Buy order timeout for %s.', trade)
-            logger.info('Sell order timeout for %s.', trade)
+            else:
-            return True
+                # if trade is partially complete, edit the stake details for the trade
-        else:
+                # and close the order
-            # TODO: figure out how to handle partially complete sell orders
+                trade.amount = order['amount'] - order['remaining']
-            return False
+                trade.stake_amount = trade.amount * trade.open_rate
-    else:
+                trade.open_order_id = None
-        return False
+                logger.info('Partial buy order timeout for %s.', trade)
+        elif order['type'] == "LIMIT_SELL" and ordertime < timeoutthreashold:
+            # Sell timeout - cancel order and update trade
+            if order['remaining'] == order['amount']:
+                # if trade is not partially completed, just cancel the trade
+                exchange.cancel_order(trade.open_order_id)
+                trade.close_rate = None
+                trade.close_profit = None
+                trade.close_date = None
+                trade.is_open = True
+                trade.open_order_id = None
+                logger.info('Sell order timeout for %s.', trade)
+                return True
+            else:
+                # TODO: figure out how to handle partially complete sell orders
+                pass
 
 
 def execute_sell(trade: Trade, limit: float) -> None:

freqtrade/tests/conftest.py

@@ -3,6 +3,7 @@ from datetime import datetime
 from unittest.mock import MagicMock
 
 import pytest
+import arrow
 from jsonschema import validate
 from telegram import Message, Chat, Update
 
@@ -123,11 +124,50 @@ def limit_buy_order():
         'id': 'mocked_limit_buy',
         'type': 'LIMIT_BUY',
         'pair': 'mocked',
-        'opened': datetime.utcnow(),
+        'opened': str(arrow.utcnow().datetime),
         'rate': 0.00001099,
         'amount': 90.99181073,
         'remaining': 0.0,
-        'closed': datetime.utcnow(),
+        'closed': str(arrow.utcnow().datetime),
+    }
+
+
+@pytest.fixture
+def limit_buy_order_old():
+    return {
+        'id': 'mocked_limit_buy_old',
+        'type': 'LIMIT_BUY',
+        'pair': 'BTC_ETH',
+        'opened': str(arrow.utcnow().shift(minutes=-601).datetime),
+        'rate': 0.00001099,
+        'amount': 90.99181073,
+        'remaining': 90.99181073,
+    }
+
+
+@pytest.fixture
+def limit_sell_order_old():
+    return {
+        'id': 'mocked_limit_sell_old',
+        'type': 'LIMIT_SELL',
+        'pair': 'BTC_ETH',
+        'opened': str(arrow.utcnow().shift(minutes=-601).datetime),
+        'rate': 0.00001099,
+        'amount': 90.99181073,
+        'remaining': 90.99181073,
+    }
+
+
+@pytest.fixture
+def limit_buy_order_old_partial():
+    return {
+        'id': 'mocked_limit_buy_old_partial',
+        'type': 'LIMIT_BUY',
+        'pair': 'BTC_ETH',
+        'opened': str(arrow.utcnow().shift(minutes=-601).datetime),
+        'rate': 0.00001099,
+        'amount': 90.99181073,
+        'remaining': 67.99181073,
     }
 
 
@@ -137,11 +177,11 @@ def limit_sell_order():
         'id': 'mocked_limit_sell',
         'type': 'LIMIT_SELL',
         'pair': 'mocked',
-        'opened': datetime.utcnow(),
+        'opened': str(arrow.utcnow().datetime),
         'rate': 0.00001173,
         'amount': 90.99181073,
         'remaining': 0.0,
-        'closed': datetime.utcnow(),
+        'closed': str(arrow.utcnow().datetime),
     }
 
 

freqtrade/tests/test_main.py

@@ -5,7 +5,7 @@ from unittest.mock import MagicMock
 import pytest
 import requests
 import logging
-from datetime import timedelta, datetime
+import arrow
 from sqlalchemy import create_engine
 
 from freqtrade import DependencyException, OperationalException
@@ -17,7 +17,7 @@ from freqtrade.misc import get_state, State
 from freqtrade.persistence import Trade
 
 
-def test_process_trade_creation(default_conf, ticker, health, mocker):
+def test_process_trade_creation(default_conf, ticker, limit_buy_order, health, mocker):
     mocker.patch.dict('freqtrade.main._CONF', default_conf)
     mocker.patch.multiple('freqtrade.rpc', init=MagicMock(), send_msg=MagicMock())
     mocker.patch('freqtrade.main.get_signal', side_effect=lambda s, t: True)
@@ -25,7 +25,8 @@ def test_process_trade_creation(default_conf, ticker, health, mocker):
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
                           get_wallet_health=health,
-                          buy=MagicMock(return_value='mocked_limit_buy'))
+                          buy=MagicMock(return_value='mocked_limit_buy'),
+                          get_order=MagicMock(return_value=limit_buy_order))
     init(default_conf, create_engine('sqlite://'))
 
     trades = Trade.query.filter(Trade.is_open.is_(True)).all()
@@ -319,161 +320,104 @@ def test_close_trade(default_conf, ticker, limit_buy_order, limit_sell_order, mo
         handle_trade(trade)
 
 
-def test_check_handle_timedout(default_conf, ticker, health, mocker):
+def test_check_handle_timedout_buy(default_conf, ticker, health, 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.multiple('freqtrade.main.exchange',
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
-                          get_order=MagicMock(return_value={
+                          get_order=MagicMock(return_value=limit_buy_order_old),
-                              'closed': None,
-                              'type': 'LIMIT_BUY',
-                              'remaining': 1.0,
-                              'amount': 1.0,
-                          }),
                           cancel_order=cancel_order_mock)
     init(default_conf, create_engine('sqlite://'))
 
     tradeBuy = Trade(
         pair='BTC_ETH',
-        open_rate=1,
+        open_rate=0.00001099,
         exchange='BITTREX',
         open_order_id='123456789',
-        amount=1,
+        amount=90.99181073,
         fee=0.0,
         stake_amount=1,
-        open_date=datetime.utcnow(),
+        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    tradeSell = Trade(
-        pair='BTC_BCC',
-        open_rate=1,
-        exchange='BITTREX',
-        open_order_id='678901234',
-        amount=1,
-        fee=0.0,
-        stake_amount=1,
-        open_date=datetime.utcnow(),
-        close_date=datetime.utcnow(),
         is_open=True
     )
 
     Trade.session.add(tradeBuy)
-    Trade.session.add(tradeSell)
-
-    # check it doesn't cancel any buy trades under the time limit
-    ret = check_handle_timedout(tradeBuy)
-    assert ret is False
-    assert cancel_order_mock.call_count == 0
-    trades = Trade.query.filter(Trade.open_order_id.is_(tradeBuy.open_order_id)).all()
-    assert len(trades) == 1
-
-    # change the trade open datetime to 601 minutes in the past
-    tradeBuy.open_date = datetime.utcnow() - timedelta(minutes=601)
 
     # check it does cancel buy orders over the time limit
-    ret = check_handle_timedout(tradeBuy)
+    check_handle_timedout(600)
-    assert ret is True
     assert cancel_order_mock.call_count == 1
     trades = Trade.query.filter(Trade.open_order_id.is_(tradeBuy.open_order_id)).all()
     assert len(trades) == 0
 
-    # check it doesn't cancel any sell trades under the time limit
-    ret = check_handle_timedout(tradeSell)
-    assert ret is False
-    assert cancel_order_mock.call_count == 1
-    assert tradeSell.is_open is True
 
-    # change the trade close datetime to 601 minutes in the past
+def test_check_handle_timedout_sell(default_conf, ticker, health, limit_sell_order_old, mocker):
-    tradeSell.close_date = datetime.utcnow() - timedelta(minutes=601)
-
-    # check it does cancel sell orders over the time limit
-    ret = check_handle_timedout(tradeSell)
-    assert ret is True
-    assert cancel_order_mock.call_count == 2
-    assert tradeSell.is_open is True
-
-
-def test_check_handle_timedout_partial(default_conf, ticker, health, 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.multiple('freqtrade.main.exchange',
                           validate_pairs=MagicMock(),
                           get_ticker=ticker,
-                          get_order=MagicMock(return_value={
+                          get_order=MagicMock(return_value=limit_sell_order_old),
-                              'closed': None,
+                          cancel_order=cancel_order_mock)
-                              'type': 'LIMIT_BUY',
+    init(default_conf, create_engine('sqlite://'))
-                              'remaining': 0.5,
+
-                              'amount': 1.0,
+    tradeSell = Trade(
-                          }),
+        pair='BTC_ETH',
+        open_rate=0.00001099,
+        exchange='BITTREX',
+        open_order_id='123456789',
+        amount=90.99181073,
+        fee=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(tradeSell)
+
+    # check it does cancel sell orders over the time limit
+    check_handle_timedout(600)
+    assert cancel_order_mock.call_count == 1
+    assert tradeSell.is_open is True
+
+
+def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old_partial,
+                                       health, 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.multiple('freqtrade.main.exchange',
+                          validate_pairs=MagicMock(),
+                          get_ticker=ticker,
+                          get_order=MagicMock(return_value=limit_buy_order_old_partial),
                           cancel_order=cancel_order_mock)
     init(default_conf, create_engine('sqlite://'))
 
     tradeBuy = Trade(
         pair='BTC_ETH',
-        open_rate=1,
+        open_rate=0.00001099,
         exchange='BITTREX',
         open_order_id='123456789',
-        amount=1,
+        amount=90.99181073,
         fee=0.0,
         stake_amount=1,
-        open_date=datetime.utcnow(),
+        open_date=arrow.utcnow().shift(minutes=-601).datetime,
-        is_open=True
-    )
-
-    tradeSell = Trade(
-        pair='BTC_BCC',
-        open_rate=1,
-        exchange='BITTREX',
-        open_order_id='678901234',
-        amount=1,
-        fee=0.0,
-        stake_amount=1,
-        open_date=datetime.utcnow(),
-        close_date=datetime.utcnow(),
         is_open=True
     )
 
     Trade.session.add(tradeBuy)
-    Trade.session.add(tradeSell)
-
-    # check it doesn't cancel any buy trades under the time limit
-    ret = check_handle_timedout(tradeBuy)
-    assert ret is False
-    assert cancel_order_mock.call_count == 0
-    trades = Trade.query.filter(Trade.open_order_id.is_(tradeBuy.open_order_id)).all()
-    assert len(trades) == 1
-
-    # change the trade open datetime to 601 minutes in the past
-    tradeBuy.open_date = datetime.utcnow() - timedelta(minutes=601)
 
     # check it does cancel buy orders over the time limit
     # note this is for a partially-complete buy order
-    ret = check_handle_timedout(tradeBuy)
+    check_handle_timedout(600)
-    assert ret is True
     assert cancel_order_mock.call_count == 1
     trades = Trade.query.filter(Trade.open_order_id.is_(tradeBuy.open_order_id)).all()
     assert len(trades) == 1
-    assert trades[0].amount == 0.5
+    assert trades[0].amount == 23.0
-    assert trades[0].stake_amount == 0.5
+    assert trades[0].stake_amount == tradeBuy.open_rate * trades[0].amount
-
-    # check it doesn't cancel any sell trades under the time limit
-    ret = check_handle_timedout(tradeSell)
-    assert ret is False
-    assert cancel_order_mock.call_count == 1
-    assert tradeSell.is_open is True
-
-    # change the trade close datetime to 601 minutes in the past
-    tradeSell.close_date = datetime.utcnow() - timedelta(minutes=601)
-
-    # check it does not cancel partially-complete sell orders over the time limit
-    ret = check_handle_timedout(tradeSell)
-    assert ret is False
-    assert cancel_order_mock.call_count == 1
-    assert tradeSell.open_order_id is not None
 
 
 def test_balance_fully_ask_side(mocker):