[MRG] Replace verbose class with standard logging library#9313
[MRG] Replace verbose class with standard logging library#9313anntzer merged 1 commit intomatplotlib:masterfrom
Conversation
| command = [str("latex"), "-interaction=nonstopmode", | ||
| '"%s"' % latexfile] | ||
| verbose.report(command, 'debug') | ||
| log.debug(command) |
There was a problem hiding this comment.
Please use log.debug('%s', command) (throughout) so as not to crash if command has the bad idea of including a %. See sphinx-doc/sphinx#4070 for a similar issue (except that they mangled the fix :-/).
There was a problem hiding this comment.
OK, I can see this has an advantage. OTOH, there is lots of this kind of formatting that was being passed to verbose. I don't mind fixing the easy cases, but there are also cases like:
log.info('figure size (inches) has been adjusted '
'from %s x %s to %s x %s' % (wo, ho, w, h))I tested this, and its not as simple as:
log.info('figure size (inches) has been adjusted '
'from %s x %s to %s x %s', (wo, ho, w, h))which fails.
More importantly, I'm concerned that by redoing all these I'll screw something up. These aren't the easiest parts of the code to debug since the tests don't get run with the logging turned on.
For now, I'll fix the easy one-%s cases, but not the more complicated formatting.
lib/matplotlib/__init__.py
Outdated
| log = logging.getLogger(__name__) | ||
| if "".join(config['text.latex.preamble']): | ||
| verbose.report(""" | ||
| log.info(""" |
There was a problem hiding this comment.
The standard way is to do
log.info("format_string %s", args)
instead of
log.info("format string %s" % args)
Note that the latter form will raise an exception if args has the bad idea of including a % (see comment below for more details).
There was a problem hiding this comment.
Additional point of information: the reason the logging module uses a format string followed by arguments is that this means the string interpolation is done only if the logging level is such that the result will actually be used. In other words, it is a performance optimization.
|
Asking for functionality reviews before I write up docs as they will need to be changed in a number of places if this is the way we want to go forward. |
lib/matplotlib/__init__.py
Outdated
| output: | ||
| `import logging` | ||
| `logger=logging.getLogger('matplotlib')` | ||
| `logger.set_level(logging.INFO)` |
There was a problem hiding this comment.
import logging
logging.getLogger('matplotlib').setLevel(logging.INFO)
yes it's camelcase
and if you want to keep it over three lines, spaces around =
lib/matplotlib/__init__.py
Outdated
| """ | ||
| levelmap = {'silent': logging.WARNING, 'helpful': logging.INFO, | ||
| 'debug': logging.DEBUG, 'debug-annoying': logging.DEBUG, | ||
| 'info': logging.INFO, 'warning': logging.warning} |
lib/matplotlib/__init__.py
Outdated
| fileo = open(file_str, 'w') | ||
| # if this fails, we will just write to stdout | ||
| except IOError: | ||
| warning.warn('could not open log file "{0}"' |
lib/matplotlib/__init__.py
Outdated
| # if this fails, we will just write to stdout | ||
| except IOError: | ||
| warning.warn('could not open log file "{0}"' | ||
| 'for writing.\nCheck your ' |
There was a problem hiding this comment.
I tend not to prefer embedding newlines into this kind of messages because you never know what the width of the console is going to be anyways. Not a big deal though.
|
|
||
| for arg in sys.argv[1:]: | ||
| # cast to str because we are using unicode_literals, | ||
| # and argv is always str |
There was a problem hiding this comment.
I don't think you need the cast? On Py2 the str will just happily check for startswith against unicode; on Py3 everything is str.
If you do need the cast I'd just write for arg in map(str, sys.argv[1:])
There was a problem hiding this comment.
This might a 2.6 hold over?
This works as expected on as far back as 2.7.3 (the earliest version conda had easily available).
There was a problem hiding this comment.
Works with 2.6.8 as well, I do wonder how far back this goes...
There was a problem hiding this comment.
I'm going to leave this in as I just copied from old code and don't understand the cast. Feel free to tell me the proper way to do it.
There was a problem hiding this comment.
I would also suggest leaving out the cast and the comment block that goes with it.
| output through logger | ||
|
|
||
| if always is True, the report will occur on every function | ||
| call; otherwise only on the first time the function is called |
There was a problem hiding this comment.
I don't think we ever use always=True so we may as well drop that
There was a problem hiding this comment.
The whole class is deprecated, so...
lib/matplotlib/__init__.py
Outdated
|
|
||
| _obsolete_set = {'text.dvipnghack', 'legend.isaxes'} | ||
| _obsolete_set = {'text.dvipnghack', 'legend.isaxes', 'verbose.level', | ||
| 'verbose.fileo'} |
There was a problem hiding this comment.
Why did you deprecated them? I the log level should stay configurable from the mplrc?
| import six | ||
|
|
||
| import os, sys | ||
| import os, sys, loging |
anntzer
left a comment
There was a problem hiding this comment.
There's bunch of minor edits here and there (haven't listed them all) and I think the logger level should stay configurable from the matplotlibrc, but the general approach looks good to me.
The main point that must be paid attention to is that by default, a given warning.warn (same content and emitted from the same line of code) will only be shown once (it is then stored in a cache and later calls will be suppressed), whereas a logger.warning will be shown every time. |
|
@anntzer Thanks so much for the comments. I'll try and address (though quite a few were just copied over, rather than new). Your larger points: More than happy to walk back the changes and deprecation warnings on the matplotlibrc. I personally think it could cause more confusion than not, but maybe thats also how I've implemented it. Right now, it takes the most verbose of a) an already instantiated I think there is also a problem calling all these things WRT guidance about what level of verbosity folks should use, and choices between |
|
I think we can leave the calls to warnings.warn as they are for now and change them to logger.warning in a piecemeal fashion whereever appropriate. |
|
I will try to give this a close look ASAP. Thank you for taking this on; it's definitely the direction we need to go. |
|
Yes, please go ahead with @anntzer's suggestions. |
lib/matplotlib/animation.py
Outdated
| w, h = self.fig.get_size_inches() | ||
| verbose.report('frame size in pixels is %s x %s' % self.frame_size, | ||
| level='debug') | ||
| log.info('frame size in pixels is %s x %s' % self.frame_size) |
There was a problem hiding this comment.
Did you mean to change the lever on this one (makes sense to match the one just above)
|
Without minimizing the amount of work done, this is less invasive change than I expected! I definitely think that this is the right way to go. On a quick read, the mapping between the verbose levels and the logging level makes sense. Agree with @anntzer to not touch A while ago I also wrote up notes on loggers (https://github.com/scikit-beam/scikit-beam/blob/dd8625baa22c886601d51ff0c6fea0aee01c86cb/doc/resource/dev_guide/logging.rst ) which may or may not be a useful reference. |
|
@anntzer Above you proposed to prioritze:
The problem is I don't think there is anyway from within If its true that we can't detect that the user has specified this in their code, then that becomes very confusing if we say that the coded logger will take priority unless it is set to I am personally against this being set at all in the My proposal would be:
If we want to keep the This is probably just my bias, as I think I've dug out my |
|
@tacaswell Not minimizing the amount of work at all. It was pretty minimal. Which I think is somewhat unfortunate, because it means people are avoiding putting debugging into their code. Not sure if this will change that, and maybe there are good reasons not to spam the logger if you are doing something that requires high performance. |
I think I'm +0.5 on keeping matplotlibrc support, but am happy to hear input from others. |
|
Awesome! I’m fine with instantiation trumps all if that is the route to go. If anyone else has an opinion let me know. If not I’ll implement @anntzers preferred method. |
|
Meh. If we set So, given that we can't tell if the root logger has been set (I don't think), what do we want to do? |
doc/devel/contributing.rst
Outdated
| Using logging for debug messages | ||
| -------------------------------- | ||
|
|
||
| Matplotlib uses the standard python logging_ library to write verbose |
There was a problem hiding this comment.
We have an intersphinx mapping (https://github.com/matplotlib/matplotlib/blob/master/doc/conf.py#L95) to the stdlib so you can (should) just write
`logging`
`print`
`warnings.warn`
etc. and they will link to the corresponding entries in the stdlib docs
doc/devel/contributing.rst
Outdated
| Which logging level to use? | ||
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~ | ||
|
|
||
| There are five logging levels. :func:`logging.critical()` and |
There was a problem hiding this comment.
the level is logging.CRITICAL, not logging.critical.
There was a problem hiding this comment.
OK, but I want to refer to the functions. Changed to There are five levels at which you can emit messages.
doc/faq/troubleshooting_faq.rst
Outdated
|
|
||
| import matplotlib.pyplot as plt | ||
|
|
||
| Note that if you want to use logging_ in your own code, but do not |
6b3edf1 to
d77e94f
Compare
.appveyor.yml
Outdated
|
|
||
| # Build the wheel with the static libs | ||
| # Hide the output, the copied files really clutter the build log... | ||
| # Hide the output, the copied files really clutter the build_log... |
doc/devel/contributing.rst
Outdated
| There are five levels at which you can emit messages. | ||
| `logging.critical` and `logging.error` | ||
| are really only there for errors that will end the use of the library but | ||
| not kill the interpreter. :`logging.warning()` overlaps with the |
lib/matplotlib/__init__.py
Outdated
| _verbose_msg = """\ | ||
| Command line argument --verbose-LEVEL is deprecated. | ||
| This functionality is now provided by the standard | ||
| python logging library. To get more (or less) logging output:" |
lib/matplotlib/__init__.py
Outdated
| verbose.report('platform is %s' % sys.platform) | ||
| verbose.report('loaded modules: %s' % list(sys.modules), 'debug') | ||
| _log.info('matplotlib version %s', __version__) | ||
| #_log.info('verbose.level %s' % verbose.level) |
lib/matplotlib/animation.py
Outdated
| # Logging is quieted because subprocess.PIPE has limited buffer size. | ||
| if not verbose.ge('debug'): | ||
|
|
||
| if not (_log.getEffectiveLevel() >= logging.DEBUG): |
| TransformedBbox) | ||
| from matplotlib.backend_bases import NonGuiException | ||
|
|
||
| _log = logging.getLogger(__name__) |
There was a problem hiding this comment.
can do without? (and without the import)
There was a problem hiding this comment.
I stuck it in there because I have a PR that will need it anyways ;-) I actually think this should be at the top of most modules so folks use the debugging. I appreciate there may be a small performance hit on some intensive modules, but hopefully not a big deal
doc/devel/contributing.rst
Outdated
|
|
||
| will log to a logger named ``matplotlib.yourmodulename``. | ||
|
|
||
| If an end-user of your module sets up `logging` to display at levels |
doc/devel/contributing.rst
Outdated
| import logging | ||
| Format = '%(name)s:%(lineno)5d - %(levelname)s - %(message)s' | ||
| logging.basicConfig(level=logging.DEBUG, | ||
| format=Format) |
doc/devel/contributing.rst
Outdated
| more verbose than `logger.WARNING` in their code as follows:: | ||
|
|
||
| import logging | ||
| Format = '%(name)s:%(lineno)5d - %(levelname)s - %(message)s' |
There was a problem hiding this comment.
No capitalization for variables; fmt if you want to avoid format.
| ~~~~~~~~~~~~~~~~~~~~~~~~~~~ | ||
|
|
||
| There are five levels at which you can emit messages. | ||
| `logging.critical` and `logging.error` |
There was a problem hiding this comment.
I'll leave as is for now, but am happy for tweaks later...
doc/faq/troubleshooting_faq.rst
Outdated
| * You can get very helpful debugging output from matlotlib by running your | ||
| script with a ``verbose-helpful`` or ``--verbose-debug`` flags and posting | ||
| the verbose output the lists:: | ||
| * You can get helpful debugging output from matlotlib by using the logging_ |
|
|
||
| import os, sys, warnings | ||
| import logging | ||
|
|
| "not enabled the matplotlib 'text.latex.unicode' " | ||
| "rcParam.", 'helpful') | ||
| _log.info("You are using unicode and latex, but have " | ||
| "not enabled the matplotlib 'text.latex.unicode' " |
| command = [str('dvips'), '-q', '-R0', '-o', os.path.basename(psfile), | ||
| os.path.basename(dvifile)] | ||
| verbose.report(command, 'debug') | ||
| _log.debug(command) |
There was a problem hiding this comment.
Why did you convert the one above to use '%s' and not this one (or the rest of them)?
lib/matplotlib/dviread.py
Outdated
| unicode_literals) | ||
|
|
||
| import six | ||
| import logging |
| from six.moves.urllib.request import urlopen | ||
|
|
||
| import datetime | ||
| import logging |
There was a problem hiding this comment.
As this file is deprecated, you may want to send these changes to the new upstream.
There was a problem hiding this comment.
Not sure what you mean? Whatever is replacing this file? Not sure what that is!
| Using logging for debug messages | ||
| -------------------------------- | ||
|
|
||
| Matplotlib uses the standard python `logging` library to write verbose |
Change verbose to standard logging library PEP8 fixes and formatting of log messages @anntzer PEP8 fixes and formatting of log messages @anntzer Small fixes as suggested by @aantzer and @tacaswell Documentation Fix on merge Number small fixes Small fix for docs Small fix for error in animate.py fixed import order and small doc fix Small doc fix Changed log. to _log. Fix on merge Number small fixes Small fix for docs Small fix for error in animate.py fixed import order and small doc fix Small doc fix Changed log. to _log. Changed log. to _log. fixed fonts gah gah gah gah gah gah PEP8 doc fix revert _base.py fix missing _log Fixes for @efiring Fixes for @anntzer minor Doc link fixes @anntzer Small doc change Many small changes, thanks @QuLogic and @anntzer Link error docs
|
master rebase |
|
Sweet! 🎉 |
PR Summary
This replaces Matplotlib's
Verboseclass and calls with the standardlogginglibrary. Hopefully this will lead to more debugging information and better integration with downstream packages.See #9302 and discussion therein.
How to use:
For the end-user:
The old command-line
--verbose-debugand--verbose-helpfulare still respected (and--verbose-infowas even added). These are likely to be deprecated but are not for now.Better is for a script to load and configure the
logginglibrary before importing matplotlib:At its most basic:
in the header should do it. A slightly more useful formatting will give line numbers:
The resulting console output will be something like:
which is then pretty easily grep-able to find debug info in particular modules.
For the module writer
At the top of the module, you need to
import logging. Then calls likewill log to a logger named
matplotlib.yourmodulename. Theoretically,getLoggeris not too expensive, so you need not save the logger for each class (and you don't need to instantiate it in any way other than a call togetLoggersomewhere).I've used the name
logthroughout the code, which maybe is a problematic choice. One can use any name you want if this clashes in your module's namespace.Which logging level to use?
There are five logging levels.
logging.critical()andlogging.error()are really only there for errors that will end the use of the library but not kill the interpreter.WARNINGoverlaps with thewarninglibrary. The logging tutorial has suggested differentiation betweenlogging.warning()andwarning.warn().By default,
loggingdisplays all log messages at levels higher thanlogging.WARNINGtosys.stderr.logging.info()is not displayed by default. Its for information that the user may want to know if the program behaves oddly. For instance, if an object isn't drawn because its position isNaN, that can usually be ignored, but a mystified user could setlogging.basicConfig(level=logging.INFO)and if the module writer is kind get an error message that says why.logging.debug()is the least likely to be displayed, and hence can be the most verbose.Fate of --verbose and the rcParams...
The
--verbose-debugand--verbose-helpfulcommand line options are still handled and setlogging.basicConfig(level=logging.DEBUG)and ``logging.basicConfig(level=logging.INFO)` respectively.The entries in
matplotlibrcare still respected by the same logic (verbose.levelandverbose.fileo). However, they are on thedeprecatedlist and those entries have been removed from thematplotlibrc.template.PR Checklist