はじめに

みなさんこんにちは、クラウドワークスのじゅんてつです。

ここしばらく何かしらの更新(gem、ruby、rails)をしています。そんな中、rubyの更新をしてたらgemの依存関係で大変な目にあったので事例を紹介しようかと思います。

何があったのか

非同期メール送信処理の例外通知がすべての始まりでした・・・

アプリケーション上で例外が発生するとdelayed_jobにrollbar通知の処理を引き渡していたんですが(仕様)、gem ojとrollbarのバージョンの組み合わせに問題があり（原因）、rollbarの通知でojを呼び出す処理が無限ループを引き起こし（事象）、delayed_jobのプロセスを落としてしまう事象がありました。

Gem補足

delayed_job: メール送信やバッチ処理をバックグラウンドで非同期的に実行するためのgemです。 rollbar: 例外が発生するとリアルタイムに報告をあげてくれる、運用のためのgemです。 oj(Optimized JSON): JSONパーサー

対応のサマリ

この問題はojを3系に上げることで回避できました。

Ruby2.3のEOL対応としてRuby2.4への更新をしていたところ、ojを2.18以上に更新する必要がありました。ojを更新が原因で、delayed_jobのプロセスを落としてしまうことがデバッグして分かりました。

なぜoj最新版の3系ではなく2.18だったのか？

rollbar 2.15.0
delayed_job 4.0.6
oj 2.12.2
- update to 2.18.6
内製gem

当時は上記のバージョンで稼働していました。この状態から bundle update oj を実行すると内製のgemの依存関係に引きずられて2系の最新2.18.5に更新される状態でした。

spec.add_runtime_dependency "oj", "~> 2.12"

oj 2.18からRuby2.4に対応していたので要件は満たしていましたし、内製のgemを一緒に更新すると話がややこしくなるためまずは2.18に更新することにしました。

どんなエラー通知が飛んできたのか

ojを更新して間もなく、Datadogから「delayed_jobのプロセスが既定値の8件以下ですよ」という通知がslackに届きました。確認してみるとたしかにオンライン用に動いているはずのプロセスがすべて落ちていました。(2件ほど動いているのはバッチ処理用)

通知などのバックグラウンド処理が止まったままはまずいので、詳しい調査よりdelayed_jobのプロセスを回復させることを優先。ほぼ間違いなくoj更新が原因なのでリバート。

プロセスが落ちる原因はrollbarなのでは？

サーバのログを漁ったり、原因の切り分けをしたり、長い長い調査の末に「プロセスが落ちる原因はrollbarなのでは？」という仮説にたどり着きました。アプリケーション例外の発生はサーバログに残っているのに、その通知をするrollbarが動いておらず、その例外発生の時間を境にdelayed_jobのプロセスが落ちていたからです。

rollbarが非常に怪しいことがわかりましたが「どうしてdelayed_jobのプロセスが死ぬのか」を突き止める必要がありました。

まずは検証

rollbarの例外通知が有効化されているステージング環境で検証をしてみたところ、確かにrollbarが通知するタイミングで落ちていることが分かりました。ローカルの開発環境では通知の必要がないため無効化されていたため、有効化してデバッグできるようにしました。

動作確認すると、事象が再現。delayed_jobのプロセスが落ちました。

どうしてdelayed_jobのプロセスが死ぬのか(原因調査)

本当にrollbarなのか、実際に何が起こっているのかを確認するため bundle install されたgemに binding.pry を仕込んで動作させてみました。

Frame number: 0/77

From: /usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapter.rb @ line 26 MultiJson::Adapter.dump:

    24:       def dump(object, options = {})
    25:           binding.pry
 => 26:        instance.dump(object, cached_dump_options(options))
    27:       end

[1] pry(MultiJson::Adapters::Oj)> continue

Frame number: 0/78

From: /usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapters/oj.rb @ line 39 MultiJson::Adapters::Oj#dump:

    37:       def dump(object, options = {})
    38:     binding.pry
 => 39:  options.merge!(:indent => 2) if options[:pretty]
    40:         options[:indent] = options[:indent].to_i if options[:indent]
    41:         ::Oj.dump(object, options)
    42:       end

[1] pry(#<MultiJson::Adapters::Oj>)> continue

Frame number: 0/38

From: /usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapter.rb @ line 26 MultiJson::Adapter.dump:

    24:       def dump(object, options = {})
    25:           binding.pry
 => 26:        instance.dump(object, cached_dump_options(options))
    27:       end

[1] pry(MultiJson::Adapters::Oj)> continue

Frame number: 0/39

From: /usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapters/oj.rb @ line 39 MultiJson::Adapters::Oj#dump:

    37:       def dump(object, options = {})
    38:     binding.pry
 => 39:  options.merge!(:indent => 2) if options[:pretty]
    40:         options[:indent] = options[:indent].to_i if options[:indent]
    41:         ::Oj.dump(object, options)
    42:       end

[1] pry(#<MultiJson::Adapters::Oj>)> continue
rake aborted!
NoMemoryError: Too deeply nested.
/usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapters/oj.rb:41:in `dump'
/usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapters/oj.rb:41:in `dump'
/usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json/adapter.rb:26:in `dump'
/usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json.rb:139:in `dump'
/usr/local/bundle/bundler/gems/rollbar-gem-e3a35525d1b1/lib/rollbar/json.rb:18:in `block in dump'
/usr/local/bundle/gems/multi_json-1.13.1/lib/multi_json.rb:147:in `with_adapter'

原因はrollbarで、multi_jsonからのoj呼び出しがループしていました。 rollbarとojのバージョンの組み合わせに問題があったという結論。内製gemの依存関係を解消したうえで、oj 3系で試してみたところループが解消され一件落着となりました。