Logging etiquette

[coroa]

The current default logging behaviour by pyam is rude, if you actually want to configure logging.

Usually, one can expect a zen-like experience by just invoking

import logging
logging.basicConfig(level="ERROR")

But pyam's initialization in

pyam/pyam/__init__.py

Line 14 in f071e79

logger.addHandler(logging.NullHandler())

and

pyam/pyam/__init__.py

Lines 21 to 26 in f071e79

	logger.setLevel(logging.INFO)
	stderr_info_handler = logging.StreamHandler()
	formatter = logging.Formatter('%(name)s - %(levelname)s: %(message)s')
	stderr_info_handler.setFormatter(formatter)
	logger.addHandler(stderr_info_handler)

does not respect these settings.

With those, one has to additionally issue

pyam.logger.setLevel(level="ERROR")

Annoyingly,

logging.getLogger().setLevel("ERROR")

will still show INFO messages coming from pyam, since they are already written out into stderr by the pyam logger.

That's why the Configuring logging for a library section in the logging tutorial has this note:

It is strongly advised that you do not add any handlers other than NullHandler to your library’s loggers.

I see two alternatives for improvement:

Best practice

Move the initialization into a separate routine setup_logger and tell everyone to use

import pyam
pyam.setup_logging()

(setup_logging should take keyword arguments like level)

If they forget about it, it's not that problematic either as long as we get in tandem rid of the NullHandler, because since python 3.2 the default behaviour of the logging library for a LogRecord which bubbles through the logging tree without encountering a Handler is to send the message to stderr, if it is at least a warning (without timestamp and loglevel), as described in What happens if no configuration is provided.

Looks like so:

Least change (but still slightly rude)

Get the root logger in __init__.py and check whether the user has set up any handlers before, as like:

rootLogger = logging.getLogger()
if not rootLogger.hasHandlers():
    # add handlers to rootLogger

That way, the user experience for the average pyam user is unchanged, but one can configure logging, by using

logging.basicConfig(level="ERROR")

as long as one does it before import pyam.

And it is possible to make it shut up with

logging.getLogger().setLevel("ERROR")

even after the import is through.

Thoughts? @danielhuppmann @gidden @znicholls .
I do strongly favor the Best practice option but would prepare a PR for either!

[znicholls]

I do strongly favour the Best practice option

+1 from me, I find the current behaviour a) fiddly to deal with (as @coroa has beautifully outlined) and b) it encourages users to not learn about logging (yes logging hurts, but encouraging people to learn about it is probably a good thing)

Move the initialization into a separate routine setup_logger and tell everyone to use

I think this is a great workaround for those who really don't want to think about loggings.

[coroa]

Ok, one more option, which could be a transitionary one: If we are in a notebook, we add a JITConfigPseudoHandler to the pyam logger, which sets up logging when the first message should be shown, if the rootLogger has no handlers yet and then unregisters.

class JITConfigPseudoHandler(logging.Handler):
    def __init__(self, remove_from_logger=None, **config_kwargs):
        self.remove_from_logger = remove_from_logger
        self.config_kwargs = config_kwargs
        super().__init__()

    def emit(self, record):
        if self.remove_from_logger is not None:
            self.remove_from_logger.removeHandler(self)

        rootLogger = logging.getLogger()
        if not rootLogger.hasHandlers():
            logging.basicConfig(**self.config_kwargs)

            logger.warning("Running logging.basicConfig for you, since you did not set up logging")

if <running_in_notebook>:
    logger.addHandler(JITConfigPseudoHandler(logger, level="INFO", format='%(name)s - %(levelname)s: %(message)s'))

Untested, but should work. Unsure whether the first record would have to be re-injected manually or would be shown correctly.

[danielhuppmann]

Thanks @coroa & @znicholls for trying to make pyam more in line with best-practice python! I just looked at #294 and #288, where @znicholls refactored the logging implementation - but I have to admit that logging is still a bit of a mystery for me...

Anyway, two comments:

Less sophisticated solutions

My experience with pyam development (and similar projects) has taught me some hesitancy to go for sophisticated solutions - because this makes maintenance really difficult when that one person is not available. An example is the unit-conversion-module - brilliant implementation, but only @khaeru can realistically make changes, so #442 depends on one person with limited time and a small stake in pyam.

So I'm not sure if we even (still?) need to set up the logging and handlers in __init__.py at all, as long as the "right" messages bubble up in some way... (which seems to be the case based on my trials).

Make it easy for non-experts

Our user base largely consists of users with only basic python knowledge (that's the people who can benefit most from it), and I tried to write all tutorials in a way that they are helpful if this is the first time a user sees python code and can be a useful starting point for their own work.

So statements like "encouraging people to learn logging" and "tell everyone to use ..." are really talking past our user base - hardly anyone ever reads the docs when something doesn't work as expected...

Requirements

From my point of view, the only two requirements are that

1. log messages don't get lost, which was a concern the last time @znicholls worked on logging, and see Use warnings module for deprecation warning #444 (comment)
2. that the log-level for pyam is set to INFO by default (i.e., unless the user has done something to change logging behavior), because a lot of functions write info-messages that are helpful for non-expert users.

[znicholls]

I completely understand the comments and desire to make things easy. My suggestion would be that we try simply removing the null handler and logging initialisation as it currently exists and see what happens (@coroa nicely points out that things should still bubble up if we do this so we won't lose any messages). That should cover requirement 1. Reading https://docs.python.org/3/howto/logging.html#what-happens-if-no-configuration-is-provided, I am concerned it will not hold for requirement 2 (and my quick experiment suggests requirement 2 doesn't work if we simply remove all the logging config).

If requirement 2 is really important, I think we have a problem. In short, the requirements specified are what @coroa describes as 'rude'. I agree with this assessment. We cannot have a library which automatically sets up its own logging without it being annoying for anyone who wants to set up their logging in the standard ways. Further, having a library which sets up its own default logging level is in direct conflict with a library which isn't rude. (I think the note here https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library is important to respect.)

I think @coroa's suggestion of a pyam.setup_logging() function is best. We add it to tutorials etc. and make it sufficiently simple so maintenance isn't a complete headache (or add sufficient documentation to its docstring that anyone who wants to learn what is going on can). If we really don't want to add such a function, then we can leave pyam being rude. It just pushes the issue onto (admittedly expert logging) users and makes it very clear that we're not following best practice.

[danielhuppmann]

Playing a bit around and trying learn about logging - I think the following would be a simple solution without being too rude.

# this is ignored if logging is already configured
logging.basicConfig(format='%(name)s - %(levelname)s: %(message)s')

logger = logging.getLogger(__name__)

# if logger is at default level WARNING, set to INFO
if logger.getEffectiveLevel() == 30:
    logger.setLevel(20)
    logger.info(f'Setting `{__name__}` logging level to `logging.INFO`')

This approach respects any previous logging setup and does not make pyam loud if logging has been configured to a less verbose setting earlier.

Checking for rootLogger.hasHandlers() (suggested above by @coroa) seems to be too coarse - even the current rude pyam implementation doesn't add handlers to the root logger...

[coroa]

Checking for rootLogger.hasHandlers() (suggested above by @coroa) seems to be too coarse - even the current rude pyam implementation doesn't add handlers to the root logger...

I don't agree with too coarse.

logging.basicConfig does exactly that:

def basicConfig(**kwargs):
        [...]
        if len(root.handlers) == 0:
            handlers = kwargs.pop("handlers", None)
            [...]

[znicholls]

this is ignored if logging is already configured

In my opinion this is worse as it requires people to setup their logging before they import pyam. It would be a nightmare working out where basicConfig is being called in a stack that had pyam as a dependency.

if logger is at default level WARNING, set to INFO

If a user tried to set the level as warning then this would update it to INFO (also annoying in my opinion).

[gidden]

Hi folks, thought it could be useful to chime in here. First, love the discussion =)

I think it's important to highlight that there are largely three 'user types' for pyam:

1. analysis users (work entirely in notebook environments, coming to pyam from the IPCC notebooks among other places)
2. power users (using pyam in scripting environments)
3. developers (us, actively updating pyam code)

Notebooks are a first-class environment for pyam where we want to support fairly verbose logging statements to help guide these users, hence the original (rude) design of high-jacking the logging.

However, it is fundamentally important to also provide first-class support for the other two user categories, and @coroa has provided a nice example of where we have failed to do so.

Therefore, I would support a solution that raises our log level sufficiently if in a notebook environment, which I think @coroa has also provided. What do others think?

[znicholls]

What do others think?

Sounds good to me, as long as @danielhuppmann is now happy with @coroa's slightly more complicated than present solution

[danielhuppmann]

I agree with @gidden on the principles, but not quite sure which of the options by @coroa is the one you are talking about...

[gidden]

I agree with @gidden on the principles, but not quite sure which of the options by @coroa is the one you are talking about...

@coroa's suggestion here would provide a hook that tests which environment the logger is in (notebook or not), and maintain current behavior if in a notebook. If I have understood it correctly =)

@coroa - could you comment on whether we need a specific handler class as you suggest above or whether we could implement the logging functionality as-is but after checking the environment?

[coroa]

Ok, then to sum everything up, I see now two options:

1a. KISS

if <running_in_notebook>:
    logging.basicConfig(level="INFO", format="....")

• Will not do anything, if not in notebook
• Will not do anything, if user has configured logging before importing pyam
• Will give INFO logging messages about pyam and anything else to notebook users (for the unaware user)
• Will shut up with logging.getLogger().setLevel('ERROR')
• Simple
• But: Will depend on import order

2a. With Handler from #449 (comment)

Basically same solution as above, but defers running logging.basicConfig to when the first log message is generated.

class JITConfigPseudoHandler(Handler):
    [...]

if <running_in_notebook>:
    logger.addHandler(JITConfigPseudoHandler(logger, level="INFO", format="...")))

• Will not do anything, if not in notebook
• Will not do anything, if user configures logging before pyam wants to display the first log message
• Will give INFO logging messages about pyam and anything else to notebook users (for the unaware user)
• Will shut up with logging.getLogger().setLevel('ERROR')
• Hard to maintain? logging library very stable, no change to be expected

Variant b: only affect loglevel of pyam

If you think, setting the global loglevel to INFO is too intrusive, I'd suggest to replace logging.basicConfig in either 1a or 2a with

if not logger.root.hasHandlers():
    logging.basicConfig(format="...")
    logger.setLevel("INFO")

I prefer to not touch the per-package loglevels, ie. leave them at logging.NOTSET, so that they inherit the loglevel transparently from the root logger, so that i can steer the logging amount by just adjusting the root loggers loglevel. ie. if I do logging.getLogger().setLevel("ERROR"), then pyam will still print its INFO messages, which I don't like as a behaviour. But that might be just my personal opinion.

My choice

Would be the slightly more sophisticated deferred running of logging.basicConfig, ie. option 2a.

[znicholls]

Awesome summary thanks @coroa. I’d prefer 2a. As you say, super stable API with at least a few of us now who have looked at logging so maintenance should be fine.

[danielhuppmann]

Thanks a lot, I agree that 2a seems like a really nice solution and striking a great balance between our different user groups!