1361037 – [ruby] Invalid stdio handle error during tests run

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1361037 - [ruby] Invalid stdio handle error during tests run

Summary: [ruby] Invalid stdio handle error during tests run

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	ruby
Sub Component:
Version:	rawhide
Hardware:	ppc64
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Jeroen van Meeuwen
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	PPCTracker
TreeView+	depends on / blocked

Reported:	2016-07-28 08:32 UTC by Rafael Fonseca
Modified:	2016-08-27 10:42 UTC (History)
CC List:	12 users (show)
Fixed In Version:	ruby-2.3.1-58.fc25
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-08-27 10:42:33 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Ruby	12666	0	None	None	None	2016-08-10 16:23:07 UTC

Description Rafael Fonseca 2016-07-28 08:32:22 UTC

Description of problem: when building ruby for ppc64 we're hitting the following error

Fiddle::TestImport#test_io = Fatal error: glibc detected an invalid stdio handle
uncommon.mk:612: recipe for target 'yes-test-almost' failed
make: *** [yes-test-almost] Aborted (core dumped)


Version-Release number of selected component (if applicable): 2.3.1-57


How reproducible: always on ppc-koji



Additional info: build log http://ppc.koji.fedoraproject.org/koji/taskinfo?taskID=3561716

Comment 1 Rafael Fonseca 2016-07-28 12:20:19 UTC

For ppc64le, the error is a bit different:

  1) Failure:
TestSocketNonblock#test_udp_recv_nonblock [/builddir/build/BUILD/ruby-2.3.1/test/socket/test_nonblock.rb:128]:
cygwin 1.5.19 has a problem to send an empty UDP packet. [ruby-dev:28915].
Exception raised:
<#<Timeout::Error: execution expired>>.

  2) Failure:
TestSocketNonblock#test_udp_recvfrom_nonblock [/builddir/build/BUILD/ruby-2.3.1/test/socket/test_nonblock.rb:106]:
cygwin 1.5.19 has a problem to send an empty UDP packet. [ruby-dev:28915].
Exception raised:
<#<Timeout::Error: execution expired>>.

15847 tests, 2235440 assertions, 2 failures, 0 errors, 38 skips

ruby -v: ruby 2.3.1p112 (2016-04-26 revision 54768) [powerpc64le-linux]
uncommon.mk:612: recipe for target 'yes-test-almost' failed
make: *** [yes-test-almost] Error 2

Comment 2 Dan Horák 2016-08-05 09:28:21 UTC

from a recent scratch build on f25 ppc64le

...

                         
test_thread.rb           ...Fstderr output is not empty
   bootstraptest.tmp.rb:4:in `initialize': can't create Thread: Resource temporarily unavailable (ThreadError)
           from bootstraptest.tmp.rb:4:in `new'
           from bootstraptest.tmp.rb:4:in `block (2 levels) in <main>'
           from bootstraptest.tmp.rb:3:in `each'
           from bootstraptest.tmp.rb:3:in `map'
           from bootstraptest.tmp.rb:3:in `block in <main>'
           from bootstraptest.tmp.rb:2:in `times'
           from bootstraptest.tmp.rb:2:in `<main>'
uncommon.mk:581: recipe for target 'yes-btest-ruby' failed
make: *** [yes-btest-ruby] Error 1

Comment 3 Dan Horák 2016-08-05 09:30:01 UTC

in general it's unlikely a ruby issue as the change between successful -56 and unsuccessful -57 is http://pkgs.fedoraproject.org/cgit/rpms/ruby.git/commit/?id=b1466a4c8f2cd28556efcd93c5dc539bff041be9

Comment 4 Dan Horák 2016-08-05 09:49:38 UTC

and a F-24 build of the same srpm succeeds - http://ppc.koji.fedoraproject.org/koji/taskinfo?taskID=3582342

Comment 5 Dan Horák 2016-08-08 18:03:53 UTC

(In reply to Rafael Fonseca from comment #0)
> Description of problem: when building ruby for ppc64 we're hitting the
> following error
> 
> Fiddle::TestImport#test_io = Fatal error: glibc detected an invalid stdio
> handle
> uncommon.mk:612: recipe for target 'yes-test-almost' failed
> make: *** [yes-test-almost] Aborted (core dumped)
> 
> 
> Version-Release number of selected component (if applicable): 2.3.1-57
> 
> 
> How reproducible: always on ppc-koji
> 
> 
> 
> Additional info: build log
> http://ppc.koji.fedoraproject.org/koji/taskinfo?taskID=3561716

the backtrace looks like

(gdb) where
#0  0x00003fff8e6a0888 in __GI_raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00003fff8e6a2af4 in __GI_abort () at abort.c:89
#2  0x00003fff8e6e9b88 in __libc_message (do_abort=<optimized out>, fmt=<optimized out>) at ../sysdeps/posix/libc_fatal.c:175
#3  0x00003fff8e6e9bf0 in __GI___libc_fatal (message=0x3fff8e7fb770 "Fatal error: glibc detected an invalid stdio handle\n") at ../sysdeps/posix/libc_fatal.c:185
#4  0x00003fff8e6ea774 in _IO_vtable_check () at vtables.c:69
#5  0x00003fff8e6be664 in IO_validate_vtable (vtable=0x3fff984a1bf0 <__GI__IO_file_jumps>) at ../libio/libioP.h:940
#6  _IO_vfprintf_internal (s=0x1001da241c0, format=0x1001b9bc3d0 "hello", ap=0x3fffd828aee0 "") at vfprintf.c:1320
#7  0x00003fff8e6c585c in __fprintf (stream=<optimized out>, format=<optimized out>) at fprintf.c:32
#8  0x00003fff8e8679a4 in .ffi_call_LINUX64 () at ../src/powerpc/linux64.S:133
#9  0x00003fff8e866ad0 in ffi_call (cif=0x10021a32860, fn=<optimized out>, rvalue=0x3fffd828b270, avalue=0x3fffd828b220) at ../src/powerpc/ffi.c:100
#10 0x00003fff8e8976c4 in nogvl_ffi_call (ptr=<optimized out>) at function.c:160
#11 0x00003fff988f98c4 in call_without_gvl (func=@0x3fff8e8af278: 0x3fff8e8976a0 <nogvl_ffi_call>, data1=0x3fffd828b258, ubf=<optimized out>, data2=<optimized out>, 
    fail_if_interrupted=<optimized out>) at thread.c:1289
#12 0x00003fff8e897428 in function_call (argc=<optimized out>, argv=<optimized out>, self=1099982351040) at function.c:219
#13 0x00003fff988c5534 in call_cfunc_m1 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1459
#14 0x00003fff988d1a24 in vm_call_cfunc_with_frame (ci=0x3fff98a18178 <ruby_vm_event_flags>, cc=0x1001b9515d0, calling=0x1001c0eaac0, reg_cfp=0x3fff916afa10, th=0x1001b9515d0)
    at vm_insnhelper.c:1638
...

the corresponding test code is

ruby-2.3.1/test/fiddle/test_import.rb
...
    def test_io()
      if( RUBY_PLATFORM != BUILD_RUBY_PLATFORM )
        return
      end
      io_in,io_out = IO.pipe()
      LIBC.fprintf(io_out, "hello")
      io_out.flush()
      io_out.close()
      str = io_in.read()
      io_in.close()
      assert_equal("hello", str)
    end

Comment 6 Vít Ondruch 2016-08-09 06:52:58 UTC

This obviously calls fprintf from glibc via FFI.

libffi have not changed for ages, so what about glibc?

Comment 7 Vít Ondruch 2016-08-09 06:55:30 UTC

And looking at yesterdays build, it failed on PPC the same way as on primary ... interesting. I thought it is just some random threading glitch ...

Comment 8 Dan Horák 2016-08-09 07:06:46 UTC

(In reply to Vít Ondruch from comment #6)
> This obviously calls fprintf from glibc via FFI.
> 
> libffi have not changed for ages, so what about glibc?

I've tried with older glibc, was still failing.

But now I understand nothing, same guest, no changes, 9 hours ago it was consistently failing with the "invalid stdio handle", now it gets over and fails much later with the "empty UDP packet" ...

Comment 9 Florian Weimer 2016-08-10 02:06:56 UTC

(In reply to Dan Horák from comment #2)
> from a recent scratch build on f25 ppc64le
> 
> ...
> 
>                          
> test_thread.rb           ...Fstderr output is not empty
>    bootstraptest.tmp.rb:4:in `initialize': can't create Thread: Resource
> temporarily unavailable (ThreadError)
>            from bootstraptest.tmp.rb:4:in `new'
>            from bootstraptest.tmp.rb:4:in `block (2 levels) in <main>'
>            from bootstraptest.tmp.rb:3:in `each'
>            from bootstraptest.tmp.rb:3:in `map'
>            from bootstraptest.tmp.rb:3:in `block in <main>'
>            from bootstraptest.tmp.rb:2:in `times'
>            from bootstraptest.tmp.rb:2:in `<main>'
> uncommon.mk:581: recipe for target 'yes-btest-ruby' failed
> make: *** [yes-btest-ruby] Error 1

This looks similar to an issue Carlos saw in recent glibc builds (on multiple architectures).  pthread_create was failing with EAGAIN there as well.  At present, we don't think this was caused by a change in glibc.

Comment 10 Florian Weimer 2016-08-10 02:30:24 UTC

(In reply to Dan Horák from comment #5)
> #3  0x00003fff8e6e9bf0 in __GI___libc_fatal (message=0x3fff8e7fb770 "Fatal
> error: glibc detected an invalid stdio handle\n") at
> ../sysdeps/posix/libc_fatal.c:185

Can you please try this reduced test case:

require 'fiddle'
require 'fiddle/import'

module Fiddle
  module LIBC
    extend Importer
    dlload 'libc.so.6'

    typealias 'FILE*', 'void*'

    extern "int fprintf(FILE*, char*)"
  end
end

io_in,io_out = IO.pipe()
Fiddle::LIBC.fprintf(io_out, "hello\n")
io_out.flush()
io_out.close()
str = io_in.read()
io_in.close()
print str


Run it under GDB, set a breakpoint on fprintf, and get the value of the libio vtable pointer:

(gdb) break fprintf
Breakpoint 1 at 0x7ffff6c97c20: file fprintf.c, line 27.
(gdb) r
Starting program: /usr/bin/ruby-mri test_import.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff7ff5700 (LWP 30422)]

Breakpoint 1, __fprintf (stream=0x555555bba460, format=0x555555a7d038 "hello\n") at fprintf.c:27
27	{
(gdb) bt
#0  __fprintf (stream=0x555555bba460, format=0x555555a7d038 "hello\n") at fprintf.c:27
#1  0x00007fffef565d30 in ffi_call_unix64 () from /lib64/libffi.so.6
#2  0x00007fffef56579b in ffi_call () from /lib64/libffi.so.6
#3  0x00007fffef76b3d9 in function_call () from /usr/lib64/ruby/fiddle.so
#4  0x00007ffff7adae11 in vm_call_cfunc () from /lib64/libruby.so.2.2
#5  0x00007ffff7aeb32e in vm_call_method () from /lib64/libruby.so.2.2
#6  0x00007ffff7ade917 in vm_exec_core () from /lib64/libruby.so.2.2
#7  0x00007ffff7ae420d in vm_exec () from /lib64/libruby.so.2.2
#8  0x00007ffff7ae573f in rb_iseq_eval_main () from /lib64/libruby.so.2.2
#9  0x00007ffff79cfcad in ruby_exec_internal () from /lib64/libruby.so.2.2
#10 0x00007ffff79d184d in ruby_exec_node () from /lib64/libruby.so.2.2
#11 0x00007ffff79d37ae in ruby_run_node () from /lib64/libruby.so.2.2
#12 0x00005555555549ab in main ()
(gdb) print *stream
$1 = {_flags = -72539004, _IO_read_ptr = 0x0, _IO_read_end = 0x0, _IO_read_base = 0x0, _IO_write_base = 0x0, _IO_write_ptr = 0x0, 
  _IO_write_end = 0x0, _IO_buf_base = 0x0, _IO_buf_end = 0x0, _IO_save_base = 0x0, _IO_backup_base = 0x0, _IO_save_end = 0x0, _markers = 0x0, 
  _chain = 0x7ffff7000560 <_IO_2_1_stderr_>, _fileno = 8, _flags2 = 0, _old_offset = 93824998941808, _cur_column = 0, _vtable_offset = -89 '\247', 
  _shortbuf = "U", _lock = 0x555555bba540, _offset = -1, _codecvt = 0x555555bba440, _wide_data = 0x555555bba550, _freeres_list = 0x0, 
  _freeres_buf = 0x555555bba4d8, _freeres_size = 5, _mode = 0, _unused2 = "\000\000\000\000\002\000\000\000\000\000\000\000\200\246\273UUU\000"}
(gdb) print stream + 1
$2 = (FILE *) 0x555555bba538
(gdb) print *(void **)(stream + 1)
$3 = (void *) 0x7ffff6ffe6c0 <__GI__IO_file_jumps>

I wonder if it is still equal to __GI__IO_file_jumps.

Comment 11 Dan Horák 2016-08-10 09:13:34 UTC

self-note how to run the test_import.rb from command line (and get the Fatal error):
LD_LIBRARY_PATH=. ./ruby --disable-gems -I. -Ilib -I.ext/common -I.ext/powerpc64-linux test/runner.rb test/fiddle/test_import.rb

Comment 12 Dan Horák 2016-08-10 12:00:42 UTC

I wasn't able to reproduce the crash with the reduced test case, but the full test case returns

(gdb) run
Starting program: /home/sharkcz/ruby/ruby-2.3.1/ruby --disable-gems -I. -Ilib -I.ext/common -I.ext/powerpc64-linux test/runner.rb test/fiddle/test_import.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/power8/libthread_db.so.1".
[New Thread 0x3fffb75bf190 (LWP 21384)]
Run options: 

# Running tests:

[ 8/24] Fiddle::TestImport#test_io                      
Thread 1 "ruby" hit Breakpoint 1, __fprintf (stream=0x206f7b10, format=0x200487a0 "hello") at fprintf.c:27
27	{
(gdb) bt
#0  __fprintf (stream=0x206f7b10, format=0x200487a0 "hello") at fprintf.c:27
#1  0x00003fffb7447924 in .ffi_call_LINUX64 () at ../src/powerpc/linux64.S:133
#2  0x00003fffb7446a50 in ffi_call (cif=0x204be420, fn=<optimized out>, rvalue=0x3fffffffb440, avalue=0x3fffffffb3f0) at ../src/powerpc/ffi.c:100
#3  0x00003fffb7485c84 in nogvl_ffi_call (ptr=<optimized out>) at function.c:160
#4  0x00003fffb7e5ba84 in call_without_gvl (func=@0x3fffb749f108: 0x3fffb7485c60 <nogvl_ffi_call>, data1=0x3fffffffb428, ubf=<optimized out>, data2=<optimized out>, 
    fail_if_interrupted=<optimized out>) at thread.c:1289
#5  0x00003fffb74859e8 in function_call (argc=<optimized out>, argv=<optimized out>, self=537355600) at function.c:219
#6  0x00003fffb7e276f4 in call_cfunc_m1 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1459
#7  0x00003fffb7e33be4 in vm_call_cfunc_with_frame (ci=0x3fffb7f782c8 <ruby_vm_event_flags>, cc=0x200320d0, calling=0x20076550, reg_cfp=0x3fffb76bfa10, th=0x200320d0)
    at vm_insnhelper.c:1638
#8  vm_call_cfunc (th=th@entry=0x200320d0, reg_cfp=reg_cfp@entry=0x3fffb76bfa10, calling=calling@entry=0x3fffffffb8b8, ci=ci@entry=0x20408a20, cc=cc@entry=0x204a1e58)
    at vm_insnhelper.c:1733
#9  0x00003fffb7e44464 in vm_call_method_each_type (th=0x200320d0, cfp=0x3fffb76bfa10, calling=0x3fffffffb8b8, ci=0x20408a20, cc=0x204a1e58) at vm_insnhelper.c:2022
#10 0x00003fffb7e45794 in vm_call_method (cc=0x204a1e58, ci=0x20408a20, calling=0x3fffffffb8b8, cfp=0x3fffb76bfa10, th=0x200320d0) at vm_insnhelper.c:2157
#11 vm_call_general (th=0x200320d0, reg_cfp=0x3fffb76bfa10, calling=0x3fffffffb8b8, ci=0x20408a20, cc=0x204a1e58) at vm_insnhelper.c:2189
#12 0x00003fffb7e38784 in vm_exec_core (th=th@entry=0x200320d0, initial=initial@entry=0) at insns.def:964
#13 0x00003fffb7e3dce8 in vm_exec (th=th@entry=0x200320d0) at vm.c:1650
#14 0x00003fffb7e4627c in invoke_block (block=0x3fffb76bfbb0, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=537550960, iseq=0x20297820, th=0x200320d0) at vm.c:921
#15 invoke_block_from_c_0 (splattable=1, cref=0x0, blockptr=0x0, argv=0x3fffffffc170, argc=1, self=537550960, block=0x3fffb76bfbb0, th=0x200320d0) at vm.c:971
#16 invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x3fffffffc170, argc=1, self=537550960, block=0x3fffb76bfbb0, th=0x200320d0) at vm.c:988
#17 vm_yield (argv=0x3fffffffc170, argc=1, th=0x200320d0) at vm.c:1023
#18 rb_yield_0 (argv=0x3fffffffc170, argc=1) at vm_eval.c:1010
#19 rb_yield_1 (val=<optimized out>) at vm_eval.c:1016
#20 rb_yield (val=<optimized out>) at vm_eval.c:1026
#21 0x00003fffb7c7d594 in rb_ary_collect (ary=537172600) at array.c:2733
#22 0x00003fffb7e2774c in call_cfunc_0 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1465
#23 0x00003fffb7e33be4 in vm_call_cfunc_with_frame (ci=<optimized out>, cc=<optimized out>, calling=<optimized out>, reg_cfp=0x3fffb76bfb90, th=0x200320d0) at vm_insnhelper.c:1638
#24 vm_call_cfunc (th=0x200320d0, reg_cfp=0x3fffb76bfb90, calling=<optimized out>, ci=<optimized out>, cc=<optimized out>) at vm_insnhelper.c:1733
#25 0x00003fffb7e38784 in vm_exec_core (th=th@entry=0x200320d0, initial=initial@entry=0) at insns.def:964
#26 0x00003fffb7e3dce8 in vm_exec (th=th@entry=0x200320d0) at vm.c:1650
#27 0x00003fffb7e4627c in invoke_block (block=0x3fffb76bfcb0, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=537550960, iseq=0x20061448, th=0x200320d0) at vm.c:921
#28 invoke_block_from_c_0 (splattable=1, cref=0x0, blockptr=0x0, argv=0x3fffffffcd50, argc=1, self=537550960, block=0x3fffb76bfcb0, th=0x200320d0) at vm.c:971
#29 invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x3fffffffcd50, argc=1, self=537550960, block=0x3fffb76bfcb0, th=0x200320d0) at vm.c:988
#30 vm_yield (argv=0x3fffffffcd50, argc=1, th=0x200320d0) at vm.c:1023
#31 rb_yield_0 (argv=0x3fffffffcd50, argc=1) at vm_eval.c:1010
#32 rb_yield_1 (val=<optimized out>) at vm_eval.c:1016
#33 rb_yield (val=<optimized out>) at vm_eval.c:1026
#34 0x00003fffb7c78c14 in rb_ary_each (ary=544830040) at array.c:1815
#35 0x00003fffb7e2774c in call_cfunc_0 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1465
#36 0x00003fffb7e33be4 in vm_call_cfunc_with_frame (ci=0x3fffb7f782c8 <ruby_vm_event_flags>, cc=0x200320d0, calling=0x20797258, reg_cfp=0x3fffb76bfc90, th=0x200320d0)
    at vm_insnhelper.c:1638
#37 vm_call_cfunc (th=th@entry=0x200320d0, reg_cfp=reg_cfp@entry=0x3fffb76bfc90, calling=calling@entry=0x3fffffffd218, ci=ci@entry=0x201b99b0, cc=cc@entry=0x2024f910)
    at vm_insnhelper.c:1733
#38 0x00003fffb7e44464 in vm_call_method_each_type (th=0x200320d0, cfp=0x3fffb76bfc90, calling=0x3fffffffd218, ci=0x201b99b0, cc=0x2024f910) at vm_insnhelper.c:2022
#39 0x00003fffb7e45794 in vm_call_method (cc=0x2024f910, ci=0x201b99b0, calling=0x3fffffffd218, cfp=0x3fffb76bfc90, th=0x200320d0) at vm_insnhelper.c:2157
#40 vm_call_general (th=0x200320d0, reg_cfp=0x3fffb76bfc90, calling=0x3fffffffd218, ci=0x201b99b0, cc=0x2024f910) at vm_insnhelper.c:2189
#41 0x00003fffb7e38784 in vm_exec_core (th=th@entry=0x200320d0, initial=initial@entry=0) at insns.def:964
#42 0x00003fffb7e3dce8 in vm_exec (th=th@entry=0x200320d0) at vm.c:1650
#43 0x00003fffb7e4627c in invoke_block (block=0x3fffb76bfe30, opt_pc=<optimized out>, type=<optimized out>, cref=0x0, self=537550960, iseq=0x20296128, th=0x200320d0) at vm.c:921
#44 invoke_block_from_c_0 (splattable=1, cref=0x0, blockptr=0x0, argv=0x3fffffffdad0, argc=1, self=537550960, block=0x3fffb76bfe30, th=0x200320d0) at vm.c:971
#45 invoke_block_from_c_splattable (cref=0x0, blockptr=0x0, argv=0x3fffffffdad0, argc=1, self=537550960, block=0x3fffb76bfe30, th=0x200320d0) at vm.c:988
#46 vm_yield (argv=0x3fffffffdad0, argc=1, th=0x200320d0) at vm.c:1023
#47 rb_yield_0 (argv=0x3fffffffdad0, argc=1) at vm_eval.c:1010
#48 rb_yield_1 (val=<optimized out>) at vm_eval.c:1016
#49 rb_yield (val=<optimized out>) at vm_eval.c:1026
#50 0x00003fffb7c78c14 in rb_ary_each (ary=544830240) at array.c:1815
#51 0x00003fffb7e2774c in call_cfunc_0 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1465
---Type <return> to continue, or q <return> to quit---
#52 0x00003fffb7e33be4 in vm_call_cfunc_with_frame (ci=0x3fffb7f782c8 <ruby_vm_event_flags>, cc=0x200320d0, calling=0x20797320, reg_cfp=0x3fffb76bfe10, th=0x200320d0)
    at vm_insnhelper.c:1638
#53 vm_call_cfunc (th=th@entry=0x200320d0, reg_cfp=reg_cfp@entry=0x3fffb76bfe10, calling=calling@entry=0x3fffffffdf98, ci=ci@entry=0x202a0cb0, cc=cc@entry=0x202a0e38)
    at vm_insnhelper.c:1733
#54 0x00003fffb7e44464 in vm_call_method_each_type (th=0x200320d0, cfp=0x3fffb76bfe10, calling=0x3fffffffdf98, ci=0x202a0cb0, cc=0x202a0e38) at vm_insnhelper.c:2022
#55 0x00003fffb7e45794 in vm_call_method (cc=0x202a0e38, ci=0x202a0cb0, calling=0x3fffffffdf98, cfp=0x3fffb76bfe10, th=0x200320d0) at vm_insnhelper.c:2157
#56 vm_call_general (th=0x200320d0, reg_cfp=0x3fffb76bfe10, calling=0x3fffffffdf98, ci=0x202a0cb0, cc=0x202a0e38) at vm_insnhelper.c:2189
#57 0x00003fffb7e38784 in vm_exec_core (th=th@entry=0x200320d0, initial=initial@entry=0) at insns.def:964
#58 0x00003fffb7e3dce8 in vm_exec (th=0x200320d0) at vm.c:1650
#59 0x00003fffb7cced54 in ruby_exec_internal (n=0x200563e0) at eval.c:245
#60 0x00003fffb7cd1478 in ruby_exec_node (n=<optimized out>) at eval.c:310
#61 0x00003fffb7cd4400 in ruby_run_node (n=0x200563e0) at eval.c:302
#62 0x0000000020000c80 in main (argc=<optimized out>, argv=<optimized out>) at main.c:36
(gdb) print *stream
$1 = {_flags = -72539004, _IO_read_ptr = 0x0, _IO_read_end = 0x0, _IO_read_base = 0x0, _IO_write_base = 0x0, _IO_write_ptr = 0x0, _IO_write_end = 0x0, _IO_buf_base = 0x0, 
  _IO_buf_end = 0x0, _IO_save_base = 0x0, _IO_backup_base = 0x0, _IO_save_end = 0x0, _markers = 0x0, _chain = 0x3fffb79518a0 <_IO_2_1_stderr_>, _fileno = 9, _flags2 = 0, _old_offset = 0, 
  _cur_column = 0, _vtable_offset = 0 '\000', _shortbuf = "", _lock = 0x206f7bf0, _offset = -1, _codecvt = 0x6578706563746564, _wide_data = 0x206f7c00, _freeres_list = 0x0, 
  _freeres_buf = 0x3a617267732c203a, __pad5 = 8243122744761003040, _mode = 0, _unused2 = "ck)\n", '\000' <repeats 15 times>}
(gdb) print stream + 1
$2 = (FILE *) 0x206f7be8
(gdb) print *(void **)(stream + 1)
$3 = (void *) 0x3fffb7941c30 <__GI__IO_file_jumps>
(gdb) cont
Continuing.
Fatal error: glibc detected an invalid stdio handle

Thread 1 "ruby" received signal SIGABRT, Aborted.
0x00003fffb72807ac in __libc_signal_restore_set (set=0x3fffffffa550) at ../sysdeps/unix/sysv/linux/nptl-signals.h:79
79	  return INTERNAL_SYSCALL (rt_sigprocmask, err, 4, SIG_SETMASK, set, NULL,
(gdb)

Comment 13 Dan Horák 2016-08-10 12:03:40 UTC

The standalone case gives

(gdb) run
Starting program: /home/sharkcz/ruby/ruby-2.3.1/ruby --disable-gems -I. -Ilib -I.ext/common -I.ext/powerpc64-linux ../test_import.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/power8/libthread_db.so.1".
[New Thread 0x3fffb75bf190 (LWP 21413)]

Thread 1 "ruby" hit Breakpoint 1, __fprintf (stream=0x201fe670, format=0x20202dc0 "hello\n") at fprintf.c:27
27	{
Missing separate debuginfos, use: dnf debuginfo-install gmp-6.1.1-1.fc25.ppc64
(gdb) w
Ambiguous command "w": watch, wh, whatis, where, while, while-stepping, winheight, ws.
(gdb) bt
#0  __fprintf (stream=0x201fe670, format=0x20202dc0 "hello\n") at fprintf.c:27
#1  0x00003fffb74d7924 in .ffi_call_LINUX64 () at ../src/powerpc/linux64.S:133
#2  0x00003fffb74d6a50 in ffi_call (cif=0x201e2820, fn=<optimized out>, rvalue=0x3fffffffdb30, avalue=0x3fffffffdae0) at ../src/powerpc/ffi.c:100
#3  0x00003fffb7515c84 in nogvl_ffi_call (ptr=<optimized out>) at function.c:160
#4  0x00003fffb7e5ba84 in call_without_gvl (func=@0x3fffb752f108: 0x3fffb7515c60 <nogvl_ffi_call>, data1=0x3fffffffdb18, ubf=<optimized out>, data2=<optimized out>, 
    fail_if_interrupted=<optimized out>) at thread.c:1289
#5  0x00003fffb75159e8 in function_call (argc=<optimized out>, argv=<optimized out>, self=538982160) at function.c:219
#6  0x00003fffb7e276f4 in call_cfunc_m1 (func=<optimized out>, recv=<optimized out>, argc=<optimized out>, argv=<optimized out>) at vm_insnhelper.c:1459
#7  0x00003fffb7e33be4 in vm_call_cfunc_with_frame (ci=0x3fffb7f782c8 <ruby_vm_event_flags>, cc=0x200320d0, calling=0x20203710, reg_cfp=0x3fffb76bff50, th=0x200320d0)
    at vm_insnhelper.c:1638
#8  vm_call_cfunc (th=th@entry=0x200320d0, reg_cfp=reg_cfp@entry=0x3fffb76bff50, calling=calling@entry=0x3fffffffdfa8, ci=ci@entry=0x201ea9c0, cc=cc@entry=0x201f9788)
    at vm_insnhelper.c:1733
#9  0x00003fffb7e44464 in vm_call_method_each_type (th=0x200320d0, cfp=0x3fffb76bff50, calling=0x3fffffffdfa8, ci=0x201ea9c0, cc=0x201f9788) at vm_insnhelper.c:2022
#10 0x00003fffb7e45794 in vm_call_method (cc=0x201f9788, ci=0x201ea9c0, calling=0x3fffffffdfa8, cfp=0x3fffb76bff50, th=0x200320d0) at vm_insnhelper.c:2157
#11 vm_call_general (th=0x200320d0, reg_cfp=0x3fffb76bff50, calling=0x3fffffffdfa8, ci=0x201ea9c0, cc=0x201f9788) at vm_insnhelper.c:2189
#12 0x00003fffb7e38784 in vm_exec_core (th=th@entry=0x200320d0, initial=initial@entry=0) at insns.def:964
#13 0x00003fffb7e3dce8 in vm_exec (th=0x200320d0) at vm.c:1650
#14 0x00003fffb7cced54 in ruby_exec_internal (n=0x200584d8) at eval.c:245
#15 0x00003fffb7cd1478 in ruby_exec_node (n=<optimized out>) at eval.c:310
#16 0x00003fffb7cd4400 in ruby_run_node (n=0x200584d8) at eval.c:302
#17 0x0000000020000c80 in main (argc=<optimized out>, argv=<optimized out>) at main.c:36
(gdb) print *stream
$1 = {_flags = -72539004, _IO_read_ptr = 0x0, _IO_read_end = 0x0, _IO_read_base = 0x0, _IO_write_base = 0x0, _IO_write_ptr = 0x0, _IO_write_end = 0x0, _IO_buf_base = 0x0, 
  _IO_buf_end = 0x0, _IO_save_base = 0x0, _IO_backup_base = 0x0, _IO_save_end = 0x0, _markers = 0x0, _chain = 0x3fffb79518a0 <_IO_2_1_stderr_>, _fileno = 9, _flags2 = 0, 
  _old_offset = 4294967296, _cur_column = 0, _vtable_offset = 63 '?', _shortbuf = "\377", _lock = 0x201fe750, _offset = -1, _codecvt = 0x3fffb7950ef0 <main_arena+88>, 
  _wide_data = 0x201fe760, _freeres_list = 0x0, _freeres_buf = 0x201fe750, __pad5 = 70368744165384, _mode = 0, 
  _unused2 = "\000\000\000\v\000\000\000\001\000\000\000\000\000\000\000\000 \037\347\020"}
(gdb) print stream + 1
$2 = (FILE *) 0x201fe748
(gdb) print *(void **)(stream + 1)
$3 = (void *) 0x3fffb7941c30 <__GI__IO_file_jumps>
(gdb) cont
Continuing.
hello
[Thread 0x3fffb75bf190 (LWP 21413) exited]
[Inferior 1 (process 21410) exited normally]

Comment 14 Dan Horák 2016-08-10 12:06:33 UTC

[sharkcz@ibm-p8-generic-01-guest09 ruby-2.3.1]$ ldd ./ruby
	linux-vdso64.so.1 (0x00003fffa7000000)
	libruby.so.2.3 => /home/sharkcz/ruby/ruby-2.3.1/libruby.so.2.3 (0x00003fffa6c50000)
	libpthread.so.0 => /lib64/power8/libpthread.so.0 (0x00003fffa6bf0000)
	libgmp.so.10 => /lib64/libgmp.so.10 (0x00003fffa6b30000)
	libdl.so.2 => /lib64/libdl.so.2 (0x00003fffa6b00000)
	libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00003fffa6ab0000)
	libm.so.6 => /lib64/power8/libm.so.6 (0x00003fffa69b0000)
	libc.so.6 => /lib64/power8/libc.so.6 (0x00003fffa6780000)
	/lib64/ld64.so.1 (0x00000000542d0000)

I have updated the system to latest glibc (scratch built) and rebuilt libffi in f25, just to try latest stuff.

[sharkcz@ibm-p8-generic-01-guest09 ruby-2.3.1]$ rpm -q glibc libffi
glibc-2.24-1.fc25.ppc64
libffi-3.1-9.fc25.1.ppc64

Comment 15 Dan Horák 2016-08-10 12:27:51 UTC

We also see few more test failures where popen() call is involved, might be related to this pipe() one ...

Comment 16 Dan Horák 2016-08-10 13:28:03 UTC

(In reply to Rafael Fonseca from comment #1)
> For ppc64le, the error is a bit different:
> 
>   1) Failure:
> TestSocketNonblock#test_udp_recv_nonblock
> [/builddir/build/BUILD/ruby-2.3.1/test/socket/test_nonblock.rb:128]:
> cygwin 1.5.19 has a problem to send an empty UDP packet. [ruby-dev:28915].
> Exception raised:
> <#<Timeout::Error: execution expired>>.
> 
>   2) Failure:
> TestSocketNonblock#test_udp_recvfrom_nonblock
> [/builddir/build/BUILD/ruby-2.3.1/test/socket/test_nonblock.rb:106]:
> cygwin 1.5.19 has a problem to send an empty UDP packet. [ruby-dev:28915].
> Exception raised:
> <#<Timeout::Error: execution expired>>.

If I can see correctly in my environment, then this problem exists when the running kernel is 4.7 and goes away with kernels 4.6 or 4.5.

Comment 17 Florian Weimer 2016-08-10 14:14:47 UTC

libio vtable verification fails because there are two copies of libc.so.6 in the process:

	0x00003fffb79413a8 - 0x00003fffb7941f78 is __libc_IO_vtables in /lib64/power8/libc.so.6
	0x00003fffb74213c0 - 0x00003fffb7421f90 is __libc_IO_vtables in /lib64/libc.so.6

IO.pipe refers to a vtable from a the first copy, but the fprintf called via libffi comes from the second copy.

The root cause is the Fiddle module loading libc.so.6 with an absolute path:

#0  __dlopen (file=0x20728280 "/lib64/libc.so.6", mode=257) at dlopen.c:75
#1  0x00003fffb748782c in rb_fiddle_handle_initialize (argc=<optimized out>, argv=<optimized out>, self=544821280) at handle.c:179

This comes from test/fiddle/helper.rb:

when /x86_64-linux/
  libc_so = "/lib64/libc.so.6"
  libm_so = "/lib64/libm.so.6"
when /linux/
  libdir = '/lib'
  case [0].pack('L!').size
  when 4
    # 32-bit ruby
    libdir = '/lib32' if File.directory? '/lib32'
  when 8
    # 64-bit ruby
    libdir = '/lib64' if File.directory? '/lib64'
  end
  libc_so = File.join(libdir, "libc.so.6")
  libm_so = File.join(libdir, "libm.so.6")

So the good news is that it's just a path.  I expect the fix looks like this:

when /linux/
  libc_so = "libc.so.6"
  libm_so = "libm.so.6"

(This replaces tehe x86_64-linux branch, too.)

Comment 18 Vít Ondruch 2016-08-10 14:23:07 UTC

(In reply to Florian Weimer from comment #17)
Wow, did not expected this. Now the question to me is why this got exposed now, since the code did not changed in Ruby ...

Comment 19 Florian Weimer 2016-08-10 14:24:36 UTC

(In reply to Vít Ondruch from comment #18)
> (In reply to Florian Weimer from comment #17)
> Wow, did not expected this. Now the question to me is why this got exposed
> now, since the code did not changed in Ruby ...

libio vtable verification is a new security hardening feature in Fedora 25.

Comment 20 Carlos O'Donell 2016-08-10 16:37:57 UTC

(In reply to Florian Weimer from comment #17)
> libio vtable verification fails because there are two copies of libc.so.6 in
> the process:
> 
> 	0x00003fffb79413a8 - 0x00003fffb7941f78 is __libc_IO_vtables in
> /lib64/power8/libc.so.6
> 	0x00003fffb74213c0 - 0x00003fffb7421f90 is __libc_IO_vtables in
> /lib64/libc.so.6
> 
> IO.pipe refers to a vtable from a the first copy, but the fprintf called via
> libffi comes from the second copy.
> 
> The root cause is the Fiddle module loading libc.so.6 with an absolute path:
> 
> #0  __dlopen (file=0x20728280 "/lib64/libc.so.6", mode=257) at dlopen.c:75
> #1  0x00003fffb748782c in rb_fiddle_handle_initialize (argc=<optimized out>,
> argv=<optimized out>, self=544821280) at handle.c:179

This is an application defect.

If you're using a path it's expected you know what you're loading.

One _should_ be using '#include <gnu/lib-names.h>' to get LIBC_SO and then dlopen that, it's the only supported solution, particularly consider distributions that might have /usr/lib64, or multi-arched lib dirs. You could be loading libc.so.6 from an incompatible ABI.

Loding by SONAME is the only safe option.

Comment 21 Fedora Update System 2016-08-11 06:06:55 UTC

ruby-2.3.1-58.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2016-491340cf7b

Comment 22 Fedora Update System 2016-08-11 16:56:35 UTC

ruby-2.3.1-58.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-491340cf7b

Comment 23 Fedora Update System 2016-08-27 10:42:27 UTC

ruby-2.3.1-58.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.