From 1a57247510dbaa1b84dda9c3214e9ef27b55c29e Mon Sep 17 00:00:00 2001 From: Dmitrii Gridnev Date: Tue, 26 May 2026 10:34:01 +0300 Subject: [PATCH 1/2] fix: anchor behave step start_time to formatter.step() callback MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit parse_step computed ``start_time = current_time - step.duration``, where ``current_time`` was the moment of behave's ``formatter.result()`` callback. That callback fires after the ``after_step`` hook, so any hook latency inflated both the recorded start_time and end_time of every step — the durations stayed correct but absolute timestamps drifted forward by the cumulative hook overhead. In a scenario with a 200 ms ``after_step``, the first step appeared to start 200 ms into the scenario rather than at the scenario boundary. Capture wall-clock in ``QaseFormatter.step()`` (behave's "right before this step executes" formatter hook) and pass it explicitly to parse_step via a new ``start_time`` argument. Compute end_time as ``start_time + step.duration`` so the recorded window matches the real step body and excludes after_step latency. Clear the slot in ``result()`` and on every new ``scenario()`` so state can't leak. Fall back to the previous "now - duration" path when no start_time is supplied (e.g. BehaveX JSON replay, third-party callers). --- qase-behave/src/qase/behave/formatter.py | 17 ++++++- qase-behave/src/qase/behave/utils.py | 28 ++++++++--- qase-behave/tests/test_formatter.py | 60 ++++++++++++++++++++++++ qase-behave/tests/test_utils.py | 51 ++++++++++++++++++++ 4 files changed, 149 insertions(+), 7 deletions(-) diff --git a/qase-behave/src/qase/behave/formatter.py b/qase-behave/src/qase/behave/formatter.py index a791a015..201a5f0b 100644 --- a/qase-behave/src/qase/behave/formatter.py +++ b/qase-behave/src/qase/behave/formatter.py @@ -26,6 +26,7 @@ def __init__(self, stream_opener=None, config=None): self.__already_started = False self.__case_ids = [] self.__current_scenario = None + self.__current_step_start = None if not self._behavex_mode: super().__init__(stream_opener, config) @@ -79,9 +80,23 @@ def scenario(self, scenario: Scenario): self.__current_scenario = parse_scenario(scenario) qase._set_current_scenario(self.__current_scenario) qase._set_current_step(None) + self.__current_step_start = None + + def step(self, step): + """Capture the real wall-clock start of the upcoming step. + + Behave calls ``formatter.step()`` immediately before executing + the step (after ``before_step`` hooks). Without this, parse_step + would later derive ``start_time = result_callback_time - duration``, + which absorbs any ``after_step`` hook latency into the next + step's absolute timestamps. + """ + from qase.commons.utils import QaseUtils + self.__current_step_start = QaseUtils.get_real_time() def result(self, result: Step): - step = parse_step(result) + step = parse_step(result, start_time=self.__current_step_start) + self.__current_step_start = None qase._set_current_step(step) if step.execution.status != 'passed': diff --git a/qase-behave/src/qase/behave/utils.py b/qase-behave/src/qase/behave/utils.py index 07e5718b..19000c32 100644 --- a/qase-behave/src/qase/behave/utils.py +++ b/qase-behave/src/qase/behave/utils.py @@ -273,15 +273,23 @@ def parse_step_from_json(step_dict: dict, time_offset: float = 0.0) -> QaseStep: return model -def parse_step(step: Step) -> QaseStep: +def parse_step(step: Step, start_time: float = None) -> QaseStep: + """Build a Qase Step model from a behave step result. + + ``start_time`` is the wall-clock instant captured by + ``QaseFormatter.step()`` just before behave handed control to the + step body — it excludes ``after_step`` hook latency that would + otherwise contaminate every subsequent step's start_time. + + If no ``start_time`` is supplied (legacy callers, BehaveX JSON + replay) fall back to ``now - step.duration``. + """ model = QaseStep( step_type=StepType.GHERKIN, id=str(uuid.uuid4()), data=StepGherkinData(keyword=step.keyword, name=step.name, line=step.line) ) - current_time = QaseUtils.get_real_time() - # Map behave status to qase status status_mapping = { 'passed': 'passed', @@ -290,10 +298,18 @@ def parse_step(step: Step) -> QaseStep: 'undefined': 'skipped', 'pending': 'skipped' } - model.execution.set_status(status_mapping.get(step.status.name, 'skipped')) - model.execution.start_time = current_time - step.duration model.execution.duration = int(step.duration * 1000) - model.execution.end_time = current_time + + if start_time is not None: + # Anchor to the real moment behave called formatter.step(); use + # behave's recorded duration for end_time so any after_step hook + # latency in the result() callback doesn't inflate end_time. + model.execution.start_time = start_time + model.execution.end_time = start_time + step.duration + else: + current_time = QaseUtils.get_real_time() + model.execution.end_time = current_time + model.execution.start_time = current_time - step.duration return model diff --git a/qase-behave/tests/test_formatter.py b/qase-behave/tests/test_formatter.py index 17e71a4f..b8c24a46 100644 --- a/qase-behave/tests/test_formatter.py +++ b/qase-behave/tests/test_formatter.py @@ -337,6 +337,66 @@ def test_offset_lands_earliest_near_now(self): assert before - 1000.0 <= offset <= after - 1000.0 +class TestFormatterStepCallback: + """``formatter.step()`` is behave's only "right before this step runs" + hook from a formatter's perspective. Capturing the wall-clock at that + instant and passing it to parse_step is what prevents after_step hook + latency from leaking into the next step's absolute start_time. + """ + + def _make_formatter(self): + formatter = QaseFormatter() + formatter._behavex_mode = False # exercise the standard path + formatter.reporter = MagicMock() + formatter._QaseFormatter__current_scenario = MagicMock() + formatter._QaseFormatter__current_scenario.ignore = False + formatter._QaseFormatter__current_scenario.steps = [] + return formatter + + def test_step_stores_start_time(self): + formatter = self._make_formatter() + formatter._QaseFormatter__current_step_start = None + + formatter.step(MagicMock()) + + assert formatter._QaseFormatter__current_step_start is not None + assert formatter._QaseFormatter__current_step_start > 0 + + def test_result_passes_stored_start_to_parse_step(self): + formatter = self._make_formatter() + formatter._QaseFormatter__current_step_start = 12345.6 + + captured = {} + + def fake_parse_step(step, start_time=None): + captured['start_time'] = start_time + qstep = MagicMock() + qstep.execution.status = 'passed' + return qstep + + step_result = MagicMock() + step_result.error_message = None + + with patch('qase.behave.formatter.parse_step', side_effect=fake_parse_step): + formatter.result(step_result) + + assert captured['start_time'] == 12345.6 + # And the slot is cleared so a subsequent step doesn't reuse it. + assert formatter._QaseFormatter__current_step_start is None + + def test_scenario_resets_step_start(self): + """When a new scenario begins, any leftover step-start from the + previous scenario must be discarded so it can't leak across.""" + formatter = self._make_formatter() + formatter._QaseFormatter__current_step_start = 42.0 + formatter._QaseFormatter__current_scenario = None # no prior scenario to flush + + with patch('qase.behave.formatter.parse_scenario', return_value=MagicMock(ignore=False)): + formatter.scenario(MagicMock()) + + assert formatter._QaseFormatter__current_step_start is None + + class TestBehaveXWorkerMode: """Test QaseFormatter in BehaveX worker mode (lock file coordination).""" diff --git a/qase-behave/tests/test_utils.py b/qase-behave/tests/test_utils.py index 5dfef007..822c3a30 100644 --- a/qase-behave/tests/test_utils.py +++ b/qase-behave/tests/test_utils.py @@ -352,6 +352,57 @@ def test_step_defaults(self): assert step.step_type == StepType.GHERKIN +class TestParseStepRealTimeStart: + """parse_step must anchor timestamps to a wall-clock instant supplied + by the formatter, rather than deriving them from ``now() - duration``. + + Regression for the standard-behave bug where ``after_step`` hook + latency contaminated every step's absolute start_time / end_time. + """ + + def _make_step(self, duration=0.05, status_name="passed"): + step = MagicMock() + step.keyword = "Given" + step.name = "a step" + step.line = 1 + step.duration = duration + step.status.name = status_name + return step + + def test_explicit_start_time_anchors_end_to_duration(self): + step = self._make_step(duration=0.05) + + qstep = parse_step(step, start_time=1000.0) + + assert qstep.execution.start_time == 1000.0 + # end = start + behave's recorded duration — NOT current time. + assert qstep.execution.end_time == 1000.05 + assert qstep.execution.duration == 50 + + def test_explicit_start_time_excludes_callback_latency(self): + """If the formatter captured step start at T and then 5 minutes + of debugger pause elapsed before result() fired, the recorded + end_time must still be T + duration — not T + 5 minutes.""" + step = self._make_step(duration=0.1) + + qstep = parse_step(step, start_time=500.0) + # Sleeping/blocking happens between formatter.step() and + # formatter.result() — but parse_step doesn't read the clock. + import time as _t + _t.sleep(0.01) + + assert qstep.execution.end_time == 500.1 + + def test_fallback_to_now_minus_duration_when_no_start_time(self): + step = self._make_step(duration=0.2) + + qstep = parse_step(step) + + assert qstep.execution.duration == 200 + assert qstep.execution.end_time > 1_000_000 # current unix time + assert abs(qstep.execution.end_time - qstep.execution.start_time - 0.2) < 0.05 + + class TestBehavexAbsoluteTimestamps: """When BehaveX records ``start`` / ``stop`` (unix-ms), the parsed Result/Step must use those timestamps (shifted by ``time_offset``) From ce09e90920d94baf692b1b15ec21ee9de4cde3b7 Mon Sep 17 00:00:00 2001 From: Dmitrii Gridnev Date: Tue, 26 May 2026 10:34:01 +0300 Subject: [PATCH 2/2] chore: bump qase-behave to 3.2.2 --- qase-behave/pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/qase-behave/pyproject.toml b/qase-behave/pyproject.toml index b4f93fd4..55c14329 100644 --- a/qase-behave/pyproject.toml +++ b/qase-behave/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "qase-behave" -version = "3.2.1" +version = "3.2.2" description = "Qase Behave Plugin for Qase TestOps and Qase Report" readme = "README.md" keywords = ["qase", "behave", "plugin", "testops", "report", "qase reporting", "test observability"]