Moving to standard logging/warning module #3267

Merged
merged 22 commits into from Jan 4, 2017

Conversation

Projects
None yet
2 participants
@tk0miya
Member

tk0miya commented Dec 20, 2016

Note: This is still experimental.
refs: #2367.

TODO:

  • Replace app.info()
  • Support parallel build
  • Add testcode to verify new logging structure (or test manually?)
  • Replace all self.warn() by logger.warning()
  • Write docs for logging API
  • Emit warning on using old logging methods

@tk0miya tk0miya added the api label Dec 20, 2016

@tk0miya tk0miya added this to the 1.6 milestone Dec 20, 2016

@tk0miya tk0miya requested a review from shimizukawa Dec 20, 2016

@tk0miya

This comment has been minimized.

Show comment
Hide comment
@tk0miya

tk0miya Dec 20, 2016

Member

@shimizukawa Could you review the sphinx.util.logging package?

Member

tk0miya commented Dec 20, 2016

@shimizukawa Could you review the sphinx.util.logging package?

@shimizukawa

@tk0miya it's a great job! Thank you!

sphinx/util/docutils.py
+ location, type, level, message = matched.groups()
+ if type in self.level_mapping:
+ logger_method = self.level_mapping.get(type)
+ logger_method(message, location=location)

This comment has been minimized.

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think you can use logger.log(type, message, location=location) instead.
http://docs.python.jp/3/library/logging.html#logging.log

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think you can use logger.log(type, message, location=location) instead.
http://docs.python.jp/3/library/logging.html#logging.log

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

Unfortunately, logger.log() expects integer levels.
But your idea seems good. I will implement this convert in our Adapter class.

@tk0miya

tk0miya Dec 24, 2016

Member

Unfortunately, logger.log() expects integer levels.
But your idea seems good. I will implement this convert in our Adapter class.

tests/test_highlighting.py
+ ret = bridge.highlight_block('reST ``like`` text', 'python3')
+ logger.warning.assert_called_with('Could not lex literal_block as "%s". '
+ 'Highlighting skipped.', 'python3',
+ type='misc', subtype='highlighting_failure', location=None)

This comment has been minimized.

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think testfixtures.LogCapture is good choice for such verifying.
http://testfixtures.readthedocs.io/en/latest/logging.html

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think testfixtures.LogCapture is good choice for such verifying.
http://testfixtures.readthedocs.io/en/latest/logging.html

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

I will use it if we have to mock loggers again.

@tk0miya

tk0miya Dec 24, 2016

Member

I will use it if we have to mock loggers again.

sphinx/util/logging.py
+
+ def filter(self, record):
+ if self.app.warningiserror:
+ raise SphinxWarning(record.msg % record.args)

This comment has been minimized.

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think this raise is threw even if type of logging is INFO, isn't it?

@shimizukawa

shimizukawa Dec 21, 2016

Member

I think this raise is threw even if type of logging is INFO, isn't it?

This comment has been minimized.

@tk0miya

tk0miya Dec 21, 2016

Member

Yes, but this implementation does not support logging.info.
app.info() emits INFO log to STDOUT. but this implement does not refer STDOUT yet. It always emits logs to STDERR.
We should switch the target fd by log level. But I don't investigate how to do that.

@tk0miya

tk0miya Dec 21, 2016

Member

Yes, but this implementation does not support logging.info.
app.info() emits INFO log to STDOUT. but this implement does not refer STDOUT yet. It always emits logs to STDERR.
We should switch the target fd by log level. But I don't investigate how to do that.

This comment has been minimized.

@shimizukawa

shimizukawa Dec 21, 2016

Member

I see

This comment has been minimized.

@tk0miya

tk0miya Dec 21, 2016

Member

I just pushed new sphinx.util.logging supporting INFO logs.
I hope you like it.

@tk0miya

tk0miya Dec 21, 2016

Member

I just pushed new sphinx.util.logging supporting INFO logs.
I hope you like it.

@shimizukawa

This comment has been minimized.

Show comment
Hide comment
sphinx/builders/epub.py
@@ -547,14 +551,14 @@ def handle_finish(self):
def build_mimetype(self, outdir, outname):
# type: (unicode, unicode) -> None
"""Write the metainfo file mimetype."""
- self.info('writing %s file...' % outname)
+ logger.info('writing %s file...' % outname)

This comment has been minimized.

@shimizukawa

shimizukawa Dec 22, 2016

Member

By convention, it is more common to pass string and params to logger instead of formatting them like:

logger.info('writing %s file...', outname)

The implementation of applicatoin.py has already been like this, so I think it would be better to fit the writing style.

@shimizukawa

shimizukawa Dec 22, 2016

Member

By convention, it is more common to pass string and params to logger instead of formatting them like:

logger.info('writing %s file...', outname)

The implementation of applicatoin.py has already been like this, so I think it would be better to fit the writing style.

This comment has been minimized.

@tk0miya

tk0miya Dec 25, 2016

Member

Fixed.

@tk0miya

tk0miya Dec 25, 2016

Member

Fixed.

sphinx/builders/latex.py
@@ -247,7 +250,7 @@ def validate_config_values(app):
app.warn('latex_use_parts conflicts with latex_toplevel_sectioning, ignored.')
else:
app.warn('latex_use_parts is deprecated. Use latex_toplevel_sectioning instead.')
- app.config.latex_toplevel_sectioning = 'parts' # type: ignore
+ app.config.latex_toplevel_sectioning = 'part' # type: ignore

This comment has been minimized.

@shimizukawa

shimizukawa Dec 22, 2016

Member

Memo: Perhaps I don’t have to worry about this, do you?

@shimizukawa

shimizukawa Dec 22, 2016

Member

Memo: Perhaps I don’t have to worry about this, do you?

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

Ah, sorry. This is not a part of this pull request.
It was already commited into stable branch: 12096b3.

@tk0miya

tk0miya Dec 24, 2016

Member

Ah, sorry. This is not a part of this pull request.
It was already commited into stable branch: 12096b3.

@@ -532,3 +536,12 @@ def split_docinfo(text):
return '', result[0]
else:
return result[1:]
+
+
+def display_chunk(chunk):

This comment has been minimized.

@shimizukawa

shimizukawa Dec 22, 2016

Member

Memo: what is this? Perhaps it's utility function for parallel building, but no code is using this yet.

@shimizukawa

shimizukawa Dec 22, 2016

Member

Memo: what is this? Perhaps it's utility function for parallel building, but no code is using this yet.

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

Yes, this is copied, but not used function. I just removed it.

@tk0miya

tk0miya Dec 24, 2016

Member

Yes, this is copied, but not used function. I just removed it.

sphinx/application.py
- raise SphinxWarning(warntext)
- self._warncount += 1
- self._log(colorfunc(warntext), self._warning, True)
+ logger.warning(message, type=type, subtype=subtype, location=location)

This comment has been minimized.

@shimizukawa

shimizukawa Dec 22, 2016

Member

When will we deprecate this app.warn function? The current implementation does not seem to warn deprecatoin yet. I think it is appropriate to set RemovedInSphinx18Warning(PendingDeprecationWarning). (OR maybe RemovedInSphinx20Warning?)

@shimizukawa

shimizukawa Dec 22, 2016

Member

When will we deprecate this app.warn function? The current implementation does not seem to warn deprecatoin yet. I think it is appropriate to set RemovedInSphinx18Warning(PendingDeprecationWarning). (OR maybe RemovedInSphinx20Warning?)

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

app.warn and app.info are used for a long time. So I'd like to keep provided during 1.x series.
So I will warn them as RemovedInSphinx20Warning.

@tk0miya

tk0miya Dec 24, 2016

Member

app.warn and app.info are used for a long time. So I'd like to keep provided during 1.x series.
So I will warn them as RemovedInSphinx20Warning.

sphinx/util/parallel.py
- else:
- ret = func(arg)
- pipe.send((False, ret))
+ logger = logging.LogCollector()

This comment has been minimized.

@shimizukawa

shimizukawa Dec 23, 2016

Member

I think the name logger is misleading and is hiding global logger object. collector is better to me.

@shimizukawa

shimizukawa Dec 23, 2016

Member

I think the name logger is misleading and is hiding global logger object. collector is better to me.

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

LGTM.

@tk0miya

tk0miya Dec 24, 2016

Member

LGTM.

sphinx/util/parallel.py
+ failed = True
+ ret = (err, traceback.format_exc())
+ logging.convert_serializable(logger.logs)
+ pipe.send((failed, logger.logs, ret))

This comment has been minimized.

@shimizukawa

shimizukawa Dec 23, 2016

Member

I feel this part is bit complicated. As a user of logging utility, it would be nice if we can write:

    def _process(self, pipe, func, arg):
        # type: (Any, Callable, Any) -> None
        with logging.logcollector() as collector:
            if arg is None:
                ret = func()
            else:
                ret = func(arg)
        logging.convert_serializable(collector.logs)
        pipe.send(collector.result)
@shimizukawa

shimizukawa Dec 23, 2016

Member

I feel this part is bit complicated. As a user of logging utility, it would be nice if we can write:

    def _process(self, pipe, func, arg):
        # type: (Any, Callable, Any) -> None
        with logging.logcollector() as collector:
            if arg is None:
                ret = func()
            else:
                ret = func(arg)
        logging.convert_serializable(collector.logs)
        pipe.send(collector.result)

This comment has been minimized.

@tk0miya

tk0miya Dec 24, 2016

Member

failed and ret are not related with logging feature. So I don't like it.

@tk0miya

tk0miya Dec 24, 2016

Member

failed and ret are not related with logging feature. So I don't like it.

sphinx/util/logging.py
+ info_handler.setLevel(VERBOSITY_MAP.get(app.verbosity))
+ info_handler.setFormatter(ColorizeFormatter())
+
+ warning_handler = WarningStreamHandler(SafeEncodingWriter(warning))

This comment has been minimized.

@tk0miya

tk0miya Dec 23, 2016

Member

Note: mypy warns SafeEncodingWriter is not IO object:

sphinx/util/logging.py: note: In function "setup":
sphinx/util/logging.py:405: error: Argument 1 to "NewLineStreamHandlerPY2" has incompatible type "SafeEncodingWriter"; expected IO[str]
@tk0miya

tk0miya Dec 23, 2016

Member

Note: mypy warns SafeEncodingWriter is not IO object:

sphinx/util/logging.py: note: In function "setup":
sphinx/util/logging.py:405: error: Argument 1 to "NewLineStreamHandlerPY2" has incompatible type "SafeEncodingWriter"; expected IO[str]

This comment has been minimized.

@shimizukawa

shimizukawa Dec 25, 2016

Member

logging.StremHandler which is base class of WarningSteamHandler is defined as

class StreamHandler(Handler):
    def __init__(self, stream: Optional[IO[str]] = ...) -> None: ...

https://github.com/python/typeshed/blob/master/stdlib/2and3/logging/__init__.pyi#L355

And IO is defined with many abstract methods:
https://github.com/python/typing/blob/master/src/typing.py#L1994

@shimizukawa

shimizukawa Dec 25, 2016

Member

logging.StremHandler which is base class of WarningSteamHandler is defined as

class StreamHandler(Handler):
    def __init__(self, stream: Optional[IO[str]] = ...) -> None: ...

https://github.com/python/typeshed/blob/master/stdlib/2and3/logging/__init__.pyi#L355

And IO is defined with many abstract methods:
https://github.com/python/typing/blob/master/src/typing.py#L1994

+ levelno = LEVEL_NAMES.get(level)
+ super(SphinxLoggerAdapter, self).log(levelno, msg, *args, **kwargs)
+
+ def verbose(self, msg, *args, **kwargs):

This comment has been minimized.

@tk0miya

tk0miya Dec 26, 2016

Member

Is this really needed?
This is used only in Sphinx.setup_extension() and sphinx.ext.viewcode.

@tk0miya

tk0miya Dec 26, 2016

Member

Is this really needed?
This is used only in Sphinx.setup_extension() and sphinx.ext.viewcode.

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

verbose seems same level as 'info' to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

verbose seems same level as 'info' to me.

This comment has been minimized.

@tk0miya

tk0miya Jan 4, 2017

Member

Okay, let's discuss in another issue.

@tk0miya

tk0miya Jan 4, 2017

Member

Okay, let's discuss in another issue.

+ # type: (unicode, Any, Any) -> None
+ self.log(VERBOSE, msg, *args, **kwargs)
+
+ def debug2(self, msg, *args, **kwargs):

This comment has been minimized.

@tk0miya

tk0miya Dec 26, 2016

Member

This is also.
This is used only in Sphinx.emit() and sphinx.ext.autodoc.

@tk0miya

tk0miya Dec 26, 2016

Member

This is also.
This is used only in Sphinx.emit() and sphinx.ext.autodoc.

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

it seems same as 'debug' to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

it seems same as 'debug' to me.

+ """Log record class supporting location"""
+ location = None # type: Any
+
+ def getMessage(self):

This comment has been minimized.

@tk0miya

tk0miya Dec 26, 2016

Member

I try to implement this as LogRecord. But it seems the behavior is similar to Formatter.
Is it better to modify this to Formatter?

@tk0miya

tk0miya Dec 26, 2016

Member

I try to implement this as LogRecord. But it seems the behavior is similar to Formatter.
Is it better to modify this to Formatter?

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I have no opinion for that. Ether OK to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I have no opinion for that. Ether OK to me.

This comment has been minimized.

@tk0miya

tk0miya Jan 4, 2017

Member

Finally, I decided to implement this as LogRecord.

@tk0miya

tk0miya Jan 4, 2017

Member

Finally, I decided to implement this as LogRecord.

@tk0miya

This comment has been minimized.

Show comment
Hide comment
@tk0miya

tk0miya Jan 2, 2017

Member

I just finished all my work.
@shimizukawa I'm terribly sorry, but could you review this again?

Member

tk0miya commented Jan 2, 2017

I just finished all my work.
@shimizukawa I'm terribly sorry, but could you review this again?

@tk0miya tk0miya changed the title from [WIP] Moving to standard logging/warning module to Moving to standard logging/warning module Jan 2, 2017

@shimizukawa

LGTM with nits!

CHANGES
@@ -8,6 +8,8 @@ Incompatible changes
members by default. Thanks to Luc Saffre.
* LaTeX ``\includegraphics`` command isn't overloaded: only ``\sphinxincludegraphics``
has the custom code to fit image to available width if oversized.
+* #2367: ``Sphinx.warn()``, ``Sphinx.info()`` and other logging methods are now
+ deprecated. Please use ``sphinx.util.logging`` (:ref:`logging-api`) instead.

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I think it would be better if "deprecation" changes are located in "Deprecated" section as like as sphinx-1.5's one.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I think it would be better if "deprecation" changes are located in "Deprecated" section as like as sphinx-1.5's one.

sphinx/application.py
else:
- self.info('failed: %s' % err)
+ logger.info('failed: %s' % err)

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

It would be nice if , instead of % as:

logger.info('failed: %s', err)

This is logger standard style I think.

@shimizukawa

shimizukawa Jan 4, 2017

Member

It would be nice if , instead of % as:

logger.info('failed: %s', err)

This is logger standard style I think.

sphinx/builders/latex.py
@@ -119,7 +122,7 @@ def write(self, *ignored):
destination = FileOutput(
destination_path=path.join(self.outdir, targetname),
encoding='utf-8')
- self.info("processing " + targetname + "... ", nonl=1)
+ logger.info("processing " + targetname + "... ", nonl=1)

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I feel uncomfortable when it is implemented by string concatenation. How about the following?

logger.info("processing %s...", targetname, nonl=1)
@shimizukawa

shimizukawa Jan 4, 2017

Member

I feel uncomfortable when it is implemented by string concatenation. How about the following?

logger.info("processing %s...", targetname, nonl=1)
sphinx/builders/latex.py
- app.warn('invalid latex_toplevel_sectioning, ignored: %s' %
- app.config.latex_toplevel_sectioning)
+ logger.warning('invalid latex_toplevel_sectioning, ignored: %s' %
+ app.config.latex_toplevel_sectioning)

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

It would be better if using , instead of % for formatting.

@shimizukawa

shimizukawa Jan 4, 2017

Member

It would be better if using , instead of % for formatting.

sphinx/ext/imgmath.py
@@ -234,7 +237,7 @@ def html_visit_math(self, node):
sm = nodes.system_message(msg, type='WARNING', level=2,
backrefs=[], source=node['latex'])
sm.walkabout(self)
- self.builder.warn('display latex %r: ' % node['latex'] + msg)
+ logger.warning('display latex %r: ' % node['latex'] + msg)

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

proposal:

logger.warning('display latex %r%r: ', node['latex'], msg)
@shimizukawa

shimizukawa Jan 4, 2017

Member

proposal:

logger.warning('display latex %r%r: ', node['latex'], msg)
sphinx/ext/pngmath.py
@@ -234,7 +237,7 @@ def html_visit_displaymath(self, node):
sm = nodes.system_message(msg, type='WARNING', level=2,
backrefs=[], source=node['latex'])
sm.walkabout(self)
- self.builder.warn('inline latex %r: ' % node['latex'] + msg)
+ logger.warning('inline latex %r: ' % node['latex'] + msg)

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

again

sphinx/ext/viewcode.py
- (modname, e))
+ logger.verbose(traceback.format_exc().rstrip())
+ logger.verbose('viewcode can\'t import %s, failed with error "%s"' %
+ (modname, e))

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

, instead of %

@shimizukawa

shimizukawa Jan 4, 2017

Member

, instead of %

+ """Log record class supporting location"""
+ location = None # type: Any
+
+ def getMessage(self):

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I have no opinion for that. Ether OK to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

I have no opinion for that. Ether OK to me.

+ levelno = LEVEL_NAMES.get(level)
+ super(SphinxLoggerAdapter, self).log(levelno, msg, *args, **kwargs)
+
+ def verbose(self, msg, *args, **kwargs):

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

verbose seems same level as 'info' to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

verbose seems same level as 'info' to me.

+ # type: (unicode, Any, Any) -> None
+ self.log(VERBOSE, msg, *args, **kwargs)
+
+ def debug2(self, msg, *args, **kwargs):

This comment has been minimized.

@shimizukawa

shimizukawa Jan 4, 2017

Member

it seems same as 'debug' to me.

@shimizukawa

shimizukawa Jan 4, 2017

Member

it seems same as 'debug' to me.

@tk0miya tk0miya merged commit d2b913c into sphinx-doc:master Jan 4, 2017

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
@tk0miya

This comment has been minimized.

Show comment
Hide comment
@tk0miya

tk0miya Jan 4, 2017

Member

Merged!

Member

tk0miya commented Jan 4, 2017

Merged!

@tk0miya tk0miya deleted the tk0miya:2367_logging branch Jan 4, 2017

@shimizukawa

This comment has been minimized.

Show comment
Hide comment
@shimizukawa

shimizukawa Jan 4, 2017

Member

Great! Thanks!!

Member

shimizukawa commented Jan 4, 2017

Great! Thanks!!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment