[
https://issues.apache.org/jira/browse/SUREFIRE-1302?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16029804#comment-16029804
]
Emmanuel Lecharny edited comment on SUREFIRE-1302 at 5/30/17 5:40 PM:
----------------------------------------------------------------------
Hi guys,
I think I'm stuck with a similar pb in the Apache Directory LDAP API project :
trying to cut a release ends up with this error :
{noformat}
[INFO] [SUREFIRE] std/in stream corrupted
[INFO] java.io.IOException: Command NOOP unexpectedly read Void data with
length 4.
[INFO] at
org.apache.maven.surefire.booter.MasterProcessCommand.decode(MasterProcessCommand.java:139)
[INFO] at
org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:360)
[INFO] at java.lang.Thread.run(Thread.java:745)
...
[INFO] [ERROR] Failed to execute goal
org.apache.maven.plugins:maven-surefire-plugin:2.19.1:test (default-test) on
project api-integ-osgi: Execution default-test of goal
org.apache.maven.plugins:maven-surefire-plugin:2.19.1:test failed: The forked
VM terminated without properly saying goodbye. VM crash or System.exit called?
[INFO] [ERROR] Command was /bin/sh -c cd
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi &&
/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/bin/java
-Xmx1024m -jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefirebooter3370697464825684132.jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire2251022129393537760tmp
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire_158862987326254246739tmp
heds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefirebooter3370697464825684132.jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire2251022129393537760tmp
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire_158862987326254246739tmp
{noformat}
The weird thing is that the exact same test work perfectly well when I run
{{mvn test}} in the module, or when I do a release dry-run or a release
prepare, it's really when I do the {{mvn release:perform}} that it fails.
The test itself can take a bit of time. Here is the output, for instance :
{noformat}
[INFO] -------------------------------------------------------
[INFO] T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.apache.directory.api.osgi.ApiAsn1ApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.375
sec - in org.apache.directory.api.osgi.ApiAsn1ApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiAsn1BerOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.303
sec - in org.apache.directory.api.osgi.ApiAsn1BerOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiDsmlEngineOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.44 sec
- in org.apache.directory.api.osgi.ApiDsmlEngineOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiDsmlParserOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.185
sec - in org.apache.directory.api.osgi.ApiDsmlParserOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiI18nOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.237
sec - in org.apache.directory.api.osgi.ApiI18nOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapClientApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.315
sec - in org.apache.directory.api.osgi.ApiLdapClientApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapCodecCoreOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.224
sec - in org.apache.directory.api.osgi.ApiLdapCodecCoreOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasAciOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.19 sec
- in org.apache.directory.api.osgi.ApiLdapExtrasAciOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasCodecApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.154
sec - in org.apache.directory.api.osgi.ApiLdapExtrasCodecApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasCodecOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.193
sec - in org.apache.directory.api.osgi.ApiLdapExtrasCodecOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasSpOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.094
sec - in org.apache.directory.api.osgi.ApiLdapExtrasSpOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasTriggerOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.164
sec - in org.apache.directory.api.osgi.ApiLdapExtrasTriggerOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasUtilOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.12 sec
- in org.apache.directory.api.osgi.ApiLdapExtrasUtilOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapModelOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.275
sec - in org.apache.directory.api.osgi.ApiLdapModelOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapNetMinaOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.119
sec - in org.apache.directory.api.osgi.ApiLdapNetMinaOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapSchemaConverterOsgiTest
[INFO]
[INFO] [SUREFIRE] std/in stream corrupted
...
{noformat}
The cumulative time is *just* below 20s (19.938 exactly), but is more than 20 s
when counting the surrounding tasks :
{noformat}
[INFO] [INFO] Apache Directory API OSGi Integration Tests ........ FAILURE [
21.710 s]
{noformat}
The same test ran in isolation also take longer, but I guess there are some
extra checks done when running a {{mvn release:perform}}...
Is there an expected date for a release that I can test, or even a SNAPSHOT ?
Many thanks !
Forgot to mention that I'm using surefire 2.18.1
was (Author: elecharny):
Hi guys,
I think I'm stuck with a similar pb in the Apache Directory LDAP API project :
trying to cut a release ends up with this error :
{noformat}
[INFO] [SUREFIRE] std/in stream corrupted
[INFO] java.io.IOException: Command NOOP unexpectedly read Void data with
length 4.
[INFO] at
org.apache.maven.surefire.booter.MasterProcessCommand.decode(MasterProcessCommand.java:139)
[INFO] at
org.apache.maven.surefire.booter.CommandReader$CommandRunnable.run(CommandReader.java:360)
[INFO] at java.lang.Thread.run(Thread.java:745)
...
[INFO] [ERROR] Failed to execute goal
org.apache.maven.plugins:maven-surefire-plugin:2.19.1:test (default-test) on
project api-integ-osgi: Execution default-test of goal
org.apache.maven.plugins:maven-surefire-plugin:2.19.1:test failed: The forked
VM terminated without properly saying goodbye. VM crash or System.exit called?
[INFO] [ERROR] Command was /bin/sh -c cd
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi &&
/Library/Java/JavaVirtualMachines/jdk1.8.0_102.jdk/Contents/Home/jre/bin/java
-Xmx1024m -jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefirebooter3370697464825684132.jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire2251022129393537760tmp
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire_158862987326254246739tmp
heds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefirebooter3370697464825684132.jar
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire2251022129393537760tmp
/Users/elecharny/apacheds/trunks/shared/target/checkout/integ-osgi/target/surefire/surefire_158862987326254246739tmp
{noformat}
The weird thing is that the exact same test work perfectly well when I run
{{mvn test}} in the module, or when I do a release dry-run or a release
prepare, it's really when I do the {{mvn release:perform}} that it fails.
The test itself can take a bit of time. Here is the output, for instance :
{noformat}
[INFO] -------------------------------------------------------
[INFO] T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.apache.directory.api.osgi.ApiAsn1ApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.375
sec - in org.apache.directory.api.osgi.ApiAsn1ApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiAsn1BerOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.303
sec - in org.apache.directory.api.osgi.ApiAsn1BerOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiDsmlEngineOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.44 sec
- in org.apache.directory.api.osgi.ApiDsmlEngineOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiDsmlParserOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.185
sec - in org.apache.directory.api.osgi.ApiDsmlParserOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiI18nOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.237
sec - in org.apache.directory.api.osgi.ApiI18nOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapClientApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.315
sec - in org.apache.directory.api.osgi.ApiLdapClientApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapCodecCoreOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.224
sec - in org.apache.directory.api.osgi.ApiLdapCodecCoreOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasAciOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.19 sec
- in org.apache.directory.api.osgi.ApiLdapExtrasAciOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasCodecApiOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.154
sec - in org.apache.directory.api.osgi.ApiLdapExtrasCodecApiOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasCodecOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.193
sec - in org.apache.directory.api.osgi.ApiLdapExtrasCodecOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasSpOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.094
sec - in org.apache.directory.api.osgi.ApiLdapExtrasSpOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasTriggerOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.164
sec - in org.apache.directory.api.osgi.ApiLdapExtrasTriggerOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapExtrasUtilOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.12 sec
- in org.apache.directory.api.osgi.ApiLdapExtrasUtilOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapModelOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.275
sec - in org.apache.directory.api.osgi.ApiLdapModelOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapNetMinaOsgiTest
[INFO]
[INFO]
[INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.119
sec - in org.apache.directory.api.osgi.ApiLdapNetMinaOsgiTest
[INFO] Running org.apache.directory.api.osgi.ApiLdapSchemaConverterOsgiTest
[INFO]
[INFO] [SUREFIRE] std/in stream corrupted
...
{noformat}
The cumulative time is *just* below 20s (19.938 exactly), but is more than 20 s
when counting the surrounding tasks :
{noformat}
[INFO] [INFO] Apache Directory API OSGi Integration Tests ........ FAILURE [
21.710 s]
{noformat}
The same test ran in isolation also take longer, but I guess there are some
extra checks done when running a {{mvn release:perform}}...
Is there an expected date for a release that I can test, or even a SNAPSHOT ?
Many thanks !
> Surefire does not wait long enough for the forked VM and assumes it to be dead
> ------------------------------------------------------------------------------
>
> Key: SUREFIRE-1302
> URL: https://issues.apache.org/jira/browse/SUREFIRE-1302
> Project: Maven Surefire
> Issue Type: Request
> Components: Maven Surefire Plugin
> Affects Versions: 2.19.1
> Reporter: Yuriy Zaplavnov
> Assignee: Tibor Digana
> Fix For: 2.20.1
>
> Attachments: 2017-05-18T05-48-08_685-jvmRun1.dumpstream,
> surefire-gclog.log, surefire-logs,
> surefire-tests-terminated-master-aa9330316038f6b46316ce36ff40714ffc7cf299.zip,
> tests_log_01.txt, tests_log_02.txt
>
>
> This issue happens because surefire kills the forked container if it times
> out waiting for the 'ping'.
> In org.apache.maven.surefire.booter.ForkedBooter class there is hardcoded
> constant PING_TIMEOUT_IN_SECONDS = 20 which is used in the following method:
> {code}
> private static ScheduledFuture<?> listenToShutdownCommands( CommandReader
> reader )
> {
> reader.addShutdownListener( createExitHandler( reader ) );
> AtomicBoolean pingDone = new AtomicBoolean( true );
> reader.addNoopListener( createPingHandler( pingDone ) );
> return JVM_TERMINATOR.scheduleAtFixedRate( createPingJob( pingDone,
> reader ),
> 0,PING_TIMEOUT_IN_SECONDS,
> SECONDS );
> }
> {code}
> to create ScheduledFuture.
> In some of the cases the forked container might respond a bit later than it's
> expected and surefire kills it
> {code}
> private static Runnable createPingJob( final AtomicBoolean pingDone, final
> CommandReader reader )
> {
> return new Runnable()
> {
> public void run()
> {
> boolean hasPing = pingDone.getAndSet( false );
> if ( !hasPing )
> {
> exit( 1, KILL, reader, true );
> }
> }
> };
> }
> {code}
> As long as we need to terminate it anyway, It would be really helpful if the
> problem could be solved making the PING_TIMEOUT_IN_SECONDS configurable with
> the ability to specify the value from maven-surefire-plugin.
> It would help to configure this timeout based on needs and factors of the
> projects where surefire runs.
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
