diff --git a/freqtrade/exchange/exchange.py b/freqtrade/exchange/exchange.py index b3255f1bd..f2f8cd69f 100644 --- a/freqtrade/exchange/exchange.py +++ b/freqtrade/exchange/exchange.py @@ -913,6 +913,14 @@ class Exchange: self._async_get_trade_history(pair=pair, since=since, until=until, from_id=from_id)) + def check_order_canceled_empty(self, order: Dict) -> bool: + """ + Verify if an order has been cancelled without being partially filled + :param order: Order dict as returned from get_order() + :return: True if order has been cancelled without being filled, False otherwise. + """ + return order.get('status') in ('closed', 'canceled') and order.get('filled') == 0.0 + @retrier def cancel_order(self, order_id: str, pair: str) -> None: if self._config['dry_run']: diff --git a/freqtrade/freqtradebot.py b/freqtrade/freqtradebot.py index 570f8bea8..a0d142dee 100644 --- a/freqtrade/freqtradebot.py +++ b/freqtrade/freqtradebot.py @@ -143,6 +143,10 @@ class FreqtradeBot: self.dataprovider.refresh(self._create_pair_whitelist(self.active_pair_whitelist), self.strategy.informative_pairs()) + with self._sell_lock: + # Check and handle any timed out open orders + self.check_handle_timedout() + # Protect from collisions with forcesell. # Without this, freqtrade my try to recreate stoploss_on_exchange orders # while selling is in process, since telegram messages arrive in an different thread. @@ -154,8 +158,6 @@ class FreqtradeBot: if self.get_free_open_trades(): self.enter_positions() - # Check and handle any timed out open orders - self.check_handle_timedout() Trade.session.flush() def _refresh_whitelist(self, trades: List[Trade] = []) -> List[str]: @@ -600,7 +602,6 @@ class FreqtradeBot: trades_closed = 0 for trade in trades: try: - self.update_trade_state(trade) if (self.strategy.order_types.get('stoploss_on_exchange') and self.handle_stoploss_on_exchange(trade)): @@ -860,30 +861,26 @@ class FreqtradeBot: continue order = self.exchange.get_order(trade.open_order_id, trade.pair) except (RequestException, DependencyException, InvalidOrderException): - logger.info( - 'Cannot query order for %s due to %s', - trade, - traceback.format_exc()) + logger.info('Cannot query order for %s due to %s', trade, traceback.format_exc()) continue - # Check if trade is still actually open - if float(order.get('remaining', 0.0)) == 0.0: - self.wallets.update() - continue + trade_state_update = self.update_trade_state(trade, order) - if ((order['side'] == 'buy' and order['status'] == 'canceled') - or (self._check_timed_out('buy', order))): + if (order['side'] == 'buy' and ( + trade_state_update + or self._check_timed_out('buy', order))): self.handle_timedout_limit_buy(trade, order) self.wallets.update() order_type = self.strategy.order_types['buy'] self._notify_buy_cancel(trade, order_type) - elif ((order['side'] == 'sell' and order['status'] == 'canceled') - or (self._check_timed_out('sell', order))): - self.handle_timedout_limit_sell(trade, order) + elif (order['side'] == 'sell' and ( + trade_state_update + or self._check_timed_out('sell', order))): + reason = self.handle_timedout_limit_sell(trade, order) self.wallets.update() order_type = self.strategy.order_types['sell'] - self._notify_sell_cancel(trade, order_type) + self._notify_sell_cancel(trade, order_type, reason) def handle_timedout_limit_buy(self, trade: Trade, order: Dict) -> bool: """ @@ -916,17 +913,7 @@ class FreqtradeBot: # we need to fall back to the values from order if corder does not contain these keys. trade.amount = order['amount'] - corder.get('remaining', order['remaining']) trade.stake_amount = trade.amount * trade.open_rate - # verify if fees were taken from amount to avoid problems during selling - try: - new_amount = self.get_real_amount(trade, corder if 'fee' in corder else order, - trade.amount) - if not isclose(order['amount'], new_amount, abs_tol=constants.MATH_CLOSE_PREC): - trade.amount = new_amount - # Fee was applied, so set to 0 - trade.fee_open = 0 - trade.recalc_open_trade_price() - except DependencyException as e: - logger.warning("Could not update trade amount: %s", e) + self.update_trade_state(trade, corder if 'fee' in corder else order, trade.amount) trade.open_order_id = None logger.info('Partial buy order timeout for %s.', trade) @@ -936,14 +923,14 @@ class FreqtradeBot: }) return False - def handle_timedout_limit_sell(self, trade: Trade, order: Dict) -> bool: + def handle_timedout_limit_sell(self, trade: Trade, order: Dict) -> str: """ Sell timeout - cancel order and update trade - :return: True if order was fully cancelled + :return: Reason for cancel """ # if trade is not partially completed, just cancel the trade - if order['remaining'] == order['amount']: - if order["status"] != "canceled": + if order['remaining'] == order['amount'] or order.get('filled') == 0.0: + if not self.exchange.check_order_canceled_empty(order): reason = "cancelled due to timeout" # if trade is not partially completed, just delete the trade self.exchange.cancel_order(trade.open_order_id, trade.pair) @@ -953,16 +940,17 @@ class FreqtradeBot: logger.info('Sell order %s for %s.', reason, trade) trade.close_rate = None + trade.close_rate_requested = None trade.close_profit = None trade.close_profit_abs = None trade.close_date = None trade.is_open = True trade.open_order_id = None - return True + return reason # TODO: figure out how to handle partially complete sell orders - return False + return 'partially filled - keeping order open' def _safe_sell_amount(self, pair: str, amount: float) -> float: """ @@ -1081,7 +1069,7 @@ class FreqtradeBot: # Send the message self.rpc.send_msg(msg) - def _notify_sell_cancel(self, trade: Trade, order_type: str) -> None: + def _notify_sell_cancel(self, trade: Trade, order_type: str, reason: str) -> None: """ Sends rpc notification when a sell cancel occured. """ @@ -1108,6 +1096,7 @@ class FreqtradeBot: 'close_date': trade.close_date, 'stake_currency': self.config['stake_currency'], 'fiat_currency': self.config.get('fiat_display_currency', None), + 'reason': reason, } if 'fiat_display_currency' in self.config: @@ -1122,9 +1111,12 @@ class FreqtradeBot: # Common update trade state methods # - def update_trade_state(self, trade: Trade, action_order: dict = None) -> None: + def update_trade_state(self, trade: Trade, action_order: dict = None, + order_amount: float = None) -> bool: """ Checks trades with open orders and updates the amount if necessary + Handles closing both buy and sell orders. + :return: True if order has been cancelled without being filled partially, False otherwise """ # Get order details for actual price per unit if trade.open_order_id: @@ -1134,25 +1126,31 @@ class FreqtradeBot: order = action_order or self.exchange.get_order(trade.open_order_id, trade.pair) except InvalidOrderException as exception: logger.warning('Unable to fetch order %s: %s', trade.open_order_id, exception) - return + return False # Try update amount (binance-fix) try: - new_amount = self.get_real_amount(trade, order) + new_amount = self.get_real_amount(trade, order, order_amount) if not isclose(order['amount'], new_amount, abs_tol=constants.MATH_CLOSE_PREC): order['amount'] = new_amount + del order['filled'] # Fee was applied, so set to 0 trade.fee_open = 0 trade.recalc_open_trade_price() - except DependencyException as exception: logger.warning("Could not update trade amount: %s", exception) + if self.exchange.check_order_canceled_empty(order): + # Trade has been cancelled on exchange + # Handling of this will happen in check_handle_timeout. + return True trade.update(order) # Updating wallets when order is closed if not trade.is_open: self.wallets.update() + return False + def get_real_amount(self, trade: Trade, order: Dict, order_amount: float = None) -> float: """ Get real amount for the trade diff --git a/freqtrade/persistence.py b/freqtrade/persistence.py index b0ef4bd8f..fb314f439 100644 --- a/freqtrade/persistence.py +++ b/freqtrade/persistence.py @@ -328,7 +328,7 @@ class Trade(_DECL_BASE): if order_type in ('market', 'limit') and order['side'] == 'buy': # Update open rate and actual amount self.open_rate = Decimal(order['price']) - self.amount = Decimal(order['amount']) + self.amount = Decimal(order.get('filled', order['amount'])) self.recalc_open_trade_price() logger.info('%s_BUY has been fulfilled for %s.', order_type.upper(), self) self.open_order_id = None diff --git a/freqtrade/rpc/telegram.py b/freqtrade/rpc/telegram.py index ad01700ab..a21f7556c 100644 --- a/freqtrade/rpc/telegram.py +++ b/freqtrade/rpc/telegram.py @@ -172,7 +172,8 @@ class Telegram(RPC): ' / {profit_fiat:.3f} {fiat_currency})`').format(**msg) elif msg['type'] == RPCMessageType.SELL_CANCEL_NOTIFICATION: - message = "*{exchange}:* Cancelling Open Sell Order for {pair}".format(**msg) + message = ("*{exchange}:* Cancelling Open Sell Order " + "for {pair}. Reason: {reason}").format(**msg) elif msg['type'] == RPCMessageType.STATUS_NOTIFICATION: message = '*Status:* `{status}`'.format(**msg) diff --git a/tests/conftest.py b/tests/conftest.py index da1fbd6d4..62c1d7046 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -758,6 +758,7 @@ def limit_buy_order(): 'datetime': arrow.utcnow().isoformat(), 'price': 0.00001099, 'amount': 90.99181073, + 'filled': 90.99181073, 'remaining': 0.0, 'status': 'closed' } @@ -773,6 +774,7 @@ def market_buy_order(): 'datetime': arrow.utcnow().isoformat(), 'price': 0.00004099, 'amount': 91.99181073, + 'filled': 91.99181073, 'remaining': 0.0, 'status': 'closed' } @@ -788,6 +790,7 @@ def market_sell_order(): 'datetime': arrow.utcnow().isoformat(), 'price': 0.00004173, 'amount': 91.99181073, + 'filled': 91.99181073, 'remaining': 0.0, 'status': 'closed' } @@ -803,6 +806,7 @@ def limit_buy_order_old(): 'datetime': str(arrow.utcnow().shift(minutes=-601).datetime), 'price': 0.00001099, 'amount': 90.99181073, + 'filled': 0.0, 'remaining': 90.99181073, 'status': 'open' } @@ -818,6 +822,7 @@ def limit_sell_order_old(): 'datetime': arrow.utcnow().shift(minutes=-601).isoformat(), 'price': 0.00001099, 'amount': 90.99181073, + 'filled': 0.0, 'remaining': 90.99181073, 'status': 'open' } @@ -833,6 +838,7 @@ def limit_buy_order_old_partial(): 'datetime': arrow.utcnow().shift(minutes=-601).isoformat(), 'price': 0.00001099, 'amount': 90.99181073, + 'filled': 23.0, 'remaining': 67.99181073, 'status': 'open' } @@ -856,6 +862,7 @@ def limit_sell_order(): 'datetime': arrow.utcnow().isoformat(), 'price': 0.00001173, 'amount': 90.99181073, + 'filled': 90.99181073, 'remaining': 0.0, 'status': 'closed' } diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py index c0aedc7f9..b74ea1a6b 100644 --- a/tests/exchange/test_exchange.py +++ b/tests/exchange/test_exchange.py @@ -1731,6 +1731,20 @@ def test_cancel_order_dry_run(default_conf, mocker, exchange_name): assert exchange.cancel_order(order_id='123', pair='TKN/BTC') is None +@pytest.mark.parametrize("exchange_name", EXCHANGES) +@pytest.mark.parametrize("order,result", [ + ({'status': 'closed', 'filled': 10}, False), + ({'status': 'closed', 'filled': 0.0}, True), + ({'status': 'canceled', 'filled': 0.0}, True), + ({'status': 'canceled', 'filled': 10.0}, False), + ({'status': 'unknown', 'filled': 10.0}, False), + ({'result': 'testest123'}, False), + ]) +def test_check_order_canceled_empty(mocker, default_conf, exchange_name, order, result): + exchange = get_patched_exchange(mocker, default_conf, id=exchange_name) + assert exchange.check_order_canceled_empty(order) == result + + # Ensure that if not dry_run, we should call API @pytest.mark.parametrize("exchange_name", EXCHANGES) def test_cancel_order(default_conf, mocker, exchange_name): diff --git a/tests/rpc/test_rpc_telegram.py b/tests/rpc/test_rpc_telegram.py index d769016c4..bbc961763 100644 --- a/tests/rpc/test_rpc_telegram.py +++ b/tests/rpc/test_rpc_telegram.py @@ -1316,18 +1316,20 @@ def test_send_msg_sell_cancel_notification(default_conf, mocker) -> None: 'type': RPCMessageType.SELL_CANCEL_NOTIFICATION, 'exchange': 'Binance', 'pair': 'KEY/ETH', + 'reason': 'Cancelled on exchange' }) assert msg_mock.call_args[0][0] \ - == ('*Binance:* Cancelling Open Sell Order for KEY/ETH') + == ('*Binance:* Cancelling Open Sell Order for KEY/ETH. Reason: Cancelled on exchange') msg_mock.reset_mock() telegram.send_msg({ 'type': RPCMessageType.SELL_CANCEL_NOTIFICATION, 'exchange': 'Binance', 'pair': 'KEY/ETH', + 'reason': 'timeout' }) assert msg_mock.call_args[0][0] \ - == ('*Binance:* Cancelling Open Sell Order for KEY/ETH') + == ('*Binance:* Cancelling Open Sell Order for KEY/ETH. Reason: timeout') # Reset singleton function to avoid random breaks telegram._fiat_converter.convert_amount = old_convamount diff --git a/tests/test_freqtradebot.py b/tests/test_freqtradebot.py index e37270bd3..9fb545b15 100644 --- a/tests/test_freqtradebot.py +++ b/tests/test_freqtradebot.py @@ -1592,13 +1592,13 @@ def test_exit_positions_exception(mocker, default_conf, limit_buy_order, caplog) mocker.patch('freqtrade.exchange.Exchange.get_order', return_value=limit_buy_order) trade = MagicMock() - trade.open_order_id = '123' + trade.open_order_id = None trade.open_fee = 0.001 trades = [trade] # Test raise of DependencyException exception mocker.patch( - 'freqtrade.freqtradebot.FreqtradeBot.update_trade_state', + 'freqtrade.freqtradebot.FreqtradeBot.handle_trade', side_effect=DependencyException() ) n = freqtrade.exit_positions(trades) @@ -1970,7 +1970,7 @@ def test_check_handle_cancelled_buy(default_conf, ticker, limit_buy_order_old, o rpc_mock = patch_RPCManager(mocker) cancel_order_mock = MagicMock() patch_exchange(mocker) - limit_buy_order_old.update({"status": "canceled"}) + limit_buy_order_old.update({"status": "canceled", 'filled': 0.0}) mocker.patch.multiple( 'freqtrade.exchange.Exchange', fetch_ticker=ticker, @@ -2049,7 +2049,7 @@ def test_check_handle_cancelled_sell(default_conf, ticker, limit_sell_order_old, """ Handle sell order cancelled on exchange""" rpc_mock = patch_RPCManager(mocker) cancel_order_mock = MagicMock() - limit_sell_order_old.update({"status": "canceled"}) + limit_sell_order_old.update({"status": "canceled", 'filled': 0.0}) patch_exchange(mocker) mocker.patch.multiple( 'freqtrade.exchange.Exchange', @@ -2129,7 +2129,7 @@ def test_check_handle_timedout_partial_fee(default_conf, ticker, open_trade, cap assert rpc_mock.call_count == 2 trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all() assert len(trades) == 1 - # Verify that tradehas been updated + # Verify that trade has been updated assert trades[0].amount == (limit_buy_order_old_partial['amount'] - limit_buy_order_old_partial['remaining']) - 0.0001 assert trades[0].open_order_id is None @@ -2168,7 +2168,7 @@ def test_check_handle_timedout_partial_except(default_conf, ticker, open_trade, assert rpc_mock.call_count == 2 trades = Trade.query.filter(Trade.open_order_id.is_(open_trade.open_order_id)).all() assert len(trades) == 1 - # Verify that tradehas been updated + # Verify that trade has been updated assert trades[0].amount == (limit_buy_order_old_partial['amount'] - limit_buy_order_old_partial['remaining']) @@ -2276,7 +2276,8 @@ def test_handle_timedout_limit_sell(mocker, default_conf) -> None: assert freqtrade.handle_timedout_limit_sell(trade, order) assert cancel_order_mock.call_count == 1 order['amount'] = 2 - assert not freqtrade.handle_timedout_limit_sell(trade, order) + assert (freqtrade.handle_timedout_limit_sell(trade, order) + == 'partially filled - keeping order open') # Assert cancel_order was not called (callcount remains unchanged) assert cancel_order_mock.call_count == 1 @@ -2499,6 +2500,7 @@ def test_execute_sell_with_stoploss_on_exchange(default_conf, ticker, fee, ticke assert trade trades = [trade] + freqtrade.check_handle_timedout() freqtrade.exit_positions(trades) # Increase the price and sell it @@ -2544,8 +2546,11 @@ def test_may_execute_sell_after_stoploss_on_exchange_hit(default_conf, ticker, f # Create some test data freqtrade.enter_positions() + freqtrade.check_handle_timedout() trade = Trade.query.first() trades = [trade] + assert trade.stoploss_order_id is None + freqtrade.exit_positions(trades) assert trade assert trade.stoploss_order_id == '123'