Code Polaris Advent Calendar 2020 用記事です！！！！
Railsでお仕事して２年目@kaori_choと申します。
今年、callbackしているコードで大苦戦したため、そこで得た学びをシェアするために筆を執りました。
忙しい人への３行まとめ
- callback、実装１秒、デバッグ一生
- callbackでできることは、callbackでなくてもできます
- callbackには、無限回実行されても問題ない処理だけ書け！
結論、callbackを書くときは注意しようぜ！というお話です。特にチーム開発時は。
この記事では、まだcallback書いたことない方向けに、読みやすいようにアンチパターンの成り立ちから解説します。
すでにハマったことがある方向けには、じゃあどうしたらええねん？を一緒に考えるきっかけになれると嬉しいです！
目次
1.callbackとは？
2.アンチパターンの生まれ方
2-a.サンプルコードA callbackのない世界
2-b.サンプルコードB callbackで書いてみる
2-c.サンプルコードC callback、２重発火する
2-d.サンプルコードD 一生デバッグすることになる
2-e.A→B→C→Dで起きたことのまとめ
2-e.実際はもっと複雑だった...
3.結論：callbackの使い所
3-a.callbackの利用を制限する
3-b.callbackをチームで受け入れる
1.callbackとは？
Active Record コールバック
https://railsguides.jp/active_record_callbacks.html
早い話が、データを作成・更新したりする前後に、特定の処理を発火させることができる仕組みです。
callbackとコード上で記述されるわけではなく
class User < ApplicationRecord
before_save :hogemethod
after_update :fugamethod
...
end
のように記載されたものがcallbackです。
Active Recordが持っている機能でActiveRecord::Baseを継承しているクラスで利用できます。
2.アンチパターンの生まれ方
callbackが悪いとかイケてないとかいうつもりはまったくなく、適切に使えば強力な武器だと思うのですが
callback、仕込むのがあまりに簡単で、アプリケーション全体に影響及ぼすような顔してないのに、効果絶大なので
例えばこうしてコードが育つと、自然にアンチパターンになってしまうのでは？の例を書いて解説していきます。
2-a.サンプルコードA callbackのない世界
適当なUserというモデルがあります。
Userはid、名前、メアド、誕生日を持っているとしましょうか。
class User < ApplicationRecord
end
よくあるユーザー情報の更新処理があったとします。
ここでは、「ユーザー情報が更新されたときにログが残る」ようになっていたとします。
※ 途中出てくる ... は（略）として読んでください！
class UsersController < ApplicationController
...
def update
@user = User.find(current_user.id)
@user.assign_attributes(user_params)
@user.save
save_user_log # ログを残すよ！
redirect_to :back
end
private
# ユーザーが更新したらログを残すよ
def save_user_log
message = "#{@user.name}さんの情報が更新されたよ！"
UserLog.create(user_id: @user.id, log_message: message)
end
def user_params
params.require(:user).permit(:name, :email, :birthdate)
end
更新するとログが残ります。はい。
select * from user_logs;
+----+---------+------------------------------------------------+---------------------+---------------------+
| id | user_id | log_message | created_at | updated_at |
+----+---------+------------------------------------------------+---------------------+---------------------+
| 1 | 4 | pikachuさんの情報が更新されたよ！ | 2020-12-20 10:12:17 | 2020-12-20 10:12:17 |
+----+---------+------------------------------------------------+---------------------+---------------------+
2-b.サンプルコードB callbackで書いてみる
上記の処理をcallbackで書いてみます。
「更新された時にログを残す」のには、after_updateが使えそうです。
callbackは、controllerではなくmodel側に記載します。 これ超重要ポイント。（のちにハマる）
User modelに追記します。
class User < ApplicationRecord
...
after_update :save_user_log
private
def save_user_log
message = "#{self.name}さんの情報が更新されたよ！"
UserLog.create(user_id: self.id, log_message: message)
end
end
で、controller側はこうなる
save_user_logの処理がまったくいなくなりました。ここも重要ポイント！
class UsersController < ApplicationController
...
# ユーザのアカウント情報を更新
def update
@user = User.find(current_user.id)
@user.assign_attributes(user_params)
@user.save
redirect_to :back
end
...
end
更新してみると、ちゃんとログ保存されます。
mysql> select * from user_logs;
+----+---------+------------------------------------------------+---------------------+---------------------+
| id | user_id | log_message | created_at | updated_at |
+----+---------+------------------------------------------------+---------------------+---------------------+
| 6 | 4 | raichuさんの情報が更新されたよ！ | 2020-12-20 10:47:08 | 2020-12-20 10:47:08 |
+----+---------+------------------------------------------------+---------------------+---------------------+
うんうん、なんか良さそうな感じですね〜、callback！
無事にcallbackで書けました。よかったよかった。またひとつ賢くなったわ。
2-c.サンプルコードC callback、２重発火する
ところでアプリケーションは育っていくので、ある日こんな機能を追加することに。
「userテーブルに年齢カラムを追加してほしい」
あくまで外から入力できるのは誕生日で、年齢はデータとして保存するようです。
そう難しくないのでAとBの実装担当したのとは別の、Cさんにお願いしましょう。
Cさんは、年齢カラムを足し、誕生日から年齢を計算し、更新するようにcontrollerを修正しました。
class UsersController < ApplicationController
...
# ユーザのアカウント情報を更新
def update
@user = User.find(current_user.id)
@user.assign_attributes(user_params)
set_age # 誕生日から年齢を計算してセットしたい
@user.save
redirect_to :back
end
private
def set_age
if @user.age.nil? || @user.birthdate_changed?
birthday = Date.parse(@user.birthdate)
age = (Date.today.strftime('%Y%m%d').to_i - birthday.strftime('%Y%m%d').to_i) / 10000
@user.update(age: age)
end
end
def user_params
params.require(:user).permit(:name, :email, :birthdate)
end
end
なんか良さそうな気がします。（説明のためアレな処理になっているのはスルーしてくださいね。）
更新実行してみましょう。
お！ちゃんと年齢がはいっていますね！要件は満たせてそうです。
mysql> select id,name,birthdate,age from users where id=4;
+----+---------+------------+------+
| id | name | birthdate | age |
+----+---------+------------+------+
| 4 | pikachu | 1990-12-01 | 30 |
+----+---------+------------+------+
1 row in set (0.00 sec)
無事に機能がリリースされました。
（裏で何が起きているか、このときは誰も知らなかった。。。）
2-d.サンプルコードD 一生デバッグすることになる
年齢カラムの追加のリリースからしばらくたって、
「user_logがたまに２重で書き込まれているんだけど、なんでか調べてくれない？」
っていう調査依頼がきました。
今度は、たまたま手が空いていそうなDさんにお願いしてみましょう。
Dさんはまず、user_logsを見に行きます。
mysql> select * from user_logs;
+----+---------+------------------------------------------------+---------------------+---------------------+
| id | user_id | log_message | created_at | updated_at |
+----+---------+------------------------------------------------+---------------------+---------------------+
| 4 | 4 | pikachuさんの情報が更新されたよ！ | 2020-12-20 14:19:15 | 2020-12-20 14:19:15 |
| 5 | 4 | pikachuさんの情報が更新されたよ！ | 2020-12-20 14:19:15 | 2020-12-20 14:19:15 |
おや？確かに、同じタイミングで２重で登録されている？？？
しかも、２重で登録されるときとそうでないときがあるようだな・・・
仕方ない、コード読みに行くか。。
controllerをみると...Cさんが修正した時から時間が立ち、コードが育って、さらに色々な処理が挟まっています。
class UsersController < ApplicationController
...
# ユーザのアカウント情報を更新
def update
@user = User.find(current_user.id)
...
@user.assign_attributes(user_params)
...
...
Hoge.set_age(@user)
...
...
@user.save
redirect_to :back
end
private
def user_params
params.require(:user).permit(:name, :email, :birthdate)
end
end
うーん...？ここではログの保存処理していないのかなあ...？とRails１年目のDさんは先輩に助けを求め、callbackの存在を知ります。
そしてなぜかHogeクラスに移されていた処理も眺めて...
class Hoge
...
def set_age
if @user.age.nil? || @user.birthdate_changed?
birthday = Date.parse(@user.birthdate)
age = (Date.today.strftime('%Y%m%d').to_i - birthday.strftime('%Y%m%d').to_i) / 10000
@user.update(age: age)
end
end
end
カンの良い方はこの話の流れでもうわかったと思いますが、
実は年齢がnilの時と、誕生日を更新したときに、２重ログになります。
Hogeクラスの@user.update(age: age)
UsersControllerクラスの@user.save
で、２度userに対してupdateが走ります。
なのでmodelにあるafter_update :save_user_log が２回呼ばれてしまっています。
（そう書いてあるので当たり前といえばそうなのですが）
2-e.A→B→C→D ポイント解説
説明のため不自然な部分もあったかと思いますが、各サンプルコードで伝えたかったことは以下です。
- A: callbackで記述することは、controllerにcallbackを使わないで書くこともできる
- B: callbackはmodelに記載するため、controller側だけ見るとどんな処理をしているのかパッと見わからない
- C: 機能追加するときに、controller側しか見ないと、callbackの存在に気づかない場合がある（で、バグを生む）
- D: 意図せずcallbackが２重発火している場合の調査は、難易度が高くなる
2-f.実際はもっと複雑...
このように、はじめは便利！簡単！に実装できるcallbackですが、時が経ちコードが育つと、callbackの存在に気づきにくくなることが往々にしてあります。
上記はもちろん説明のためのコードなので正直「まだわかる」のですが
実際私はDさん立場で調査に入り、かなーり遠い処理でcallbackを呼ぶ処理を見つけるまで、かなり苦労しました。。こんな流れでした。
- 2重処理になっている条件の洗い出し（まだ何が悪いのか検討つかない）
- APIや非同期処理のところで２重送信になっているのでは？（callbackの可能性にまだ気づかず）
- userもcontrollerも巨大だったため、コード読み込むのに時間がかかる（うすうすcallbackと思いはじめる）
- userクラスで他にもたくさんのcallbackが仕込まれているため、callbackだとしても、どいつが犯人かわからん（callbackめっちゃ疑う）
- 最終的には同僚に借りたモンキーパッチを仕込んで、２重になっている時とそうでない時に呼び出されるメソッドを目grepで比較し、２つめのupdateを発見する
しかもこのcallback、一度埋め込んでしまうと引っ剥がすのが超大変です。
アプリケーション全体で、userに対してupdateしているすべての箇所で副作用がないかみないといけないため、複雑なシステムだと不可能に近い場合もあると思います。
（本当はここもとても頑張ったのですが、文字数と締切がアレなのでまたの機会に・・・！）
3.結論：callbackの使い所
苦労したのはわかった。大事なのはこれからどうするかだ。
個人的に考えたことをいくつか箇条書きにします。
3-a.callbackの利用を制限する
- ２回以上呼び出されても問題ない処理だけcallbackで書く
- すでに３箇所以上、同じ処理をしている箇所があり、今後も一定のペースで同じ処理が増える見込みがある場合
基本的にはもう、callbackでなくても書けるものは、callbackで書かない。以上。
冒頭に「無限回実行されても良い処理」と書いたのは、インパクトがあるのと、実際callbackのかみ合わせが悪いと、無限ループするからね。
callbackさん、書く時のコストは本当に低くて感動モノなんだけど、**何かあったときの調査・修正コストが高すぎる。**重要なビジネスロジックであるほど、特に１箇所でしか発火しないものは「それcallbackで書く必要あるんだっけ？」とレビューではつっこんで聞いていきたい。
3-a.callbackをチームで受け入れる
- callbackが1度だけ実行されることのテストを書く
- チームでcallbackに対する認識合わせをする
- まずcallbackからコードリーディングするよう教育する
使う場合はとにかく**「重複実行への対策」と、「後の人が行間読むのにかかる時間コストの削減」**に注力したらいいんじゃないかなと。callback、味方にすれば便利で素晴らしい機能なのでね。
例えば今回の例のログが２重で落ちちゃう、みたいなのは最悪別にいいとしても、「お客様に通知メール送る」「ポイントやクーポンを付与する」など２重で発火するとアカンものは、callbackで実装するのは避ける。どうしてもやる場合は実行回数をみるテストを書き、重複実行されたとき気づくようにする。
これだけかなと。
あとがき
こんなに長い記事を、最後まで読んでくださってありがとうございます！！
気になる点や・質問疑問あれば、遠慮なく @kaori_cho まで。
間違いもこっそり教えていただけると助かります。
ではでは、大変な２０２０年でしたが、来年も学びのある１年になりますように〜〜〜！