Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

logging: propagate errors during log message emits #7231

Merged
merged 1 commit into from
May 22, 2020
Merged

logging: propagate errors during log message emits #7231

merged 1 commit into from
May 22, 2020

Conversation

bluetech
Copy link
Member

Fixes #6433.

Currently, a bad logging call, e.g.

logger.info('oops', 'first', 2)

triggers the default logging handling, which is printing an error to
stderr but otherwise continuing.

For regular programs this behavior makes sense, a bad log message
shouldn't take down the program. But during tests, it is better not to
skip over such mistakes, but propagate them to the user.

@bluetech
logging: propagate errors during log message emits
b13fcb2 
Currently, a bad logging call, e.g.

    logger.info('oops', 'first', 2)

triggers the default logging handling, which is printing an error to
stderr but otherwise continuing.

For regular programs this behavior makes sense, a bad log message
shouldn't take down the program. But during tests, it is better not to
skip over such mistakes, but propagate them to the user.
@bluetech
Copy link
Member Author

Relevant doc is here: https://docs.python.org/3/library/logging.html#logging.Handler.handleError

nicoddemus
nicoddemus approved these changes May 19, 2020
View reviewed changes
Copy link
Member

@nicoddemus nicoddemus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice!

nicoddemus
nicoddemus reviewed May 19, 2020
View reviewed changes
src/_pytest/logging.py
@@ -737,6 +753,10 @@ def emit(self, record):
self._section_name_shown = True
super().emit(record)

def handleError(self, record: logging.LogRecord) -> None:
# Handled by LogCaptureHandler.
pass
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suggest to change those pass to a docstring to "trick" coverage 😁

    def handleError(self, record: logging.LogRecord) -> None:
        """Handled by LogCaptureHandler."""

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hehe I didn't know it would trick it.

Actually it really isn't covered so I prefer not to. I don't think it worth covering really, but if someone ever wants 100% coverage, they'd need to :)

@bluetech bluetech merged commit 919ac22 into pytest-dev:master May 22, 2020
@bluetech bluetech deleted the logging-error branch June 17, 2020 14:58
The-Compiler added a commit to qutebrowser/qutebrowser that referenced this pull request Jul 10, 2020
@The-Compiler
log: Set line number to -1 if it's None for Qt messages
e206d34 
If lineno is set to None in the LogRecord, pytest's logging formatting fails:

    tests/unit/utils/test_log.py:418: in test_empty_message
        log.qt_message_handler(QtCore.QtDebugMsg, self.Context(), "")
    qutebrowser/utils/log.py:508: in qt_message_handler
        qt.handle(record)
    /usr/lib/python3.8/logging/__init__.py:1587: in handle
        self.callHandlers(record)
    /usr/lib/python3.8/logging/__init__.py:1649: in callHandlers
        hdlr.handle(record)
    /usr/lib/python3.8/logging/__init__.py:950: in handle
        self.emit(record)
    ../../pytest/src/_pytest/logging.py:326: in emit
        super().emit(record)
    /usr/lib/python3.8/logging/__init__.py:1089: in emit
        self.handleError(record)
    /usr/lib/python3.8/logging/__init__.py:1081: in emit
        msg = self.format(record)
    /usr/lib/python3.8/logging/__init__.py:925: in format
        return fmt.format(record)
    ../../pytest/src/_pytest/logging.py:89: in format
        return super().format(record)
    /usr/lib/python3.8/logging/__init__.py:667: in format
        s = self.formatMessage(record)
    /usr/lib/python3.8/logging/__init__.py:636: in formatMessage
        return self._style.format(record)
    ../../pytest/src/_pytest/logging.py:185: in format
        return self._fmt % record.__dict__
    E   TypeError: %d format: a number is required, not NoneType

According to typeshed, lineno should never be None:
https://github.com/python/typeshed/blob/028f0d52931fe1f96bb25d066186961159c1f801/stdlib/2and3/logging/__init__.pyi#L386

Thus, this is our fault, not pytest's. However, before pytest 6.0.0, pytest did
not surface logging errors:

pytest-dev/pytest#7231
pytest-dev/pytest@b13fcb2

Thus, we never noticed something was going wrong here.
@The-Compiler The-Compiler mentioned this pull request Jul 10, 2020
Closed
The-Compiler added a commit to qutebrowser/qutebrowser that referenced this pull request Jul 10, 2020
@The-Compiler
log: Set line number to -1 if it's None for Qt messages
106a3a2 
If lineno is set to None in the LogRecord, pytest's logging formatting fails:

    tests/unit/utils/test_log.py:418: in test_empty_message
        log.qt_message_handler(QtCore.QtDebugMsg, self.Context(), "")
    qutebrowser/utils/log.py:508: in qt_message_handler
        qt.handle(record)
    /usr/lib/python3.8/logging/__init__.py:1587: in handle
        self.callHandlers(record)
    /usr/lib/python3.8/logging/__init__.py:1649: in callHandlers
        hdlr.handle(record)
    /usr/lib/python3.8/logging/__init__.py:950: in handle
        self.emit(record)
    ../../pytest/src/_pytest/logging.py:326: in emit
        super().emit(record)
    /usr/lib/python3.8/logging/__init__.py:1089: in emit
        self.handleError(record)
    /usr/lib/python3.8/logging/__init__.py:1081: in emit
        msg = self.format(record)
    /usr/lib/python3.8/logging/__init__.py:925: in format
        return fmt.format(record)
    ../../pytest/src/_pytest/logging.py:89: in format
        return super().format(record)
    /usr/lib/python3.8/logging/__init__.py:667: in format
        s = self.formatMessage(record)
    /usr/lib/python3.8/logging/__init__.py:636: in formatMessage
        return self._style.format(record)
    ../../pytest/src/_pytest/logging.py:185: in format
        return self._fmt % record.__dict__
    E   TypeError: %d format: a number is required, not NoneType

According to typeshed, lineno should never be None:
https://github.com/python/typeshed/blob/028f0d52931fe1f96bb25d066186961159c1f801/stdlib/2and3/logging/__init__.pyi#L386

Thus, this is our fault, not pytest's. However, before pytest 6.0.0, pytest did
not surface logging errors:

pytest-dev/pytest#7231
pytest-dev/pytest@b13fcb2

Thus, we never noticed something was going wrong here.

(cherry picked from commit e206d34)

Make mypy happy

It doesn't know about QMessageLogContext.lineno being Optional[int] rather than
int.

(cherry picked from commit 4136c84)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@nicoddemus nicoddemus nicoddemus approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

warn when logging fails
2 participants
@bluetech @nicoddemus