Merge pull request #11505 from freqtrade/feat/log_from_config

allow loading logging from config

tests/conftest.py

@@ -549,6 +549,14 @@ def user_dir(mocker, tmp_path) -> Path:
     return user_dir
 
 
+@pytest.fixture()
+def keep_log_config_loggers(mocker):
+    # Mock the _handle_existing_loggers function to prevent it from disabling all loggers.
+    # This is necessary to keep all loggers active, and avoid random failures if
+    # this file is ran before the test_rest_client file.
+    mocker.patch("logging.config._handle_existing_loggers")
+
+
 @pytest.fixture(autouse=True)
 def patch_coingecko(mocker) -> None:
     """

tests/exchange_online/test_ccxt_ws_compat.py

@@ -12,7 +12,6 @@ import pytest
 
 from freqtrade.enums import CandleType
 from freqtrade.exchange.exchange_utils import timeframe_to_prev_date
-from freqtrade.loggers.set_log_levels import set_loggers
 from freqtrade.util.datetime_helpers import dt_now
 from tests.conftest import log_has_re
 from tests.exchange_online.conftest import EXCHANGE_WS_FIXTURE_TYPE
@@ -50,7 +49,6 @@ class TestCCXTExchangeWs:
         assert res[pair_tf] is not None
         df1 = res[pair_tf]
         caplog.set_level(logging.DEBUG)
-        set_loggers(1)
         assert df1.iloc[-1]["date"] == curr_candle
 
         # Wait until the next candle (might be up to 1 minute).

tests/test_configuration.py

@@ -603,7 +603,7 @@ def test_cli_verbose_with_params(default_conf, mocker, caplog) -> None:
     patched_configuration_load_config_file(mocker, default_conf)
 
     # Prevent setting loggers
-    mocker.patch("freqtrade.loggers.set_loggers", MagicMock)
+    mocker.patch("freqtrade.loggers.logging.config.dictConfig", MagicMock)
     arglist = ["trade", "-vvv"]
     args = Arguments(arglist).get_parsed_arg()
 
@@ -614,7 +614,9 @@ def test_cli_verbose_with_params(default_conf, mocker, caplog) -> None:
     assert log_has("Verbosity set to 3", caplog)
 
 
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_logfile(default_conf, mocker, tmp_path):
+    default_conf["ft_tests_force_logging"] = True
     patched_configuration_load_config_file(mocker, default_conf)
     f = tmp_path / "test_file.log"
     assert not f.is_file()

tests/test_log_setup.py

@@ -1,4 +1,5 @@
 import logging
+import re
 import sys
 
 import pytest
@@ -7,7 +8,6 @@ from freqtrade.exceptions import OperationalException
 from freqtrade.loggers import (
     FTBufferingHandler,
     FtRichHandler,
-    set_loggers,
     setup_logging,
     setup_logging_pre,
 )
@@ -17,6 +17,7 @@ from freqtrade.loggers.set_log_levels import (
 )
 
 
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_loggers() -> None:
     # Reset Logging to Debug, otherwise this fails randomly as it's set globally
     logging.getLogger("requests").setLevel(logging.DEBUG)
@@ -27,8 +28,11 @@ def test_set_loggers() -> None:
     previous_value1 = logging.getLogger("requests").level
     previous_value2 = logging.getLogger("ccxt.base.exchange").level
     previous_value3 = logging.getLogger("telegram").level
-
-    set_loggers()
+    config = {
+        "verbosity": 1,
+        "ft_tests_force_logging": True,
+    }
+    setup_logging(config)
 
     value1 = logging.getLogger("requests").level
     assert previous_value1 is not value1
@@ -41,15 +45,17 @@ def test_set_loggers() -> None:
     value3 = logging.getLogger("telegram").level
     assert previous_value3 is not value3
     assert value3 is logging.INFO
-
-    set_loggers(verbosity=2)
+    config["verbosity"] = 2
+    setup_logging(config)
 
     assert logging.getLogger("requests").level is logging.DEBUG
     assert logging.getLogger("ccxt.base.exchange").level is logging.INFO
     assert logging.getLogger("telegram").level is logging.INFO
     assert logging.getLogger("werkzeug").level is logging.INFO
 
-    set_loggers(verbosity=3, api_verbosity="error")
+    config["verbosity"] = 3
+    config["api_server"] = {"verbosity": "error"}
+    setup_logging(config)
 
     assert logging.getLogger("requests").level is logging.DEBUG
     assert logging.getLogger("ccxt.base.exchange").level is logging.DEBUG
@@ -58,12 +64,14 @@ def test_set_loggers() -> None:
 
 
 @pytest.mark.skipif(sys.platform == "win32", reason="does not run on windows")
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_loggers_syslog():
     logger = logging.getLogger()
     orig_handlers = logger.handlers
     logger.handlers = []
 
     config = {
+        "ft_tests_force_logging": True,
         "verbosity": 2,
         "logfile": "syslog:/dev/log",
     }
@@ -82,12 +90,14 @@ def test_set_loggers_syslog():
 
 
 @pytest.mark.skipif(sys.platform == "win32", reason="does not run on windows")
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_loggers_Filehandler(tmp_path):
     logger = logging.getLogger()
     orig_handlers = logger.handlers
     logger.handlers = []
     logfile = tmp_path / "logs/ft_logfile.log"
     config = {
+        "ft_tests_force_logging": True,
         "verbosity": 2,
         "logfile": str(logfile),
     }
@@ -108,6 +118,7 @@ def test_set_loggers_Filehandler(tmp_path):
 
 
 @pytest.mark.skipif(sys.platform == "win32", reason="does not run on windows")
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_loggers_Filehandler_without_permission(tmp_path):
     logger = logging.getLogger()
     orig_handlers = logger.handlers
@@ -117,6 +128,7 @@ def test_set_loggers_Filehandler_without_permission(tmp_path):
         tmp_path.chmod(0o400)
         logfile = tmp_path / "logs/ft_logfile.log"
         config = {
+            "ft_tests_force_logging": True,
             "verbosity": 2,
             "logfile": str(logfile),
         }
@@ -131,12 +143,14 @@ def test_set_loggers_Filehandler_without_permission(tmp_path):
 
 
 @pytest.mark.skip(reason="systemd is not installed on every system, so we're not testing this.")
-def test_set_loggers_journald(mocker):
+@pytest.mark.usefixtures("keep_log_config_loggers")
+def test_set_loggers_journald():
     logger = logging.getLogger()
     orig_handlers = logger.handlers
     logger.handlers = []
 
     config = {
+        "ft_tests_force_logging": True,
         "verbosity": 2,
         "logfile": "journald",
     }
@@ -150,12 +164,14 @@ def test_set_loggers_journald(mocker):
     logger.handlers = orig_handlers
 
 
+@pytest.mark.usefixtures("keep_log_config_loggers")
 def test_set_loggers_journald_importerror(import_fails):
     logger = logging.getLogger()
     orig_handlers = logger.handlers
     logger.handlers = []
 
     config = {
+        "ft_tests_force_logging": True,
         "verbosity": 2,
         "logfile": "journald",
     }
@@ -164,6 +180,56 @@ def test_set_loggers_journald_importerror(import_fails):
     logger.handlers = orig_handlers
 
 
+@pytest.mark.usefixtures("keep_log_config_loggers")
+def test_set_loggers_json_format(capsys):
+    logger = logging.getLogger()
+    orig_handlers = logger.handlers
+    logger.handlers = []
+
+    config = {
+        "ft_tests_force_logging": True,
+        "verbosity": 2,
+        "log_config": {
+            "version": 1,
+            "formatters": {
+                "json": {
+                    "()": "freqtrade.loggers.json_formatter.JsonFormatter",
+                    "fmt_dict": {
+                        "timestamp": "asctime",
+                        "level": "levelname",
+                        "logger": "name",
+                        "message": "message",
+                    },
+                }
+            },
+            "handlers": {
+                "json": {
+                    "class": "logging.StreamHandler",
+                    "formatter": "json",
+                }
+            },
+            "root": {
+                "handlers": ["json"],
+                "level": "DEBUG",
+            },
+        },
+    }
+
+    setup_logging_pre()
+    setup_logging(config)
+    assert len(logger.handlers) == 2
+    assert [x for x in logger.handlers if type(x).__name__ == "StreamHandler"]
+    assert [x for x in logger.handlers if isinstance(x, FTBufferingHandler)]
+
+    logger.info("Test message")
+
+    captured = capsys.readouterr()
+    assert re.search(r'{"timestamp": ".*"Test message".*', captured.err)
+
+    # reset handlers to not break pytest
+    logger.handlers = orig_handlers
+
+
 def test_reduce_verbosity():
     setup_logging_pre()
     reduce_verbosity_for_bias_tester()