ENH: Switch from verbose to logging for warnings and logging

[jklymak]

Enhancement suggestion

It was brought up that the matplotlib verbose class (in __init__.py) could be perhaps replaced by logger.

[jklymak]

verbose only appears 144 times in the code base so making this change shouldn't be too hard.

1. should verbose just be written using logger or should logger replace verbose
2. how should command-line arguments be handled? i.e. --verbose-debug etc?

[tacaswell]

I would go with

1. just replace verbose
2. by setting the logger state to an equivalent and deprecating them

[jklymak]

Well I can take a crack at that. verbose is mostly used in highly technical parts of the code, i.e. not too likely to change, so it should be tractable in a few evenings.

Would we map:

• 'silent', 'helpful' -> INFO
• 'debug', 'debug-annoying' -> DEBUG

The other logging options are WARNING, ERROR, CRITICAL, which don't seem to line up w/ the verbose options.

There is a little chart at the top of https://docs.python.org/3/howto/logging.html that says what they think the different options are for. Seems that logging.error and logging.critical are for non-killing errors. logging.warning is if there is nothing the client can do about the warning....

[anntzer]

I had a look at this some time ago, IIRC the main difficulty was not so much replacing the calls to verbose, but reproducing the config.
WARNING level would be fine for e.g. the nonfinite text handling (because it's (it'll be...) easier to suppress).
There are some technicalities as to whether to add a log handler or not (see e.g. ipython/ipython#2917, Theano/Theano#1815).

Also, I would like to look into dropping the --verbose-foo flags, because they are essentially useless when mpl is used in a larger app which may be doing its own command line parsing (basically cf #3710). On the other hand I would have preferred not introducing $MPLVERBOSITY, as my ultimate plan was to merge everything into a single environment variable (#6884). I guess in the meantime I'd rather keep --verbose-foo and deprecate them if and when I get to introduce $MPLRC, rather than having to go through two rounds of deprecation (via $MPLVERBOSITY)...

[jklymak]

My quick read of this subject was that the consensus you should not add a log handler.

I think but am not sure, that the command line options could be handled by indeed setting a handler in a callable method and sending logging to stdout or stderr along with a deprecation warning. This approach also means users could do something like matplotlib.mpllogging(‘DEBUG’) in a script and logging would magically work without them knowing anything about logging. Of course we should provide a simple recipe to use logging properly as well.

Unless I’m missing something. verbose is really not used in that many places. I’m actually not too worried about mucking with it. Was it ever really that useful to get the verbose messages for debugging purposes? Maybe I’m not searching the codebase properly. I hope that’s switch to using logging will get more developers to use logging, and hence we could get more thorough info and debugging.

[anntzer]

Adding a handler conditional on the command line option (or whatever we cook up to replace it) and rcParams["verbose.level"] (or really, validate_verbose) sounds fine to me.
I think we may actually want to set a fairly loose default on verbosity (i.e. on an unconfigured system, do install a handler and print the warnings out), as that's what's going to be most helpful to many users.
Keeping the rcparam as the configurable point allows file-based config, which should be documented and will avoid making advanced users cringe at the need to suppress log messages from each individual module (just suppress them in the matplotlibrc).

[jklymak]

Logging allows hierarchical levels of messages, so I hope advanced users aren’t too worried about that. I.e. you could set the matplotlib logger to WARNING so all modules default to WARNING, but the matplotlib.text logger to DEBUG and the matplotlib.tight_layout logger to INFO.

[anntzer]

The problem is that here you are sort of selecting the default level of logging from a module based on the message that you plan to emit, which is all very nice until another dev wants to add another message at another severity. It also makes things complicated to explain to intermediate users. I would prefer just sticking to one default level... advanced users can of course set up whatever logging severity hierarchy they want.

[jklymak]

Not quite sure I follow. logging doesn't have a default level. The library/module writer chooses from: DEBUG, INFO, WARNING, ERROR, CRITICAL. The module writer is not supposed to choose what gets emitted, the user of the library chooses what levels to emit.

verbose had more levels at the DEBUG and INFO levels than logging, not fewer. i.e. it had debug and debug-annoying, and helpful and silent, though I can't see the latter is ever used.

Are you concerned about module writers not knowing what level to set a message at? I guess I'd hope the review process would help police that.

As for matplotlib setting what gets emitted, I'd agree that we only do that from the command line or if the correct rcParams are set, and that we deprecate those parameters in favour of top-level users simply turning on the correct logging options in their top-level program.

Just as a taste for how I'd propose this works, consider the text.py example that started this. The "warning" would now be:

    if not np.isfinite(posx) or not np.isfinite(posy):
                log = logging.getLogger(__name__)
                log.warning("posx and posy should be finite values not rendering text")
                return

The __name__ will make this logger have the hierarchical name matplotlib.text, as would any other calls to the logger from the text module.

WARNING and above are emitted by default by logging. If the user wants to suppress warnings from matplotlib:

logger = logging.getLogger('matplotlib')
logger.setLevel(logging.ERROR)

If they just want to suppress the warning in text:

logger = logging.getLogger('matplotlib.text')
logger.setLevel(logging.ERROR)

[jklymak]

So I've mostly got this done. The only gotcha is that the user needs to set logging parameters before matplotlib.__init__ is called (i.e. before import matplotlib) in order for the more verbose output to show up (without setting the debug level via the command-line/rcParams check). I think thats probably OK, but a bit of a nuisance.

[tacaswell]

Could we provide a helper function in the top-level namespace to tune the settings on the top-level mpl logger? It is not obvious to me why those have to be set before matplotlib.__init__.

Another pattern I have seen is to get the logger as a module-level variable so you don't have to call getLogger every time you want to use it.

[jklymak]

@tacaswell Right now verbose dumps out a bunch of useful things in __init__ at the helpful or debug level. If we go to logging then you need to set the logging level to INFO or DEBUG if you want those to show up. That level setting needs to be done before __init__ is called for the __init__ info to be dumped.

I was planning to accept --verbose-helpful etc and then have a top-level method that parsed argh and set the logging level appropriately if its not already set to a more verbose level by the mpl logger (i.e. the user did it in code before the matplotlib.__init__). If I'm smart I'll also make use of the existing file options. Whether we deprecate all this is a matter of taste, but it seems having a command-line/rcParam route to higher logging verbosity (for matplotlib only) is a reasonable thing to do.

WRT module-level variable to store the logger in, I think that can be on a case-by-case basis. The current use of verbose is pretty sparse, and didn't seem to be in places where logging would be a big resource drain. However, if someone wanted to have a whole bunch of log.debug('Boo') messages, it would make sense to store the logger. Right now, what I've done is get the logger for every function so logging.getLogger only is called once a function call. The scuttlebutt on the internet is that logging is a pretty lightweight module.

[jklymak]

... though I guess another way to get the useful information in matplotlib.__init__ is to log it when a figure is created. I don't think there is much you can do w/ mpl until a figure is created. And that would typically happen after logging is set up by the user.

[anntzer]

The problem of the command-line argument is that it conflicts with the fairly common case where mpl is part of another program which does its own CLI parsing, now that other program ends up having to pass through all unknown flags (or hard-code mpl's behavior). In any case changing that behavior can wait and is fairly independent of the change proposed here.

Running a simple script with --verbose-debug shows that the first logged lines are

$HOME=/home/antony
matplotlib data path /home/antony/src/extern/matplotlib/lib/matplotlib/mpl-data
loaded rc file /home/antony/.config/matplotlib/matplotlibrc
matplotlib version 2.1.0rc1.post129+g726af766d

which suggests that as early as the third line, the rc verbose level is known. I think we can get rid of $HOME, and move the second line log later; then nothing will be logged before the desired log level is known?

[jklymak]

Right now verbose sets its level in Verbose.__init__ by parsing sys.argv[1:], so before any logging takes place.

The problem as I see it, is not when in __init__ that logging is called, but that it is required in __init__ at all. The issue is this:

import logging
import matplotlib

logger = logging.getLogger('matplotlib')
logger.setLevel(logging.DEBUG)

won't return any of the information above because matplotlib.__init__ is called before the matplotlib logger is set to logging.DEBUG (and logging defaults to reporting logging.WARNING and above).

Its not a huge deal to import and set before:

import logging
logger = logging.getLogger('matplotlib')
logger.setLevel(logging.DEBUG)
import matplotlib

but its a bit awkward. It would be kind of nice to not have to set the logging until the main body of the user's program. OTOH, there is probably some steps being taken in matplotlib.__init__ that would benefit from logging (i.e. reading the rcParams).

This is apart from allowing a command-line interface.

[anntzer]

I think having to set it before is totally fine for now.

[jklymak]

Closed by #9313