Add buffered logging option

build.sbt

@@ -279,7 +279,9 @@ lazy val tests = crossProject(JSPlatform, JVMPlatform, NativePlatform)
   .jsSettings(sharedJSSettings)
   .jvmSettings(
     sharedJVMSettings,
-    fork := true
+    fork := true,
+    Test / parallelExecution := true,
+    Test / testOptions += Tests.Argument(TestFrameworks.MUnit, "+b")
   )
   .disablePlugins(MimaPlugin)
 lazy val testsJVM = tests.jvm

docs/tests.md

@@ -118,6 +118,14 @@ parallel test suite execution in sbt, add the following setting to `build.sbt`.
 Test / parallelExecution := false
 ```
 
+In case you do run your tests in parallel, you might also want to enable buffered logging, 
+so that the test results of multiple suites do not appear interleaved.
+In contrast to other test frameworks, buffered logging is not the default in munit.
+
+```sh
+Test / testOptions += Tests.Argument(TestFrameworks.MUnit, "+b")
+```
+
 To learn more about sbt test execution, see
 https://www.scala-sbt.org/1.x/docs/Testing.html.
 

junit-interface/src/main/java/munit/internal/junitinterface/EventDispatcher.java

@@ -5,6 +5,8 @@
 import java.util.Set;
 import java.util.concurrent.ConcurrentHashMap;
 import java.io.IOException;
+import java.util.concurrent.ConcurrentLinkedDeque;
+import java.util.stream.Collectors;
 
 import org.junit.runner.Description;
 import org.junit.runner.Result;
@@ -30,6 +32,8 @@ final class EventDispatcher extends RunListener
   private final RunStatistics runStatistics;
   private OutputCapture capture;
 
+  private final static Description TEST_RUN = Description.createTestDescription("Test", "run");
+
   EventDispatcher(RichLogger logger, EventHandler handler, RunSettings settings, Fingerprint fingerprint,
                   Description taskDescription, RunStatistics runStatistics)
   {
@@ -71,7 +75,7 @@ public void testAssumptionFailure(final Failure failure)
     postIfFirst(failure.getDescription(), new ErrorEvent(failure, Status.Skipped) {
       void logTo(RichLogger logger) {
         if (settings.verbose) {
-          logger.info(Ansi.c("==> i "  + failure.getDescription().getMethodName(), WARNMSG));
+          logger.info(failure.getDescription(), Ansi.c("==> i "  + failure.getDescription().getMethodName(), WARNMSG));
         }
       }
     });
@@ -95,7 +99,7 @@ public void testFailure(final Failure failure)
     uncapture(true);
     postIfFirst(failure.getDescription(), new ErrorEvent(failure, Status.Failure) {
       void logTo(RichLogger logger) {
-        logger.error( settings.buildTestResult(Status.Failure) +ansiName+" "+ durationSuffix() + " " + ansiMsg, error);
+        logger.error( failure.getDescription(), settings.buildTestResult(Status.Failure) +ansiName+" "+ durationSuffix() + " " + ansiMsg, error);
       }
     });
   }
@@ -107,7 +111,7 @@ public void testFinished(Description desc)
     uncapture(false);
     postIfFirst(desc, new InfoEvent(desc, Status.Success) {
       void logTo(RichLogger logger) {
-        logger.info(settings.buildTestResult(Status.Success) + Ansi.c(desc.getMethodName(), SUCCESS1) + durationSuffix());
+        logger.info(desc, settings.buildTestResult(Status.Success) + Ansi.c(desc.getMethodName(), SUCCESS1) + durationSuffix());
       }
     });
     logger.popCurrentTestClassName();
@@ -118,31 +122,31 @@ public void testIgnored(Description desc)
   {
     postIfFirst(desc, new InfoEvent(desc, Status.Skipped) {
       void logTo(RichLogger logger) {
-        logger.warn(settings.buildTestResult(Status.Ignored) + ansiName+" ignored" + durationSuffix());
+        logger.warn(desc, settings.buildTestResult(Status.Ignored) + ansiName+" ignored" + durationSuffix());
       }
     });
   }
 
 
   @Override
-  public void testSuiteStarted(Description description)
+  public void testSuiteStarted(Description desc)
   {
-    if (description == null || description.getClassName() == null || description.getClassName().equals("null")) return;
-    reportedSuites.add(description.getClassName());
-    logger.info(c(description.getClassName() + ":", SUCCESS1));
+    if (desc == null || desc.getClassName() == null || desc.getClassName().equals("null")) return;
+    reportedSuites.add(desc.getClassName());
+    logger.info(desc, c(desc.getClassName() + ":", SUCCESS1));
   }
 
 
   @Override
-  public void testStarted(Description description)
+  public void testStarted(Description desc)
   {
-    recordStartTime(description);
-    if (reportedSuites.add(description.getClassName())) {
-      testSuiteStarted(description);
+    recordStartTime(desc);
+    if (reportedSuites.add(desc.getClassName())) {
+      testSuiteStarted(desc);
     }
-    logger.pushCurrentTestClassName(description.getClassName());
+    logger.pushCurrentTestClassName(desc.getClassName());
     if (settings.verbose) {
-      logger.info(settings.buildPlainName(description) + " started");
+      logger.info(desc, settings.buildPlainName(desc) + " started");
     }
     capture();
   }
@@ -164,32 +168,39 @@ private Long elapsedTime(Description description) {
   public void testRunFinished(Result result)
   {
       if (settings.verbose) {
-        logger.info("Test run " +taskInfo+" finished: "+
+        logger.info(TEST_RUN, "Test run " +taskInfo+" finished: "+
           result.getFailureCount()+" failed" +
           ", " +
           result.getIgnoreCount()+" ignored" +
           ", "+result.getRunCount()+" total, "+(result.getRunTime()/1000.0)+"s") ;
       }
     runStatistics.addTime(result.getRunTime());
+      logger.flush(TEST_RUN);
   }
 
   @Override
-  public void testRunStarted(Description description)
+  public void testSuiteFinished(Description description) throws Exception {
+    logger.flush(description);
+  }
+
+  @Override
+  public void testRunStarted(Description desc)
   {
       if (settings.verbose) {
-        logger.info(taskInfo + " started");
+        logger.info(desc, taskInfo + " started");
       }
   }
 
   void testExecutionFailed(String testName, Throwable err)
   {
     post(new Event(Ansi.c(testName, Ansi.ERRMSG), settings.buildErrorMessage(err), Status.Error, 0L, err) {
       void logTo(RichLogger logger) {
-        logger.error(ansiName+" failed: "+ansiMsg, error);
+        logger.error(TEST_RUN, ansiName+" failed: "+ansiMsg, error);
       }
     });
   }
 
+
   private void postIfFirst(Description desc, AbstractEvent e)
   {
     if(reported.add(desc)) {
@@ -220,7 +231,7 @@ void uncapture(boolean replay)
       if(replay)
       {
         try { capture.replay(); }
-        catch(IOException ex) { logger.error("Error replaying captured stdio", ex); }
+        catch(IOException ex) { logger.error(TEST_RUN, "Error replaying captured stdio", ex); }
       }
       capture = null;
     }

junit-interface/src/main/java/munit/internal/junitinterface/JUnitRunner.java

@@ -35,7 +35,7 @@ final class JUnitRunner implements Runner {
     Settings defaults = Settings.defaults();
 
     boolean quiet = false, nocolor = false, decodeScalaNames = false,
-        logAssert = true, logExceptionClass = true, useSbtLoggers = false;
+        logAssert = true, logExceptionClass = true, useSbtLoggers = false, useBufferedLoggers = false;
     boolean verbose = false;
     boolean suppressSystemError = false;
     boolean trimStackTraces = defaults.trimStackTraces();
@@ -59,6 +59,10 @@ final class JUnitRunner implements Runner {
       else if("-a".equals(s)) logAssert = true;
       else if("-c".equals(s)) logExceptionClass = false;
       else if("+l".equals(s)) useSbtLoggers = true;
+      else if("+b".equals(s)) useBufferedLoggers = true;
+      else if("-b".equals(s)) useBufferedLoggers = false;
+      else if("--logger=sbt".equals(s)) useSbtLoggers = true;
+      else if("--logger=buffered".equals(s)) useBufferedLoggers = true;
       else if("-l".equals(s)) useSbtLoggers = false;
       else if("-F".equals(s)) trimStackTraces = false;
       else if("+F".equals(s)) trimStackTraces = true;
@@ -86,7 +90,7 @@ else if(s.startsWith("-D") && s.contains("=")) {
       else if("--stderr".equals(s)) suppressSystemError = false;
     }
     this.settings =
-      new RunSettings(!nocolor, decodeScalaNames, quiet, verbose, useSbtLoggers, trimStackTraces, summary, logAssert, ignoreRunners, logExceptionClass,
+      new RunSettings(!nocolor, decodeScalaNames, quiet, verbose, useSbtLoggers, useBufferedLoggers, trimStackTraces, summary, logAssert, ignoreRunners, logExceptionClass,
           suppressSystemError, sysprops, globPatterns, includeCategories, excludeCategories, includeTags, excludeTags,
         testFilter);
     this.runListener = createRunListener(runListener);

junit-interface/src/main/java/munit/internal/junitinterface/RichLogger.java

@@ -8,7 +8,9 @@
 import java.util.Set;
 import java.util.Stack;
 import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.ConcurrentLinkedDeque;
 
+import org.junit.runner.Description;
 import sbt.testing.Logger;
 import static munit.internal.junitinterface.Ansi.*;
 
@@ -21,6 +23,7 @@ final class RichLogger
   /* The top element is the test class of the currently executing test */
   private final Stack<String> currentTestClassName = new Stack<String>();
   private final Map<String, Boolean> highlightedCache = new HashMap<>();
+  private final ConcurrentHashMap<String, ConcurrentLinkedDeque<String>> buffers = new ConcurrentHashMap<>();
 
   RichLogger(Logger[] loggers, RunSettings settings, String testClassName, JUnitRunner runner)
   {
@@ -37,70 +40,71 @@ void popCurrentTestClassName()
     if(currentTestClassName.size() > 1) currentTestClassName.pop();
   }
 
-  void debug(String s)
-  {
-    // Disabled by default because debug logging is noisy and enabled by default in sbt.
-    if (settings.useSbtLoggers) {
-      for(Logger l : loggers)
-      if(settings.color && l.ansiCodesSupported()) l.debug(s);
-      else l.debug(filterAnsi(s));
-    }
-  }
-
-  void error(String s)
+  void error(Description desc, String s)
   {
     if (settings.useSbtLoggers) {
       for (Logger l : loggers)
         if (settings.color && l.ansiCodesSupported()) l.error(s);
         else l.error(filterAnsi(s));
+    } else if (settings.useBufferedLoggers) {
+      bufferMessage(desc, s);
     } else {
       System.out.println(s);
     }
   }
 
-  void error(String s, Throwable t)
+  void error(Description desc, String s, Throwable t)
   {
-    error(s);
-    if(t != null && (settings.logAssert || !(t instanceof AssertionError))) logStackTrace(t);
+    error(desc, s);
+    if(t != null && (settings.logAssert || !(t instanceof AssertionError))) logStackTrace(desc, t);
   }
 
-  void info(String s)
+  void info(Description desc, String s)
   {
     if (settings.useSbtLoggers) {
       for (Logger l : loggers)
         if (settings.color && l.ansiCodesSupported()) l.info(s);
         else l.info(filterAnsi(s));
+    } else if (settings.useBufferedLoggers) {
+      bufferMessage(desc, s);
     } else {
       System.out.println(s);
     }
   }
 
-  void warn(String s)
+  void warn(Description desc, String s)
   {
     if (settings.useSbtLoggers) {
       for (Logger l : loggers)
         if (settings.color && l.ansiCodesSupported()) l.warn(s);
         else l.warn(filterAnsi(s));
+    } else if (settings.useBufferedLoggers) {
+      bufferMessage(desc, s);
     } else {
       System.out.println(s);
     }
   }
 
-  void warn(String s, Throwable t)
-  {
-    warn(s);
-    if(t != null && (settings.logAssert || !(t instanceof AssertionError))) logStackTrace(t);
+  void flush(Description desc) {
+    ConcurrentLinkedDeque<String> logs = buffers.remove(String.valueOf(desc.getClassName()));
+    if (logs != null) {
+      System.out.println(String.join("\n", logs));
+    }
   }
 
-  private void logStackTrace(Throwable t)
+  private void bufferMessage(Description desc, String message) {
+    ConcurrentLinkedDeque<String> logs = buffers.computeIfAbsent(String.valueOf(desc.getClassName()), d -> new ConcurrentLinkedDeque<>());
+    logs.addLast(message);
+  }
+  private void logStackTrace(Description desc, Throwable t)
   {
     StackTraceElement[] trace = t.getStackTrace();
     String testClassName = currentTestClassName.peek();
     String testFileName = settings.color ? findTestFileName(trace, testClassName) : null;
-    logStackTracePart(trace, trace.length-1, 0, t, testClassName, testFileName);
+    logStackTracePart(desc, trace, trace.length-1, 0, t, testClassName, testFileName);
   }
 
-  private void logStackTracePart(StackTraceElement[] trace, int m, int framesInCommon, Throwable t, String testClassName, String testFileName)
+  private void logStackTracePart(Description desc, StackTraceElement[] trace, int m, int framesInCommon, Throwable t, String testClassName, String testFileName)
   {
     final int m0 = m;
     int top = 0;
@@ -126,22 +130,22 @@ private void logStackTracePart(StackTraceElement[] trace, int m, int framesInCom
     }
     for(int i=top; i<=m; i++) {
       if (!trace[i].getClassName().startsWith("scala.runtime."))
-        error(stackTraceElementToString(trace[i], testClassName, testFileName));
+        error(desc, stackTraceElementToString(trace[i], testClassName, testFileName));
     }
     if(m0 != m)
     {
       // skip junit-related frames
-      error("    ...");
+      error(desc, "    ...");
     }
     else if(framesInCommon != 0)
     {
       // skip frames that were in the previous trace too
-      error("    ... " + framesInCommon + " more");
+      error(desc, "    ... " + framesInCommon + " more");
     }
-    logStackTraceAsCause(trace, t.getCause(), testClassName, testFileName);
+    logStackTraceAsCause(desc, trace, t.getCause(), testClassName, testFileName);
   }
 
-  private void logStackTraceAsCause(StackTraceElement[] causedTrace, Throwable t, String testClassName, String testFileName)
+  private void logStackTraceAsCause(Description desc, StackTraceElement[] causedTrace, Throwable t, String testClassName, String testFileName)
   {
     if(t == null) return;
     StackTraceElement[] trace = t.getStackTrace();
@@ -151,8 +155,8 @@ private void logStackTraceAsCause(StackTraceElement[] causedTrace, Throwable t,
       m--;
       n--;
     }
-    error("Caused by: " + t);
-    logStackTracePart(trace, m, trace.length-1-m, t, testClassName, testFileName);
+    error(desc, "Caused by: " + t);
+    logStackTracePart(desc, trace, m, trace.length-1-m, t, testClassName, testFileName);
   }
 
   private String findTestFileName(StackTraceElement[] trace, String testClassName)

junit-interface/src/main/java/munit/internal/junitinterface/RunSettings.java

@@ -30,6 +30,7 @@ class RunSettings implements Settings {
   final boolean logExceptionClass;
   final Set<String> includeTags, excludeTags;
   final boolean useSbtLoggers;
+  final boolean useBufferedLoggers;
   final boolean trimStackTraces;
   final boolean verbose;
   final boolean suppressSystemError;
@@ -43,7 +44,7 @@ class RunSettings implements Settings {
   private final HashSet<String> ignoreRunners = new HashSet<String>();
 
   RunSettings(boolean color, boolean decodeScalaNames, boolean quiet,
-              boolean verbose, boolean useSbtLoggers, boolean trimStackTraces,
+              boolean verbose, boolean useSbtLoggers, boolean useBufferedLoggers, boolean trimStackTraces,
               Summary summary, boolean logAssert, String ignoreRunners,
               boolean logExceptionClass,
               boolean suppressSystemError, HashMap<String, String> sysprops,
@@ -69,6 +70,7 @@ class RunSettings implements Settings {
     this.excludeCategories = excludeCategories;
     this.testFilter = testFilter;
     this.useSbtLoggers = useSbtLoggers;
+    this.useBufferedLoggers = useBufferedLoggers;
     this.trimStackTraces = trimStackTraces;
   }