[Ruby]うるう日の午前0時から9時までに起動したプロセスでのみ再現するサーバー障害

こんにちは、サーバーサイドエンジニアの市東です。
今年の2月29日にゲームサーバーの障害が発生したため、今回はその現象と解決策について紹介します。

環境

Ruby 3.1.4
ActiveRecord 6.0.0
TZ “Asia/Tokyo”
MySQL 8系
時刻に関して、サーバーロジックはJSTで、データベースではUTCで扱っています

要約

障害の発生:
日本の時刻で2024/02/29 0時以降に、一定確率でデータベースへのINSERTが失敗するようになりました。

再現条件:
この現象は2024/02/29 0~9時 JSTに起動したプロセスでのみ再現しました。

原因:
INSERTが失敗するのは、過去の時刻が2023/02/29などの存在しない時刻になることが要因でした。その時刻が生成されるのは、Ruby3.1.4特有のバグでした。

解決策:
うるう日の9時以降に再起動すれば直ります。また、Rubyのバージョンを3.2以上にアップグレードすることで、この問題は発生しません。

将来の影響:
次に同様の日付が回ってくる2028年2月29日までには、Ruby3.1.4はサポート終了(EOL)を迎えるため、影響を受けるシステムはほとんどないと予想されます。

謝辞

この度の問題解決に至るまでには、ruby-jp Slack ワークスペースの皆様からの貴重な情報提供が不可欠でした。皆様の知識と経験に基づく支援に心から感謝申し上げます。

障害発生の状況

原因調査

エラーの発生箇所の特定

このエラーIncorrect datetime valueはデータベースのdatetime columnに対して不正な値を書き込もうとしたことが原因で発生しています。通常のINSERT statementを使って、過去の時刻を書き込むことはほとんどありませんが、MySQLなどに用意されているINSERT … ON DUPLICATE KEY UPDATE statementを使って複数の行を更新するときには、過去の時間を使ったクエリが生成されます。
例えば、複数の消耗品を所持しており、1つのクエリで複数の所持数を変更するときは、下記のようになります。

// PK(user_id, item_id)
SELECT * FROM items WHERE user_id = 123;
 user_id | item_id | quantity |     created_at
---------+---------+----------+---------------------
   123   |  10001  |   2000   | 2023-02-28 21:10:22 
   123   |  10002  |   3000   | 2024-01-10 12:58:09 

//正常なINSERT statement
INSERT INTO 
 items (user_id, item_id, quantity, created_at) 
VALUES 
 (123, 10001, 2005, '2023-02-28 21:10:22'), 
 (123, 10002, 3019, '2024-01-10 12:58:09')
ON DUPLICATE KEY UPDATE 
 quantity=VALUES(quantity)

正常であれば、’2023-02-28 21:10:22’となるはずですが、’2023-02-29 21:10:22’という存在しない日付になっていることが問題になります。データベース上の値を読み込んで、書き出すときに別の値になるということは、該当のserialize/deserializeの実装に着眼すると良さそうです。あとは再現することができれば、解決に近づきます。

再現方法

ところが、手元で実行しても再現しません。より環境の近いステージングにおいて、同様のデータを用意しても全く再現しません。
困っていたところに、Rubyコミュニティの方々から、「うるう日の0~9時に実行すると再現する」という情報をいただきました。faketimeを使ったり、システム時刻を直接書き換えたりすることで、再現することができました。

$ RBENV_VERSION=3.1.4 faketime '2024-02-29 08:00:00' \
 ruby -ve "p Time.utc(2023, 2, 28, 21, 10, 22, 0)"
ruby 3.1.4p223 (...)
2023-02-29 21:10:22 UTC

手元でもステージング環境でも、確認していた時刻がすでに9時を過ぎていたため、再現しなかったことがわかります。また、該当のタイトルはメンテナンス日で、ちょうど9時前に起動したプロセスがたくさんある状態でした。メンテナンス前の0時に発生していたエラーは、何らかの要因で自動的に再起動したサーバープロセスがいたと推測できます。

短期的対処

プロセスの起動時刻に依存した挙動であることがわかったため、サーバーを再起動すれば直ることが期待できます。詳細の原因はまだ特定できていませんが、リリースされている環境で正常に動作させるために再起動を行いました。この結果、エラー通知は止み、本番環境は正常な状態に戻ったと観測できました。

原因の詳細

さて、挙動はある程度理解できましたが、いつ再発するかわかりません。もしかしたら明日の午前0時に再発するかもしれませんし、1ヶ月後に再発するかもしれません。これらの不安を払拭するためには、原因を特定する必要があります。プロセスの特定の起動時刻に依存して、時刻のserialize/deserializeの挙動が意図しない形になることを調査するためには、該当のRubyの実装を読むと良さそうです。任意の好きなエディタでデバッグすると、うるう日とそれ以外で呼び出される関数に変化があることがわかりました。これが今日の本題です。
私の場合は、エディタはJetBrains CLionを、debuggerはMacOSのためLLDBを使いました

RubyのTime.utcは、CRubyではtime_s_mkutcという関数で定義されています。

rb_define_singleton_method(rb_cTime, "utc", time_s_mkutc, -1);
// https://github.com/ruby/ruby/blob/v3_1_4/time.c#L5664

ここの実装をたどると、下記の挙動をしていることがわかります。いくつか簡略化しています

• 1. 入力値からエポックタイムを計算する。
  • 1-1. 現在時刻を元に366日後までの未来のうるう秒情報を初期化する。
  • 1-2. 以下のいずれかが実行される:
    • 1-2-a. 未来のうるう秒がなければ、入力値に対してうるう秒なしのエポックタイムを返す。
    • 1-2-b. 未来のうるう秒があり、うるう秒が適用される最大の時刻より、入力の時刻が大きければ、入力値にうるう秒を加算したエポックタイムを返す。
    • 1-2-c. a,bでなければ、入力値にうるう秒が適用されるエポックタイムを二分探索して返す。
• 2. エポックタイムから時刻構造体を再構築する。
  • 2-1. 現在時刻を元に366日後までの未来のうるう秒情報を初期化する。(メモ化されているため何もしない)
  • 2-2. 以下のいずれかが実行される:
    • 2-2-a. 未来のうるう秒がなければ、エポックタイムに対してうるう秒なしの時刻構造体を返す。
    • 2-2-b. 未来のうるう秒があり、うるう秒が適用される最大の時刻より、エポックタイムが大きければ、それに対してうるう秒を減算した時刻構造体を返す。
    • 2-2-c. a,bでなければ、うるう秒を考慮した時刻構造体を返す。gmtimew_noleapsecond

この未来のうるう秒情報を初期化する init_leap_second_info 実装では、最初に評価した結果をメモ化しています。ここが、うるう日の特定時刻に起動したプロセスで発生する原因となります。
また、1-1や2-2-cなどの処理では、エポックタイムからうるう秒を考慮した時刻構造体を返すgmtime_with_leapsecond関数を使用しています。この実装にはバグがあり、Ruby3.2では修正されていますが、Ruby3.1.4にはバックポートされていません。
これは、現地時刻が03/01で、UTC時刻が1日前のとき、うるう年にかかわらずUTC時刻は02/29を返すという挙動をしてしまいます。これを元に未来のうるう秒を計算すると異常値が発生し、未来のうるう秒が存在しなくても、存在する分岐の方へと流れてしまいます。

これらを組み合わせると、下記のような挙動になります。

これが、JSTのうるう日の午前0時から9時までに起動した(正確には、Time.utcなどの呼び出しで未来のうるう秒情報を計算した)プロセスでのみ、JSTで03/01、UTCで1日前になる時間をパースすると全てUTCでは02/29になる現象の正体でした。
該当の時刻に起動したサーバーで、任意のユーザーが2023/02/28 15:00 UTCや2021/02/28 23:00 UTCなどに入手したアイテムを、消費や獲得などで複数の行を更新するときに2023/02/29 15:00 UTCや2021/02/29 23:00 UTCという無効な時刻でクエリを生成し、データベース側でエラーになります。これはアイテムなどにかかわらず、複数の行を更新する実装すべてに影響がありました。

原因は特定でき、1ヶ月先に突然再発することはないため、夜も安心して眠れそうです。

解決策

短期的対処ではサーバーをうるう日の9時以降に再起動する対応をしましたが、長期的な対処としてはRubyのバージョンを3.2にすることが推奨されます。この現象が次に再発するのは2028/02/29ですが、その頃にはRuby3.1.4はEOLを迎えているため、特に気にする必要もないでしょう。

最後に

今回の経験から、重要な教訓を得ることができました。非常にありきたりなものですが、それは使用しているプログラミング言語やライブラリのアップデートを先延ばしにしないことの重要性です。日々進化するテクノロジーの世界では、バージョンを頻繁に安定版の最新に更新することで、潜在的な問題を未然に防ぐことができます。今回発生した障害は、非常に限定的な条件下でのみ現れる珍しい現象でしたが、それだけに、貴重な学びを提供してくれました。
時刻処理は想像より複雑で、自分自身もまだ理解できていない部分があります。もし興味を持たれた方がいらっしゃれば、ぜひこの機会に直接コードを試してみて、理解を深めていただければ幸いです。