TestIO#test_close_read sometimes logs EPIPE #1838

Open
headius opened this Issue Jul 20, 2014 · 9 comments

Comments

Projects
None yet
3 participants
@headius
Member

headius commented Jul 20, 2014

Unsure what's going on here. Does not appear to break the test, but should be investigated:

[2879/5903] TestIO#test_close_read
Errno::EPIPE: Broken pipe - <STDOUT>
   write at org/jruby/RubyIO.java:1314
   write at org/jruby/RubyIO.java:1287
  (root) at -e:1

@headius headius added this to the JRuby 9000 milestone Jul 20, 2014

@headius headius added the core label Jul 20, 2014

@enebo enebo modified the milestone: JRuby 9.0.0.0 Jul 14, 2015

@areman

This comment has been minimized.

Show comment Hide comment
@areman

areman Mar 15, 2016

Contributor

I found this stackoverflow question
Broken pipe - is raised at the first puts when my application is deployed on a glassfish server.

Contributor

areman commented Mar 15, 2016

I found this stackoverflow question
Broken pipe - is raised at the first puts when my application is deployed on a glassfish server.

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Mar 15, 2016

Member

I will try to investigate this finally. Have been wanting to figure out why that output happens.

@areman Is it possible for you to prepare a github repo with a deployable app that exhibits this problem?

Member

headius commented Mar 15, 2016

I will try to investigate this finally. Have been wanting to figure out why that output happens.

@areman Is it possible for you to prepare a github repo with a deployable app that exhibits this problem?

@headius headius added this to the JRuby 9.1.0.0 milestone Mar 15, 2016

@areman

This comment has been minimized.

Show comment Hide comment
@areman

areman Mar 16, 2016

Contributor

Thanks for the fast repley . I'm sorry currently I can't reproduces the problem outside our application and environment setup. I keep trying.

Contributor

areman commented Mar 16, 2016

Thanks for the fast repley . I'm sorry currently I can't reproduces the problem outside our application and environment setup. I keep trying.

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Apr 20, 2016

Member

Still no way to reproduce. Bumping.

Member

headius commented Apr 20, 2016

Still no way to reproduce. Bumping.

@headius headius modified the milestones: JRuby 9.1.1.0, JRuby 9.1.0.0 Apr 20, 2016

@headius headius modified the milestones: JRuby 9.1.1.0, JRuby 9.1.2.0 May 11, 2016

@enebo enebo modified the milestones: JRuby 9.1.2.0, JRuby 9.1.3.0 May 23, 2016

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Aug 17, 2016

Member

Able to reproduce very quickly running MRI tests:

[] ~/projects/jruby $ EXCLUDES=test/mri/excludes jruby test/mri/runner.rb test/mri/ruby/test_io.rb 
Run options: 

# Running tests:

[  8/176] TestIO#test_close_readorg/jruby/RubyIO.java:1430:in `write': Broken pipe - <STDOUT> (Errno::EPIPE)
    from org/jruby/RubyIO.java:1401:in `write'
    from -e:1:in `<main>'
[ 14/176] TestIO#test_close_write^C    

Finally investigating.

Member

headius commented Aug 17, 2016

Able to reproduce very quickly running MRI tests:

[] ~/projects/jruby $ EXCLUDES=test/mri/excludes jruby test/mri/runner.rb test/mri/ruby/test_io.rb 
Run options: 

# Running tests:

[  8/176] TestIO#test_close_readorg/jruby/RubyIO.java:1430:in `write': Broken pipe - <STDOUT> (Errno::EPIPE)
    from org/jruby/RubyIO.java:1401:in `write'
    from -e:1:in `<main>'
[ 14/176] TestIO#test_close_write^C    

Finally investigating.

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Aug 17, 2016

Member

Ok, here's the test triggering it, from MRI's test_io.rb:

  def test_close_read
    ruby do |f|
      f.close_read
      f.write "foobarbaz"
      assert_raise(IOError) { f.read }
      assert_nothing_raised(IOError) {f.close_read}
      assert_nothing_raised(IOError) {f.close}
      assert_nothing_raised(IOError) {f.close_read}
    end
  end

The subprocess logic in the ruby method looks like this:

  def ruby(*args)
    args = ['-e', '$>.write($<.read)'] if args.empty?
    ruby = EnvUtil.rubybin
    opts = {}
    if defined?(Process::RLIMIT_NPROC)
      lim = Process.getrlimit(Process::RLIMIT_NPROC)[1]
      opts[:rlimit_nproc] = [lim, 1024].min
    end
    f = IO.popen([ruby] + args, 'r+', opts)
    pid = f.pid
    yield(f)
  ensure
    f.close unless !f || f.closed?
    begin
      Process.wait(pid)
    rescue Errno::ECHILD, Errno::ESRCH
    end
  end

So it starts up a subprocess that's writing to stdout everything it's reading from stdin.

If I track when during the test we see the output, it happens after the first IOError line, somewhere around the first IOError line that attempts to close_read again.

The message appears to be stderr output from the write call seeing that the other end of the stream has been close_read. It may be completely valid output that we're just not supposed to see during this test.

Member

headius commented Aug 17, 2016

Ok, here's the test triggering it, from MRI's test_io.rb:

  def test_close_read
    ruby do |f|
      f.close_read
      f.write "foobarbaz"
      assert_raise(IOError) { f.read }
      assert_nothing_raised(IOError) {f.close_read}
      assert_nothing_raised(IOError) {f.close}
      assert_nothing_raised(IOError) {f.close_read}
    end
  end

The subprocess logic in the ruby method looks like this:

  def ruby(*args)
    args = ['-e', '$>.write($<.read)'] if args.empty?
    ruby = EnvUtil.rubybin
    opts = {}
    if defined?(Process::RLIMIT_NPROC)
      lim = Process.getrlimit(Process::RLIMIT_NPROC)[1]
      opts[:rlimit_nproc] = [lim, 1024].min
    end
    f = IO.popen([ruby] + args, 'r+', opts)
    pid = f.pid
    yield(f)
  ensure
    f.close unless !f || f.closed?
    begin
      Process.wait(pid)
    rescue Errno::ECHILD, Errno::ESRCH
    end
  end

So it starts up a subprocess that's writing to stdout everything it's reading from stdin.

If I track when during the test we see the output, it happens after the first IOError line, somewhere around the first IOError line that attempts to close_read again.

The message appears to be stderr output from the write call seeing that the other end of the stream has been close_read. It may be completely valid output that we're just not supposed to see during this test.

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Aug 17, 2016

Member

Ok, so the output does not happen in MRI, confirmed by redirecting stderr to a file. Direct writes to it appear, but this error does not.

Member

headius commented Aug 17, 2016

Ok, so the output does not happen in MRI, confirmed by redirecting stderr to a file. Direct writes to it appear, but this error does not.

@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Aug 17, 2016

Member

Here's the full Ruby and Java traces for the EPIPE we produce. As far as I can tell our logic matches MRI at least down to the actual system IO layer:

java.io.IOException: Broken pipe
    at jnr.enxio.channels.NativeDeviceChannel.write(NativeDeviceChannel.java:88)
    at org.jruby.util.io.PosixShim.write(PosixShim.java:106)
    at org.jruby.util.io.OpenFile$3.run(OpenFile.java:1334)
    at org.jruby.util.io.OpenFile$3.run(OpenFile.java:1325)
    at org.jruby.RubyThread.executeTask(RubyThread.java:1464)
    at org.jruby.util.io.OpenFile.writeInternal(OpenFile.java:2232)
    at org.jruby.util.io.OpenFile.binwrite(OpenFile.java:2173)
    at org.jruby.util.io.OpenFile.fwrite(OpenFile.java:2038)
    at org.jruby.RubyIO.write(RubyIO.java:1429)
    at org.jruby.RubyIO.write(RubyIO.java:1401)
    at org.jruby.RubyIO$INVOKER$i$1$0$write.call(RubyIO$INVOKER$i$1$0$write.gen)
    at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:338)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:163)
    at DashE.invokeOther3:write(-e:1)
    at DashE.RUBY$script(-e:1)
    at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)
    at org.jruby.ir.Compiler$1.load(Compiler.java:111)
    at org.jruby.Ruby.runScript(Ruby.java:834)
    at org.jruby.Ruby.runNormally(Ruby.java:749)
    at org.jruby.Ruby.runNormally(Ruby.java:767)
    at org.jruby.Ruby.runFromMain(Ruby.java:580)
    at org.jruby.Main.doRunFromMain(Main.java:425)
    at org.jruby.Main.internalRun(Main.java:313)
    at org.jruby.Main.run(Main.java:242)
    at org.jruby.Main.main(Main.java:204)
org/jruby/RubyIO.java:1430:in `write': Broken pipe - <STDOUT> (Errno::EPIPE)
    from org/jruby/RubyIO.java:1401:in `write'
    from -e:1:in `<main>'
Member

headius commented Aug 17, 2016

Here's the full Ruby and Java traces for the EPIPE we produce. As far as I can tell our logic matches MRI at least down to the actual system IO layer:

java.io.IOException: Broken pipe
    at jnr.enxio.channels.NativeDeviceChannel.write(NativeDeviceChannel.java:88)
    at org.jruby.util.io.PosixShim.write(PosixShim.java:106)
    at org.jruby.util.io.OpenFile$3.run(OpenFile.java:1334)
    at org.jruby.util.io.OpenFile$3.run(OpenFile.java:1325)
    at org.jruby.RubyThread.executeTask(RubyThread.java:1464)
    at org.jruby.util.io.OpenFile.writeInternal(OpenFile.java:2232)
    at org.jruby.util.io.OpenFile.binwrite(OpenFile.java:2173)
    at org.jruby.util.io.OpenFile.fwrite(OpenFile.java:2038)
    at org.jruby.RubyIO.write(RubyIO.java:1429)
    at org.jruby.RubyIO.write(RubyIO.java:1401)
    at org.jruby.RubyIO$INVOKER$i$1$0$write.call(RubyIO$INVOKER$i$1$0$write.gen)
    at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:338)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:163)
    at DashE.invokeOther3:write(-e:1)
    at DashE.RUBY$script(-e:1)
    at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)
    at org.jruby.ir.Compiler$1.load(Compiler.java:111)
    at org.jruby.Ruby.runScript(Ruby.java:834)
    at org.jruby.Ruby.runNormally(Ruby.java:749)
    at org.jruby.Ruby.runNormally(Ruby.java:767)
    at org.jruby.Ruby.runFromMain(Ruby.java:580)
    at org.jruby.Main.doRunFromMain(Main.java:425)
    at org.jruby.Main.internalRun(Main.java:313)
    at org.jruby.Main.run(Main.java:242)
    at org.jruby.Main.main(Main.java:204)
org/jruby/RubyIO.java:1430:in `write': Broken pipe - <STDOUT> (Errno::EPIPE)
    from org/jruby/RubyIO.java:1401:in `write'
    from -e:1:in `<main>'
@headius

This comment has been minimized.

Show comment Hide comment
@headius

headius Aug 17, 2016

Member

What I don't get here is that it seems like the write should error when the read side of the parent process's pipes have been closed.

So there's a bit more research but I'm still not sure why we error and MRI doesn't. Punting to 9.2.

Member

headius commented Aug 17, 2016

What I don't get here is that it seems like the write should error when the read side of the parent process's pipes have been closed.

So there's a bit more research but I'm still not sure why we error and MRI doesn't. Punting to 9.2.

@headius headius modified the milestones: JRuby 9.2.0.0, JRuby 9.1.3.0 Aug 17, 2016

@headius headius removed this from the JRuby 9.2.0.0 milestone May 15, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment