Trim the stack trace the tools show and report ctrl-c as a signal.

A ctrl-c raised KeyboardInterrupt out of main() and python printed the traceback, which is the whole path from main() down to the select() the harness happened to be waiting in and says nothing about a run that was stopped on purpose. Catch it and log "terminated on signal SIGINT" as the C does, exiting with the status the C exits with for TermError.

An unexpected exception is a bug in the tool so the trace is what gets it fixed, but the trace ends with the message that says what went wrong, which is where the message gets lost. Show the message first and keep only the innermost frames, since the frames above them are the path from main() into the tool and are much the same for every error. The frame count says how many were dropped and how to get them, and the complete trace, which is what python printed before, is shown at debug level the same way the C shows a stack trace only at debug level.

The rendering is error_trace() in common/error.py, beside ToolError, so every tool reports a bug in itself the same way. The CI wrapper asks for the complete trace since a run there cannot be repeated at debug level to get it, and the code builder handles the interrupt but not the trace since it has no log level to raise.

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)
 

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.

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
 

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
 

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
 

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():

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