How to display entire stack trace for thrown exceptions from ScalaCheck tests?

Question

I'm running ScalaCheck tests in sbt, and if my test fails because the code under test throws an exception, the test report shows the failed test, the thrown exception and the message, but not the entire stack trace (note the mere Exception: java.lang.NullPointerException: exception exception message below).

[info] Loading global plugins from /Users/jacek/.sbt/0.13/plugins
[info] Set current project to scalacheck (in build file:/Users/jacek/sandbox/scalacheck/)
[info] Updating {file:/Users/jacek/sandbox/scalacheck/}scalacheck...
[info] Resolving jline#jline;2.11 ...
[info] Done updating.
[info] Compiling 1 Scala source to /Users/jacek/sandbox/scalacheck/target/scala-2.11/test-classes...
[info] ! String.throw exception: Exception raised on property evaluation.
[info] > ARG_0: ""
[info] > Exception: java.lang.NullPointerException: exception
[error] Error: Total 1, Failed 0, Errors 1, Passed 0
[error] Error during tests:
[error]     StringSpecification
[error] (test:test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 5 s, completed Jun 25, 2014 3:25:47 AM

I found https://groups.google.com/forum/#!msg/scalacheck/AGBgE_JlqpI/B2eSG84_QzYJ from 2008 which seems to report the same issue, and indicates it should be fixed in the next release. I'm currently using the latest release 1.11.4.

I also found http://www.scala-sbt.org/release/docs/Testing.html which indicates sbt has a testOptions key which I suppose seems reasonable to use, and I know ScalaTest has a setting for full stack traces, "-F", but that doesn't work for ScalaCheck. Even the example from the above page, testOptions in Test += Tests.Argument(TestFrameworks.ScalaCheck, "-d", "-g") gives me an error:

[error] Could not run test org.example.myproject.MyTestClass: java.lang.Exception: [1.1] failure: option name expected
[error] 
[error] -d -g
[error] ^

How do I use these test arguments, is there a list of these arguments anywhere, and finally, is it possible to get a stacktrace out of it all, or am I chasing a red herring?

Answer 1

tl;dr There's no support for verbosity under sbt with the released version of ScalaCheck. You'd have to build a version from the sources yourself to have the feature.

The available options for ScalaCheck are described in Test Execution:

Available options:
  -workers, -w: Number of threads to execute in parallel for testing
  -minSize, -n: Minimum data generation size
  -verbosity, -v: Verbosity level
  -minSuccessfulTests, -s: Number of tests that must succeed in order to pass a property
  -maxDiscardRatio, -r: The maximum ratio between discarded and succeeded tests allowed before ScalaCheck stops testing a property. At least minSuccessfulTests will always be tested, though.
  -maxSize, -x: Maximum data generation size

The source code of org.scalacheck.util.Pretty tells us more about the different levels of vebosity:

implicit def prettyThrowable(e: Throwable) = Pretty { prms =>
  val strs = e.getStackTrace.map { st =>
    import st._
    getClassName+"."+getMethodName + "("+getFileName+":"+getLineNumber+")"
  }

  val strs2 =
    if(prms.verbosity <= 0) Array[String]()
    else if(prms.verbosity <= 1) strs.take(5)
    else strs

  e.getClass.getName + ": " + e.getMessage / strs2.mkString("\n")
}

So, 0 gives nothing, 1 takes 5 lines out of a stack trace, whereas a number greater than 1 gives you the entire stack trace as follows:

➜  scalacheck  scala -cp .:/Users/jacek/.ivy2/cache/org.scalacheck/scalacheck_2.11/jars/scalacheck_2.11-1.11.4.jar StringSpecification -verbosity 3
+ String.startsWith: OK, passed 100 tests.
Elapsed time: 0.242 sec
! String.concatenate: Falsified after 0 passed tests.
> ARG_0: ""
> ARG_1: ""
Elapsed time: 0.003 sec
+ String.substring: OK, passed 100 tests.
Elapsed time: 0.126 sec
! String.throw exception: Exception raised on property evaluation.
> ARG_0: ""
> Exception: java.lang.NullPointerException: exception
StringSpecification$$anonfun$14.apply(StringSpecification.scala:19)
StringSpecification$$anonfun$14.apply(StringSpecification.scala:18)
scala.Function1$$anonfun$andThen$1.apply(Function1.scala:55)
org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$3.apply(Prop.scala:622
  )
org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$3.apply(Prop.scala:622
  )
org.scalacheck.Prop$.secure(Prop.scala:473)
org.scalacheck.Prop$$anonfun$forAllShrink$1.org$scalacheck$Prop$$anonfun$$r
  esult$1(Prop.scala:622)
org.scalacheck.Prop$$anonfun$forAllShrink$1.apply(Prop.scala:659)
org.scalacheck.Prop$$anonfun$forAllShrink$1.apply(Prop.scala:616)
org.scalacheck.Prop$$anon$1.apply(Prop.scala:309)
org.scalacheck.Test$.org$scalacheck$Test$$workerFun$1(Test.scala:335)
org.scalacheck.Test$$anonfun$org$scalacheck$Test$$worker$1$1.apply(Test.sca
  la:316)
org.scalacheck.Test$$anonfun$org$scalacheck$Test$$worker$1$1.apply(Test.sca
  la:316)
org.scalacheck.Test$.check(Test.scala:385)
org.scalacheck.Test$$anonfun$checkProperties$1.apply(Test.scala:402)
org.scalacheck.Test$$anonfun$checkProperties$1.apply(Test.scala:395)
scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala
  :245)
scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala
  :245)
scala.collection.immutable.List.foreach(List.scala:383)
scala.collection.generic.TraversableForwarder$class.foreach(TraversableForw
  arder.scala:35)
scala.collection.mutable.ListBuffer.foreach(ListBuffer.scala:45)
scala.collection.TraversableLike$class.map(TraversableLike.scala:245)
scala.collection.AbstractTraversable.map(Traversable.scala:104)
org.scalacheck.Test$.checkProperties(Test.scala:395)
org.scalacheck.Properties.mainRunner(Properties.scala:62)
org.scalacheck.Prop$class.main(Prop.scala:106)
org.scalacheck.Properties.main(Properties.scala:27)
StringSpecification.main(StringSpecification.scala:-1)
sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:
  -2)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:5
  7)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImp
  l.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
scala.reflect.internal.util.ScalaClassLoader$$anonfun$run$1.apply(ScalaClas
  sLoader.scala:68)
scala.reflect.internal.util.ScalaClassLoader$class.asContext(ScalaClassLoad
  er.scala:31)
scala.reflect.internal.util.ScalaClassLoader$URLClassLoader.asContext(Scala
  ClassLoader.scala:99)
scala.reflect.internal.util.ScalaClassLoader$class.run(ScalaClassLoader.sca
  la:68)
scala.reflect.internal.util.ScalaClassLoader$URLClassLoader.run(ScalaClassL
  oader.scala:99)
scala.tools.nsc.CommonRunner$class.run(ObjectRunner.scala:22)
scala.tools.nsc.ObjectRunner$.run(ObjectRunner.scala:39)
scala.tools.nsc.CommonRunner$class.runAndCatch(ObjectRunner.scala:29)
scala.tools.nsc.ObjectRunner$.runAndCatch(ObjectRunner.scala:39)
scala.tools.nsc.MainGenericRunner.runTarget$1(MainGenericRunner.scala:72)
scala.tools.nsc.MainGenericRunner.process(MainGenericRunner.scala:94)
scala.tools.nsc.MainGenericRunner$.main(MainGenericRunner.scala:103)
scala.tools.nsc.MainGenericRunner.main(MainGenericRunner.scala:-1)
Elapsed time: 0.000 sec

You're right that the documentation for sbt is incorect. There are no "-d", "-g" options and I believe they're simply a copy-and-paste error in the documentation. It was already fixed in a pull request that's soon to be accepted.

The verbosity option is not supported under sbt in the recent version of ScalaCheck 1.11.4. The following is the entire build definition of a sample project.

build.sbt

scalaVersion := "2.11.1"

libraryDependencies += "org.scalacheck" %% "scalacheck" % "1.11.4" % "test"

testOptions in Test += Tests.Argument(TestFrameworks.ScalaCheck, "-verbosity", "3")

Even when the verbosity parameter is properly specified in build.sbt, test execution won't print more than a single line.

➜  scalacheck  xsbt test
[info] Loading global plugins from /Users/jacek/.sbt/0.13/plugins
[info] Set current project to scalacheck (in build file:/Users/jacek/sandbox/scalacheck/)
[info] + String.startsWith: OK, passed 100 tests.
[info] ! String.concatenate: Falsified after 0 passed tests.
[info] > ARG_0: ""
[info] > ARG_1: ""
[info] + String.substring: OK, passed 100 tests.
[info] ! String.throw exception: Exception raised on property evaluation.
[info] > ARG_0: ""
[info] > Exception: java.lang.NullPointerException: exception
[error] Error: Total 4, Failed 1, Errors 1, Passed 2
[error] Error during tests:
[error]     StringSpecification
[error] (test:test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 1 s, completed Jun 25, 2014 2:57:08 AM

The reason is that org.scalacheck.ScalaCheckFramework has the following implementation and assumes verbosity always be 0:

override def onTestResult(n: String, r: Test.Result) = {
  for (l <- loggers) {
    import Pretty._
    l.info(
      (if (r.passed) "+ " else "! ") + n + ": " + pretty(r, Params(0))
    )
  }
  handler.handle(asEvent((n,r)))
}

A pull request to fix it has already been accepted to the repo under Support verbosity under sbt for TestFrameworks.ScalaCheck. You'd have to build ScalaCheck yourself with sbt publishLocal in the directory where you cloned the repo. Don't forget to use 1.12.0-SNAPSHOT version in build.sbt to pick up the changes.

Answer 2

Since the issue that Jacek Laskowski noted has been resolved, you can now get stack traces from ScalaCheck in sbt by adding a line to your build.sbt file to set ScalaCheck's verbosity level.

testOptions in Test += Tests.Argument(TestFrameworks.ScalaCheck, "-verbosity", "2")

As Jacek Laskowski noted, a verbosity of 0 will give you just the exception.

[info] ! RandomAccessFile.readWriteInt: Exception raised on property evaluation.
[info] > ARG_0: 0
[info] > ARG_0_ORIGINAL: -2073744736
[info] > Exception: java.lang.UnsupportedOperationException: null

A verbosity of 1 will give you the first five lines of the stack trace.

[info] ! RandomAccessFile.readWriteInt: Exception raised on property evaluation.
[info] > ARG_0: 0
[info] > ARG_0_ORIGINAL: 2147483647
[info] > Exception: java.lang.UnsupportedOperationException: null
[info] java.nio.IntBuffer.array(IntBuffer.java:994)
[info] csc365a01.RandomAccessFile.readInt(RandomAccessFile.scala:22)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply$mcZI$sp(RandomAccessFileSpec.scala:14)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply(RandomAccessFileSpec.scala:11)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply(RandomAccessFileSpec.scala:11)

A verbosity greater than one will give you the full stack trace.

[info] ! RandomAccessFile.readWriteInt: Exception raised on property evaluation.
[info] > ARG_0: 0
[info] > ARG_0_ORIGINAL: 1693735989
[info] > Exception: java.lang.UnsupportedOperationException: null
[info] java.nio.IntBuffer.array(IntBuffer.java:994)
[info] csc365a01.RandomAccessFile.readInt(RandomAccessFile.scala:22)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply$mcZI$sp(RandomAccessFileSpec.scala:14)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply(RandomAccessFileSpec.scala:11)
[info] RandomAccessFileProps$$anonfun$1$$anonfun$apply$1.apply(RandomAccessFileSpec.scala:11)
[info] scala.Function1$$anonfun$andThen$1.apply(Function1.scala:52)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$3.apply(Prop.scala:712)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$3.apply(Prop.scala:712)
[info] org.scalacheck.Prop$.secure(Prop.scala:456)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1.org$scalacheck$Prop$$anonfun$$result$1(Prop.scala:712)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$4.apply(Prop.scala:719)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1$$anonfun$4.apply(Prop.scala:719)
[info] scala.collection.immutable.Stream.map(Stream.scala:418)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1.getFirstFailure$1(Prop.scala:719)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1.shrinker$1(Prop.scala:729)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1.apply(Prop.scala:751)
[info] org.scalacheck.Prop$$anonfun$forAllShrink$1.apply(Prop.scala:706)
[info] org.scalacheck.Prop$$anonfun$apply$5.apply(Prop.scala:292)
[info] org.scalacheck.Prop$$anonfun$apply$5.apply(Prop.scala:291)
[info] org.scalacheck.PropFromFun.apply(Prop.scala:22)
[info] org.scalacheck.Prop$$anonfun$delay$1.apply(Prop.scala:461)
[info] org.scalacheck.Prop$$anonfun$delay$1.apply(Prop.scala:461)
[info] org.scalacheck.Prop$$anonfun$apply$5.apply(Prop.scala:292)
[info] org.scalacheck.Prop$$anonfun$apply$5.apply(Prop.scala:291)
[info] org.scalacheck.PropFromFun.apply(Prop.scala:22)
[info] org.scalacheck.Test$.org$scalacheck$Test$$workerFun$1(Test.scala:294)
[info] org.scalacheck.Test$$anonfun$3.apply(Test.scala:323)
[info] org.scalacheck.Test$$anonfun$3.apply(Test.scala:323)
[info] org.scalacheck.Platform$.runWorkers(Platform.scala:40)
[info] org.scalacheck.Test$.check(Test.scala:323)
[info] org.scalacheck.ScalaCheckRunner$$anon$2$$anonfun$execute$3$$anonfun$apply$2.apply(ScalaCheckFramework.scala:102)
[info] org.scalacheck.ScalaCheckRunner$$anon$2$$anonfun$execute$3$$anonfun$apply$2.apply(ScalaCheckFramework.scala:100)
[info] scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:733)
[info] scala.collection.immutable.List.foreach(List.scala:381)
[info] scala.collection.generic.TraversableForwarder$class.foreach(TraversableForwarder.scala:35)
[info] scala.collection.mutable.ListBuffer.foreach(ListBuffer.scala:45)
[info] scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:732)
[info] org.scalacheck.ScalaCheckRunner$$anon$2$$anonfun$execute$3.apply(ScalaCheckFramework.scala:100)
[info] org.scalacheck.ScalaCheckRunner$$anon$2$$anonfun$execute$3.apply(ScalaCheckFramework.scala:97)
[info] scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
[info] scala.collection.TraversableLike$$anonfun$flatMap$1.apply(TraversableLike.scala:241)
[info] scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
[info] scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
[info] scala.collection.TraversableLike$class.flatMap(TraversableLike.scala:241)
[info] scala.collection.mutable.ArrayOps$ofRef.flatMap(ArrayOps.scala:186)
[info] org.scalacheck.ScalaCheckRunner$$anon$2.execute(ScalaCheckFramework.scala:97)
[info] sbt.TestRunner.runTest$1(TestFramework.scala:76)
[info] sbt.TestRunner.run(TestFramework.scala:85)
[info] sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
[info] sbt.TestFramework$$anon$2$$anonfun$$init$$1$$anonfun$apply$8.apply(TestFramework.scala:202)
[info] sbt.TestFramework$.sbt$TestFramework$$withContextLoader(TestFramework.scala:185)
[info] sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
[info] sbt.TestFramework$$anon$2$$anonfun$$init$$1.apply(TestFramework.scala:202)
[info] sbt.TestFunction.apply(TestFramework.scala:207)
[info] sbt.Tests$$anonfun$9.apply(Tests.scala:216)
[info] sbt.Tests$$anonfun$9.apply(Tests.scala:216)
[info] sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
[info] sbt.std.Transform$$anon$3$$anonfun$apply$2.apply(System.scala:44)
[info] sbt.std.Transform$$anon$4.work(System.scala:63)
[info] sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:226)
[info] sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:226)
[info] sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:17)
[info] sbt.Execute.work(Execute.scala:235)
[info] sbt.Execute$$anonfun$submit$1.apply(Execute.scala:226)
[info] sbt.Execute$$anonfun$submit$1.apply(Execute.scala:226)
[info] sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:159)
[info] sbt.CompletionService$$anon$2.call(CompletionService.scala:28)
[info] java.util.concurrent.FutureTask.run(FutureTask.java:266)
[info] java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[info] java.util.concurrent.FutureTask.run(FutureTask.java:266)
[info] java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[info] java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[info] java.lang.Thread.run(Thread.java:745)
[info] Elapsed time: 0.047 sec