sidekiqをバージョンアップしたらsidekiq-statisticがエラーになったが解消した話 - ホワイトヘルスケア

概要
動作環境
はじめに
発生した現象と調査について
まとめ / 感想
採用情報

概要

ruby 3.1 系から 3.2 系にバージョンアップしたら、sidekiq-statisticでエラーが発生するようになった。
sidekiqのバージョンアップに伴い、sidekiq-statisticが期待する I/F が変わったため、エラーが発生した。

動作環境

ruby 3.1 系から 3.2 系にバージョンアップ
- sidekiq6 系から 7 系にバージョンアップ
sidekiq-statistic導入済み

はじめに

ホワイトヘルスケアエンジニアの林です。

本記事は、 ruby 3.1 系から 3.2 系にバージョンアップした際、sidekiq-statisticがエラーが発生した時の話になります。

発生した現象と調査について

事の始まり

弊社は Ruby on Rails を使ったアプリを開発しており、sidekiqを使用した job で処理を行なうロジックがあります。また、開発補助のためsidekiqの統計情報をグラフィカルに確認できるsidekiq-statisticという gem も導入しています。

アプリは ruby 3.1 系を使用して開発していましたが、脆弱性対応もあり、ruby 3.2 系にバージョンアップすることになりました。

それに伴い、使用していた gem のバージョンアップも同時に実施しました。

発生した現象

sidekiqの job 実行時にエラーが発生し job が失敗するようになりました。sidekiqの UI 上から確認できたエラーログは以下でした。

NoMethodError: undefined method `value` for 300:Integer Processor (以下略

調査

エラーの原因はバージョンアップではあるのは確かでしたが、どこで何が起こりエラーになったのかわからなかったため、順番にエラーの調査を行っていきました。

1. バージョンアップ前後での rspec の実行状況

弊社は rspec でテストを書くことになっており、今回エラーとなったsidekiqの job が実行している class に対してもテストが存在していました。

そこで、まず rspec がバージョンアップ前後で失敗しないか確認しました。バージョンアップ直後にも全体を通して実行し、エラーが発生していないことは確認はしていましたが、ランダム値による突発的な発生なども考えられるため、エラーが起こった job を何度か実行してみました。しかし、rspec 上では再現しませんでした。

2. job の内容の確認

次に、job の内容について調査しました。

job の挙動をざっくりと説明すると、DB のテーブルコピーを行う、というものです。エラー発生時の環境と rspec 実行時の環境とでは、DB 内のデータの作り方が異なる(rspec では FactoryBot を使ってダミーデータを投入する)ため、そこで差が出たのかと考えました。前述の観点でコードを確認しましたが、特にデータの作り方で何か変わるようなロジックはありませんでした。

また、rails のコンソール(rails c)上で job を直接実行したところ、エラーが発生しなかったため、 job ではなく別のところに原因があると予測しました。

エラーの原因の特定

前述の調査の他にも、google で検索をかけたり等行っていましたが、原因の特定に至らず手詰まり状態になっていました。

そこで、エラーメッセージ前後のログの内容を確認することにしました。前述したエラーログの前後に、以下のログも出力されていました。これは、「hmsetが deprecated である」旨のメッセージであり、エラーになっていたわけではありませんが、このログを元にsidekiq-statistic-1.4.0/lib/sidekiq/statistic/middleware.rbを確認してみることにしました。

worker  | [sidekiq#5788] Redis has deprecated the `hmset`command, called at ["/usr/local/bundle/gems/sidekiq-statistic-1.4.0/lib/sidekiq/statistic/middleware.rb:42:in `block (2 levels) in save_entry_for_worker'"]

sidekiq-statistic-1.4.0/lib/sidekiq/statistic/middleware.rbを調べたところ、deprecated に該当しているコードが確認できました。それとは別に、問題の発端となったエラーに出てきたvalue method を使っているコードも発見しました。

参考リンク：https://github.com/davydovanton/sidekiq-statistic/blob/v1.4.0/lib/sidekiq/statistic/middleware.rb

コード抜粋

if times_list_length.value > max_timelist_length
  redis.ltrim(timeslist_key, 0, (max_timelist_length * 0.75).to_i)
end

このコードに対しログを仕込んでみたところ、times_list_length.valueでエラーになっていることがわかり、エラーの発生源を突き止めることができました。

根本原因

根本的な原因は、sidekiqのバージョンアップにより、内部で使用している redis のクライアントがredisからredis-clientに変わり、I/F も変わってしまったためでした。そのため、sidekiq-statisticがその変更に対応できていなかったため、エラーが発生してしまったということです。

本体コードを簡素化した以下のコードを実行してもクラスや I/F が変わっていることが確認できます。

Sidekiq.redis do |redis|
  r = nil
  redis.pipelined do
    r = redis.lpush "timeslist_key", 0.12132123
  end
  p r.class
  p r
end

# sidekiq v6 の場合
# => Redis::Future
# => <Redis::Future [:lpush, "timeslist_key", 0.12132123]>

# sidekiq v7 の場合
# => Integer
# => 1

対応策

対応方法としてはいくつかあると思いますが、他 gem との兼ね合いなども考慮した結果、該当 method をclass_evalを使って上書きすることで対応することとしました。こうすることで、他の gem への影響を最小限に抑えて対応することができました。

まとめ / 感想

今回調査した中で、色々と学ぶ点が多くあったと感じました。具体的には以下の通りです。

原因となったエラーメッセージ前後のメッセージも、エラー特定に役立つ
- エラーの原因が特定できたのは偶然性が高いと感じている
想定していないところでアップデートの影響が出ることもある
- アプリの挙動と直接関係ない gem で発生した
- rspec や API サーバとして確認する方法では捕捉できなかった
gem 管理リポジトリはhttps://rubygems.org/だが、そこに最新バージョンが登録されているわけではない
- sidekiq-statisticのバージョンは、rubygems.org(https://rubygems.org/)では 1.4.0 が最新であるが、github(https://github.com/davydovanton/sidekiq-statistic)では2.0.0が最新
- ただ、なぜこのような状態なのか、どちらを使うべきなのか、までは深く調査できていない

採用情報

Ruby on Rails を使った Whitehealthcare に興味のある方はこちらから https://whitehealthcare.co.jp/recruit/