Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[SUREFIRE-1995] Ping and process checker should use isolated schedulers and the errors should be logged #454

Merged
merged 1 commit into from Feb 1, 2022
Merged

[SUREFIRE-1995] Ping and process checker should use isolated schedulers and the errors should be logged #454

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
108 changes: 69 additions & 39 deletions surefire-booter/src/main/java/org/apache/maven/surefire/booter/ForkedBooter.java
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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