introduction words interfere with duration reporting

[adrian-herscu]

Try following test:

public class JGivenDurationReporting extends
    ScenarioTest<JGivenDurationReporting.Fixtures<?>, JGivenDurationReporting.Actions<?>, JGivenDurationReporting.Verifications<?>> {

    static class Actions<SELF extends Actions<SELF>> extends Stage<SELF> {
        public SELF doing_nothing(final long millis) {
            sleep(millis);
            return self();
        }
    }

    static class Fixtures<SELF extends Fixtures<SELF>> extends Stage<SELF> {
        public SELF nothing() {
            return self();
        }
    }

    static class Verifications<SELF extends Verifications<SELF>>
        extends Stage<SELF> {
        public SELF succeeds() {
            return self();
        }
    }

    @Test
    public void missesDurationReports() {
        given().nothing();
        when().doing_nothing(1_000)
            .and().doing_nothing(1_000)
            .and().doing_nothing(1_000);
        then().succeeds();
    }

    @Test
    public void reportsDurationOnEveryStep() {
        given().nothing();
        when().doing_nothing(1_000)
            .doing_nothing(1_000)
            .doing_nothing(1_000);
        then().succeeds();
    }
}

First one is reported like this:
Given nothing (11ms)
When doing nothing 1000
And doing nothing 1000
And doing nothing 1000 (1.001s)
Then succeeds

Second one, without the intro-words, is reported:
Given nothing
When doing nothing 1000 (1.001s)
doing nothing 1000 (1.000s)
doing nothing 1000 (1.001s)
Then succeeds

[adrian-herscu]

Patched using AspectJ:

@Aspect
@Slf4j
public class StepModelPatchAspect {

    /**
     * Monitors attempts to set step method's duration. If the duration is
     * already set, then overrides to do nothing.
     *
     * @param stepModel
     *            instance of {@link StepModel}
     *
     * @see #setDurationInNanos(StepModel)
     */
    @Around(value = "setDurationInNanos(stepModel)",
        argNames = "thisJoinPoint,stepModel") // for debugging info
    @SuppressWarnings("static-method")
    public void aroundSetDurationInNanos(
        final ProceedingJoinPoint thisJoinPoint,
        final StepModel stepModel) throws Throwable {
        if (0 == stepModel.getDurationInNanos())
            thisJoinPoint.proceed(); // as duration is not set, otherwise ovoid
    }

    /**
     * Matches the execution of {@link StepModel#setDurationInNanos(long)}
     *
     * @param stepModel
     *            instance of {@link StepModel}
     */
    @Pointcut("execution("
        + "void com.tngtech.jgiven.report.model.StepModel.setDurationInNanos(long))"
        + "&& target(stepModel)")
    public void setDurationInNanos(final StepModel stepModel) {
        // nothing to do here -- just defines a pointcut matcher
    }
}

[l-1squared]

Hi Adrian,
thanks for contacting us.
I have a few questions regarding the test I am supposed to run: Is it a TestNG test? I ran your suite with both JUnit and TestNG and got not a single timing info in the text report. So, is your result from the html report? There I have seen a hint for the behavior you described in a testng test.
Furthermore I'd like to thank you for providing a solution to the issue via AspectJ. However, I'd like to get a better understanding of the issue, before applying that solution. I also want to note that I am currently out of office and therefore I cannot look into your issue immedeately.

[adrian-herscu]

Hi Adrian, thanks for contacting us. I have a few questions regarding the test I am supposed to run: Is it a TestNG test?

Yes.

I ran your suite with both JUnit and TestNG and got not a single timing info in the text report. So, is your result from the html report?

HTML -- in the text report timings are not reported.

There I have seen a hint for the behavior you described in a testng test. Furthermore I'd like to thank you for providing a solution to the issue via AspectJ.

That's only a patch, of course. The real issue is somewhere in StepInterceptorImpl class. Somehow it happens that intro words are handled by calling handleMethodFinished method without updating ScenarioModelBuilder#currentStep, thus overriding previous step's duration... The entire mechanism has way too many fields, changed in various places, making it hard to comprehend how things really work.

However, I'd like to get a better understanding of the issue, before applying that solution. I also want to note that I am currently out of office and therefore I cannot look into your issue immedeately.

[l-1squared]

I've managed to identify the issue: Two components have a different understanding of what a "step" is. I came up with a solution, however, I am not content with merging it yet, because it does not satisfy my quality standards.

A proper solution would involve translating between the different step concepts. Implementing this is however a bit more involved, so it is going to take significantly more time.

[adrian-herscu]

I've managed to identify the issue: Two components have a different understanding of what a "step" is. I came up with a solution, however, I am not content with merging it yet, because it does not satisfy my quality standards.

A proper solution would involve translating between the different step concepts. Implementing this is however a bit more involved, so it is going significantly more time.

Happens too me too :) I am just making it work and write a to-do or fix-me notes alongside.
The AspectJ fix works quite simple: the setDurationInNanos is altered to check if durationInNanos field is still untouched and only then it sets its value. For you is just one line:

if (0 == this.durationInNanos)

[l-1squared]

merged preliminary solution: #778