From e8ed8a2ea73c42ffd872896ca57d4c1937230787 Mon Sep 17 00:00:00 2001 From: Matthias Date: Sun, 3 Feb 2019 13:39:05 +0100 Subject: [PATCH 1/6] Handle orders cancelled on exchange fix #1527 --- freqtrade/freqtradebot.py | 48 ++++++++++++++++++++++++--------------- 1 file changed, 30 insertions(+), 18 deletions(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index e81e05e9e..3c0979861 100644 --- a/freqtrade/freqtradebot.py +++ b/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: + + 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,11 +782,10 @@ 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 @@ -788,7 +794,13 @@ class FreqtradeBot(object): 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 Cancelled on exchange for %s.', trade) trade.close_rate = None trade.close_profit = None trade.close_date = None @@ -796,9 +808,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 {pair_s} cancelled {reason}' }) - logger.info('Sell order timeout for %s.', trade) + return True # TODO: figure out how to handle partially complete sell orders From 91ed02134e56000eb46b5d347daa3f06c13e460b Mon Sep 17 00:00:00 2001 From: Matthias Date: Sun, 3 Feb 2019 13:39:19 +0100 Subject: [PATCH 2/6] Add tests for cancelled on exchnage --- freqtrade/tests/test_freqtradebot.py | 81 +++++++++++++++++++++++++++- 1 file changed, 80 insertions(+), 1 deletion(-) diff --git a/freqtrade/tests/test_freqtradebot.py b/freqtrade/tests/test_freqtradebot.py index 9200c5fa6..8513ee96d 100644 --- a/freqtrade/tests/test_freqtradebot.py +++ b/freqtrade/tests/test_freqtradebot.py @@ -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("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,43 @@ 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) -> 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 + + def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old_partial, mocker) -> None: rpc_mock = patch_RPCManager(mocker) @@ -1744,7 +1822,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 From 02c3552954dc3400bc3972eec0146f01dadee424 Mon Sep 17 00:00:00 2001 From: Matthias Date: Sun, 3 Feb 2019 13:49:55 +0100 Subject: [PATCH 3/6] Adjust comment --- freqtrade/freqtradebot.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 3c0979861..733aefe4a 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -800,7 +800,7 @@ class FreqtradeBot(object): logger.info('Sell order timeout for %s.', trade) else: reason = "on exchange" - logger.info('Sell order Cancelled on exchange for %s.', trade) + logger.info('Sell order canceled on exchange for %s.', trade) trade.close_rate = None trade.close_profit = None trade.close_date = None From 40fea4593f0ea2f9e462d20f10a0c71728efb8b1 Mon Sep 17 00:00:00 2001 From: Matthias Date: Sun, 3 Feb 2019 13:50:03 +0100 Subject: [PATCH 4/6] Add log_has_re --- freqtrade/tests/conftest.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/freqtrade/tests/conftest.py b/freqtrade/tests/conftest.py index ba2e1e84e..809dc12e0 100644 --- a/freqtrade/tests/conftest.py +++ b/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()) From 1d940041e31bc2f18cd7a43b3d87482f267f730d Mon Sep 17 00:00:00 2001 From: Matthias Date: Sun, 3 Feb 2019 13:50:15 +0100 Subject: [PATCH 5/6] Add log test for cancelled order --- freqtrade/tests/test_freqtradebot.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/freqtrade/tests/test_freqtradebot.py b/freqtrade/tests/test_freqtradebot.py index 8513ee96d..2edf063b5 100644 --- a/freqtrade/tests/test_freqtradebot.py +++ b/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 @@ -1592,7 +1592,7 @@ def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old, 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("Buy order canceled on Exchange for Trade.*", caplog.record_tuples) + 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, @@ -1669,7 +1669,8 @@ 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) -> None: +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() @@ -1704,6 +1705,7 @@ def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old, 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, From 0a71ebce68c1372efd92349e52aa8ed8a6142c91 Mon Sep 17 00:00:00 2001 From: Matthias Date: Mon, 4 Feb 2019 06:13:22 +0100 Subject: [PATCH 6/6] Remove unneeded pair conversation, add docstring --- freqtrade/freqtradebot.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 733aefe4a..a13e92926 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -755,7 +755,7 @@ class FreqtradeBot(object): self.wallets.update() 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) @@ -791,7 +791,6 @@ class FreqtradeBot(object): 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 if order["status"] != "canceled": @@ -808,7 +807,7 @@ 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 {reason}' + 'status': f'Unfilled sell order for {trade.pair} cancelled {reason}' }) return True