sidekiq ジョブ実行で時々想定していないデータ登録が発生する

f:id:mpiyok:20190111175748j:plain — schedule

Photo by rawpixel on Unsplash

ファイルをアップロード、その後の処理が時間がかかるので非同期にしていたRailsアプリで、謎のデータ登録が起こる（それも時々）

システムの概要（ざっくり）

Rails app （1台）
sidekiq（Rails appと同じサーバー上で実行）
バッチサーバーなので普段はさほどアクセスがない
月に1回程度使われる

処理の概要

ユーザーがファイルをアップロードする
最初のファイルアップロード時はファイルの中身を一旦Modelにそのまま保存 (raw_context みたいなカラムにとりあえず保存)
Model保存が終わった段階で、after_commit でそのファイル内容を非同期で処理
- ファイルの内容1行につき、子Modelを1つ作成する、みたいな処理

発生した問題

月に一度登録しようとすると、1回目だけなぜかファイルの1行から子Modelが2つ作成されている
データ数が合わないため、削除。もう一度同じファイルを使って登録し直すと想定している1行1子Modelになる

ロジックを調査して、ファイル1行=子Model1つからはずれるバグは見つからず・・・ sidekiq おかしいんじゃないかと疑い始める。

非同期ジョブが2回実行されているのでは・・？

sidekiq.logを確認

2019-01-08T06:10:59.085Z 5738 TID-x454o XxWorker JID-1111fcd9bb51360b8a54d999 INFO: start
...
2019-01-08T06:11:04.030Z 5738 TID-x45t4 XxWorker JID-1111fcd9bb51360b8a54d999 INFO: start

同じJIDが数秒違いで実行されている・・（上のJID- 以降は適当ですが、同じIDが別のワーカーで実行されてる感じのログ）

同じジョブが実行されてるんじゃない？の検索ワードがわかったので、 sidekiq same JID で検索。

github.com

redisとの接続がよろしくないと2回実行される、ような感じ。。

解決策は提示されておらずさらに彷徨う、sidekiq wikiで以下を発見する。

github.com

One problem with cloud-based systems like EC2 and Heroku is unpredictable network performance.

件のサーバーはEC2上にいるので、これ・・ありそう・・・

REMEMBER: THIS IS A BANDAID となっているので、解決策・・ではないですが・・

config.redis = { url: 'redis://...', network_timeout: 5 }

ひとまずこれを指定して、networkの状況が悪くても、なるべくタイムアウトしないでくれることを祈る・・

おまけ : ジョブの冪等性

今回の処理では、

親Model作成
親の持つデータからジョブ実行で子Model作成

という処理がトランザクション内で実行されるように考慮されてた。

ActiveRecord::Base.transaction do
  @parent_model.items.delete_all
  # ...いろんな処理で子モデルのリスト items を作る
  items.each { |item| @parent_model.items << item }
  @parent_model.status = 'uploaded'
  @parent_model.save!
end

こんな感じ

が、非同期ジョブが別スレッドからほぼ同時にこの処理を流してしまうと

ジョブ1: delete_all
ジョブ2: delete_all
ジョブ1: save!
ジョブ2: save!

こんな感じになってしまうのはあり得る。

幸いにも @parent_model が status を持っていたので、処理が始まる前のstatusをチェックして、 2つ目ジョブ実行を阻むようにして回避しました。

おまけのおまけ

サーバーでの非同期のバッチ処理（かつ保守だけ担当しているシステムの一部）だったので、原因突き止めるまでめちゃ苦戦しました・・

1日ほど格闘して夕方ごろ、「これは・・自分だけで解決無理っぽい・・」と判断して、社内グループウェア（kibe.la）に [HELP WANTED] のタイトルつけて投稿して、諸先輩がたに助けを求めてことなきを得ました。（感謝しかない！）

合計37件のコメント（半分は自分が状況の説明＆いただいた「これはチェックした？」のコメントへの回答）が集まって、ある意味大盛況エントリになってしまいました。。諸先輩方やさしひ・・（感涙）とありがたさを噛み締めておりました。

リモートワーカーなので、一人自宅で「ウガガ・・」と頭を抱えていても誰も気づいてくれないわけで、

これはこのまま抱えこんでも無理そうという判断や

困ってる、HELP!を恥をかき捨ててでかい声あげてかなきゃいけない んですよね。

あと、助けてもらうための情報出し も重要。

今週は苦手な保守系の仕事が多かったので、HELPしてもらうばっかりでしたが・・精進せねば〜

まりぴよこのブログ

日々の日記。技術ネタでまとまりきってないものの記録、伝わる文章の書き方を練習とか。