バージョン2.6以前の古いRubyで動いていたプログラムのRubyバージョンを上げてみたら、Timeを要素に含むArrayやHashのto_sの挙動が変わってしまった

何があったのか？

何がおかしくなったのか

そのプログラムには以下のような仕組みがありました。よくある仕組みだと思います。

1. ユーザーが特定のアクションを起こしたとき、文字列でログをテキストファイルに出す
   • 専用のロガーを使う
2. バッチ処理的なもので、定期的にテキストファイルをパースする
3. パースしたものを分析しやすいようにDWHに突っ込む

Rubyのバージョンを上げたところ、パースして取り込む仕組みが壊れてしまいました。
具体的には、Timeを要素に含むHashをもとにログ文字列を出力すると、出力されたテキストのパースに失敗してバッチ処理がコケるようになりました。

専用のロガーについて

そのプログラムではログを出力するときにフォーマットを一定に整えるため、簡易な拡張ロガーを作成してそれを使っているようでした。

実装は次のようになっており、単純です。見ての通り Hash#to_s の結果を文字列として出すようになっています。

 def track(action, user_id, params = {}) 
   logger.info { "action=#{action} user_id=#{user_id} params=#{params.to_s}" } 
 end 

（機械的にパースする必要があるのにこの実装はツッコミどころなのですが、その件はあとの「対策」に書いています）

文字列化されたものは本来は次のようになる想定です。これを分析システムがパースすることになっています。

action=foo user_id=12345 params={:aaa=>123, :bbb=>456, :time=>2024-05-01 13:05:12 +0900}

しかしながら、アップデート後にはこのように日時の表記が変わってしまいパースに失敗するようになってしまいました。

action=foo user_id=12345 params={:aaa=>123, :bbb=>456, :time=>2024-05-01 13:05:12.064792204 +0900}

Timeを要素に含むHashにおいて、何らかの原因で Hash#to_s の挙動が変わってしまった ようでした。

Timeが含まれるHashのto_sが、Rubyバージョンアップで具体的にどのように変わったのか

次は非常に単純なコードで、具体的な挙動の変化を確認してみることにします。

Timeのインスタンスであるtimeを含むHashに対して以下を実行し、その結果を確認してみます。

{time: time}.to_s

Ruby2.6以前

秒未満の単位は表示されないようです。

{:time=>2024-05-01 13:05:12 +0900}

Ruby2.7以降

秒未満の単位がある場合に、それを表示するようになっていました。

{:time=>2024-05-01 13:05:12.064792204 +0900}

秒未満がRationalで指定された場合にも対応していそうです。

{:time=>2024-05-01 13:05:12 1610613/4194304 +0900}

なぜRuby2.6以前からのバージョンアップで挙動が変わってしまったのか

Time#inspectの実装変更

以下を背景に Ruby2.7で実装の変更が行われた ようです。

• https://bugs.ruby-lang.org/issues/15958
• https://twitter.com/__gfx__/status/1143056072422219776

とはいえ、ここで変更しているのはinspectでありto_sではありません。
ぱっと見ではtimeを要素に含む Hash#to_s の挙動が変わるようには見えないと思います。

Rubyにおける Array#to_s と Hash#to_s の正体

実は、Rubyにおいて ArrayとHashのto_sはinspectのエイリアス になっています。
つい最近変更されたとかではなく、太古から元々こうなっているようです。

• https://github.com/ruby/ruby/blob/1c991f3bf40c2e506a819732dd0c4afe5d3c5f46/array.c#L8613
• https://github.com/ruby/ruby/blob/1c991f3bf40c2e506a819732dd0c4afe5d3c5f46/hash.c#L7148

そしてソースコードを見ての通り、これらのinspectは各要素のinspectを順番に呼ぶ実装になっています。
なのでTimeを要素に含むArrayやHashにてto_sを呼ぶと Time#inspect が呼ばれて文字列化されます。

それゆえに Time#inspect の挙動が変わると、Timeを要素に持つArrayやHashのto_sの挙動が変わってしまうというわけです。

挙動が変わる例・変わらない例

foo_time = Time.now

# 挙動そのまま
foo_time.to_s

# 挙動変わってる
foo_time.inspect

# Hash#to_sの中身はinspectを順に呼んでるので挙動変わってる
{bar: foo_time}.to_s

# Array#to_sの中身はinspectを順に呼んでるので挙動変わってる
[foo_time].to_s 

対策

暗黙的な文字列化処理に頼らず、個別で文字列化処理を入れる

こういうものを文字列化するのであれば

{
 aaa: 123,
 bbb: "foobar",
 updated_at: time,
}.to_s

暗黙的な文字列化処理に頼らず、以下のようにすれば影響範囲を抑えることができます。単純な方法です。

{
 aaa: 123,
 bbb: "foobar",
 updated_at: time.to_s, # time.strftime("%Y-%m-%d %H:%M:%S %z") みたいなのだとなお良し
}.to_s

あとは transform_values(&:to_s) なんてのもアリなのかもしれません。

モンキーパッチを当てる

「Ruby2.6以前の挙動に戻す」のであれば、こんなモンキーパッチを仕込むことができそうです。これもお手軽です。

ただ、影響範囲が広すぎるので考えものなのかなという気もします。

class Time
  # ruby2.6ではinspectはto_sなのでそれに合わせる https://github.com/ruby/ruby/blob/ruby_2_6/time.c#L5569
  def inspect
    to_s
  end
end

そもそもto_sのようなフォーマットが明確ではないものを使わない

はじめに「ツッコミどころがある」と書いたのはこういうことです。
マシンリーダブルであることが要求されるものに、出力フォーマットが不定のto_sを使うこと自体があまり良い実装ではありません。
パースのために文字列の細かいフォーマットを気にするのであれば、何らかの決まりにのっとったものを使うべきです。

どこまで厳密にするかは要件次第なのでなんともいえません。
ログ用途だけであれば自力でログを組み立てず、構造化ログを前提にした既存のライブラリの仕組みに乗っかるのが便利そうです。

複雑なことをやらずに、JSON化で済ませることもできる？

一方、それほどの厳密性が求められない場合も多いです。
日時文字列を良い感じに出力できればよいだけで、細かいことを気にしなくてOKであれば、JSONシリアライザーに突っ込むだけで済ませるのも一つの手段になりうると私は考えています。

挙動は個々のシリアライザー次第です。とはいえ大抵はWeb系で使うことを前提にしており、日時を渡すと JavaScriptのDate.parseで絶対パース可能なISO8601 で出力してくれます。

いわゆる デファクトスタンダード的な挙動 だと思います。
フォーマットが明確であるとは言い難いのですが、現実的にこれでよいケースは結構ありそうです。

まとめ

最近は製品の寿命が短くソースコードを短期間で捨てられるというのに慣れてしまう気がします。（それはそれでよいことなのかもしれませんが）
そういう空気の中では周辺環境の変更に強い実装というものが忘れられがちです。

商売は長く稼いでナンボです。故に周辺環境の変化に負けない防御的な実装が必要な場面があるはずです。
うまいことやっていきたいですね。