Bug 1361037

Summary: [ruby] Invalid stdio handle error during tests run
Product: [Fedora] Fedora Reporter: Rafael Fonseca <rdossant>
Component: rubyAssignee: Jeroen van Meeuwen <vanmeeuwen+fedora>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: codonell, dan, fweimer, jcajka, mmorsi, mtasaka, pbrobinson, s, strzibny, tagoh, vanmeeuwen+fedora, vondruch
Target Milestone: ---   
Target Release: ---   
Hardware: ppc64   
OS: Unspecified   
Whiteboard:
Fixed In Version: ruby-2.3.1-58.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-08-27 10:42:33 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1071880    

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.