Repository navigation
Use of logging in matplotlib #13264
Description
I think the use of logging in matplotlib is not right.
Unfortunately the official logging documentation is not quite comprehensive. I'll try to explain in the following how I understand that logging should be used.
TLDR: I propose to just remove matplotlib._set_logger_verbose_level() and all logging issues are gone. - Maybe add a bit of documentation how to use logging, but that's really not matplotlib specific.
How logging should be used in simple cases
In the minimal case, libraries do only define a logger and call the respective info(), error() etc. functions on that logger.
_log = logging.getLogger(__name__)
In this case, the library does not care about handling at all. IMO this is generally good practice as the library will issue messages, but it will not care which will be delivered or where they will go to (stdout, file, ...). That's the task of the code using the library:
-
if the programmer does not care about logging at all, logging.lastResort is used, which is a StreamHandler to stderr. This makes sure the messages go somewhere even without configuration (note: this was introduced in 3.2).
-
if the programmer wants to control the logging, the simple way is logging.basicConfig(). This is sufficent to redirect output to files, set the global log level etc.
How matplotlib uses logging
Former times
There has been some argument parsing magic, so that passing --verbose to a script using matplotlib could be used to control matplotlib's logging. This has been removed because it's too magical and can badly interfere with the argument handling of a script.
Now
Currently, there is only matplotlib._set_logger_verbose_level().
If unused (default) the processes work as described above for loggging in simple cases.
The function binds a new StreamHandler (named console in the code) to _log and controls the level of the handler. This works ok for the case when the matplotlib-using programmer does not configure any logging himself: The messages are sent to console. logging.lastResort is not used. However, if logging basicConfig() is used, we have two handlers: console plus the one from the config, as can be seen when running
import matplotlib
import logging
logging.basicConfig()
matplotlib._set_logger_verbose_level('helpful')
matplotlib._log.info('test')
This outputs the message twice
test
INFO:matplotlib:test
luckily _set_logger_verbose_level() is private and should not be used currently.
Future
The proposal in #13129 is making _set_logger_verbose_level() indirectly public through some convenience functions. IMHO this is the wrong way to go as described above.
What we should do is just remove _set_logger_verbose_level(). It's standard use casescan be handled using logging.basicConfig(). e.g.
- redirecting to file: `logging.basicConfig(filename='errors.log')
- setting the level: `logging.basicConfig(level='debug')
logging.basicConfig() is actually more general, e.g.
- specifying the output format
- choosing between append and overwrite for a file.
- using another handler
- etc.
There's one special case that we do not cover: Logging matplotlibs output somewhere else that other logging output. That was possible / the case for _set_logger_verbose_level(). Not sure if it was by design or just accidentially. If a user really needs that, he has to attach a handler to the matplotlib logger (but also maybe set _log.propagate = False. We could add a convenience function for this, but IMHO this is rather an advance usage and it should be sufficient to make the matplotlib logger accessible.
Activity
NelleV commentedon Jan 22, 2019
Too bad we can't leave a reaction to a subset of the text. "Unfortunately the official logging documentation is not quite comprehensive" made me laugh 🤣
jklymak commentedon Jan 22, 2019
The new convenience function in #13129 is meant for people who do not want to import the logging module or even know anything about it. i.e. a user on stackoverfow says I’m having a mysterious problem and we tell them to do
plt.debug()or whatever we decide to call it in the end. The point being we don’t have to make themimport loggingand set the logging level. Sure it’s only two lines, but its actually pretty verbose...If someone is actually using
loggingproperly, then they should not call this function and everything will work just fine.NelleV commentedon Jan 22, 2019
I think I agree with @jklymak on that one.
WeatherGod commentedon Jan 22, 2019
timhoffm commentedon Jan 22, 2019
but
plt.debug()will badly interact withlogging.basicConfig(). Certainly there are users who will use it (without us telling them) and running into problems.If we really need a convenience function (not convinced we do need it), we should base it on
basicConfig()e.g.also you coud do
plt.logging.basicConfig(level='debug')- no need to import logging 😝 .anntzer commentedon Jan 22, 2019
logging.basicConfig() won't work because it attaches a handler to the root logger, whereas we want to attach it to the matplotlib logger (so that plt.debug() doesn't spew out e.g. pandas' logs).
Moreover the use case proposed e.g. in #13129 (comment) clearly wants two have two handlers after plt.debug() is called -- one to the "centralized system" and one to the end user's terminal.
I think the intersection of people using plt.debug() and also configuring logging themselves is quite small (the intended use cases don't really overlap -- I think that's also @jklymak's point above), but even then, if they're really bothered by the duplication, they can set the
.propagateattribute on the matplotlib logger to False and then the handler installed by basicConfig() won't see the matplotlib logs anymore (frankly I would not even bother documenting this until someone complains).jklymak commentedon Jan 22, 2019
Further, if someone has
logging.basicConfig()already turned on, its hard to see why they would callplt.debug/set_loglevel()since they are already getting all the log messages...But more to the point "badly interact" just means twice as many logging messages, which shouldn't be too big a deal.
To me the bigger weakness of #13129 is that a lot of debug messages are missed from
import matplotlib.timhoffm commentedon Jan 22, 2019
IMO it's not our task as a library to care about handlers:
https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library
plt.debug()is at least only doing this on request, but still I don't think it's the right approach.anntzer commentedon Jan 23, 2019
I think a user calling
plt.debug()falls under "the application developer who uses your library". We're not doing that for them, just giving them an easy way to do it.jklymak commentedon Jan 23, 2019
pyplotis an end-user interface into the library. The library itself follows the strictures given above.timhoffm commentedon Jan 23, 2019
I'm not fundamentally opposed to a
plt.debug()functionality (though I don't advocate it). However it should be the right scope.If it's for inexperienced users, who cannot setup logging themselves, it should really be just a wrapper for
logging.basicConfig(). Having multiple handlers is really an advanced concept, which people should use knowingly and not accidentally by calling some convenience function.There's little harm in all messages going to the same output. In contrast duplicate messages can be very confusing.
I really don't see why we need a complicated solution with a separate handler if the simple standard solution works well.
jklymak commentedon Jan 23, 2019
OK, but @danielballan explicitly asked that it not be a wrapper of
basicConfig(#13129 (comment)), and it was setup with its own streamhandler before, so I just used that.
timhoffm commentedon Jan 23, 2019
I would say that #13129 (comment) is not a simple use case. We as well as the user would be better of in making the logger public, so that they can attach any handler they like and configure levels.
Note also that the implementation of
_set_logger_verbose_levelis buggy: You cannot increase the level anymore; setting higher levels is silently ignored (if newlev < oldlevel). Also, for each decrease of level, you add a new handler.anntzer commentedon Jan 24, 2019
I guess(?) the point of #13129 (comment) is that @danielballan attaches his own handlers from the Python startup but basicConfig "does nothing if the root logger already has handlers configured for it", so set_loglevel() or however you want to name it would have no effect on his system.
That should pretty clearly be fixed by keeping track of the previously attached handler (if any) and reconfiguring/replacing it as needed.
timhoffm commentedon Jan 30, 2019
Discussion has shifted to #13275
My position still holds #13275 (comment)
Let's wait how the discussion there goes. No need for a quick decision.
jklymak commentedon Jan 30, 2019
After the weekly call @tacaswell said he will weigh in on what he thinks - he says he is doing a major logging integration at work, and will think about best practices thoroughly during that effort.
jklymak commentedon Feb 11, 2019
OK, th logging PR was merged, so I'm closing this. Hopefully @timhoffm is OK with the changes; if not, please feel free to re-open!