Inconsistent IO on JRuby about childprocess HOT 15 CLOSED

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) 

from childprocess.

Awesome! thanks

from childprocess.

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

from childprocess.

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).

from childprocess.

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

from childprocess.

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

from childprocess.

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

from childprocess.

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

from childprocess.

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

from childprocess.

Thank you for the amazingly fast response!!!

from childprocess.

You're welcome :) 0.3.1 is out now.

from childprocess.

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

from childprocess.

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

from childprocess.

@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.

from childprocess.

Ugh.

from childprocess.