Skip to content

logger: use py3 methods to display the exception #3059

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

Closed
wants to merge 3 commits into from
Closed

logger: use py3 methods to display the exception #3059

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0d0b421
logger: use py3 methods to display the exception
Jan 5, 2020
6b425ec
logger: method to get the cause of exceptions
Jan 7, 2020
67db48a
logger: add a third exception to test nesting
Jan 7, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
130 changes: 42 additions & 88 deletions dvc/logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
"""Manages logging configuration for dvc repo."""

import io
import traceback
import logging.config
import logging.handlers

Expand All @@ -21,9 +21,7 @@


class LoggingException(Exception):
def __init__(self, record):
msg = "failed to log {}".format(str(record))
super().__init__(msg)
pass


class ExcludeErrorsFilter(logging.Filter):
Expand All @@ -37,16 +35,12 @@ def filter(self, record):


class ColorFormatter(logging.Formatter):
"""Enable color support when logging to a terminal that supports it.
"""Spit out colored text in supported terminals.

Color support on Windows versions that do not support ANSI color codes is
enabled by use of the colorama__ library.
colorama__ makes ANSI escape character sequences work under Windows.
See the colorama documentation for details.

__ https://pypi.python.org/pypi/colorama

For records containing `exc_info`, it will use a custom `_walk_exc` to
retrieve the whole traceback.
"""

color_code = {
Expand All @@ -58,97 +52,57 @@ class ColorFormatter(logging.Formatter):
}

def format(self, record):
info = record.msg

if record.levelname == "INFO":
return record.msg

if record.levelname == "ERROR" or record.levelname == "CRITICAL":
exception, stack_trace = self._parse_exc(record.exc_info)

return (
"{color}{levelname}{nc}: {description}" "{stack_trace}\n"
).format(
color=self.color_code.get(record.levelname, ""),
nc=colorama.Fore.RESET,
levelname=record.levelname,
Comment on lines -67 to -72
Copy link
Contributor

@efiop efiop Jan 6, 2020

Choose a reason for hiding this comment

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

@MrOutis Why do we need to make these changes? Isn't the point of this change to just use py3 interfaces? If so, the only thing that should be affected is _parse_exc. Or am I missing something?

Copy link
Author

@ghost ghost Jan 7, 2020 •
edited by ghost
Loading

Choose a reason for hiding this comment

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

we are using format_exc. just some reorganization, nothing on the logic changed besides misreading the while loop

Copy link
Contributor

@efiop efiop Jan 7, 2020

Choose a reason for hiding this comment

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

@MrOutis I understand, but it really widens the scope and makes this hard to review when having simple py3 migration in mind. Something might slip by. 🙁

Copy link
Contributor

@casperdcl casperdcl Jan 7, 2020

Choose a reason for hiding this comment

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

I agree with @efiop - it's very tempting to fix multiple issues in one go but with a big PR like this it's best to tidy up/reorganise in a follow-up PR.

Copy link
Author

@ghost ghost Jan 7, 2020

Choose a reason for hiding this comment

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

got it, @efiop , @casperdcl ; I'll take it into account for further PR's 🙂

description=self._description(record.msg, exception),
msg=record.msg,
stack_trace=stack_trace,
return info

if record.exc_info:
_, exception, _ = record.exc_info

info = "{message}{separator}{exception}".format(
message=record.msg or "",
separator=" - " if record.msg and exception.args else "",
exception=": ".join(self._causes(exception)),
)

return "{color}{levelname}{nc}: {msg}".format(
color=self.color_code.get(record.levelname, ""),
nc=colorama.Fore.RESET,
if self._current_level() == logging.DEBUG:
trace = "".join(traceback.format_exception(*record.exc_info))

return (
"{red}{levelname}{nc}: {info}\n"
"{red}{line}{nc}\n"
"{trace}"
"{red}{line}{nc}".format(
levelname=record.levelname,
info=info,
red=colorama.Fore.RED,
line="-" * 60,
trace=trace,
nc=colorama.Fore.RESET,
)
)

return "{color}{levelname}{nc}: {info}".format(
color=self.color_code[record.levelname],
levelname=record.levelname,
msg=record.msg,
nc=colorama.Fore.RESET,
info=info,
)

def _current_level(self):
return logging.getLogger("dvc").getEffectiveLevel()

def _is_visible(self, record):
return record.levelno >= self._current_level()

def _description(self, message, exception):
description = ""

if exception and message:
description = "{message} - {exception}"
elif exception:
description = "{exception}"
elif message:
description = "{message}"

return description.format(message=message, exception=exception)

def _walk_exc(self, exc_info):
import traceback

buffer = io.StringIO()

traceback.print_exception(*exc_info, file=buffer)

exc = exc_info[1]
tb = buffer.getvalue()

exc_list = [str(exc)]
tb_list = [tb]

# NOTE: parsing chained exceptions. See dvc/exceptions.py for more info
while hasattr(exc, "__cause__") and exc.__cause__:
exc_list.append(str(exc.__cause__))
if hasattr(exc, "cause_tb") and exc.cause_tb:
tb_list.insert(0, str(exc.cause_tb))
def _causes(self, exc):
while exc:
yield str(exc)
exc = exc.__cause__

return exc_list, tb_list

def _parse_exc(self, exc_info):
if not exc_info:
return (None, "")

exc_list, tb_list = self._walk_exc(exc_info)

exception = ": ".join(exc_list)

if self._current_level() == logging.DEBUG:
stack_trace = (
"\n" "{red}{line}{nc}\n" "{stack_trace}" "{red}{line}{nc}"
).format(
red=colorama.Fore.RED,
nc=colorama.Fore.RESET,
line="-" * 60,
stack_trace="\n".join(tb_list),
)
else:
stack_trace = ""

return (exception, stack_trace)
def _current_level(self):
return logging.getLogger("dvc").getEffectiveLevel()


class LoggerHandler(logging.StreamHandler):
def handleError(self, record):
super().handleError(record)
raise LoggingException(record)
raise LoggingException("failed to log {}".format(record))

def emit(self, record):
"""Write to Tqdm's stream so as to not break progress-bars"""
Expand Down
27 changes: 15 additions & 12 deletions tests/unit/test_logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ def test_error(self, caplog):
with caplog.at_level(logging.INFO, logger="dvc"):
logger.error("message")

expected = "{red}ERROR{nc}: message\n".format(**colors)
expected = "{red}ERROR{nc}: message".format(**colors)

assert expected == formatter.format(caplog.records[0])

Expand All @@ -55,7 +55,7 @@ def test_exception(self, caplog):
except Exception:
logger.exception("message")

expected = "{red}ERROR{nc}: message\n".format(**colors)
expected = "{red}ERROR{nc}: message".format(**colors)

assert expected == formatter.format(caplog.records[0])

Expand All @@ -66,7 +66,7 @@ def test_exception_with_description_and_without_message(self, caplog):
except Exception:
logger.exception("")

expected = "{red}ERROR{nc}: description\n".format(**colors)
expected = "{red}ERROR{nc}: description".format(**colors)

assert expected == formatter.format(caplog.records[0])

Expand All @@ -77,9 +77,7 @@ def test_exception_with_description_and_message(self, caplog):
except Exception:
logger.exception("message")

expected = "{red}ERROR{nc}: message - description\n".format(
**colors
)
expected = "{red}ERROR{nc}: message - description".format(**colors)

assert expected == formatter.format(caplog.records[0])

Expand All @@ -95,7 +93,7 @@ def test_exception_under_verbose(self, caplog):
"{red}ERROR{nc}: description\n"
"{red}{line}{nc}\n"
"{stack_trace}"
"{red}{line}{nc}\n".format(
"{red}{line}{nc}".format(
line="-" * 60, stack_trace=stack_trace, **colors
)
)
Expand All @@ -109,21 +107,26 @@ def test_nested_exceptions(self, caplog):
except Exception as exc:
try:
raise DvcException("second") from exc
except DvcException:
stack_trace = traceback.format_exc()
logger.exception("message")
except DvcException as exc:
try:
raise ValueError("third") from exc
Copy link
Contributor

@Suor Suor Jan 7, 2020

Choose a reason for hiding this comment

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

Need to test how it works without explicit cause. Maybe that is even more important because that is an error in error handler presumably, which we want to fix.

except ValueError:
stack_trace = traceback.format_exc()
logger.exception("message")

expected = (
"{red}ERROR{nc}: message - second: first\n"
"{red}ERROR{nc}: message - third: second: first\n"
"{red}{line}{nc}\n"
"{stack_trace}"
"{red}{line}{nc}\n".format(
Copy link
Contributor

@efiop efiop Jan 7, 2020

Choose a reason for hiding this comment

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

Could you please explain why \n are getting removed now?

Copy link
Author

@ghost ghost Jan 7, 2020

Choose a reason for hiding this comment

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

I found it excessive, maybe not enough reason to do so.

Copy link
Contributor

@efiop efiop Jan 7, 2020

Choose a reason for hiding this comment

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

@MrOutis The newline is needed there, it is part of the message. I imagine you are trying to solve double newline between the exc and "Having any troubles" footer, right? If so, it is probably worth just removing \n there. But again, this is out of scope for this PR, so let's not touch new lines at all, please roll back this change for now.

Copy link
Author

@ghost ghost Jan 7, 2020

Choose a reason for hiding this comment

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

Ok

"{red}{line}{nc}".format(
line="-" * 60, stack_trace=stack_trace, **colors
)
)

assert expected == formatter.format(caplog.records[0])
assert "Exception: first" in stack_trace
assert "dvc.exceptions.DvcException: second" in stack_trace
assert "ValueError: third" in stack_trace

def test_progress_awareness(self, mocker, capsys, caplog):
from dvc.progress import Tqdm
Expand Down