はじめに
RSpec + Shrine の環境のテストで updated_at がうまく設定できない事象を調査・解消したので備忘としてまとめておきます。
起こった問題
問題がなかった状態
以下のようなモデル・コントローラーを作りました。
class Article < ApplicationRecord
end
class ArticlesController < ApplicationController
def index
@articles = Article.all.order(:updated_at)
end
end
このモデル・コントローラーに対して、以下のような RSpec のテストと、FactoryBot の設定をしました。
require 'rails_helper'
RSpec.describe 'Articles', type: :request do
describe 'GET /index' do
let!(:newer_article) { create :article, updated_at: Date.new(2024, 6, 20) }
let!(:older_article) { create :article, updated_at: Date.new(2024, 6, 19) }
it do
get '/articles/index.json'
response_json = response.parsed_body
p '=== newer_article ==='
pp newer_article
p '=== older_article ==='
pp older_article
p '=== response ==='
pp response_json
expect(response_json[0]['id']).to eq older_article.id
expect(response_json[1]['id']).to eq newer_article.id
end
end
end
FactoryBot.define do
factory :article do
title { 'test title' }
body { 'sample body' }
end
end
この時点ではテストは問題なくパスしていました。
$ rspec
"=== newer_article ==="
#<Article:0x00007f49dae28cb0
id: 1,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 01:13:49.600516000 UTC +00:00,
updated_at: Thu, 20 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data: nil>
"=== older_article ==="
#<Article:0x00007f49da92dd50
id: 2,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 01:13:49.606225000 UTC +00:00,
updated_at: Wed, 19 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data: nil>
"=== response ==="
[{"id"=>2, "title"=>"test title", "body"=>"sample body"},
{"id"=>1, "title"=>"test title", "body"=>"sample body"}]
.
Finished in 0.34433 seconds (files took 5.86 seconds to load)
1 example, 0 failures
問題が起こった状態
この状態から、Shrine の gem を使って画像をアップロードできるように変更しました。
shrinerb.com
class ImageUploader < Shrine
end
class Article < ApplicationRecord
include Shrine::Attachment(:image)
end
FactoryBot.define do
factory :article do
title { 'test title' }
body { 'sample body' }
image { File.new('spec/fixtures/test.png') }
end
end
この状態でテストを実行したところ、updated_at の値が変更されて、返却順が変わったことでテストがこけるようになっていました。
$ rspec
"=== newer_article ==="
id: 1,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 02:50:04.749216000 UTC +00:00,
updated_at: Sun, 23 Jun 2024 02:50:04.762817000 UTC +00:00,
image_data:
"{\"id\":\"5132a30ebd927dbe516b933e9a967fe2.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}">
"=== older_article ==="
id: 2,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 02:50:04.795344000 UTC +00:00,
updated_at: Sun, 23 Jun 2024 02:50:04.805194000 UTC +00:00,
image_data:
"{\"id\":\"325af135c2acfb43169c48c522c1d2c5.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}">
"=== response ==="
[{"id"=>1, "title"=>"test title", "body"=>"sample body"},
{"id"=>2, "title"=>"test title", "body"=>"sample body"}]
F
Failures:
1) Articles GET /index is expected to eq 2
Failure/Error: expect(response_json[0]['id']).to eq older_article.id
expected: 2
got: 1
(compared using ==)
Finished in 0.45642 seconds (files took 6.12 seconds to load)
1 example, 1 failure
Failed examples:
rspec ./spec/requests/articles_spec.rb:8
調査
状況整理
shrine を使って画像をアップロードするようにしてからテストが動かなくなったというのが今回の状況です。
また、updated_at が更新されていることから、インスタンスの作成後に何らかの SQL 動いていそうです。
原因の切り分け
一度 shrine の各種設定はそのまま、かつ以下のように画像のアップロードがない状態で RSpec のテストを再度走らせてみました。
FactoryBot.define do
factory :article do
title { 'test title' }
body { 'sample body' }
image {}
end
end
実行結果を確認したところ、updated_at が指定通りの日時になっており、問題なくテストをパスすることを確認できました。
$ rspec
"=== newer_article ==="
id: 1,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 03:17:15.470633000 UTC +00:00,
updated_at: Thu, 20 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data: nil>
"=== older_article ==="
id: 2,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 03:17:15.477019000 UTC +00:00,
updated_at: Wed, 19 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data: nil>
"=== response ==="
[{"id"=>2, "title"=>"test title", "body"=>"sample body"},
{"id"=>1, "title"=>"test title", "body"=>"sample body"}]
.
Finished in 0.36878 seconds (files took 5.66 seconds to load)
1 example, 0 failures
テスト実行時のログの調査
原因はおおよそわかったので、次に画像アップロード時に何が起こっているか確認するためにログを確認しました。
まず、画像をアップロードをしない場合のテスト実行時のログを確認しました。
$ cat log/test.log
ActiveRecord::InternalMetadata Load (0.6ms) SELECT * FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? ORDER BY "ar_internal_metadata"."key" ASC LIMIT 1 [[nil, "schema_sha1"]]
ActiveRecord::SchemaMigration Load (0.5ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
TRANSACTION (0.1ms) begin transaction
TRANSACTION (0.1ms) SAVEPOINT active_record_1
Article Create (1.6ms) INSERT INTO "articles" ("title", "body", "created_at", "updated_at", "image_data") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["title", "test title"], ["body", "sample body"], ["created_at", "2024-06-23 03:54:48.899419"], ["updated_at", "2024-06-20 00:00:00"], ["image_data", nil]]
TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
TRANSACTION (0.2ms) SAVEPOINT active_record_1
Article Create (2.5ms) INSERT INTO "articles" ("title", "body", "created_at", "updated_at", "image_data") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["title", "test title"], ["body", "sample body"], ["created_at", "2024-06-23 03:54:48.907741"], ["updated_at", "2024-06-19 00:00:00"], ["image_data", nil]]
TRANSACTION (0.5ms) RELEASE SAVEPOINT active_record_1
Started GET "/articles/index.json" for 127.0.0.1 at 2024-06-23 03:54:48 +0000
Processing by ArticlesController#index as JSON
Rendering articles/index.json.jbuilder
Article Load (0.2ms) SELECT "articles".* FROM "articles" ORDER BY "articles"."updated_at" ASC
Rendered articles/index.json.jbuilder (Duration: 5.0ms | Allocations: 558)
Completed 200 OK in 78ms (Views: 23.2ms | ActiveRecord: 0.2ms | Allocations: 5829)
TRANSACTION (0.1ms) rollback transaction
次に、まず、画像をアップロードをする場合のテスト実行時のログを確認しました。
INSERT 分でのレコード作成後に、 UPDATE 文で更新タイミングの時刻で updated_at 更新がかかっていることが分かりました。
$ cat log/test.log
ActiveRecord::InternalMetadata Load (0.6ms) SELECT * FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = ? ORDER BY "ar_internal_metadata"."key" ASC LIMIT 1 [[nil, "schema_sha1"]]
ActiveRecord::SchemaMigration Load (0.4ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
TRANSACTION (0.1ms) begin transaction
TRANSACTION (0.1ms) SAVEPOINT active_record_1
Article Create (1.3ms) INSERT INTO "articles" ("title", "body", "created_at", "updated_at", "image_data") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["title", "test title"], ["body", "sample body"], ["created_at", "2024-06-23 03:26:35.095011"], ["updated_at", "2024-06-20 00:00:00"], ["image_data", "{\"id\":\"042a5d1290474df6d6ce5991e093e930.png\",\"storage\":\"cache\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}"]]
TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
TRANSACTION (0.1ms) SAVEPOINT active_record_1
Article Update (1.1ms) UPDATE "articles" SET "updated_at" = ?, "image_data" = ? WHERE "articles"."id" = ? [["updated_at", "2024-06-23 03:26:35.109074"], ["image_data", "{\"id\":\"01478f78b5c25ba21a285abc458163a5.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}"], ["id", 1]]
TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
TRANSACTION (0.1ms) SAVEPOINT active_record_1
Article Create (1.3ms) INSERT INTO "articles" ("title", "body", "created_at", "updated_at", "image_data") VALUES (?, ?, ?, ?, ?) RETURNING "id" [["title", "test title"], ["body", "sample body"], ["created_at", "2024-06-23 03:26:35.141299"], ["updated_at", "2024-06-19 00:00:00"], ["image_data", "{\"id\":\"630b9a4a01f703f2534c8b0587cf24a2.png\",\"storage\":\"cache\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}"]]
TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
TRANSACTION (0.1ms) SAVEPOINT active_record_1
Article Update (1.3ms) UPDATE "articles" SET "updated_at" = ?, "image_data" = ? WHERE "articles"."id" = ? [["updated_at", "2024-06-23 03:26:35.154750"], ["image_data", "{\"id\":\"c5b54dec0f1b455088e87f50985692ec.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}"], ["id", 2]]
TRANSACTION (0.1ms) RELEASE SAVEPOINT active_record_1
Started GET "/articles/index.json" for 127.0.0.1 at 2024-06-23 03:26:35 +0000
Processing by ArticlesController#index as JSON
Rendering articles/index.json.jbuilder
Article Load (0.4ms) SELECT "articles".* FROM "articles" ORDER BY "articles"."updated_at" ASC
Rendered articles/index.json.jbuilder (Duration: 5.2ms | Allocations: 555)
Completed 200 OK in 53ms (Views: 19.5ms | ActiveRecord: 0.3ms | Allocations: 4842)
TRANSACTION (0.1ms) rollback transaction
解決方法
解決方法はいくつかある気もしますが、before 節で touch で updated_at 設定し直してテストを通せるようにしました。
require 'rails_helper'
RSpec.describe 'Articles', type: :request do
describe 'GET /index' do
let!(:newer_article) { create :article }
let!(:older_article) { create :article }
before do
newer_article.touch(time: Date.new(2024, 6, 20))
older_article.touch(time: Date.new(2024, 6, 19))
end
it do
get '/articles/index.json'
response_json = response.parsed_body
p '=== newer_article ==='
pp newer_article
p '=== older_article ==='
pp older_article
p '=== response ==='
pp response_json
expect(response_json[0]['id']).to eq older_article.id
expect(response_json[1]['id']).to eq newer_article.id
end
end
end
$ rspec
"=== newer_article ==="
#<Article:0x00007effc4a71000
id: 1,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 04:11:57.994704000 UTC +00:00,
updated_at: Thu, 20 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data:
"{\"id\":\"a1cba966174f7aa752a50a9fa3ae1a82.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}">
"=== older_article ==="
#<Article:0x00007effc471e4c0
id: 2,
title: "test title",
body: "sample body",
created_at: Sun, 23 Jun 2024 04:11:58.064807000 UTC +00:00,
updated_at: Wed, 19 Jun 2024 00:00:00.000000000 UTC +00:00,
image_data:
"{\"id\":\"00179feb51547ac848c0f45bc7f25243.png\",\"storage\":\"store\",\"metadata\":{\"filename\":\"test.png\",\"size\":10084,\"mime_type\":null}}">
"=== response ==="
[{"id"=>2, "title"=>"test title", "body"=>"sample body"},
{"id"=>1, "title"=>"test title", "body"=>"sample body"}]
.
Finished in 0.42006 seconds (files took 5.13 seconds to load)
1 example, 0 failures
まとめ
Shrine を使った際に、 updated_at に依存したテストがうまくいかなくなる問題を調査・解消しました。
Shrine を使った画像アップロードを行うテストで、updated_at を参照する場合、画像アップロードの段階で UPDATE 文が走るため、updated_at が更新されてしまうため、別途 updated_at を調整する必要がありそうです。
