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/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"] diff --git a/qase-tavern/src/qase/tavern/plugin.py b/qase-tavern/src/qase/tavern/plugin.py index 028d7e8d..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 @@ -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, 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"