Backport #5850: Backport r34129, r34250, r34252 and r34253 ( Failure test/ruby/test_io.rb )

• Status: Closed
• Assignee: -

[ayumin (Ayumu AIZAWA)]

=begin
r34219で test/ruby/test_io.rb が1件失敗、1件エラーになります。
エラーの方は-j で実行すると最初は失敗してそのあと成功します。

0:ruby ➔ make test-all TESTS=test/ruby/test_io.rb
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems"

Running tests:

.F.............E..................................................................................................

Finished tests in 4.242426s, 26.8714 tests/s, 134.3571 assertions/s.

1. Failure:
   test_autoclose(TestIO) [/Users/ayumin/github/ruby/test/ruby/test_io.rb:1444]:
   Errno::EBADF expected but nothing was raised.

2. Error:
   test_copy_stream(TestIO):
   Errno::EBADF: Bad file descriptor
   /Users/ayumin/github/ruby/test/ruby/test_io.rb:32:in close' /Users/ayumin/github/ruby/test/ruby/test_io.rb:32:in rescue in block in pipe'
   /Users/ayumin/github/ruby/test/ruby/test_io.rb:29:in `block in pipe'

114 tests, 570 assertions, 1 failures, 1 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-06 trunk 34219) [x86_64-darwin10.8.0]
make: *** [yes-test-all] Error 2
0:ruby ➔ make test-all TESTS='-j 2 test/ruby/test_io.rb'
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -j 2 test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -j 2

Running tests:

.F.............E..................................................................................................
Retrying...

.F................................................................................................................

Finished tests in 10.072929s, 11.3175 tests/s, 56.5873 assertions/s.

1. Failure:
   test_autoclose(TestIO) [/Users/ayumin/github/ruby/test/ruby/test_io.rb:1444]:
   Errno::EBADF expected but nothing was raised.

114 tests, 570 assertions, 1 failures, 0 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-06 trunk 34219) [x86_64-darwin10.8.0]
make: *** [yes-test-all] Error 1

=end

[nagachika (Tomoyuki Chikanaga)]

test_autoclose の Failure は年末に Ubuntu で発生していました。その時は Mac OS では再現していなかったのですが、現在 34220 では同じように 1 failure 1 error になっています。 autoclose の仕様を誤解していなければ、このテストは try_fdopen で GC で IO オブジェクトが確実に解放されることを期待しているのですが、CRuby の GC は正確ではないため回収されないことがあり、それで failure になっているのだと思います。 test_copy_stream は test_autoclose の巻き添えになってるような気がします -n test_copy_stream で単体で動かすと成功しますが、 -n '/test_(autoclose|copy_stream)\Z/' で test_autoclose の後に動かすと Error になります。

[nagachika (Tomoyuki Chikanaga)]

ええと、まず GC で確実に回収される保障がない以上 test_autoclose の後半の assertion は失敗する可能性があります。try_fdopen でメソッド呼び出しを100回ネストして IO.for_fd した後 GC でその IO オブジェクトを回収させようとしているようですが、ruby で書かれたメソッドの呼び出しをネストしてもマシンスタックは積まれないためマシンスタック上からの誤った参照の影響をなくす効果は薄いと思います。ためしに try_fdopen に 1.times do ... end のようにブロック呼び出しするメソッド(マシンスタック消費する)を入れてみると Snow Leopard では Failure がおきなくなりました。ただこれ以外のところにたまたま偽の参照があったらやはり回収されないので失敗する可能性は残ります。

また test_copy_stream の Error ですが、これは先の test_autoclose で 2つの IO オブジェクトが同じ fd について open されている状態になっていて、一方(Tempfile のほう)は明示的に close されていますがもう一方は close されないまま放置されているため、その IO が GC されたタイミングで close(2) が呼ばれます。その時にその fd が別の IO オブジェクトのために再利用されたものを閉じてしまうためではないかと思います。 これは [Feature #2250] で言われている IO.for_fd の危険な使いかたそのものです。

• test_autoclose の後半の assertion は IO オブジェクトに finalizer を設定して回収されたかどうかをチェックして、回収されなかったらあきらめる
• autoclose: true の時のテストは子プロセスに分離する

というのでどうでしょうか。問題or代案がなければこの方針でテストを修正するパッチを書こうと思います。

[ayumin (Ayumu AIZAWA)]

=begin

GCが変更されたからなのかわかりませんが、挙動が変化しました。
test_io.rbの全体を実行した場合のみ test_copy_stream がエラーとなります。

== test_autoclose のみ実行した場合:

1:ruby ➔ make test-all TESTS="-n '/test_autoclose\Z/' test/ruby/test_io.rb"
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n '/test_autoclose\Z/' test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n /test_autoclose\Z/

Running tests:

.

Finished tests in 0.608045s, 1.6446 tests/s, 13.1569 assertions/s.

1 tests, 8 assertions, 0 failures, 0 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-08 trunk 34230) [x86_64-darwin10.8.0]

== test_copy_stream のみ実行した場合:

1:ruby ➔ make test-all TESTS="-n '/test_copy_stream\Z/' test/ruby/test_io.rb"
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n '/test_copy_stream\Z/' test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n /test_copy_stream\Z/

Running tests:

.

Finished tests in 1.147130s, 0.8717 tests/s, 52.3044 assertions/s.

1 tests, 60 assertions, 0 failures, 0 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-08 trunk 34230) [x86_64-darwin10.8.0]

== test_autoclose と test_copy_stream を実行した場合:

1:ruby ➔ make test-all TESTS="-n '/test_(autoclose|copy_stream)\Z/' test/ruby/test_io.rb"
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n '/test_(autoclose|copy_stream)\Z/' test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" -n "/test_(autoclose|copy_stream)\Z/"

Running tests:

..

Finished tests in 1.767467s, 1.1316 tests/s, 38.4731 assertions/s.

2 tests, 68 assertions, 0 failures, 0 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-08 trunk 34230) [x86_64-darwin10.8.0]

== test_io.rb 全体を実行した場合:

1:ruby ➔ make test-all TESTS="test/ruby/test_io.rb"
./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems "./test/runner.rb" --ruby="./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems" test/ruby/test_io.rb
Run options: "--ruby=./miniruby -I./lib -I. -I.ext/common ./tool/runruby.rb --extout=.ext -- --disable-gems"

Running tests:

...............E..................................................................................................

Finished tests in 4.331913s, 26.3163 tests/s, 131.8124 assertions/s.

1. Error:
   test_copy_stream(TestIO):
   IOError: closed stream
   /Users/ayumin/github/ruby/lib/tempfile.rb:275:in close' /Users/ayumin/github/ruby/lib/tempfile.rb:275:in call'
   /Users/ayumin/github/ruby/test/ruby/test_io.rb:416:in read' /Users/ayumin/github/ruby/test/ruby/test_io.rb:416:in block (4 levels) in test_copy_stream'

114 tests, 571 assertions, 0 failures, 1 errors, 0 skips

ruby -v: ruby 2.0.0dev (2012-01-08 trunk 34230) [x86_64-darwin10.8.0]
make: *** [yes-test-all] Error 1

=end

[nagachika (Tomoyuki Chikanaga)]

GC の変更で test_autoclose はうまく IO オブジェクトが回収されるようになったみたいですね。こちらでも再現しなくなってしまいました。

test_copy_stream の Error は以前とは別もので、Tempfile#_close で File#close が例外(Errno::EBADF)を発生させた時に finalizer に渡すオブジェクト(@data[1])を nil でクリアするのが飛ばされてしまうからのようです。 @data に残っていると Tempfile の finalizer で再度 close しようとしてしまうのでそこで例外が発生します。あと unlink にも typo らしいのをみつけたので以下のように修正しようと思います。

ただ finalizer で例外が発生した時にそれが実行中の処理にまで波及するのは正しいのでしょうか? 少し実験してみたのですが finalizer の中で例外を発生させても無視されるようなのでこれはこれでまた別の問題があるのかもしれません。

diff --git a/lib/tempfile.rb b/lib/tempfile.rb
index 3321116..b7c2f91 100644
--- a/lib/tempfile.rb
+++ b/lib/tempfile.rb
@@ -162,9 +162,9 @@ class Tempfile < DelegateClass(File)
end

def _close # :nodoc:

• @data[1] = nil if @data
  @tmpfile.close if @tmpfile
  @tmpfile = nil

• @data[1] = nil if @data
  end
  protected :_close

@@ -231,7 +231,7 @@ class Tempfile < DelegateClass(File)
File.unlink(@tmpname)
end
# remove tmpname from remover

•  @data[0] = @data[2] = nil
  

•  @data[0] = @data[1] = nil
   @tmpname = nil
  

  rescue Errno::EACCES
  # may not be able to unlink on Windows; just ignore

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Open to Closed
• % Done changed from 0 to 100

This issue was solved with changeset r34253.
Ayumu, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

---

• test/ruby/test_io.rb (test_autoclose_true_closed_by_finalizer,
  test_autoclose_true_closed_by_finalizer): skip if IO objects are
  not recycled yet. [ruby-dev:45098] [Bug #5850]

[nagachika (Tomoyuki Chikanaga)]

• Tracker changed from Bug to Backport
• Project changed from Ruby master to Backport193
• Category deleted (core)
• Status changed from Closed to Open
• Target version deleted (2.0.0)

r34250 (finalizer の例外が外に影響するのを修正)、r34252 (Tempfile の close で例外が発生すると finalizer で例外になるのを修正)、 r34253 (test_autoclose で IO が回収されなかった時を考慮) の 3つをコミットしました。backport のためどなたかレビューをお願いします。

[ayumin (Ayumu AIZAWA)]

• Subject changed from Failure test/ruby/test_io.rb to Backport r34129, r34250, r34252 and r34253 ( Failure test/ruby/test_io.rb )

Tempfile.new のブロックが実行されないのにテストで使われていたのを直した際( r34129 ) に今回のバグが顕在化したようです。
ビルドとテストをして問題なければBackport します。

[ayumin (Ayumu AIZAWA)]

• Status changed from Open to Closed

This issue was solved with changeset r34276.
Ayumu, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

---

merge revision(s) 34253:

* test/ruby/test_io.rb (test_autoclose_true_closed_by_finalizer,
  test_autoclose_true_closed_by_finalizer): skip if IO objects are
  not recycled yet. [ruby-dev:45098] [Bug #5850]

[ayumin (Ayumu AIZAWA)]

Merged by r34273, r34274, r34275 and r34276