これは「フィヨルドブートキャンプ Advent Calendar 2023」の14日目の記事です。

こんにちは。現在、フィヨルドブートキャンプ（以下 FBC）でチーム開発の課題に取り組んでいます。今回はチーム開発のプラクティスに入って最初のイシューでエラーに遭遇したので、そのとき学んだことについて書きたいと思います。

FBCチーム開発の特徴

最初にFBCではどんな形でチーム開発が進められるのか、特徴について簡単に触れたいと思います。

Bootcampというシステムを使って開発を行う

Bootcamp は受講生たちが毎日書く日報、質問の投稿・閲覧を行うQ&A、メンターさんが書かれる Docs やブログ記事、各種イベント、受講生の入会・退会なども管理されており、FBCの主要なシステムとして実際に使われているものです。オープンソースソフトウェア（OSS）としてソースコードも公開されています。また discord のチャンネルでは、発見したバグや欲しい機能などを discord 内のメンバーが誰でも投稿したり、イシューとして提案することもできます。

開発手法はアジャイル開発のひとつであるスクラムを採用

チーム開発プラクティスの前準備として、アジャイルとスクラムについて学び、それらがどういうものなのか、どのような目的でスクラムを利用するのか、ある程度理解したうえでチーム開発に入るようになっています。
以下の書籍で学びました。

FBCのスプリント期間は一週間で、作業完了したものが毎週リリースされます。
ふりかえり・計画ミーティングも毎週行われ、そこでは一週間の進捗報告や実装したもののデモを行なったり、詰まっていることなどを相談することができます。

PRは、まず受講生にレビューを依頼してOKをいただいてから、スクラムマスターに依頼する

受講生同士レビューを行うことで、レビュー側の視点も持つことができ、自分のイシューだけでなく自分以外の受講生が取り組んでいるイシューについても調べることになるので、より多くのことを学べる仕組みになっています。

最初のイシューでエラーに遭遇した

修正作業

最初は簡単な作業からイシューを振り分けていただけるのですが、私が担当したのはこちらのイシューの一部でした。

slim-lint の実行で出力されるようになったスタイル違反を修正して欲しい · Issue #6496 · fjordllc/bootcamp · GitHub

rubocop-fjord とは、FBC用の RuboCop の設定で課題提出する前にこちらを通します。バージョンアップにより slim-lint で警告が出るようになったので、ハッシュを省略形に修正して警告を出なくするというものでした。修正自体は他の受講生が既に別のファイルを担当されていたので、PRの書き方などそちらも参考にしながら取り組みました。

テストを通す

修正が終わったらテストを通します。

正しい順番

修正する
↓
ローカルで、修正部分に関係すると思われるテストを通す
↓
ローカルテストが異常なければ、プッシュする
↓
CIが通っているか確認する
↓
CIに異常がなければ、レビューを依頼する

継続的インテグレーション (CI) とは？ - CircleCI

私は順番を間違えてしまい、先にGitHubの自分の作ったブランチにプッシュして受講生にレビューを依頼してしまいました。
その後、間違いに気づいてローカルテストを通さなくてはと思い、そこで事件は起きました。

CI は通っていました。
Image from Gyazo
最初に使っていた実行コマンドがこちらで、

$ bin/rails test:all

なかなか安定せず、通らないものと通るものがバラバラでした。それでも何回かやったら通るようになっていくのかと思い、次のコマンドを実行しました。

$ CI=1 PARALLEL_WORKERS=1 bin/rails test:all

CI: CI環境で有効になる変数。これがあると失敗したテストをretryしてくれる。
失敗するテストが多い時にこのフラグを付けると時間が余計にかかる。
PARALLEL_WORKERS: 並列実行する数を指定する変数。1の場合は並列実行しない。

何回かやったら通るのか?という考えを持っていたのは、「ローカルテスト」や「Flakyなテスト」というものに理解がなかったからでした。調べてはいましたが...
(その部分については後半のテストの考え方をご参照ください。)

flaky testとは何かというと、コードにまったく手を触れていないにもかかわらず、成功したり失敗したりするテストのことです。
自動テストに対して信頼がだんだん失われていく時とは - 和田卓人 - ログミーTech

最終的に、通らないテストが3つぐらいになったので、もう何回かやったら全部通るのではないかと思いましたが、そこからエラーがバンバン出るようになりました。

エラー多発前のテスト結果

あと3つ通れば...

$ CI=1 PARALLEL_WORKERS=1 bin/rails test:all
~ 省略 ~
Finished in 3457.581514s, 0.4659 runs/s, 1.2682 assertions/s.
1611 runs, 4385 assertions, 3 failures, 0 errors, 2 skips

エラー多発後のテスト結果

コマンド実行直後からエラーがバンバン出る状態。

$ CI=1 PARALLEL_WORKERS=1 bin/rails test:all
~ 省略 ~
Finished in 3516.373300s, 0.4581 runs/s, 0.8261 assertions/s.
1611 runs, 2905 assertions, 38 failures, 752 errors, 2 skips

発生したエラーの全てにNil location provided. Can't build URI. (ActionView::Template::Error)の記載があり、何回やっても752個のエラーが検出されるようになりました。「これもFlakyなテストなのだろうか？もうわけわかんねぇ...」と思ったので、FBCのQ&Aで状況報告の投稿をして助けを求めました。

調査

Q&Aで何回かやりとりをさせていただき、伝わらない部分があったのでメンターさんとビデオ通話で一緒に原因調査をさせていただけることになりました。

エラー内容

Nil location provided. Can't build URI. (ActionView::Template::Error)

確認したこと

yarn installで npm パッケージがきちんとインストールできているか。
bundle install は行っているか。
CI のテストは通っているか。
RAILS_ENV=test rails assets:precompileを実行して問題なくコンパイルが成功するか？
imagemagick が intel 版だったので mac 版に変更。
リサイズ自体がきちんと機能しているかを確認。
デバッグしてログを出力
マシンスペックの確認。私のマシンはチップ：Apple M1, メモリ：16 GB で問題ないということでした。

デバッグしたり、関係ありそうなことを一つ一つ確認して潰していきました。

yarn installで npm パッケージがきちんとインストールできているか。

Node.jsの代表的なパッケージの管理ツールには、npm と yarn があるが、プロジェクトによってどちらを使うかが決まっている。
確認方法：bin/setup ファイルにsystem! 'bin/yarn'という記載があり yarn を使うということがわかる。この場合、npm install の結果は関係がない。

yarn install の実行結果

$ yarn install
yarn install v1.22.17
warning ../../package.json: No license field
[1/5] 🔍  Validating package.json...
[2/5] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.22s.

異常なし。

CI のテストは通っているか。

CI のテスト結果

Success!!

RAILS_ENV=test rails assets:precompile を実行して問題なくコンパイルが成功するか？

RAILS_ENV=test rails assets:precompile の実行結果

public/assets 下に209個のファイルが作成された。Git の変更は210個。正常に実行されたことが確認できればこの変更は削除して良いし、public/assets が .gitignore ファイルに記載されていればこの変更は出ない。
(後日 .gitignore ファイルに記載するためのPRが作成されました。)

$ RAILS_ENV=test rails assets:precompile
yarn install v1.22.17
warning ../../package.json: No license field
[1/5] 🔍  Validating package.json...
[2/5] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.18s.
I, [2023-11-24T07:15:50.502974 #10379]  INFO -- : Writing /Users/kw/bin/bootcamp/public/assets/manifest-1abee1fd73fc0752f6b1b9ff7228ddd5a78e08474f73e235db5047c62b437427.js
~省略~
Everything's up-to-date. Nothing to do

異常なし。

$ git status
On branch chore/fix-slim-lint-issues-6994
Untracked files:
  (use "git add <file>..." to include in what will be committed)
    public/assets/

デバッグしてログを出力

デバッグの内容

元のコード

  def avatar_url
    default_image_path = '/images/users/avatars/default.png'

    if avatar.attached?
      avatar.variant(resize: AVATAR_SIZE).processed.url # urlがnil
    else
      image_url default_image_path
    end
  rescue ActiveStorage::FileNotFoundError, ActiveStorage::InvariableError
    image_url default_image_path
  end

デバッグ

def avatar_url
  default_image_path = '/images/users/avatars/default.png'
  
  if avatar.attached?
    my_variant = avatar.variant(resize: AVATAR_SIZE)
    if my_variant.processed?
      # puts "existing-image: #{my_variant.send(:record)}/#{my_variant.image.url}"
      my_variant.process unless  my_variant.image.url
      # puts "existing-image2: #{my_variant.send(:record)}/#{my_variant.image.url}"
    else
      my_variant.process
      # puts "processed?: #{my_variant.processed?}"
      # puts "created-image: #{my_variant.image.url}"
    end
    puts "existing-image: #{my_variant.image.inspect}/#{my_variant.image.url}"
    my_variant.image.url
    # my_variant
    # avatar.variant(resize: AVATAR_SIZE).processed.url
  else
    image_url default_image_path
  end
rescue ActiveStorage::FileNotFoundError, ActiveStorage::InvariableError
  image_url default_image_path
end

prosessメソッド：画像をリサイズしたファイルが保存され、DBにも variation_digest が保存される。
variation_digest：リサイズしたファイルの情報が含まれている。

デバッグして出力したログの一部

existing-image: #<ActiveStorage::Attached::One:0x00000001170d58a0 @name="image", @record=#<ActiveStorage::VariantRecord id: 15341, blob_id: 50006297, variation_digest: "JO2GMsBpNz8fyJD0VI9jyWmfQoA=">>/http://127.0.0.1:53601/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDVG9JYTJWNVNTSWhiM2h6T1hveU1UaGhaSEJxY21vME5UQnhaVzgyWjNreU56SnRiZ1k2QmtWVU9oQmthWE53YjNOcGRHbHZia2tpUTJsdWJHbHVaVHNnWm1sc1pXNWhiV1U5SW10dmJXRm5ZWFJoTG5CdVp5STdJR1pwYkdWdVlXMWxLajFWVkVZdE9DY25hMjl0WVdkaGRHRXVjRzVuQmpzR1ZEb1JZMjl1ZEdWdWRGOTBlWEJsU1NJT2FXMWhaMlV2Y0c1bkJqc0dWRG9SYzJWeWRtbGpaVjl1WVcxbE9nbDBaWE4wIiwiZXhwIjoiMjAyMy0xMS0yM1QxMTo0NjoxNS42MTRaIiwicHVyIjoiYmxvYl9rZXkifX0=--1bf0bbbbc9e5799e4585a96eb1df16572545e961/yamada.png
existing-image: #<ActiveStorage::Attached::One:0x0000000100981920 @name="image", @record=#<ActiveStorage::VariantRecord id: 15342, blob_id: 300959870, variation_digest: "IkByHq+XI5DNYzeXPjUKpqesijM=">>/http://127.0.0.1:53601/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDVG9JYTJWNVNTSWhZV3Q1YzNBeE9YRmpkREZ2WVRsd05HUjBkbkp3ZFhCM05uVnhlQVk2QmtWVU9oQmthWE53YjNOcGRHbHZia2tpUVdsdWJHbHVaVHNnWm1sc1pXNWhiV1U5SW0xaFkyaHBaR0V1YW5Cbklqc2dabWxzWlc1aGJXVXFQVlZVUmkwNEp5ZHRZV05vYVdSaExtcHdad1k3QmxRNkVXTnZiblJsYm5SZmRIbHdaVWtpRDJsdFlXZGxMMnB3WldjR093WlVPaEZ6WlhKMmFXTmxYMjVoYldVNkNYUmxjM1E9IiwiZXhwIjoiMjAyMy0xMS0yM1QxMTo0NjoxNS42NzhaIiwicHVyIjoiYmxvYl9rZXkifX0=--405eac42fc47992f3a1b222f9090d625eb4b7e7f/sato.jpg
existing-image: #<ActiveStorage::Attached::One:0x000000011119f9d0 @name="image", @record=#<ActiveStorage::VariantRecord id: 15342, blob_id: 300959870, variation_digest: "IkByHq+XI5DNYzeXPjUKpqesijM=">>/http://127.0.0.1:53601/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDVG9JYTJWNVNTSWhZV3Q1YzNBeE9YRmpkREZ2WVRsd05HUjBkbkp3ZFhCM05uVnhlQVk2QmtWVU9oQmthWE53YjNOcGRHbHZia2tpUVdsdWJHbHVaVHNnWm1sc1pXNWhiV1U5SW0xaFkyaHBaR0V1YW5Cbklqc2dabWxzWlc1aGJXVXFQVlZVUmkwNEp5ZHRZV05vYVdSaExtcHdad1k3QmxRNkVXTnZiblJsYm5SZmRIbHdaVWtpRDJsdFlXZGxMMnB3WldjR093WlVPaEZ6WlhKMmFXTmxYMjVoYldVNkNYUmxjM1E9IiwiZXhwIjoiMjAyMy0xMS0yM1QxMTo0NjoxNS42OTVaIiwicHVyIjoiYmxvYl9rZXkifX0=--bca229fe940c5489f021d6393cfe7db7944096af/sato.jpg

解決

puts で上記のようにmy_variant.image.inspect を出力してログを確認すると、DB の id で極端に古いものが含まれている、、怪しい、というところから DB でテーブルを確認すると古いレコードが残っていました!!

$ RAILS_ENV=test rails db -p
psql (14.9 (Homebrew), server 14.0)
Type "help" for help.

bootcamp_test=# SELECT * from active_storage_variant_records;
  id   |  blob_id   |       variation_digest
-------+------------+------------------------------
 13681 |  801588450 | IkByHq+XI5DNYzeXPjUKpqesijM=
 13682 |   50006297 | JO2GMsBpNz8fyJD0VI9jyWmfQoA=
 13683 | 1005505682 | JO2GMsBpNz8fyJD0VI9jyWmfQoA=
(3 rows)

よってレコードを削除。(後日 PRが作成され、こちらの作業は不要になっています。)

bootcamp_test=# delete from active_storage_variant_records;

その後、テストを実行するとエラーは出なくなりました。

$ PARALLEL_WORKERS=1 bin/rails test:all

原因

Activestorageが古いレコードを認識すると、(variation_digestが同じであれば）既にリサイズしたものと誤認して、実ファイルが存在しないので url が nil になってエラーが起きていました。同じファイルを同じようにリサイズすると variation_digest が同じになるのでは、という見解です。

fixturesには active_storage_attachments と active_storage_blobs のymlファイルしかなく、

active_storage_attachments → 古いデータは削除される
active_storage_blobs → 古いデータは削除される
active_storage_variant_records → 古いデータは残ったまま

という状態になり、DB上のデータに不整合が発生するという状況になっていました。
fixtures に空の yml ファイルを用意しておくことで、テスト毎にレコードが残っていない状態でテストを開始することができるようになります。
PR: テスト実行時の"ActionView::Template::Error: Nil location provided. Can't build URI."エラーを回避する #7074

active_storage_variant_records について
2 セットアップ - Active Storage - Rails ガイド

テストの考え方

ビデオ通話時、絶好の機会だと思い、疑問に思っていたことをたくさん質問させていただきました。
（以下は考え方の一つであって、現場によって変わるのかもしれません。）

bin/rails test:all を実行する必要があるのか。

行うべきではあるが、、以下の理由から現実的ではない。

テストには時間がかかるので、開発のテンポが遅くなる。
マシン（PC）の性能に依存し、個人のマシンはそれぞれ違う。人によってうまくいくときもあればうまくいかないときもあり、何回やっても失敗する可能性もある。テストが追加されて増えるほど影響は大きくなる。

ではどのように実施するのが良いのか

新規追加の機能、修正した部分に関係していると思われるテストを行う。ただ、システムは複雑なので全然関係ないところでテストが転ける場合もある。ダメなのは、関係するテストがあるのに行わないこと。

テスト実行時は、

マシンがテストだけに集中できるよう、使わないブラウザやアプリは全て閉じ、CPUとメモリを開放する。
Macにデフォルトで入っているアクティビティモニタでメモリとCPUの動きを把握できる。

Flaky なテスト

ローカルで Flaky なケース

落ちたり通ったりして安定しないテスト。
個々人のマシンに依存するので、ローカルテストでは基準が作れない。

CI で Flaky なケース

例えば、3回に1回ぐらい落ちたり、何回かやれば通るというような場合。

基準にするのは

ローカルテストではなく CI を基準にする。

修正後、思いがけないところが壊れることはよくある。当たりをつけても違うテストが転けることもある。
CIで落ちたときにジャッジする。自分の修正に関係あるのか Flaky であるのか。自分のした修正に関係ありそうなら修正する。関係なさそうなら落ちたテストをローカルで実行して（何回かやって）みて、ローカルがパスしたら CI は Flkay。ローカルもCIも同じ落ち方なら修正。

今回のエラーでは CI は通っていましたが、途中からローカルで何回テストを実行しても752個のエラーが発生するようになりました。ということは Flaky ではなく、修正する必要があったのだと思います。 bin/rails test:allではなく範囲を絞ると通ったり通らなかったりするものもあったとは思いますが、Nil location provided. Can't build URI. (ActionView::Template::Error)の数は多かったです。

後日談として、受講生の方の簡単なイシューのレビューで、関連するファイルを一つテストしたのですが綺麗に通りました。

MacBook-Pro: ~/bin/bootcamp (feature/change-QA-title-format =)
$ bin/rails test test/system/questions_test.rb
Running via Spring preloader in process 7112
Run options: --seed 55144

# Running:

..........................................
[Minitest::CI] Generating test report in JUnit XML format...


Finished in 89.827101s, 0.4676 runs/s, 1.0465 assertions/s.
42 runs, 94 assertions, 0 failures, 0 errors, 0 skips

テキスト形式で質問するとき

一部分のスクショだけ切り取ったものを載せても、どこのファイルで起きているかがわからない。git の変更が210個出ましたというのであれば、git status の結果も一緒に記載するとわかりやすいかも。
エラーの一部分をテキストで貼り付ける場合も、その前後関係がわからないので安易に端折らない。GitHub Gist などを使って広範囲を載せると良いかも。
端折る場合はその旨を記載する。記載がないと、そのように表示されたエラーに見えてしまう。
一貫したリポジトリで説明する。あるときは clone A で、あるときは clone B で説明するのは同じブランチであったとしても一貫性がない。
エラーの再現手順も記載する。PRにも変更確認方法が記載されている。

最後に

わからないことが複数あると、それをテキストでどのように伝えれば良いのか難しく感じました。
今回はチーム開発に入りたてということもあったのか、メンターさんに全面的にフォローしていただき感謝しかありません。確かその日は祝日で、にも関わらず半日近くお付き合いいただき、エラーが消えたときは感動でした。解決したときに、「このようなエラーはよく出るものですか？」というような感じの質問をしたのですが、エラーを解決しないといけない場面はよくあって、「名探偵コナンのように謎を解決に導いていくことが、プログラマーの醍醐味でもある」というようなお言葉をいただきました。今回であれば、Active Storage のソースコードを読んだり、調べ直すことで、自分の中に知識として蓄えていくのだそうです。考えて、調べて、試して、考えて、調べて、試して。
自分で解決できるようになりたいです！
最後までお読みいただきありがとうございました。

banban2562’s blog

テストとは。最初のイシューでエラーに遭遇した話。

目次