no STDOUT with drip on jruby-9.0.0.0.pre1 #2690

blinsay · 2015-03-13T03:17:52Z

I started playing with drip tonight and noticed that after drip started doing its thing, I wasn't getting any console output just running ruby -e puts 9 * 9.

It works just fine on jruby-1.7.19, so I'd guess it's a regression. Maybe #511?

(I tried to take rbenv out of the equation and call jruby directly, but the path is still there so you can see the versions.)

[23:13:06] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-9.0.0.0.pre1/bin/ruby -e 'puts 9 * 9'
81
[23:13:18] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-9.0.0.0.pre1/bin/ruby -e 'puts 9 * 9'
[23:13:19] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-9.0.0.0.pre1/bin/ruby -e 'puts 9 * 9'

And

[23:12:37] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-1.7.19/bin/ruby -e 'puts 9 * 9'
81
[23:12:54] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-1.7.19/bin/ruby -e 'puts 9 * 9'
81
[23:12:55] benl:drip-test $ /Users/benl/.rbenv/versions/jruby-1.7.19/bin/ruby -e 'puts 9 * 9'
81

For posterity, here's my ENV.

[23:20:20] benl:drip-test $ env | grep DRIP
DRIP_INIT_CLASS=org.jruby.main.DripMain
DRIP_INIT=
[23:20:25] benl:drip-test $ env | grep JAVACMD
JAVACMD=/usr/local/bin/drip

The text was updated successfully, but these errors were encountered:

blinsay · 2015-03-13T03:23:11Z

FWIW, this keeps happening if I unset DRIP_INIT_CLASS and unset DRIP_INIT.

dennissivia · 2016-01-14T12:42:01Z

I am experiencing the same issue. As soon as drip is used by my command, there is no output anymore.

danhper · 2016-06-19T02:42:33Z

I am having the same issue with jruby 9.1.2, any idea?

headius · 2016-07-12T00:10:06Z

How peculiar!

I have a theory...I suspect that Drip's background JVM processes don't use the typical 0, 1, 2 stdio file descriptors, since they need to reroute a but when the foreground process connects to them. It's likely we assume all commands launched in a normal way will use those file descriptors.

If this is indeed the case, there's two solutions I can think of:

Do a better job of figuring out what file descriptors stdin/out/err are using.
Wire up some Drip-specific logic in our DripMain. This is the less-desirable fix since it won't work for a bare Drip set-up with no DRIP_INIT_CLASS.

headius · 2016-07-12T00:29:27Z

My first attempt at this appears to have failed:

diff --git a/core/src/main/java/org/jruby/RubyGlobal.java b/core/src/main/java/org/jruby/RubyGlobal.java
index 213cbc9..573433f 100644
--- a/core/src/main/java/org/jruby/RubyGlobal.java
+++ b/core/src/main/java/org/jruby/RubyGlobal.java
@@ -59,13 +59,17 @@ import org.jruby.util.OSEnvironment;
 import org.jruby.util.RegexpOptions;
 import org.jruby.util.cli.OutputStrings;
 import org.jruby.util.io.EncodingUtils;
+import org.jruby.util.io.FilenoUtil;
 import org.jruby.util.io.OpenFile;
 import org.jruby.util.io.STDIO;

 import static org.jruby.internal.runtime.GlobalVariable.Scope.*;

+import java.io.FileInputStream;
+import java.io.FileOutputStream;
 import java.io.InputStream;
 import java.io.OutputStream;
+import java.io.PipedInputStream;
 import java.nio.channels.Channel;
 import java.nio.channels.Channels;
 import java.util.Map;
@@ -278,18 +282,39 @@ public class RubyGlobal {

     private static Channel prepareStdioChannel(Ruby runtime, STDIO stdio, Object stream) {
         if (runtime.getPosix().isNative() && stdio.isJVMDefault(stream) && !Platform.IS_WINDOWS) {
-            // use real native channel for stdio
-            return new NativeDeviceChannel(stdio.fileno());
-        } else {
-            switch (stdio) {
-                case IN:
-                    return Channels.newChannel((InputStream)stream);
-                case OUT:
-                case ERR:
-                    return Channels.newChannel((OutputStream)stream);
-                default: throw new RuntimeException("invalid stdio: " + stdio);
+            // use real native fileno for stdio, if possible
+
+            // try typical stdio stream and channel types
+            Channel channel = null;
+            if (stream instanceof Channel) {
+                channel = (Channel) stream;
+            } else if (stream instanceof FileInputStream) {
+                channel = ((FileInputStream) stream).getChannel();
+            } else if (stream instanceof FileOutputStream) {
+                channel = ((FileOutputStream) stream).getChannel();
+            }
+
+            int fileno = channel != null ? FilenoUtil.filenoFrom(channel) : stdio.fileno();
+
+            if (fileno >= 0) {
+                // We got a real fileno, use it
+                return new NativeDeviceChannel(fileno);
             }
         }
+
+        // fall back on non-direct stdio
+        // NOTE (CON): This affects interactivity in any case where we cannot determine the real fileno and use native.
+        //             We do force flushing of stdout and stdout, but we can't provide all the interactive niceities
+        //             without a proper native channel. This is the case under e.g. Drip, which replaces the stdio
+        //             streams with its own wrappers. See https://github.com/jruby/jruby/issues/2690
+        switch (stdio) {
+            case IN:
+                return Channels.newChannel((InputStream)stream);
+            case OUT:
+            case ERR:
+                return Channels.newChannel((OutputStream)stream);
+            default: throw new RuntimeException("invalid stdio: " + stdio);
+        }
     }

This patch changes our stdio setup logic to:

Try to acquire the true fileno from a given stream, for cases where it may be other than 0, 1, 2.
If that fails, do not assume 0, 1, 2 and just wrap the given Java stream as-is (likely hurting interactivity).

I thought one of these two fixes would do it, but I'm still not getting any output from the background JVMs.

headius · 2016-07-12T00:32:16Z

Ok, nevermind. Immediately after I commented I realized my logic was flawed, still falling back on 0, 1, 2 for stdio rather than just wrapping the given stream. If the patch is modified to never use stdio.fileno() it works as expected.

I'm going to poke around Drip to see if there's any way we can improve this a bit and actually get the proper streams.

headius · 2016-07-12T03:34:06Z

Ok...I tried to take this farther and do a proper unwrapping of the Drip streams, but there's a problem of initialization order I'm not sure how to address.

Current situation

On startup, we assume stdio will be at the usual 0,1,2 values descriptors, and we use those directly to open native stdio streams for Ruby. This conflicts with Drip background processes, since after the "drip main" has run, it switches System.in/out/err to point at FIFO file streams that are used to proxy the client process. If we assume stdio is always at 0,1,2, we wire up the wrong descriptors.

First fix

My first fix was to just skip the native stream logic and use our tried-and-true unwrapping logic to take System.in/out/err and unwrap them down to their innermost File*Stream. When running under Drip, one of its Switchable streams will be in the way, and we will fall back on using wrapped-stream logic for stdio. That fixes this issue at least well enough for stdio to function.

Unfortunately this fix has a problem: by not unwrapping all the way to the FileChannel, we lose some interactivity at a console. Granted, we already lose some interactivity due to Drip's FIFO being in the way, but on top of that we also have Java's stream buffering interfering with interactive use.

Additional fix that doesn't quite work

I continued with the above fix and added smarts to further unwrap any Switchable streams. After much fussing around, I have the logic properly getting Drip's FIFO file descriptors for stdio, and fully unwrapping them.

Unfortunately, by default when Drip boots JRuby, it attempts to use our org.jruby.main.DripMain to start up a background JRuby instance. This instance sees the stdio streams before they have been switched to the FIFOs, and so that prebooted instance has stdio pointing at the wrong descriptors.

We have addressed this for other Drip laziness by adding Ruby.reinitialize, which re-inits anything we need to defer until the process "really" starts. For example, ARGV is re-defined to point at the actual arguments passed in by the Drip client. I also did this work so that the streams would be reinitialized, and I think we can commit this change...but any code that grabs the Ruby stdio streams before the "true" process start will continue to point at the old, incorrect file descriptors.

Possible solutions

We could ignore the problem. Most of the time, people don't grab and hold onto $stdin and friends...they just use top-level IO functions that write to those streams. But there's always troublemakers...
I can improve my logic to reopen the Ruby-exposed streams with the new channels. It would take a bit of work to ensure we're not leaving some nasty state hanging onto the old channels.
Perhaps we could persuade @ninjudd that the Drip daemon should actually dup the appropriate side of the FIFOs directly into stdio. This would mean every access from DripMain forward would see plain old stdio file descriptors without requiring any switching.

I'll see if I'm comfortable enough with the "Additional fix" to use it for now.

@ninjudd We should also talk about exposing some API so power users like me can get access to the Switchables and other drip Main odds and ends.

@ninjudd

This fixes jruby#2690, mostly. Previous situation ================== On startup, we assume stdio will be at the usual 0,1,2 values descriptors, and we use those directly to open native stdio streams for Ruby. This conflicts with Drip background processes, since after the "drip main" has run, it switches System.in/out/err to point at FIFO file streams that are used to proxy the client process. If we assume stdio is always at 0,1,2, we wire up the wrong descriptors. First fix ========= My first fix was to just skip the native stream logic and use our tried-and-true unwrapping logic to take System.in/out/err and unwrap them down to their innermost File*Stream. When running under Drip, one of its Switchable streams will be in the way, and we will fall back on using wrapped-stream logic for stdio. That fixes this issue at least well enough for stdio to function. Unfortunately this fix has a problem: by not unwrapping all the way to the FileChannel, we lose some interactivity at a console. Granted, we already lose some interactivity due to Drip's FIFO being in the way, but on top of that we also have Java's stream buffering interfering with interactive use. Additional fix ============== I continued with the above fix and added smarts to further unwrap any Switchable streams. After much fussing around, I have the logic properly getting Drip's FIFO file descriptors for stdio, and fully unwrapping them. Unfortunately, by default when Drip boots JRuby, it attempts to use our org.jruby.main.DripMain to start up a background JRuby instance. This instance sees the stdio streams *before* they have been switched to the FIFOs, and so that prebooted instance has stdio pointing at the wrong descriptors. We have addressed this for other Drip laziness by adding Ruby.reinitialize, which re-inits anything we need to defer until the process "really" starts. For example, ARGV is re-defined to point at the actual arguments passed in by the Drip client. I also did this work so that the streams would be reinitialized, by replacing the existing descriptors in the stdio streams with the new ones from Drip. However, any code that grabs the Ruby stdio file descriptors before the "true" process start will continue to point at the old, incorrect descriptors. Possible solutions ============== * We could ignore the problem. Most of the time, people don't grab and hold onto the file descriptors for `$stdin` and friends...they just use top-level IO functions that write to those streams. But there's always troublemakers... * Perhaps we could persuade @ninjudd that the Drip daemon should actually dup the appropriate side of the FIFOs directly into stdio. This would mean every access from DripMain forward would see plain old stdio file descriptors without requiring any switching. A side effect from my changes here is that stdio.fileno will now always reflect the actual fileno. Previously I forced stdio streams to always report their fileno in the 0,1,2 group, which doesn't make sense if they're not actually using those fileno.

@ninjudd

This fixes jruby#2690, mostly. Previous situation ================== On startup, we assume stdio will be at the usual 0,1,2 values descriptors, and we use those directly to open native stdio streams for Ruby. This conflicts with Drip background processes, since after the "drip main" has run, it switches System.in/out/err to point at FIFO file streams that are used to proxy the client process. If we assume stdio is always at 0,1,2, we wire up the wrong descriptors. First fix ========= My first fix was to just skip the native stream logic and use our tried-and-true unwrapping logic to take System.in/out/err and unwrap them down to their innermost File*Stream. When running under Drip, one of its Switchable streams will be in the way, and we will fall back on using wrapped-stream logic for stdio. That fixes this issue at least well enough for stdio to function. Unfortunately this fix has a problem: by not unwrapping all the way to the FileChannel, we lose some interactivity at a console. Granted, we already lose some interactivity due to Drip's FIFO being in the way, but on top of that we also have Java's stream buffering interfering with interactive use. Additional fix ============== I continued with the above fix and added smarts to further unwrap any Switchable streams. After much fussing around, I have the logic properly getting Drip's FIFO file descriptors for stdio, and fully unwrapping them. Unfortunately, by default when Drip boots JRuby, it attempts to use our org.jruby.main.DripMain to start up a background JRuby instance. This instance sees the stdio streams *before* they have been switched to the FIFOs, and so that prebooted instance has stdio pointing at the wrong descriptors. We have addressed this for other Drip laziness by adding Ruby.reinitialize, which re-inits anything we need to defer until the process "really" starts. For example, ARGV is re-defined to point at the actual arguments passed in by the Drip client. I also did this work so that the streams would be reinitialized, by replacing the existing descriptors in the stdio streams with the new ones from Drip. However, any code that grabs the Ruby stdio file descriptors before the "true" process start will continue to point at the old, incorrect descriptors. Possible solutions ============== * We could ignore the problem. Most of the time, people don't grab and hold onto the file descriptors for `$stdin` and friends...they just use top-level IO functions that write to those streams. But there's always troublemakers... * Perhaps we could persuade @ninjudd that the Drip daemon should actually dup the appropriate side of the FIFOs directly into stdio. This would mean every access from DripMain forward would see plain old stdio file descriptors without requiring any switching. A side effect from my changes here is that stdio.fileno will now always reflect the actual fileno. Previously I forced stdio streams to always report their fileno in the 0,1,2 group, which doesn't make sense if they're not actually using those fileno.

headius · 2016-07-12T15:17:34Z

I pushed a PR with the best fix I can come up with, short of patching drip to always force its fifos into stdio descriptors.

headius · 2016-07-12T15:18:16Z

@blinsay @scepticulous @tuvistavie If you folks can pull the PR branch and build/test it, I'd appreciate it!

danhper · 2016-07-13T06:43:20Z

Thank you very much for the great work!
The simple case is working like a charm

$ git status
On branch reopen_stdio_for_drip
Your branch is up-to-date with 'origin/reopen_stdio_for_drip'.
nothing to commit, working directory clean
$ JAVACMD=$(which drip) JRUBY_OPTS="-J-XX:+TieredCompilation -J-XX:TieredStopAtLevel=1 -J-noverify -X-C" time ./bin/jruby -e 'puts "foobar"'
foobar
2.46user 0.16system 0:01.70elapsed 154%CPU (0avgtext+0avgdata 133796maxresident)k
0inputs+8outputs (0major+17808minor)pagefaults 0swaps
$ JAVACMD=$(which drip) JRUBY_OPTS="-J-XX:+TieredCompilation -J-XX:TieredStopAtLevel=1 -J-noverify -X-C" time ./bin/jruby -e 'puts "foobar"'
foobar
0.04user 0.01system 0:00.12elapsed 45%CPU (0avgtext+0avgdata 3892maxresident)k
0inputs+16outputs (0major+13464minor)pagefaults 0swaps

I am having some troubles running my tests with drip, but I am not sure if it is directly related to this.
My test looks like this:

require_relative 'helper'

class TestConsole < Test
  def test_run
    assert_output(/\$ ls\n/) { assert_equal 0, Console.run('ls') }
    _out, err = capture_subprocess_io { refute_equal 0, Console.run('ls /foobarbaz') }
    assert_match(/No such file or directory/, err)
  end
end

It passes without any issue when running without drip, but with drip I get

  1) Failure:
TestConsole#test_run [/path/to/project/test/console_test.rb:8]:
Expected /No such file or directory/ to match "".

So it seems that stderr is not being captured correctly
When using drip and the master branch of jruby, I do not get any output, but the exit code is 0.

Please let me know if you need any other information.

Thank you!

headius · 2016-08-11T23:11:12Z

@tuvistavie I can't reproduce with a trivial example:

[] ~/projects/jruby $ JAVACMD=/Users/headius/projects/drip/bin/drip jruby -e '$stdout << "foo"'
foo
[] ~/projects/jruby $ JAVACMD=/Users/headius/projects/drip/bin/drip jruby -e '$stderr << "foo"'
foo

Given that your case is more complicated than the original issue, I recommend that we close this issue (since the streams definitely are working now) and open a new issue for this stderr problem you're seeing.

I'll merge my PR momentarily.

blinsay · 2016-08-12T03:33:30Z

@headius thanks so much!

This code was originally removed in 7e024a7 to fix #2690, but childprocess was no longer able to launch a subprocess (#4122). Until Windows has native, we need this code in place...and may always need it for non-native setups, to keep stdio fileno sane. Fixes #4122.

rtyler added JDK compatibility JRuby 9000 and removed JDK compatibility labels Mar 22, 2015

headius added this to the JRuby 9.1.3.0 milestone Jul 12, 2016

headius mentioned this issue Jul 12, 2016

Publish a maven artifact to central ninjudd/drip#96

Open

headius mentioned this issue Jul 12, 2016

Reopen stdio streams when run from Drip, to pick up its FIFOs. #4010

Merged

headius closed this as completed in #4010 Aug 11, 2016

headius mentioned this issue Sep 1, 2016

The child-process gem fails to spawn processes on Windows #4122

Closed

headius mentioned this issue Sep 21, 2016

Nailgun output redirection on Windows #1535

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

no STDOUT with drip on jruby-9.0.0.0.pre1 #2690

no STDOUT with drip on jruby-9.0.0.0.pre1 #2690

blinsay commented Mar 13, 2015

blinsay commented Mar 13, 2015

dennissivia commented Jan 14, 2016

danhper commented Jun 19, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016 •

edited

headius commented Jul 12, 2016

headius commented Jul 12, 2016

danhper commented Jul 13, 2016

headius commented Aug 11, 2016

blinsay commented Aug 12, 2016

no STDOUT with drip on jruby-9.0.0.0.pre1 #2690

no STDOUT with drip on jruby-9.0.0.0.pre1 #2690

Comments

blinsay commented Mar 13, 2015

blinsay commented Mar 13, 2015

dennissivia commented Jan 14, 2016

danhper commented Jun 19, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016

headius commented Jul 12, 2016 • edited

Current situation

First fix

Additional fix that doesn't quite work

Possible solutions

headius commented Jul 12, 2016

headius commented Jul 12, 2016

danhper commented Jul 13, 2016

headius commented Aug 11, 2016

blinsay commented Aug 12, 2016

headius commented Jul 12, 2016 •

edited