diff --git a/doc/source/ExecResult.rst b/doc/source/ExecResult.rst index 569c18d..da23f7e 100644 --- a/doc/source/ExecResult.rst +++ b/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`` diff --git a/exec_helpers/_ssh_client_base.py b/exec_helpers/_ssh_client_base.py index 4266ae2..235f8ce 100644 --- a/exec_helpers/_ssh_client_base.py +++ b/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 diff --git a/exec_helpers/async_api/subprocess_runner.py b/exec_helpers/async_api/subprocess_runner.py index 4ec6f90..887428a 100644 --- a/exec_helpers/async_api/subprocess_runner.py +++ b/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) diff --git a/exec_helpers/exec_result.py b/exec_helpers/exec_result.py index b8b79d7..fc3ec85 100644 --- a/exec_helpers/exec_result.py +++ b/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: diff --git a/exec_helpers/subprocess_runner.py b/exec_helpers/subprocess_runner.py index db3d1b6..d7463a5 100644 --- a/exec_helpers/subprocess_runner.py +++ b/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) diff --git a/test/test_exec_result.py b/test/test_exec_result.py index c03376b..dd3f118 100644 --- a/test/test_exec_result.py +++ b/test/test_exec_result.py @@ -208,6 +208,7 @@ 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), @@ -215,12 +216,15 @@ def test_started(self): "\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}", ), )