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

(cherry picked from commit 06f1650)

Author: penguinolog

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

@@ -718,6 +718,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 = _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

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

exec_helpers/exec_result.py

@@ -97,7 +97,7 @@ def __init__(
             self._stderr = ()
 
         self.__exit_code = proc_enums.INVALID  # type: typing.Union[int, proc_enums.ExitCodes]
-        self.__timestamp = None
+        self.__timestamp = None  # type: typing.Optional[datetime.datetime]
         self.exit_code = exit_code
 
         self.__started = started  # type: typing.Optional[datetime.datetime]
@@ -139,6 +139,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.
@@ -370,7 +380,7 @@ def exit_code(self, new_val: typing.Union[int, proc_enums.ExitCodes]) -> None:
         with self.stdout_lock, self.stderr_lock:
             self.__exit_code = proc_enums.exit_code_to_enum(new_val)
             if self.__exit_code != proc_enums.INVALID:
-                self.__timestamp = datetime.datetime.utcnow()  # type: ignore
+                self.__timestamp = datetime.datetime.utcnow()
 
     @property
     def started(self) -> typing.Optional[datetime.datetime]:
@@ -471,20 +481,31 @@ def __str__(self) -> str:
         """Representation for logging."""
         if self.started:
             started = "\tstarted={started},\n".format(started=self.started.strftime('%Y-%m-%d %H:%M:%S'))
+            if self.timestamp:
+                _spent = (self.timestamp - self.started).seconds
+                spent = "\tspent={hours:02d}:{minutes:02d}:{seconds:02d},\n".format(
+                    hours=_spent // (60 * 60),
+                    minutes=_spent // 60,
+                    seconds=_spent % 60
+                )
+            else:
+                spent = ""
         else:
             started = ""
+            spent = ""
         return (
             "{cls}(\n\tcmd={cmd!r},"
             "\n\t stdout=\n'{stdout_brief}',"
             "\n\tstderr=\n'{stderr_brief}', "
             "\n\texit_code={exit_code!s},"
-            "\n{started})".format(
+            "\n{started}{spent})".format(
                 cls=self.__class__.__name__,
                 cmd=self.cmd,
                 stdout_brief=self.stdout_brief,
                 stderr_brief=self.stderr_brief,
                 exit_code=self.exit_code,
-                started=started
+                started=started,
+                spent=spent
             )
         )
 

exec_helpers/subprocess_runner.py

@@ -171,6 +171,7 @@ def close_streams() -> None:
                             command, async_result.interface.returncode
                         )
                     )
+            result.set_timestamp()
             close_streams()
 
         wait_err_msg = _log_templates.CMD_WAIT_ERROR.format(result=result, timeout=timeout)

test/test_exec_result.py

@@ -226,19 +226,27 @@ 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="{hours:02d}:{minutes:02d}:{seconds:02d}".format(
+                    hours=spent // (60 * 60),
+                    minutes=spent // 60,
+                    seconds=spent % 60
+                ),
             ),
         )