Merge pull request #3649 from freqtrade/improve_cancel_order_handling
Better handle cancelled buy orders
This commit is contained in:
		| @@ -107,12 +107,12 @@ def retrier_async(f): | ||||
|         except TemporaryError as ex: | ||||
|             logger.warning('%s() returned exception: "%s"', f.__name__, ex) | ||||
|             if count > 0: | ||||
|                 logger.warning('retrying %s() still for %s times', f.__name__, count) | ||||
|                 count -= 1 | ||||
|                 kwargs.update({'count': count}) | ||||
|                 logger.warning('retrying %s() still for %s times', f.__name__, count) | ||||
|                 if isinstance(ex, DDosProtection): | ||||
|                     backoff_delay = calculate_backoff(count + 1, API_RETRY_COUNT) | ||||
|                     logger.debug(f"Applying DDosProtection backoff delay: {backoff_delay}") | ||||
|                     logger.info(f"Applying DDosProtection backoff delay: {backoff_delay}") | ||||
|                     await asyncio.sleep(backoff_delay) | ||||
|                 return await wrapper(*args, **kwargs) | ||||
|             else: | ||||
| @@ -131,13 +131,13 @@ def retrier(_func=None, retries=API_RETRY_COUNT): | ||||
|             except (TemporaryError, RetryableOrderError) as ex: | ||||
|                 logger.warning('%s() returned exception: "%s"', f.__name__, ex) | ||||
|                 if count > 0: | ||||
|                     logger.warning('retrying %s() still for %s times', f.__name__, count) | ||||
|                     count -= 1 | ||||
|                     kwargs.update({'count': count}) | ||||
|                     logger.warning('retrying %s() still for %s times', f.__name__, count) | ||||
|                     if isinstance(ex, DDosProtection) or isinstance(ex, RetryableOrderError): | ||||
|                         # increasing backoff | ||||
|                         backoff_delay = calculate_backoff(count + 1, retries) | ||||
|                         logger.debug(f"Applying DDosProtection backoff delay: {backoff_delay}") | ||||
|                         logger.info(f"Applying DDosProtection backoff delay: {backoff_delay}") | ||||
|                         time.sleep(backoff_delay) | ||||
|                     return wrapper(*args, **kwargs) | ||||
|                 else: | ||||
|   | ||||
| @@ -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: | ||||
| @@ -1008,7 +1008,7 @@ class Exchange: | ||||
|  | ||||
|         return order | ||||
|  | ||||
|     @retrier | ||||
|     @retrier(retries=5) | ||||
|     def fetch_order(self, order_id: str, pair: str) -> Dict: | ||||
|         if self._config['dry_run']: | ||||
|             try: | ||||
| @@ -1022,10 +1022,10 @@ class Exchange: | ||||
|             return self._api.fetch_order(order_id, pair) | ||||
|         except ccxt.OrderNotFound as e: | ||||
|             raise RetryableOrderError( | ||||
|                 f'Order not found (id: {order_id}). Message: {e}') from e | ||||
|                 f'Order not found (pair: {pair} id: {order_id}). Message: {e}') from e | ||||
|         except ccxt.InvalidOrder as e: | ||||
|             raise InvalidOrderException( | ||||
|                 f'Tried to get an invalid order (id: {order_id}). Message: {e}') from e | ||||
|                 f'Tried to get an invalid order (pair: {pair} id: {order_id}). Message: {e}') from e | ||||
|         except ccxt.DDoSProtection as e: | ||||
|             raise DDosProtection(e) from e | ||||
|         except (ccxt.NetworkError, ccxt.ExchangeError) as e: | ||||
|   | ||||
| @@ -78,7 +78,7 @@ class Ftx(Exchange): | ||||
|         except ccxt.BaseError as e: | ||||
|             raise OperationalException(e) from e | ||||
|  | ||||
|     @retrier | ||||
|     @retrier(retries=5) | ||||
|     def fetch_stoploss_order(self, order_id: str, pair: str) -> Dict: | ||||
|         if self._config['dry_run']: | ||||
|             try: | ||||
|   | ||||
| @@ -660,7 +660,7 @@ class FreqtradeBot: | ||||
|                     trades_closed += 1 | ||||
|  | ||||
|             except DependencyException as exception: | ||||
|                 logger.warning('Unable to sell trade: %s', exception) | ||||
|                 logger.warning('Unable to sell trade %s: %s', trade.pair, exception) | ||||
|  | ||||
|         # Updating wallets if any trade occured | ||||
|         if trades_closed: | ||||
| @@ -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 | ||||
|   | ||||
| @@ -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 | ||||
|  | ||||
| @@ -1896,10 +1896,10 @@ def test_fetch_order(default_conf, mocker, exchange_name): | ||||
|         assert tm.call_args_list[1][0][0] == 2 | ||||
|         assert tm.call_args_list[2][0][0] == 5 | ||||
|         assert tm.call_args_list[3][0][0] == 10 | ||||
|     assert api_mock.fetch_order.call_count == API_RETRY_COUNT + 1 | ||||
|     assert api_mock.fetch_order.call_count == 6 | ||||
|  | ||||
|     ccxt_exceptionhandlers(mocker, default_conf, api_mock, exchange_name, | ||||
|                            'fetch_order', 'fetch_order', | ||||
|                            'fetch_order', 'fetch_order', retries=6, | ||||
|                            order_id='_', pair='TKN/BTC') | ||||
|  | ||||
|  | ||||
| @@ -1932,6 +1932,7 @@ def test_fetch_stoploss_order(default_conf, mocker, exchange_name): | ||||
|  | ||||
|     ccxt_exceptionhandlers(mocker, default_conf, api_mock, exchange_name, | ||||
|                            'fetch_stoploss_order', 'fetch_order', | ||||
|                            retries=6, | ||||
|                            order_id='_', pair='TKN/BTC') | ||||
|  | ||||
|  | ||||
| @@ -2315,6 +2316,18 @@ def test_calculate_fee_rate(mocker, default_conf, order, expected) -> None: | ||||
|     (3, 3, 1), | ||||
|     (0, 1, 2), | ||||
|     (1, 1, 1), | ||||
|     (0, 4, 17), | ||||
|     (1, 4, 10), | ||||
|     (2, 4, 5), | ||||
|     (3, 4, 2), | ||||
|     (4, 4, 1), | ||||
|     (0, 5, 26), | ||||
|     (1, 5, 17), | ||||
|     (2, 5, 10), | ||||
|     (3, 5, 5), | ||||
|     (4, 5, 2), | ||||
|     (5, 5, 1), | ||||
|  | ||||
| ]) | ||||
| def test_calculate_backoff(retrycount, max_retries, expected): | ||||
|     assert calculate_backoff(retrycount, max_retries) == expected | ||||
|   | ||||
| @@ -154,4 +154,5 @@ def test_fetch_stoploss_order(default_conf, mocker): | ||||
|  | ||||
|     ccxt_exceptionhandlers(mocker, default_conf, api_mock, 'ftx', | ||||
|                            'fetch_stoploss_order', 'fetch_orders', | ||||
|                            retries=6, | ||||
|                            order_id='_', pair='TKN/BTC') | ||||
|   | ||||
| @@ -1660,6 +1660,7 @@ def test_exit_positions_exception(mocker, default_conf, limit_buy_order, caplog) | ||||
|     trade = MagicMock() | ||||
|     trade.open_order_id = None | ||||
|     trade.open_fee = 0.001 | ||||
|     trade.pair = 'ETH/BTC' | ||||
|     trades = [trade] | ||||
|  | ||||
|     # Test raise of DependencyException exception | ||||
| @@ -1669,7 +1670,7 @@ def test_exit_positions_exception(mocker, default_conf, limit_buy_order, caplog) | ||||
|     ) | ||||
|     n = freqtrade.exit_positions(trades) | ||||
|     assert n == 0 | ||||
|     assert log_has('Unable to sell trade: ', caplog) | ||||
|     assert log_has('Unable to sell trade ETH/BTC: ', caplog) | ||||
|  | ||||
|  | ||||
| def test_update_trade_state(mocker, default_conf, limit_buy_order, caplog) -> None: | ||||
| @@ -2025,11 +2026,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 | ||||
|     ) | ||||
| @@ -2062,7 +2068,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) | ||||
| @@ -2073,7 +2079,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', | ||||
| @@ -2261,7 +2269,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', | ||||
| @@ -2394,7 +2405,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) | ||||
| @@ -2414,9 +2429,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'], | ||||
|   | ||||
		Reference in New Issue
	
	Block a user