Skip to content

Commit

Permalink
[SUREFIRE-1995] Ping and process checker should use isolated schedule…
Browse files Browse the repository at this point in the history 
…rs and the errors should be logged
  • Loading branch information
@Tibor17
Tibor17 committed Feb 1, 2022
1 parent 7fc9474 commit 50d680e
Show file tree
Hide file tree
Showing 6 changed files with 90 additions and 78 deletions.
108 changes: 69 additions & 39 deletions surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java
View file
Expand Up @@ -31,8 +31,6 @@
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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -138,10 +140,10 @@ private void setupBooter( String tmpDir, String dumpFileName, String surefirePro
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 );

Expand Down Expand Up @@ -169,16 +171,12 @@ private void execute()
{
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
{
Expand All @@ -187,10 +185,11 @@ private void execute()

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();
}
}
Expand Down Expand Up @@ -247,26 +246,37 @@ private void closeForkChannel()
}
}

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 );
}

Expand All @@ -282,10 +292,11 @@ public void run()
{
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
Expand Down Expand Up @@ -327,19 +338,31 @@ public void update( Command command )
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
Expand Down Expand Up @@ -373,6 +396,7 @@ public void run()
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
Expand Down Expand Up @@ -463,6 +487,12 @@ private void launchLastDitchDaemonShutdownThread( final int returnCode )
@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()
Expand Down Expand Up @@ -572,11 +602,9 @@ private static void run( ForkedBooter booter, String[] args )
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();
Expand All @@ -601,12 +629,11 @@ private static boolean acquireOnePermit( Semaphore barrier, long timeoutMillis )
}
}

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;
}

Expand All @@ -632,20 +659,24 @@ private static boolean isDebugging()
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();
}
}
}
Expand Down Expand Up @@ -679,5 +710,4 @@ private static String getProcessName()
return ManagementFactory.getRuntimeMXBean()
.getName();
}

}
4 changes: 2 additions & 2 deletions surefire-booter/src/main/java/org/apache/maven/surefire/booter/PpidChecker.java
View file
Expand Up @@ -59,7 +59,7 @@
*/
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;
Expand Down Expand Up @@ -250,7 +250,7 @@ void destroyActiveCommands()
}
}

private boolean isStopped()
boolean isStopped()
{
return stopped;
}
Expand Down
16 changes: 7 additions & 9 deletions surefire-booter/src/main/java/org/apache/maven/surefire/booter/ProcessInfo.java
View file
Expand Up @@ -34,8 +34,8 @@
*/
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:
Expand All @@ -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;
Expand All @@ -82,26 +82,24 @@ String getPID()
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()
Expand Down
26 changes: 6 additions & 20 deletions surefire-booter/src/test/java/org/apache/maven/surefire/booter/ForkedBooterMockTest.java
View file
Expand Up @@ -19,10 +19,10 @@
* 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;
Expand Down Expand Up @@ -66,6 +66,7 @@
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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -187,7 +182,7 @@ public void testMainWithError() throws Exception
.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 );
Expand All @@ -198,17 +193,8 @@ public void testMainWithError() throws Exception
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" );
Expand Down

0 comments on commit 50d680e

Please sign in to comment.