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

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

Open
ppinchuk opened this issue Aug 3, 2023 · 0 comments
Assignees

Comments

@ppinchuk
Copy link

ppinchuk commented Aug 3, 2023

The logging.info calls added recently here

logging.info("Unable to import azure auth packages")

and here
logging.info("Unable to import google auth packages")

(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(). 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!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants
@jreadey @ppinchuk and others