[
https://issues.apache.org/jira/browse/SUREFIRE-1631?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16972782#comment-16972782
]
Adolfo Cia commented on SUREFIRE-1631:
--------------------------------------
Here is an old build on our CI, I pasted relevant info:
{code:java}
[18:09:12]Step 1/7: build-maven (Maven) (33s)[18:09:13][Step 1/7] Using agent
local repository at
/opt/buildagent/system/jetbrains.maven.runner/maven.repo.local[18:09:13][Step
1/7] Initial M2_HOME not set[18:09:13][Step 1/7] Current M2_HOME =
/opt/buildagent/tools/maven3_3[18:09:13][Step 1/7] PATH =
/opt/buildagent/tools/maven3_3/bin:/opt/java/openjdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin[18:09:13][Step
1/7] Using watcher:
/opt/buildagent/plugins/mavenPlugin/maven-watcher-jdk16/maven-watcher-agent.jar[18:09:13][Step
1/7] Initial MAVEN_OPTS not set[18:09:13][Step 1/7] Current MAVEN_OPTS not
set[18:09:13][Step 1/7] Starting: /opt/java/openjdk/bin/java
-DOctopusReleaseVersion=1 -DPROJECT_NAME=ltl-java-linehauloperations-ensemble
-Dagent.home.dir=/opt/buildagent
-Dagent.name=teamcity-agent-k8s-cluster-03-90c290fe-9c11-4765-9eb4-5bc8600ab84d
-Dagent.ownPort=9090 -Dagent.work.dir=/opt/buildagent/work
-Dbuild.number=1.0.0.22.9-SNAPSHOT-21
-Dbuild.vcs.number=10992cd3eda8b3961a39e5d4ff75190e1a19bf25
-Dbuild.vcs.number.1=10992cd3eda8b3961a39e5d4ff75190e1a19bf25
-Dbuild.vcs.number.XpoLtl_GithubXPO=10992cd3eda8b3961a39e5d4ff75190e1a19bf25
-Dclassworlds.conf=/opt/buildagent/temp/buildTmp/teamcity.m2.conf
-Dcom.jetbrains.maven.watcher.report.file=/opt/buildagent/temp/buildTmp/maven-build-info.xml
-Dcomponent=linehauloperations-ensemble
-Dgcp_project=ltl-java-linehauloperations-ensemble
-Djava.io.tmpdir=/opt/buildagent/temp/buildTmp
-Dk8s_cluster=xpo-ltl-dev-gke-cluster-03
-Dmaven.home=/opt/buildagent/tools/maven3_3
-Dmaven.multiModuleProjectDirectory=/opt/buildagent/work/8d1ea2f96e40b6ad
-Dmaven.repo.local=/opt/buildagent/system/jetbrains.maven.runner/maven.repo.local
-Dteamcity.agent.cpuBenchmark=435
-Dteamcity.agent.dotnet.agent_url=http://localhost:9090/RPC2
-Dteamcity.agent.dotnet.build_id=2058 -Dteamcity.auth.password=*******
-Dteamcity.auth.userId=TeamCityBuildId=2058
-Dteamcity.build.changedFiles.file=/opt/buildagent/temp/buildTmp/changedFiles436895329153164929.txt
-Dteamcity.build.checkoutDir=/opt/buildagent/work/8d1ea2f96e40b6ad
-Dteamcity.build.id=2058
-Dteamcity.build.properties.file=/opt/buildagent/temp/buildTmp/teamcity.build1424809028942160220.properties
-Dteamcity.build.tempDir=/opt/buildagent/temp/buildTmp
-Dteamcity.build.workingDir=/opt/buildagent/work/8d1ea2f96e40b6ad
-Dteamcity.buildConfName=ltl-java-linehauloperations-ensemble-development
-Dteamcity.buildType.id=XpoLtl_Java_Development_LtlJavaLinehauloperationsEnsembleDevelopment
-Dteamcity.configuration.properties.file=/opt/buildagent/temp/buildTmp/teamcity.config3418460461704538667.properties
-Dteamcity.maven.watcher.home=/opt/buildagent/plugins/mavenPlugin/maven-watcher-jdk16
-Dteamcity.projectName=Development
-Dteamcity.runner.properties.file=/opt/buildagent/temp/buildTmp/teamcity.runner6062948348053628422.properties
-Dteamcity.tests.recentlyFailedTests.file=/opt/buildagent/temp/buildTmp/testsToRunFirst6288640780621088159.txt
"-Dteamcity.version=2019.1.3 (build 66439)" -classpath
/opt/buildagent/tools/maven3_3/boot/plexus-classworlds-2.5.2.jar:
org.codehaus.plexus.classworlds.launcher.Launcher -f
/opt/buildagent/work/8d1ea2f96e40b6ad/pom.xml -B clean package -U -X
-Dskip.server=true[18:09:13][Step 1/7] in directory:
/opt/buildagent/work/8d1ea2f96e40b6ad[18:09:13][Step 1/7] Picked up
JAVA_TOOL_OPTIONS: -XX:+UnlockExperimentalVMOptions
-XX:+UseCGroupMemoryLimitForHeap[18:09:13][Step 1/7] Apache Maven 3.3.9
(bb52d8502b132ec0a5a3f4c09453c07478323dc5;
2015-11-10T16:41:47+00:00)[18:09:13][Step 1/7] Maven home:
/opt/buildagent/tools/maven3_3[18:09:13][Step 1/7] Java version: 1.8.0_192,
vendor: Oracle Corporation[18:09:13][Step 1/7] Java home:
/opt/java/openjdk/jre[18:09:13][Step 1/7] Default locale: en, platform
encoding: UTF-8[18:09:13][Step 1/7] OS name: "linux", version: "4.14.137+",
arch: "amd64", family: "unix"{code}
{code:java}
[18:09:45][Step 1/7] [INFO] Results:[18:09:45][Step 1/7] [INFO] [18:09:45][Step
1/7] [INFO] Tests run: 64, Failures: 0, Errors: 0, Skipped: 0[18:09:45][Step
1/7] [INFO] [18:09:45][Step 1/7] Failed to execute goal
org.apache.maven.plugins:maven-surefire-plugin:2.22.0:test (default-test) on
project ltl-java-linehauloperations-ensemble: There are test failures.
Please refer to /opt/buildagent/work/8d1ea2f96e40b6ad/target/surefire-reports
for the individual test results.
Please refer to dump files (if any exist) [date]-jvmRun[N].dump,
[date].dumpstream and [date]-jvmRun[N].dumpstream.
The forked VM terminated without properly saying goodbye. VM crash or
System.exit called?
Command was /bin/sh -c cd /opt/buildagent/work/8d1ea2f96e40b6ad &&
/opt/java/openjdk/jre/bin/java -Xmx1024m -XX:MaxPermSize=256m
-javaagent:/opt/buildagent/system/jetbrains.maven.runner/maven.repo.local/org/jmockit/jmockit/1.48/jmockit-1.48.jar
-jar
/opt/buildagent/work/8d1ea2f96e40b6ad/target/surefire/surefirebooter1970452189048870321.jar
/opt/buildagent/work/8d1ea2f96e40b6ad/target/surefire
2019-11-01T18-09-22_800-jvmRun1 surefire473320808725044380tmp
surefire_06909595553598109916tmp
Error occurred in starting fork, check output in log
Process Exit Code: 1
Crashed tests:
com.xpo.ltl.linehauloperations.service.ejb.v1.GetImageThumbnailMinuetTest
org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM
terminated without properly saying goodbye. VM crash or System.exit called?
Command was /bin/sh -c cd /opt/buildagent/work/8d1ea2f96e40b6ad &&
/opt/java/openjdk/jre/bin/java -Xmx1024m -XX:MaxPermSize=256m
-javaagent:/opt/buildagent/system/jetbrains.maven.runner/maven.repo.local/org/jmockit/jmockit/1.48/jmockit-1.48.jar
-jar
/opt/buildagent/work/8d1ea2f96e40b6ad/target/surefire/surefirebooter1970452189048870321.jar
/opt/buildagent/work/8d1ea2f96e40b6ad/target/surefire
2019-11-01T18-09-22_800-jvmRun1 surefire473320808725044380tmp
surefire_06909595553598109916tmp
Error occurred in starting fork, check output in log
Process Exit Code: 1
Crashed tests:
com.xpo.ltl.linehauloperations.service.ejb.v1.GetImageThumbnailMinuetTest
at
org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:671)
at
org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:533)
at
org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:278)
at
org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:244)
at
org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1194)
at
org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1022)
at
org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:868)
at
org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
at
org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
at
org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
at
org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
at
org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
at
org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
at
org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
at
org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
at
org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
at
org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
at
org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
[18:09:45][Step 1/7] [INFO]
------------------------------------------------------------------------[18:09:45][Step
1/7] [INFO] BUILD FAILURE[18:09:45][Step 1/7] [INFO]
------------------------------------------------------------------------[18:09:45][Step
1/7] [INFO] Total time: 30.396 s[18:09:45][Step 1/7] [INFO] Finished at:
2019-11-01T18:09:45+00:00[18:09:45][Step 1/7] [INFO] Final Memory: 36M/228M
{code}
> Forked VM terminated without properly saying goodbye with AciveMQ on
> Windows10 and MinTTY(Cygwin) console
> ---------------------------------------------------------------------------------------------------------
>
> Key: SUREFIRE-1631
> URL: https://issues.apache.org/jira/browse/SUREFIRE-1631
> Project: Maven Surefire
> Issue Type: Bug
> Components: Maven Surefire Plugin
> Affects Versions: 2.20.1, 2.22.0, 3.0.0-M2, 3.0.0-M1
> Reporter: Aaron Digulla
> Assignee: Tibor Digana
> Priority: Major
> Attachments: cmd.PNG, cmd2.PNG, shurefire-shutdownhook-bug-0.0.1.zip
>
>
> I'm seeing spurious "The forked VM terminated without properly saying
> goodbye. VM crash or System.exit called?" messages when running unit tests in
> a big multi-module project.
> OS: Windows 10, running Maven 3.5.0 to 3.6.0 and different versions of
> Surefire (2.20.1 to 3.0.0.-M2), Java 8u171 to 8u191.
> I'm running Maven from the command line using MinTTY (Cygwin).
> Things I tried which have no effect:
> * Reboot / Cold boot (happens first thing on Monday morning when I come into
> the office and turn on my PC).
> * More free memory (happens when I only have a single window open). I have
> 16GB of RAM.
> * Different terminal. I tried CMD prompt and urxvt (Cygwin/X).
> * Different versions of the Surefire plugin or Maven
> * Different JDK 8 builds
> Things that affect the bug:
> * Redirecting Maven's stdout to a file: mvn ... | tee mvn.log
> * Redirecting all log output to a file using logback-test.xml
> * Running Surefire with forkCount=0
> * Running a subset of the tests (-Dtest=...)
> * Pending Windows updates (I think, not sure about this one).
> Counts: I've never seen it with forkCount=0 (~ 20 test builds). I've never
> seen it with redirecting log output (~ 10 builds). Redirecting sometimes
> helps but not always.
> One thing which I notice is that one of the tests creates an ActiveMQ broker
> and uses a shutdown hook to stop it. So I created a small test project which
> demonstrates that Surefire will sometimes cut off stdout. I think that
> happens because the main process kills the child after a timeout (correct?).
> So my guess would be that shutdown hooks can mess with the pipeline between
> the surefire child VM and main Maven process. ActiveMQ might be worse since
> it stops threads and execution pools (so the output comes slowly with a
> couple of exceptions sprinkled in when one component loses connection because
> another is shutting down).
> But now, it gets weird. When the build succeeds, it takes about ~5 minutes to
> run 1028 tests. The log is 25 MB.
> When it fails, it takes ~8 minutes to run ~700-800 tests (this number varies)
> and the log stops in the middle of a test but is also 25 MB.
> Some of the time discrepancy is probably because writing to a file is faster
> than printing on a terminal. The strange part is that the log file is about
> the same size but 30% of the tests haven't run. Most tests log a lot, do I
> would expect to see a difference of at least a few MB. The Maven part (which
> contains escape sequences, etc). is just 60 KB.
> Maybe the parent takes some part of the log output as "child terminated".
> I'm running out of ideas what to try next. I think a way to log the
> communication between parent and child would help. Also the parent should
> terminate the child and then read stdout until EOF to we can see anything
> that happens afterwards.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
