Improved logging

- "Test run started/finished" messages include class name.
- More useful verbosity settings with a new option to show only the
  (now more useful) "Test run finished" messages.
- Optional summary with more details.

Author: szeiger

README.md

@@ -16,13 +16,13 @@ The following options are supported for JUnit tests:
 
  Option                                       | Description
 :---------------------------------------------|:----------------------
- `-v`                                         | Log "test run started" / "test started" / "test run finished" events on log level "info" instead of "debug".
+ `-v`                                         | Same as `--verbosity=2`
  `-q`                                         | Suppress stdout for successful tests. Stderr is printed to the console normally. Stdout is written to a buffer and discarded when a test succeeds. If it fails, the buffer is dumped to the console. Since stdio redirection in Java is a bad kludge (`System.setOut()` changes the static final field System.out through native code) this may not work for all scenarios. Scala has its own console with a sane redirection feature. If Scala is detected on the class path, junit-interface tries to reroute scala.Console's stdout, too.
  `-n`                                         | Do not use ANSI colors in the output even if sbt reports that they are supported.
  `-s`                                         | Try to decode Scala names in stack traces and test names. Fall back silently to non-decoded names if no matching Scala library is on the class path.
  `-a`                                         | Show stack traces and exception class name for AssertionErrors (thrown by all assert* methods in JUnit).`
  `-c`                                         | Do not print the exception class name prefix for any messages. With this option, only the result of getMessage() plus a stack trace is shown.
- `+v`                                         | Turn off `-v`. Takes precedence over `-v`.
+ `+v`                                         | Same as `--verbosity=0`
  `+q`                                         | Turn off `-q`. Takes precedence over `-q`.
  `+n`                                         | Turn off `-n`. Takes precedence over `-n`.
  `+s`                                         | Turn off `-s`. Takes precedence over `-s`.
@@ -34,6 +34,8 @@ The following options are supported for JUnit tests:
  `--run-listener=<CLASS_NAME>`                | A (user defined) class which extends `org.junit.runner.notification.RunListener`. An instance of this class is created and added to the JUnit Runner, so that it will receive the run events. For more information, see [RunListener](http://junit.org/javadoc/latest/org/junit/runner/notification/RunListener.html). *Note: this uses the test-classloader, so the class needs to be defined in `src/test` or `src/main` or included as a test or compile dependency*
  `--include-categories=<CLASSES>`             | A comma separated list of category class names that should be included. Only tests with one or more of these categories will be run.
  `--exclude-categories=<CLASSES>`             | A comma separated list of category class names that should be excluded. No tests that match one or more of these categories will be run.
+ `--verbosity=<INT>`                          | Higher verbosity logs more events at level "info" instead of "debug". 0: Default; 1: "Test run finished" at info; 2: Also "test run started" and "test started" at info; 3: Also "test finished" at info.
+ `--summary=<INT>`                            | The type of summary to show for a test task execution. 0: Leave to sbt (default); 1: One line; 2: Include list of failed tests
 
 Any parameter not starting with `-` or `+` is treated as a glob pattern for matching tests. Unlike the patterns given directly to sbt's `test-only` command, the patterns given to junit-interface will match against the full test names (as displayed by junit-interface) of all atomic test cases, so you can match on test methods and parts of suites with custom runners.
 

src/main/java/com/novocode/junit/EventDispatcher.java

@@ -1,5 +1,6 @@
 package com.novocode.junit;
 
+import java.util.ArrayList;
 import java.util.Collections;
 import java.util.Set;
 import java.util.concurrent.ConcurrentHashMap;
@@ -23,17 +24,20 @@ final class EventDispatcher extends RunListener
   private final ConcurrentHashMap<String, Long> startTimes = new ConcurrentHashMap<String, Long>();
   private final EventHandler handler;
   private final RunSettings settings;
-  private OutputCapture capture;
   private final Fingerprint fingerprint;
-  private final Description taskDescription;
+  private final String taskInfo;
+  private final RunStatistics runStatistics;
+  private OutputCapture capture;
 
-  EventDispatcher(RichLogger logger, EventHandler handler, RunSettings settings, Fingerprint fingerprint, Description taskDescription)
+  EventDispatcher(RichLogger logger, EventHandler handler, RunSettings settings, Fingerprint fingerprint,
+                  Description taskDescription, RunStatistics runStatistics)
   {
     this.logger = logger;
     this.handler = handler;
     this.settings = settings;
     this.fingerprint = fingerprint;
-    this.taskDescription = taskDescription;
+    this.taskInfo = settings.buildInfoName(taskDescription);
+    this.runStatistics = runStatistics;
   }
 
   private abstract class Event extends AbstractEvent {
@@ -87,7 +91,7 @@ public void testFinished(Description desc)
     uncapture(false);
     postIfFirst(new InfoEvent(desc, Status.Success) {
       void logTo(RichLogger logger) {
-        logger.debug("Test "+ansiName+" finished" + durationSuffix());
+        debugOrInfo("Test "+ansiName+" finished" + durationSuffix(), RunSettings.Verbosity.TEST_FINISHED);
       }
     });
     logger.popCurrentTestClassName();
@@ -108,7 +112,7 @@ public void testStarted(Description description)
   {
     recordStartTime(description);
     logger.pushCurrentTestClassName(description.getClassName());
-    debugOrInfo("Test " + settings.buildInfoName(description) + " started");
+    debugOrInfo("Test " + settings.buildInfoName(description) + " started", RunSettings.Verbosity.STARTED);
     capture();
   }
 
@@ -128,17 +132,18 @@ private Long elapsedTime(Description description) {
   @Override
   public void testRunFinished(Result result)
   {
-    debugOrInfo(c("Test run finished: ", INFO)+
+    debugOrInfo(c("Test run ", INFO)+taskInfo+c(" finished: ", INFO)+
       c(result.getFailureCount()+" failed", result.getFailureCount() > 0 ? ERRCOUNT : INFO)+
       c(", ", INFO)+
       c(result.getIgnoreCount()+" ignored", result.getIgnoreCount() > 0 ? IGNCOUNT : INFO)+
-      c(", "+result.getRunCount()+" total, "+(result.getRunTime()/1000.0)+"s", INFO));
+      c(", "+result.getRunCount()+" total, "+(result.getRunTime()/1000.0)+"s", INFO), RunSettings.Verbosity.RUN_FINISHED);
+    runStatistics.addTime(result.getRunTime());
   }
 
   @Override
   public void testRunStarted(Description description)
   {
-    debugOrInfo(c("Test run started", INFO));
+    debugOrInfo(c("Test run ", INFO)+taskInfo+c(" started", INFO), RunSettings.Verbosity.STARTED);
   }
 
   void testExecutionFailed(String testName, Throwable err)
@@ -153,12 +158,16 @@ void logTo(RichLogger logger) {
   private void postIfFirst(AbstractEvent e)
   {
     e.logTo(logger);
-    if(reported.add(e.fullyQualifiedName())) handler.handle(e);
+    if(reported.add(e.fullyQualifiedName())) {
+      runStatistics.captureStats(e);
+      handler.handle(e);
+    }
   }
 
   void post(AbstractEvent e)
   {
     e.logTo(logger);
+    runStatistics.captureStats(e);
     handler.handle(e);
   }
 
@@ -182,9 +191,9 @@ void uncapture(boolean replay)
     }
   }
 
-  private void debugOrInfo(String msg)
+  private void debugOrInfo(String msg, RunSettings.Verbosity atVerbosity)
   {
-    if(settings.verbose) logger.info(msg);
+    if(atVerbosity.ordinal() <= settings.verbosity.ordinal()) logger.info(msg);
     else logger.debug(msg);
   }
 }

src/main/java/com/novocode/junit/JUnitRunner.java

@@ -13,16 +13,21 @@ final class JUnitRunner implements Runner {
   private final String[] remoteArgs;
   private final RunSettings settings;
 
+  private volatile boolean used = false;
+
   final ClassLoader testClassLoader;
   final RunListener runListener;
+  final RunStatistics runStatistics;
 
   JUnitRunner(String[] args, String[] remoteArgs, ClassLoader testClassLoader) {
     this.args = args;
     this.remoteArgs = remoteArgs;
     this.testClassLoader = testClassLoader;
 
-    boolean quiet = false, verbose = true, nocolor = false, decodeScalaNames = false,
+    boolean quiet = false, nocolor = false, decodeScalaNames = false,
         logAssert = true, logExceptionClass = true;
+    RunSettings.Verbosity verbosity = RunSettings.Verbosity.TERSE;
+    RunSettings.Summary summary = RunSettings.Summary.SBT;
     HashMap<String, String> sysprops = new HashMap<String, String>();
     ArrayList<String> globPatterns = new ArrayList<String>();
     Set<String> includeCategories = new HashSet<String>();
@@ -33,7 +38,10 @@ final class JUnitRunner implements Runner {
     String runListener = null;
     for(String s : args) {
       if("-q".equals(s)) quiet = true;
-      else if("-v".equals(s)) verbose = true;
+      else if("-v".equals(s)) verbosity = RunSettings.Verbosity.STARTED;
+      else if("+v".equals(s)) verbosity = RunSettings.Verbosity.TERSE;
+      else if(s.startsWith("--verbosity=")) verbosity = RunSettings.Verbosity.values()[Integer.parseInt(s.substring(12))];
+      else if(s.startsWith("--summary=")) summary = RunSettings.Summary.values()[Integer.parseInt(s.substring(10))];
       else if("-n".equals(s)) nocolor = true;
       else if("-s".equals(s)) decodeScalaNames = true;
       else if("-a".equals(s)) logAssert = true;
@@ -51,21 +59,22 @@ else if(s.startsWith("-D") && s.contains("=")) {
     }
     for(String s : args) {
       if("+q".equals(s)) quiet = false;
-      else if("+v".equals(s)) verbose = false;
       else if("+n".equals(s)) nocolor = false;
       else if("+s".equals(s)) decodeScalaNames = false;
       else if("+a".equals(s)) logAssert = false;
       else if("+c".equals(s)) logExceptionClass = true;
     }
     this.settings =
-      new RunSettings(!nocolor, decodeScalaNames, quiet, verbose, logAssert, ignoreRunners, logExceptionClass,
+      new RunSettings(!nocolor, decodeScalaNames, quiet, verbosity, summary, logAssert, ignoreRunners, logExceptionClass,
         sysprops, globPatterns, includeCategories, excludeCategories,
         testFilter);
     this.runListener = createRunListener(runListener);
+    this.runStatistics = new RunStatistics(settings);
   }
 
   @Override
   public Task[] tasks(TaskDef[] taskDefs) {
+    used = true;
     int length = taskDefs.length;
     Task[] tasks = new Task[length];
     for (int i = 0; i < length; i++) {
@@ -87,7 +96,12 @@ private RunListener createRunListener(String runListenerClassName) {
 
   @Override
   public String done() {
-    return "";
+    // Can't simply return the summary due to https://github.com/sbt/sbt/issues/3510
+    if(!used) return "";
+    String stats = runStatistics.createSummary();
+    if(stats.isEmpty()) return stats;
+    System.out.println(stats);
+    return " ";
   }
 
   @Override

src/main/java/com/novocode/junit/JUnitTask.java

@@ -38,7 +38,7 @@ public Task[] execute(EventHandler eventHandler, Logger[] loggers) {
     String testClassName = taskDef.fullyQualifiedName();
     Description taskDescription = Description.createSuiteDescription(testClassName);
     RichLogger logger = new RichLogger(loggers, settings, testClassName);
-    EventDispatcher ed = new EventDispatcher(logger, eventHandler, settings, fingerprint, taskDescription);
+    EventDispatcher ed = new EventDispatcher(logger, eventHandler, settings, fingerprint, taskDescription, runner.runStatistics);
     JUnitCore ju = new JUnitCore();
     ju.addListener(ed);
     if (runner.runListener != null) ju.addListener(runner.runListener);

src/main/java/com/novocode/junit/RunSettings.java

@@ -16,7 +16,9 @@
 class RunSettings {
   private static final Object NULL = new Object();
 
-  final boolean color, quiet, verbose, logAssert, logExceptionClass;
+  final boolean color, quiet, logAssert, logExceptionClass;
+  final Verbosity verbosity;
+  final Summary summary;
   final ArrayList<String> globPatterns;
   final Set<String> includeCategories, excludeCategories;
   final String testFilter;
@@ -26,7 +28,7 @@ class RunSettings {
   private final HashSet<String> ignoreRunners = new HashSet<String>();
 
   RunSettings(boolean color, boolean decodeScalaNames, boolean quiet,
-              boolean verbose, boolean logAssert, String ignoreRunners,
+              Verbosity verbosity, Summary summary, boolean logAssert, String ignoreRunners,
               boolean logExceptionClass,
               HashMap<String, String> sysprops,
               ArrayList<String> globPatterns,
@@ -35,7 +37,8 @@ class RunSettings {
     this.color = color;
     this.decodeScalaNames = decodeScalaNames;
     this.quiet = quiet;
-    this.verbose = verbose;
+    this.verbosity = verbosity;
+    this.summary = summary;
     this.logAssert = logAssert;
     this.logExceptionClass = logExceptionClass;
     for(String s : ignoreRunners.split(","))
@@ -160,4 +163,12 @@ void restoreSystemProperties(Map<String, Object> oldprops) {
       }
     }
   }
+
+  static enum Verbosity {
+    TERSE, RUN_FINISHED, STARTED, TEST_FINISHED
+  }
+
+  static enum Summary {
+    SBT, ONE_LINE, LIST_FAILED
+  }
 }

src/main/java/com/novocode/junit/RunStatistics.java

@@ -0,0 +1,62 @@
+package com.novocode.junit;
+
+import sbt.testing.Status;
+
+import java.util.ArrayList;
+import java.util.List;
+
+class RunStatistics {
+  private final RunSettings settings;
+
+  private int failedCount, ignoredCount, otherCount;
+  private final ArrayList<String> failedNames = new ArrayList<>();
+  private final ArrayList<String> otherNames = new ArrayList<>();
+  private volatile long accumulatedTime;
+
+  RunStatistics(RunSettings settings) {
+    this.settings = settings;
+  }
+
+  void addTime(long t) { accumulatedTime += t; }
+
+  synchronized void captureStats(AbstractEvent e) {
+    Status s = e.status();
+    if(s == Status.Error || s == Status.Failure) {
+      failedCount++;
+      failedNames.add(e.fullyQualifiedName());
+    }
+    else {
+      if(s == Status.Ignored) ignoredCount++;
+      else otherCount++;
+      otherNames.add(e.fullyQualifiedName());
+    }
+  }
+
+  private String summaryLine() {
+    return (failedCount == 0 ? "All tests passed: " : "Some tests failed: ") +
+      failedCount+" failed, "+ignoredCount+" ignored, "+(failedCount+ignoredCount+otherCount)+" total, "+
+      (accumulatedTime/1000.0)+"s";
+  }
+
+  private static String mkString(List<String> l) {
+    StringBuilder b = new StringBuilder();
+    for(String s : l) {
+      if(b.length() != 0) b.append(", ");
+      b.append(s);
+    }
+    return b.toString();
+  }
+
+  synchronized String createSummary() {
+    switch(settings.summary) {
+      case LIST_FAILED:
+        return failedNames.isEmpty() ?
+          summaryLine() :
+          (summaryLine() + "\n- Failed tests: " + mkString(failedNames));
+      case ONE_LINE:
+        return summaryLine();
+      default:
+        return "";
+    }
+  }
+}

src/sbt-test/simple/categories/test

@@ -22,7 +22,7 @@
 
 # Turn on fast and slow category
 > set testOptions := Seq(Tests.Argument(TestFrameworks.JUnit, Constants.IncludeFastAndSlow))
-> test
+> testOnly -- --summary=2
 > testsExecuted one-fast one-slow two-a two-b
 > testsNotExecuted one-none
 

src/sbt-test/simple/tests-run-once/build.sbt

@@ -5,3 +5,5 @@ scalaVersion := "2.10.2"
 libraryDependencies += "com.novocode" % "junit-interface" % sys.props("project.version") % "test"
 
 fork in Test := true
+
+testOptions += Tests.Argument(TestFrameworks.JUnit, "--verbosity=1")