qlib icon indicating copy to clipboard operation
qlib copied to clipboard

fix duplicate log

Open qianyun210603 opened this issue 1 year ago • 0 comments

Fix duplicated log record issue.

Description

Set parent property propagate of QlibLogger to False.

Motivation and Context

If the official python logging module is called somewhere during qlib run, after its call, the same qlib log record will get printed twice with different format, e.g. execute below code snippet

    qlib.init()
    logger = get_module_logger("mytest")
    logger.info("normal")
    logging.debug("directly call logging")
    logger.info("see duplicate")

leads to below result (note the last two lines):

[300088:MainThread](2023-10-05 09:39:03,847) INFO - qlib.Initialization - [config.py:416] - default_conf: client.
[300088:MainThread](2023-10-05 09:39:04,548) INFO - qlib.Initialization - [__init__.py:74] - qlib successfully initialized based on client settings.
[300088:MainThread](2023-10-05 09:39:04,548) INFO - qlib.Initialization - [__init__.py:76] - data_path={'__DEFAULT_FREQ': WindowsPath('G:/qlib_data/cn_data')}
[300088:MainThread](2023-10-05 09:39:04,549) INFO - qlib.mytest - [log_debug.py:8] - normal
[300088:MainThread](2023-10-05 09:39:04,549) INFO - qlib.mytest - [log_debug.py:10] - see duplicate
INFO:qlib.mytest:see duplicate

After some investigation, found that the qlib logger organised with hierarchy <qlib.log.QlibLogger qlib.mytest (INFO)>-<logging.Logger qlib (DEBUG)>-><logging.RootLogger root (WARNING)>, and the log record generated in QlibLogger is propagated to the <logging.Logger qlib (DEBUG)> to be emitted. By default it will also be propagated to the root level, but by default root level has no handler so no emission occurs. However, direct call of logging will automatically add StreamHandler to the RootLogger, thus we see logger.info("see duplicate") gets emitted twice. Therefore to fix this we need to truncate the propagation at the second level.

How Has This Been Tested?

  • [x] Pass the test by running: pytest qlib/tests/test_all_pipeline.py under upper directory of qlib.
  • [ ] If you are adding a new feature, test on your own test scripts.

Screenshots of Test Results (if appropriate):

  1. Pipeline test:
  2. Your own tests: After fix the code snippet gives:
[296660:MainThread](2023-10-05 10:08:41,651) INFO - qlib.Initialization - [config.py:416] - default_conf: client.
[296660:MainThread](2023-10-05 10:08:42,348) INFO - qlib.Initialization - [__init__.py:74] - qlib successfully initialized based on client settings.
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.Initialization - [__init__.py:76] - data_path={'__DEFAULT_FREQ': WindowsPath('G:/qlib_data/cn_data')}
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.mytest - [log_debug.py:8] - normal
[296660:MainThread](2023-10-05 10:08:42,349) INFO - qlib.mytest - [log_debug.py:10] - see duplicate

The duplicate record disappears.

Types of changes

  • [x] Fix bugs
  • [ ] Add new feature
  • [ ] Update documentation

qianyun210603 avatar Oct 05 '23 02:10 qianyun210603