You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@maven.apache.org by "Aaron Digulla (JIRA)" <ji...@apache.org> on 2019/01/31 10:20:00 UTC

[jira] [Commented] (SUREFIRE-1631) Forked VM terminated without properly saying goodbye with AciveMQ

    [ https://issues.apache.org/jira/browse/SUREFIRE-1631?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16757106#comment-16757106 ] 

Aaron Digulla commented on SUREFIRE-1631:
-----------------------------------------

Updates. I've made some changes to the logger configuration (I'm using slf4j with logback) and then built the system 10 times.

The first change was adding color to the log by changing the pattern
{code}
<property name="logPattern" value="%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n" />{code}

to
{code}
<property name="logPattern" value="%d{HH:mm:ss.SSS} [%thread] %highlight(%-5level) %cyan(%logger{36}) - %msg%n" />{code}

Now the build fails 10 out of 11 times (the first build succeeded ...).

Then, I've disabled AMQ logging. This avoids log output in a shutdown hook.

{code}
<logger name="org.apache.activemq" level="OFF" />{code}

Now 6 out of 10 builds fail.

If I also disable {{org.springframework.core.env}} (which creates a few 80KB lines of log), then only 2 out of 20 builds fail.
Weird fact: The first two of 20 builds failed. It's as if the problem "heals" itself.

It seems the amount of logging has an effect on the bug but I can't see why. In the code of Surefire, you're using {{readLine()}} in {{org.apache.maven.shared.utils.cli.StreamPumper.run()}} to read the test output which has no length limitation. Non-printables are escaped in {{ForkingRunListener.writeTestOutput()}}. It seems that the length of the line shouldn't have an effect but it does.

So I wrote a small test project which just writes a 100K log and ... it crashes for me with:
{code}
11:01:25.347 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 96420
11:01:25.347 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 96421
11:01:25.347 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 96422
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  04:23 min
[INFO] Finished at: 2019-01-31T11:02:22+01:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M2:test (default-test) on project surefire-shutdownhook-bug: There are test failures.
[ERROR]
[ERROR] Please refer to C:\dev\workspace\surefire-shutdownhook-bug\target\surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was cmd.exe /X /C "C:\tools\java\jdk1.8.0_191\jre\bin\java -jar C:\tools\cygwin\tmp\surefire2097056449345541265\surefirebooter7815058800200549210.jar C:\tools\cygwin\tmp\surefire2097056449345541265 2019-01-31T10-58-05_362-jvmRun1 surefire7801676233715227954tmp surefire_06053953062955035510tmp"
[ERROR] Process Exit Code: 0
[ERROR] Crashed tests:
[ERROR] org.apache.maven.surefire.bugs.shutdownhook.SomethingWhichInstallShutdownHookTest
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was cmd.exe /X /C "C:\tools\java\jdk1.8.0_191\jre\bin\java -jar C:\tools\cygwin\tmp\surefire2097056449345541265\surefirebooter7815058800200549210.jar C:\tools\cygwin\tmp\surefire2097056449345541265 2019-01-31T10-58-05_362-jvmRun1 surefire7801676233715227954tmp surefire_06053953062955035510tmp"
[ERROR] Process Exit Code: 0
[ERROR] Crashed tests:
[ERROR] org.apache.maven.surefire.bugs.shutdownhook.SomethingWhichInstallShutdownHookTest
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:670)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:283)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:246)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1159)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1000)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:846)
[ERROR]         at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
[ERROR]         at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
[ERROR]         at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
[ERROR]         at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
[ERROR]         at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
[ERROR]         at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
[ERROR]         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR]         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR]         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR]         at java.lang.reflect.Method.invoke(Method.java:498)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
{code}



> Forked VM terminated without properly saying goodbye with AciveMQ
> -----------------------------------------------------------------
>
>                 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, 3.0.0-M1, 2.22.0, 3.0.0-M2
>            Reporter: Aaron Digulla
>            Priority: Major
>
> 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
(v7.6.3#76005)