Fix test cases execution time in reports

[clicman]

This is bug fix for test steps execution time. It was fired fireTestStarted event after test was performed.
I was moved event at the start of step execution. Now timings calculated right.

In tests I was just removed fireTestStarted execution verification because it not performed in that places.

[brasmusson]

This PR does not only correct the test steps execution time. It does also change one invariant; that a testStarted notification always is followed by a testFinished notification. With the PR a testStarted notification is sometimes followed by a testIgnored notification (for Undefined and Pending steps in non-strict mode). The questing is, do all RunListeners handle that a testStarted notification is followed by a testIgnored notification? What do you say @clicman? It's possible that the original intent behind not fire the testStarted notification until in the result method, was to ensure that either a testStarted notification and a testFinished notification was fired, or a testIgnored (its impossible to determine that a step is pending until in the result method).

When changing the invariant that a testStarted is followed by a testFinished is changed then the cucumber.runtime.junit.SanityChecker must be updated accordingly. Now it will trigger a failure when a testStarted is not folloed by a testFinished (hence the broken build for this PR).

When the testStarted is fired from the match method, I really thing there should be a test case that verifies that it actually is fired there.

[clicman]

@brasmusson, I`m not familiar with jUnit internals and just waited for reaction form person who could expalin me it :)

The questing is, do all RunListeners handle that a testStarted notification is followed by a testIgnored notification?
I`ve not faced problems with it. Standard jUnit listener works good.

When changing the invariant that a testStarted is followed by a testFinished is changed then the cucumber.runtime.junit.SanityChecker must be updated accordingly. Now it will trigger a failure when a testStarted is not folloed by a testFinished (hence the broken build for this PR).

Where SanityChecker used? In which projects/cases? I only can see it in picocontainer tests. I want determine what ele can be tested after SanityChecker update/

When the testStarted is fired from the match method, I really thing there should be a test case that verifies that it actually is fired there.
Ok. This is clear.

[brasmusson]

@clicman I'm actually not familiar with SanityChecker, it looks as it was added as an internal utility to find problems in the JUnit integration. I don't find it used in any other place than in the picocontainer tests.

[clicman]

@brasmusson ok. I`ll update this PR soon with updated SanityChecker

[clicman]

• SanityChecker was updated.
• Tests not updated. Have no idea how to test it. And probably it should not be covered by separate test case.

[brasmusson]

@clicman If you pull brasmusson@2e20deb from my clicman-junit-fire-test-started branch, you get a test case checking that testStarted is fired from the match method. I also improved the SanityChecker to check that testIgnored is fired for the latest fired testStarted.

[clicman]

Sorry for delay. To use RunListener in pair with Description - the better way, i like it. Thank you for test, now I undrstand how mocking works. I will update this PR ASAP.

[brasmusson]

This was the only fireTestFinished() on the executionUnitNotifier (all others are on the stepNotifier), now the scenario (or in JUnit terms the test suite) will not be finished. The log for the picocontainer tests visualize this clearly (line 5758).

[clicman]

Agree. Stupid commit. Will revert it.

[clicman]

So I will not push any commits into this PR. Will commit if only it will fix reason which will deny merge to master.

[clicman]

@brasmusson should testFinished events fire for Ignored/skipped scenarios?

Sanity checker outputs this:

START  Scenario: An undefined step
  START  Given something undefined(Scenario: An undefined step)
  IGNORE Given something undefined(Scenario: An undefined step)
IGNORE Scenario: An undefined step
END    Scenario: An undefined step

START  Scenario: A pending step
  START  Given something pending(Scenario: A pending step)
  IGNORE Given something pending(Scenario: A pending step)
IGNORE Scenario: A pending step
END    Scenario: A pending step

As result we have two records in surefire xml for scenario finishing.

  <testcase name="Scenario: second" classname="Scenario: second" time="0">
    <skipped/>
  </testcase>
  <testcase name="Scenario: second" classname="Scenario: second" time="0"/>

[brasmusson]

@clicman Whether testFinished should be fired for ignored/skipped scenarios, is a really good question. I recon that the answer depends on how common listeners like:

• maven surefire
• ant's junit task
• Eclipse
• IDEA

reacts when testFinished is fired versus when in is not fired for ignored/skipped scenarios (and maven surefire seems not to react well when it is fired).

The change that testFinished should always fire were introduced a couple of years ago. It is hard to see today the specific rational for that change (except that it make the SanityChecker's matching of testStarted and testFinished possible).

[clicman]

@brasmusson Okay. Now I understand problem background. Actually it doesn`t not affect on my project, but timing does. Could you answer when this PR will merged to master. And how often cucumber-jvm releases? I want do determine when it will be possible to make a new release of allure cucmber-jvm adaptor.

[brasmusson]

@clicman Looking back, there have been a new Cucumber-JVM release every 2-3 months or so. Unfortunately I can't really say when this PR will be merged.

[aslakhellesoy]

@brasmusson is this good to merge?

[brasmusson]

@aslakhellesoy I think it comes down to a trade-off between accurate times versus a bit more reasonably run counts - from the perspective on listeners to the JUnit-notifications. For listeners to be able to calculate accurate executions times, this PR is necessary (sending both the start and finish notification after the step has executed make the time between the notification irrelevant with respect to the execution time of the step).

On the other hand receiving first a start notification and then a ignore notification is not what listeners are expecting (I assume that an ignore notification is sent by itself for @org.junit.Ignore annotated tests from JUnit). When I make one step pending in the Java-Calculator example and run it. Then Cucumber-JVM's step count is 1skipped, 1pending, 34passed.

Executing it in Eclipse without this PR makes Eclipse JUnit listener to report the run count "36/36 (3 skipped)" (I guess the extra skipped comes from the scenario for which both a skipped and a finished notification is sent). Apart from that "36/36" (the number of steps) seems as reasonable reporting.

Executing it with this PR makes the reported run count "38/36 (3 skipped)", it seems like the two steps for which both a start and a ignore notification is send is counted twice in the "38". "38/36 (3 skipped) is less reasonable than, "36/36 (3 skipped)", but "36/36 (2 skipped)" seems to me even more reasonable. In both cases the test tree view is the same (the pending and skipped step, as well as their scenario is marked as skipped).

In the end I think it is OK to prioritize the accuracy in execution time calculated from the notifications, and merge this PR.

[clicman]

Up.

[dhaerinck]

Think it's important this one is fixed. Using Cucumber-JVM with the Allure reporting tool to automate production testing, and using simple internal DSL instead, I can have accurate timings in my test case reports. Pity.

[0I0u3uk]

Hey, guys, why don't accept this PR?

[clicman]

@brasmusson I see you have merge rights. Can you merge this pull request?

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.