fix: anchor behave step start_time to formatter.step() callback

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"]

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':

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

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)."""
 

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``)