This is an automated email from the ASF dual-hosted git repository. tibordigana pushed a commit to branch SUREFIRE-1995 in repository https://gitbox.apache.org/repos/asf/maven-surefire.git
commit f49b3bd42ff78f15d8021dc05b316ea29f5a2900 Author: Tibor Digaňa <[email protected]> AuthorDate: Mon Jan 31 02:21:04 2022 +0100 [SUREFIRE-1995] Ping and process checker should use isolated schedulers and the errors should be logged --- .../apache/maven/surefire/booter/ForkedBooter.java | 108 +++++++++++++-------- .../apache/maven/surefire/booter/PpidChecker.java | 4 +- .../apache/maven/surefire/booter/ProcessInfo.java | 16 ++- .../surefire/booter/ForkedBooterMockTest.java | 26 ++--- .../maven/surefire/booter/ForkedBooterTest.java | 8 +- .../maven/surefire/booter/PpidCheckerTest.java | 6 +- 6 files changed, 90 insertions(+), 78 deletions(-) diff --git a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java index d170237..fe64a95 100644 --- a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java +++ b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java @@ -31,8 +31,6 @@ import org.apache.maven.surefire.api.fork.ForkNodeArguments; import org.apache.maven.surefire.api.provider.CommandListener; import org.apache.maven.surefire.api.provider.ProviderParameters; import org.apache.maven.surefire.api.provider.SurefireProvider; -import org.apache.maven.surefire.api.report.LegacyPojoStackTraceWriter; -import org.apache.maven.surefire.api.report.StackTraceWriter; import org.apache.maven.surefire.api.testset.TestSetFailedException; import org.apache.maven.surefire.booter.spi.LegacyMasterProcessChannelProcessorFactory; import org.apache.maven.surefire.booter.spi.SurefireMasterProcessChannelProcessorFactory; @@ -88,10 +86,14 @@ public final class ForkedBooter private static final long ONE_SECOND_IN_MILLIS = 1_000L; private static final String LAST_DITCH_SHUTDOWN_THREAD = "surefire-forkedjvm-last-ditch-daemon-shutdown-thread-"; private static final String PING_THREAD = "surefire-forkedjvm-ping-"; + private static final String PROCESS_CHECKER_THREAD = "surefire-process-checker"; + private static final String PROCESS_PIPES_ERROR = + "The channel (std/out or TCP/IP) failed to send a stream from this subprocess."; private final Semaphore exitBarrier = new Semaphore( 0 ); private volatile MasterProcessChannelEncoder eventChannel; + private volatile ConsoleLogger logger; private volatile MasterProcessChannelProcessorFactory channelProcessorFactory; private volatile CommandReader commandReader; private volatile long systemExitTimeoutInSeconds = DEFAULT_SYSTEM_EXIT_TIMEOUT_IN_SECONDS; @@ -138,10 +140,10 @@ public final class ForkedBooter flushEventChannelOnExit(); forkingReporterFactory = createForkingReporterFactory(); - ConsoleLogger logger = (ConsoleLogger) forkingReporterFactory.createReporter(); + logger = (ConsoleLogger) forkingReporterFactory.createReporter(); commandReader = new CommandReader( decoder, providerConfiguration.getShutdown(), logger ); - pingScheduler = isDebugging ? null : listenToShutdownCommands( booterDeserializer.getPluginPid(), logger ); + pingScheduler = isDebugging ? null : listenToShutdownCommands( booterDeserializer.getPluginPid() ); systemExitTimeoutInSeconds = providerConfiguration.systemExitTimeout( DEFAULT_SYSTEM_EXIT_TIMEOUT_IN_SECONDS ); @@ -169,16 +171,12 @@ public final class ForkedBooter { runSuitesInProcess(); } - catch ( InvocationTargetException e ) - { - Throwable t = e.getTargetException(); - DumpErrorSingleton.getSingleton().dumpException( t ); - eventChannel.consoleErrorLog( new LegacyPojoStackTraceWriter( "test subsystem", "no method", t ), false ); - } catch ( Throwable t ) { - DumpErrorSingleton.getSingleton().dumpException( t ); - eventChannel.consoleErrorLog( new LegacyPojoStackTraceWriter( "test subsystem", "no method", t ), false ); + Throwable e = + t instanceof InvocationTargetException ? ( (InvocationTargetException) t ).getTargetException() : t; + DumpErrorSingleton.getSingleton().dumpException( e ); + logger.error( e.getLocalizedMessage(), e ); } finally { @@ -187,10 +185,11 @@ public final class ForkedBooter if ( eventChannel.checkError() ) { - DumpErrorSingleton.getSingleton() - .dumpText( "The channel (std/out or TCP/IP) failed to send a stream from this subprocess." ); + DumpErrorSingleton.getSingleton().dumpText( PROCESS_PIPES_ERROR ); + logger.error( PROCESS_PIPES_ERROR ); } + // process pipes are closed far here acknowledgedExit(); } } @@ -247,26 +246,37 @@ public final class ForkedBooter } } - private PingScheduler listenToShutdownCommands( String ppid, ConsoleLogger logger ) + private PingScheduler listenToShutdownCommands( String ppid ) { PpidChecker ppidChecker = ppid == null ? null : new PpidChecker( ppid ); commandReader.addShutdownListener( createExitHandler( ppidChecker ) ); AtomicBoolean pingDone = new AtomicBoolean( true ); commandReader.addNoopListener( createPingHandler( pingDone ) ); - PingScheduler pingMechanisms = new PingScheduler( createPingScheduler(), ppidChecker ); + PingScheduler pingMechanisms = new PingScheduler( + createScheduler( PING_THREAD + PING_TIMEOUT_IN_SECONDS + "s" ), + createScheduler( PROCESS_CHECKER_THREAD ), + ppidChecker ); ProcessCheckerType checkerType = startupConfiguration.getProcessChecker(); - if ( ( checkerType == ALL || checkerType == NATIVE ) && pingMechanisms.pluginProcessChecker != null ) + if ( ( checkerType == ALL || checkerType == NATIVE ) && pingMechanisms.processChecker != null ) { - logger.debug( pingMechanisms.pluginProcessChecker.toString() ); - Runnable checkerJob = processCheckerJob( pingMechanisms ); - pingMechanisms.pingScheduler.scheduleWithFixedDelay( checkerJob, 0L, 1L, SECONDS ); + logger.debug( pingMechanisms.processChecker.toString() ); + if ( pingMechanisms.processChecker.canUse() ) + { + Runnable checkerJob = processCheckerJob( pingMechanisms ); + pingMechanisms.processCheckerScheduler.scheduleWithFixedDelay( checkerJob, 0L, 1L, SECONDS ); + } + else if ( !pingMechanisms.processChecker.isStopped() ) + { + logger.warning( "Cannot use process checker with configuration " + checkerType + + ". Platform not supported." ); + } } if ( checkerType == ALL || checkerType == PING ) { - Runnable pingJob = createPingJob( pingDone, pingMechanisms.pluginProcessChecker ); + Runnable pingJob = createPingJob( pingDone, pingMechanisms.processChecker ); pingMechanisms.pingScheduler.scheduleWithFixedDelay( pingJob, 0L, PING_TIMEOUT_IN_SECONDS, SECONDS ); } @@ -282,10 +292,11 @@ public final class ForkedBooter { try { - if ( pingMechanism.pluginProcessChecker.canUse() - && !pingMechanism.pluginProcessChecker.isProcessAlive() + if ( pingMechanism.processChecker.canUse() + && !pingMechanism.processChecker.isProcessAlive() && !pingMechanism.pingScheduler.isShutdown() ) { + logger.error( "Surefire is going to kill self fork JVM. Maven process died." ); DumpErrorSingleton.getSingleton() .dumpText( "Killing self fork JVM. Maven process died." + NL @@ -327,19 +338,31 @@ public final class ForkedBooter Shutdown shutdown = command.toShutdownData(); if ( shutdown.isKill() ) { - ppidChecker.stop(); + if ( ppidChecker != null ) + { + ppidChecker.stop(); + } + + logger.error( "Surefire is going to kill self fork JVM. " + + "Received SHUTDOWN {" + shutdown + "} command from Maven shutdown hook." ); DumpErrorSingleton.getSingleton() .dumpText( "Killing self fork JVM. Received SHUTDOWN command from Maven shutdown hook." + NL + "Thread dump before killing the process (" + getProcessName() + "):" + NL + generateThreadDump() ); + kill(); } else if ( shutdown.isExit() ) { - ppidChecker.stop(); + if ( ppidChecker != null ) + { + ppidChecker.stop(); + } cancelPingScheduler(); + logger.error( "Surefire is going to exit self fork JVM. " + + "Received SHUTDOWN {" + shutdown + "} command from Maven shutdown hook." ); DumpErrorSingleton.getSingleton() .dumpText( "Exiting self fork JVM. Received SHUTDOWN command from Maven shutdown hook." + NL @@ -373,6 +396,7 @@ public final class ForkedBooter boolean hasPing = pingDone.getAndSet( false ); if ( !hasPing ) { + logger.error( "Killing self fork JVM. PING timeout elapsed." ); DumpErrorSingleton.getSingleton() .dumpText( "Killing self fork JVM. PING timeout elapsed." + NL @@ -463,6 +487,12 @@ public final class ForkedBooter @Override public void run() { + if ( logger != null ) + { + logger.error( "Surefire is going to kill self fork JVM. The exit has elapsed " + + systemExitTimeoutInSeconds + " seconds after System.exit(" + returnCode + ")." ); + } + DumpErrorSingleton.getSingleton() .dumpText( "Thread dump for process (" + getProcessName() @@ -572,11 +602,9 @@ public final class ForkedBooter catch ( Throwable t ) { DumpErrorSingleton.getSingleton().dumpException( t ); - t.printStackTrace(); - if ( booter.eventChannel != null ) + if ( booter.logger != null ) { - StackTraceWriter stack = new LegacyPojoStackTraceWriter( "test subsystem", "no method", t ); - booter.eventChannel.consoleErrorLog( stack, false ); + booter.logger.error( t.getLocalizedMessage(), t ); } booter.cancelPingScheduler(); booter.exit1(); @@ -601,12 +629,11 @@ public final class ForkedBooter } } - private static ScheduledExecutorService createPingScheduler() + private static ScheduledExecutorService createScheduler( String threadName ) { - ThreadFactory threadFactory = newDaemonThreadFactory( PING_THREAD + PING_TIMEOUT_IN_SECONDS + "s" ); + ThreadFactory threadFactory = newDaemonThreadFactory( threadName ); ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor( 1, threadFactory ); - executor.setKeepAliveTime( 3L, SECONDS ); - executor.setMaximumPoolSize( 2 ); + executor.setMaximumPoolSize( executor.getCorePoolSize() ); return executor; } @@ -632,20 +659,24 @@ public final class ForkedBooter private static class PingScheduler { private final ScheduledExecutorService pingScheduler; - private final PpidChecker pluginProcessChecker; + private final ScheduledExecutorService processCheckerScheduler; + private final PpidChecker processChecker; - PingScheduler( ScheduledExecutorService pingScheduler, PpidChecker pluginProcessChecker ) + PingScheduler( ScheduledExecutorService pingScheduler, ScheduledExecutorService processCheckerScheduler, + PpidChecker processChecker ) { this.pingScheduler = pingScheduler; - this.pluginProcessChecker = pluginProcessChecker; + this.processCheckerScheduler = processCheckerScheduler; + this.processChecker = processChecker; } void shutdown() { pingScheduler.shutdown(); - if ( pluginProcessChecker != null ) + processCheckerScheduler.shutdown(); + if ( processChecker != null ) { - pluginProcessChecker.destroyActiveCommands(); + processChecker.destroyActiveCommands(); } } } @@ -679,5 +710,4 @@ public final class ForkedBooter return ManagementFactory.getRuntimeMXBean() .getName(); } - } diff --git a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/PpidChecker.java b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/PpidChecker.java index f2567a9..ff5d77c 100644 --- a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/PpidChecker.java +++ b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/PpidChecker.java @@ -59,7 +59,7 @@ import static org.apache.maven.surefire.api.util.internal.StringUtils.NL; */ final class PpidChecker { - private static final int MINUTES_TO_MILLIS = 60 * 1000; + private static final long MINUTES_TO_MILLIS = 60L * 1000L; // 25 chars https://superuser.com/questions/937380/get-creation-time-of-file-in-milliseconds/937401#937401 private static final int WMIC_CREATION_DATE_VALUE_LENGTH = 25; private static final int WMIC_CREATION_DATE_TIMESTAMP_LENGTH = 18; @@ -250,7 +250,7 @@ final class PpidChecker } } - private boolean isStopped() + boolean isStopped() { return stopped; } diff --git a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ProcessInfo.java b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ProcessInfo.java index c7e22de..f86e2ce 100644 --- a/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ProcessInfo.java +++ b/surefire-booter/src/main/java/org/apache/maven/surefire/booter/ProcessInfo.java @@ -34,8 +34,8 @@ import javax.annotation.Nonnull; */ final class ProcessInfo { - static final ProcessInfo INVALID_PROCESS_INFO = new ProcessInfo( null, null ); - static final ProcessInfo ERR_PROCESS_INFO = new ProcessInfo( null, null ); + static final ProcessInfo INVALID_PROCESS_INFO = new ProcessInfo( null, 0 ); + static final ProcessInfo ERR_PROCESS_INFO = new ProcessInfo( null, 0 ); /** * On Unix we do not get PID due to the command is interested only to etime of PPID: @@ -53,9 +53,9 @@ final class ProcessInfo } private final String pid; - private final Comparable time; + private final long time; - private ProcessInfo( String pid, Comparable time ) + private ProcessInfo( String pid, long time ) { this.pid = pid; this.time = time; @@ -82,26 +82,24 @@ final class ProcessInfo return pid; } - Comparable getTime() + long getTime() { checkValid(); return time; } - @SuppressWarnings( "unchecked" ) boolean isTimeEqualTo( ProcessInfo that ) { checkValid(); that.checkValid(); - return time.compareTo( that.time ) == 0; + return time == that.time; } - @SuppressWarnings( "unchecked" ) boolean isTimeBefore( ProcessInfo that ) { checkValid(); that.checkValid(); - return time.compareTo( that.time ) < 0; + return time < that.time; } private void checkValid() diff --git a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterMockTest.java b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterMockTest.java index d353521..37c7b6a 100644 --- a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterMockTest.java +++ b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterMockTest.java @@ -19,10 +19,10 @@ package org.apache.maven.surefire.booter; * under the License. */ +import org.apache.maven.plugin.surefire.log.api.ConsoleLogger; import org.apache.maven.surefire.api.booter.MasterProcessChannelDecoder; import org.apache.maven.surefire.api.booter.MasterProcessChannelEncoder; import org.apache.maven.surefire.api.fork.ForkNodeArguments; -import org.apache.maven.surefire.api.report.StackTraceWriter; import org.apache.maven.surefire.api.util.internal.WritableBufferedByteChannel; import org.apache.maven.surefire.booter.spi.AbstractMasterProcessChannelProcessorFactory; import org.apache.maven.surefire.booter.spi.CommandChannelDecoder; @@ -66,6 +66,7 @@ import static org.fest.assertions.Assertions.assertThat; import static org.fest.assertions.Fail.fail; import static org.mockito.ArgumentMatchers.any; import static org.mockito.ArgumentMatchers.anyString; +import static org.mockito.ArgumentMatchers.eq; import static org.mockito.ArgumentMatchers.same; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.times; @@ -108,13 +109,7 @@ public class ForkedBooterMockTest private MasterProcessChannelProcessorFactory channelProcessorFactory; @Mock - private EventChannelEncoder eventChannel; - - @Captor - private ArgumentCaptor<StackTraceWriter> capturedStackTraceWriter; - - @Captor - private ArgumentCaptor<Boolean> capturedBoolean; + private ConsoleLogger logger; @Captor private ArgumentCaptor<String[]> capturedArgs; @@ -187,7 +182,7 @@ public class ForkedBooterMockTest .when( booter, "setupBooter", any( String.class ), any( String.class ), any( String.class ), any( String.class ) ); - setInternalState( booter, "eventChannel", eventChannel ); + setInternalState( booter, "logger", logger ); String[] args = new String[]{ "/", "dump", "surefire.properties", "surefire-effective.properties" }; invokeMethod( ForkedBooter.class, "run", booter, args ); @@ -198,17 +193,8 @@ public class ForkedBooterMockTest verifyPrivate( booter, times( 1 ) ) .invoke( "execute" ); - verify( eventChannel, times( 1 ) ) - .consoleErrorLog( capturedStackTraceWriter.capture(), capturedBoolean.capture() ); - assertThat( capturedStackTraceWriter.getValue() ) - .isNotNull(); - assertThat( capturedStackTraceWriter.getValue().smartTrimmedStackTrace() ) - .isEqualTo( "test subsystem#no method RuntimeException dummy exception" ); - assertThat( capturedStackTraceWriter.getValue().getThrowable().getTarget() ) - .isNotNull() - .isInstanceOf( RuntimeException.class ); - assertThat( capturedStackTraceWriter.getValue().getThrowable().getTarget().getMessage() ) - .isEqualTo( "dummy exception" ); + verify( logger, times( 1 ) ) + .error( eq( "dummy exception" ), any( RuntimeException.class ) ); verifyPrivate( booter, times( 1 ) ) .invoke( "cancelPingScheduler" ); diff --git a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterTest.java b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterTest.java index ef2ba61..2e2dcee 100644 --- a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterTest.java +++ b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterTest.java @@ -34,7 +34,6 @@ import java.util.Collection; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledThreadPoolExecutor; import java.util.concurrent.Semaphore; -import java.util.concurrent.TimeUnit; import static java.nio.charset.StandardCharsets.UTF_8; import static org.fest.assertions.Assertions.assertThat; @@ -134,7 +133,7 @@ public class ForkedBooterTest ScheduledExecutorService scheduler = null; try { - scheduler = invokeMethod( ForkedBooter.class, "createPingScheduler" ); + scheduler = invokeMethod( ForkedBooter.class, "createScheduler", "thread name" ); assertThat( scheduler ) .isNotNull(); } @@ -178,11 +177,10 @@ public class ForkedBooterTest @Test public void testScheduler() throws Exception { - ScheduledThreadPoolExecutor executor = invokeMethod( ForkedBooter.class, "createPingScheduler" ); + ScheduledThreadPoolExecutor executor = invokeMethod( ForkedBooter.class, "createScheduler", "thread name" ); executor.shutdown(); assertThat( executor.getCorePoolSize() ).isEqualTo( 1 ); - assertThat( executor.getKeepAliveTime( TimeUnit.SECONDS ) ).isEqualTo( 3L ); - assertThat( executor.getMaximumPoolSize() ).isEqualTo( 2 ); + assertThat( executor.getMaximumPoolSize() ).isEqualTo( 1 ); } @Test diff --git a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/PpidCheckerTest.java b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/PpidCheckerTest.java index e67d0b3..ce1066b 100644 --- a/surefire-booter/src/test/java/org/apache/maven/surefire/booter/PpidCheckerTest.java +++ b/surefire-booter/src/test/java/org/apache/maven/surefire/booter/PpidCheckerTest.java @@ -84,7 +84,7 @@ public class PpidCheckerTest .isEqualTo( expectedPid ); assertThat( processInfo.getTime() ) - .isNotNull(); + .isGreaterThan( 0L ); } @Test @@ -117,7 +117,7 @@ public class PpidCheckerTest .isEqualTo( expectedPid ); assertThat( processInfo.getTime() ) - .isNotNull(); + .isGreaterThan( 0L ); assertThat( checker.toString() ) .contains( "ppid=" + expectedPid ) @@ -329,6 +329,6 @@ public class PpidCheckerTest private static long windowsProcessStartTime( PpidChecker checker ) { - return (long) checker.windows().getTime(); + return checker.windows().getTime(); } }
