Merge pull request #6114 from cdimauro/reduce_kucoin_logs

Reduce kucoin logs

freqtrade/exchange/common.py

@@ -4,9 +4,20 @@ import time
 from functools import wraps
 
 from freqtrade.exceptions import DDosProtection, RetryableOrderError, TemporaryError
+from freqtrade.mixins import LoggingMixin
 
 
 logger = logging.getLogger(__name__)
+__logging_mixin = None
+
+
+def _get_logging_mixin():
+    # Logging-mixin to cache kucoin responses
+    # Only to be used in retrier
+    global __logging_mixin
+    if not __logging_mixin:
+        __logging_mixin = LoggingMixin(logger)
+    return __logging_mixin
 
 
 # Maximum default retry count.
@@ -72,28 +83,33 @@ def calculate_backoff(retrycount, max_retries):
 def retrier_async(f):
     async def wrapper(*args, **kwargs):
         count = kwargs.pop('count', API_RETRY_COUNT)
+        kucoin = args[0].name == "Kucoin"  # Check if the exchange is KuCoin.
         try:
             return await f(*args, **kwargs)
         except TemporaryError as ex:
-            logger.warning('%s() returned exception: "%s"', f.__name__, ex)
+            msg = f'{f.__name__}() returned exception: "{ex}". '
             if count > 0:
-                logger.warning('retrying %s() still for %s times', f.__name__, count)
+                msg += f'Retrying still for {count} times.'
                 count -= 1
-                kwargs.update({'count': count})
+                kwargs['count'] = count
                 if isinstance(ex, DDosProtection):
-                    if "kucoin" in str(ex) and "429000" in str(ex):
+                    if kucoin and "429000" in str(ex):
                         # Temporary fix for 429000 error on kucoin
                         # see https://github.com/freqtrade/freqtrade/issues/5700 for details.
-                        logger.warning(
+                        _get_logging_mixin().log_once(
                             f"Kucoin 429 error, avoid triggering DDosProtection backoff delay. "
-                            f"{count} tries left before giving up")
+                            f"{count} tries left before giving up", logmethod=logger.warning)
+                        # Reset msg to avoid logging too many times.
+                        msg = ''
                     else:
                         backoff_delay = calculate_backoff(count + 1, API_RETRY_COUNT)
                         logger.info(f"Applying DDosProtection backoff delay: {backoff_delay}")
                         await asyncio.sleep(backoff_delay)
+                if msg:
+                    logger.warning(msg)
                 return await wrapper(*args, **kwargs)
             else:
-                logger.warning('Giving up retrying: %s()', f.__name__)
+                logger.warning(msg + 'Giving up.')
                 raise ex
     return wrapper
 
@@ -106,9 +122,9 @@ def retrier(_func=None, retries=API_RETRY_COUNT):
             try:
                 return f(*args, **kwargs)
             except (TemporaryError, RetryableOrderError) as ex:
-                logger.warning('%s() returned exception: "%s"', f.__name__, ex)
+                msg = f'{f.__name__}() returned exception: "{ex}". '
                 if count > 0:
-                    logger.warning('retrying %s() still for %s times', f.__name__, count)
+                    logger.warning(msg + f'Retrying still for {count} times.')
                     count -= 1
                     kwargs.update({'count': count})
                     if isinstance(ex, (DDosProtection, RetryableOrderError)):
@@ -118,7 +134,7 @@ def retrier(_func=None, retries=API_RETRY_COUNT):
                         time.sleep(backoff_delay)
                     return wrapper(*args, **kwargs)
                 else:
-                    logger.warning('Giving up retrying: %s()', f.__name__)
+                    logger.warning(msg + 'Giving up.')
                     raise ex
         return wrapper
     # Support both @retrier and @retrier(retries=2) syntax

tests/conftest.py

@@ -4,7 +4,6 @@ import logging
 import re
 from copy import deepcopy
 from datetime import datetime, timedelta
-from functools import reduce
 from pathlib import Path
 from unittest.mock import MagicMock, Mock, PropertyMock
 
@@ -50,17 +49,23 @@ def pytest_configure(config):
 
 
 def log_has(line, logs):
-    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'foobar')
+    """Check if line is found on some caplog's message."""
-    # and we want to match line against foobar in the tuple
+    return any(line == message for message in logs.messages)
-    return reduce(lambda a, b: a or b,
-                  filter(lambda x: x[2] == line, logs.record_tuples),
-                  False)
 
 
 def log_has_re(line, logs):
-    return reduce(lambda a, b: a or b,
+    """Check if line matches some caplog's message."""
-                  filter(lambda x: re.match(line, x[2]), logs.record_tuples),
+    return any(re.match(line, message) for message in logs.messages)
-                  False)
+
+
+def num_log_has(line, logs):
+    """Check how many times line is found in caplog's messages."""
+    return sum(line == message for message in logs.messages)
+
+
+def num_log_has_re(line, logs):
+    """Check how many times line matches caplog's messages."""
+    return sum(bool(re.match(line, message)) for message in logs.messages)
 
 
 def get_args(args):

tests/exchange/test_exchange.py

@@ -20,7 +20,7 @@ from freqtrade.exchange.exchange import (market_is_active, timeframe_to_minutes,
                                          timeframe_to_next_date, timeframe_to_prev_date,
                                          timeframe_to_seconds)
 from freqtrade.resolvers.exchange_resolver import ExchangeResolver
-from tests.conftest import get_mock_coro, get_patched_exchange, log_has, log_has_re
+from tests.conftest import get_mock_coro, get_patched_exchange, log_has, log_has_re, num_log_has_re
 
 
 # Make sure to always keep one exchange here which is NOT subclassed!!
@@ -1740,6 +1740,44 @@ async def test__async_get_candle_history(default_conf, mocker, caplog, exchange_
                                                  (arrow.utcnow().int_timestamp - 2000) * 1000)
 
 
+@pytest.mark.asyncio
+async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
+    caplog.set_level(logging.INFO)
+    api_mock = MagicMock()
+    api_mock.fetch_ohlcv = MagicMock(side_effect=ccxt.DDoSProtection(
+        "kucoin GET https://openapi-v2.kucoin.com/api/v1/market/candles?"
+        "symbol=ETH-BTC&type=5min&startAt=1640268735&endAt=1640418735"
+        "429 Too Many Requests" '{"code":"429000","msg":"Too Many Requests"}'))
+    exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
+
+    msg = "Kucoin 429 error, avoid triggering DDosProtection backoff delay"
+    assert not num_log_has_re(msg, caplog)
+
+    for _ in range(3):
+        with pytest.raises(DDosProtection, match=r'429 Too Many Requests'):
+            await exchange._async_get_candle_history(
+                "ETH/BTC", "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=3)
+    assert num_log_has_re(msg, caplog) == 3
+
+    caplog.clear()
+    # Test regular non-kucoin message
+    api_mock.fetch_ohlcv = MagicMock(side_effect=ccxt.DDoSProtection(
+        "kucoin GET https://openapi-v2.kucoin.com/api/v1/market/candles?"
+        "symbol=ETH-BTC&type=5min&startAt=1640268735&endAt=1640418735"
+        "429 Too Many Requests" '{"code":"2222222","msg":"Too Many Requests"}'))
+
+    msg = r'_async_get_candle_history\(\) returned exception: .*'
+    msg2 = r'Applying DDosProtection backoff delay: .*'
+    with patch('freqtrade.exchange.common.asyncio.sleep', get_mock_coro(None)):
+        for _ in range(3):
+            with pytest.raises(DDosProtection, match=r'429 Too Many Requests'):
+                await exchange._async_get_candle_history(
+                    "ETH/BTC", "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=3)
+        # Expect the "returned exception" message 12 times (4 retries * 3 (loop))
+        assert num_log_has_re(msg, caplog) == 12
+        assert num_log_has_re(msg2, caplog) == 9
+
+
 @pytest.mark.asyncio
 async def test__async_get_candle_history_empty(default_conf, mocker, caplog):
     """ Test empty exchange result """

tests/plugins/test_pairlist.py

@@ -15,7 +15,7 @@ from freqtrade.plugins.pairlist.pairlist_helpers import expand_pairlist
 from freqtrade.plugins.pairlistmanager import PairListManager
 from freqtrade.resolvers import PairListResolver
 from tests.conftest import (create_mock_trades, get_patched_exchange, get_patched_freqtradebot,
-                            log_has, log_has_re)
+                            log_has, log_has_re, num_log_has)
 
 
 @pytest.fixture(scope="function")
@@ -237,19 +237,13 @@ def test_remove_logs_for_pairs_already_in_blacklist(mocker, markets, static_pl_c
     # Ensure that log message wasn't generated.
     assert not log_has('Pair BLK/BTC in your blacklist. Removing it from whitelist...', caplog)
 
-    new_whitelist = freqtrade.pairlists.verify_blacklist(whitelist + ['BLK/BTC'], logger.warning)
+    for _ in range(3):
-    # Ensure that the pair is removed from the white list, and properly logged.
+        new_whitelist = freqtrade.pairlists.verify_blacklist(
-    assert set(whitelist) == set(new_whitelist)
+            whitelist + ['BLK/BTC'], logger.warning)
-    matches = sum(1 for message in caplog.messages
+        # Ensure that the pair is removed from the white list, and properly logged.
-                  if message == 'Pair BLK/BTC in your blacklist. Removing it from whitelist...')
+        assert set(whitelist) == set(new_whitelist)
-    assert matches == 1
+    assert num_log_has('Pair BLK/BTC in your blacklist. Removing it from whitelist...',
-
+                       caplog) == 1
-    new_whitelist = freqtrade.pairlists.verify_blacklist(whitelist + ['BLK/BTC'], logger.warning)
-    # Ensure that the pair is not logged anymore when being removed from the pair list.
-    assert set(whitelist) == set(new_whitelist)
-    matches = sum(1 for message in caplog.messages
-                  if message == 'Pair BLK/BTC in your blacklist. Removing it from whitelist...')
-    assert matches == 1
 
 
 def test_refresh_pairlist_dynamic(mocker, shitcoinmarkets, tickers, whitelist_conf):