Overlapping results text when tests are run in parallel in multiple JVMs

[Emre Çelikten]

Hello,

I am interested in running some tests in parallel, like Selenium and integration tests which take a long time to complete. I would like to do this in forked JVMs - simply running the tests in parallel will not work in my case because of global-state changing stuff like dependency injection.

I think I managed to configure my Build.scala to do this. I divided my tests into some different groups according to their categories and I run these categories in parallel. But since all these JVMs write to the console at the same time, I get overlapping test result text, which is hard to read.

Here's an excerpt of what I see:

[info] DummySpec
[info] AnotherDBSpec
[info] DBSpec
[info]
[info]
[info]
[info] DBSpec should
[info] AnotherDBSpec should
[info] DummySpec should
[info] + do stuff
[info] + do stuff
[info] + do stuff
[info] Execution time: 10 seconds, 134 ms
[info]
[info]
[info]
[info]
[info] Total for specification DBSpec
[info]
[info] Total for specification DummySpec
[info]
[info] Total for specification AnotherDBSpec
[info] Finished in 10 seconds, 264 ms
[info] 1 example, 0 failure, 0 error
[info]
[info] Finished in 10 seconds, 264 ms
[info] 1 example, 0 failure, 0 error
[info]
[info] Finished in 10 seconds, 356 ms
[info] 1 example, 0 failure, 0 error
[info]

Is there a way for me to specify custom loggers for each forked JVM? I tried Keys.outputStrategy in Test := Some(LoggedOutput(logger)) and passing it my own logger implementation, but apparently it gets ignored. I am thinking of writing to different OutputStreams then merging them or creating a logging structure that allows only one thing to be written at a time.

This is what my Build.scala looks like, currently:

object ApplicationBuild extends Build {
  val appName = "SBTTest"
  val appVersion = "1.0-SNAPSHOT"

  def groupByCategory(tests: Seq[TestDefinition]) = tests groupBy {
    case t if t.name contains ".unit." => "unit"
    case t if t.name contains ".functional." => "func" + (t.name.hashCode % 4)
    case t if t.name contains ".integration." => "int" + (t.name.hashCode % 4)
  } map {
    case (category, tests) => new Group(category, tests, SubProcess(Seq.empty[String]))
  } toSeq

  val appDependencies = Seq(
    jdbc,
    anorm
  )

  val main = play.Project(appName, appVersion, appDependencies).settings(
  ).settings(
    parallelExecution in Test := true,
    Keys.fork in Test := true,
    concurrentRestrictions in Global := Seq(Tags.limit(Tags.ForkedTestGroup, 8)),
    testGrouping <<= definedTests in Test map {
      test =>
        groupByCategory(test)
    },
    logBuffered in Test := true
  )
}

I am using Play Framework 2.1.2 with sbt 0.12.4 and specs2 by the way.

Thanks in advance,

Emre

[Emre Çelikten]

Defining outputStrategy in project settings apparently does not work for manually created subprocesses. I managed to provide it directly into subprocesses in my grouping function after upgrading to 0.13.0, like

  def groupByCategory(tests: Seq[TestDefinition]) = tests groupBy {
    case t if t.name contains ".unit." => "unit"
    case t if t.name contains ".functional." => "func" + (t.name.hashCode % 4)
    case t if t.name contains ".integration." => "int" + (t.name.hashCode % 4)
  } map {
    case (category, tests) =>

      val forkOptions = ForkOptions(outputStrategy = Some(BufferedOutput(myLogger)))
      val process = new SubProcess(forkOptions)
      new Group(category, tests, process)
  } toSeq

myLogger is just a basic AbstractLogger that prints "FOO: " in front of everything it receives and prints the result to the console.

I get

FOO: AnotherDB thread: 1
FOO: anotherdbspec 1378733688381
FOO: DB thread: 1
FOO: dbspec 1378733688400
FOO: integrationspec 1378733691209
FOO: anotherdbspec1378733691382
FOO: dbspec1378733691402
[info] AnotherDBSpec
[info] AnotherDBSpec should
[info] DBSpec
[info] DBSpec should
[info] + do stuff

[info] Total for specification AnotherDBSpec

[info] + do stuff
[info] Finished in 3 seconds, 40 ms

[info] 1 example, 0 failure, 0 error

[info] Total for specification DBSpec

[info] Finished in 3 seconds, 35 ms

[info] 1 example, 0 failure, 0

error
FOO: integrationspec 1378733694211
[info] IntegrationSpec
[info] Application should
[info] + work from within a browser
[info] Total for specification IntegrationSpec
[info] Finished in 5 seconds, 863 ms

[info] 1 example, 0 failure, 0 error

[info] Passed: Total 3, Failed 0, Errors 0, Passed 3
[success] Total time: 9 s, completed Sep 9, 2013 4:34:54 PM

The numbers are thread numbers and start times in milliseconds, which are written to the console in the tests using println. Yet, myLogger does not intercept test results, which makes me think that they aren't written to the console in the forked processes.

Defining an extraLogger does intercept the test results, but in the same interleaved order as above. I looked for a way to separate the logging buffer by specification class, but it doesn't look like I have access to that.

Any suggestions for solving this problem? I think this might help a lot of people out there.

Thanks in advance,

Emre