【Rails】StateMachineがコミットするタイミングがよくわからない説
2017-10-17 | カテゴリ >> Rails

Railsで鬼ハマったのでエントリ。
とあるモデルがあって、StateMachineで状態変更の際にメール通知する処理を実装していた。
ところが、そのメールの本文に入っているデータが、変更前の状態のレコードを参照している様子だったので困った。

この事象に1週間くらい悩みましたが、@5t111111さんに相談してみたところ何となく見えてきました。
本当にありがとうございます。明日の夜ステーキおごります。

問題となったソースコード

Lessonというモデルがあって、ユーザーが予約するとStateMachineの中で event :entry が実行されるようになっている。

  module Lesson::StateMachine
    extend ActiveSupport::Concern

    included do
      include AASM
   
      aasm column: :state, enum: true do
        state :open, initial: true
        state :entried
        (略) 
  
        event :entry do
          transitions from: [ :open, :deleted ], to: :entried, success: :use_ticket, guard: :has_  ticket?
        end

  (略)

    def use_ticket
  (略)
      self.required_ticket_number = trainer&.required_ticket_number # 消費チケットを保存
      save
      LessonMailer.user_entry(self, user, message).deliver_later
  (略)
    end
end

LessonMailer.user_entry(self, user, message).deliver_later の中身は以下の通りです。

class LessonMailer < ApplicationMailer
 (略)
  def user_entry(lesson, user, message)
    send_user(lesson, user, message)
  end

 (略)

  private
 (略)
      
    def send_user(lesson, user = nil, message = nil)
      @lesson = lesson
      @user = user || @lesson.user
      @message = message
      if @user
        mail(to: @user.email)
      else
  (略) 
      end
   end
end

:entry のsuccessで use_ticketが呼ばれるんですが、その中でメールを送信しています。
メールはActiveJobの deliver_laterを使っています。

今回発生した問題

send_user の中で @lesson には、save後のlesson が入ってくるはずだが
save前のデータが入っている(updateされていない)
そこで、
module Lesson::StateMachine側で、

save
logger.debug ' update done => ' + self.inspect
LessonMailer.user_entry(self, user, message).deliver_later

として、 send_user 前の中身を見てみると、実際はupdateされている
けど、 send_userの中で

def send_user(lesson, user = nil, message = nil)
  @lesson = lesson
  logger.debug @lesson.inspect

としてみると、 こちらにはupdate前のレコードの内容が出力される。

具体的には、こう
save直後のログ

D, [2017-09-06T11:17:58.783084 #29582] DEBUG -- : [571e8575-3d37-49f1-a1eb-ebe4645a4594] update done =>  #<Lesson id: 2034, state: "entried", user_id: 3, required_ticket_number: 1, created_at: "2017-09-06 01:35:55", updated_at: "2017-09-06 02:17:58" (略) >


send_user内のログ

D, [2017-09-06T11:18:03.789407 #29583] DEBUG -- : [ActiveJob] [ActionMailer::DeliveryJob] [e4c9bc11-4a49-4e3a-974c-c3ba6aebfb5b] #<Lesson id: 2034, state: "open", user_id: nil, required_ticket_number: 0, created_at: "2017-09-06 01:35:55", updated_at: "2017-09-06 01:35:55" (略) >

state がupdate前の状態になっているのがわかった。
というか、 created_at と updated_at が同じなので普通に更新されていない様子

ちなみに、production, staging, development 全部でこの事象が発生しました。
毎回発生するかというと、実はそうではなくて80%くらいの確率で発生しました。

あと、deliver_later ではなくて deliver_now にしてみたらこの事象は発生しませんでした。
よってActiveJobがSidekiqにqueueを入れるタイミングなどが絡んできそう。

いろいろ試してみる

周りの人にも聞いてみて、まず以下の様な事を試してみました

1:reload してみる

save
reload
user.reload
LessonMailer.user_entry(self, user, message).deliver_later

を試してみました => 結果ダメ

2: save! にしてみる

save!
LessonMailer.user_entry(self, user, message).deliver_later

をためしてみました => 結果ダメ

3: save のあとにsleepしてみる

save
sleep(5)
LessonMailer.user_entry(self, user, message).deliver_later

をためしてみました => 結果ダメ

4: lessonをidで渡して send_user() の中でfindさせる

save
LessonMailer.user_entry(self.id, user.id, message).deliver_later

として、

class LessonMailer < ApplicationMailer
 (略)
  def user_entry(lesson_id, user_id, message)
    send_user(lesson_id, user_id, message)
  end

 (略)

  private
 (略)
      
    def send_user(lesson_id, user_id = nil, message = nil)
      @lesson = Lesson.find(lesson_id)
      @user = User.find(user_id) || @lesson.user
      @message = message
      if @user
        mail(to: @user.email)

こうしたところログを見るに、
ちゃんとsaveの際にlessonをUPDATEする処理が記録されており、
かつ、
send_userの中でLesson.find する処理(SELECTが発行されている)が行われている
のにもかかわらず
SELECTしてきたデータがUpdate前のレコードになっていました。 
・・なんでぇ・・・・(;´Д`)

5: transactionを使ってみる

Lesson.transaction do
  save
end

ともしてみましたが、結果は変わりませんでした。

saveしてもコミットまで行ってない説

そんなこんなしている最中、@5t111111先生に
send_user 内でfindする処理の前にsleep() を入れる
もしくは
deliver_later(wait: 5.seconds) を使ってみる
を試すようアドバイスいただき、両方試したところ100%成功するようになりました。
若杉さんて神なの?

また、saveしてもコミットされてDBの情報が更新されていない説を指摘いただき
save後にsleep(60) くらいの長めのヤツを入れておき、そのスキを狙って mysql にログインしておいたターミナルから直接DBにSELECTしてみた

Rails方のログ(tail -f 的なヤツで)

save => 
SQL (0.6ms)  UPDATE `lessons` SET `state` = 2, `user_id` = 3, `updated_at` = '2017-09-06 08:08:05' WHERE `lessons`.`id` = 2044

と出ているのを確認した後、mysql側でselectした結果

mysql>  SELECT  `lessons`.* FROM `lessons` WHERE `lessons`.`id` = 2044 LIMIT 1 \G;
*************************** 1. row ***************************
                    id: 2044
                 state: 1
            trainer_id: 7
               user_id: NULL
required_ticket_number: 0
            created_at: 2017-09-06 02:56:40
            updated_at: 2017-09-06 02:56:40
    (略)
1 row in set (0.00 sec)

(state も updated_ate も変わっていないぞ・・・)
やはりどうもコミットされていない様子です。
あと、save! としてから sleep中にmysqlを覗いてみたりもしましたが、
! をつけても更新されていませんでした。

とうわけで、まず前提として以下の2点の勘違いをしていた事が分かりました
・AASMでtransition を変更してもDBまで更新してから success のコールバックを実行しているわけではない。
・コールバックの中でレコードをUpdateしても即座に実際のDBが書き換わらない。
言われてみれば確かにRailsnログで commit transaction的なログが出るはずなのに出ていない

というわけで、
コミットしなくてもdeliver_now はSidekiqに処理を渡さないからUpdate仕掛り中のオブジェクトを正しく渡すことができる
けど、
Sidekiqとかの非同期処理が挟まると(ActiveJobかもしれませんが)DBの現在の状態に依存する
という事っぽい。
一般的に言うレースコンディションが発生していたっていうことですね。

この状態遷移(lesson.entry!)を呼び出した後はDBの中身は既に更新されているか?

調べてみる為に、Controller内にもSleep(60)を仕込んでそのスキにMySQLを直接覗いてみました。
さすがに更新されていてほしい。

def create     
  @lesson.attributes = lesson_params
  begin        
  if @lesson.entry!
    sleep(60)
    redirect_to complete_users_reserf_path(@lesson)
  else    

見たところ、案の定更新されていました

mysql>  SELECT  `lessons`.* FROM `lessons` WHERE `lessons`.`id` = 2049 LIMIT 1 \G;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    136424
Current database: fizit_staging
*************************** 1. row ***************************
                    id: 2049
                 state: 2
               user_id: 3
required_ticket_number: 1
            created_at: 2017-09-06 08:47:05
            updated_at: 2017-09-07 03:12:53
  coupon_ticket_number: 0
1 row in set (0.01 sec)

というわけで、今言える事は
StateMachine内でコールバックで実行しているメソッドが終わればDBの書き換えが実施される
ようです。

どう直すか?

まずdeliver_laterでSidekiqに渡したキューの発火を遅らせればまず成功するのですが、無駄にsleepとか入れるのダサいので他の案を考えます。

案1

AASMの他のコールバックのイベントにメール処理のロジックを移せないだろうか?
参考:https://github.com/aasm/aasm#lifecycle

今は event の success で処理していますが
event : after というのもあるらしいので、この時点では既にレコードがUpdateされてコミットされている事を期待してみます。

早速 メール送信処理部分をsend_confirmation_mail メソッドに分離して after で 呼び出してみます

event :entry do
  transitions from: [ :open, :deleted ], to: :entried, success: :use_ticket, guard: :has_ticket?, after: :send_confirmation_mail
end

def send_confirmation_mail
  LessonMailer.user_entry(self.id, user.id, message).deliver_later
end

結果:ダメ.. orz
afeter を呼び出してる時もまだDB反映していなかったです。
こう考えるとAASMはstateを変更しおえて全ての処理を終えるまで実DBの更新をしないかも。
(ソース見ればいいじゃんて言われればそれまでなんですが、私の実力が・・(;´Д`))

案2

StateMachineの中でメール送信ロジックを入れるのを辞めて順当にコントローラ側で処理する。
だって、今更なんですがStateMachineのコールバックの中にビジネスロジック書くのって微妙くないですか?

def create
  @lesson.attributes = lesson_params
  begin
  if @lesson.entry!
    LessonMailer.trainer_entry(@lesson).deliver_now
    LessonMailer.user_entry(@lesson).deliver_now
    Admins::Mailer.lesson_entry(@lesson).deliver_now

結果:うまくいった( ´∀`)

余談ですが、そもそもDBの更新処理も終わっているので id で渡す必要もなくなりました。
このコードを書いた人はもういないんですが(この世にはいるはず)これってAASMのコールバックをどうしても使ってみたくて最初の様な感じに書いたんじゃないかな
どうだろう。。・ω・;;
けど、地味にスーパーハマったので原因がわかって嬉しい。

おわり

 

 

Share on FacebookShare on Google+Tweet about this on TwitterShare on LinkedIn
2017-10-17 | カテゴリ >> Rails 

関連記事

Comment





Comment



*