Cannot set log level of `ignite.distributed` because of calls to setup_logger inside auto functions

[schuhschuh]

🐛 Bug description

The ignite.distributed auto functions such as ignite.distributed.auto_dataloader use setup_logger to get a logging.Logger instance. However, this function always sets the logging level to logging.INFO and furthermore removes ands sets up the logging handlers. Functions should not be setting up a logger object if it is already initialized such that user code can specify a different log level, handlers, or log message format string in their code (e.g., main function).

See for example:

• ignite/ignite/distributed/auto.py

  Line 67 in 6d490c8

  logger = setup_logger(__name__ + ".auto_dataloader")

• ignite/ignite/distributed/launcher.py

  Line 201 in 6d490c8

  self.logger = setup_logger(__name__ + "." + self.__class__.__name__, distributed_rank=0)

Note that in case of ignite.distributed.launcher.Parallel one can modify the self.logger instance, but this logger already prints messages right after setup_logger in its __init__ function, hence, making it impossible to adjust the log level, format, or handlers for these first messages also.

Environment

• PyTorch Version (e.g., 1.4):
• Ignite Version (e.g., 0.3.0):
• OS (e.g., Linux):
• How you installed Ignite (conda, pip, source):
• Python version:
• Any other relevant information:

[vfdev-5]

Thanks for the report @schuhschuh !
Yes, this part of code should be definitetly improved and I think @sdesrozis also proposed to do that.

@schuhschuh if you would like help us with improving the code, please feel free to discuss it here and then send a draft PR. Thanks

[sdesrozis]

We could add logger argument to functions. Or define a logger for the module distributed.

@vfdev-5 other ideas ?

[vfdev-5]

Defining a logger for the module could be nice but can be tricky as it should be adapted and re-adapted to the dist config...

[schuhschuh]

I would say you already have global logging objects for these functions anyway by the use of logging.getLogger() in setup_logger(). This is what makes it possible to adjust the logger without accessing a module level logger instance reference. Multiple calls to auto_*() functions will give you the same logger instance. The issue is just that this instance will also always reset the level, format, and handlers.

Would it work to just use a setup_logger variant (maybe a flag for this function) which instead of removing any previous handlers and setting up the logger retrieved by logging.getLogger(name) would simply check logger.hasHandlers() and just return the already set up logger object if True at this line? One could still check and remove all handlers for distributed_rank > 0. But given that these loggers have a NullHandler set by any previous call to the auto_* functions, I don't think this would be necessary. Also, by only checking hasHandlers() and making any changes to the logger object only if False, you leave the user the option to setup any desired handlers even for loggers where the distributed_rank of the process is greater than zero.

For example:

def setup_logger(
    name: Optional[str] = None,
    level: int = logging.INFO,
    stream: Optional[TextIO] = None,
    format: str = "%(asctime)s %(name)s %(levelname)s: %(message)s",
    filepath: Optional[str] = None,
    distributed_rank: Optional[int] = None,
    reset: bool = True,
) -> logging.Logger:
    logger = logging.getLogger(name)
    if logger.hasHandlers() and not reset:
        return logger
    # [...]

EDIT: It may be desirable to have the handlers always be removed and replaced by a NullHandler if distributed_rank > 0 regardless of the reset flag (to be used in auto_*() functions when calling setup_logger()), though. Because then a user can setup the handler for the named logger in the main process before any processes are spawned.

[vfdev-5]

@schuhschuh yes, I agree that we could use setup_logger for setting up and retrieving existing logger.

@sdesrozis what do you think ?

[sdesrozis]

Sorry for the lag, I missed this message !!

Just a remark. If user first calls logging.basicConfig() (or any configuration), the root logger is defined and embeds handlers. So after that, calling setup_logger() considering the suggestion of @schuhschuh should return the root logger initialized by the user... and it does not take into account the specific ignite handlers pushed in the method.

EDIT : This is the EDIT part of the last message of @schuhschuh

I'll look into it on my side.

[sdesrozis]

Another remark.

We use native logging module in Engine and TerminateOnNan and LRFinder (grep told me).

logging.basicConfig(level=logging.INFO)

engine = Engine(lambda e, b: None)
engine.run([0, 1, 2], max_epochs=2)

prints in console

INFO:ignite.engine.engine.Engine:Engine run starting with max_epochs=2.
INFO:ignite.engine.engine.Engine:Epoch[1] Complete. Time taken: 00:00:00
INFO:ignite.engine.engine.Engine:Epoch[2] Complete. Time taken: 00:00:00
INFO:ignite.engine.engine.Engine:Engine run complete. Time taken: 00:00:00

Do we want that behavior ? IMO it would be better to use setup_logger in our modules rather than native logging as we have specific handlers for distributed mode. However, default level of setup_logger is logging.INFO. We would be better to have logger configured using logging.ERROR for internal.

What do you think ?

[schuhschuh]

@sdesrozis Actually, setup_logger is using the native logging module. You are not actually retrieving the root logger, because getLogger is called with the module name as argument.The question should only be whether you are able to tell if the specific logger that you obtain, which is not a reference to the root logger, has had handlers set? I would think/hope so.

[sdesrozis]

I agree that we always use native logging. I was talking about configuration, sorry it was not understandable.

If you call setup_logger() without argument, you get the root logger. I think that is a point to have in mind. logging.basicConfig(...) should not conflict with our way to setup loggers. If a logger is setup with a specific name, I assume that it won't conflict. Finally I suppose it could help if setup_logger() returns a logger that differs from root.

What I said may be beside the point of the issue. I understand that multiple calls reset handlers and level. The suggested solution aims to configure once each logger. (Loggers must not have handlers attached, take care of root).

I will have a look on my own.