fix: anchor behave step start_time to formatter.step() callback#496
Merged
Conversation
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).
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
parse_stepcomputedstart_time = current_time - step.duration, wherecurrent_timewas the moment of behave'sformatter.result()callback. That callback fires after theafter_stephook, so any hook latency inflated both the recordedstart_timeandend_time— durations stayed correct but absolute timestamps drifted forward by the cumulative hook overhead. In a scenario with a 200 msafter_step, the first step appeared to start 200 ms into the scenario rather than at the scenario boundary.QaseFormatter.step()(behave's "right before this step executes" formatter hook) and pass it explicitly toparse_stepvia a newstart_timeargument. Computeend_time = start_time + step.durationso the window matches the real step body and excludesafter_steplatency. Clear the slot inresult()and on every newscenario()so state can't leak across.now - durationpath when nostart_timeis supplied (BehaveX JSON replay path from fix: preserve behavex absolute timestamps when replaying JSON #494, third-party callers).qase-behaveto3.2.2.Test plan
TestParseStepRealTimeStartintest_utils.py(3 cases): explicit start anchorsend = start + duration; explicit start excludes callback latency; fallback path preserved when nostart_time.TestFormatterStepCallbackintest_formatter.py(3 cases):step()stores wall-clock;result()forwards the stored value toparse_stepand clears the slot;scenario()resets the slot to prevent leakage.pytest qase-behave/tests/ -v→ 86 passed locally (Python 3.12).environment.pysleeps 200 ms inafter_step:start_time+0.204 s relative to scenario start (200 ms drift);end_timeis also +0.257 s (200 ms past real step end).start_timeis +0.0003 s relative to scenario start;end_timeis +0.055 s — matches the real 50 ms step body, drift removed.