diff --git a/avocado/core/test.py b/avocado/core/test.py index 6e7ba8eef5..bd250e2095 100644 --- a/avocado/core/test.py +++ b/avocado/core/test.py @@ -318,7 +318,12 @@ def record_and_warn(*args, **kwargs): elif isinstance(params, tuple): params, paths = params[0], params[1] self.__params = parameters.AvocadoParams(params, paths, self.__log.name) - self.timeout = self.params.get("timeout", default=self.timeout) + self.timeout = original_timeout = self.params.get( + "timeout", default=self.timeout + ) + timeout_factor = float(self.params.get("timeout_factor", default=1.0)) + if original_timeout is not None: + self.timeout = float(original_timeout) * timeout_factor self.__status = None self.__fail_reason = None @@ -346,6 +351,9 @@ def record_and_warn(*args, **kwargs): pass else: self.log.debug(" teststmpdir: %s", teststmpdir) + self.log.debug(" original timeout: %s", original_timeout) + self.log.debug(" timeout factor: %s", timeout_factor) + self.log.debug(" actual timeout: %s", self.timeout) unittest.TestCase.__init__(self, methodName=methodName) TestData.__init__(self) diff --git a/docs/source/guides/writer/chapters/writing.rst b/docs/source/guides/writer/chapters/writing.rst index 7c7e32bdd9..8cd34726cc 100644 --- a/docs/source/guides/writer/chapters/writing.rst +++ b/docs/source/guides/writer/chapters/writing.rst @@ -793,53 +793,64 @@ Setting a Test Timeout Sometimes your test suite/test might get stuck forever, and this might impact your test grid. You can account for that possibility and set up a ``timeout`` parameter for your test. The test timeout can be set through -the test parameters, as shown below. +test parameters. The included example "sleep test" contains a default +sleep time of 1 second. -:: +.. literalinclude:: ../../../../../examples/tests/sleeptest.py - sleep_length: 5 - timeout: 3 +Which can be run with a timeout (shorter the sleep time) with:: + $ avocado run -p timeout=0.5 examples/tests/sleeptest.py + JOB ID : 01f7e7e9ee82a331c1c6a6b3a939f694d9c0c948 + JOB LOG : $HOME/avocado/job-results/job-2016-11-02T11.13-01f7e7e/job.log + (1/1) examples/tests/sleeptest.py:SleepTest.test: STARTED + (1/1) examples/tests/sleeptest.py:SleepTest.test: INTERRUPTED: Test interrupted: Timeout reached (0.53 s) + RESULTS : PASS 0 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 1 + JOB TIME : 2.14 s + JOB HTML : $HOME/avocado/job-results/job-2016-11-02T11.13-01f7e7e/html/results.html -:: +When the timeout is reached, the spawner will terminate the test +runner task, making it raise a +:class:`avocado.core.exceptions.TestInterruptedError`. The termination +process is specific to spawner implementation, for more information +see :class:`avocado.core.plugin_interfaces.Spawner.terminate_task`. - $ avocado run examples/tests/sleeptest.py --mux-yaml /tmp/sleeptest-example.yaml - JOB ID : c78464bde9072a0b5601157989a99f0ba32a288e - JOB LOG : $HOME/avocado/job-results/job-2016-11-02T11.13-c78464b/job.log - (1/1) examples/tests/sleeptest.py:SleepTest.test;run-0fc1: STARTED - (1/1) examples/tests/sleeptest.py:SleepTest.test;run-0fc1: INTERRUPTED: timeout (3.01 s) - RESULTS : PASS 0 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 1 - JOB TIME : 3.14 s - JOB HTML : $HOME/avocado/job-results/job-2016-11-02T11.13-c78464b/html/results.html +Timeout Factor +~~~~~~~~~~~~~~ +Like it was mentioned before, a test may have an (adequate) timeout, +set as a class attribute, such as in the following included example +test: -:: +.. literalinclude:: ../../../../../examples/tests/timeouttest.py - $ cat $HOME/avocado/job-results/job-2016-11-02T11.13-c78464b/job.log - 2021-10-01 15:44:53,622 job L0319 INFO | Multiplex tree representation: - 2021-10-01 15:44:53,622 job L0319 INFO | \-- run - 2021-10-01 15:44:53,622 job L0319 INFO | - 2021-10-01 15:44:53,622 job L0319 INFO | Multiplex variants (1): - 2021-10-01 15:44:53,622 job L0319 INFO | Variant run-0fc1: /run - 2021-10-01 15:44:53,622 job L0312 INFO | Temporary dir: /tmp/avocado_tmp_hp4cswyn/avocado_job_pmn___6i - 2021-10-01 15:44:53,622 job L0313 INFO | - 2021-10-01 15:44:53,622 job L0306 INFO | Job ID: 927fdc4143e9e093a485319820825faacc0f36a3 - 2021-10-01 15:44:53,622 job L0309 INFO | - 2021-10-01 15:44:54,165 selector_events L0059 DEBUG| Using selector: EpollSelector - 2021-10-01 15:44:54,622 testlogs L0094 INFO | examples/tests/sleeptest.py:SleepTest.test;run-0fc1: STARTED - 2021-10-01 15:44:57,653 testlogs L0101 INFO | examples/tests/sleeptest.py:SleepTest.test;run-0fc1: INTERRUPTED - 2021-10-01 15:44:57,654 testlogs L0103 INFO | More information in /home/jarichte/avocado/job-results/job-2021-10-01T15.44-927fdc4/test-results/1-examples_tests_sleeptest.py_SleepTest.test_run-0fc1 - 2021-10-01 15:44:57,762 job L0643 INFO | Test results available in /home/jarichte/avocado/job-results/job-2021-10-01T15.44-927fdc4 +But, depending on the environment it may be executed (maybe by a +different user, on a slower machine or more limited network), the +hardcoded timeout won't be adequate anymore. +On those circumstances, it's possible to set a "timeout factor". This +can be given as a parameter, and is pretty much a multiplier to the +timeout. Example:: + $ avocado run -p timeout_factor=2.0 examples/tests/timeouttest.py + JOB ID : 55722574664b01077dffd5504e329ad5e0062cc8 + JOB LOG : $HOME/avocado/job-results/job-2023-11-29T11.16-5572257/job.log + (1/1) examples/tests/timeouttest.py:TimeoutTest.test: STARTED + (1/1) examples/tests/timeouttest.py:TimeoutTest.test: PASS (5.01 s) + RESULTS : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0 + JOB HTML : $HOME/avocado/job-results/job-2023-11-29T11.16-5572257/results.html + JOB TIME : 7.77 s -The YAML file defines a test parameter ``timeout`` which overrides -the default test timeout. When the timeout is reached, the spawner -will terminate the test runner task, making it raise a -:class:`avocado.core.exceptions.TestInterruptedError`. The termination -process is specific to spawner implementation, for more information see -:class:`avocado.core.plugin_interfaces.Spawner.terminate_task`. +Notice how, under normal circumstances, the test would have timed out, +due to the sleep time (5.0 seconds) being larger than the timeout set +in the class attribute (``timeout = 3``). + +The actual timeout will be given in the "Test metadata" section in +test logs. For the previous test execution it shows:: + [stdlog] 2023-11-29 11:16:23,745 test L0345 DEBUG| Test metadata: + ... + [stdlog] 2023-11-29 11:16:23,746 test L0354 DEBUG| actual timeout: 6.0 Skipping Tests -------------- diff --git a/examples/tests/timeouttest.py b/examples/tests/timeouttest.py index 1d43c24a1e..3d075149ba 100644 --- a/examples/tests/timeouttest.py +++ b/examples/tests/timeouttest.py @@ -17,6 +17,6 @@ def test(self): """ This should throw a TestTimeoutError. """ - sleep_time = self.params.get("sleep_time", default=5) + sleep_time = float(self.params.get("sleep_time", default=5.0)) self.log.info("Sleeping for %.2f seconds (2 more than the timeout)", sleep_time) time.sleep(sleep_time) diff --git a/selftests/functional/basic.py b/selftests/functional/basic.py index 9a5ccd7387..788c01635f 100644 --- a/selftests/functional/basic.py +++ b/selftests/functional/basic.py @@ -511,6 +511,30 @@ def test_runner_timeout(self): # Ensure no test aborted error messages show up self.assertNotIn(b"TestAbortError: Test aborted unexpectedly", output) + def test_runner_timeout_factor(self): + cmd_line = ( + f"{AVOCADO} run --disable-sysinfo --job-results-dir " + f"{self.tmpdir.name} -p sleep_time=7 -p timeout_factor=3.0" + " -- examples/tests/timeouttest.py" + ) + result = process.run(cmd_line, ignore_status=True) + json_path = os.path.join(self.tmpdir.name, "latest", "results.json") + with open(json_path, encoding="utf-8") as json_file: + result_json = json.load(json_file) + expected_rc = exit_codes.AVOCADO_ALL_OK + unexpected_rc = exit_codes.AVOCADO_JOB_INTERRUPTED + self.assertNotEqual( + result.exit_status, + unexpected_rc, + f"Avocado result not expected (rc {unexpected_rc}):\n{result}", + ) + self.assertEqual( + result.exit_status, + expected_rc, + f"Avocado did not return rc {expected_rc}:\n{result}", + ) + self.assertNotIn("timeout", result_json["tests"][0]["fail_reason"]) + def test_silent_output(self): cmd_line = ( f"{AVOCADO} --show=none run --disable-sysinfo "