Fix logging_level: make logging level specified in qlib.init applies to all loggers (#1368)

* fix logging_level: make logging level specified in qlib.init apply to all loggers

* downgrade loglevel in expmanager __init__ to debug (it will be called in each process in multiprocessing operations such as read data)

* correct gramma error

* fix black lint

* use functor to cache loggers and set level

* correct black lint

* correct pylint

* correct pylint

docs/developer/code_standard_and_dev_guide.rst

@@ -16,7 +16,7 @@ When you submit a PR request, you can check whether your code passes the CI test
 
 1. Qlib will check the code format with black. The PR will raise error if your code does not align to the standard of Qlib(e.g. a common error is the mixed use of space and tab).
 
-   You can fix the bug by inputing the following code in the command line.
+   You can fix the bug by inputting the following code in the command line.
 
 .. code-block:: bash
 

qlib/__init__.py

@@ -10,7 +10,7 @@ import yaml
 import logging
 import platform
 import subprocess
-from .log import get_module_logger
+from .log import get_module_logger, set_global_logger_level
 
 
 # init qlib
@@ -34,8 +34,7 @@ def init(default_conf="client", **kwargs):
     from .config import C  # pylint: disable=C0415
     from .data.cache import H  # pylint: disable=C0415
 
-    # FIXME: this logger ignored the level in config
-    logger = get_module_logger("Initialization", level=logging.INFO)
+    logger = get_module_logger("Initialization")
 
     skip_if_reg = kwargs.pop("skip_if_reg", False)
     if skip_if_reg and C.registered:
@@ -48,6 +47,7 @@ def init(default_conf="client", **kwargs):
     if clear_mem_cache:
         H.clear()
     C.set(default_conf, **kwargs)
+    get_module_logger.setLevel(C.logging_level)
 
     # mount nfs
     for _freq, provider_uri in C.provider_uri.items():

qlib/config.py

@@ -411,8 +411,7 @@ class QlibConfig(Config):
         if _logging_config:
             set_log_with_config(_logging_config)
 
-        # FIXME: this logger ignored the level in config
-        logger = get_module_logger("Initialization", level=logging.INFO)
+        logger = get_module_logger("Initialization", kwargs.get("logging_level", self.logging_level))
         logger.info(f"default_conf: {default_conf}.")
 
         self.set_mode(default_conf)

qlib/log.py

@@ -48,33 +48,44 @@ class QlibLogger(metaclass=MetaLogger):
         return self.logger.__getattribute__(name)
 
 
-def get_module_logger(module_name, level: Optional[int] = None) -> QlibLogger:
-    """
-    Get a logger for a specific module.
+class _QLibLoggerManager:
+    def __init__(self):
+        self._loggers = {}
 
-    :param module_name: str
-        Logic module name.
-    :param level: int
-    :return: Logger
-        Logger object.
-    """
-    if level is None:
-        level = C.logging_level
+    def setLevel(self, level):
+        for logger in self._loggers.values():
+            logger.setLevel(level)
 
-    if not module_name.startswith("qlib."):
-        # Add a prefix of qlib. when the requested ``module_name`` doesn't start with ``qlib.``.
-        # If the module_name is already qlib.xxx, we do not format here. Otherwise, it will become qlib.qlib.xxx.
-        module_name = "qlib.{}".format(module_name)
+    def __call__(self, module_name, level: Optional[int] = None) -> QlibLogger:
+        """
+        Get a logger for a specific module.
 
-    # Get logger.
-    module_logger = QlibLogger(module_name)
-    module_logger.setLevel(level)
-    return module_logger
+        :param module_name: str
+            Logic module name.
+        :param level: int
+        :return: Logger
+            Logger object.
+        """
+        if level is None:
+            level = C.logging_level
+
+        if not module_name.startswith("qlib."):
+            # Add a prefix of qlib. when the requested ``module_name`` doesn't start with ``qlib.``.
+            # If the module_name is already qlib.xxx, we do not format here. Otherwise, it will become qlib.qlib.xxx.
+            module_name = "qlib.{}".format(module_name)
+
+        # Get logger.
+        module_logger = self._loggers.setdefault(module_name, QlibLogger(module_name))
+        module_logger.setLevel(level)
+        return module_logger
+
+
+get_module_logger = _QLibLoggerManager()
 
 
 class TimeInspector:
 
-    timer_logger = get_module_logger("timer", level=logging.INFO)
+    timer_logger = get_module_logger("timer")
 
     time_marks = []
 

qlib/workflow/exp.py

@@ -4,13 +4,12 @@
 from typing import Dict, List, Union
 from qlib.typehint import Literal
 import mlflow
-import logging
 from mlflow.entities import ViewType
 from mlflow.exceptions import MlflowException
 from .recorder import Recorder, MLflowRecorder
 from ..log import get_module_logger
 
-logger = get_module_logger("workflow", logging.INFO)
+logger = get_module_logger("workflow")
 
 
 class Experiment:
@@ -22,7 +21,7 @@ class Experiment:
     def __init__(self, id, name):
         self.id = id
         self.name = name
-        self.active_recorder = None  # only one recorder can running each time
+        self.active_recorder = None  # only one recorder can run each time
         self._default_rec_name = "abstract_recorder"
 
     def __repr__(self):
@@ -232,7 +231,7 @@ class Experiment:
 
         Returns
         -------
-        The return type depent on `rtype`
+        The return type depends on `rtype`
             if `rtype` == "dict":
                 A dictionary (id -> recorder) of recorder information that being stored.
             elif `rtype` == "list":
@@ -354,7 +353,7 @@ class MLflowExperiment(Experiment):
         Parameters
         ----------
         max_results : int
-            the number limitation of the results
+            the number limitation of the results'
         status : str
             the criteria based on status to filter results.
             `None` indicates no filtering.

qlib/workflow/expm.py

@@ -37,7 +37,7 @@ class ExpManager:
         self._active_exp_uri = None  # No active experiments. So it is set to None
         self._default_exp_name = default_exp_name
         self.active_experiment = None  # only one experiment can be active each time
-        logger.info(f"experiment manager uri is at {self.uri}")
+        logger.debug(f"experiment manager uri is at {self.uri}")
 
     def __repr__(self):
         return "{name}(uri={uri})".format(name=self.__class__.__name__, uri=self.uri)

qlib/workflow/recorder.py

@@ -5,7 +5,6 @@ import os
 import sys
 from typing import Optional
 import mlflow
-import logging
 import shutil
 import pickle
 import tempfile
@@ -20,7 +19,7 @@ from qlib.utils.paral import AsyncCaller
 from ..log import TimeInspector, get_module_logger
 from mlflow.store.artifact.azure_blob_artifact_repo import AzureBlobArtifactRepository
 
-logger = get_module_logger("workflow", logging.INFO)
+logger = get_module_logger("workflow")
 # mlflow limits the length of log_param to 500, but this caused errors when using qrun, so we extended the mlflow limit.
 mlflow.utils.validation.MAX_PARAM_VAL_LENGTH = 1000