Enforce test duration across reboots and restarts

docs/releases/pending/4416.fmf

@@ -0,0 +1,7 @@
+description: |
+  Test :ref:`/spec/tests/duration` is now measured and enforced across
+  all test restarts and guest reboots. With previous tmt versions,
+  a guest reboot or test restart cleared the duration timer, and every
+  test invocation was therefore given full budget. This could lead to
+  tests running forever. From this release, tmt measures the duration
+  for the test as a whole, no matter how many times it was invoked.

spec/tests/duration.fmf

@@ -18,6 +18,14 @@ description: |
 
     Must be a ``string``. The default value is ``5m``.
 
+    .. note::
+
+       Test duration is measured and enforced for all its invocations
+       combined. Every time a test is invoked, after a
+       :ref:`/spec/tests/restart` or guest reboot, it gets only the
+       remainder of its ``duration`` limit. Limit is not refreshed by
+       these events.
+
     .. versionadded:: 1.34
         Multiplication
 

tests/execute/duration/data/test.fmf

@@ -9,18 +9,18 @@
 
 /long:
     summary: Test exceeding the duration limit
-    duration: 5s
+    duration: 30s
 
     /shell:
-        test: sleep 20s
+        test: sleep 60s
     /beakerlib:
         framework: beakerlib
         test: ./long.sh
 
 /duration-modified:
     summary: Adjust the duration in test metadata
-    duration: 2s
-    test: sleep 1s
+    duration: 20s
+    test: sleep 10s
     adjust:
       - when: slow-arch == yes
         duration+: '*2.5'

tests/execute/duration/test.sh

@@ -20,20 +20,20 @@ rlJournalStart
                 rlPhaseStartTest "Test provision $PROVISION_HOW, execute $execute_method, $tty, $interactive short tests"
                     rlRun -s "tmt $context --log-topic=command-events run --scratch -vfi $tmp -a provision -h $PROVISION_HOW execute -h $execute_method $interactive test --name short" 0
 
-                    rlRun "grep 'duration \"5\" exceeded' $tmp/log.txt" 1
+                    rlAssertNotGrep "Maximum test time .* exceeded'" $tmp/log.txt
                 rlPhaseEnd
 
                 rlPhaseStartTest "Test provision $PROVISION_HOW, execute $execute_method, $tty, $interactive long tests"
                     if [ "$interactive" = "" ]; then
                         rlRun -s "tmt $context --log-topic=command-events run --scratch -vfi $tmp -a provision -h $PROVISION_HOW execute -h $execute_method $interactive test --name long" 2
 
-                        rlAssertNotGrep "warn: Ignoring requested duration, not supported in interactive mode." $rlRun_LOG
-                        rlAssertGrep "duration limit: 5 seconds" $tmp/log.txt
+                        rlAssertNotGrep "warn: Test duration is not effective due to interactive mode." $rlRun_LOG
+                        rlAssertGrep "duration deadline: 30 seconds" $tmp/log.txt
                     else
                         rlRun -s "tmt $context --log-topic=command-events run --scratch -vfi $tmp -a provision -h $PROVISION_HOW execute -h $execute_method $interactive test --name long" 0
 
-                        rlAssertGrep "warn: Ignoring requested duration, not supported in interactive mode." $rlRun_LOG
-                        rlAssertGrep "duration limit: None" $tmp/log.txt
+                        rlAssertGrep "warn: Test duration is not effective due to interactive mode." $rlRun_LOG
+                        rlAssertGrep "duration deadline: none" $tmp/log.txt
                     fi
 
                     rlAssertNotGrep "00:02:.. errr /test/long/beakerlib (timeout)" $rlRun_LOG
@@ -42,11 +42,11 @@ rlJournalStart
                     if [ "$interactive" = "" ]; then
                         rlRun -s "tmt --log-topic=command-events run --last report -fvvvv" 2
 
-                        rlAssertGrep "Maximum test time '5s' exceeded." $rlRun_LOG
+                        rlAssertGrep "Maximum test time '30s' exceeded." $rlRun_LOG
                         rlAssertGrep "Adjust the test 'duration' attribute" $rlRun_LOG
                         rlAssertGrep "spec/tests.html#duration" $rlRun_LOG
 
-                        rlRun -s "grep -A4 'duration \"5\" exceeded' $tmp/log.txt"
+                        rlRun -s "grep -A4 'duration \"29\" exceeded' $tmp/log.txt"
 
                         rlRun "grep -E ' [[:digit:]]{1,2}\.[[:digit:]]+ sent SIGKILL signal' $rlRun_LOG"
                         rlRun "grep -E ' [[:digit:]]{1,2}\.[[:digit:]]+ kill confirmed' $rlRun_LOG"
@@ -55,11 +55,11 @@ rlJournalStart
                     else
                         rlRun -s "tmt --log-topic=command-events run --last report -fvvvv" 0
 
-                        rlAssertNotGrep "Maximum test time '5s' exceeded." $rlRun_LOG
+                        rlAssertNotGrep "Maximum test time '30s' exceeded." $rlRun_LOG
                         rlAssertNotGrep "Adjust the test 'duration' attribute" $rlRun_LOG
                         rlAssertNotGrep "spec/tests.html#duration" $rlRun_LOG
 
-                        rlAssertNotGrep "duration \"5\" exceeded" $tmp/log.txt
+                        rlAssertNotGrep "duration \"29\" exceeded" $tmp/log.txt
 
                         rlRun "grep -E ' [[:digit:]]{1,2}\.[[:digit:]]+ sent SIGKILL signal' $rlRun_LOG" 1
                         rlRun "grep -E ' [[:digit:]]{1,2}\.[[:digit:]]+ kill confirmed' $rlRun_LOG" 1
@@ -72,23 +72,23 @@ rlJournalStart
     done
 
     rlPhaseStartTest "Test duration+ and adjust-tests modifications"
-        rlRun -s "tmt -v run --scratch -i $tmp test --name duration-modified" 0 "Base duration limit, unmodified"
-        rlAssertGrep "duration limit: 2 seconds" $tmp/log.txt
+        rlRun -s "tmt -v run --scratch -i $tmp test --name duration-modified" 0 "Base duration deadline, unmodified"
+        rlAssertGrep "duration deadline: 20 seconds" $tmp/log.txt
 
-        rlRun -s "tmt -v --context slow-arch=yes run --scratch -i $tmp test --name duration-modified" 0 "Base duration limit, modified by adjust slow-arch"
-        # base duration: 2s, *2.5 from test adjust slow-arch, results in 5 sec limit
-        rlAssertGrep "duration limit: 5 seconds" $tmp/log.txt
+        rlRun -s "tmt -v --context slow-arch=yes run --scratch -i $tmp test --name duration-modified" 0 "Base duration deadline, modified by adjust slow-arch"
+        # base duration: 20s, *2.5 from test adjust slow-arch, results in 50 sec limit
+        rlAssertGrep "duration deadline: 50 seconds" $tmp/log.txt
 
-        rlRun -s "tmt -v run --scratch -i $tmp plan --name adjust-tests" 0 "Base duration limit, modified by discover adjust-tests"
-        # base duration: 2s, *2 from plan discover adjust-tests, results in 4 sec limit
-        rlAssertGrep "duration limit: 4 seconds" $tmp/log.txt
+        rlRun -s "tmt -v run --scratch -i $tmp plan --name adjust-tests" 0 "Base duration deadline, modified by discover adjust-tests"
+        # base duration: 20s, *2 from plan discover adjust-tests, results in 40 sec limit
+        rlAssertGrep "duration deadline: 40 seconds" $tmp/log.txt
 
-        rlRun -s "tmt -v --context slow-arch=yes run --scratch -i $tmp plan --name adjust-tests" 0 "Base duration limit, modified by adjust slow-arch and discover adjust-tests"
-        # base duration: 2s, *2.5 from test adjust slow-arch, *2 from plan discover adjust-tests, results in 10 sec limit
-        rlAssertGrep "duration limit: 10 seconds" $tmp/log.txt
+        rlRun -s "tmt -v --context slow-arch=yes run --scratch -i $tmp plan --name adjust-tests" 0 "Base duration deadline, modified by adjust slow-arch and discover adjust-tests"
+        # base duration: 20s, *2.5 from test adjust slow-arch, *2 from plan discover adjust-tests, results in 100 sec limit
+        rlAssertGrep "duration deadline: 100 seconds" $tmp/log.txt
 
         rlRun -s "tmt -v --context slow-arch=yes run --scratch -i $tmp --all execute --ignore-duration plan --name adjust-tests" 0 "Verify --ignore-duration"
-        rlAssertGrep "duration limit: None" $tmp/log.txt
+        rlAssertGrep "duration deadline: none" $tmp/log.txt
     rlPhaseEnd
 
     rlPhaseStartCleanup

tests/execute/reboot/data/test.fmf

@@ -1,3 +1,4 @@
 summary: Try rebooting the machine
 test: ./test.sh
 framework: beakerlib
+duration: 30m

tests/execute/reboot/out-of-session/test.fmf

@@ -1,6 +1,7 @@
 summary: Spin and observe reboot behavior
 test: ./test.sh
 framework: beakerlib
+duration: 15m
 require:
   - procps-ng
   - psmisc

tmt/steps/context/reboot.py

@@ -143,7 +143,7 @@ def handle_reboot(self, restart: Optional['RestartContext'] = None) -> bool:
             waiting = Waiting(deadline=Deadline.from_seconds(reboot_data.timeout))
 
             os.remove(self.request_path)
-            self.guest.execute(ShellScript(f'rm -f {self.request_path}'))
+            self.guest.execute(ShellScript(f'rm -f {self.request_path}'), silent=True)
 
             def _handle_run_error(error: tmt.utils.RunError) -> NoReturn:
                 if reboot_command is not None:

tmt/steps/execute/__init__.py

@@ -44,9 +44,11 @@
     CommandOutput,
     Environment,
     EnvVarValue,
+    GeneralError,
     HasEnvironment,
     HasStepWorkdir,
     Path,
+    ProcessExitCodes,
     ShellScript,
     Stopwatch,
     configure_bool_constant,
@@ -414,14 +416,24 @@ def invoke_checks_after_test(self) -> list[CheckResult]:
     def invoke_internal_checks(self) -> list[CheckResult]:
         return self.invoke_checks(CheckEvent.AFTER_TEST, CheckPlugin.internal_checks(self.logger))
 
+    @functools.cached_property
+    def deadline(self) -> tmt.utils.wait.Deadline:
+        """
+        Test duration represented as a deadline.
+        """
+
+        return tmt.utils.wait.Deadline.from_seconds(
+            tmt.utils.duration_to_seconds(self.test.duration, tmt.base.DEFAULT_TEST_DURATION_L1)
+        )
+
     def invoke_test(
         self,
         command: ShellScript,
         *,
         cwd: Path,
         log: tmt.log.LoggingFunction,
         interactive: bool,
-        timeout: Optional[int],
+        deadline: Optional[tmt.utils.wait.Deadline],
     ) -> tmt.utils.CommandOutput:
         """
         Start the command which represents the test in this invocation.
@@ -431,8 +443,8 @@ def invoke_test(
         :param interactive: if set, the command would be executed in an interactive
             manner, i.e. with stdout and stdout connected to terminal for live
             interaction with user.
-        :param timeout: if set, command would be interrupted, if still running,
-            after this many seconds.
+        :param deadline: if set, the test would be interrupted once reaching
+            this deadline.
         :param log: a logging function to use for logging of command output. By
             default, ``logger.debug`` is used.
         :returns: command output.
@@ -479,43 +491,69 @@ def _reset_process(
                 if self.on_interrupt_callback_token is not None:
                     tmt.utils.signals.remove_callback(self.on_interrupt_callback_token)
 
-        with Stopwatch() as timer:
+        def _invoke(timeout: Optional[int] = None) -> CommandOutput:
+            """
+            Actually invoke the test, and handle its immediate outcome.
+            """
+
+            output, error, timer = Stopwatch.measure(
+                self.guest.execute,
+                command,
+                cwd=cwd,
+                env=self.environment,
+                join=True,
+                interactive=interactive,
+                tty=self.test.tty,
+                log=log,
+                timeout=timeout,
+                on_process_start=_save_process,
+                on_process_end=_reset_process,
+                test_session=True,
+                friendly_command=str(self.test.test),
+                sourced_files=[self.phase.step.plan.plan_source_script],
+            )
+
             self.start_time = timer.start_time_formatted
+            self.end_time = timer.end_time_formatted
+            self.real_duration = timer.duration_formatted
 
-            try:
-                output = self.guest.execute(
-                    command,
-                    cwd=cwd,
-                    env=self.environment,
-                    join=True,
-                    interactive=interactive,
-                    tty=self.test.tty,
-                    log=log,
-                    timeout=timeout,
-                    on_process_start=_save_process,
-                    on_process_end=_reset_process,
-                    test_session=True,
-                    friendly_command=str(self.test.test),
-                    sourced_files=[self.phase.step.plan.plan_source_script],
-                )
+            if error is not None:
+                self.exceptions.append(error)
+
+                if isinstance(error, tmt.utils.RunError):
+                    output = error.output
+
+                    self.return_code = error.returncode
+
+                else:
+                    raise error
 
+            elif output is not None:
                 self.return_code = tmt.utils.ProcessExitCodes.SUCCESS
 
-            except tmt.utils.RunError as error:
-                self.exceptions.append(error)
+            else:
+                raise GeneralError('Command produced no output but raised no exception.')
+
+            return output
 
-                output = error.output
+        if deadline is None:
+            output = _invoke()
+
+        else:
+            with deadline:
+                if deadline.is_due:
+                    self.return_code = ProcessExitCodes.TIMEOUT
 
-                self.return_code = error.returncode
+                    output = CommandOutput(None, None)
 
-                if self.return_code == tmt.utils.ProcessExitCodes.TIMEOUT:
-                    self.logger.debug(f"Test duration '{self.test.duration}' exceeded.")
+                else:
+                    output = _invoke(int(deadline.time_left.total_seconds()))
 
-                elif tmt.utils.ProcessExitCodes.is_pidfile(self.return_code):
-                    self.logger.warning('Test failed to manage its pidfile.')
+        if self.return_code == tmt.utils.ProcessExitCodes.TIMEOUT:
+            self.logger.debug(f"Test duration '{self.test.duration}' exceeded.")
 
-        self.end_time = timer.end_time_formatted
-        self.real_duration = timer.duration_formatted
+        elif tmt.utils.ProcessExitCodes.is_pidfile(self.return_code):
+            self.logger.warning('Test failed to manage its pidfile.')
 
         return output
 

tmt/steps/execute/internal.py

@@ -14,6 +14,7 @@
 import tmt.utils
 import tmt.utils.signals
 import tmt.utils.themes
+import tmt.utils.wait
 from tmt.container import container, field
 from tmt.result import Result, ResultOutcome
 from tmt.steps import safe_filename
@@ -375,40 +376,41 @@ def _test_output_logger(
         invocation.check_results = invocation.invoke_checks_before_test()
 
         # Pick the proper timeout for the test
-        timeout: Optional[int]
+        deadline: Optional[tmt.utils.wait.Deadline]
 
         if self.data.interactive:
-            if test.duration:
-                logger.warning('Ignoring requested duration, not supported in interactive mode.')
+            logger.warning('Test duration is not effective due to interactive mode.')
+            logger.info('duration deadline', 'none')
 
-            timeout = None
+            deadline = None
 
         elif self.data.ignore_duration:
             logger.debug("Test duration is not effective due to ignore-duration option.")
-            timeout = None
+            logger.info('duration deadline', 'none')
 
-        else:
-            timeout = tmt.utils.duration_to_seconds(
-                test.duration, tmt.base.DEFAULT_TEST_DURATION_L1
-            )
+            deadline = None
 
-        if logger.verbosity_level >= 1:
-            shift = 1 if self.verbosity_level < 2 else 2
-            logger.verbose(
-                'duration limit',
-                f"{timeout}{' seconds' if timeout is not None else ''}",
-                color="yellow",
-                shift=shift,
-                level=1,
-            )
+        else:
+            deadline = invocation.deadline
+
+            if logger.verbosity_level >= 1:
+                with deadline:
+                    logger.verbose(
+                        'duration deadline',
+                        f'{deadline.time_left.total_seconds():.0f} seconds,'
+                        f' at {deadline.due_at.strftime("%H:%M:%S %Y-%m-%d %Z")}',
+                        color="yellow",
+                        shift=1 if self.verbosity_level < 2 else 2,
+                        level=1,
+                    )
 
         # And invoke the test process.
         output = invocation.invoke_test(
             remote_command,
             cwd=workdir,
             interactive=self.data.interactive,
             log=_test_output_logger,
-            timeout=timeout,
+            deadline=deadline,
         )
 
         # Save the captured output. Do not let the follow-up pulls

tmt/steps/provision/__init__.py

@@ -560,7 +560,7 @@ class BootMarkBootTime(BootMark):
 
     @classmethod
     def fetch(cls, guest: 'Guest') -> str:
-        stdout = guest.execute(Command("cat", "/proc/stat")).stdout
+        stdout = guest.execute(Command("cat", "/proc/stat"), silent=True).stdout
 
         assert stdout