Merge pull request #3146 from freqtrade/buy_order_timeout_logging

Improve handling for buy order cancels

freqtrade/freqtradebot.py

@@ -20,6 +20,7 @@ from freqtrade.data.dataprovider import DataProvider
 from freqtrade.edge import Edge
 from freqtrade.exceptions import DependencyException, InvalidOrderException
 from freqtrade.exchange import timeframe_to_minutes, timeframe_to_next_date
+from freqtrade.misc import safe_value_fallback
 from freqtrade.pairlist.pairlistmanager import PairListManager
 from freqtrade.persistence import Trade
 from freqtrade.resolvers import ExchangeResolver, StrategyResolver
@@ -889,18 +890,24 @@ class FreqtradeBot:
         """
         if order['status'] != 'canceled':
             reason = "cancelled due to timeout"
+            try:
                 corder = self.exchange.cancel_order(trade.open_order_id, trade.pair)
                 # Some exchanges don't return a dict here.
                 if not isinstance(corder, dict):
                     corder = {}
                 logger.info('Buy order %s for %s.', reason, trade)
+            except InvalidOrderException:
+                corder = {}
+                logger.exception(
+                    f"Could not cancel buy order {trade.open_order_id} for pair {trade.pair}")
         else:
             # Order was cancelled already, so we can reuse the existing dict
             corder = order
             reason = "cancelled on exchange"
             logger.info('Buy order %s for %s.', reason, trade)
 
-        if corder.get('remaining', order['remaining']) == order['amount']:
+        if safe_value_fallback(corder, order, 'remaining', 'remaining') == order['amount']:
+            logger.info('Buy order fully cancelled. Removing %s from database.', trade)
             # if trade is not partially completed, just delete the trade
             Trade.session.delete(trade)
             Trade.session.flush()
@@ -911,7 +918,8 @@ class FreqtradeBot:
         # cancel_order may not contain the full order dict, so we need to fallback
         # to the order dict aquired before cancelling.
         # 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.amount = order['amount'] - safe_value_fallback(corder, order,
+                                                             'remaining', 'remaining')
         trade.stake_amount = trade.amount * trade.open_rate
         self.update_trade_state(trade, corder if 'fee' in corder else order, trade.amount)
 

freqtrade/misc.py

@@ -134,6 +134,21 @@ def round_dict(d, n):
     return {k: (round(v, n) if isinstance(v, float) else v) for k, v in d.items()}
 
 
+def safe_value_fallback(dict1: dict, dict2: dict, key1: str, key2: str, default_value=None):
+    """
+    Search a value in dict1, return this if it's not None.
+    Fall back to dict2 - return key2 from dict2 if it's not None.
+    Else falls back to None.
+
+    """
+    if key1 in dict1 and dict1[key1] is not None:
+        return dict1[key1]
+    else:
+        if key2 in dict2 and dict2[key2] is not None:
+            return dict2[key2]
+    return default_value
+
+
 def plural(num: float, singular: str, plural: str = None) -> str:
     return singular if (num == 1 or num == -1) else plural or singular + 's'
 

tests/test_freqtradebot.py

@@ -2204,14 +2204,11 @@ def test_check_handle_timedout_exception(default_conf, ticker, open_trade, mocke
                       caplog)
 
 
-def test_handle_timedout_limit_buy(mocker, default_conf, limit_buy_order) -> None:
+def test_handle_timedout_limit_buy(mocker, caplog, default_conf, limit_buy_order) -> None:
     patch_RPCManager(mocker)
     patch_exchange(mocker)
     cancel_order_mock = MagicMock(return_value=limit_buy_order)
-    mocker.patch.multiple(
-        'freqtrade.exchange.Exchange',
-        cancel_order=cancel_order_mock
-    )
+    mocker.patch('freqtrade.exchange.Exchange.cancel_order', cancel_order_mock)
 
     freqtrade = FreqtradeBot(default_conf)
 
@@ -2227,9 +2224,14 @@ def test_handle_timedout_limit_buy(mocker, default_conf, limit_buy_order) -> Non
     assert not freqtrade.handle_timedout_limit_buy(trade, limit_buy_order)
     assert cancel_order_mock.call_count == 1
 
+    mocker.patch('freqtrade.exchange.Exchange.cancel_order', side_effect=InvalidOrderException)
+    assert not freqtrade.handle_timedout_limit_buy(trade, limit_buy_order)
+    assert log_has_re(r"Could not cancel buy order", caplog)
+
 
 @pytest.mark.parametrize('cancelorder', [
     {},
+    {'remaining': None},
     'String Return value',
     123
 ])

tests/test_misc.py

@@ -9,7 +9,7 @@ import pytest
 from freqtrade.data.converter import ohlcv_to_dataframe
 from freqtrade.misc import (datesarray_to_datetimearray, file_dump_json,
                             file_load_json, format_ms_time, pair_to_filename,
-                            plural, shorten_date)
+                            plural, safe_value_fallback, shorten_date)
 
 
 def test_shorten_date() -> None:
@@ -93,6 +93,27 @@ def test_format_ms_time() -> None:
     assert format_ms_time(date_in_epoch_ms) == res.astimezone(None).strftime('%Y-%m-%dT%H:%M:%S')
 
 
+def test_safe_value_fallback():
+    dict1 = {'keya': None, 'keyb': 2, 'keyc': 5, 'keyd': None}
+    dict2 = {'keya': 20, 'keyb': None, 'keyc': 6, 'keyd': None}
+    assert safe_value_fallback(dict1, dict2, 'keya', 'keya') == 20
+    assert safe_value_fallback(dict2, dict1, 'keya', 'keya') == 20
+
+    assert safe_value_fallback(dict1, dict2, 'keyb', 'keyb') == 2
+    assert safe_value_fallback(dict2, dict1, 'keyb', 'keyb') == 2
+
+    assert safe_value_fallback(dict1, dict2, 'keyc', 'keyc') == 5
+    assert safe_value_fallback(dict2, dict1, 'keyc', 'keyc') == 6
+
+    assert safe_value_fallback(dict1, dict2, 'keyd', 'keyd') is None
+    assert safe_value_fallback(dict2, dict1, 'keyd', 'keyd') is None
+    assert safe_value_fallback(dict2, dict1, 'keyd', 'keyd', 1234) == 1234
+
+    assert safe_value_fallback(dict1, dict2, 'keyNo', 'keyNo') is None
+    assert safe_value_fallback(dict2, dict1, 'keyNo', 'keyNo') is None
+    assert safe_value_fallback(dict2, dict1, 'keyNo', 'keyNo', 1234) == 1234
+
+
 def test_plural() -> None:
     assert plural(0, "page") == "pages"
     assert plural(0.0, "page") == "pages"