fix: measure tavern stage timings via beta request/response hooks

examples/single/tavern/test_multistage.tavern.yaml

@@ -0,0 +1,57 @@
+# Multi-stage tests used to verify per-stage step timings reach Qase TestOps.
+
+---
+test_name: QaseID=200 Multistage GET sequence
+
+stages:
+  - name: Stage 1 - Get all users
+    delay_before: 0.05
+    request:
+      url: https://jsonplaceholder.typicode.com/users
+      method: GET
+    response:
+      status_code: 200
+
+  - name: Stage 2 - Get single user
+    delay_before: 0.05
+    request:
+      url: https://jsonplaceholder.typicode.com/users/1
+      method: GET
+    response:
+      status_code: 200
+
+  - name: Stage 3 - Get posts list
+    delay_before: 0.05
+    request:
+      url: https://jsonplaceholder.typicode.com/posts
+      method: GET
+    response:
+      status_code: 200
+
+---
+test_name: QaseID=201 Multistage with longer pause between stages
+
+stages:
+  - name: First request
+    delay_before: 0.1
+    request:
+      url: https://jsonplaceholder.typicode.com/todos/1
+      method: GET
+    response:
+      status_code: 200
+
+  - name: Pause then second
+    delay_before: 0.3
+    request:
+      url: https://jsonplaceholder.typicode.com/todos/2
+      method: GET
+    response:
+      status_code: 200
+
+  - name: Pause then third
+    delay_before: 0.2
+    request:
+      url: https://jsonplaceholder.typicode.com/todos/3
+      method: GET
+    response:
+      status_code: 200

qase-tavern/pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "qase-tavern"
-version = "3.1.0"
+version = "3.1.1"
 description = "Qase Tavern Plugin for Qase TestOps and Qase Report"
 readme = "README.md"
 keywords = ["qase", "tavern", "plugin", "testops", "report", "qase reporting", "test observability"]

qase-tavern/src/qase/tavern/plugin.py

@@ -3,6 +3,8 @@
 import re
 from typing import Tuple, List
 
+import pytest
+
 from qase.commons.models import Runtime, Result, Relation, Attachment
 from qase.commons.models.relation import SuiteData
 from qase.commons.models.step import Step, StepType, StepTextData
@@ -21,6 +23,7 @@ def __init__(
         self.run_id = None
         self._current_item = None
         self.ignore = None
+        self._tavern_stage_index = 0
 
     def pytest_sessionstart(self, session):
         self.run_id = self.reporter.start_run()
@@ -32,6 +35,33 @@ def pytest_sessionfinish(self, session, exitstatus):
     def pytest_runtest_protocol(self, item):
         self.start_pytest_item(item)
 
+    # ``optionalhook=True`` prevents pluggy from refusing to load the plugin
+    # when the Tavern package isn't installed (and therefore the hookspec
+    # isn't registered) — the unit-test environment in tox installs only
+    # qase-tavern + pytest, not Tavern itself.
+    @pytest.hookimpl(optionalhook=True)
+    def pytest_tavern_beta_before_every_request(self, request_args):
+        """Mark the actual start time of the current Tavern stage.
+
+        Each stage triggers exactly one ``before_every_request`` call, so
+        we use the current stage index as a cursor into ``runtime.steps``.
+        """
+        if self.runtime.result is None:
+            return
+        steps_list = list(self.runtime.steps.values())
+        if self._tavern_stage_index < len(steps_list):
+            steps_list[self._tavern_stage_index].execution.start_time = QaseUtils.get_real_time()
+
+    @pytest.hookimpl(optionalhook=True)
+    def pytest_tavern_beta_after_every_response(self, expected, response):
+        """Mark the actual end time of the current Tavern stage and advance."""
+        if self.runtime.result is None:
+            return
+        steps_list = list(self.runtime.steps.values())
+        if self._tavern_stage_index < len(steps_list):
+            steps_list[self._tavern_stage_index].execution.complete()
+            self._tavern_stage_index += 1
+
     def pytest_runtest_makereport(self, item, call):
         if self.runtime.result is None:
             return
@@ -51,29 +81,46 @@ def pytest_runtest_makereport(self, item, call):
 
                         is_failed = False
                         for key, step in self.runtime.steps.items():
-                            step.execution.complete()
                             if step.data.action == failed_step:
-                                step.execution.set_status("failed")
+                                self._ensure_step_closed(step, "failed")
                                 is_failed = True
                                 continue
 
                             if is_failed:
-                                step.execution.set_status("skipped")
+                                self._ensure_step_closed(step, "skipped")
                                 continue
 
-                            step.execution.set_status("passed")
+                            self._ensure_step_closed(step, "passed")
                         return
 
                     for key, step in self.runtime.steps.items():
-                        step.execution.complete()
-                        step.execution.set_status("skipped")
+                        self._ensure_step_closed(step, "skipped")
 
                 return
 
             self.runtime.result.execution.status = "passed"
             for key, step in self.runtime.steps.items():
+                self._ensure_step_closed(step, "passed")
+
+    @staticmethod
+    def _ensure_step_closed(step, status):
+        """Close a step without overwriting timings already set by Tavern hooks.
+
+        ``pytest_tavern_beta_after_every_response`` calls ``complete()`` for
+        every stage that actually ran, so we must not stamp the test-end
+        time on top of that. Steps that never executed (skipped after a
+        failure, or no hook fired) get a zero-duration placeholder at
+        ``now`` so the timeline doesn't show them spanning the full test.
+        """
+        if not step.execution.end_time:
+            if status == "skipped":
+                now = QaseUtils.get_real_time()
+                step.execution.start_time = now
+                step.execution.end_time = now
+                step.execution.duration = 0
+            else:
                 step.execution.complete()
-                step.execution.set_status("passed")
+        step.execution.set_status(status)
 
     def pytest_runtest_logfinish(self):
         if self.runtime.result is None:
@@ -84,6 +131,7 @@ def pytest_runtest_logfinish(self):
         self.runtime.clear()
 
     def start_pytest_item(self, item):
+        self._tavern_stage_index = 0
         qase_ids, project_ids, title, tags = self.extract_qase_ids(self._get_title(item))
         self.runtime.result = Result(
             title=title,

qase-tavern/tests/test_plugin.py

@@ -245,3 +245,111 @@ def test_tags_case_insensitive(self):
             "qasetags.smoke Test"
         )
         assert tags == ["smoke"]
+
+
+# ---------------------------------------------------------------------------
+# pytest_tavern_beta_* hooks -- per-stage timing
+# ---------------------------------------------------------------------------
+
+
+class TestTavernBetaHooksTiming:
+    """Each Tavern stage must carry its own start_time/end_time.
+
+    Regression for the bug where all Step() objects were created up-front
+    in start_pytest_item (so they shared one start_time), and then closed
+    in a single makereport loop (so they shared one end_time), making the
+    TestOps timeline collapse all stages onto the same instant.
+    """
+
+    def _plugin_with_steps(self, stages):
+        """Create a plugin with one Step per stage and a fresh stage index."""
+        plugin = _make_plugin(with_result=True)
+        from qase.commons.models.step import Step, StepType, StepTextData
+
+        for name in stages:
+            step = Step(StepType.TEXT, name, StepTextData(name))
+            plugin.runtime.add_step(step)
+        plugin._tavern_stage_index = 0
+        return plugin
+
+    def test_each_stage_gets_distinct_timings(self):
+        plugin = self._plugin_with_steps(["s1", "s2", "s3"])
+
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        starts = [s.execution.start_time for s in plugin.runtime.steps.values()]
+        ends = [s.execution.end_time for s in plugin.runtime.steps.values()]
+
+        # Hooks fire in real time, so each start must be >= the previous end.
+        assert starts[0] < ends[0] <= starts[1] < ends[1] <= starts[2] < ends[2]
+        # And no two steps share the same start/end.
+        assert len(set(starts)) == 3
+        assert len(set(ends)) == 3
+
+    def test_hooks_advance_only_one_stage_per_pair(self):
+        plugin = self._plugin_with_steps(["s1", "s2"])
+
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        assert plugin._tavern_stage_index == 1
+        # s2 must still be untouched by hooks.
+        s2 = list(plugin.runtime.steps.values())[1]
+        # complete() sets end_time to float; un-completed default is 0.
+        assert s2.execution.end_time == 0
+
+    def test_extra_hook_calls_after_last_stage_are_ignored(self):
+        """If Tavern fires more hooks than we have steps (e.g. MQTT multiple
+        responses) we must not crash or wrap around to the first step."""
+        plugin = self._plugin_with_steps(["only"])
+
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        original_end = list(plugin.runtime.steps.values())[0].execution.end_time
+
+        # One extra spurious pair — must not touch the existing step.
+        plugin.pytest_tavern_beta_before_every_request(request_args={})
+        plugin.pytest_tavern_beta_after_every_response(expected={}, response=None)
+
+        assert list(plugin.runtime.steps.values())[0].execution.end_time == original_end
+
+    def test_ensure_step_closed_skips_already_closed(self):
+        plugin = _make_plugin(with_result=True)
+        from qase.commons.models.step import Step, StepType, StepTextData
+
+        step = Step(StepType.TEXT, "s", StepTextData("s"))
+        step.execution.start_time = 100.0
+        step.execution.end_time = 100.5
+        step.execution.duration = 500
+
+        plugin._ensure_step_closed(step, "passed")
+
+        # Original timings preserved; only status updated.
+        assert step.execution.start_time == 100.0
+        assert step.execution.end_time == 100.5
+        assert step.execution.duration == 500
+        assert step.execution.status == "passed"
+
+    def test_ensure_step_closed_marks_unrun_skipped_as_zero_duration(self):
+        plugin = _make_plugin(with_result=True)
+        from qase.commons.models.step import Step, StepType, StepTextData
+
+        step = Step(StepType.TEXT, "s", StepTextData("s"))
+        original_start = step.execution.start_time  # set by StepExecution.__init__
+
+        plugin._ensure_step_closed(step, "skipped")
+
+        # Step never ran — give it a zero-duration placeholder at "now",
+        # not a duration spanning the whole test.
+        assert step.execution.start_time != original_start
+        assert step.execution.start_time == step.execution.end_time
+        assert step.execution.duration == 0
+        assert step.execution.status == "skipped"