Rails+RSpec+DatabaseCleanerでテストをするとローカルは通るのにCIで落ちる

この記事は信州大学kstmアドベントカレンダー2019の13日目の記事です（遅くなってごめんなさい）。

丁度タイムリーにつまずいていることがあったのでそれをまとめ、ここに残すこととします。
参考リポジトリは arsley/circleci-databasecleaner-experiment です。

環境

• macOS Mojave 10.14.6
• Docker Desktop 2.1.0.5

その他使うgem

• RSpec
• DatabaseCleaner
• FactoryBot

サンプルアプリとテストについて

アプリの概要

• 書き手 Author とその本 Book
• 書き手は出版した本をたくさん持つ Author has_many Books
• 本には必ず書き手が必要 Book belongs_to Author

テストの概要

初期データとして書き手 Author を10人分あらかじめ登録しておきます。
その上で下記のことを検証します。

• 書き手一覧 /authors および本一覧 /books にアクセスし、それぞれが全て表示可能か検証
  • 各テストにおいてランダムに1人を選択し、その1人に10冊分の本データを登録

テストの目的

FactoryBot を使って belongs_to 関連付けを初期データに対して適用できることを確認したい。

一見良さそうながらこのテストは落ちます

なぜテストが落ちるのか

あらかじめ db:seed にて投入したデータと関連付けが取れず、それを使うようなテストが全て落ちる。

Failures:

  1) Authors GET / or /authors shows all authors
     Failure/Error: let!(:books) { create_list(:book, 10) }

     ActiveRecord::RecordInvalid:
       Validation failed: Author must exist
     # ./spec/requests/authors_spec.rb:5:in `block (3 levels) in <main>'
     # ./spec/rails_helper.rb:44:in `block (3 levels) in <top (required)>'
     # ./spec/rails_helper.rb:44:in `block (2 levels) in <top (required)>'

  2) Authors GET / or /authors returns status code 200
     Failure/Error: let!(:books) { create_list(:book, 10) }

     ActiveRecord::RecordInvalid:
       Validation failed: Author must exist
(以下略)

調査

rails db:seed で入れたはずのデータが綺麗さっぱりなくなっている。

2.6.3 :002 > Author.all
  Author Load (0.3ms)  SELECT "authors".* FROM "authors" LIMIT $1  [["LIMIT", 11]]
 => #<ActiveRecord::Relation []>

CircleCI SSH 上で db:seed すればデータは入る。

circleci@default:~/project$ docker-compose run -e RAILS_ENV=test --rm web bundle exec rails db:seed
Starting project_devserver_1 ...
Starting project_postgres_1 ... done

circleci@default:~/project$ docker-compose run -e RAILS_ENV=test --rm web bundle exec rails c
Starting project_postgres_1 ...
Starting project_devserver_1 ... done

Loading test environment (Rails 6.0.1)
2.6.3 :001 > Author.all
  Author Load (0.3ms)  SELECT "authors".* FROM "authors" LIMIT $1  [["LIMIT", 11]]
 => #<ActiveRecord::Relation [#<Author id: 1, name: "Earnest Jenkins...

なんならテストも通る。

circleci@default:~/project$ docker-compose run --rm web bundle exec rspec
Starting project_devserver_1 ... done
**....ng project_postgres_1 ... done

Pending: (Failures listed here are expected and do not affect your suite's status)

  1) Author add some examples to (or delete) /home/app/web/spec/models/author_spec.rb
     # Not yet implemented
     # ./spec/models/author_spec.rb:4

  2) Book add some examples to (or delete) /home/app/web/spec/models/book_spec.rb
     # Not yet implemented
     # ./spec/models/book_spec.rb:4


Finished in 3.25 seconds (files took 0.83349 seconds to load)
6 examples, 0 failures, 2 pending

テスト後にクリーンアップされているわけでもなさそう（ローカルと同様に）。

circleci@default:~/project$ docker-compose run -e RAILS_ENV=test --rm web bundle exec rails c
Starting project_postgres_1 ...
Starting project_devserver_1 ... done
Loading test environment (Rails 6.0.1)
2.6.3 :001 > Author.all
  Author Load (0.3ms)  SELECT "authors".* FROM "authors" LIMIT $1  [["LIMIT", 11]]
 => #<ActiveRecord::Relation [#<Author id: 1, name: "Earnest Jenkins...

同じ step に rails db:seed を含めてみた。

- run:
    name: Run tests
    command: |
      docker-compose run --rm -e RAILS_ENV=test web bundle exec rails db:seed
      docker-compose run --rm -e RAILS_ENV=test web bundle exec rspec

おお、神よ (rails db:seed が正しく機能していない?)

**FFFF

Pending: (Failures listed here are expected and do not affect your suite's status)

  1) Author add some examples to (or delete) /home/app/web/spec/models/author_spec.rb
     # Not yet implemented
     # ./spec/models/author_spec.rb:4

  2) Book add some examples to (or delete) /home/app/web/spec/models/book_spec.rb
     # Not yet implemented
     # ./spec/models/book_spec.rb:4


Failures:

  1) Authors GET / or /authors shows all authors
     Failure/Error: let!(:books) { create_list(:book, 10) }

     ActiveRecord::RecordInvalid:
       Validation failed: Author must exist
(以下略)

--verbose --trace=stdout とかで中間出力見たり、生成される log/test.log を確認してみる。

Starting project_postgres_1 ... 

Starting project_devserver_1 ... 


Starting project_postgres_1 ... done

Starting project_devserver_1 ... done
^@^@** Invoke db:create (first_time)
** Invoke db:load_config (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:load_config
** Execute db:create
Created database 'circleci_databasecleaner_experiment_test'
Starting project_postgres_1 ... 


Starting project_postgres_1 ... done
Starting project_devserver_1 ... 


Starting project_devserver_1 ... done
** Invoke db:migrate (first_time)
** Invoke db:load_config (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:load_config
** Execute db:migrate
== 20191212051422 CreateAuthors: migrating ====================================
-- create_table(:authors)
   -> 0.0300s
== 20191212051422 CreateAuthors: migrated (0.0301s) ===========================

== 20191212051528 CreateBooks: migrating ======================================
-- create_table(:books)
   -> 0.0135s
== 20191212051528 CreateBooks: migrated (0.0136s) =============================

** Invoke db:_dump (first_time)
** Execute db:_dump
** Invoke db:schema:dump (first_time)
** Invoke db:load_config 
** Execute db:schema:dump
Starting project_postgres_1 ... 

Starting project_devserver_1 ... 


Starting project_devserver_1 ... done

Starting project_postgres_1 ... done
** Invoke db:seed (first_time)
** Invoke db:load_config (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:load_config
** Execute db:seed
** Invoke db:abort_if_pending_migrations (first_time)
** Invoke db:load_config 
** Execute db:abort_if_pending_migrations
   (252.9ms)  CREATE DATABASE "circleci_databasecleaner_experiment_test" ENCODING = 'unicode'
   (19.0ms)  CREATE TABLE "schema_migrations" ("version" character varying NOT NULL PRIMARY KEY)
   (8.1ms)  CREATE TABLE "ar_internal_metadata" ("key" character varying NOT NULL PRIMARY KEY, "value" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)
   (0.3ms)  SELECT pg_try_advisory_lock(3827134079361798870)
   (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
Migrating to CreateAuthors (20191212051422)
   (0.3ms)  BEGIN
   (28.7ms)  CREATE TABLE "authors" ("id" bigserial primary key, "name" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)
  primary::SchemaMigration Create (0.6ms)  INSERT INTO "schema_migrations" ("version") VALUES ($1) RETURNING "version"  [["version", "20191212051422"]]
   (1.1ms)  COMMIT
Migrating to CreateBooks (20191212051528)
   (0.2ms)  BEGIN
   (7.1ms)  CREATE TABLE "books" ("id" bigserial primary key, "name" character varying, "description" character varying, "author_id" bigint NOT NULL, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL, CONSTRAINT "fk_rails_53d51ce16a"
FOREIGN KEY ("author_id")
  REFERENCES "authors" ("id")
)
   (2.8ms)  CREATE  INDEX  "index_books_on_author_id" ON "books"  ("author_id")
  primary::SchemaMigration Create (0.4ms)  INSERT INTO "schema_migrations" ("version") VALUES ($1) RETURNING "version"  [["version", "20191212051528"]]
   (1.2ms)  COMMIT
  ActiveRecord::InternalMetadata Load (0.4ms)  SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2  [["key", "environment"], ["LIMIT", 1]]
   (0.2ms)  BEGIN
  ActiveRecord::InternalMetadata Create (0.5ms)  INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "key"  [["key", "environment"], ["value", "test"], ["created_at", "2019-12-13 04:25:18.984380"], ["updated_at", "2019-12-13 04:25:18.984380"]]
   (1.1ms)  COMMIT
   (0.3ms)  SELECT pg_advisory_unlock(3827134079361798870)
   (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.2ms)  BEGIN
  Author Create (0.6ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Jasmin McKenzie"], ["created_at", "2019-12-13 04:25:22.894663"], ["updated_at", "2019-12-13 04:25:22.894663"]]
   (1.2ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Derek Okuneva"], ["created_at", "2019-12-13 04:25:22.898512"], ["updated_at", "2019-12-13 04:25:22.898512"]]
   (0.9ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Edwin Predovic"], ["created_at", "2019-12-13 04:25:22.901265"], ["updated_at", "2019-12-13 04:25:22.901265"]]
   (0.9ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.4ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Miss Ninfa Funk"], ["created_at", "2019-12-13 04:25:22.903902"], ["updated_at", "2019-12-13 04:25:22.903902"]]
   (1.0ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Teodoro Mayert"], ["created_at", "2019-12-13 04:25:22.906679"], ["updated_at", "2019-12-13 04:25:22.906679"]]
   (0.9ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Karl Oberbrunner"], ["created_at", "2019-12-13 04:25:22.909354"], ["updated_at", "2019-12-13 04:25:22.909354"]]
   (1.0ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.4ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Dr. Eliseo Koss"], ["created_at", "2019-12-13 04:25:22.912073"], ["updated_at", "2019-12-13 04:25:22.912073"]]
   (0.8ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Ms. Mikki Harvey"], ["created_at", "2019-12-13 04:25:22.914628"], ["updated_at", "2019-12-13 04:25:22.914628"]]
   (0.9ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Mrs. Sommer Dickens"], ["created_at", "2019-12-13 04:25:22.917220"], ["updated_at", "2019-12-13 04:25:22.917220"]]
   (0.8ms)  COMMIT
   (0.2ms)  BEGIN
  Author Create (0.3ms)  INSERT INTO "authors" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "Essie Gleichner Jr."], ["created_at", "2019-12-13 04:25:22.919641"], ["updated_at", "2019-12-13 04:25:22.919641"]]
   (0.9ms)  COMMIT

ちゃんと INSERT してるやん...なんでや...

中身 Author.all を確認するRakeタスクを追加して、データ追加以後の部分で実際に見てみる.

desc 'Show all Authors'
task authors: [:environment] do
  puts Author.all
end

Starting project_postgres_1 ... 


Starting project_postgres_1 ... done
Starting project_devserver_1 ... 


Starting project_devserver_1 ... done
^@^@** Invoke authors (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute authors
#<Author:0x0000555ac1209150>
#<Author:0x0000555ac124ea98>
#<Author:0x0000555ac124e9d0>
#<Author:0x0000555ac124e908>
#<Author:0x0000555ac124e840>
#<Author:0x0000555ac124e778>
#<Author:0x0000555ac124e6b0>
#<Author:0x0000555ac124e5e8>
#<Author:0x0000555ac124e520>
#<Author:0x0000555ac124e458>
Starting project_devserver_1 ... 

Starting project_postgres_1 ... 


Starting project_devserver_1 ... done

Starting project_postgres_1 ... done
**FFFF

Pending: (Failures listed here are expected and do not affect your suite's status)

  1) Author add some examples to (or delete) /home/app/web/spec/models/author_spec.rb
     # Not yet implemented
     # ./spec/models/author_spec.rb:4

  2) Book add some examples to (or delete) /home/app/web/spec/models/book_spec.rb
     # Not yet implemented
     # ./spec/models/book_spec.rb:4


Failures:

  1) Authors GET / or /authors shows all authors
     Failure/Error: let!(:books) { create_list(:book, 10) }

     ActiveRecord::RecordInvalid:
       Validation failed: Author must exist
(以下略)

テスト前に確認してみるとデータは入ってるぞ???
FactoryBotの使い方が悪いか?
いやでもローカルだと通るんだよなあ...

ん?テストの実行方法違うんじゃない?

# local
docker-compose run --rm web bundle exec rspec

# CI
docker-compose run --rm -e RAILS_ENV=test web bundle exec rspec

関係なくて泣いた。

$ dcc run --rm -e RAILS_ENV=test web bundle exec rspec
Starting circleci_databasecleaner_experiment_devserver_1 ... done
Starting circleci_databasecleaner_experiment_postgres_1  ... done
**....

Pending: (Failures listed here are expected and do not affect your suite's status)

  1) Author add some examples to (or delete) /home/app/web/spec/models/author_spec.rb
     # Not yet implemented
     # ./spec/models/author_spec.rb:4

  2) Book add some examples to (or delete) /home/app/web/spec/models/book_spec.rb
     # Not yet implemented
     # ./spec/models/book_spec.rb:4


Finished in 29.29 seconds (files took 6.05 seconds to load)
6 examples, 0 failures, 2 pending

$ dcc run --rm  web bundle exec rspec
Starting circleci_databasecleaner_experiment_postgres_1  ... done
Starting circleci_databasecleaner_experiment_devserver_1 ... done
**....

Pending: (Failures listed here are expected and do not affect your suite's status)

  1) Author add some examples to (or delete) /home/app/web/spec/models/author_spec.rb
     # Not yet implemented
     # ./spec/models/author_spec.rb:4

  2) Book add some examples to (or delete) /home/app/web/spec/models/book_spec.rb
     # Not yet implemented
     # ./spec/models/book_spec.rb:4


Finished in 27.74 seconds (files took 5.73 seconds to load)
6 examples, 0 failures, 2 pending

今一度CircleCIの方へSSHして、 log/test.log をみてみた。

  Author Load (0.5ms)  SELECT "authors".* FROM "authors"
  Author Load (0.5ms)  SELECT "authors".* FROM "authors"
  Author Load (0.6ms)  SELECT "authors".* FROM "authors"
   (0.3ms)  SELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1  [["key", "schema_sha1"]]
   (0.6ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.3ms)  SELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1  [["key", "environment"]]
   (0.3ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.3ms)  SELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1  [["key", "environment"]]
   (0.3ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
   (0.2ms)  SELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1  [["key", "environment"]]
   (107.5ms)  DROP DATABASE IF EXISTS "circleci_databasecleaner_experiment_test"
   (238.8ms)  CREATE DATABASE "circleci_databasecleaner_experiment_test" ENCODING = 'unicode'
  SQL (0.3ms)  CREATE EXTENSION IF NOT EXISTS "plpgsql"
   (0.2ms)  DROP TABLE IF EXISTS "authors" CASCADE
   (12.1ms)  CREATE TABLE "authors" ("id" bigserial primary key, "name" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)
   (0.3ms)  DROP TABLE IF EXISTS "books" CASCADE
   (8.8ms)  CREATE TABLE "books" ("id" bigserial primary key, "name" character varying, "description" character varying, "author_id" bigint NOT NULL, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)
   (4.1ms)  CREATE  INDEX  "index_books_on_author_id" ON "books"  ("author_id")
   (2.6ms)  ALTER TABLE "books" ADD CONSTRAINT "fk_rails_53d51ce16a"
FOREIGN KEY ("author_id")

なぜか勝手にDB消してるねえ...

   (107.5ms)  DROP DATABASE IF EXISTS "circleci_databasecleaner_experiment_test"
   (238.8ms)  CREATE DATABASE "circleci_databasecleaner_experiment_test" ENCODING = 'unicode'
  SQL (0.3ms)  CREATE EXTENSION IF NOT EXISTS "plpgsql"
   (0.2ms)  DROP TABLE IF EXISTS "authors" CASCADE
   (12.1ms)  CREATE TABLE "authors" ("id" bigserial primary key, "name" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)
   (0.3ms)  DROP TABLE IF EXISTS "books" CASCADE

再現条件がわからないけど、ローカルでも db:drop db:create db:migrate db:seed spec を続けてやったら勝手にDB消してた。

  [1m[35m (2.3ms)[0m  [1m[34mSELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1[0m  [["key", "schema_sha1"]]
  [1m[35m (5.9ms)[0m  [1m[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC[0m
  [1m[35m (3.6ms)[0m  [1m[34mSELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1[0m  [["key", "environment"]]
  [1m[35m (1.4ms)[0m  [1m[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC[0m
  [1m[35m (4.7ms)[0m  [1m[34mSELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1[0m  [["key", "environment"]]
  [1m[35m (1.4ms)[0m  [1m[34mSELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC[0m
  [1m[35m (2.0ms)[0m  [1m[34mSELECT "ar_internal_metadata"."value" FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1[0m  [["key", "environment"]]
  [1m[35m (663.2ms)[0m  [1m[35mDROP DATABASE IF EXISTS "circleci_databasecleaner_experiment_test"[0m
  [1m[35m (2972.1ms)[0m  [1m[35mCREATE DATABASE "circleci_databasecleaner_experiment_test" ENCODING = 'unicode'[0m
  [1m[35mSQL (6.2ms)[0m  [1m[35mCREATE EXTENSION IF NOT EXISTS "plpgsql"[0m
  [1m[35m (0.6ms)[0m  [1m[35mDROP TABLE IF EXISTS "authors" CASCADE[0m
  [1m[35m (95.5ms)[0m  [1m[35mCREATE TABLE "authors" ("id" bigserial primary key, "name" character varying, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)[0m
  [1m[35m (0.7ms)[0m  [1m[35mDROP TABLE IF EXISTS "books" CASCADE[0m
  [1m[35m (23.7ms)[0m  [1m[35mCREATE TABLE "books" ("id" bigserial primary key, "name" character varying, "description" character varying, "author_id" bigint NOT NULL, "created_at" timestamp(6) NOT NULL, "updated_at" timestamp(6) NOT NULL)[0m
  [1m[35m (7.2ms)[0m  [1m[35mCREATE  INDEX  "index_books_on_author_id" ON "books"  ("author_id")[0m
  [1m[35m (29.9ms)[0m  [1m[35mALTER TABLE "books" ADD CONSTRAINT "fk_rails_53d51ce16a"
FOREIGN KEY ("author_id")
  REFERENCES "authors" ("id")

おそらくテストの開始前にDBのクリーンアップ処理が行われるという形になっていそうなので、DBのクリーンアップ後に初期データ投入プロセスを実施させることで解決することにしました。

解決策

RSpec によるテストを回し始める前にテストDBにおける主要テーブルを全て truncate し、その後に初期データ投入を行うこととしました。
具体的には spec/rails_helper.rb の RSpec.configure ブロック内に下記を記述しました。

RSpec.configure do |config|
...
  config.before(:suite) do
    DatabaseCleaner.strategy = :transaction
    DatabaseCleaner.clean_with(:truncation)
    Rails.application.load_seed
  end
...
end

これでテストが通りました

ﾖｼ!!!!!!!!!!!!!!!!!!!! pic.twitter.com/80drr3kKEH

— Aoshi (@arsley_) December 13, 2019

小言

この問題なんですが、別のプロジェクトでRailsを 5.2 から 6.0 に上げた時に発生したもので、↑にて調査した内容から察するにActiveRecordで何かあったのかな...と思っています。
DatabaseCleaner や FactoryBot のバージョンは変わっていないので...

参考

• With RSpec, how to seed the database on load? - Stack Overflow