From 114fd10a32994576d6ddc1032ac909182385493e Mon Sep 17 00:00:00 2001 From: Dmitrii Gridnev Date: Mon, 25 May 2026 19:48:19 +0300 Subject: [PATCH 1/3] fix: measure tavern stage timings via beta request/response hooks Steps were created up-front in start_pytest_item with StepExecution() auto-stamping start_time, and then all closed in a single pytest_runtest_makereport loop, so every stage of a multi-stage Tavern test ended up with identical start_time, end_time and a duration equal to the full test length. The TestOps timeline could not show stage ordering or per-stage runtime. Hook into Tavern's pluggy hooks: - pytest_tavern_beta_before_every_request stamps start_time on the step that matches the current stage index. - pytest_tavern_beta_after_every_response calls execution.complete() on that step and advances the cursor. Replace the unconditional execution.complete() calls in pytest_runtest_makereport with _ensure_step_closed(), which respects timings already set by the hooks and falls back to a zero-duration placeholder for steps that never ran (skip-after-failure, etc.). Add a test_multistage.tavern.yaml example demonstrating sequential stages with delay_before between them, and unit tests covering hook ordering, the extra-hook-after-last-stage guard, and _ensure_step_closed. --- .../single/tavern/test_multistage.tavern.yaml | 57 +++++++++ qase-tavern/src/qase/tavern/plugin.py | 54 +++++++-- qase-tavern/tests/test_plugin.py | 108 ++++++++++++++++++ 3 files changed, 212 insertions(+), 7 deletions(-) create mode 100644 examples/single/tavern/test_multistage.tavern.yaml diff --git a/examples/single/tavern/test_multistage.tavern.yaml b/examples/single/tavern/test_multistage.tavern.yaml new file mode 100644 index 00000000..de0e7a5b --- /dev/null +++ b/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 diff --git a/qase-tavern/src/qase/tavern/plugin.py b/qase-tavern/src/qase/tavern/plugin.py index 028d7e8d..591c9508 100644 --- a/qase-tavern/src/qase/tavern/plugin.py +++ b/qase-tavern/src/qase/tavern/plugin.py @@ -21,6 +21,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 +33,27 @@ def pytest_sessionfinish(self, session, exitstatus): def pytest_runtest_protocol(self, item): self.start_pytest_item(item) + 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() + + 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 +73,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 +123,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, diff --git a/qase-tavern/tests/test_plugin.py b/qase-tavern/tests/test_plugin.py index 80e76d55..07af8df5 100644 --- a/qase-tavern/tests/test_plugin.py +++ b/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" From 8397e7f5178b3d0500a74a3b2bafe7cad8f61b29 Mon Sep 17 00:00:00 2001 From: Dmitrii Gridnev Date: Mon, 25 May 2026 19:48:19 +0300 Subject: [PATCH 2/3] chore: bump qase-tavern to 3.1.1 --- qase-tavern/pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/qase-tavern/pyproject.toml b/qase-tavern/pyproject.toml index a973304c..84e33da7 100644 --- a/qase-tavern/pyproject.toml +++ b/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"] From b41216440e4038b9ceaceb981030961bf29ff738 Mon Sep 17 00:00:00 2001 From: Dmitrii Gridnev Date: Mon, 25 May 2026 20:21:54 +0300 Subject: [PATCH 3/3] fix: mark tavern beta hooks as optional for pluggy validation Adding pytest_tavern_beta_before_every_request and pytest_tavern_beta_after_every_response as plain methods on QasePytestPlugin makes pluggy refuse to load the plugin when the Tavern package isn't installed, because the matching hookspecs are only registered when tavern itself is imported. The tox testing environment installs only qase-tavern + pytest, so CI fails with: PluginValidationError: unknown hook 'pytest_tavern_beta_after_every_response' in plugin Decorate both hooks with @pytest.hookimpl(optionalhook=True) so pluggy skips the unknown-hook check; the hooks still fire when Tavern is present at runtime. --- qase-tavern/src/qase/tavern/plugin.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/qase-tavern/src/qase/tavern/plugin.py b/qase-tavern/src/qase/tavern/plugin.py index 591c9508..9820d068 100644 --- a/qase-tavern/src/qase/tavern/plugin.py +++ b/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 @@ -33,6 +35,11 @@ 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. @@ -45,6 +52,7 @@ def pytest_tavern_beta_before_every_request(self, request_args): 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: