Deleting order from database when Position adjust triggered and order timed out

medenlin commented 2 years ago

Describe your environment

Operating system: WIndows 10 (Freqtrade running in Docker container)
Python Version: as in docker container (python -V)
CCXT version: as in docker container (pip freeze | grep ccxt)
Freqtrade Version: 2022.5 (freqtrade -V or docker-compose run --rm freqtrade -V for Freqtrade running in docker)

Note: All issues other than enhancement requests will be closed without further comment if the above template is deleted or not filled out.

Describe the problem:

When Position adjust triggered and order timed out, then Freqtrade fully remove it from database. See log with my comments.

Steps to reproduce:

Run Freqtrade in LIVE mode with adjust_trade_position() callback and unfilledtimeout.entry configured
Wait while position (1st) order open and fullfilled
Wait while Position adjust (2nd or any next) order open, but not filled and unfilledtimeout.entry triggered

Observed Results:

What happened? The position will be instantly deleted from the database, disappear from the list and no longer served by Freqtrade.
What did you expect to happen? Cancel only last adjustment order

Relevant code exceptions or logs

Note: Please copy/paste text of the messages, no screenshots of logs please.

// Opening 1st order
2022-05-30 16:00:13,604 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 16:00:13,877 - freqtrade.freqtradebot - INFO - Long signal found: about create a new trade for BZZ3S/USDT with stake_amount: 5.380282557466667 ...
2022-05-30 16:00:14,146 - freqtrade.freqtradebot - INFO - Order #162433026757 was created for BZZ3S/USDT and status is open.
2022-05-30 16:00:15,454 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 16:00:15,460 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 4.08807, 'open_rate': 4.08807, 'order_type': 'limit', 'stake_amount': 5.380282557466667, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 1.3160935496375226, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 4.08807}
2022-05-30 16:00:15,919 - freqtrade.worker - INFO - Bot heartbeat. PID=1, version='2022.5', state='RUNNING'
2022-05-30 16:00:17,063 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=434, pair=BZZ3S/USDT, amount=1.31609355, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14)
[...]
2022-05-30 16:01:57,146 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=434, pair=BZZ3S/USDT, amount=1.31609355, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14)
2022-05-30 16:01:57,453 - freqtrade.persistence.trade_model - INFO - Updating trade (id=434) ...
2022-05-30 16:01:57,453 - freqtrade.persistence.trade_model - INFO - LIMIT_BUY has been fulfilled for Trade(id=434, pair=BZZ3S/USDT, amount=1.31600000, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14).
2022-05-30 16:01:57,761 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 16:01:57,762 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry_fill, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 4.08807, 'open_rate': 4.08807, 'order_type': None, 'stake_amount': 5.37990012, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 1.316, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 4.08807}
2022-05-30 16:01:57,763 - freqtrade.rpc.telegram - INFO - Notification 'entry_fill' not sent.

// Opening 2nd order (Position adjustment)
[...]
2022-05-30 17:55:44,646 - freqtrade.freqtradebot - INFO - Position adjust: about to create a new order for BZZ3S/USDT with stake: 6.724875150000001 for Trade(id=434, pair=BZZ3S/USDT, amount=1.31600000, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14)
2022-05-30 17:55:44,929 - freqtrade.freqtradebot - INFO - Order #162461181248 was created for BZZ3S/USDT and status is open.
2022-05-30 17:55:45,274 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 17:55:45,280 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 3.87804, 'open_rate': 3.87804, 'order_type': 'limit', 'stake_amount': 5.37990012, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 1.316, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 3.87804}
2022-05-30 17:55:45,495 - freqtrade.freqtradebot - INFO - DCA order open, will wait for resolution: Trade(id=434, pair=BZZ3S/USDT, amount=1.31600000, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14)
2022-05-30 17:55:48,839 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=434, pair=BZZ3S/USDT, amount=1.31600000, is_short=False, leverage=1.0, open_rate=4.08807000, open_since=2022-05-30 16:00:14)
[...]
2022-05-30 18:00:47,761 - freqtrade.persistence.trade_model - INFO - Updating trade (id=434) ...
2022-05-30 18:00:47,762 - freqtrade.persistence.trade_model - INFO - LIMIT_BUY has been fulfilled for Trade(id=434, pair=BZZ3S/USDT, amount=1.73400000, is_short=False, leverage=1.0, open_rate=3.87804000, open_since=2022-05-30 16:00:14).
2022-05-30 18:00:48,166 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 18:00:48,167 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry_fill, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 3.87804, 'open_rate': 3.87804, 'order_type': None, 'stake_amount': 12.10442148, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 1.734, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 3.87804}
2022-05-30 18:00:48,168 - freqtrade.rpc.telegram - INFO - Notification 'entry_fill' not sent.

// Trying to open 3rd order (Position adjustment)
[...]
2022-05-30 18:42:46,656 - freqtrade.freqtradebot - INFO - Position adjust: about to create a new order for BZZ3S/USDT with stake: 8.06985018 for Trade(id=434, pair=BZZ3S/USDT, amount=3.05000000, is_short=False, leverage=1.0, open_rate=3.96866278, open_since=2022-05-30 16:00:14)
2022-05-30 18:42:46,926 - freqtrade.freqtradebot - INFO - Order #162471040442 was created for BZZ3S/USDT and status is open.
2022-05-30 18:42:47,224 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 18:42:47,229 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 3.57109, 'open_rate': 3.57109, 'order_type': 'limit', 'stake_amount': 12.10442148, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 3.05, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 3.57109}
2022-05-30 18:42:47,325 - freqtrade.freqtradebot - INFO - DCA order open, will wait for resolution: Trade(id=434, pair=BZZ3S/USDT, amount=3.05000000, is_short=False, leverage=1.0, open_rate=3.96866278, open_since=2022-05-30 16:00:14)
2022-05-30 18:42:54,733 - freqtrade.freqtradebot - INFO - Found open order for Trade(id=434, pair=BZZ3S/USDT, amount=3.05000000, is_short=False, leverage=1.0, open_rate=3.96866278, open_since=2022-05-30 16:00:14)

// 3rd order timeout triggered
// Freqtrade cancel order and _FULLY_REMOVE_ Trade Position from database:
[...]
2022-05-30 18:48:47,604 - freqtrade.freqtradebot - INFO - Buy order cancelled due to timeout for Trade(id=434, pair=BZZ3S/USDT, amount=3.05000000, is_short=False, leverage=1.0, open_rate=3.96866278, open_since=2022-05-30 16:00:14).
2022-05-30 18:48:47,605 - freqtrade.freqtradebot - INFO - Buy order fully cancelled. Removing Trade(id=434, pair=BZZ3S/USDT, amount=3.05000000, is_short=False, leverage=1.0, open_rate=3.96866278, open_since=2022-05-30 16:00:14) from database.
2022-05-30 18:48:47,933 - freqtrade.wallets - INFO - Wallets synced.
2022-05-30 18:48:47,933 - freqtrade.rpc.rpc_manager - INFO - Sending rpc message: {'trade_id': 434, 'type': entry_cancel, 'buy_tag': None, 'enter_tag': None, 'exchange': 'Gateio', 'pair': 'BZZ3S/USDT', 'leverage': 1.0, 'direction': 'Long', 'limit': 3.9686627803278687, 'order_type': 'limit', 'stake_amount': 12.10442148, 'stake_currency': 'USDT', 'fiat_currency': None, 'amount': 3.05, 'open_date': datetime.datetime(2022, 5, 30, 16, 0, 14, 147005), 'current_rate': 3.57109, 'reason': 'cancelled due to timeout, fully cancelled'}

xmatthias commented 2 years ago

Thanks for the detailed description / bugreport. I've been aware of "Odd" behaviour in this area - but was unable to recreate the problem / know the exact events (@eSeR1805 this is the problem i was trying to trace down in #6861 but was unable to...).

However with this description, i was immediately able to recreate this.

I think i have a fix for this (at least in mind) - but will obviously need to test that a bit further before releasing that - to avoid unintended sideeffects.

medenlin commented 2 years ago

Is there any workaround for this issue until the update is released?

xmatthias commented 2 years ago

Sure, you can either avoid using multiple orders, or make sure that the adjusted order does not time out.

xmatthias commented 2 years ago

It's fixed in the latest develop - let me know if you still encounter this after updating to that.

medenlin commented 2 years ago

It's fixed in the latest develop - let me know if you still encounter this after updating to that.

Ok. I update to latest dev version and keep observing :)

medenlin commented 2 years ago

Confirm! Canceling adjustment orders by timeout works correct now. Thank you!

freqtrade / freqtrade