diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py index a4c827e07..3916ee8f7 100644 --- a/freqtrade/exchange/common.py +++ b/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 diff --git a/tests/conftest.py b/tests/conftest.py index 3ce064ee3..9cd1332d4 100644 --- a/tests/conftest.py +++ b/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') - # and we want to match line against foobar in the tuple - return reduce(lambda a, b: a or b, - filter(lambda x: x[2] == line, logs.record_tuples), - False) + """Check if line is found on some caplog's message.""" + return any(line == message for message in logs.messages) def log_has_re(line, logs): - return reduce(lambda a, b: a or b, - filter(lambda x: re.match(line, x[2]), logs.record_tuples), - False) + """Check if line matches some caplog's message.""" + return any(re.match(line, message) for message in logs.messages) + + +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): diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py index a4b151742..071f4e2b8 100644 --- a/tests/exchange/test_exchange.py +++ b/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 """ diff --git a/tests/plugins/test_pairlist.py b/tests/plugins/test_pairlist.py index dec6ca726..f7ff495ac 100644 --- a/tests/plugins/test_pairlist.py +++ b/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) - # Ensure that the pair is removed from the white list, and properly logged. - 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 - - 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 + for _ in range(3): + new_whitelist = freqtrade.pairlists.verify_blacklist( + whitelist + ['BLK/BTC'], logger.warning) + # Ensure that the pair is removed from the white list, and properly logged. + assert set(whitelist) == set(new_whitelist) + assert num_log_has('Pair BLK/BTC in your blacklist. Removing it from whitelist...', + caplog) == 1 def test_refresh_pairlist_dynamic(mocker, shitcoinmarkets, tickers, whitelist_conf):