From 96fbf63d0b0714c42374994984fbf454972f39b8 Mon Sep 17 00:00:00 2001
From: cdimauro <cesare.di.mauro@gmail.com>
Date: Sat, 25 Dec 2021 22:32:22 +0100
Subject: [PATCH 01/10] Reduce KuCoin logs on DDosProtection error messages

KuCoin APIs generate A LOT of error messages.
Consequently, logs are flooded with lines like:
2021-12-25 22:30:23 freqtrade.exchange.common: WARNING -
_async_get_candle_history() returned exception:
"kucoin GET https://openapi-v2.kucoin.com/api/v1/market/candles?
symbol=PDEX-USDT&type=5min&startAt=1640317818&endAt=1640467818
429 Too Many Requests {"code":"429000","msg":"Too Many Requests"}"
2021-12-25 22:30:23 freqtrade.exchange.common: WARNING -
retrying _async_get_candle_history() still for 3 times
2021-12-25 22:30:23 freqtrade.exchange.common: WARNING -
Kucoin 429 error, avoid triggering DDosProtection backoff delay.
2 tries left before giving up
2021-12-25 22:30:24 freqtrade.exchange.common: WARNING -
_async_get_candle_history() returned exception:
"kucoin GET https://openapi-v2.kucoin.com/api/v1/market/candles?
symbol=UBX-USDT&type=5min&startAt=1640317821&endAt=1640467821
429 Too Many Requests {"code":"429000","msg":"Too Many Requests"}"

Messages like:
Kucoin 429 error, avoid triggering DDosProtection backoff delay.
are logged only once for a certain period of time (default is 3600 seconds).
---
 freqtrade/exchange/common.py    |  7 +++++--
 tests/exchange/test_exchange.py | 22 ++++++++++++++++++++++
 2 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index a4c827e07..d10682a61 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -1,12 +1,15 @@
 import asyncio
 import logging
 import time
-from functools import wraps
+from functools import partial, wraps
 
 from freqtrade.exceptions import DDosProtection, RetryableOrderError, TemporaryError
+from freqtrade.mixins import LoggingMixin
 
 
 logger = logging.getLogger(__name__)
+logging_mixin = LoggingMixin(logger)
+log_once_warning = partial(logging_mixin.log_once, logmethod=logger.warning)
 
 
 # Maximum default retry count.
@@ -84,7 +87,7 @@ def retrier_async(f):
                     if "kucoin" in str(ex) and "429000" in str(ex):
                         # Temporary fix for 429000 error on kucoin
                         # see https://github.com/freqtrade/freqtrade/issues/5700 for details.
-                        logger.warning(
+                        log_once_warning(
                             f"Kucoin 429 error, avoid triggering DDosProtection backoff delay. "
                             f"{count} tries left before giving up")
                     else:
diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py
index a4b151742..9bd419e24 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -1740,6 +1740,28 @@ 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()
+
+    assert not log_has_re('Kucoin 429 error, avoid triggering DDosProtection backoff delay.*',
+                          caplog)
+
+    for _ in range(3):
+        with pytest.raises(DDosProtection, match=r'429 Too Many Requests'):
+            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")
+            await exchange._async_get_candle_history(
+                'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
+    logs_found = sum('Kucoin 429 error, avoid triggering DDosProtection backoff delay' in message
+                     for message in caplog.messages)
+    assert logs_found == 1
+
+
 @pytest.mark.asyncio
 async def test__async_get_candle_history_empty(default_conf, mocker, caplog):
     """ Test empty exchange result """

From fbaf46901edc8747d58dafecd0b6df3680b203cd Mon Sep 17 00:00:00 2001
From: cdimauro <cesare.di.mauro@gmail.com>
Date: Sun, 26 Dec 2021 09:06:26 +0100
Subject: [PATCH 02/10] Reduce more KuCoin logs on retrier decorator

More logs are reduced, for KuCoin, on the retrier_async decorator:

_async_get_candle_history() returned exception
retrying _async_get_candle_history() still for
Giving up retrying: _async_get_candle_history()
Applying DDosProtection backoff delay
---
 freqtrade/exchange/common.py    | 19 +++++++++++++------
 tests/exchange/test_exchange.py | 25 ++++++++++++++++++++++++-
 2 files changed, 37 insertions(+), 7 deletions(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index d10682a61..68e454c79 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -9,6 +9,7 @@ from freqtrade.mixins import LoggingMixin
 
 logger = logging.getLogger(__name__)
 logging_mixin = LoggingMixin(logger)
+log_once_info = partial(logging_mixin.log_once, logmethod=logger.info)
 log_once_warning = partial(logging_mixin.log_once, logmethod=logger.warning)
 
 
@@ -75,16 +76,20 @@ def calculate_backoff(retrycount, max_retries):
 def retrier_async(f):
     async def wrapper(*args, **kwargs):
         count = kwargs.pop('count', API_RETRY_COUNT)
+        self = args[0]  # Extract the exchange instance.
+        kucoin = self.name == "Kucoin"
         try:
             return await f(*args, **kwargs)
         except TemporaryError as ex:
-            logger.warning('%s() returned exception: "%s"', f.__name__, ex)
+            message = f'{f.__name__}() returned exception: "{ex}"'
+            (log_once_warning if kucoin else logger.warning)(message)
             if count > 0:
-                logger.warning('retrying %s() still for %s times', f.__name__, count)
+                message = f'retrying {f.__name__}() still for {count} times'
+                (log_once_warning if kucoin else logger.warning)(message)
                 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.
                         log_once_warning(
@@ -92,11 +97,13 @@ def retrier_async(f):
                             f"{count} tries left before giving up")
                     else:
                         backoff_delay = calculate_backoff(count + 1, API_RETRY_COUNT)
-                        logger.info(f"Applying DDosProtection backoff delay: {backoff_delay}")
+                        message = f"Applying DDosProtection backoff delay: {backoff_delay}"
+                        (log_once_info if kucoin else logger.info)(message)
                         await asyncio.sleep(backoff_delay)
                 return await wrapper(*args, **kwargs)
             else:
-                logger.warning('Giving up retrying: %s()', f.__name__)
+                message = f'Giving up retrying: {f.__name__}()'
+                (log_once_warning if kucoin else logger.warning)(message)
                 raise ex
     return wrapper
 
diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py
index 9bd419e24..4e37a6e4a 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -1757,7 +1757,30 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
             exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
             await exchange._async_get_candle_history(
                 'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    logs_found = sum('Kucoin 429 error, avoid triggering DDosProtection backoff delay' in message
+    logs_found = sum('_async_get_candle_history() returned exception: "kucoin GET ' in message
+                     for message in caplog.messages)
+    assert logs_found == 1
+    logs_found = sum('retrying _async_get_candle_history() still for ' in message
+                     for message in caplog.messages)
+    assert logs_found == 1
+    logs_found = sum("Kucoin 429 error, avoid triggering DDosProtection backoff delay" in message
+                     for message in caplog.messages)
+    assert logs_found == 1
+    logs_found = sum(message == 'Giving up retrying: _async_get_candle_history()'
+                     for message in caplog.messages)
+    assert logs_found == 1
+
+    mocker.patch('freqtrade.exchange.common.calculate_backoff', MagicMock(return_value=0.01))
+    for _ in range(3):
+        with pytest.raises(DDosProtection, match=r'XYZ Too Many Requests'):
+            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"
+                "XYZ Too Many Requests" '{"code":"XYZ000","msg":"Too Many Requests"}'))
+            exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
+            await exchange._async_get_candle_history(
+                'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
+    logs_found = sum('Applying DDosProtection backoff delay: ' in message
                      for message in caplog.messages)
     assert logs_found == 1
 

From 6509c387173da83eb45f74e9e35c74bd505bf8f8 Mon Sep 17 00:00:00 2001
From: cdimauro <cesare.di.mauro@gmail.com>
Date: Sun, 26 Dec 2021 09:49:14 +0100
Subject: [PATCH 03/10] Introduce new test functions to check logs

New functions log_contains, num_log_contains, num_log_has and num_log_has_re
are introduced in the conftest module to help and simplify checking:
- if logs contain a string;
- count how many messages contain a string;
- count how many messages are the given string;
- count how many messages matchs a regex.

A couple of existing tests are changed using the new functions.
---
 tests/conftest.py               | 28 ++++++++++++++++++++++++++++
 tests/exchange/test_exchange.py | 29 +++++++++++------------------
 tests/plugins/test_pairlist.py  | 12 +++++-------
 3 files changed, 44 insertions(+), 25 deletions(-)

diff --git a/tests/conftest.py b/tests/conftest.py
index 3ce064ee3..1a34d326e 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -49,6 +49,13 @@ def pytest_configure(config):
         setattr(config.option, 'markexpr', 'not longrun')
 
 
+def log_contains(line, logs, count=False):
+    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'spamfoobar')
+    # and we want to check if line ('foo', for example) is contained in the tuple.
+    return any(line in logger_name or line in message
+               for logger_name, level, message in logs.record_tuples)
+
+
 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
@@ -63,6 +70,27 @@ def log_has_re(line, logs):
                   False)
 
 
+def num_log_contains(line, logs, count=False):
+    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'spamfoobar')
+    # and we want to check how many times line ('foo', for example) is contained in the tuples.
+    return sum(line in logger_name or line in message
+               for logger_name, level, message in logs.record_tuples)
+
+
+def num_log_has(line, logs, count=False):
+    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'foobar')
+    # and we want to check how many times line is presente in the tuples.
+    return sum(line == logger_name or line == message
+               for logger_name, level, message in logs.record_tuples)
+
+
+def num_log_has_re(line, logs, count=False):
+    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'foobar')
+    # and we want to check how many times line matches in the tuples.
+    return sum(re.match(line, logger_name) or re.match(line, message)
+               for logger_name, level, message in logs.record_tuples)
+
+
 def get_args(args):
     return Arguments(args).get_parsed_arg()
 
diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py
index 4e37a6e4a..8d34a4d7b 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -20,7 +20,8 @@ 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_contains, log_has, log_has_re,
+                            num_log_contains)
 
 
 # Make sure to always keep one exchange here which is NOT subclassed!!
@@ -1745,8 +1746,8 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
     caplog.set_level(logging.INFO)
     api_mock = MagicMock()
 
-    assert not log_has_re('Kucoin 429 error, avoid triggering DDosProtection backoff delay.*',
-                          caplog)
+    assert not log_contains('Kucoin 429 error, avoid triggering DDosProtection backoff delay',
+                            caplog)
 
     for _ in range(3):
         with pytest.raises(DDosProtection, match=r'429 Too Many Requests'):
@@ -1757,18 +1758,12 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
             exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
             await exchange._async_get_candle_history(
                 'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    logs_found = sum('_async_get_candle_history() returned exception: "kucoin GET ' in message
-                     for message in caplog.messages)
-    assert logs_found == 1
-    logs_found = sum('retrying _async_get_candle_history() still for ' in message
-                     for message in caplog.messages)
-    assert logs_found == 1
-    logs_found = sum("Kucoin 429 error, avoid triggering DDosProtection backoff delay" in message
-                     for message in caplog.messages)
-    assert logs_found == 1
-    logs_found = sum(message == 'Giving up retrying: _async_get_candle_history()'
-                     for message in caplog.messages)
-    assert logs_found == 1
+    assert num_log_contains('_async_get_candle_history() returned exception: "kucoin GET ',
+                            caplog) == 1
+    assert num_log_contains('retrying _async_get_candle_history() still for ', caplog) == 1
+    assert num_log_contains("Kucoin 429 error, avoid triggering DDosProtection backoff delay",
+                            caplog) == 1
+    assert num_log_contains('Giving up retrying: _async_get_candle_history()', caplog) == 1
 
     mocker.patch('freqtrade.exchange.common.calculate_backoff', MagicMock(return_value=0.01))
     for _ in range(3):
@@ -1780,9 +1775,7 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
             exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
             await exchange._async_get_candle_history(
                 'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    logs_found = sum('Applying DDosProtection backoff delay: ' in message
-                     for message in caplog.messages)
-    assert logs_found == 1
+    assert num_log_contains('Applying DDosProtection backoff delay: ', caplog) == 1
 
 
 @pytest.mark.asyncio
diff --git a/tests/plugins/test_pairlist.py b/tests/plugins/test_pairlist.py
index dec6ca726..9ad4f3a2c 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")
@@ -240,16 +240,14 @@ def test_remove_logs_for_pairs_already_in_blacklist(mocker, markets, static_pl_c
     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
+    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
+    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):

From f77b8cbb7aac7959c098f8847b9edfff2f5d1815 Mon Sep 17 00:00:00 2001
From: cdimauro <cesare.di.mauro@gmail.com>
Date: Sun, 26 Dec 2021 21:09:25 +0100
Subject: [PATCH 04/10] Reduce KuCoin logs only for 429000 error

Only KuCoin messages for 429000 error code are logged once.

Logs functions are also simplified and optimized.

test_remove_logs_for_pairs_already_in_blacklist is simplified as well.
---
 freqtrade/exchange/common.py    | 15 +++++--------
 tests/conftest.py               | 40 +++++++++++++--------------------
 tests/exchange/test_exchange.py | 16 -------------
 tests/plugins/test_pairlist.py  | 14 +++++-------
 4 files changed, 25 insertions(+), 60 deletions(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index 68e454c79..948767a08 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -76,16 +76,13 @@ def calculate_backoff(retrycount, max_retries):
 def retrier_async(f):
     async def wrapper(*args, **kwargs):
         count = kwargs.pop('count', API_RETRY_COUNT)
-        self = args[0]  # Extract the exchange instance.
-        kucoin = self.name == "Kucoin"
+        kucoin = args[0].name == "Kucoin"  # Check if the exchange is KuCoin.
         try:
             return await f(*args, **kwargs)
         except TemporaryError as ex:
-            message = f'{f.__name__}() returned exception: "{ex}"'
-            (log_once_warning if kucoin else logger.warning)(message)
+            logger.warning('%s() returned exception: "%s"', f.__name__, ex)
             if count > 0:
-                message = f'retrying {f.__name__}() still for {count} times'
-                (log_once_warning if kucoin else logger.warning)(message)
+                logger.warning('retrying %s() still for %s times', f.__name__, count)
                 count -= 1
                 kwargs['count'] = count
                 if isinstance(ex, DDosProtection):
@@ -97,13 +94,11 @@ def retrier_async(f):
                             f"{count} tries left before giving up")
                     else:
                         backoff_delay = calculate_backoff(count + 1, API_RETRY_COUNT)
-                        message = f"Applying DDosProtection backoff delay: {backoff_delay}"
-                        (log_once_info if kucoin else logger.info)(message)
+                        logger.info(f"Applying DDosProtection backoff delay: {backoff_delay}")
                         await asyncio.sleep(backoff_delay)
                 return await wrapper(*args, **kwargs)
             else:
-                message = f'Giving up retrying: {f.__name__}()'
-                (log_once_warning if kucoin else logger.warning)(message)
+                logger.warning('Giving up retrying: %s()', f.__name__)
                 raise ex
     return wrapper
 
diff --git a/tests/conftest.py b/tests/conftest.py
index 1a34d326e..1af474172 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
 
@@ -49,44 +48,35 @@ def pytest_configure(config):
         setattr(config.option, 'markexpr', 'not longrun')
 
 
-def log_contains(line, logs, count=False):
-    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'spamfoobar')
-    # and we want to check if line ('foo', for example) is contained in the tuple.
-    return any(line in logger_name or line in message
-               for logger_name, level, message in logs.record_tuples)
+def log_contains(line, logs):
+    """Check if line is contained in some caplog's message."""
+    return any(line in message for message in logs.messages)
 
 
 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_contains(line, logs, count=False):
-    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'spamfoobar')
-    # and we want to check how many times line ('foo', for example) is contained in the tuples.
-    return sum(line in logger_name or line in message
-               for logger_name, level, message in logs.record_tuples)
+def num_log_contains(line, logs):
+    """Check how many times line is contained in caplog's messages."""
+    # We want to check how many times line ('foo', for example) is contained in caplog's messages.
+    return sum(line in message for message in logs.messages)
 
 
-def num_log_has(line, logs, count=False):
-    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'foobar')
-    # and we want to check how many times line is presente in the tuples.
+def num_log_has(line, logs):
+    """Check how many times line is found in caplog's messages."""
     return sum(line == logger_name or line == message
                for logger_name, level, message in logs.record_tuples)
 
 
-def num_log_has_re(line, logs, count=False):
-    # caplog mocker returns log as a tuple: ('freqtrade.something', logging.WARNING, 'foobar')
-    # and we want to check how many times line matches in the tuples.
+def num_log_has_re(line, logs):
+    """Check how many times line matches caplog's messages."""
     return sum(re.match(line, logger_name) or re.match(line, message)
                for logger_name, level, message in logs.record_tuples)
 
diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py
index 8d34a4d7b..be3f9e879 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -1758,24 +1758,8 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
             exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
             await exchange._async_get_candle_history(
                 'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    assert num_log_contains('_async_get_candle_history() returned exception: "kucoin GET ',
-                            caplog) == 1
-    assert num_log_contains('retrying _async_get_candle_history() still for ', caplog) == 1
     assert num_log_contains("Kucoin 429 error, avoid triggering DDosProtection backoff delay",
                             caplog) == 1
-    assert num_log_contains('Giving up retrying: _async_get_candle_history()', caplog) == 1
-
-    mocker.patch('freqtrade.exchange.common.calculate_backoff', MagicMock(return_value=0.01))
-    for _ in range(3):
-        with pytest.raises(DDosProtection, match=r'XYZ Too Many Requests'):
-            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"
-                "XYZ Too Many Requests" '{"code":"XYZ000","msg":"Too Many Requests"}'))
-            exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
-            await exchange._async_get_candle_history(
-                'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    assert num_log_contains('Applying DDosProtection backoff delay: ', caplog) == 1
 
 
 @pytest.mark.asyncio
diff --git a/tests/plugins/test_pairlist.py b/tests/plugins/test_pairlist.py
index 9ad4f3a2c..f7ff495ac 100644
--- a/tests/plugins/test_pairlist.py
+++ b/tests/plugins/test_pairlist.py
@@ -237,15 +237,11 @@ 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)
-    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)
+    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
 

From 314e10596bcf796aa155643a592bdb935100c2a5 Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Mon, 27 Dec 2021 16:39:31 +0100
Subject: [PATCH 05/10] Remove checking against logger_name in num_log_has

---
 tests/conftest.py | 6 ++----
 1 file changed, 2 insertions(+), 4 deletions(-)

diff --git a/tests/conftest.py b/tests/conftest.py
index 1af474172..3fc1256ef 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -71,14 +71,12 @@ def num_log_contains(line, logs):
 
 def num_log_has(line, logs):
     """Check how many times line is found in caplog's messages."""
-    return sum(line == logger_name or line == message
-               for logger_name, level, message in logs.record_tuples)
+    return sum(line == message for logger_name, level, message in logs.record_tuples)
 
 
 def num_log_has_re(line, logs):
     """Check how many times line matches caplog's messages."""
-    return sum(re.match(line, logger_name) or re.match(line, message)
-               for logger_name, level, message in logs.record_tuples)
+    return sum(re.match(line, message) for logger_name, level, message in logs.record_tuples)
 
 
 def get_args(args):

From 54858a0bbba9f3481cd6238bfadeaace71d5c481 Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Mon, 27 Dec 2021 16:39:47 +0100
Subject: [PATCH 06/10] Simplify test to only initialize and mock once.

---
 tests/exchange/test_exchange.py | 19 +++++++++----------
 1 file changed, 9 insertions(+), 10 deletions(-)

diff --git a/tests/exchange/test_exchange.py b/tests/exchange/test_exchange.py
index be3f9e879..7bd62c838 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -1745,21 +1745,20 @@ async def test__async_get_candle_history(default_conf, mocker, caplog, exchange_
 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")
 
-    assert not log_contains('Kucoin 429 error, avoid triggering DDosProtection backoff delay',
-                            caplog)
+    msg = "Kucoin 429 error, avoid triggering DDosProtection backoff delay"
+    assert not log_contains(msg, caplog)
 
     for _ in range(3):
         with pytest.raises(DDosProtection, match=r'429 Too Many Requests'):
-            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")
             await exchange._async_get_candle_history(
-                'ETH/BTC', "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
-    assert num_log_contains("Kucoin 429 error, avoid triggering DDosProtection backoff delay",
-                            caplog) == 1
+                "ETH/BTC", "5m", (arrow.utcnow().int_timestamp - 2000) * 1000, count=1)
+    assert num_log_contains(msg, caplog) == 1
 
 
 @pytest.mark.asyncio

From ef2b3262623d28c74bb4116dec90717dea80c7d2 Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Mon, 27 Dec 2021 16:47:34 +0100
Subject: [PATCH 07/10] Reduce retrier message repetition

by combining messages, we can provide the same information in fewer log messages
---
 freqtrade/exchange/common.py | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index 948767a08..2643cd499 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -80,9 +80,9 @@ def retrier_async(f):
         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)
+                logger.warning(msg + f'Retrying still for {count} times.')
                 count -= 1
                 kwargs['count'] = count
                 if isinstance(ex, DDosProtection):
@@ -98,7 +98,7 @@ def retrier_async(f):
                         await asyncio.sleep(backoff_delay)
                 return await wrapper(*args, **kwargs)
             else:
-                logger.warning('Giving up retrying: %s()', f.__name__)
+                logger.warning(msg + 'Giving up.')
                 raise ex
     return wrapper
 
@@ -111,9 +111,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)):
@@ -123,7 +123,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

From bb6562113454f15cec054aba49b9501360045c5b Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Mon, 27 Dec 2021 17:14:59 +0100
Subject: [PATCH 08/10] Simplify test, simplify "log_*" selection

---
 tests/conftest.py               | 15 ++-------------
 tests/exchange/test_exchange.py | 27 ++++++++++++++++++++++-----
 2 files changed, 24 insertions(+), 18 deletions(-)

diff --git a/tests/conftest.py b/tests/conftest.py
index 3fc1256ef..9cd1332d4 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -48,11 +48,6 @@ def pytest_configure(config):
         setattr(config.option, 'markexpr', 'not longrun')
 
 
-def log_contains(line, logs):
-    """Check if line is contained in some caplog's message."""
-    return any(line in message for message in logs.messages)
-
-
 def log_has(line, logs):
     """Check if line is found on some caplog's message."""
     return any(line == message for message in logs.messages)
@@ -63,20 +58,14 @@ def log_has_re(line, logs):
     return any(re.match(line, message) for message in logs.messages)
 
 
-def num_log_contains(line, logs):
-    """Check how many times line is contained in caplog's messages."""
-    # We want to check how many times line ('foo', for example) is contained in caplog's messages.
-    return sum(line in 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 logger_name, level, message in logs.record_tuples)
+    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(re.match(line, message) for logger_name, level, message in logs.record_tuples)
+    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 7bd62c838..071f4e2b8 100644
--- a/tests/exchange/test_exchange.py
+++ b/tests/exchange/test_exchange.py
@@ -20,8 +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_contains, log_has, log_has_re,
-                            num_log_contains)
+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!!
@@ -1752,13 +1751,31 @@ async def test__async_kucoin_get_candle_history(default_conf, mocker, caplog):
     exchange = get_patched_exchange(mocker, default_conf, api_mock, id="kucoin")
 
     msg = "Kucoin 429 error, avoid triggering DDosProtection backoff delay"
-    assert not log_contains(msg, caplog)
+    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=1)
-    assert num_log_contains(msg, caplog) == 1
+                "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

From 05a488a7a0c8d3d7d2faad0db714d413973e17db Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Mon, 27 Dec 2021 17:15:30 +0100
Subject: [PATCH 09/10] Further reduce log verbosity for kucoin 429000
 exception

---
 freqtrade/exchange/common.py | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index 2643cd499..5bb7f348c 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -82,7 +82,7 @@ def retrier_async(f):
         except TemporaryError as ex:
             msg = f'{f.__name__}() returned exception: "{ex}". '
             if count > 0:
-                logger.warning(msg + f'Retrying still for {count} times.')
+                msg += f'Retrying still for {count} times.'
                 count -= 1
                 kwargs['count'] = count
                 if isinstance(ex, DDosProtection):
@@ -92,10 +92,14 @@ def retrier_async(f):
                         log_once_warning(
                             f"Kucoin 429 error, avoid triggering DDosProtection backoff delay. "
                             f"{count} tries left before giving up")
+                        # 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(msg + 'Giving up.')

From 2b94fbfa74fc7c6c8a14ea56ab0b2e226df606c6 Mon Sep 17 00:00:00 2001
From: Matthias <xmatthias@outlook.com>
Date: Wed, 29 Dec 2021 17:05:53 +0100
Subject: [PATCH 10/10] Avoid using singleton where not necessary

---
 freqtrade/exchange/common.py | 19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)

diff --git a/freqtrade/exchange/common.py b/freqtrade/exchange/common.py
index 5bb7f348c..3916ee8f7 100644
--- a/freqtrade/exchange/common.py
+++ b/freqtrade/exchange/common.py
@@ -1,16 +1,23 @@
 import asyncio
 import logging
 import time
-from functools import partial, wraps
+from functools import wraps
 
 from freqtrade.exceptions import DDosProtection, RetryableOrderError, TemporaryError
 from freqtrade.mixins import LoggingMixin
 
 
 logger = logging.getLogger(__name__)
-logging_mixin = LoggingMixin(logger)
-log_once_info = partial(logging_mixin.log_once, logmethod=logger.info)
-log_once_warning = partial(logging_mixin.log_once, logmethod=logger.warning)
+__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.
@@ -89,9 +96,9 @@ def retrier_async(f):
                     if kucoin and "429000" in str(ex):
                         # Temporary fix for 429000 error on kucoin
                         # see https://github.com/freqtrade/freqtrade/issues/5700 for details.
-                        log_once_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: