ReportPortal returned errors CHILD_START_TIME_EARLIER_THAN_PARENT during parallel testrun

[medbedalex]

ReportPortal returned a lot of following errors during parallel testrun:

com.epam.reportportal.exception.ReportPortalException: Report Portal returned error
Status code: 406
Status message: Not Acceptable
Error Message: Start time of child ['Fri Jun 14 09:13:18 UTC 2019'] item should be same or later than start time ['Fri Jun 14 09:13:18 UTC 2019'] of the parent item/launch '5d036530ee1f100001534724'
Error Type: CHILD_START_TIME_EARLIER_THAN_PARENT

    at com.epam.reportportal.service.ReportPortalErrorHandler.handleError(ReportPortalErrorHandler.java:83)
    at com.epam.reportportal.service.ReportPortalErrorHandler.handle(ReportPortalErrorHandler.java:59)
    at com.epam.reportportal.restendpoint.http.HttpClientRestEndpoint$1.subscribe(HttpClientRestEndpoint.java:517)
    at io.reactivex.internal.operators.maybe.MaybeCreate.subscribeActual(MaybeCreate.java:45)
    at io.reactivex.Maybe.subscribe(Maybe.java:4096)
    at io.reactivex.internal.operators.maybe.MaybeCache.subscribeActual(MaybeCache.java:77)
    at io.reactivex.Maybe.subscribe(Maybe.java:4096)
    at io.reactivex.internal.operators.maybe.MaybeSubscribeOn$SubscribeTask.run(MaybeSubscribeOn.java:54)
    at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
    at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
116381 [RxComputationThreadPool-15] ERROR [SubscriptionUtils.java:75] - Logging context completed with error  
com.epam.reportportal.exception.ReportPortalException: Report Portal returned error
Status code: 406
Status message: Not Acceptable
Error Message: Start time of child ['Fri Jun 14 09:13:18 UTC 2019'] item should be same or later than start time ['Fri Jun 14 09:13:18 UTC 2019'] of the parent item/launch '5d036530ee1f100001534724'
Error Type: CHILD_START_TIME_EARLIER_THAN_PARENT

    at com.epam.reportportal.service.ReportPortalErrorHandler.handleError(ReportPortalErrorHandler.java:83) ~[client-java-4.0.13.jar:na]
    at com.epam.reportportal.service.ReportPortalErrorHandler.handle(ReportPortalErrorHandler.java:59) ~[client-java-4.0.13.jar:na]
    at com.epam.reportportal.restendpoint.http.HttpClientRestEndpoint$1.subscribe(HttpClientRestEndpoint.java:517) ~[client-java-4.0.13.jar:na]
    at io.reactivex.internal.operators.maybe.MaybeCreate.subscribeActual(MaybeCreate.java:45) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.Maybe.subscribe(Maybe.java:4096) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.internal.operators.maybe.MaybeCache.subscribeActual(MaybeCache.java:77) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.Maybe.subscribe(Maybe.java:4096) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.internal.operators.maybe.MaybeSubscribeOn$SubscribeTask.run(MaybeSubscribeOn.java:54) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38) ~[rxjava-2.1.16.jar:na]
    at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26) ~[rxjava-2.1.16.jar:na]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_151]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_151]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_151]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]

Also I want to mention that number of tests in ReportPortal every time different during parallel launch.

Here is some pox.xml details:

<properties>
         <nonfunctionalTestsSkip>true</nonfunctionalTestsSkip>
        <nonfunctionalParallelExecution>methods</nonfunctionalParallelExecution>
        <nonfunctionalParallelThreads>15</nonfunctionalParallelThreads>
        <performance.test.configuration>false</performance.test.configuration>

        <!-- Versions -->
        <serenity.version>2.0.52</serenity.version>
        <serenity.maven.version>2.0.50</serenity.maven.version>
        <serenity.reportportal.integration.version>1.4.1</serenity.reportportal.integration.version>
        <maven.surefire.plugin.version>2.22.2</maven.surefire.plugin.version>
        <maven.failsafe.plugin.version>2.22.2</maven.failsafe.plugin.version>
    </properties>

    <build>
        <plugins>
            <plugin>
                <artifactId>maven-failsafe-plugin</artifactId>
                <version>${maven.failsafe.plugin.version}</version>
                <dependencies>
                    <dependency>
                        <groupId>org.apache.maven.surefire</groupId>
                        <artifactId>surefire-junit47</artifactId>
                        <version>${maven.surefire.plugin.version}</version>
                    </dependency>
                </dependencies>
                <configuration>
                    <includes>
                        <include>**/*Tests.*</include>
                    </includes>                   
                    <parallel>classes</parallel>
                    <threadCount>${nonfunctionalParallelThreads}</threadCount>
                    <perCoreThreadCount>false</perCoreThreadCount>
                </configuration>                
            </plugin>

            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>${maven.surefire.plugin.version}</version>
                <configuration>
                    <parallel>${nonfunctionalParallelExecution}</parallel>
                    <threadCount>${nonfunctionalParallelThreads}</threadCount>
                    <skipTests>${nonfunctionalTestsSkip}</skipTests>                    
                </configuration>
            </plugin>

            <plugin>
                <groupId>net.serenity-bdd.maven.plugins</groupId>
                <artifactId>serenity-maven-plugin</artifactId>
                <version>${serenity.maven.version}</version>
                <dependencies>
                    <dependency>
                        <groupId>net.serenity-bdd</groupId>
                        <artifactId>serenity-core</artifactId>
                        <version>${serenity.version}</version>
                    </dependency>
                </dependencies>
                <executions>
                    <execution>
                        <id>serenity-reports</id>
                        <phase>post-integration-test</phase>
                        <goals>
                            <goal>aggregate</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>            
        </plugins>
    </build>

    <dependencies>
        <dependency>
            <groupId>net.serenity-bdd</groupId>
            <artifactId>serenity-core</artifactId>
            <version>${serenity.version}</version>
        </dependency>
        <dependency>
            <groupId>net.serenity-bdd</groupId>
            <artifactId>serenity-junit</artifactId>
            <version>${serenity.version}</version>
        </dependency>
        <dependency>
            <groupId>net.serenity-bdd</groupId>
            <artifactId>serenity-rest-assured</artifactId>
            <version>${serenity.version}</version>
        </dependency>
        <dependency>
            <groupId>com.github.invictum</groupId>
            <artifactId>serenity-reportportal-integration</artifactId>
            <version>${serenity.reportportal.integration.version}</version>
            <exclusions>
                <exclusion>
                    <groupId>net.serenity-bdd</groupId>
                    <artifactId>serenity-core</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
    </dependencies>
</project>

So the actual behaviour during parallel launch:

1. errors from RP CHILD_START_TIME_EARLIER_THAN_PARENT
2. different number of tests in ReportPortal launch

And expected behaviour during parallel launch:

1. no errors
2. same number of tests in ReportPortal (as in sequence launch)

Do you need any additional information?

[Invictum]

@medbedalex Thanks for issue reporting. I will look into it and let you know if I need more details

[BushnevYuri]

The same issue has been previously reported on report portal itself by guys using cucumber integration https://github.com/reportportal/reportportal/issues/188 and was fixed by https://github.com/reportportal/agent-java-cucumber/pull/8

Probably a similar issue.

[Invictum]

@medbedalex

What version of Report Portal server did you use?

[medbedalex]

@Invictum

Analysis Service: 4.3.0;
API Service: 4.3.0;
Index Service: 4.2.0;
Jira Service: 4.3.0;
Authorization Service: 4.2.0;
Service UI: 4.3.0

[Invictum]

@medbedalex

I'm unable to reproduce your error, but noticed some side effect that connected to parallel execution. And it is definitely an issue that will be fixed in a separate ticket.

Could you please provide a simple project that reproduced an issue?

[slavamarkovski]

I have the same issue, cannot provide the project - sorry, it is production code. RP version is the same, serenity-reportportal-integration version is 1.4.1

[Invictum]

@slavamarkovski

Unfortunately, it is hard to determinate the root cause of issue without example. Synthetic project with several fake tests that reproduces an issue should be enough and I will really appreciate it.