Bug #6228: [mingw] Errno::EBADF in ruby/test_io.rb on ruby_1_9_3

• Status: Closed
• Assignee: luislavena (Luis Lavena)
• Target version: 1.9.3
• ruby -v: ruby 1.9.3p172 (2012-03-30 revision 35179) [i386-mingw32]

[jonforums (Jon Forums)]

On Win7 32bit built with MinGW 4.6.2 using the RubyInstaller build recipes, I get the following test error:

sh-3.1$ ruby --version
ruby 1.9.3p172 (2012-03-30 revision 35179) [i386-mingw32]

sh-3.1$ make test-all TESTS='openssl fiddle psych zlib io json mkmf pathname stringio erb
fileutils ruby/test_io.rb ruby/test_io_m17n.rb ruby/test_file.rb'

7. Error:
   test_lines(TestIO):
   Errno::EBADF: Bad file descriptor
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:33:in close' c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:33:in rescue in block in pipe'
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:30:in `block in pipe'

[naruse (Yui NARUSE)]

Do you know which revision break it?

[jonforums (Jon Forums)]

Not yet.

[jonforums (Jon Forums)]

Haven't found root cause, but these commits also have Errno::EBADF errors:

commit revision patch

---

b1bcb82 r34865 p154
1b21d03 r34811 p146
7e2e3dc r34806 p144

In the above commits, the failures are at a different location in ruby/test_io.rb likely because I'm not building deps in order to speed things up:

5. Error:
   test_invalid_advise(TestIO):
   Errno::EBADF: Bad file descriptor - C:/Users/Jon/AppData/Local/Temp/test_io20120330-6868-1lqi3p9
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1119:in make_tempfile' c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1848:in block (2 levels) in test_invalid_advise'
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1847:in each' c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1847:in block in test_invalid_advise'
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1846:in each' c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:1846:in test_invalid_advise'
   ../../../../Users/Jon/Documents/RubyDev/ruby-git/test/runner.rb:15:in `'

I suspect this testing difference isn't relevant since EBADF errors persist, but it is a difference.

Time permitting this weekend, I'll try again using git bisect

[jonforums (Jon Forums)]

In my configuration, one fix is to remove the recent -DFD_SETSEZE=32767 define from the RubyInstaller build recipe. Removing the define gives the following results on r35179:

• no deps build using WinSDK 7.1 (without RubyInstaller) has no test_lines(TestIO) nor test_invalid_advise(TestIO) Errno::EBADF failures
• no deps build using MinGW GCC 4.6.2 (with or without RubyInstaller) has no test_lines nor test_invalid_advise failures
• full deps build using MinGW GCC 4.6.2 (with RubyInstaller recipe) has no test_lines nor test_invalid_advise failures

However, removing the define is not acceptable as it was added to fix the following user issue

https://github.com/oneclick/rubyinstaller/issues/104

And it get's more convoluted.

Running git bisect between commits a81c766/r34649 (good) and 7e2e3dc/r34806 (bad) with -DFD_SETSEZE=32767 enabled in the RubyInstaller recipes, the "first bad commit" is Nobu's 35bf809/r34749 tweak to Enumerator in io.c. Building the "good" fa1a2ae/r34746 parent commit (without deps) resulted in no test_invalid_advise failure when running make test-all TESTS='ruby/test_io.rb'. But strangely, test_lines failed while test_invalid_advise passed when running my original make test-all TESTS='openssl ... ruby/test_io.rb ...'

I suspect there are other lurking issues left to discover, so don't close this issue as a 3rd party issue until we know more.

[jonforums (Jon Forums)]

of course it's the FD_SETSIZE macro I'm talking about...

[naruse (Yui NARUSE)]

• Status changed from Open to Assigned
• Assignee set to luislavena (Luis Lavena)

[h.shirosaki (Hiroshi Shirosaki)]

This issue seems to be related to GC finalizer.
GC is triggered just before Errno::EBADF occurs, and finalizer closes the fd of make_tempfile. Errno::EBADF is raised for trying to close again the closed fd of make_tempfile.

This seems due to test_flush_in_finalizer1.

 500.times {
   f = File.open(path, "w")
   fds << f.fileno
   f.print "hoge"
 }

f is not closed. When GC sweeps f, the fd associated with f seems to be closed.
fds contains 3. And make_tempfile in test_invalid_advise creates fd of 3.

I confirmed the error disappeared with the following patch.
-DFD_SETSEZE=32767 and ruby 1.9.3p184 (2012-04-15 revision 35335) [i386-mingw32] on Windows 7.

diff --git a/test/ruby/test_io.rb b/test/ruby/test_io.rb
index edf449d..70ca240 100644
--- a/test/ruby/test_io.rb
+++ b/test/ruby/test_io.rb
@@ -1800,6 +1800,7 @@ End
end
ensure
fds.each {|fd| IO.for_fd(fd).close rescue next}

• GC.start
  end

def test_flush_in_finalizer2

[h.shirosaki (Hiroshi Shirosaki)]

I tried to create simplified test case of this issue.

cat gc_io_test.rb
f = open("test_file", "w")
p f.fileno
IO.for_fd(f.fileno).close

f = open("test_file", "w")
p f.fileno

GC.start # trigger GC

begin
f.close # => raise Errno::EBADF
rescue
p $!
end

File.unlink("test_file")

~/ruby-trunk/bin/ruby -v gc_io_test.rb
ruby 2.0.0dev (2012-04-17 trunk 35363) [x86_64-darwin11.3.0]
5
5
#<Errno::EBADF: Bad file descriptor - test_file>

[luislavena (Luis Lavena)]

• Status changed from Assigned to Open
• Assignee deleted (luislavena (Luis Lavena))

Who should be the responsible for GC? Seems to me that open file descriptor shouldn't be garbage collected while still open.

[phasis68 (Heesob Park)]

I found that this issue is related with the auto-close flag of IO.

The following code fails with Errno::EBADF

f = open("test_file", "w")
IO.for_fd(f.fileno).autoclose = true # default value
GC.start
f.close

But, the following code works fine.

f = open("test_file", "w")
IO.for_fd(f.fileno).autoclose = false
GC.start
f.close

[mame (Yusuke Endoh)]

• Status changed from Open to Assigned
• Assignee set to authorNari (Narihiro Nakamura)

Who should be the responsible for GC?

Nari-san.

--
Yusuke Endoh [e-mail]

[nagachika (Tomoyuki Chikanaga)]

Hi,

I think the root cause is wrong usage of IO.for_fd in ensure clause of test_flush_finalizer1,
and just call GC.start works fine for recycle fds.

This test was written by nobu.

nakada-san
Is the following patch seems ok?

diff --git a/test/ruby/test_io.rb b/test/ruby/test_io.rb
index ebf9b76..be5a333 100644
--- a/test/ruby/test_io.rb
+++ b/test/ruby/test_io.rb
@@ -1891,7 +1891,7 @@ End
}
end
ensure

• fds.each {|fd| IO.for_fd(fd).close rescue next}

• GC.start
  end

def test_flush_in_finalizer2

[jonforums (Jon Forums)]

Why is the following

ensure
fds.each {|fd| IO.for_fd(fd).close rescue next}

wrong usage of IO.for_fd?

In normal usage, I would likely use this style of explicit closure (by IO wrapping the fd) but not kick off a GC cycle with GC.start.

I'd like to understand why the usage is wrong. Specifically, is there another style of explicit recycling of fds that doesn't require starting a GC cycle?

[mame (Yusuke Endoh)]

• Assignee changed from authorNari (Narihiro Nakamura) to nobu (Nobuyoshi Nakada)

+1 for nagachika-san.

jonforums (Jon Forums) wrote:

Why is the following

ensure
fds.each {|fd| IO.for_fd(fd).close rescue next}

wrong usage of IO.for_fd?

f = open("...") # this first IO has a fd X which is opened now.
IO.for_fd(f.fileno) # this second IO also has the fd X.
GC.start # the second IO is GC'ed; the fd X is auto-closed.
f.close # this attempts to close the fd X, but it is already closed => Errno::EBADF

Specifically, is there another style of explicit recycling of fds that doesn't require starting a GC cycle?

Call IO#close explicitly.

--
Yusuke Endoh [e-mail]

[jonforums (Jon Forums)]

mame (Yusuke Endoh) wrote:

jonforums (Jon Forums) wrote:

Why is the following

ensure
fds.each {|fd| IO.for_fd(fd).close rescue next}

wrong usage of IO.for_fd?

f = open("...") # this first IO has a fd X which is opened now.
IO.for_fd(f.fileno) # this second IO also has the fd X.
GC.start # the second IO is GC'ed; the fd X is auto-closed.
f.close # this attempts to close the fd X, but it is already closed => Errno::EBADF

Specifically, is there another style of explicit recycling of fds that doesn't require starting a GC cycle?

Call IO#close explicitly.

Endoh-san, thank you. I understand.

Why do you think the same incorrect test code fails (consistently, not intermittently) on windows when only using -DFD_SETSIZE, but doesn't appear to fail on *nix? On Arch, I've not been able to repro when building using -DFD_SETSIZE=32767. This may indicate a lurking weakness in an _WIN32 MRI codepath (or winsock2 peculiarity) that doesn't exist (or does a better job of hiding) on *nix.

FYI, there's another recent issue on windows in which -DFD_SETSIZE=32767 exposes a SEGV with EventMachine with a simple EM.run {}. By default, EM sets FD_SETSIZE to 1024. Rebuilding ruby on windows without the FD_SETSIZE override fixes the SEGV. The EM issue is a separate issue than this one, but may be related. I haven't started investigating, so FYI.

I will test again on ruby_1_9_3 and trunk with the suggested patch and reply if errors persist.

Jon

[h.shirosaki (Hiroshi Shirosaki)]

Why do you think the same incorrect test code fails (consistently, not intermittently) on windows when only using -DFD_SETSIZE, but doesn't appear to fail on *nix? On Arch, I've not been able to repro when building using -DFD_SETSIZE=32767. This may indicate a lurking weakness in an _WIN32 MRI codepath (or winsock2 peculiarity) that doesn't exist (or does a better job of hiding) on *nix.

This issue depends on the timing when IO object is GCed. GC of an object with the same fd must occur between open() and close().
I guess -DFD_SETSIZE=32767 would change memory usage and GC timing. MRI implementation is different between WIndows and Linux, so GC timing would differ.

FYI, there's another recent issue on windows in which -DFD_SETSIZE=32767 exposes a SEGV with EventMachine with a simple EM.run {}. By default, EM sets FD_SETSIZE to 1024. Rebuilding ruby on windows without the FD_SETSIZE override fixes the SEGV. The EM issue is a separate issue than this one, but may be related. I haven't started investigating, so FYI.

I think above issue is cause of fd_array buffer overflow.

typedef struct fd_set
{
u_int fd_count;
SOCKET fd_array[FD_SETSIZE];
} fd_set;

On EM, FD_SETSIZE = 1024 and fd_array[1024].
EM uses FD_SET() and FD_SET() seems rb_w32_fdset() on Windows.

https://github.com/ruby/ruby/blob/trunk/win32/win32.c#L2458

In rb_w32_fdset(), FD_SETSIZE = 32767 since rb_w32_fdset is compiled with -DFD_SETSIZE=32767.

if (i == set->fd_count) {
    if (set->fd_count < FD_SETSIZE) { // FD_SETSIZE = 32767
        set->fd_array[i] = s;                 // `i` could be over 1023
        set->fd_count++;
    }
}

If above scenario is correct, FD_SETSIZE of Ruby should be equal or less then FD_SETSIZE of EM.

include/winsock2.h has FD_SET macro on mingw, but MRI undef FD_SET and uses rb_w32_fdset() function. It might be better that FD_SET() is macro instead of function.

[luislavena (Luis Lavena)]

• Assignee changed from nobu (Nobuyoshi Nakada) to usa (Usaku NAKAMURA)

Usa-san, what do you think about Hiroshi suggestion about leave FD_SET() as macro instead?

[usa (Usaku NAKAMURA)]

Hello,

In message "[ruby-core:44560] [ruby-trunk - Bug #6228] [mingw] Errno::EBADF in ruby/test_io.rb on ruby_1_9_3"
on Apr.24,2012 00:38:57, [e-mail] wrote:

Usa-san, what do you think about Hiroshi suggestion about leave FD_SET() as macro instead?

First, as Jon mentioned, the SEGV of EM is another issue.
Please split it from this ticket.

Second, I don't understand how Hiroshi want to change the code,
so I cannot say anything about this.

Regards,

U.Nakamura [e-mail]

[luislavena (Luis Lavena)]

• Assignee changed from usa (Usaku NAKAMURA) to luislavena (Luis Lavena)

usa (Usaku NAKAMURA) wrote:

First, as Jon mentioned, the SEGV of EM is another issue.
Please split it from this ticket.

Understood, creating another one to have FD_SET() discussion.

I'll commit suggested patch from nagachika-san.

Thank you.

[luislavena (Luis Lavena)]

• Status changed from Assigned to Feedback

luislavena (Luis Lavena) wrote:

I'll commit suggested patch from nagachika-san.

I seem unable to reproduce the exact exception on both trunk and ruby_1_9_3 branches. The error seems randomly manifest.

Right now, against ruby_1_9_3, it shows in test_invalid_advise

  5) Error:
test_invalid_advise(TestIO):
Errno::EBADF: Bad file descriptor - C:/Users/Luis/AppData/Local/Temp/test_io20120427-1432-1xmkrxh
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1119:in `make_tempfile'
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1872:in `block (2 levels) in test_invalid_advise'
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1871:in `each'
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1871:in `block in test_invalid_advise'
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1870:in `each'
    C:/Users/Luis/Projects/oss/ruby/test/ruby/test_io.rb:1870:in `test_invalid_advise'
    ../test/runner.rb:15:in `'

[jonforums (Jon Forums)]

I seem unable to reproduce the exact exception on both trunk and ruby_1_9_3 branches. The error seems randomly manifest.

Right now, against ruby_1_9_3, it shows in test_invalid_advise

I've seen failures in both test_invalid_advise (see comment #3) and test_lines. Both disappeared when I tested Nagachika-san's suggested patch.

I'll try again with the latest trunk and ruby_1_9_3, but IIRC, the test_invalid_advise failure occurred when I built without deps.

[jonforums (Jon Forums)]

On Win7 32bit, using the following build recipe on both trunk@r35485 and ruby_1_9_3@r35484 with MinGW GCC 4.6.2

sh -c "../configure --enable-shared --disable-install-doc CPPFLAGS='-DFD_SETSIZE=32767'"
make
make test-all TESTS="ruby/test_io.rb"

I get only the test_invalid_advise(TestIO) error on ruby_1_9_3, and a freeze (cleared by CTRL-C) on trunk. Nagachika-san's suggested patch fixes the errors as does adding TestIO#setup and TestIO#teardown containing GC.disable and GC.enable, respectively.

[luislavena (Luis Lavena)]

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

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

---

• test/ruby/test_io.rb (class TestIO): Disable GC during IO tests to
  avoid file descriptors being GC'ed. Suggestion by Tomoyuki Chikanaga
  [ruby-core:43951][Bug #6228]

[luislavena (Luis Lavena)]

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

Reopening as reported in [ruby-core:45015] this breaks chkbuild on debian.

[h.shirosaki (Hiroshi Shirosaki)]

Hi Luis,

I think Nagachika-san's original patch as below is sufficient for this issue. GC.disable for all tests seems too far.
Did you test with this patch?

diff --git a/test/ruby/test_io.rb b/test/ruby/test_io.rb
index ebf9b76..be5a333 100644
--- a/test/ruby/test_io.rb
+++ b/test/ruby/test_io.rb
@@ -1891,7 +1891,7 @@ End
}
end
ensure

• fds.each {|fd| IO.for_fd(fd).close rescue next}

• GC.start
  end

def test_flush_in_finalizer2

[nagachika (Tomoyuki Chikanaga)]

Hi Luis,

Sorry for a lack of enough explanations about my patch.

The ensure clause of test_flush_in_finalizer1 seems to try close all IO objects opened above and not GC'ed & finalized using IO.for_fd. But it's wrong usage of IO.for_fd. The scenario is as follows.

io = open("..")
fd = io.fileno
io = nil
IO.for_fd(fd).close # <- at this moment, io (if not GC'ed yet) has invalid fd,
# because it's already closed by IO.for_fd(fd).close
new_io = open("...") # new_io might have same fd of io, because file descriptor can be recycled.
... # => io is GC'ed and finalized here. Now new_io has closed fd!
new_io.gets # => raised Errno::EBADF

test_flush_in_finalizer1 is test for finalizer of IO (see #3910) and GC.disable breaks it's intent.
I'm sorry, but I'd like to revert r35631.
And I'll commit my patch. Please check it.

[nagachika (Tomoyuki Chikanaga)]

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

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

---

• test/ruby/test_io.rb (test_flush_in_finalizer1): don't use IO.for_fd
  to close IO objects. it create IO object with already closed fd, and
  cause occasional Errno::EBADF in following tests. [ruby-core:45020]
  [Bug #6228]

[luislavena (Luis Lavena)]

Hi Tomoyuki,

Please revert my change. As commented before, was unable to use your
suggested patch since the invalid file descriptor error 'moved' to a
different test.

I was unable to replicate the error from chkbuild.

Please revert and commit your change, will verify again later today.

Thank you.

Sorry for top posting. Sent from mobile.
On May 13, 2012 11:32 AM, "nagachika (Tomoyuki Chikanaga)" <
[e-mail]> wrote:

Issue #6228 has been updated by nagachika (Tomoyuki Chikanaga).

Hi Luis,

Sorry for a lack of enough explanations about my patch.

The ensure clause of test_flush_in_finalizer1 seems to try close all IO
objects opened above and not GC'ed & finalized using IO.for_fd. But it's
wrong usage of IO.for_fd. The scenario is as follows.

io = open("..")
fd = io.fileno
io = nil
IO.for_fd(fd).close # <- at this moment, io (if not GC'ed yet) has
invalid fd,
# because it's already closed by IO.for_fd(fd).close
new_io = open("...") # new_io might have same fd of io, because file
descriptor can be recycled.
... # => io is GC'ed and finalized here. Now new_io has closed fd!
new_io.gets # => raised Errno::EBADF

test_flush_in_finalizer1 is test for finalizer of IO (see #3910) and
GC.disable breaks it's intent.
I'm sorry, but I'd like to revert r35631.
And I'll commit my patch. Please check it.

Bug #6228: [mingw] Errno::EBADF in ruby/test_io.rb on ruby_1_9_3
https://bugs.ruby-lang.org/issues/6228#change-26601

Author: jonforums (Jon Forums)
Status: Assigned
Priority: Normal
Assignee: luislavena (Luis Lavena)
Category: test
Target version: 1.9.3
ruby -v: ruby 1.9.3p172 (2012-03-30 revision 35179) [i386-mingw32]

On Win7 32bit built with MinGW 4.6.2 using the RubyInstaller build
recipes, I get the following test error:

sh-3.1$ ruby --version
ruby 1.9.3p172 (2012-03-30 revision 35179) [i386-mingw32]

sh-3.1$ make test-all TESTS='openssl fiddle psych zlib io json mkmf
pathname stringio erb
fileutils ruby/test_io.rb ruby/test_io_m17n.rb ruby/test_file.rb'

7. Error:
   test_lines(TestIO):
   Errno::EBADF: Bad file descriptor
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:33:in
   close' c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:33:in rescue in block in pipe'
   c:/Users/Jon/Documents/RubyDev/ruby-git/test/ruby/test_io.rb:30:in
   `block in pipe'

--
http://bugs.ruby-lang.org/