XEMM - Order created late and not recognized by the executor

[rapcmia]

Describe the bug

When checking a reported issue on discord and ran tests on XEMM (v2 strategy), found out that a scenario where the connector OrderCreatedEvent is late and scrip fails to recognized. The difference on the time where the order is placed, created and cancelled are too fast the executor failed to catch up causing failed to cancel and order stuck on exchange (eventually filled).

Here's sample scenario on the attached log:

1. Creating order XEKWYICXBXPUT61854d86431df6c7d

   2024-05-13 20:15:47,028 - 52696 - hummingbot.strategy.script_strategy_base - INFO - Creating XRP-USDT buy order: price: 0.5041158849945732609768130242 amount: 29.61208172934557299378146284.
   2024-05-13 20:15:47,028 - 52696 - hummingbot.strategy_v2.executors.xemm_executor.xemm_executor - INFO - Created maker order x-XEKWYICXBXPUT61854d86431df6c7d at price 0.5041158849945732609768130242.
   

2. Canceling order

     2024-05-13 20:15:48,029 - 52696 - hummingbot.strategy_v2.executors.xemm_executor.xemm_executor - INFO - Trade profitability -0.001099891465219536260483473113 is below minimum profitability. Cancelling order.
     2024-05-13 20:15:48,030 - 52696 - hummingbot.strategy.script_strategy_base - INFO - (XRP-USDT) Canceling the limit order x-XEKWYICXBXPUT61854d86431df6c7d. [clock=2024-05-13 12:15:48+00:00]
     # trimmed timestamps
     2024-05-13 20:15:52,669 - 52696 - hummingbot.connector.exchange.binance.binance_exchange.BinanceExchange - WARNING - Failed to cancel order x-XEKWYICXBXPUT61854d86431df6c7d (order not found)
     # trimmed timestamps
     2024-05-13 20:16:00,128 - 52696 - hummingbot.connector.client_order_tracker - INFO - Created LIMIT BUY order x-XEKWYICXBXPUT61854d86431df6c7d for 29.00000000 XRP-USDT.
     2024-05-13 20:16:00,133 - 52696 - hummingbot.core.event.event_reporter - EVENT_LOG - {"timestamp": NaN, "type": "OrderType.LIMIT", "trading_pair": "XRP-USDT", "amount": "29.00000000", "price": "0.50410000", "order_id": "x-XEKWYICXBXPUT61854d86431df6c7d", "creation_timestamp": 1715602545.0, "exchange_order_id": "6163310929", "leverage": 1, "position": "NIL", "event_name": "BuyOrderCreatedEvent", "event_source": "binance"}
   

   • The time diff from where the maker order is created and a trade profitability was triggered then cancellation of order is too small and fast
   • The XEMM executor proceed with canceling the order but failed since its still not complete created yet
   • The connector order event completed only after the order was being cancelled

• Orders stuck on the exchange:
  
  • The orders on the exchange are accumulated causing the bot not able to place order due to insufficient balance

    2024-05-13 20:18:12,633 - 53033 - hummingbot.connector.exchange.binance.binance_exchange.BinanceExchange - NETWORK - Error submitting sell LIMIT order to Binance for 29.00000000 XRP-USDT 0.50910000.
    Traceback (most recent call last):
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/connector/exchange_py_base.py", line 452, in _create_order
        await self._place_order_and_process_update(order=order, **kwargs,)
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/connector/exchange_py_base.py", line 469, in _place_order_and_process_update
        exchange_order_id, update_timestamp = await self._place_order(
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/connector/exchange/binance/binance_exchange.py", line 198, in _place_order
        order_result = await self._api_post(
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/connector/exchange_py_base.py", line 867, in _api_post
        return await self._api_request(*args, **kwargs)
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/connector/exchange_py_base.py", line 906, in _api_request
        request_result = await rest_assistant.execute_request(
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/core/web_assistant/rest_assistant.py", line 47, in execute_request
        response = await self.execute_request_and_get_response(
      File "/Users/rapcomia/github/hummingbot/development/hummingbot/core/web_assistant/rest_assistant.py", line 100, in execute_request_and_get_response
        raise IOError(f"Error executing request {method.name} {url}. HTTP status is {response.status}. "
    OSError: Error executing request POST https://api.binance.com/api/v3/order. HTTP status is 400. Error: {"code":-2010,"msg":"Account has insufficient balance for requested action."}
    

Steps to reproduce

1. Setup rate_limit_pct (20) and tick_size(3) (optional)
2. Setup v2_xemm

     markets: {}
     candles_config: []
     controllers_config: []
     config_update_interval: 60
     script_file_name: v2_xemm.py
     maker_connector: binance
     maker_trading_pair: xxx-USDT
     taker_connector: okx
     taker_trading_pair: xxx-USDT
     target_profitability: 0.004
     min_profitability: 0.004
     max_profitability: 0.006
     order_amount_quote: 15
   

3. Start the script and observe behavior after couple of hours

Release version

1.27.0 and dev-1.28.0

Type of installation

Source

Attach required files

05132024.zip

[rapcmia]

Reproduced when testing MEXC as maker:

# Creating buy order 
2024-05-23 05:51:28,305 - 15 - hummingbot.strategy.script_strategy_base - INFO - Creating FIRO-USDT buy order: price: 1.790195498751733703190013870 amount: 6.653728860548932630995286942.
2024-05-23 05:51:28,309 - 15 - hummingbot.strategy_v2.executors.xemm_executor.xemm_executor - INFO - Created maker order HUMBOTBFOUT61918a465ce3edb229de0 at price 1.790195498751733703190013870.
2024-05-23 05:51:29,313 - 15 - hummingbot.strategy_v2.executors.xemm_executor.xemm_executor - INFO - Trade profitability -0.0009991682838924313834211255892 is below minimum profitability. Cancelling order.
2024-05-23 05:51:29,315 - 15 - hummingbot.strategy.script_strategy_base - INFO - (FIRO-USDT) Canceling the limit order HUMBOTBFOUT61918a465ce3edb229de0. [clock=2024-05-23 05:51:29+00:00]
2024-05-23 05:51:29,568 - 15 - hummingbot.connector.exchange.mexc.mexc_exchange.MexcExchange - ERROR - Failed to cancel order HUMBOTBFOUT61918a465ce3edb229de0
Traceback (most recent call last):
  File "/home/hummingbot/hummingbot/connector/exchange_py_base.py", line 520, in _execute_order_cancel
    cancelled = await self._execute_order_cancel_and_process_update(order=order)
  File "/home/hummingbot/hummingbot/connector/exchange_py_base.py", line 540, in _execute_order_cancel_and_process_update
    cancelled = await self._place_cancel(order.client_order_id, order)
  File "/home/hummingbot/hummingbot/connector/exchange/mexc/mexc_exchange.py", line 230, in _place_cancel
    cancel_result = await self._api_delete(
  File "/home/hummingbot/hummingbot/connector/exchange_py_base.py", line 875, in _api_delete
    return await self._api_request(*args, **kwargs)
  File "/home/hummingbot/hummingbot/connector/exchange_py_base.py", line 906, in _api_request
    request_result = await rest_assistant.execute_request(
  File "/home/hummingbot/hummingbot/core/web_assistant/rest_assistant.py", line 47, in execute_request
    response = await self.execute_request_and_get_response(
  File "/home/hummingbot/hummingbot/core/web_assistant/rest_assistant.py", line 100, in execute_request_and_get_response
    raise IOError(f"Error executing request {method.name} {url}. HTTP status is {response.status}. "
OSError: Error executing request DELETE https://api.mexc.com/api/v3/order. HTTP status is 400. Error: {"msg":"Unknown order id.","code":-2011}

• Buy order created but no BuyOrderCreatedEvent happened
• After couple of seconds, Trade profitability triggered and cancellation order in process:
  • Failed to cancel buy order for MEXC with OSError: Error executing request DELETE https://api.mexc.com/api/v3/order. HTTP status is 400. Error: {"msg":"Unknown order id.","code":-2011}
  • It seems that the order was not successfully created yet but the XEMM executor is trying to cancel due to trade profitability rate 👀
• Order created at 2024-05-23 05:51:29,854

  2024-05-23 05:51:29,911 - 15 - hummingbot.core.event.event_reporter - EVENT_LOG - {"timestamp": 1716443489.0, "type": "OrderType.LIMIT", "trading_pair": "FIRO-USDT", "amount": "6.65", "price": "1.790", "order_id": "HUMBOTBFOUT61918a465ce3edb229de0", "creation_timestamp": 1716443488.0, "exchange_order_id": "C02__422203898716053504049", "leverage": 1, "position": "NIL", "event_name": "BuyOrderCreatedEvent", "event_source": "mexc"}
  

  • However this is now not recognized by the script leaving it active on the exchange
  • The order on our tests eventually got filled

    2024-05-23 06:31:12,514 - 15 - hummingbot.connector.client_order_tracker - INFO - The BUY order HUMBOTBFOUT61918a465ce3edb229de0 amounting to 6.65/6.65 FIRO has been filled.
    2024-05-23 06:31:12,676 - 15 - hummingbot.core.event.event_reporter - EVENT_LOG - {"timestamp": 1716445872.0, "order_id": "HUMBOTBFOUT61918a465ce3edb229de0", "trading_pair": "FIRO-USDT", "trade_type": "TradeType.BUY", "order_type": "OrderType.LIMIT", "price": "1.79", "amount": "6.65", "trade_fee": {"percent": "0", "percent_token": "USDT", "flat_fees": [{"token": "USDT", "amount": "0"}]}, "exchange_trade_id": "422203898716053504X1", "exchange_order_id": "C02__422203898716053504049", "leverage": 1, "position": "NIL", "event_name": "OrderFilledEvent", "event_source": "mexc"}
    2024-05-23 06:31:13,125 - 15 - hummingbot.core.event.event_reporter - EVENT_LOG - {"timestamp": 1716445872.0, "order_id": "HUMBOTBFOUT61918a465ce3edb229de0", "base_asset": "FIRO", "quote_asset": "USDT", "base_asset_amount": "6.65", "quote_asset_amount": "11.9035", "order_type": "OrderType.LIMIT", "exchange_order_id": "C02__422203898716053504049", "event_name": "BuyOrderCompletedEvent", "event_source": "mexc"}
    2024-05-23 06:31:13,127 - 15 - hummingbot.connector.client_order_tracker - INFO - BUY order HUMBOTBFOUT61918a465ce3edb229de0 completely filled.
    

    • No market order created on taker since already been recognized as cancelled on the earlier events logs

---

Steps to reproduce:

• Setup v2_xemm config where the values of min_profitability and target_profitability is tight or close enough

  target_profitability: 0.005
  min_profitability: 0.003
  max_profitability: 0.009