[SUREFIRE-1926] Console logs should be synchronized

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/booterclient/ForkStarter.java

@@ -33,6 +33,7 @@
 import org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer;
 import org.apache.maven.plugin.surefire.log.api.ConsoleLogger;
 import org.apache.maven.plugin.surefire.report.DefaultReporterFactory;
+import org.apache.maven.plugin.surefire.report.ReportsMerger;
 import org.apache.maven.surefire.booter.AbstractPathConfiguration;
 import org.apache.maven.surefire.booter.PropertiesWrapper;
 import org.apache.maven.surefire.booter.ProviderConfiguration;
@@ -155,7 +156,7 @@ public class ForkStarter
 
     private final ConsoleLogger log;
 
-    private final DefaultReporterFactory defaultReporterFactory;
+    private final ReportsMerger reportMerger;
 
     private final Collection<DefaultReporterFactory> defaultReporterFactories;
 
@@ -206,7 +207,7 @@ public void run()
                     // if tests failed, but if this does not happen then printing warning to console is the only way to
                     // inform the users.
                     String msg = "ForkStarter IOException: " + e.getLocalizedMessage() + ".";
-                    File reportsDir = defaultReporterFactory.getReportsDirectory();
+                    File reportsDir = reportMerger.getReportsDirectory();
                     File dump = InPluginProcessDumpSingleton.getSingleton()
                                         .dumpStreamException( e, msg, reportsDir, jvmRun );
                     log.warning( msg + " See the dump file " + dump.getAbsolutePath() );
@@ -247,8 +248,8 @@ public ForkStarter( ProviderConfiguration providerConfiguration, StartupConfigur
         this.startupConfiguration = startupConfiguration;
         this.startupReportConfiguration = startupReportConfiguration;
         this.log = log;
-        defaultReporterFactory = new DefaultReporterFactory( startupReportConfiguration, log );
-        defaultReporterFactory.runStarting();
+        reportMerger = new DefaultReporterFactory( startupReportConfiguration, log );
+        reportMerger.runStarting();
         defaultReporterFactories = new ConcurrentLinkedQueue<>();
         currentForkClients = new ConcurrentLinkedQueue<>();
         timeoutCheckScheduler = createTimeoutCheckScheduler();
@@ -268,8 +269,8 @@ public RunResult run( @Nonnull SurefireProperties effectiveSystemProperties, @No
         }
         finally
         {
-            defaultReporterFactory.mergeFromOtherFactories( defaultReporterFactories );
-            defaultReporterFactory.close();
+            reportMerger.mergeFromOtherFactories( defaultReporterFactories );
+            reportMerger.close();
             pingThreadScheduler.shutdownNow();
             timeoutCheckScheduler.shutdownNow();
             for ( String line : logsAtEnd )
@@ -574,8 +575,8 @@ private RunResult fork( Object testSet, PropertiesWrapper providerProperties, Fo
         File dumpLogDir = replaceForkThreadsInPath( startupReportConfiguration.getReportsDirectory(), forkNumber );
         try
         {
-            ForkNodeArguments forkNodeArguments =
-                new ForkedNodeArg( forkConfiguration.isDebug(), forkNumber, dumpLogDir, randomUUID().toString() );
+            ForkNodeArguments forkNodeArguments = new ForkedNodeArg( forkConfiguration.isDebug(), forkNumber,
+                dumpLogDir, randomUUID().toString() );
             forkChannel = forkNodeFactory.createForkChannel( forkNodeArguments );
             closer.addCloseable( forkChannel );
             tempDir = forkConfiguration.getTempDirectory().getCanonicalPath();
@@ -639,7 +640,7 @@ private RunResult fork( Object testSet, PropertiesWrapper providerProperties, Fo
             CommandlineStreams streams = exec.execute();
             closer.addCloseable( streams );
 
-            err = bindErrorStream( forkNumber, countdownCloseable, streams );
+            err = bindErrorStream( forkNumber, countdownCloseable, streams, forkClient.getConsoleOutputReceiver() );
 
             forkChannel.bindCommandReader( commandReader, streams.getStdInChannel() );
 
@@ -753,10 +754,10 @@ else if ( result != SUCCESS )
         return runResult;
     }
 
-    private Stoppable bindErrorStream( int forkNumber, CountdownCloseable countdownCloseable,
-                                       CommandlineStreams streams )
+    private static Stoppable bindErrorStream( int forkNumber, CountdownCloseable countdownCloseable,
+                                              CommandlineStreams streams, Object errorStreamLock )
     {
-        EventHandler<String> errConsumer = new NativeStdErrStreamConsumer( log );
+        EventHandler<String> errConsumer = new NativeStdErrStreamConsumer( errorStreamLock );
         LineConsumerThread stdErr = new LineConsumerThread( "fork-" + forkNumber + "-err-thread",
             streams.getStdErrChannel(), errConsumer, countdownCloseable );
         stdErr.start();
@@ -938,6 +939,13 @@ public ConsoleLogger getConsoleLogger()
             return log;
         }
 
+        @Nonnull
+        @Override
+        public Object getConsoleLock()
+        {
+            return log;
+        }
+
         @Override
         public File getEventStreamBinaryFile()
         {

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/booterclient/output/ForkClient.java

@@ -78,7 +78,7 @@ public class ForkClient
 
     private final int forkNumber;
 
-    private RunListener testSetReporter;
+    private volatile RunListener testSetReporter;
 
     /**
      * Written by one Thread and read by another: Main Thread and ForkStarter's Thread.
@@ -340,7 +340,7 @@ public final void tryToTimeout( long currentTimeMillis, int forkedProcessTimeout
     {
         if ( forkedProcessTimeoutInSeconds > 0 )
         {
-            final long forkedProcessTimeoutInMillis = 1000 * forkedProcessTimeoutInSeconds;
+            final long forkedProcessTimeoutInMillis = 1000L * forkedProcessTimeoutInSeconds;
             final long startedAt = testSetStartedAt.get();
             if ( startedAt > START_TIME_ZERO && currentTimeMillis - startedAt >= forkedProcessTimeoutInMillis )
             {
@@ -376,11 +376,20 @@ public final boolean hadTimeout()
         return testSetStartedAt.get() == START_TIME_NEGATIVE_TIMEOUT;
     }
 
+    /**
+     * Only {@link #getConsoleOutputReceiver()} may call this method in another Thread.
+     */
     private RunListener getTestSetReporter()
     {
         if ( testSetReporter == null )
         {
-            testSetReporter = defaultReporterFactory.createReporter();
+            synchronized ( this )
+            {
+                if ( testSetReporter == null )
+                {
+                    testSetReporter = defaultReporterFactory.createReporter();
+                }
+            }
         }
         return testSetReporter;
     }
@@ -394,7 +403,7 @@ void dumpToLoFile( String msg )
 
     private void writeTestOutput( String output, boolean newLine, boolean isStdout )
     {
-        getOrCreateConsoleOutputReceiver()
+        getConsoleOutputReceiver()
                 .writeTestOutput( output, newLine, isStdout );
     }
 
@@ -414,7 +423,7 @@ public final RunListener getReporter()
         return getTestSetReporter();
     }
 
-    private ConsoleOutputReceiver getOrCreateConsoleOutputReceiver()
+    public ConsoleOutputReceiver getConsoleOutputReceiver()
     {
         return (ConsoleOutputReceiver) getTestSetReporter();
     }

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/booterclient/output/NativeStdErrStreamConsumer.java

@@ -19,13 +19,12 @@
  * under the License.
  */
 
-import org.apache.maven.plugin.surefire.log.api.ConsoleLogger;
 import org.apache.maven.surefire.extensions.EventHandler;
 
 import javax.annotation.Nonnull;
 
 /**
- * The error logger for the error stream of the forked JMV,
+ * The standard error logger for the error stream of the forked JMV,
  * see {@link org.apache.maven.plugin.surefire.booterclient.ForkStarter}.
  *
  * @author <a href="mailto:tibordigana@apache.org">Tibor Digana (tibor17)</a>
@@ -35,16 +34,19 @@
 public final class NativeStdErrStreamConsumer
     implements EventHandler<String>
 {
-    private final ConsoleLogger logger;
+    private final Object errStreamLock;
 
-    public NativeStdErrStreamConsumer( ConsoleLogger logger )
+    public NativeStdErrStreamConsumer( Object errStreamLock )
     {
-        this.logger = logger;
+        this.errStreamLock = errStreamLock;
     }
 
     @Override
-    public void handleEvent( @Nonnull String line )
+    public void handleEvent( @Nonnull String message )
     {
-        logger.error( line );
+        synchronized ( errStreamLock )
+        {
+            System.err.println( message );
+        }
     }
 }

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/booterclient/output/NativeStdOutStreamConsumer.java

@@ -19,13 +19,12 @@
  * under the License.
  */
 
-import org.apache.maven.plugin.surefire.log.api.ConsoleLogger;
 import org.apache.maven.surefire.extensions.EventHandler;
 
 import javax.annotation.Nonnull;
 
 /**
- * The output/INFO logger for the output stream of the forked JMV,
+ * The standard output logger for the output stream of the forked JMV,
  * see org.apache.maven.plugin.surefire.extensions.SurefireForkChannel.
  *
  * @author <a href="mailto:tibordigana@apache.org">Tibor Digana (tibor17)</a>
@@ -34,16 +33,19 @@
 public final class NativeStdOutStreamConsumer
     implements EventHandler<String>
 {
-    private final ConsoleLogger logger;
+    private final Object outStreamLock;
 
-    public NativeStdOutStreamConsumer( ConsoleLogger logger )
+    public NativeStdOutStreamConsumer( Object outStreamLock )
     {
-        this.logger = logger;
+        this.outStreamLock = outStreamLock;
     }
 
     @Override
-    public void handleEvent( @Nonnull String event )
+    public void handleEvent( @Nonnull String message )
     {
-        logger.info( event );
+        synchronized ( outStreamLock )
+        {
+            System.out.println( message );
+        }
     }
 }

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/extensions/SurefireForkChannel.java

@@ -143,7 +143,7 @@ public void bindEventHandler( @Nonnull EventHandler<Event> eventHandler,
     {
         ForkNodeArguments args = getArguments();
         out = new LineConsumerThread( "fork-" + args.getForkChannelId() + "-out-thread", stdOut,
-            new NativeStdOutStreamConsumer( args.getConsoleLogger() ), countdown );
+            new NativeStdOutStreamConsumer( args.getConsoleLock() ), countdown );
         out.start();
 
         eventBindings = new EventBindings( eventHandler, countdown );

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/log/PluginConsoleLogger.java

@@ -25,6 +25,10 @@
 /**
  * Wrapper logger of miscellaneous implementations of {@link Logger}.
  *
+ * This instance is synchronized. The logger operations are mutually exclusive to standard out, standard err and console
+ * err/warn/info/debug logger operations, see {@link org.apache.maven.plugin.surefire.report.DefaultReporterFactory},
+ * {@link org.apache.maven.plugin.surefire.report.TestSetRunListener}.
+ *
  * @author <a href="mailto:tibordigana@apache.org">Tibor Digana (tibor17)</a>
  * @since 2.20
  * @see ConsoleLogger
@@ -46,12 +50,12 @@ public boolean isDebugEnabled()
     }
 
     @Override
-    public void debug( String message )
+    public synchronized void debug( String message )
     {
         plexusLogger.debug( message );
     }
 
-    public void debug( CharSequence content, Throwable error )
+    public synchronized void debug( CharSequence content, Throwable error )
     {
         plexusLogger.debug( content == null ? "" : content.toString(), error );
     }
@@ -63,7 +67,7 @@ public boolean isInfoEnabled()
     }
 
     @Override
-    public void info( String message )
+    public synchronized void info( String message )
     {
         plexusLogger.info( message );
     }
@@ -75,12 +79,12 @@ public boolean isWarnEnabled()
     }
 
     @Override
-    public void warning( String message )
+    public synchronized void warning( String message )
     {
         plexusLogger.warn( message );
     }
 
-    public void warning( CharSequence content, Throwable error )
+    public synchronized void warning( CharSequence content, Throwable error )
     {
         plexusLogger.warn( content == null ? "" : content.toString(), error );
     }
@@ -92,19 +96,19 @@ public boolean isErrorEnabled()
     }
 
     @Override
-    public void error( String message )
+    public synchronized void error( String message )
     {
         plexusLogger.error( message );
     }
 
     @Override
-    public void error( String message, Throwable t )
+    public synchronized void error( String message, Throwable t )
     {
         plexusLogger.error( message, t );
     }
 
     @Override
-    public void error( Throwable t )
+    public synchronized void error( Throwable t )
     {
         plexusLogger.error( "", t );
     }

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/report/DefaultReporterFactory.java

@@ -65,7 +65,7 @@
  * @author Kristian Rosenvold
  */
 public class DefaultReporterFactory
-    implements ReporterFactory
+    implements ReporterFactory, ReportsMerger
 {
     private final Collection<TestSetRunListener> listeners = new ConcurrentLinkedQueue<>();
     private final StartupReportConfiguration reportConfiguration;
@@ -107,11 +107,13 @@ public RunListener createReporter()
                                     createStatisticsReporter(),
                                     reportConfiguration.isTrimStackTrace(),
                                     PLAIN.equals( reportConfiguration.getReportFormat() ),
-                                    reportConfiguration.isBriefOrPlainFormat() );
+                                    reportConfiguration.isBriefOrPlainFormat(),
+                                    consoleLogger );
         addListener( testSetRunListener );
         return testSetRunListener;
     }
 
+    @Override
     public File getReportsDirectory()
     {
         return reportConfiguration.getReportsDirectory();
@@ -151,6 +153,7 @@ private StatisticsReporter createStatisticsReporter()
         return useNonNull( statisticsReporter, NullStatisticsReporter.INSTANCE );
     }
 
+    @Override
     public void mergeFromOtherFactories( Collection<DefaultReporterFactory> factories )
     {
         for ( DefaultReporterFactory factory : factories )
@@ -176,6 +179,7 @@ public RunResult close()
         return globalStats.getRunResult();
     }
 
+    @Override
     public void runStarting()
     {
         if ( reportConfiguration.isPrintSummary() )

maven-surefire-common/src/main/java/org/apache/maven/plugin/surefire/report/ReportsMerger.java

@@ -0,0 +1,36 @@
+package org.apache.maven.plugin.surefire.report;
+
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+import org.apache.maven.surefire.api.suite.RunResult;
+
+import java.io.File;
+import java.util.Collection;
+
+/**
+ * This interface is used to merge reports in {@link org.apache.maven.plugin.surefire.booterclient.ForkStarter}.
+ */
+public interface ReportsMerger
+{
+    void runStarting();
+    void mergeFromOtherFactories( Collection<DefaultReporterFactory> factories );
+    File getReportsDirectory();
+    RunResult close();
+}