diff --git a/freqtrade/exchange/exchange.py b/freqtrade/exchange/exchange.py index 04ad10a68..c3779ff8e 100644 --- a/freqtrade/exchange/exchange.py +++ b/freqtrade/exchange/exchange.py @@ -999,7 +999,7 @@ class Exchange: if self.is_cancel_order_result_suitable(corder): return corder except InvalidOrderException: - logger.warning(f"Could not cancel order {order_id}.") + logger.warning(f"Could not cancel order {order_id} for {pair}.") try: order = self.fetch_order(order_id, pair) except InvalidOrderException: diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index a6d96ef77..b866842b7 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -976,6 +976,12 @@ class FreqtradeBot: reason = constants.CANCEL_REASON['TIMEOUT'] corder = self.exchange.cancel_order_with_result(trade.open_order_id, trade.pair, trade.amount) + # Avoid race condition where the order could not be cancelled coz its already filled. + # Simply bailing here is the only safe way - as this order will then be + # handled in the next iteration. + if corder.get('status') not in ('canceled', 'closed'): + logger.warning(f"Order {trade.open_order_id} for {trade.pair} not cancelled.") + return False else: # Order was cancelled already, so we can reuse the existing dict corder = order diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py index 60c4847f6..4f5cfa9e1 100644 --- a/tests/exchange/test_exchange.py +++ b/tests/exchange/test_exchange.py @@ -1818,7 +1818,7 @@ def test_cancel_order_with_result_error(default_conf, mocker, exchange_name, cap res = exchange.cancel_order_with_result('1234', 'ETH/BTC', 1541) assert isinstance(res, dict) - assert log_has("Could not cancel order 1234.", caplog) + assert log_has("Could not cancel order 1234 for ETH/BTC.", caplog) assert log_has("Could not fetch cancelled order 1234.", caplog) assert res['amount'] == 1541 diff --git a/tests/test_freqtradebot.py b/tests/test_freqtradebot.py index fd57eae6f..d93672ea7 100644 --- a/tests/test_freqtradebot.py +++ b/tests/test_freqtradebot.py @@ -2023,11 +2023,16 @@ def test_check_handle_timedout_buy_usercustom(default_conf, ticker, limit_buy_or rpc_mock = patch_RPCManager(mocker) cancel_order_mock = MagicMock(return_value=limit_buy_order_old) + cancel_buy_order = deepcopy(limit_buy_order_old) + cancel_buy_order['status'] = 'canceled' + cancel_order_wr_mock = MagicMock(return_value=cancel_buy_order) + patch_exchange(mocker) mocker.patch.multiple( 'freqtrade.exchange.Exchange', fetch_ticker=ticker, fetch_order=MagicMock(return_value=limit_buy_order_old), + cancel_order_with_result=cancel_order_wr_mock, cancel_order=cancel_order_mock, get_fee=fee ) @@ -2060,7 +2065,7 @@ def test_check_handle_timedout_buy_usercustom(default_conf, ticker, limit_buy_or freqtrade.strategy.check_buy_timeout = MagicMock(return_value=True) # Trade should be closed since the function returns true freqtrade.check_handle_timedout() - assert cancel_order_mock.call_count == 1 + assert cancel_order_wr_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() nb_trades = len(trades) @@ -2071,7 +2076,9 @@ def test_check_handle_timedout_buy_usercustom(default_conf, ticker, limit_buy_or 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(return_value=limit_buy_order_old) + limit_buy_cancel = deepcopy(limit_buy_order_old) + limit_buy_cancel['status'] = 'canceled' + cancel_order_mock = MagicMock(return_value=limit_buy_cancel) patch_exchange(mocker) mocker.patch.multiple( 'freqtrade.exchange.Exchange', @@ -2259,7 +2266,10 @@ def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old, def test_check_handle_timedout_partial(default_conf, ticker, limit_buy_order_old_partial, open_trade, mocker) -> None: rpc_mock = patch_RPCManager(mocker) - cancel_order_mock = MagicMock(return_value=limit_buy_order_old_partial) + limit_buy_canceled = deepcopy(limit_buy_order_old_partial) + limit_buy_canceled['status'] = 'canceled' + + cancel_order_mock = MagicMock(return_value=limit_buy_canceled) patch_exchange(mocker) mocker.patch.multiple( 'freqtrade.exchange.Exchange', @@ -2392,7 +2402,11 @@ def test_check_handle_timedout_exception(default_conf, ticker, open_trade, mocke def test_handle_cancel_buy(mocker, caplog, default_conf, limit_buy_order) -> None: patch_RPCManager(mocker) patch_exchange(mocker) - cancel_order_mock = MagicMock(return_value=limit_buy_order) + cancel_buy_order = deepcopy(limit_buy_order) + cancel_buy_order['status'] = 'canceled' + del cancel_buy_order['filled'] + + cancel_order_mock = MagicMock(return_value=cancel_buy_order) mocker.patch('freqtrade.exchange.Exchange.cancel_order_with_result', cancel_order_mock) freqtrade = FreqtradeBot(default_conf) @@ -2412,9 +2426,12 @@ def test_handle_cancel_buy(mocker, caplog, default_conf, limit_buy_order) -> Non assert not freqtrade.handle_cancel_buy(trade, limit_buy_order, reason) assert cancel_order_mock.call_count == 1 - limit_buy_order['filled'] = 2 - mocker.patch('freqtrade.exchange.Exchange.cancel_order', side_effect=InvalidOrderException) + # Order remained open for some reason (cancel failed) + cancel_buy_order['status'] = 'open' + cancel_order_mock = MagicMock(return_value=cancel_buy_order) + mocker.patch('freqtrade.exchange.Exchange.cancel_order_with_result', cancel_order_mock) assert not freqtrade.handle_cancel_buy(trade, limit_buy_order, reason) + assert log_has_re(r"Order .* for .* not cancelled.", caplog) @pytest.mark.parametrize("limit_buy_order_canceled_empty", ['binance', 'ftx', 'kraken', 'bittrex'],