From b4912f21161cebef27ccb6ce738f2e751add8ad6 Mon Sep 17 00:00:00 2001 From: Facundo Batista Date: Wed, 6 Oct 2021 11:00:37 -0300 Subject: [PATCH 1/2] Added error report support. --- craft_cli/errors.py | 59 ++++++ craft_cli/messages.py | 48 +++++ tests/unit/test_messages_emitter.py | 230 +++++++++++++++++++++++- tests/unit/test_messages_helpers.py | 18 ++ tests/unit/test_messages_integration.py | 152 ++++++++++++++++ 5 files changed, 505 insertions(+), 2 deletions(-) create mode 100644 craft_cli/errors.py diff --git a/craft_cli/errors.py b/craft_cli/errors.py new file mode 100644 index 0000000..d74839a --- /dev/null +++ b/craft_cli/errors.py @@ -0,0 +1,59 @@ +# +# Copyright 2021 Canonical Ltd. +# +# This program is free software; you can redistribute it and/or +# modify it under the terms of the GNU Lesser General Public +# License version 3 as published by the Free Software Foundation. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +# Lesser General Public License for more details. +# +# You should have received a copy of the GNU Lesser General Public License +# along with this program; if not, write to the Free Software Foundation, +# Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. + +"""Error classes.""" + +from typing import Optional + + +class CraftError(Exception): + """Signal a program error with a lot of information to report. + + - message: the main message to the user, to be shown as first line (and probably + only that, according to the different modes); note that in some cases the log + location will be attached to this message. + + - details: the full error details received from a third party which originated + the error situation + + - resolution: an extra line indicating to the user how the error may be fixed or + avoided (to be shown together with 'message') + + - docs_url: an URL to point the user to documentation (to be shown together + with 'message') + + - reportable: if an error report should be sent to some error-handling backend (like + Sentry) + + - retcode: the code to return when the application finishes + """ + + def __init__( + self, + message: str, + *, + details: Optional[str] = None, + resolution: Optional[str] = None, + docs_url: Optional[str] = None, + reportable: bool = True, + retcode: int = 1, + ): + super().__init__(message) + self.details = details + self.resolution = resolution + self.docs_url = docs_url + self.reportable = reportable + self.retcode = retcode diff --git a/craft_cli/messages.py b/craft_cli/messages.py index af2d18f..10a43e6 100644 --- a/craft_cli/messages.py +++ b/craft_cli/messages.py @@ -28,12 +28,15 @@ import sys import threading import time +import traceback from dataclasses import dataclass, field from datetime import datetime from typing import Literal, Optional, TextIO, Union import appdirs +from craft_cli import errors + @dataclass class _MessageInfo: # pylint: disable=too-many-instance-attributes @@ -105,6 +108,14 @@ def _get_log_filepath(appname: str) -> pathlib.Path: return basedir / filename +def _get_traceback_lines(exc: BaseException): + """Get the traceback lines (if any) from an exception.""" + tback_lines = traceback.format_exception(type(exc), exc, exc.__traceback__) + for tback_line in tback_lines: + for real_line in tback_line.rstrip().split("\n"): + yield real_line + + class _Spinner(threading.Thread): """A supervisor thread that will repeat long-standing messages with a spinner besides it. @@ -655,3 +666,40 @@ def open_stream(self, text: str): def ended_ok(self) -> None: """Finish the messaging system gracefully.""" self._printer.stop() # type: ignore + + def _report_error(self, error: errors.CraftError) -> None: + """Report the different message lines from a CraftError.""" + if self._mode == EmitterMode.QUIET or self._mode == EmitterMode.NORMAL: + use_timestamp = False + full_stream = None + else: + use_timestamp = True + full_stream = sys.stderr + + # the initial message + self._printer.show(sys.stderr, str(error), use_timestamp=use_timestamp, end_line=True) # type: ignore + + # detailed information and/or original exception + if error.details: + text = f"Detailed information: {error.details}" + self._printer.show(full_stream, text, use_timestamp=use_timestamp, end_line=True) # type: ignore + if error.__cause__: + for line in _get_traceback_lines(error.__cause__): + self._printer.show(full_stream, line, use_timestamp=use_timestamp, end_line=True) # type: ignore + + # hints for the user to know more + if error.resolution: + text = f"Recommended resolution: {error.resolution}" + self._printer.show(sys.stderr, text, use_timestamp=use_timestamp, end_line=True) # type: ignore + if error.docs_url: + text = f"For more information, check out: {error.docs_url}" + self._printer.show(sys.stderr, text, use_timestamp=use_timestamp, end_line=True) # type: ignore + + text = f"Full execution log: {str(self._log_filepath)!r}" + self._printer.show(sys.stderr, text, use_timestamp=use_timestamp, end_line=True) # type: ignore + + @_init_guard + def error(self, error: errors.CraftError) -> None: + """Handle the system's indicated error and stop machinery.""" + self._report_error(error) + self._printer.stop() # type: ignore diff --git a/tests/unit/test_messages_emitter.py b/tests/unit/test_messages_emitter.py index a33bacc..62ca10e 100644 --- a/tests/unit/test_messages_emitter.py +++ b/tests/unit/test_messages_emitter.py @@ -23,6 +23,7 @@ import pytest from craft_cli import messages +from craft_cli.errors import CraftError from craft_cli.messages import Emitter, EmitterMode, _Handler @@ -390,12 +391,237 @@ def test_openstream_in_verboseish_modes(get_initiated_emitter, mode): ] -# -- tests for stopping the machinery +# -- tests for stopping the machinery ok def test_ended_ok(get_initiated_emitter): - """Finish everything.""" + """Finish everything ok.""" emitter = get_initiated_emitter(EmitterMode.QUIET) emitter.ended_ok() assert emitter.printer_calls == [call().stop()] + + +# -- tests for error reporting + + +@pytest.mark.parametrize("mode", [EmitterMode.QUIET, EmitterMode.NORMAL]) +def test_reporterror_simple_message_only_quietish(mode, get_initiated_emitter): + """Report just a simple message, in silent modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=False, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=False, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.VERBOSE, EmitterMode.TRACE]) +def test_reporterror_simple_message_only_verboseish(mode, get_initiated_emitter): + """Report just a simple message, in more verbose modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.QUIET, EmitterMode.NORMAL]) +def test_reporterror_detailed_info_quietish(mode, get_initiated_emitter): + """Report an error having detailed information, in silent modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", details="boom") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=False, end_line=True), + call().show(None, "Detailed information: boom", use_timestamp=False, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=False, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.VERBOSE, EmitterMode.TRACE]) +def test_reporterror_detailed_info_verboseish(mode, get_initiated_emitter): + """Report an error having detailed information, in more verbose modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", details="boom") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, "Detailed information: boom", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.QUIET, EmitterMode.NORMAL]) +def test_reporterror_chained_exception_quietish(mode, get_initiated_emitter): + """Report an error that was originated after other exception, in silent modes.""" + emitter = get_initiated_emitter(mode) + try: + try: + raise ValueError("original") + except ValueError as err: + orig_exception = err + raise CraftError("test message") from err + except CraftError as err: + error = err + + with patch("craft_cli.messages._get_traceback_lines") as tblines_mock: + tblines_mock.return_value = ["traceback line 1", "traceback line 2"] + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=False, end_line=True), + call().show(None, "traceback line 1", use_timestamp=False, end_line=True), + call().show(None, "traceback line 2", use_timestamp=False, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=False, end_line=True), + call().stop(), + ] + + # check the traceback lines are generated using the original exception + tblines_mock.assert_called_with(orig_exception) # type: ignore + + +@pytest.mark.parametrize("mode", [EmitterMode.VERBOSE, EmitterMode.TRACE]) +def test_reporterror_chained_exception_verboseish(mode, get_initiated_emitter): + """Report an error that was originated after other exception, in more verbose modes.""" + emitter = get_initiated_emitter(mode) + try: + try: + raise ValueError("original") + except ValueError as err: + orig_exception = err + raise CraftError("test message") from err + except CraftError as err: + error = err + + with patch("craft_cli.messages._get_traceback_lines") as tblines_mock: + tblines_mock.return_value = ["traceback line 1", "traceback line 2"] + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, "traceback line 1", use_timestamp=True, end_line=True), + call().show(sys.stderr, "traceback line 2", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] + + # check the traceback lines are generated using the original exception + tblines_mock.assert_called_with(orig_exception) # type: ignore + + +@pytest.mark.parametrize("mode", [EmitterMode.QUIET, EmitterMode.NORMAL]) +def test_reporterror_with_resolution_quietish(mode, get_initiated_emitter): + """Report an error with a recommended resolution, in silent modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", resolution="run") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=False, end_line=True), + call().show(sys.stderr, "Recommended resolution: run", use_timestamp=False, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=False, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.VERBOSE, EmitterMode.TRACE]) +def test_reporterror_with_resolution_verboseish(mode, get_initiated_emitter): + """Report an error with a recommended resolution, in more verbose modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", resolution="run") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, "Recommended resolution: run", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.QUIET, EmitterMode.NORMAL]) +def test_reporterror_with_docs_quietish(mode, get_initiated_emitter): + """Report including a docs url, in silent modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", docs_url="https://charmhub.io/docs/whatever") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + full_docs_message = "For more information, check out: https://charmhub.io/docs/whatever" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=False, end_line=True), + call().show(sys.stderr, full_docs_message, use_timestamp=False, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=False, end_line=True), + call().stop(), + ] + + +@pytest.mark.parametrize("mode", [EmitterMode.VERBOSE, EmitterMode.TRACE]) +def test_reporterror_with_docs_verboseish(mode, get_initiated_emitter): + """Report including a docs url, in more verbose modes.""" + emitter = get_initiated_emitter(mode) + error = CraftError("test message", docs_url="https://charmhub.io/docs/whatever") + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + full_docs_message = "For more information, check out: https://charmhub.io/docs/whatever" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_docs_message, use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] + + +def test_reporterror_full_complete(get_initiated_emitter): + """Sanity case to check order between the different parts.""" + emitter = get_initiated_emitter(EmitterMode.TRACE) + try: + try: + raise ValueError("original") + except ValueError as err: + raise CraftError( + "test message", + details="boom", + resolution="run", + docs_url="https://charmhub.io/docs/whatever", + ) from err + except CraftError as err: + error = err + + with patch("craft_cli.messages._get_traceback_lines") as tblines_mock: + tblines_mock.return_value = ["traceback line 1", "traceback line 2"] + emitter.error(error) + + full_log_message = f"Full execution log: {repr(emitter._log_filepath)}" + full_docs_message = "For more information, check out: https://charmhub.io/docs/whatever" + assert emitter.printer_calls == [ + call().show(sys.stderr, "test message", use_timestamp=True, end_line=True), + call().show(sys.stderr, "Detailed information: boom", use_timestamp=True, end_line=True), + call().show(sys.stderr, "traceback line 1", use_timestamp=True, end_line=True), + call().show(sys.stderr, "traceback line 2", use_timestamp=True, end_line=True), + call().show(sys.stderr, "Recommended resolution: run", use_timestamp=True, end_line=True), + call().show(sys.stderr, full_docs_message, use_timestamp=True, end_line=True), + call().show(sys.stderr, full_log_message, use_timestamp=True, end_line=True), + call().stop(), + ] diff --git a/tests/unit/test_messages_helpers.py b/tests/unit/test_messages_helpers.py index 8b6c86f..94b9da0 100644 --- a/tests/unit/test_messages_helpers.py +++ b/tests/unit/test_messages_helpers.py @@ -30,6 +30,7 @@ from craft_cli.messages import ( EmitterMode, _get_log_filepath, + _get_traceback_lines, _Handler, _MessageInfo, _Printer, @@ -415,3 +416,20 @@ def test_handler_emit_verboseish(handler, mode): call.show(sys.stderr, "test info", use_timestamp=True), call.show(sys.stderr, "test debug", use_timestamp=True), ] + + +# -- tests for the traceback lines extractor + + +def test_traceback_lines_simple(): + """Extract traceback lines from an exception.""" + try: + raise ValueError("pumba") + except ValueError as err: + tbacklines = list(_get_traceback_lines(err)) + + assert tbacklines[0] == "Traceback (most recent call last):" + assert tbacklines[1].startswith(' File "/') + assert tbacklines[1].endswith(", in test_traceback_lines_simple") + assert tbacklines[2] == ' raise ValueError("pumba")' + assert tbacklines[3] == "ValueError: pumba" diff --git a/tests/unit/test_messages_integration.py b/tests/unit/test_messages_integration.py index c08e0c1..c19c7f3 100644 --- a/tests/unit/test_messages_integration.py +++ b/tests/unit/test_messages_integration.py @@ -30,10 +30,12 @@ import sys import textwrap from dataclasses import dataclass +from unittest.mock import patch import pytest from craft_cli import messages +from craft_cli.errors import CraftError from craft_cli.messages import Emitter, EmitterMode # the timestamp format (including final separator space) @@ -393,6 +395,156 @@ def test_04_third_party_output_verbose(capsys, tmp_path, mode): assert_outputs(capsys, emit, expected_err=expected, expected_log=expected) +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.QUIET, + EmitterMode.NORMAL, + ], +) +def test_05_06_simple_errors_quietly(capsys, mode): + """Error because of application or external rules, quiet and normal mode.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + error = CraftError( + "Cannot find config file 'somepath'.", + ) + emit.error(error) + + expected = [ + Line("Cannot find config file 'somepath'."), + Line(f"Full execution log: {emit._log_filepath!r}"), + ] + assert_outputs(capsys, emit, expected_err=expected, expected_log=expected) + + +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.VERBOSE, + EmitterMode.TRACE, + ], +) +def test_05_06_simple_errors_verbosely(capsys, mode): + """Error because of application or external rules, more verbose modes.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + error = CraftError( + "Cannot find config file 'somepath'.", + ) + emit.error(error) + + expected = [ + Line("Cannot find config file 'somepath'.", timestamp=True), + Line(f"Full execution log: {emit._log_filepath!r}", timestamp=True), + ] + assert_outputs(capsys, emit, expected_err=expected, expected_log=expected) + + +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.QUIET, + EmitterMode.NORMAL, + ], +) +def test_07_error_api_quietly(capsys, mode): + """Somewhat expected API error, quiet and normal mode.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + full_error = {"message": "Invalid channel.", "code": "BAD-CHANNEL"} + error = CraftError("Invalid channel.", details=str(full_error)) + emit.error(error) + + expected_err = [Line("Invalid channel."), Line(f"Full execution log: {emit._log_filepath!r}")] + expected_log = [ + Line("Invalid channel."), + Line(f"Detailed information: {full_error}"), + Line(f"Full execution log: {emit._log_filepath!r}"), + ] + assert_outputs(capsys, emit, expected_err=expected_err, expected_log=expected_log) + + +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.VERBOSE, + EmitterMode.TRACE, + ], +) +def test_07_error_api_verbosely(capsys, mode): + """Somewhat expected API error, more verbose modes.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + full_error = {"message": "Invalid channel.", "code": "BAD-CHANNEL"} + error = CraftError("Invalid channel.", details=str(full_error)) + emit.error(error) + + expected = [ + Line("Invalid channel.", timestamp=True), + Line(f"Detailed information: {full_error}", timestamp=True), + Line(f"Full execution log: {emit._log_filepath!r}", timestamp=True), + ] + assert_outputs(capsys, emit, expected_err=expected, expected_log=expected) + + +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.QUIET, + EmitterMode.NORMAL, + ], +) +def test_08_09_error_unexpected_quietly(capsys, mode): + """Unexpected error from a 3rd party or application crash, quiet and normal mode.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + try: + raise ValueError("pumba") + except ValueError as exc: + error = CraftError("First message.") + error.__cause__ = exc + with patch("craft_cli.messages._get_traceback_lines", return_value=["foo", "bar"]): + emit.error(error) + + expected_err = [Line("First message."), Line(f"Full execution log: {emit._log_filepath!r}")] + expected_log = [ + Line("First message."), + Line("foo"), + Line("bar"), + Line(f"Full execution log: {emit._log_filepath!r}"), + ] + assert_outputs(capsys, emit, expected_err=expected_err, expected_log=expected_log) + + +@pytest.mark.parametrize( + "mode", + [ + EmitterMode.VERBOSE, + EmitterMode.TRACE, + ], +) +def test_08_09_error_unexpected_verbosely(capsys, mode): + """Unexpected error from a 3rd party or application crash, more verbose modes.""" + emit = Emitter() + emit.init(mode, "testapp", GREETING) + try: + raise ValueError("pumba") + except ValueError as exc: + error = CraftError("First message.") + error.__cause__ = exc + with patch("craft_cli.messages._get_traceback_lines", return_value=["foo", "bar"]): + emit.error(error) + + expected = [ + Line("First message.", timestamp=True), + Line("foo", timestamp=True), + Line("bar", timestamp=True), + Line(f"Full execution log: {emit._log_filepath!r}", timestamp=True), + ] + assert_outputs(capsys, emit, expected_err=expected, expected_log=expected) + + def test_logging_when_quiet(capsys, logger): """Handle the different logging levels when in quiet mode.""" emit = Emitter() From 49f6e5f45db7c369c63ed8b4a5a1793ca267fce8 Mon Sep 17 00:00:00 2001 From: Facundo Batista Date: Thu, 7 Oct 2021 11:59:35 -0300 Subject: [PATCH 2/2] Used ivar instead of dashes in the docstring. --- craft_cli/errors.py | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/craft_cli/errors.py b/craft_cli/errors.py index d74839a..102a328 100644 --- a/craft_cli/errors.py +++ b/craft_cli/errors.py @@ -22,23 +22,23 @@ class CraftError(Exception): """Signal a program error with a lot of information to report. - - message: the main message to the user, to be shown as first line (and probably - only that, according to the different modes); note that in some cases the log - location will be attached to this message. + :ivar message: the main message to the user, to be shown as first line (and + probably only that, according to the different modes); note that in some + cases the log location will be attached to this message. - - details: the full error details received from a third party which originated - the error situation + :ivar details: the full error details received from a third party which + originated the error situation - - resolution: an extra line indicating to the user how the error may be fixed or - avoided (to be shown together with 'message') + :ivar resolution: an extra line indicating to the user how the error may be + fixed or avoided (to be shown together with 'message') - - docs_url: an URL to point the user to documentation (to be shown together - with 'message') + :ivar docs_url: an URL to point the user to documentation (to be shown + together with 'message') - - reportable: if an error report should be sent to some error-handling backend (like - Sentry) + :ivar reportable: if an error report should be sent to some error-handling + backend (like Sentry) - - retcode: the code to return when the application finishes + :ivar retcode: the code to return when the application finishes """ def __init__(