Bug #1162: Build Assertion Failure with VC+++ - Incorrect flushing of stdout/stderr

• Status: Closed
• Assignee: wyhaines (Kirk Haines)
• Target version: -
• ruby -v: ruby 1.9.1p0 (2009-01-30 revision 21907) [i386-mswin32_90]
• Backport: 2.5: UNKNOWN, 2.6: UNKNOWN

[cfis (Charlie Savage)]

=begin
Build ruby 1.9.1 with VC 2008 using the following flags:

RUNTIMEFLAG = -MDd
OPTFLAGS = -Od -RTC1
LDFLAGS = -link -INCREMENTAL:NO -DEBUG -OPT:REF -OPT:ICF

Failure occurs when running miniruby.exe for the first time:

File: f:\dd\vctools\crt_bld\self_x86\src\commit.c, line 69.
Expression: ("Invalid file descriptor. File possibly closed by a different thread", 0)

The call sequence:

rb_io_flush -> fsync -> _commit -> FlushFileBuffers

The stream is stdout or stderr.

From Microsoft's documentation of FlushFileBuffers (http://msdn.microsoft.com/en-us/library/aa364439(VS.85).aspx):

The function fails if hFile is a handle to the console output. That is because the console output is not buffered. The function returns FALSE, and GetLastError returns ERROR_INVALID_HANDLE.

Thus calling _commit on STDOUT or STDERR is invalid.

This patch fixes the problem:

--- io.old.c 2009-02-14 14:27:15 -0700
+++ io.c 2009-02-14 14:27:20 -0700
@@ -1002,7 +1002,8 @@
if (io_fflush(fptr) < 0)
rb_sys_fail(0);
#ifdef _WIN32

• fsync(fptr->fd);

• if (io != rb_stdout && io != rb_stderr)

•  fsync(fptr->fd);
  

#endif
}
if (fptr->mode & FMODE_READABLE) {
=end

[cfis (Charlie Savage)]

=begin
Microsoft documentation is at:

http://msdn.microsoft.com/en-us/library/aa364439.aspx
=end

[nobu (Nobuyoshi Nakada)]

=begin
Hi,

At Sun, 15 Feb 2009 06:27:35 +0900,
Charlie Savage wrote in [ruby-core:22116]:

Failure occurs when running miniruby.exe for the first time:

File: f:\dd\vctools\crt_bld\self_x86\src\commit.c, line 69.
Expression: ("Invalid file descriptor. File possibly closed by a different thread", 0)

It's false assertion. Report it to Microsoft.

--
Nobu Nakada

=end

[cfis (Charlie Savage)]

=begin
Hi Nobu,

The error message is poor, but this is still a bug in ruby. Let me show you the code:

Starting at Visual Studio 9.0\VC\crt\src\commit.c, line 51:

     if ( !FlushFileBuffers((HANDLE)_get_osfhandle(filedes)) ) {
             retval = GetLastError();
     }
     else {
             retval = 0;     /* return success */
     }

     /* map the OS return code to C errno value and return code */
     if (retval == 0)
             goto good;

     _doserrno = retval;

             }

     errno = EBADF;
     retval = -1;

     _ASSERTE(("Invalid file descriptor. File possibly closed by a different thread",0));

As Microsoft's documentation states (see link above), it is incorrect to pass stdout or stderr to FlushFileBuffers. Therefore FlushFileBuffers fails and retval is set to 6 via the call to GetLastError. From http://msdn.microsoft.com/en-us/library/ms681382(VS.85).aspx:

ERROR_INVALID_HANDLE 6 0x6

So the assertion fails. Bad error message I agree, but still a bug in Ruby.

=end

[nobu (Nobuyoshi Nakada)]

=begin
Hi,

At Sun, 15 Feb 2009 16:24:24 +0900,
Charlie Savage wrote in [ruby-core:22134]:

As Microsoft's documentation states (see link above), it is
incorrect to pass stdout or stderr to FlushFileBuffers.
Therefore FlushFileBuffers fails and retval is set to 6 via
the call to GetLastError. From
http://msdn.microsoft.com/en-us/library/ms681382(VS.85).aspx:

Yes, it's a reasonable and expected behavior.

So the assertion fails. Bad error message I agree, but still a bug in Ruby.

It's not a bug, the file descriptor is not invalid, nor closed.
Just a false positive assertion, e.g., a bug of msvcrt.

--
Nobu Nakada

=end

[nobu (Nobuyoshi Nakada)]

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

=begin
Applied in changeset r22333.
=end

[cfis (Charlie Savage)]

=begin
Hi Nobu,

Thanks for your help on this.

However, I think your patch is the wrong approach. If I understand the intention correctly, it is meant to stub out all crt debug messages. Is such a strong remedy needed to solve this one issue? Take for example the other VC++ bug I submitted about the unassigned variable - your patch would hide it (assuming I am understanding the patch correctly). Or what about more serious issues such as using ALLOC in tandem with free instead of xfree on the Windows platform? Do we want to disable those also?

The other problem with the patch is that it doesn't actually work. To test it I applied to locally. The assertion error does not go away and it still not possible to build Ruby with the -RTC1 flag.

So would you be willing to revert this patch?

As for the original problem, I'll make my pitch one more time and then if you still disagree I'll just have to patch my own version of ruby 1.9.1. Quoting MSDN - http://msdn.microsoft.com/en-us/library/aa364439(VS.85).aspx.

"The function fails if hFile is a handle to the console output. That is because the console output is not buffered. The function returns FALSE, and GetLastError returns ERROR_INVALID_HANDLE."

Seeing that Microsoft's documentation says it invalid to pass stdout or stderr to FlushFileBuffers, and _commit calls FlushFileBuffers, I have a hard time seeing that this is a bug in msvcrt.

=end

[nobu (Nobuyoshi Nakada)]

=begin
Hi,

At Mon, 16 Feb 2009 07:40:51 +0900,
Charlie Savage wrote in [ruby-core:22170]:

The other problem with the patch is that it doesn't actually
work. To test it I applied to locally. The assertion error
does not go away and it still not possible to build Ruby with
the -RTC1 flag.

It is a compile time flag and irrelevant to debug built msvcrt.

As for the original problem, I'll make my pitch one more time
and then if you still disagree I'll just have to patch my own
version of ruby 1.9.1. Quoting MSDN -
http://msdn.microsoft.com/en-us/library/aa364439(VS.85).aspx.

It does mention about FlushFileBuffers() only, not _commit().
And says just it returns an error, not make the process
crashed.

Seeing that Microsoft's documentation says it invalid to pass
stdout or stderr to FlushFileBuffers, and _commit calls
FlushFileBuffers, I have a hard time seeing that this is a
bug in msvcrt.

Feel free to call it a bug or a paranoiac false assertion of
msvcrt, and now disabled already, at r22337.

--
Nobu Nakada

=end

[cfis (Charlie Savage)]

=begin

It is a compile time flag and irrelevant to debug built msvcrt.

Not sure what you mean. VC2008 (and earlier versions) set the -RTC1 flag by default when creating debug builds of C/C++ projects. The -RTC1 flag causes the binary to use a debug version of the C runtime libraries. These libraries are helpful in diagnosing memory problems or other incorrect usages of the C runtime library.

Since the Ruby build process depends on creating a working version of miniruby.exe, setting -RTC1 means you can't build a debug version of Ruby because miniruby crashes when invoked with an assertion error.

It does mention about FlushFileBuffers() only, not _commit().
And says just it returns an error, not make the process
crashed.

Well commit calls FlushFileBuffers, so its seems that documentation is applicable. And when you look at the documentation for _commit it says http://msdn.microsoft.com/en-us/library/17618685(VS.80).aspx

If fd is an invalid file descriptor, the invalid parameter handler is invoked, as described in Parameter Validation. If execution is allowed to continue...

In a debug build, execution is not allowed to continue because an assertion error is raised.

Feel free to call it a bug or a paranoiac false assertion of
msvcrt, and now disabled already, at r22337.

r22337 does not fix the problem. Try it with a debug build using VC2008 using the standard values set by VC2008 (/Od /D "WIN32" /D "_DEBUG" /Gm /EHsc /RTC1 /MDd /W3 /c /ZI /TP). It will crash.

I still consider this a bug - Ruby is passing an invalid file handle to commit. In a release build this will generate a "Invalid handle error" error code which Ruby ignores. In a debug build it triggers an assertion failure that causes Ruby to crash.

Once again the fix is simple and only affects windows:

#ifdef _WIN32

• fsync(fptr->fd);

• if (io != rb_stdout && io != rb_stderr)

•  fsync(fptr->fd);
  

#endif

The only new line of code is the if statement.

So, I really think this is the way to solve the problem and r22337 should be reverted.

Thanks,

Charlie

is used by default VC2008 is of

Yes, its a compile time flag. What do you mean though its irrelevant to a debug built msvcrt?
=end

[nobu (Nobuyoshi Nakada)]

=begin
Hi,

At Mon, 23 Feb 2009 12:44:32 +0900,
Charlie Savage wrote in [ruby-core:22345]:

It is a compile time flag and irrelevant to debug built msvcrt.

Not sure what you mean. VC2008 (and earlier versions) set
the -RTC1 flag by default when creating debug builds of C/C++
projects. The -RTC1 flag causes the binary to use a debug
version of the C runtime libraries. These libraries are
helpful in diagnosing memory problems or other incorrect
usages of the C runtime library.

You are wrong about -RTC1. It does emit checking code but
doesn't imply to link with msvcrtd.lib. -MDd flag directs it.
You can compile with -RTC1 and no -MDd.

　> Well commit calls FlushFileBuffers, so its seems that

documentation is applicable. And when you look at the
documentation for _commit it says
http://msdn.microsoft.com/en-us/library/17618685(VS.80).aspx

That page describes nothing about the assertion.

r22337 does not fix the problem. Try it with a debug build
using VC2008 using the standard values set by VC2008 (/Od /D
"WIN32" /D "_DEBUG" /Gm /EHsc /RTC1 /MDd /W3 /c /ZI /TP). It
will crash.

/EHsc and /TP are specific for C++. I could compile fine with
RUNTIMEFLAG=-MDd OPTFLAGS="-Od -RTC1" DEBUGFLAGS="-D_DEBUG
-DWIN32", and no assertion dialog. The dialog appeared by
commenting out the line _CrtSetReportMode(_CRT_ASSERT, 0) in
win32/win32.c:rb_w32_sysinit().

Once again the fix is simple and only affects windows:

Your ``fix'' simply doesn't work with other IOs. Try:

open("CONOUT$", "w").flush

--
Nobu Nakada

=end

[cfis (Charlie Savage)]

=begin
Hi Nobu,

Sorry, I've been out the last few days.

You are wrong about -RTC1. It does emit checking code but
doesn't imply to link with msvcrtd.lib. -MDd flag directs it.
You can compile with -RTC1 and no -MDd.

Yes, I agree these are different things. I was just pointing out that a debug build in Visual Studio by default sets both of these flags (create a new project, look at the debug build flags).

Your ``fix'' simply doesn't work with other IOs. Try:

open("CONOUT$", "w").flush

Yes, that fails with the same assertion error, with or without my patch. And it fails for the exact same reason - you can't use _commit to flush CONOUT because its a console buffer.

As I've stated earlier, I think using _CrtSetReportMode is the wrong solution. First it simply ignores the problem and second it could potentially hide other, more serious issues.

Maybe there is a better solution we could come up with? The goal is not to call flush on console buffers on windows, because that either returns a ERROR_INVALID_HANDLE error or causes an assertion failure (when the executable is built with -RTC1). So either way you look at it, these calls on Windows are incorrect.

Is there some way that console buffers (STDERR, STDOUT, CONOUT) can be easily recognized? Maybe checking fptr->stdio_file (its NULL in your example)?

Thanks,

Charlie
=end

[shyouhei (Shyouhei Urabe)]

• Status changed from Closed to Open
• Assignee set to wyhaines (Kirk Haines)

=begin

=end

[shyouhei (Shyouhei Urabe)]

• Status changed from Open to Assigned

=begin

=end

[jeremyevans0 (Jeremy Evans)]

• Tracker changed from Backport to Bug
• Project changed from 11 to Ruby
• Description updated (diff)
• Status changed from Assigned to Closed
• ruby -v set to ruby 1.9.1p0 (2009-01-30 revision 21907) [i386-mswin32_90]
• Backport set to 2.5: UNKNOWN, 2.6: UNKNOWN