From 70f3ae8122cb6f93f03c973f68c5acfcfef443ee Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 13:27:02 +0200 Subject: [PATCH 01/11] Added more info about time steps. Trying to prevent timeouts in future. --- goth/runner/step.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 513adcf61..bd739f281 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -10,7 +10,6 @@ if TYPE_CHECKING: from goth.runner.probe import Probe - logger = logging.getLogger(__name__) @@ -48,6 +47,14 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): step_time, ) raise + step_time = time.time() - start_time + logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) + if timeout - step_time < 5: + logger.warning( + "Step '%s' was very close to being timed out: %.1f s. Consider increasing time limit for this step.", + step_name, + timeout - step_time, + ) return result return wrapper From 9650432657a9f3af2dabec325d9f02307b40ec0e Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:14:07 +0200 Subject: [PATCH 02/11] fix formatting --- goth/runner/step.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index bd739f281..4fc56eec0 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -51,7 +51,8 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) if timeout - step_time < 5: logger.warning( - "Step '%s' was very close to being timed out: %.1f s. Consider increasing time limit for this step.", + "Step '%s' was very close to being timed out: %.1f s." + "Consider increasing time limit for this step.", step_name, timeout - step_time, ) From da0698c40d15eb0d46085c87db7c58d21326c200 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:17:59 +0200 Subject: [PATCH 03/11] added timeout warning to error step also --- goth/runner/step.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 4fc56eec0..beb73b070 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -12,6 +12,7 @@ logger = logging.getLogger(__name__) +TIMEOUT_LEFT_WARNING_THRESHOLD = 10 def step(default_timeout: float = 10.0): """Wrap a step function to implement timeout and log progress.""" @@ -41,15 +42,23 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): except Exception as exc: step_time = time.time() - start_time logger.error( - "Step '%s' raised %s in %.1f", + "Step '%s' raised %s in %.1f/%.1f s", step_name, exc.__class__.__name__, step_time, + timeout, ) + if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: + logger.warning( + "Step '%s' was very close to being timed out: %.1f s." + "Consider increasing time limit for this step.", + step_name, + timeout - step_time, + ) raise step_time = time.time() - start_time logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) - if timeout - step_time < 5: + if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: logger.warning( "Step '%s' was very close to being timed out: %.1f s." "Consider increasing time limit for this step.", From 3c369e4b6316080c6ed215bee4634fc01bfaf552 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:21:13 +0200 Subject: [PATCH 04/11] fix formatting --- goth/runner/step.py | 1 + 1 file changed, 1 insertion(+) diff --git a/goth/runner/step.py b/goth/runner/step.py index beb73b070..7967e9b4e 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -14,6 +14,7 @@ TIMEOUT_LEFT_WARNING_THRESHOLD = 10 + def step(default_timeout: float = 10.0): """Wrap a step function to implement timeout and log progress.""" From 47bffbe9b647f72e3d0af1a0c20476a3b6425130 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:23:15 +0200 Subject: [PATCH 05/11] Fix formatting --- goth/runner/step.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 7967e9b4e..065e01640 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -55,7 +55,7 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): "Consider increasing time limit for this step.", step_name, timeout - step_time, - ) + ) raise step_time = time.time() - start_time logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) From ec86d609e857323715d480d8e597b19fff86ad19 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:31:18 +0200 Subject: [PATCH 06/11] Bump version --- CHANGELOG.md | 4 ++++ pyproject.toml | 2 +- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index efdc466b9..1039a99b2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Changelog +# [0.15.1] - 2023-09-11 + +- Add info & warning that help with detecting potential timeouts in tasks. + # [0.15.0] - 2023-06-28 - Fix schema IDs diff --git a/pyproject.toml b/pyproject.toml index 5c9f99d46..a52f66136 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -5,7 +5,7 @@ exclude = '/(\.eggs|\.git|\.hg|\.mypy_cache|\.nox|\.tox|\.venv|venv|\.svn|_build [tool.poetry] name = "goth" -version = "0.15.0" +version = "0.15.1" description = "Golem Test Harness - integration testing framework" authors = ["Golem Factory "] license = "GPL-3.0" From 9fdca607d9ef6bad9f4cec38d3acceb237ef77e7 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:32:00 +0200 Subject: [PATCH 07/11] timeout treshhold reduced to 5 seconds --- goth/runner/step.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 065e01640..947a3c2c7 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -12,7 +12,7 @@ logger = logging.getLogger(__name__) -TIMEOUT_LEFT_WARNING_THRESHOLD = 10 +TIMEOUT_LEFT_WARNING_THRESHOLD = 5 def step(default_timeout: float = 10.0): From 9fee92c40bf24dd1dd6d0f4163f6e6620cf2caf1 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:45:40 +0200 Subject: [PATCH 08/11] Move to func --- goth/runner/step.py | 26 ++++++++++++-------------- 1 file changed, 12 insertions(+), 14 deletions(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 947a3c2c7..d454b7c95 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -15,6 +15,16 @@ TIMEOUT_LEFT_WARNING_THRESHOLD = 5 +def check_timeout_and_warn(step_name, step_time, timeout) + if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: + logger.warning( + "Step '%s' was very close to being timed out: %.1f s." + "Consider increasing time limit for this step.", + step_name, + timeout - step_time, + ) + + def step(default_timeout: float = 10.0): """Wrap a step function to implement timeout and log progress.""" @@ -49,23 +59,11 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): step_time, timeout, ) - if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: - logger.warning( - "Step '%s' was very close to being timed out: %.1f s." - "Consider increasing time limit for this step.", - step_name, - timeout - step_time, - ) + check_timeout_and_warn(step_name, step_time, timeout) raise step_time = time.time() - start_time logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) - if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: - logger.warning( - "Step '%s' was very close to being timed out: %.1f s." - "Consider increasing time limit for this step.", - step_name, - timeout - step_time, - ) + check_timeout_and_warn(step_name, step_time, timeout) return result return wrapper From 345da4d60b684688b922702e53629e0bef1a4d7d Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:46:11 +0200 Subject: [PATCH 09/11] Move to func --- goth/runner/step.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index d454b7c95..ae71ffe92 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -15,7 +15,7 @@ TIMEOUT_LEFT_WARNING_THRESHOLD = 5 -def check_timeout_and_warn(step_name, step_time, timeout) +def check_timeout_and_warn(step_name, step_time, timeout): if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: logger.warning( "Step '%s' was very close to being timed out: %.1f s." From 10e85006759ad89794d30fa6123d5208ff150411 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 14:48:26 +0200 Subject: [PATCH 10/11] Added types --- goth/runner/step.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index ae71ffe92..586a1b73f 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -12,10 +12,10 @@ logger = logging.getLogger(__name__) -TIMEOUT_LEFT_WARNING_THRESHOLD = 5 +TIMEOUT_LEFT_WARNING_THRESHOLD = 5.0 -def check_timeout_and_warn(step_name, step_time, timeout): +def check_timeout_and_warn(step_name: str, step_time: float, timeout: float): if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: logger.warning( "Step '%s' was very close to being timed out: %.1f s." From f399163b9f3882cca4ca4152c06aed57b916ca67 Mon Sep 17 00:00:00 2001 From: scx1332 Date: Mon, 11 Sep 2023 15:20:32 +0200 Subject: [PATCH 11/11] Minor fix --- goth/runner/step.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/goth/runner/step.py b/goth/runner/step.py index 586a1b73f..899784f68 100644 --- a/goth/runner/step.py +++ b/goth/runner/step.py @@ -15,11 +15,11 @@ TIMEOUT_LEFT_WARNING_THRESHOLD = 5.0 -def check_timeout_and_warn(step_name: str, step_time: float, timeout: float): +def _check_timeout_and_warn(step_name: str, step_time: float, timeout: float): if timeout - step_time < TIMEOUT_LEFT_WARNING_THRESHOLD: logger.warning( "Step '%s' was very close to being timed out: %.1f s." - "Consider increasing time limit for this step.", + " - consider increasing time limit for this step.", step_name, timeout - step_time, ) @@ -59,11 +59,11 @@ async def wrapper(self: "Probe", *args, timeout: Optional[float] = None): step_time, timeout, ) - check_timeout_and_warn(step_name, step_time, timeout) + _check_timeout_and_warn(step_name, step_time, timeout) raise step_time = time.time() - start_time logger.info("Step '%s' finished: %.1f/%.1f s", step_name, step_time, timeout) - check_timeout_and_warn(step_name, step_time, timeout) + _check_timeout_and_warn(step_name, step_time, timeout) return result return wrapper