Rails 콜백의 함정: after_save 문제와 after_commit 해결법 (Rails 5 수정 포함)

ActiveRecord 콜백은 모델의 생명주기 여러 단계에서 코드를 실행할 수 있게 해주는 아주 편리한 기능입니다.

예를 들어 Q&A 사이트를 운영하면서 모든 질문을 검색할 수 있는 기능을 만들고 싶다고 가정해 봅시다. 질문에 변경 사항이 생길 때마다 ElasticSearch 같은 검색 엔진에 해당 내용을 색인(indexing)해야 할 겁니다. 색인 작업은 시간이 걸리고 급한 일이 아니므로 Sidekiq를 이용해 백그라운드에서 처리하는 것이 자연스러운 선택입니다.

이럴 때 after_save 콜백이 딱 맞아 보입니다! 그래서 모델에 다음과 같이 코드를 작성하게 됩니다.

class Question < ActiveRecord::Base
  after_save :index_for_search

  # ...

  private
  
  def index_for_search
    QuestionIndexerJob.perform_later(self)
  end
end

class QuestionIndexerJob < ActiveJob::Base
  queue_as :default

  def perform(question)
    # ... 질문을 색인합니다 ...
  end
end

코드는 잘 동작하는 것처럼 보입니다. 하지만 작업을 대량으로 큐에 쌓기 시작하면 다음과 같은 에러가 나타나기 시작합니다.

2015-03-10T05:29:02.881Z 52530 TID-oupf889w4 WARN: Error while trying to deserialize arguments: Couldn't find Question with 'id'=3

Sidekiq은 실패한 작업을 재시도하고, 다음 시도에는 아마 성공할 겁니다. 그래도 뭔가 이상합니다. 방금 저장한 질문을 대체 왜 Sidekiq가 찾지 못하는 걸까요?

프로세스 간 경쟁 상태(race condition)

Rails는 after_save 콜백을 레코드가 저장되자마자 곧바로 호출합니다. 하지만 데이터베이스 트랜잭션이 커밋되기 전까지는 그 레코드를 Sidekiq가 사용하는 것과 같은 다른 데이터베이스 커넥션에서 조회할 수 없습니다. 즉, Sidekiq가 질문을 찾으려는 시점이 '저장 직후'부터 '커밋 직전' 사이에 끼어들 가능성이 있는 것이죠. 레코드를 찾지 못한 Sidekiq는 결국 에러를 내뱝니다.

이 문제는 너무 흔해서 Sidekiq 공식 FAQ에도 등재되어 있을 정도입니다. 다행히 해결 방법은 아주 간단합니다.

after_save 대신에:

class Question < ActiveRecord::Base
  after_save :index_for_search

  # ...
end

after_commit을 사용하세요:

class Question < ActiveRecord::Base
  after_commit :index_for_search

  # ...
end

이제 작업은 Sidekiq이 해당 모델을 실제로 조회할 수 있는 시점 이후에야 큐에 등록됩니다.

정리하면, 백그라운드 작업을 큐에 넣거나 방금 변경한 내용을 다른 프로세스에 알려야 할 때는 반드시 after_commit을 사용해야 합니다. 그렇지 않으면 상대 프로세스가 방금 건드린 레코드를 찾지 못해 에러가 발생할 수 있습니다.

하지만 아직 하나의 문제가 더 남아 있습니다…

여러 after_save 훅을 after_commit으로 교체했습니다. 모든 게 잘 동작하는 것 같네요. 이제 변경 사항을 커밋하고 집에 갈 준비가 된 걸까요?

먼저 테스트를 돌려봐야겠죠:

require 'test_helper'

class QuestionTest < ActiveSupport::TestCase
  test "A saved question is queued for indexing" do
    assert_enqueued_with(job: QuestionIndexerJob) do
      Question.create(title: "Is it legal to kill a zombie?")
    end
  end
end

  1) Failure:
QuestionTest#test_A_saved_question_is_queued_for_indexing [/Users/jweiss/Source/testapps/after_commit/test/models/question_test.rb:7]:
No enqueued job found with {:job=>QuestionIndexerJob}

어라? 테스트에서 작업이 큐에 등록됐어야 하는 것 아닌가요? 대체 무슨 일이 일어난 걸까요?

기본적으로 Rails는 각 테스트 케이스를 자체 데이터베이스 트랜잭션으로 감쌉니다. 덕분에 테스트 속도가 크게 빨라집니다. 테스트 중 발생한 모든 변경 사항을 되돌리는 데 데이터베이스 명령 단 한 번이면 충분하기 때문입니다.

하지만 이 때문에 after_commit 콜백이 실행되지 않습니다. after_commit 콜백은 가장 바깥쪽 트랜잭션이 커밋될 때만 실행되기 때문입니다.

테스트 케이스 안에서 save를 호출하면 트랜잭션이 커밋되긴 하지만, 그것은 이제 두 번째로 바깥쪽 트랜잭션일 뿐입니다. 따라서 after_commit 콜백은 기대한 시점에 실행되지 않으며, 콜백 내부의 동작도 테스트할 수 없게 됩니다.

다행히 이 문제 역시 쉬운 해결책이 있습니다. Gemfile에 test_after_commit 젬을 추가하세요:

group :test do
  gem "test_after_commit"
end

이제 after_commit 훅은 끝에서 두 번째 트랜잭션이 커밋된 후에 실행됩니다. 바로 여러분이 원래 기대했던 동작이죠.

"이상하네. Rails에 기본으로 들어 있는 콜백을 테스트하려고 별도의 젬까지 설치해야 한다니? 당연히 자동으로 되어야 하는 거 아닌가?"라고 생각하실 수 있습니다.

맞습니다. 정말 이상한 구조입니다. 하지만 오래 이상하지는 않을 겁니다.

Rails 5가 출시되면 test_after_commit에 대해 더 이상 신경 쓸 필요가 없습니다. 이 문제는 약 한 달 전 이미 Rails 코어에서 수정되었기 때문입니다.

실제로 저 역시 제 코드에서 after_commit을 매우 자주 사용합니다. 어쩌면 after_save보다 더 많이 쓰는지도 모르겠습니다! 물론 그 과정에서 문제와 낯선 엣지 케이스를 만나지 않았던 것은 아닙니다.

하지만 Rails 버전이 올라갈수록 이런 부분은 점점 개선되고 있습니다. 적절한 위치에 after_commit을 사용하기만 해도, 기묘하고 무작위적으로 발생하던 예외들이 더 이상 나타나지 않을 겁니다.