Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix duplicate log #1661

Merged
merged 7 commits into from
Dec 9, 2024
Merged

fix duplicate log #1661

merged 7 commits into from
Dec 9, 2024

Conversation

qianyun210603
Copy link
Contributor

@qianyun210603 qianyun210603 commented Oct 5, 2023

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?

  • 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

  • Fix bugs
  • Add new feature
  • Update documentation

@github-actions github-actions bot added the waiting for triage Cannot auto-triage, wait for triage. label Oct 5, 2023
@@ -69,6 +69,8 @@ def learn(self, batch):

def test_simple_env_logger(caplog):
set_log_with_config(C.logging_config)
C.logging_config["loggers"]["qlib"]["propagate"] = True
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

comment

@SunsetWolf SunsetWolf merged commit 431f574 into microsoft:main Dec 9, 2024
26 checks passed
@SunsetWolf
Copy link
Collaborator

Thank you for contributing the code. It's now merged.

@SunsetWolf SunsetWolf added bug Something isn't working and removed waiting for triage Cannot auto-triage, wait for triage. labels Dec 23, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants