You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@maven.apache.org by "Tibor Digana (Jira)" <ji...@apache.org> on 2019/10/28 16:19:00 UTC
[jira] [Comment Edited] (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=16961209#comment-16961209 ]
Tibor Digana edited comment on SUREFIRE-1631 at 10/28/19 4:18 PM:
------------------------------------------------------------------
[~digulla]
Now I used the development version {{3.0.0-SNAPSHOT}} and I got this result.
Due to the shutdown is called right before the EXIT, all the communication between Maven process and forked JVM has finished and the logs in the shutdown hook might be lost.
{noformat}
[INFO] --- maven-surefire-plugin:3.0.0-SNAPSHOT:test (default-test) @ surefire-shutdownhook-bug ---
[INFO]
[INFO] -------------------------------------------------------
[INFO] T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.apache.maven.surefire.bugs.shutdownhook.SomethingWhichInstallShutdownHookTest
17:17:24,779 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-test.xml] at [file:/C:/vcs/github/surefire-shutdownhook-bug/target/test-classes/logback-test.xml]
17:17:24,904 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:17:24,909 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
17:17:24,918 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
17:17:24,962 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
17:17:24,963 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
17:17:24,964 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
17:17:24,965 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5f2108b5 - Registering current configuration as safe fallback point
17:17:24.971 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 0
17:17:24.976 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 1
17:17:24.977 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 2
... MORE LOGS HERE ...
17:17:30.660 [ShutdownHook which will write lots of stuff to stdout] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - installShutdownHook line 7906 Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat.
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 10.640 s
[INFO] Finished at: 2019-10-28T17:17:31+01:00
[INFO] Final Memory: 13M/594M
[INFO] ------------------------------------------------------------------------
{noformat}
was (Author: tibor17):
[~digulla]
Now I used the development version {{3.0.0-SNAPSHOT}} and I got this result.
Due to the shutdown is called right before the EXIT, all the communication between Maven process and forked JVM has finished and the logs in the shutdown hook might be lost.
{noformat}
[INFO] --- maven-surefire-plugin:3.0.0-SNAPSHOT:test (default-test) @ surefire-shutdownhook-bug ---
[INFO]
[INFO] -------------------------------------------------------
[INFO] T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.apache.maven.surefire.bugs.shutdownhook.SomethingWhichInstallShutdownHookTest
17:09:25,306 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-test.xml] at [file:/C:/vcs/github/surefire-shutdownhook-bug/target/test-classes/logback-test.xml]
17:09:25,437 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:09:25,444 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
17:09:25,458 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
17:09:25,514 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
17:09:25,514 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
17:09:25,515 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
17:09:25,517 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5f2108b5 - Registering current configuration as safe fallback point
17:09:25.523 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 0
17:09:25.531 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 1
17:09:25.531 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 2
17:09:25.531 [main] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - This is a short log message 3
... LOGS HERE ...
..... [ShutdownHook which will write lots of stuff to stdout] DEBUG o.a.m.s.b.s.SomethingWhichInstallShutdownHook - installShutdownHook line 973 Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat.
[INFO] Results:
[INFO]
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 50.581 s
[INFO] Finished at: 2019-10-28T17:04:57+01:00
[INFO] Final Memory: 15M/280M
[INFO] ------------------------------------------------------------------------
{noformat}
> 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, 2.22.0, 3.0.0-M2, 3.0.0-M1
> Reporter: Aaron Digulla
> Priority: Major
> Attachments: 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)