Always set timestamp on kill, provide spent time in str()

doc/source/ExecResult.rst

@@ -44,6 +44,14 @@ API: ExecResult
         ``typing.Optional(datetime.datetime)``
         Timestamp
 
+    .. py:method:: set_timestamp()
+
+        Set timestamp if empty.
+
+        This will block future object changes.
+
+        .. versionadded:: 4.0.0
+
     .. py:attribute:: cmd
 
         ``str``

exec_helpers/_ssh_client_base.py

@@ -714,6 +714,9 @@ def poll_pipes() -> None:
         async_result.interface.status_event.set()
         future.cancel()
 
+        concurrent.futures.wait([future], 0.001)
+        result.set_timestamp()
+
         wait_err_msg: str = _log_templates.CMD_WAIT_ERROR.format(result=result, timeout=timeout)
         self.logger.debug(wait_err_msg)
         raise exceptions.ExecHelperTimeoutError(result=result, timeout=timeout)  # type: ignore

exec_helpers/async_api/subprocess_runner.py

@@ -148,6 +148,7 @@ async def poll_stderr() -> None:
         finally:
             stdout_task.cancel()
             stderr_task.cancel()
+            result.set_timestamp()
 
         wait_err_msg: str = _log_templates.CMD_WAIT_ERROR.format(result=result, timeout=timeout)
         self.logger.debug(wait_err_msg)

exec_helpers/exec_result.py

@@ -140,6 +140,16 @@ def timestamp(self) -> typing.Optional[datetime.datetime]:
         """
         return self.__timestamp
 
+    def set_timestamp(self) -> None:
+        """Set timestamp if empty.
+
+        This will block future object changes.
+
+        .. versionadded:: 4.0.0
+        """
+        if self.timestamp is None:
+            self.__timestamp = datetime.datetime.utcnow()
+
     @staticmethod
     def _get_bytearray_from_array(src: typing.Iterable[bytes]) -> bytearray:
         """Get bytearray from array of bytes blocks.
@@ -472,8 +482,14 @@ def __str__(self) -> str:
         """Representation for logging."""
         if self.started:
             started = f"\tstarted={self.started.strftime('%Y-%m-%d %H:%M:%S')},\n"
+            if self.timestamp:
+                _spent = (self.timestamp - self.started).seconds
+                spent = f"\tspent={_spent // (60 * 60):02d}:{_spent // 60:02d}:{_spent % 60:02d},\n"
+            else:
+                spent = ""
         else:
             started = ""
+            spent = ""
         return (
             f"{self.__class__.__name__}(\n"
             f"\tcmd={self.cmd!r},\n"
@@ -482,7 +498,7 @@ def __str__(self) -> str:
             f"\tstderr=\n"
             f"{self.stderr_brief!r}, \n"
             f"\texit_code={self.exit_code!s},\n"
-            f"{started})"
+            f"{started}{spent})"
         )
 
     def __eq__(self, other: typing.Any) -> bool:

exec_helpers/subprocess_runner.py

@@ -170,6 +170,7 @@ def close_streams() -> None:
                         f"Process {command!s} was closed with exit code {async_result.interface.returncode!s}, "
                         f"but FIFO buffers are still open"
                     )
+            result.set_timestamp()
             close_streams()
 
         wait_err_msg: str = _log_templates.CMD_WAIT_ERROR.format(result=result, timeout=timeout)

test/test_exec_result.py

@@ -208,19 +208,23 @@ def test_stdin_bytearray(self):
     def test_started(self):
         started = datetime.datetime.utcnow()
         result = exec_helpers.ExecResult(cmd, exit_code=0, started=started)
+        spent = (result.timestamp - started).seconds
         self.assertIs(result.started, started)
         self.assertEqual(
             str(result),
             "{cls}(\n\tcmd={cmd!r},"
             "\n\t stdout=\n'{stdout_brief}',"
             "\n\tstderr=\n'{stderr_brief}', "
             "\n\texit_code={exit_code!s},"
-            "\n\tstarted={started},\n)".format(
+            "\n\tstarted={started},"
+            "\n\tspent={spent},"
+            "\n)".format(
                 cls=exec_helpers.ExecResult.__name__,
                 cmd=cmd,
                 stdout_brief="",
                 stderr_brief="",
                 exit_code=proc_enums.EXPECTED,
-                started=started.strftime('%Y-%m-%d %H:%M:%S')
+                started=started.strftime("%Y-%m-%d %H:%M:%S"),
+                spent=f"{spent // (60 * 60):02d}:{spent // 60:02d}:{spent % 60:02d}",
             ),
         )