You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@maven.apache.org by ti...@apache.org on 2022/01/31 01:21:33 UTC
[maven-surefire] 01/01: [SUREFIRE-1995] Ping and process checker should use isolated schedulers and the errors should be logged
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 <ti...@apache.org>
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();
}
}