search

ops4j / org.ops4j.pax.exam2

Pax Exam is a testing framework for OSGi
https://ops4j1.jira.com/wiki/spaces/PAXEXAM4/
Apache License 2.0
84 stars 100 forks source link

Maven: Forked Test Container corrupts communication between surefire plugin and forked surefire executor [PAXEXAM-920] #453

Closed ops4j-issues closed 4 years ago

ops4j-issues commented 6 years ago

Arnoud Glimmerveen created PAXEXAM-920

Since upgrading the version of the maven-surefire-plugin we often see projects containing Pax Exam based tests taking a long time to execute. In these cases we can attribute the extra time to a (default) timeout of 30 seconds used by Surefire to eventually continue when the forked process did not terminate.

After analysis we have concluded that the regular shutdown protocol between Surefire plugin and forked process is halted due to an invalid command being read. The Thread dies and the 'BYE_ACK' from Surefire plugin towards forked process is never handled in the forked process, falling back to the timeout that forces the fork to stop.

I believe the source of the corruption of the communication between Surefire maven plugin and forked process can be attributed to Pax Exam's own method of forking a test container. Specifically the way the process input/output streams are handled using 'Pipes'. I see both the Surefire fork (running the test) and the Forked Test Container reading from the same System.in input stream. This means that some of the data on this InputStream intended for the Surefire forked logic is 'stolen' by the Pipe logic used by ops4j-base-exec's DefaultJavaRunner. This results in the input meant for Surefire logic running in the Surefire's forked process being incorrect.

I see that the current status of ops4j-base-exec's DefaultJavaRunner no longer contains this Pipe logic and when re-managing the version of this library to a locally build SNAPSHOT does seem to solve this issue, however with some loss of functionality: the output of the Forked Test Container is no longer reported in the stdout of surefire plugin execution and the following warning being reported:

WARNING Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /Users/arnoud/fork-test/target/surefire-reports/2018-09-26T22-43-26_347-jvmRun1.dumpstream

I have created a project that can be used to reproduce the issue: https://github.com/glimmerveen/fork-test . Note that the issue can be seen as the Maven build being blocked for about 30 seconds after the following line in the build output:

INFO Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.872 s - in org.glimmerveen.forktest.OsgiTest

Affects: 4.12.0 Fixed in: 5.0.0, 4.14.0, 4.13.3 Votes: 0, Watches: 3

ops4j-issues commented 4 years ago

Oliver Lietz commented

Jean-Baptiste Onofre, Are you aware of this issue? I suspect it has a major impact on log output also.

ops4j-issues commented 4 years ago

Oliver Lietz commented

Arnoud Glimmerveen, Christian Schneider, Jean-Baptiste Onofre, Please see 0f18b4d and give it a try. Fixed the issue for me.

ops4j-issues commented 4 years ago

Arnoud Glimmerveen commented

Oliver Lietz: thanks for looking into this!

I can verify that it works properly in the following setup:

When I tested it with maven-surefire-plugin 2.22.1 it appeared to work (I would not see the timeout I described), though I would still get the warning of the 'Corrupted STDOUT'. With 2.22.2 I no longer see this warning, though I am not sure if that is due to the warning being removed or some other (behavioural) change in maven-surefire-plugin.

Would with this fix included be a good opportunity to cut a maintenance release of v4.x?

ops4j-issues commented 4 years ago

Oliver Lietz commented

Arnoud Glimmerveen, I do not see any issues with 2.22.1, 2.22.2 and 3.0.0-M4 (testing with e.g. https://github.com/apache/sling-org-apache-sling-pipes). Can you please retest with 2.22.1? Did you test with https://github.com/glimmerveen/fork-test?

Jean-Baptiste Onofre, Can you please create a new version 4.13.3?

ops4j-issues commented 4 years ago

Jean-Baptiste Onofre commented

Oliver Lietz done for the 4.13.3 version.

ops4j-issues commented 4 years ago

Arnoud Glimmerveen commented

Oliver Lietz: I tested with another project, retesting with my initial sample project which I referenced in the issue looks just fine in both 2.22.1 and 2.22.2.

I would have to go back to the other project to see if I can explain what (else) went wrong. Would that be of interest? Otherwise updating maven-surefire-plugin to 2.22.2 is no issue for me.

ops4j-issues commented 4 years ago

Oliver Lietz commented

Arnoud Glimmerveen, Of course any issue related to Pax Exam is interesting but further analysis is not mandatory for this issue from your side. My testing with different Apache Sling modules was successful. With Apache Karaf master I see one or two tests failing randomly but I guess it’s not related to this fix.

Jean-Baptiste Onofre, Can you please verify and cut a 4.13.3 release?