Rubyのテストのややこしい失敗を直した話

Ruby の CI 維持業というのはこんな感じという事例紹介。

CIを観察する

RubyのCIがときどき次のように失敗していました。

  1) Error:
TestM17N#test_object_inspect_external:
Encoding::CompatibilityError: incompatible character encodings: UTF-8 and UTF-16BE
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:311:in `encode'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:311:in `inspect'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:313:in `inspect'
    /tmp/ruby/v2/src/trunk-test-random/test/ruby/test_m17n.rb:313:in `test_object_inspect_external'

http://ci.rvm.jp/logfiles/brlog.trunk-test-random.20200322-221411

なんか例外が発生しています。必ず再現するわけではなく、手元で再現もできないのですが、日に数回程度失敗し続けていて鬱陶しいテストでした。このログだけ見て問題箇所を特定できたらエスパーです。

問題を切り分ける

まず、ボトムアップとトップダウンの両面から観察を試みます。

ボトムアップ観察、つまり例外発生箇所から観察します。エラーメッセージの "incompatible character encodings" で検索すると、5箇所ほどrb_raiseしている箇所がありました。しかし、どれで発動しているのかよくわかりませんでした。

トップダウン観察は、失敗しているテストを見ることです。

def test_object_inspect_external
...
  Encoding.default_external = Encoding::UTF_16BE
...
  def o.inspect
    "abc".encode(Encoding.default_external)
  end

  assert_equal '[abc]', [o].inspect
...
end

問題を切り分けるために、inspect が無関係であることを確かめたいのですが、このテストだけ切り出しても問題が再現しないので、確かめることができません。そこで、"abc".encode(Encoding.default_external) だけで例外が出るかどうか、それらのエンコーディングが妙なことになっていないかなどをデバッグ出力させるコードをテストに突っ込んで、しばらくCIを観察することにしました。

デバッグ情報を集める

翌朝CIを見ると、めでたく失敗が起きていました。デバッグ出力を見ると、"abc".encode(Encoding.default_external) 単体で例外が起きることが確認できました。また、それらのエンコーディングも期待通り。意外性はなかった。

ということで問題はほぼ特定できたのですが、しかし、ちょっと考えてもどういう経緯でこの例外が投げられるかはわかりませんでした。そこで、例外発生時の C のスタックトレースを採取することを試みます。次のようなデバッグコードをテストコードにコミットしました。

TracePoint.new(:raise) do |tp|
  Process.kill(:SEGV, $$)
end.enable { "abc".encode(Encoding.default_external) }

TracePoint ってこういう風につかうものなんですよね。

問題を分析する

また翌朝、CIが失敗していて無事Cのスタックトレースが取れました。

String#encode が呼ばれてから raise が起きるまでのトレース。

/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_raise+0x94) [0x7fc6c5e4cf74] /tmp/ruby/v2/src/trunk-test-random/error.c:2689
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(enc_compatible_p+0x0) [0x7fc6c5e32d80] /tmp/ruby/v2/src/trunk-test-random/encoding.c:915
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_enc_check) (null):0
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_file_expand_path_internal+0x109) [0x7fc6c5e61cf9] /tmp/ruby/v2/src/trunk-test-random/file.c:3640
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_file_expand_path_internal+0x847) [0x7fc6c5e62437] /tmp/ruby/v2/src/trunk-test-random/file.c:3746
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_find_file_ext+0x3fb) [0x7fc6c5e62f3b] /tmp/ruby/v2/src/trunk-test-random/file.c:6330
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(require_internal+0x2dc) [0x7fc6c5eb044c] /tmp/ruby/v2/src/trunk-test-random/load.c:909
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_require_string+0x23) [0x7fc6c5eb2173] /tmp/ruby/v2/src/trunk-test-random/load.c:1111
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(load_transcoder_entry+0xa8) [0x7fc6c5fe7908] /tmp/ruby/v2/src/trunk-test-random/transcode.c:386
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(load_transcoder_entry+0x14) [0x7fc6c5feb5d0] /tmp/ruby/v2/src/trunk-test-random/transcode.c:372
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(rb_econv_open) /tmp/ruby/v2/src/trunk-test-random/transcode.c:943
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(str_transcode0+0x268) [0x7fc6c5feed28] /tmp/ruby/v2/src/trunk-test-random/transcode.c:2275
/tmp/ruby/v2/build/trunk-test-random/libruby.so.2.8.0(str_encode+0x64) [0x7fc6c5fef3f4] /tmp/ruby/v2/src/trunk-test-random/transcode.c:2763

問題を分析するのに十分な情報が取れました。これをもとに、各C関数の実装を解読していきます。1時間くらいがんばる。結果として、

  • Encoding.default_external = Encoding::UTF_16BE とすることで、ファイルシステムのエンコーディングが UTF-16BE とみなされるようになる
  • そのあと String#encode によって Encoding::UTF_16BE の実体がロードされようとする
  • このロードの際、LOAD_PATHの文字列（UTF-8）が相対パスのとき、カレントディレクトリ（UTF-16BE）と結合しようとして件の例外が投げられる

という現象であると仮説が立てられました。

この現象自体がバグかどうかは判断が難しい。ファイルシステムが UTF-16BE ならば LOAD_PATH に UTF-8 文字列を入れるのがおかしいわけで、この例外自体は正当かもしれない。でも現実問題として、いまの Ruby はファイルシステムが ASCII-compatible でないエンコーディングの場合をサポートしてない気がするので、ちょっと微妙。

仮説を検証する

この仮説をもとに、再現コードを作ります。デバッグ出力をはさみつつ30分ほどがんばると、次のコードで件の例外が観測できました。

$LOAD_PATH << "no_existing_dir"
Encoding.default_external = Encoding::UTF_16BE
load "dummy.rb" #=> incompatible character encodings: UTF-8 and UTF-16BE

存在するディレクトリへの相対パスを $LOAD_PATH に追加すると内部的に絶対パスに変換されるので、問題は発現しません。存在しないディレクトリを加えるところが再現のポイントでした。

ということで、この問題は、「何かのテストが存在しないディレクトリを $LOAD_PATH に追加している」「その後、件のテストを実行すると例外が投げられる」という現象である可能性が高まりました。

問題のテストを探す

テストの中で $LOAD_PATH をいじっているコードを全部見ていきます。たくさんあったので面倒でしたが、ほとんどの箇所は絶対パスを入れているので、丁寧に見ていけば見つけられました。

case ENV['JSON']
when 'pure'
  $:.unshift 'lib'
  require 'json/pure'
when 'ext'
  $:.unshift 'ext', 'lib'
  require 'json/ext'
else
  $:.unshift 'ext', 'lib'
  require 'json'
end

https://github.com/ruby/ruby/blob/13e9551b97d6bb9fcd09283692f6090f4c418059/test/json/test_helper.rb

まさか JSON のテストが原因とは、最初の問題からは想像できないですね。

ちなみに、これは JSON を gem として開発するときのハックのようです（JSONはpure Ruby実装とC実装の2つを持っていて、環境変数によってテスト対象を制御できるようにしている）。しかし Ruby にバンドルされた状況下では常にC実装を使うので、このハックは無意味です。

手元で再現させる

これが原因であることを確認するためには、json と件のテストだけを実行すればいいです。

$ make test-all TESTS="json ruby/m17n -n test_object_inspect_external"
Run options: 
  --seed=94886
  "--ruby=./miniruby -I../ruby.src/lib -I. -I.ext/common  ../ruby.src/tool/runruby.rb --extout=.ext  -- --disable-gems"
  --excludes-dir=../ruby.src/test/excludes
  --name=!/memory_leak/
  -n
  test_object_inspect_external

# Running tests:

[1/1] TestM17N#test_object_inspect_external/home/mame/work/ruby.src/test/ruby/test_m17n.rb:319: [BUG] Segmentation fault at 0x000003e80000751d
...

無事問題が再現しました。ということで、これが原因ということで間違いなさそうです（ひょっとしたら他にもあるかもしれないけど）。

しれっと再現したと書いていますが、2つポイントがあります。

  • in-place build では再現しません（カレントディレクトリにたまたま ext も lib も存在するので発動条件を満たさない）。out-of-place のときは lib が存在しないので発動します。（問題のCIを管理しているささださんが out-of-place build 派だという知識があると有利。）
  • -n test_object_inspect_external によって、件のテストだけを実行することが必要です。なぜなら、他の M17N のテストを先に実行すると UTF_16BE のオートロードが先に行われてしまい、問題のテストでファイルロードが行われなくなって再現しなくなる。

修正する

ここで相対パスを入れなければ大丈夫なので、雑に絶対パスにしてやりました。これで手元では問題が再現されなくなりました。コミットして CI 観察継続中。

まとめ

Ruby の CI がときどき失敗する現象の調査と修正の事例紹介でした。JSON のテストが M17N のテストを失敗させるとかなかなか難しいですね。今回はテストの修正だけで済みましたが、本体側の修正が必要になる場合ももちろんあります。また、これはRubyの知識で完結している問題でしたが、システムプログラミングの知識が要求されるようなことも多いです。Rubyの品質をたもつのは総合格闘技。