H2 Table not found during test; Exception not caught

[fijimf]

Hi --

Not sure whether this is a Slick, Play or ScalaTest question.  Basically I have two questions.  

The first issue is that when I run sbt test, sporadically I see errors of the form:

org.h2.jdbc.JdbcSQLException: Table "CONFERENCE_MAP" not found; SQL statement:
select "ID", "SEASON_ID", "CONFERENCE_ID", "TEAM_ID" from "CONFERENCE_MAP" where ("SEASON_ID" = 1) and ("TEAM_ID" = 1) [42102-187]

Initially I thought that that meant that the H2 testing database had closed before the test was complete, but now I believe it is also possible that the evolutions creation or drop statements are getting mixed in with SQL from my application code

The second issue is that ScalaTest seems to happily ignore these exceptions and report everything as A-OK.

I feel I must be doing something wrong.

Play 2.5, Scala 3.0 

So relevant code:

application.conf

slick.dbs.default.driver="slick.driver.H2Driver$"

slick.dbs.default.db.driver=org.h2.Driver

slick.dbs.default.db.url="jdbc:h2:mem:play;DB_CLOSE_DELAY=-1"

build.sbt

name := """fijbook-alpha"""

version := "1.0-SNAPSHOT"

lazy val root = (project in file(".")).enablePlugins(PlayScala)

scalaVersion := "2.11.7"

routesGenerator := InjectedRoutesGenerator

resolvers += "scalaz-bintray" at "https://dl.bintray.com/scalaz/releases"

libraryDependencies ++= Seq(

    "com.typesafe.play" %% "play-slick" % "2.0.0",

    "com.typesafe.play" %% "play-slick-evolutions" % "2.0.0",

    "com.h2database" % "h2" % "1.4.187",

    "org.scalatestplus.play" %% "scalatestplus-play" % "1.5.0" % "test",

    specs2 % Test

)

resolvers += "Sonatype snapshots" at "http://oss.sonatype.org/content/repositories/snapshots/"

fork in test := false

RepoSpec.scala
class RepoSpec extends PlaySpec with OneAppPerTest with BeforeAndAfterEach {

  val repo = Injector.inject[Repo]

  override def afterEach() = EvolutionHelper.clean()

  "ConferenceMaps " should {
    "be empty initially" in new WithApplication(FakeApplication()) {
      assert(Await.result(repo.all(repo.conferenceMaps), Duration.Inf).isEmpty)
    }
    "allow you to map a team to a conference for a season" in new WithApplication(FakeApplication()) {
      for (
        seasonId <- repo.createSeason(2016);
        confId <- repo.createConference("big-east", "Big East");
        teamId <- repo.createTeam("georgetown", "Georgetown", "Georgetown University", "Hoyas")) {
        assert(Await.result(repo.mapTeam(seasonId, teamId, confId), Duration.Inf) > 0L)
      }
    }
    "ensure that a teams conference mappping is unique for a season" in new WithApplication(FakeApplication()) {
      for (
        seasonId <- repo.createSeason(2016);
        confId1 <- repo.createConference("big-east", "Big East");
        confId2 <- repo.createConference("a10", "Atlantic 10");
        teamId <- repo.createTeam("georgetown", "Georgetown", "Georgetown University", "Hoyas")) {

        val cmId1 = Await.result(repo.mapTeam(seasonId, teamId, confId1), Duration.Inf)
        assert(cmId1 > 0L)

        val cmId2 = Await.result(repo.mapTeam(seasonId, teamId, confId2), Duration.Inf)
        assert(cmId2 > 0L)
        assert(cmId1 == cmId2)
      }
    }
  }

} 

output

[info] ConferenceMaps

[DEBUG] [09/09/2016 20:34:27.588] [application-akka.actor.default-dispatcher-2] [EventStream] shutting down: StandardOutLogger started

[DEBUG] [09/09/2016 20:34:27.613] [application-akka.actor.default-dispatcher-4] [EventStream] shutting down: StandardOutLogger started

[info] - should be empty initially

[DEBUG] [09/09/2016 20:34:27.834] [application-akka.actor.default-dispatcher-3] [EventStream] shutting down: StandardOutLogger started

[DEBUG] [09/09/2016 20:34:27.848] [application-akka.actor.default-dispatcher-2] [EventStream] shutting down: StandardOutLogger started

[info] - should allow you to map a team to a conference for a season

org.h2.jdbc.JdbcSQLException: Table "CONFERENCE_MAP" not found; SQL statement:

select "ID", "SEASON_ID", "CONFERENCE_ID", "TEAM_ID" from "CONFERENCE_MAP" where ("SEASON_ID" = 1) and ("TEAM_ID" = 1) [42102-187]

        at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)

        at org.h2.message.DbException.get(DbException.java:179)

        at org.h2.message.DbException.get(DbException.java:155)

        at org.h2.command.Parser.readTableOrView(Parser.java:5261)

        at org.h2.command.Parser.readTableFilter(Parser.java:1235)

        at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:1874)

        at org.h2.command.Parser.parseSelectSimple(Parser.java:1983)

        at org.h2.command.Parser.parseSelectSub(Parser.java:1868)

        at org.h2.command.Parser.parseSelectUnion(Parser.java:1689)

        at org.h2.command.Parser.parseSelect(Parser.java:1677)

        at org.h2.command.Parser.parsePrepared(Parser.java:433)

        at org.h2.command.Parser.parse(Parser.java:305)

        at org.h2.command.Parser.parse(Parser.java:277)

        at org.h2.command.Parser.prepareCommand(Parser.java:242)

        at org.h2.engine.Session.prepareLocal(Session.java:461)

        at org.h2.engine.Session.prepareCommand(Session.java:403)

        at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1189)

        at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:72)

        at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:277)

        at com.zaxxer.hikari.proxy.ConnectionProxy.prepareStatement(ConnectionProxy.java:268)

        at com.zaxxer.hikari.proxy.ConnectionJavassistProxy.prepareStatement(ConnectionJavassistProxy.java)

        at slick.jdbc.JdbcBackend$SessionDef$class.prepareStatement(JdbcBackend.scala:297)

        at slick.jdbc.JdbcBackend$BaseSession.prepareStatement(JdbcBackend.scala:407)

        at slick.jdbc.StatementInvoker.results(StatementInvoker.scala:33)

        at slick.jdbc.StatementInvoker.iteratorTo(StatementInvoker.scala:22)

        at slick.jdbc.Invoker$class.foreach(Invoker.scala:48)

        at slick.jdbc.StatementInvoker.foreach(StatementInvoker.scala:16)

        at slick.jdbc.Invoker$class.firstOption(Invoker.scala:24)

        at slick.jdbc.StatementInvoker.firstOption(StatementInvoker.scala:16)

        at slick.jdbc.StreamingInvokerAction$HeadOptionAction.run(StreamingInvokerAction.scala:57)

        at slick.jdbc.StreamingInvokerAction$HeadOptionAction.run(StreamingInvokerAction.scala:56)

        at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.liftedTree1$1(DatabaseComponent.scala:237)

        at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.run(DatabaseComponent.scala:237)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

        at java.lang.Thread.run(Thread.java:745)

[DEBUG] [09/09/2016 20:34:28.233] [application-akka.actor.default-dispatcher-4] [EventStream] shutting down: StandardOutLogger started

[DEBUG] [09/09/2016 20:34:28.252] [application-akka.actor.default-dispatcher-2] [EventStream] shutting down: StandardOutLogger started

[info] - should ensure that a teams conference mappping is unique for a season

org.h2.jdbc.JdbcSQLException: Table "CONFERENCE_MAP" not found; SQL statement:

select "ID", "SEASON_ID", "CONFERENCE_ID", "TEAM_ID" from "CONFERENCE_MAP" where ("SEASON_ID" = 1) and ("TEAM_ID" = 1) [42102-187]

        at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)

        at org.h2.message.DbException.get(DbException.java:179)

        at org.h2.message.DbException.get(DbException.java:155)

        at org.h2.command.Parser.readTableOrView(Parser.java:5261)

        at org.h2.command.Parser.readTableFilter(Parser.java:1235)

        at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:1874)

        at org.h2.command.Parser.parseSelectSimple(Parser.java:1983)

        at org.h2.command.Parser.parseSelectSub(Parser.java:1868)

        at org.h2.command.Parser.parseSelectUnion(Parser.java:1689)

        at org.h2.command.Parser.parseSelect(Parser.java:1677)

        at org.h2.command.Parser.parsePrepared(Parser.java:433)

        at org.h2.command.Parser.parse(Parser.java:305)

        at org.h2.command.Parser.parse(Parser.java:277)

        at org.h2.command.Parser.prepareCommand(Parser.java:242)

        at org.h2.engine.Session.prepareLocal(Session.java:461)

        at org.h2.engine.Session.prepareCommand(Session.java:403)

        at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1189)

        at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:72)

        at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:277)

        at com.zaxxer.hikari.proxy.ConnectionProxy.prepareStatement(ConnectionProxy.java:268)

        at com.zaxxer.hikari.proxy.ConnectionJavassistProxy.prepareStatement(ConnectionJavassistProxy.java)

        at slick.jdbc.JdbcBackend$SessionDef$class.prepareStatement(JdbcBackend.scala:297)

        at slick.jdbc.JdbcBackend$BaseSession.prepareStatement(JdbcBackend.scala:407)

        at slick.jdbc.StatementInvoker.results(StatementInvoker.scala:33)

        at slick.jdbc.StatementInvoker.iteratorTo(StatementInvoker.scala:22)

        at slick.jdbc.Invoker$class.foreach(Invoker.scala:48)

        at slick.jdbc.StatementInvoker.foreach(StatementInvoker.scala:16)

        at slick.jdbc.Invoker$class.firstOption(Invoker.scala:24)

        at slick.jdbc.StatementInvoker.firstOption(StatementInvoker.scala:16)

        at slick.jdbc.StreamingInvokerAction$HeadOptionAction.run(StreamingInvokerAction.scala:57)

        at slick.jdbc.StreamingInvokerAction$HeadOptionAction.run(StreamingInvokerAction.scala:56)

        at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.liftedTree1$1(DatabaseComponent.scala:237)

        at slick.backend.DatabaseComponent$DatabaseDef$$anon$2.run(DatabaseComponent.scala:237)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

        at java.lang.Thread.run(Thread.java:745)

[DEBUG] [09/09/2016 20:34:28.530] [application-akka.actor.default-dispatcher-2] [EventStream] shutting down: StandardOutLogger started

[DEBUG] [09/09/2016 20:34:28.562] [application-akka.actor.default-dispatcher-2] [EventStream] shutting down: StandardOutLogger started

[fijimf]

Wow.  

Outrageously frustrating -- two days later I have a much deeper understanding of Slick, Play and ScalaTest -- none of which were the issue.

For the sake of anyone who comes by to read this:

    "allow you to map a team to a conference for a season" in new WithApplication(FakeApplication()) {
      for (
        seasonId <- repo.createSeason(2016);
        confId <- repo.createConference("big-east", "Big East");
        teamId <- repo.createTeam("georgetown", "Georgetown", "Georgetown University", "Hoyas")) {
        assert(Await.result(repo.mapTeam(seasonId, teamId, confId), Duration.Inf) > 0L)
      }
    }

is simply not testing anything.  The assert inside the code block does not execute on the test thread.  That is, if it were a 'yield' block, it would return Future[Unit] and the test would proceed immediately without the assert being called until later.  As the 'afterEach' method is called the table gets deleted.  The tests doesn't trap the exception, because it's done already.

Takeaway: One needs to be careful testing async stuff..

For posterity, it simply was that my test was not testing what I thought it was, and a single test wh