Skip to content

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

Merged
gibiw merged 2 commits into
mainfrom
fix/behave-step-timings
May 26, 2026
Merged

fix: anchor behave step start_time to formatter.step() callback#496
gibiw merged 2 commits into
mainfrom
fix/behave-step-timings

Conversation

@gibiw
Copy link
Copy Markdown
Contributor

@gibiw gibiw commented May 26, 2026

Summary

  • 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 — 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 = start_time + step.duration so the 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 across.
  • Falls back to the old now - duration path when no start_time is supplied (BehaveX JSON replay path from fix: preserve behavex absolute timestamps when replaying JSON #494, third-party callers).
  • Bumps qase-behave to 3.2.2.

Test plan

  • Added TestParseStepRealTimeStart in test_utils.py (3 cases): explicit start anchors end = start + duration; explicit start excludes callback latency; fallback path preserved when no start_time.
  • Added TestFormatterStepCallback in test_formatter.py (3 cases): step() stores wall-clock; result() forwards the stored value to parse_step and clears the slot; scenario() resets the slot to prevent leakage.
  • pytest qase-behave/tests/ -v → 86 passed locally (Python 3.12).
  • End-to-end verified against TestOps project DEVX with a 3-step scenario whose environment.py sleeps 200 ms in after_step:
    • Before fix (run #886): first step shows start_time +0.204 s relative to scenario start (200 ms drift); end_time is also +0.257 s (200 ms past real step end).
    • After fix (run #887): first step start_time is +0.0003 s relative to scenario start; end_time is +0.055 s — matches the real 50 ms step body, drift removed.
  • CI green on all supported Python versions.

gibiw added 2 commits May 26, 2026 10:34
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).
@gibiw gibiw merged commit 5c74fd4 into main May 26, 2026
37 checks passed
@gibiw gibiw deleted the fix/behave-step-timings branch May 26, 2026 08:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant