You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
ENH: Switch from verbose to logging for warnings and logging #9302
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....
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)...
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.
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).
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.
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.
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:
ifnotnp.isfinite(posx) ornotnp.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:
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.
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.
@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.
... 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.
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?
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).
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.
Activity
jklymak commentedon Oct 7, 2017
verboseonly appears 144 times in the code base so making this change shouldn't be too hard.verbosejust be written usingloggeror shouldloggerreplaceverbose--verbose-debugetc?tacaswell commentedon Oct 7, 2017
I would go with
verbosejklymak commentedon Oct 7, 2017
Well I can take a crack at that.
verboseis 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:
The other logging options are WARNING, ERROR, CRITICAL, which don't seem to line up w/ the
verboseoptions.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 commentedon Oct 7, 2017
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 commentedon Oct 7, 2017
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.
verboseis 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 commentedon Oct 7, 2017
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 commentedon Oct 7, 2017
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 commentedon Oct 7, 2017
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 commentedon Oct 7, 2017
Not quite sure I follow.
loggingdoesn'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.verbosehad more levels at the DEBUG and INFO levels thanlogging, not fewer. i.e. it haddebuganddebug-annoying, andhelpfulandsilent, 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
loggingoptions in their top-level program.Just as a taste for how I'd propose this works, consider the
text.pyexample that started this. The "warning" would now be:The
__name__will make this logger have the hierarchical namematplotlib.text, as would any other calls to the logger from thetextmodule.WARNING and above are emitted by default by
logging. If the user wants to suppress warnings frommatplotlib:If they just want to suppress the warning in
text:jklymak commentedon Oct 7, 2017
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. beforeimport 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 commentedon Oct 7, 2017
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
getLoggerevery time you want to use it.jklymak commentedon Oct 7, 2017
@tacaswell Right now
verbosedumps out a bunch of useful things in__init__at thehelpfulordebuglevel. If we go tologgingthen you need to set the logging level toINFOorDEBUGif 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-helpfuletc and then have a top-level method that parsedarghand set thelogginglevel appropriately if its not already set to a more verbose level by the mpl logger (i.e. the user did it in code before thematplotlib.__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
verboseis pretty sparse, and didn't seem to be in places whereloggingwould be a big resource drain. However, if someone wanted to have a whole bunch oflog.debug('Boo')messages, it would make sense to store the logger. Right now, what I've done is get the logger for every function sologging.getLoggeronly is called once a function call. The scuttlebutt on the internet is thatloggingis a pretty lightweight module.jklymak commentedon Oct 7, 2017
... 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 afterloggingis set up by the user.anntzer commentedon Oct 7, 2017
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
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 commentedon Oct 7, 2017
Right now
verbosesets its level inVerbose.__init__by parsingsys.argv[1:], so before any logging takes place.The problem as I see it, is not when in
__init__thatloggingis called, but that it is required in__init__at all. The issue is this:won't return any of the information above because
matplotlib.__init__is called before thematplotliblogger is set tologging.DEBUG(andloggingdefaults to reportinglogging.WARNINGand above).Its not a huge deal to import and set before:
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 thercParams).This is apart from allowing a command-line interface.
anntzer commentedon Oct 7, 2017
I think having to set it before is totally fine for now.
jklymak commentedon Nov 25, 2017
Closed by #9313