Bot thinks order is fulfilled while actually it is completely expired on exchange

[ertanden]

I have a live setup with Docker & Freqtrade 2021.7.

Quite frequently I see some sell orders by the bot, however the bot wrongly marks the sell as fulfilled, although in Binance exchange the sell order is expired (not even a partial fill, fully expired).

See an example log sequence of such a buy and then sell order below. The position is then marked as Closed on Freq UI, however on Binance the order is fully expired.

Is this a bug and is there a solution for this other than trying to manually fix the Sqlite database?

2021-08-26 10:00:41,143 - freqtrade.freqtradebot - INFO - Executing Sell for MASK/USDT. Reason: roi
2021-08-26 10:00:42,332 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'type': sell, 'trade_id': 7, 'exchange': 'Binance', 'pair': 'MASK/USDT', 'gain': 'profit', 'limit': 17.181, 'order_type': 'limit', 'amount': 11.94, 'open_rate': 17.073412897822447, 'close_rate': None, 'current_rate': 17.181, 'profit_amount': 0.9769992, 'profit_ratio': 0.00478898, 'sell_reason': 'roi', 'open_date': datetime.datetime(2021, 8, 26, 0, 10, 20, 813789), 'close_date': datetime.datetime(2021, 8, 26, 10, 0, 42, 332413), 'stake_currency': 'USDT', 'fiat_currency': 'USD'}
2021-08-26 10:00:45,646 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=7, pair=MASK/USDT, amount=11.94000000, open_rate=17.07341290, open_since=2021-08-26 00:10:20)
2021-08-26 10:00:46,327 - freqtrade.freqtradebot - INFO - Applying fee on amount for Trade(id=7, pair=MASK/USDT, amount=11.94000000, open_rate=17.07341290, open_since=2021-08-26 00:10:20) failed: myTrade-Dict empty found
2021-08-26 10:00:46,328 - freqtrade.persistence.models - INFO - LIMIT_SELL has been fulfilled for Trade(id=7, pair=MASK/USDT, amount=11.94000000, open_rate=17.07341290, open_since=2021-08-26 00:10:20).
2021-08-26 10:00:46,328 - freqtrade.persistence.models - INFO - Marking Trade(id=7, pair=MASK/USDT, amount=11.94000000, open_rate=17.07341290, open_since=closed) as closed as the trade is fulfilled and found no open orders for it.
2021-08-26 10:00:46,586 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'type': sell_fill, 'trade_id': 7, 'exchange': 'Binance', 'pair': 'MASK/USDT', 'gain': 'profit', 'limit': 17.181, 'order_type': '', 'amount': 11.94, 'open_rate': 17.073412897822447, 'close_rate': 17.181, 'current_rate': None, 'profit_amount': 0.9769992, 'profit_ratio': 0.00478898, 'sell_reason': 'roi', 'open_date': datetime.datetime(2021, 8, 26, 0, 10, 20, 813789), 'close_date': datetime.datetime(2021, 8, 26, 10, 0, 46, 328462), 'stake_currency': 'USDT', 'fiat_currency': 'USD'}
2021-08-26 10:00:47,908 - freqtrade.freqtradebot - INFO - Pair MASK/USDT is still locked until 2021-08-26 10:05:00 due to Auto lock.

[ertanden]

For now I'm switching to market order types. But what I wonder is why Freqtrade marks the order closed/fulfilled? Is this an API limitation from Binance etc?

If this is really a technical limitation that can't be fixed solely on part of Freqtrade, maybe we can simplify life of users by providing Freq UI options to modify trades (instead of getting into SQL with Sqlite)

[xmatthias]

I'm yet to see this happen on my bot (also running on binance).

what specific configuration (specifically related to orders / order types) are you using? I'm yet to see a regular (gtc) limit order time-out on the exchange - if timeouts happen, they're from freqtrade and freqtrade will cancel the order. This makes me belive that you might be using some exotic order-timeinforce (maybe FOK) ?

For further investigation, please also provide the following info for the trade that happened:

On the database:

select * from orders where ft_trade_id = 7

From the above query, pick the affected order_id (should be the last one sorted by id) and plug it into the below section (simply run docker-compose run --rm --entrypoint python freqtrade to get into a python shell within the docker container.

import ccxt
exchange = ccxt.binance({'apiKey': '<yourApiKey>', 'secret': '<yoursecret>' })
res = exchange.fetch_order(<order_id>, 'MASK/USDT')
print(res)

This should contain the state as returned from binance. That way we can compare how it's interpreted within freqtrade.

[ertanden]

Config regarding orders was like below (but after the issue I switched order types to market);

2021-08-21 20:14:33,566 - freqtrade.resolvers.strategy_resolver - INFO - Strategy using order_types: {'buy': 'limit', 'sell': 'limit', 'stoploss': 'limit', 'stoploss_on_exchange': False, 'stoploss_on_exchange
_interval': 60}
2021-08-21 20:14:33,577 - freqtrade.resolvers.strategy_resolver - INFO - Strategy using order_time_in_force: {'buy': 'gtc', 'sell': 'ioc'}

Also, I had bid_strategy.price_side = ask and ask_strategy.price_side = bid..

The SQL records for the trade;

12|7|buy|MASK/USDT|0|32081376|closed|MASK/USDT|limit|buy|17.103|17.0734128978224|11.94|11.94|0.0|203.85655|2021-08-26 00:10:20.689000|2021-08-26 00:10:20.814317|2021-08-26 00:10:20.814319
20|7|sell|MASK/USDT|1|32794194|expired|MASK/USDT|limit|sell|17.181||11.9|0.0|11.9|0.0|2021-08-26 10:00:42.026000||2021-08-26 14:48:57.992678

The result from Binance API for the sell order;

{
    'info': {
        'symbol': 'MASKUSDT',
        'orderId': '32794194',
        'orderListId': '-1',
        'clientOrderId': 'x-R4BD3S82b2e84bfaa9e09c62006dce',
        'price': '17.18100000',
        'origQty': '11.90000000',
        'executedQty': '0.00000000',
        'cummulativeQuoteQty': '0.00000000',
        'status': 'EXPIRED',
        'timeInForce': 'IOC',
        'type': 'LIMIT',
        'side': 'SELL',
        'stopPrice': '0.00000000',
        'icebergQty': '0.00000000',
        'time': '1629972042026',
        'updateTime': '1629972042026',
        'isWorking': True,
        'origQuoteOrderQty': '0.00000000'
    },
    'id': '32794194',
    'clientOrderId': 'x-R4BD3S82b2e84bfaa9e09c62006dce',
    'timestamp': 1629972042026,
    'datetime': '2021-08-26T10:00:42.026Z',
    'lastTradeTimestamp': None,
    'symbol': 'MASK/USDT',
    'type': 'limit',
    'timeInForce': 'IOC',
    'postOnly': False,
    'side': 'sell',
    'price': 17.181,
    'stopPrice': None,
    'amount': 11.9,
    'cost': 0.0,
    'average': None,
    'filled': 0.0,
    'remaining': 11.9,
    'status': 'expired',
    'fee': None,
    'trades': [],
    'fees': []
}

[LorenzHope]

Maybe the same problem, up

2021-08-27 13:42:48 - freqtrade.freqtradebot - INFO - Executing Sell for CELO/USDT. Reason: trailing_stop_loss 2021-08-27 13:42:49 - freqtrade.wallets - INFO - Wallets synced. 2021-08-27 13:42:50 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'type': sell, 'trade_id': 202, 'exchange': 'Binance', 'pair': 'CELO/USDT', 'gain': 'profit', 'limit': 3.877, 'order_type': 'limit', 'amount': 153.5, 'open_rate': 3.7960000000000003, 'close_rate': None, 'current_rate': 3.877, 'profit_amount': 11.2556945, 'profit_ratio': 0.01929761, 'sell_reason': 'trailing_stop_loss', 'open_date': datetime.datetime(2021, 8, 27, 13, 1, 29, 857189), 'close_date': datetime.datetime(2021, 8, 27, 13, 42, 50, 226081), 'stake_currency': 'USDT', 'fiat_currency': 'EUR'} 2021-08-27 13:42:51 - freqtrade.wallets - INFO - Wallets synced. 2021-08-27 13:42:51 - freqtrade.worker - INFO - Bot heartbeat. PID=1, version='2021.7', state='RUNNING' 2021-08-27 13:42:52 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=202, pair=CELO/USDT, amount=153.50000000, open_rate=3.79600000, open_since=2021-08-27 13:01:29) 2021-08-27 13:42:53 - freqtrade.freqtradebot - INFO - Applying fee on amount for Trade(id=202, pair=CELO/USDT, amount=153.50000000, open_rate=3.79600000, open_since=2021-08-27 13:01:29) failed: myTrade-Dict empty found 2021-08-27 13:42:53 - freqtrade.persistence.models - INFO - Updating trade (id=202) ... 2021-08-27 13:42:53 - freqtrade.persistence.models - INFO - LIMIT_SELL has been fulfilled for Trade(id=202, pair=CELO/USDT, amount=153.50000000, open_rate=3.79600000, open_since=2021-08-27 13:01:29). 2021-08-27 13:42:53 - freqtrade.persistence.models - INFO - Marking Trade(id=202, pair=CELO/USDT, amount=153.50000000, open_rate=3.79600000, open_since=closed) as closed as the trade is fulfilled and found no open orders for it. 2021-08-27 13:42:53 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'type': sell_fill, 'trade_id': 202, 'exchange': 'Binance', 'pair': 'CELO/USDT', 'gain': 'profit', 'limit': 3.877, 'order_type': '', 'amount': 153.5, 'open_rate': 3.7960000000000003, 'close_rate': 3.877, 'current_rate': None, 'profit_amount': 11.2556945, 'profit_ratio': 0.01929761, 'sell_reason': 'trailing_stop_loss', 'open_date': datetime.datetime(2021, 8, 27, 13, 1, 29, 857189), 'close_date': datetime.datetime(2021, 8, 27, 13, 42, 53, 584158), 'stake_currency': 'USDT', 'fiat_currency': 'EUR'} 2021-08-27 13:42:53 - freqtrade.rpc.telegram - INFO - Notification 'sell_fill' not sent. 2021-08-27 13:42:53 - freqtrade.wallets - INFO - Wallets synced.

[LorenzHope]

Don't know if is related, but also the Balance and Wallet sync seems not be very syncronized. Hope to help

[xmatthias]

@LorenzHope your log does not hint at any problem but at regular trading activity. Maybe with additional information that would change - but for now - it's pretty simple sells that seem to happen.

Unless you're using non-gtc orders - your problem is not related to this issue.

[LorenzHope]

@LorenzHope your log does not hint at any problem but at regular trading activity. Maybe with additional information that would change - but for now - it's pretty simple sells that seem to happen.

Unless you're using non-gtc orders - your problem is not related to this issue.

Y maybe is this options in strategy, I removed it and now seems to work properly

# order_time_in_force = {
#     'buy': 'gtc',
#     'sell': 'ioc'
# }