diff --git a/build/build.py b/build/build.py index 34377db7b..aac95f91f 100755 --- a/build/build.py +++ b/build/build.py @@ -21,7 +21,7 @@ sys.dont_write_bytecode = True sys.path.insert(0, os.path.join(os.path.dirname(os.path.abspath(__file__)), "lib")) from command.main import cfg_load, cmd_build # noqa: E402 -from common.error import ToolError # noqa: E402 +from common.error import EXIT_TERM, ToolError # noqa: E402 #################################################################################################################################### @@ -35,6 +35,11 @@ def main(): try: config = cfg_load(sys.argv[1:], path_repo) cmd_build(config) + except KeyboardInterrupt: + # A ctrl-c is what was asked for, so report it the way the C reports a signal rather than as a stack trace + print("ERROR: terminated on signal SIGINT") + + return EXIT_TERM except ToolError as error: print("ERROR: %s" % error) diff --git a/build/lib/common/error.py b/build/lib/common/error.py index e5a616472..f9b341214 100644 --- a/build/lib/common/error.py +++ b/build/lib/common/error.py @@ -1,12 +1,23 @@ """Error Handling. Each tool reports failures with ToolError, which carries the exit status to return. Exit status mirrors the C: 0 is success, 1 means a -top-level coverage check found modules missing coverage, and anything greater is an error.""" +top-level coverage check found modules missing coverage, and anything greater is an error. + +Anything else that gets out of a tool is a bug in the tool, which error_trace() renders the way the C renders a stack trace: enough to +find the bug without burying the message that says what it was.""" #################################################################################################################################### +import traceback + # Exit status for an error. Distinct from 1, which a coverage command uses to report incomplete coverage rather than a failure. EXIT_ERROR = 2 +# Exit status when a signal terminated the tool, the same status the C exits with for TermError +EXIT_TERM = 63 + +# Innermost frames of a stack trace to show when it is trimmed +TRACE_FRAME_MAX = 6 + #################################################################################################################################### class ToolError(Exception): @@ -17,6 +28,31 @@ class ToolError(Exception): self.status = status +#################################################################################################################################### +def error_trace(error, full=False): + """Render an unexpected exception and its stack trace. + + An unexpected exception is a bug in the tool rather than a problem with what the tool was working on, so the stack trace is what + gets it fixed. Only the innermost frames are shown, since the frames above them are the path from main() into the tool and are + long enough to bury the message that says what went wrong. + + The complete trace, including any exception this one was raised while handling, is rendered when full is set, which is what the + tools do at debug level as the C shows a stack trace only at debug level.""" + + frame_list = traceback.extract_tb(error.__traceback__) + + # There is nothing to trim when the whole trace is already short enough, so render it as python does + if full or len(frame_list) <= TRACE_FRAME_MAX: + return "".join(traceback.format_exception(type(error), error, error.__traceback__)).rstrip("\n") + + # The message comes first so it is what gets read, followed by the frames in the order python reports them + return ( + "".join(traceback.format_exception_only(type(error), error)).rstrip("\n") + + "\nstack trace (innermost %u of %u frames, --log-level=debug shows all of them):\n" % (TRACE_FRAME_MAX, len(frame_list)) + + "".join(traceback.format_list(frame_list[-TRACE_FRAME_MAX:])).rstrip("\n") + ) + + #################################################################################################################################### def check(condition, message): """Raise ToolError when a condition does not hold. diff --git a/doc/doc.py b/doc/doc.py index 697245f8e..279b6f039 100755 --- a/doc/doc.py +++ b/doc/doc.py @@ -10,7 +10,6 @@ Exit status: 0 = success, greater = error.""" import os import signal import sys -import traceback # Do not cache bytecode. The tool runs from the source tree, where a __pycache__ would show up as an unexpected binary file in the # linter and in the distribution. This must be set before the library modules are imported below. @@ -22,7 +21,7 @@ for lib in ("build", "doc"): sys.path.insert(0, os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), lib, "lib")) from command.doc import cfg_load, cmd_doc # noqa: E402 -from common.error import EXIT_ERROR, ToolError # noqa: E402 +from common.error import EXIT_ERROR, EXIT_TERM, ToolError, error_trace # noqa: E402 from common.log import * # noqa: E402 @@ -48,13 +47,18 @@ def main(): try: cmd_doc(config) + except KeyboardInterrupt: + # A ctrl-c is what was asked for, so report it the way the C reports a signal rather than as a stack trace + log(ERROR, "terminated on signal SIGINT") + + return EXIT_TERM except ToolError as error: log(ERROR, error) return error.status - except Exception: - # An unexpected exception is a bug here rather than a problem with the documentation, so show the traceback - print(traceback.format_exc()) + except Exception as error: + # An unexpected exception is a bug here rather than a problem with the documentation, so show the stack trace + log(ERROR, error_trace(error, config.log_level >= DEBUG)) return EXIT_ERROR diff --git a/doc/release.py b/doc/release.py index d03a4d9d5..46f307901 100755 --- a/doc/release.py +++ b/doc/release.py @@ -18,7 +18,6 @@ import re import shutil import signal import sys -import traceback # Send everything written to stderr to stdout instead so the output is in the order it happened sys.stderr = sys.stdout @@ -33,7 +32,7 @@ for lib in ("build", "doc"): sys.path.insert(0, os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), lib, "lib")) from command.render.release import release_last # noqa: E402 -from common.error import EXIT_ERROR, ToolError # noqa: E402 +from common.error import EXIT_ERROR, EXIT_TERM, ToolError, error_trace # noqa: E402 from common.exec import exec_result # noqa: E402 from common.log import * # noqa: E402 from common.storage import file_read, file_remove, file_write # noqa: E402 @@ -382,13 +381,18 @@ def main(): try: return command_run(config) + except KeyboardInterrupt: + # A ctrl-c is what was asked for, so report it the way the C reports a signal rather than as a stack trace + log(ERROR, "terminated on signal SIGINT") + + return EXIT_TERM except ToolError as error: log(ERROR, error) return error.status - except Exception: - # An unexpected exception is a bug here rather than a problem with the release, so show the traceback - print(traceback.format_exc()) + except Exception as error: + # An unexpected exception is a bug here rather than a problem with the release, so show the stack trace + log(ERROR, error_trace(error, config.log_level >= DEBUG)) return EXIT_ERROR diff --git a/test/ci.py b/test/ci.py index 9755ac44b..47c9ff19e 100755 --- a/test/ci.py +++ b/test/ci.py @@ -15,7 +15,6 @@ import os import signal import sys import time -import traceback # Send everything written to stderr to stdout instead so the output is in the order it happened sys.stderr = sys.stdout @@ -29,7 +28,7 @@ sys.dont_write_bytecode = True for lib in ("build", "doc", "test"): sys.path.insert(0, os.path.join(os.path.dirname(os.path.dirname(os.path.abspath(__file__))), lib, "lib")) -from common.error import EXIT_ERROR, ToolError # noqa: E402 +from common.error import EXIT_ERROR, EXIT_TERM, ToolError, error_trace # noqa: E402 from common.exec import exec_one # noqa: E402 from common.log import * # noqa: E402 from common.user import user_name # noqa: E402 @@ -190,13 +189,19 @@ def main(): try: return command_run(cfg_load(sys.argv[1:], path_repo)) + except KeyboardInterrupt: + # A ctrl-c is what was asked for, so report it the way the C reports a signal rather than as a stack trace + log(ERROR, "terminated on signal SIGINT") + + return EXIT_TERM except ToolError as error: log(ERROR, error) return error.status - except Exception: - # An unexpected exception is a bug here rather than a problem with the run, so show the traceback - print(traceback.format_exc()) + except Exception as error: + # An unexpected exception is a bug here rather than a problem with the run, so show the stack trace. The complete trace is + # shown since a run cannot be repeated at debug level to get it, and there is no terminal here for it to get in the way of. + log(ERROR, error_trace(error, True)) return EXIT_ERROR diff --git a/test/src/module/build/common/error_test.py b/test/src/module/build/common/error_test.py index 77172a208..bdbacb98d 100644 --- a/test/src/module/build/common/error_test.py +++ b/test/src/module/build/common/error_test.py @@ -31,6 +31,65 @@ def test_error_status(): # The default is distinct from the incomplete coverage status so the two are never confused assert_not_equal(EXIT_ERROR, 1) + # A run that was terminated by a signal is distinct from one that failed + assert_not_equal(EXIT_TERM, EXIT_ERROR) + assert_not_equal(EXIT_TERM, 1) + + +#################################################################################################################################### +def _raise_nested(depth): + """Raise from depth nested calls.""" + + if depth > 0: + _raise_nested(depth - 1) + + raise ValueError("something unexpected") + + +#################################################################################################################################### +def _error_nested(depth): + """Return an exception raised from depth nested calls, so its trace has depth + 2 frames. + + The exception is caught here rather than with assert_raises(), which clears the traceback the test needs.""" + + try: + _raise_nested(depth) + except ValueError as error: + return error + + +#################################################################################################################################### +def test_error_trace_trim(): + """A trace with more frames than the limit keeps the innermost of them and says how many there were.""" + + error = _error_nested(TRACE_FRAME_MAX) + trace = error_trace(error) + + # The message comes first so a trace cannot bury it, and the frame count says what is missing and how to get it + assert_true(trace.startswith("ValueError: something unexpected\n")) + assert_in("stack trace (innermost %u of %u frames" % (TRACE_FRAME_MAX, TRACE_FRAME_MAX + 2), trace) + assert_in("--log-level=debug", trace) + + # The frames kept are the innermost ones, so the trace is shorter than the complete one and ends where the error was raised + assert_true(len(trace.splitlines()) < len(error_trace(error, True).splitlines())) + assert_true(trace.endswith('raise ValueError("something unexpected")')) + + +#################################################################################################################################### +def test_error_trace_full(): + """The complete trace is python's own, which is what debug level gets and what a trace short enough to keep gets anyway.""" + + trace = error_trace(_error_nested(TRACE_FRAME_MAX), True) + + assert_true(trace.startswith("Traceback (most recent call last):\n")) + assert_true(trace.endswith("ValueError: something unexpected")) + + # A trace with no more frames than the limit is not trimmed, so there is nothing to say about what was dropped + trace = error_trace(_error_nested(0)) + + assert_true(trace.startswith("Traceback (most recent call last):\n")) + assert_not_in("innermost", trace) + #################################################################################################################################### def test_check_pass(): diff --git a/test/test.py b/test/test.py index 1eb5a45ae..a74dca58b 100755 --- a/test/test.py +++ b/test/test.py @@ -13,7 +13,6 @@ import os import signal import sys import time -import traceback # Send everything written to stderr to stdout instead. Anything a test writes to stderr is a failure, so an error raised before # the handler in main() is installed, e.g. while importing below, would otherwise look like one. @@ -32,7 +31,7 @@ from command.code.format import cmd_code_format # noqa: E402 from command.test.test import cmd_test # noqa: E402 from command.test.unit import cmd_unit # noqa: E402 from command.vm.build import cmd_vm_build # noqa: E402 -from common.error import EXIT_ERROR, ToolError # noqa: E402 +from common.error import EXIT_ERROR, EXIT_TERM, ToolError, error_trace # noqa: E402 from common.log import * # noqa: E402 from config.config import cfg_load # noqa: E402 from config.project import project_version # noqa: E402 @@ -77,14 +76,19 @@ def main(): try: result = command_run(config) + except KeyboardInterrupt: + # A ctrl-c is what was asked for, so report it the way the C reports a signal rather than as a stack trace + log(ERROR, "terminated on signal SIGINT") + + return EXIT_TERM except ToolError as error: log(ERROR, error) log(INFO, "%s command end: aborted with exception" % config.command) return error.status - except Exception: - # An unexpected exception is a harness bug, so show the traceback. It goes to stdout like everything else. - print(traceback.format_exc()) + except Exception as error: + # An unexpected exception is a harness bug, so show the stack trace. It goes to stdout like everything else. + log(ERROR, error_trace(error, config.log_level >= DEBUG)) return EXIT_ERROR