From 20183572cb15cc302199b48824bd1812a5d4941e Mon Sep 17 00:00:00 2001 From: Stefan Zeiger Date: Fri, 28 Jun 2019 22:24:32 +0200 Subject: [PATCH] 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. --- README.md | 6 +- .../com/novocode/junit/EventDispatcher.java | 33 ++++++---- .../java/com/novocode/junit/JUnitRunner.java | 24 +++++-- .../java/com/novocode/junit/JUnitTask.java | 2 +- .../java/com/novocode/junit/RunSettings.java | 17 ++++- .../com/novocode/junit/RunStatistics.java | 62 +++++++++++++++++++ src/sbt-test/simple/categories/test | 2 +- src/sbt-test/simple/tests-run-once/build.sbt | 2 + 8 files changed, 124 insertions(+), 24 deletions(-) create mode 100644 src/main/java/com/novocode/junit/RunStatistics.java diff --git a/README.md b/README.md index 33946c7..81f63c5 100644 --- a/README.md +++ b/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=` | 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=` | 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=` | 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=` | 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=` | 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. diff --git a/src/main/java/com/novocode/junit/EventDispatcher.java b/src/main/java/com/novocode/junit/EventDispatcher.java index 178fe4b..039d299 100644 --- a/src/main/java/com/novocode/junit/EventDispatcher.java +++ b/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 startTimes = new ConcurrentHashMap(); 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); } } diff --git a/src/main/java/com/novocode/junit/JUnitRunner.java b/src/main/java/com/novocode/junit/JUnitRunner.java index 458cb20..aaa63c5 100644 --- a/src/main/java/com/novocode/junit/JUnitRunner.java +++ b/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 sysprops = new HashMap(); ArrayList globPatterns = new ArrayList(); Set includeCategories = new HashSet(); @@ -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 diff --git a/src/main/java/com/novocode/junit/JUnitTask.java b/src/main/java/com/novocode/junit/JUnitTask.java index ad45372..c9b02c8 100644 --- a/src/main/java/com/novocode/junit/JUnitTask.java +++ b/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); diff --git a/src/main/java/com/novocode/junit/RunSettings.java b/src/main/java/com/novocode/junit/RunSettings.java index 38195d0..a412d31 100644 --- a/src/main/java/com/novocode/junit/RunSettings.java +++ b/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 globPatterns; final Set includeCategories, excludeCategories; final String testFilter; @@ -26,7 +28,7 @@ class RunSettings { private final HashSet ignoreRunners = new HashSet(); RunSettings(boolean color, boolean decodeScalaNames, boolean quiet, - boolean verbose, boolean logAssert, String ignoreRunners, + Verbosity verbosity, Summary summary, boolean logAssert, String ignoreRunners, boolean logExceptionClass, HashMap sysprops, ArrayList 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 oldprops) { } } } + + static enum Verbosity { + TERSE, RUN_FINISHED, STARTED, TEST_FINISHED + } + + static enum Summary { + SBT, ONE_LINE, LIST_FAILED + } } diff --git a/src/main/java/com/novocode/junit/RunStatistics.java b/src/main/java/com/novocode/junit/RunStatistics.java new file mode 100644 index 0000000..052c825 --- /dev/null +++ b/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 failedNames = new ArrayList<>(); + private final ArrayList 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 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 ""; + } + } +} diff --git a/src/sbt-test/simple/categories/test b/src/sbt-test/simple/categories/test index 116dbb0..d9bda78 100644 --- a/src/sbt-test/simple/categories/test +++ b/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 diff --git a/src/sbt-test/simple/tests-run-once/build.sbt b/src/sbt-test/simple/tests-run-once/build.sbt index 812c7c2..3c478ee 100644 --- a/src/sbt-test/simple/tests-run-once/build.sbt +++ b/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")