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:32 UTC

[maven-surefire] branch SUREFIRE-1995 created (now f49b3bd)

This is an automated email from the ASF dual-hosted git repository.

tibordigana pushed a change to branch SUREFIRE-1995
in repository https://gitbox.apache.org/repos/asf/maven-surefire.git.


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

This branch includes the following new commits:

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

The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails.  The revisions
listed as "add" were already present in the repository and have only
been added to this reference.


[maven-surefire] 01/01: [SUREFIRE-1995] Ping and process checker should use isolated schedulers and the errors should be logged

Posted by ti...@apache.org.
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();
     }
 }