HDFGroup / h5pyd

h5py distributed - Python client library for HDF Rest API
Other
110 stars 39 forks source link

`logging.info` call forces downstream package loggers to emit messages twice #152

Open ppinchuk opened 11 months ago

ppinchuk commented 11 months ago

The logging.info calls added recently here https://github.com/HDFGroup/h5pyd/blob/ca1f8aeac9db5423b602da4f28169928c35f2831/h5pyd/_hl/openid.py#L14 and here https://github.com/HDFGroup/h5pyd/blob/ca1f8aeac9db5423b602da4f28169928c35f2831/h5pyd/_hl/openid.py#L23 (and perhaps others elsewhere) are invoked during the import step. This is often too early for handlers to be added to the root logger, in which case [the Python logging library calls logging.basicConfig()](https://docs.python.org/3/library/logging.html#:~:text=The%20functions%20debug()%2C%20info()%2C%20warning()%2C%20error()%20and%20critical()%20will%20call%20basicConfig()%20automatically%20if%20no%20handlers%20are%20defined%20for%20the%20root%20logger.). This adds a default StreamHandler that processes all logging messages to stderr in addition to any other handlers that the user adds later. Typically, the end result for any user that adds their own StreamHandler is that log messages are emitted twice - once to stdout and once to stderr.

This is similar to issues described here and here.

Example

This example was taken from the SO link above and modified slightly to show the problem using h5pyd.

test.py

import h5pyd
import logging

def test_a(logger):
    logger.debug("debug")
    logger.info("info")
    logger.warning("warning")
    logger.error("error")

if __name__ == "__main__":
    # Custom logger.
    logger = logging.getLogger("test")

    formatter = logging.Formatter('[%(levelname)s] %(message)s')
    handler = logging.StreamHandler()
    handler.setFormatter(formatter)

    logger.setLevel(logging.DEBUG)
    logger.addHandler(handler)

    test_a(logger)

A clean install (i.e. new conda environment + pip install h5pyd) gives the following output when running the file above:

[DEBUG] debug
DEBUG:test:debug
[INFO] info
INFO:test:info
[WARNING] warning
WARNING:test:warning
[ERROR] error
ERROR:test:error

Instead, the expected output (which can be achieved by removing the import h5pyd line above) is:

[DEBUG] debug
[INFO] info
[WARNING] warning
[ERROR] error

Interestingly, the missing import messages are not actually recorded. Not sure why that is the case.

Any support with this issue would be appreciated. Thanks!