State when a run failed in runez.log.timeit() (#24)

* State when a run failed in `runez.log.timeit()`

* Shortened timeit message on failure

---------

Co-authored-by: Zoran Simic <zsimic@netflix.com>

docs/history.rst

@@ -2,6 +2,14 @@
 History
 =======
 
+5.0.4 (2023-12-10)
+------------------
+
+* State when a run failed in ``runez.log.timeit()``
+
+* Show exit code for failed ``runez.run()`` even with pass-through
+
+
 5.0.3 (2023-12-04)
 ------------------
 

src/runez/logsetup.py

@@ -637,13 +637,9 @@ def __call__(self, *args, **kwargs):
             (callable): Decorated function
         """
         if self.__func__:
-            self.__enter__()
-            try:
+            with self:
                 return self.__func__(*args, **kwargs)
 
-            finally:
-                self.__exit__()
-
         # We've been used as a decorator with args, and now we're called with the decorated function as argument
         self.__func__ = args[0]
         if not self.function_name:
@@ -655,7 +651,7 @@ def __enter__(self):
         self.start_time = time.time()
         return self
 
-    def __exit__(self, *_):
+    def __exit__(self, exc_type, exc_value, exc_traceback):
         msg = self.function_name
         if not msg:
             msg = "%s()" % find_caller()
@@ -666,7 +662,16 @@ def __exit__(self, *_):
             elapsed = represented_duration(elapsed)
             msg = _R.colored(msg, self.color)
             elapsed = _R.colored(elapsed, self.color)
-            msg = self.fmt.format(function=msg, elapsed=elapsed)
+            if exc_value:
+                description = _R.colored("failed", "red")
+                if exc_type is not SystemExit:
+                    description += f": {exc_value}"
+
+                msg += f" {description} (ran for {elapsed})"
+
+            else:
+                msg = self.fmt.format(function=msg, elapsed=elapsed)
+
             logger(msg)
 
 

src/runez/program.py

@@ -350,16 +350,11 @@ def run(
 
         if fatal and result.exit_code:
             base_message = "%s exited with code %s" % (short(program), result.exit_code)
-            if passthrough and (result.output or result.error):
-                exception = _R.abort_exception(override=fatal)
-                if exception is SystemExit:
-                    raise SystemExit(result.exit_code)
-
-                if isinstance(exception, type) and issubclass(exception, BaseException):
-                    raise exception(base_message)
+            if passthrough:
+                abort(base_message, code=result.exit_code, exc_info=result.exc_info, fatal=fatal, logger=abort_logger)
 
             message = []
-            if abort_logger is not None and not passthrough:
+            if abort_logger is not None:
                 # Log full output, unless user explicitly turned it off
                 message.append("Run failed: %s" % description)
                 if result.error:
@@ -368,8 +363,8 @@ def run(
                 if result.output:
                     message.append("\nstdout:\n%s" % result.output)
 
-            message.append(base_message)
-            abort("\n".join(message), code=result.exit_code, exc_info=result.exc_info, fatal=fatal, logger=abort_logger)
+            message = _R.lc.rm.joined(message, base_message, delimiter="\n")
+            abort(message, code=result.exit_code, exc_info=result.exc_info, fatal=fatal, logger=abort_logger)
 
         if background:
             os._exit(result.exit_code)  # pragma: no cover, simply exit forked process (don't go back to caller)

tests/test_logsetup.py

@@ -657,7 +657,10 @@ def test_progress_operation(isolated_log_setup, logged):
 class SampleClass:
 
     @runez.log.timeit  # Without args
-    def instance_func1(self, message):
+    def instance_func1(self, message, fail=False):
+        if fail:
+            raise ValueError("oops")
+
         print("%s: %s" % (self, message))
 
     @runez.log.timeit()  # With args
@@ -700,6 +703,10 @@ def test_timeit(logged):
     sample.instance_func1("hello")
     assert "SampleClass.instance_func1() took " in logged.pop()
 
+    with pytest.raises(ValueError):
+        sample.instance_func1("hello", fail=True)
+    assert "SampleClass.instance_func1() failed: oops" in logged.pop()
+
     sample.instance_func2("hello")
     assert "SampleClass.instance_func2() took " in logged.pop()
 

tests/test_program.py

@@ -138,15 +138,15 @@ def test_capture(monkeypatch):
                 assert r.output is None
                 assert "failed: OSError(" in r.error
 
-        # Verify no extra "exited with code ..." message is added when pass-through had some output
+        # Verify "exited with code ..." is mention in passthrough
         logged.clear()
         with pytest.raises(SystemExit):
             runez.run(CHATTER, "fail", fatal=SystemExit, passthrough=True)
-        assert "exited with code" not in logged.pop()
+        assert "exited with code" in logged.pop()
 
         with pytest.raises(runez.system.AbortException):
             runez.run(CHATTER, "fail", fatal=True, passthrough=True)
-        assert "exited with code" not in logged.pop()
+        assert "exited with code" in logged.pop()
 
         # Verify that silent pass-through gets at least mention of exit code
         with pytest.raises(SystemExit):