Inconsistent IO on JRuby

[jkutner]

While trying to fix a JRuby specific bug in Vagrant http://vagrantup.com/, which uses ChildProcess to execute some commands, I found that output cannot always be retrieved from a subprocess.

I've been able to reproduce the bug in a single file here:
https://gist.github.com/1647275

It is creating two ChildProcesses (via the Subprocess class), and executing
them in order.

Vagrant::Util::Subprocess.new("VBoxManage", "--version").execute
Vagrant::Util::Subprocess.new("VBoxManage", "--version").execute

In the execute method, a ChildProcess is created:

process = ChildProcess.build(*@command)
stdout, stdout_writer = IO.pipe
stderr, stderr_writer = IO.pipe
process.io.stdout = stdout_writer
process.io.stderr = stderr_writer
process.duplex = true

Then it tries to read the output from the stdout pipe:

data << io.read_nonblock(READ_CHUNK_SIZE)

The first time, the ChildProcess works correctly, but the second time it
yields no output.

INFO subprocess: Starting process: ["VBoxManage", "--version"]
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stdout: 4.1.8r75467
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
INFO subprocess: Starting process: ["VBoxManage", "--version"]
DEBUG subprocess: Selecting on IO
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 31999
DEBUG subprocess: Exit status: 0

I've created a workaround in Vagrant for this issue by using IO.popen4 like this:

IO.popen4( cmd ) do |pid, stdin, stdout, stderr|
 Thread.new(stdout) {|stdout_io|
   stdout_io.each_line do |data|
     @logger.debug("stdout: #{data}")
   end
 }.join
end

hashicorp/vagrant#709

But it seems that this should be pushed down into Childprocess. I'm already looking into how this could be done, but would love some advice. Thanks.

---

Reproduce with this script:
https://gist.github.com/1647275

Background:
http://markmail.org/thread/e7rmwy4jp53e3wjj
hashicorp/vagrant#658
http://jira.codehaus.org/browse/JRUBY-6362

[jarib]

Closing the write streams after the process has finished appears to solve the problem:

diff --git a/subprocess.rb b/subprocess.rb
index 1b5d4ca..c1c478b 100644
--- a/subprocess.rb
+++ b/subprocess.rb
@@ -67,10 +67,6 @@ module Vagrant
         # Make sure the stdin does not buffer
         process.io.stdin.sync = true

-        # Close the writer pipes, since we're just reading
-        stdout_writer.close
-        stderr_writer.close
-
         # Create a dictionary to store all the output we see.
         io_data = { :stdout => "", :stderr => "" }

@@ -124,6 +120,10 @@ module Vagrant
           raise TimeoutExceeded, process.pid
         end

+        # Close the writer pipes, since we're just reading
+        stdout_writer.close
+        stderr_writer.close
+
         @logger.debug("Exit status: #{process.exit_code}")

         # Read the final output data, since it is possible we missed a small
(END) 

[jkutner]

Awesome! thanks

[jkutner]

FTR, i submitted this patch to vagrant:
hashicorp/vagrant#711

[jkutner]

Now I've found another problem. If I add the following line to the script above:

Vagrant::Util::Subprocess.new("VBoxManage", "showvminfo", "d70641b6-1dc5-47a2-9f5a-13464db8ac8d").execute

I get this output (note that this won't work exactly because UUID for the box will be different):

 INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "d70641b6-1dc5-47a2-9f5a-13464db8ac8d"]
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stdout: N
NativeException: java.lang.IndexOutOfBoundsException: null
  pump at /Users/jkutner/.rvm/gems/jruby-1.6.5/gems/childprocess-0.3.0/lib/childprocess/jruby/pump.rb:33
     run at /Users/jkutner/.rvm/gems/jruby-1.6.5/gems/childprocess-0.3.0/lib/childprocess/jruby/pump.rb:18
    call at org/jruby/RubyProc.java:270
    call at org/jruby/RubyProc.java:224

The "N" is the first character in the output, which is really "Name: " and then about 100 lines of stuff. I suspect the reason this command fails is the longer output (total SWAG).

[jkutner]

I'm trying to create a more easily reproducible result. Should I open a new ticket?

[jarib]

Test case would be good. Let's just use this ticket.

[jkutner]

Yes, it appears to be the length of the output. Here is the script using cat temp.rb (assuming the name of the script bug.rb)
https://gist.github.com/1748321

This produces the same error, which is included in the gist

[jarib]

You may want to try this patch against childprocess:

diff --git a/lib/childprocess/jruby/pump.rb b/lib/childprocess/jruby/pump.rb
index adfc58b..7cac056 100644
--- a/lib/childprocess/jruby/pump.rb
+++ b/lib/childprocess/jruby/pump.rb
@@ -30,6 +30,7 @@ module ChildProcess

           while read != -1
             avail = [@input.available, 1].max
+            avail = BUFFER_SIZE if avail > BUFFER_SIZE
             read = @input.read(buffer, 0, avail)

             if read > 0

I've pushed it to a branch here so you can try it out:

https://github.com/jarib/childprocess/tree/issue-30-index-out-of-bounds

[jarib]

Thanks, looks like my fix is correct then. I'll push 0.3.1 shortly.

[jkutner]

Thank you for the amazingly fast response!!!

[jarib]

You're welcome :) 0.3.1 is out now.

[jkutner]

this appears to fix all jruby related issues in vagrant. danka!

[jarib]

Yeah, at least on non-Windows (there's still #26). Thanks for digging into these!

[mitchellh]

@jkutner

Just realized a huge bug (see hashicorp/vagrant#721). On Windows non-Java, you have to close the writer pipes BEFORE starting the process, or reading doesn't work. You can see the commit I made to fix this: I basically check whether we're in JRuby or not and do the close at the proper place.

Annoying. Oh, subprocess IO, never easy.

[jarib]

Ugh.