Better handle cancelled buy orders

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:

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

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
 

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'],