Fixtureを複数使ったときにテストがこける

README.md

エラーメッセージ:

$ sbt test
[info] Loading global plugins from /Users/harukasan/.sbt/0.13/plugins
[info] Loading project definition from /Users/harukasan/repo/play-test/project
[info] Set current project to play-test (in build file:/Users/harukasan/repo/play-test/)
[info] Compiling 1 Scala source to /Users/harukasan/repo/play-test/target/scala-2.11/test-classes...
[info] - play.api.libs.concurrent.ActorSystemProvider - Starting application default Akka system: application
[info] - play.api.libs.concurrent.ActorSystemProvider - Shutdown application default Akka system: application
[info] TestSpec
[info]
[info] Test should
[info]   + insert
[error] - scalikejdbc.StatementExecutor$$anon$1 - SQL execution failed (Reason: Lock wait timeout exceeded; try restarting transaction):

   INSERT INTO user VALUES (1, 'bob')

[error]   ! insert again
[error]    Lock wait timeout exceeded; try restarting transaction (SQLError.java:998)
[error] com.mysql.jdbc.SQLError.createSQLException(SQLError.java:998)
[error] com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3847)
[error] com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3783)
[error] com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2447)
[error] com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
[error] com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
[error] com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1901)
[error] com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2113)
[error] com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2049)
[error] com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2034)
[error] org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
[error] org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
[error] scalikejdbc.StatementExecutor$$anonfun$executeUpdate$1.apply$mcI$sp(StatementExecutor.scala:326)
[error] scalikejdbc.StatementExecutor$$anonfun$executeUpdate$1.apply(StatementExecutor.scala:326)
[error] scalikejdbc.StatementExecutor$$anonfun$executeUpdate$1.apply(StatementExecutor.scala:326)
[error] scalikejdbc.StatementExecutor$NakedExecutor.apply(StatementExecutor.scala:18)
[error] scalikejdbc.StatementExecutor$$anon$1.scalikejdbc$StatementExecutor$LoggingSQLAndTiming$$super$apply(StatementExecutor.scala:306)
[error] scalikejdbc.StatementExecutor$LoggingSQLAndTiming$class.apply(StatementExecutor.scala:250)
[error] scalikejdbc.StatementExecutor$$anon$1.scalikejdbc$StatementExecutor$LoggingSQLIfFailed$$super$apply(StatementExecutor.scala:306)
[error] scalikejdbc.StatementExecutor$LoggingSQLIfFailed$class.apply(StatementExecutor.scala:283)
[error] scalikejdbc.StatementExecutor$$anon$1.apply(StatementExecutor.scala:306)
[error] scalikejdbc.StatementExecutor.executeUpdate(StatementExecutor.scala:326)
[error] scalikejdbc.DBSession$$anonfun$updateWithFilters$1.apply(DBSession.scala:398)
[error] scalikejdbc.DBSession$$anonfun$updateWithFilters$1.apply(DBSession.scala:396)
[error] scalikejdbc.LoanPattern$class.using(LoanPattern.scala:18)
[error] scalikejdbc.ActiveSession.scalikejdbc$DBSession$$super$using(DBSession.scala:548)
[error] scalikejdbc.DBSession$class.using(DBSession.scala:30)
[error] scalikejdbc.ActiveSession.using(DBSession.scala:548)
[error] scalikejdbc.DBSession$class.updateWithFilters(DBSession.scala:395)
[error] scalikejdbc.ActiveSession.updateWithFilters(DBSession.scala:548)
[error] scalikejdbc.DBSession$class.updateWithFilters(DBSession.scala:373)
[error] scalikejdbc.ActiveSession.updateWithFilters(DBSession.scala:548)
[error] scalikejdbc.SQLUpdate.apply(SQL.scala:506)
[error] FixtureB$class.fixture(TestSpec.scala:35)
[error] TestSpec$$anonfun$2$$anonfun$apply$2$$anon$2.fixture(TestSpec.scala:21)
[error] scalikejdbc.specs2.AutoRollbackLike$$anonfun$1.apply(AutoRollbackLike.scala:29)
[error] scalikejdbc.specs2.AutoRollbackLike$$anonfun$1.apply(AutoRollbackLike.scala:28)
[error] scalikejdbc.DBConnection$class.withinTx(DBConnection.scala:253)
[error] scalikejdbc.DB.withinTx(DB.scala:60)
[error] scalikejdbc.specs2.AutoRollbackLike$class.$init$(AutoRollbackLike.scala:28)
[error] TestSpec$$anonfun$2$$anonfun$apply$2$$anon$2.<init>(TestSpec.scala:21)
[error] TestSpec$$anonfun$2$$anonfun$apply$2.apply(TestSpec.scala:21)
[error] TestSpec$$anonfun$2$$anonfun$apply$2.apply(TestSpec.scala:21)
[info]
[info]
[info] Total for specification TestSpec
[info] Finished in 50 seconds, 716 ms
[info] 2 examples, 0 failure, 1 error
[info]
[error] Error: Total 2, Failed 0, Errors 1, Passed 1
[error] Error during tests:
[error] 	TestSpec
[error] (test:test) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 59 s, completed Sep 1, 2015 9:07:10 PM

1つめのトランザクションが終了するまえにINSERTが実行されると起こる。 図にするとこんな感じ:

---------------------------------------------------------------> time
in case 1:  +begin  +insert + select                   (+rollback)
in case 2:                          +begin  +insert (+select)
                                            ^^^^^^^
                                            failed inserting

general logをとるとこうなっている:

150901 21:14:09	 1945 Connect	root@localhost on play_test
		 1945 Query	/* mysql-connector-java-5.1.36 ... snip ...
		 1945 Query	SET character_set_results = NULL
		 1945 Query	SET autocommit=1
		 1945 Query	SET sql_mode='STRICT_TRANS_TABLES'
		 1945 Query	SET autocommit=0
		 1945 Query	INSERT INTO user VALUES (1, 'alice')
		 1945 Query	SELECT name FROM user WHERE id = 1 <--- 本当はここでロールバックされて欲しい
		 1946 Connect	root@localhost on play_test
		 1946 Query	/* mysql-connector-java-5.1.36 ... snip ...
		 1946 Query	SET character_set_results = NULL
		 1946 Query	SET autocommit=1
		 1946 Query	SET sql_mode='STRICT_TRANS_TABLES'
		 1946 Query	SET autocommit=0
		 1946 Query	INSERT INTO user VALUES (1, 'bob')

トランザクションはこうなってて、ロックされている

mysql> show engine innodb status \G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:

...snip...

------------
TRANSACTIONS
------------
Trx id counter 13BE
Purge done for trx's n:o < 139B undo n:o < 0
History list length 378
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1948, OS thread handle 0x110c9d000, query id 34687 localhost root
show engine innodb status
---TRANSACTION D21, not started
MySQL thread id 1229, OS thread handle 0x110bbe000, query id 20859 localhost 127.0.0.1 root
---TRANSACTION 13BD, ACTIVE 2 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 1952, OS thread handle 0x110d23000, query id 34686 localhost 127.0.0.1 root update
INSERT INTO user VALUES (1, 'bob')
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 9 page no 3 n bits 80 index `PRIMARY` of table `play_test`.`user` trx id 13BD lock mode S locks rec but not gap waiting
Record lock, heap no 9 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 8; hex 8000000000000001; asc         ;;
 1: len 6; hex 0000000013bc; asc       ;;
 2: len 7; hex e2000002140110; asc        ;;
 3: len 5; hex 616c696365; asc alice;;
 
...

もしかしてsequentialをつければ良いのかな？と思ってつけてみたけど改善しなかった。 1つのファイル内であれば、他のテストとかぶらないようにすることで解決できたけど、複数ファイルにまたがってると厳しい。

application.conf

play.crypto.secret = "changeme"
play.i18n.langs = [ "en" ]


# Database configuration
# ~~~~~
db.default.driver="com.mysql.jdbc.Driver"
db.default.url="jdbc:mysql://localhost/play_test?allowMultiQueries=true"
db.default.user="root"
db.default.password=""

scalikejdbc.global.loggingSQLAndTime.enabled=true
scalikejdbc.global.loggingSQLAndTime.singleLineMode=false
scalikejdbc.global.loggingSQLAndTime.logLevel=debug
scalikejdbc.global.loggingSQLAndTime.warningEnabled=true
scalikejdbc.global.loggingSQLAndTime.warningThresholdMillis=5
scalikejdbc.global.loggingSQLAndTime.warningLogLevel=warn

play.modules.enabled += "scalikejdbc.PlayModule"
play.modules.enabled += "scalikejdbc.PlayFixtureModule"
play.modules.disabled += "play.api.db.DBModule"

build.sbt

name := """play-test"""

version := "1.0-SNAPSHOT"

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

scalaVersion := "2.11.7"

libraryDependencies ++= Seq(
  specs2 % Test,

  "mysql"           %  "mysql-connector-java"         % "5.1.36",
  "org.scalikejdbc" %% "scalikejdbc"                  % "2.2.8",
  "org.scalikejdbc" %% "scalikejdbc-config"           % "2.2.8",
  "org.scalikejdbc" %% "scalikejdbc-play-fixture"     % "2.4.1",
  "org.scalikejdbc" %% "scalikejdbc-play-initializer" % "2.4.1",
  "org.scalikejdbc" %% "scalikejdbc-test"             % "2.2.8" % Test
)
resolvers += "scalaz-bintray" at "http://dl.bintray.com/scalaz/releases"

// Play provides two styles of routers, one expects its actions to be injected, the
// other, legacy style, accesses its actions statically.
routesGenerator := InjectedRoutesGenerator

TestSpec.scala

import org.junit.runner.RunWith
import org.specs2.mutable._
import org.specs2.runner._
import play.api.test.Helpers._
import play.api.test._
import scalikejdbc._
import scalikejdbc.config._
import scalikejdbc.specs2.AutoRollback


@RunWith(classOf[JUnitRunner])
class TestSpec extends Specification {
  running(FakeApplication()){}
  DBs.setupAll()
  
  sequential

  "Test" should {
    "insert" in new FixtureA {
      sql"""SELECT name FROM user WHERE id = 1""".map(rs => rs.string("name")).single.apply.get should_== "alice"
    }

    "insert again" in new FixtureB {
      sql"""SELECT name FROM user WHERE id = 1""".map(rs => rs.string("name")).single.apply.get should_== "bob"
    }
  }
}

trait FixtureA extends AutoRollback {
  override def fixture(implicit session: DBSession) = {
    sql"""INSERT INTO user VALUES (1, ${"alice"})""".update.apply
  }
}

trait FixtureB extends AutoRollback {
  override def fixture(implicit session: DBSession) = {
    sql"""INSERT INTO user VALUES (1, ${"bob"})""".update.apply
  }
}

V1__CREATE_TABLE.sql

CREATE TABLE IF NOT EXISTS user (
  id BIGINT PRIMARY KEY,
  name VARCHAR(255) NOT NULL
);

import scalikejdbc.specs2.mutable.AutoRollbackにすれば動くかと思います