Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

IO.popen(cmd) where cmd uses tty facilities fails with native.enabled=false #5624

Open
annabackiyam opened this Issue Feb 21, 2019 · 30 comments

Comments

Projects
None yet
2 participants
@annabackiyam
Copy link

annabackiyam commented Feb 21, 2019

JRuby 9.1.13.0
Linux 4.1.12-124.20.7.el6uek.x86_64
Java(TM) SE Runtime Environment (build 1.8.0_181-b13)

sample.rb

require 'open3'
require 'tempfile'
str="top|head -5"
@temp_file = Tempfile.new(["anna-temp",".sh"])
@temp_file.write <<EOS
#!/bin/sh
#{str}
EOS
@temp_file.flush
@temp_file.chmod(0500)
@temp_file.close
puts `cat #{@temp_file.path}`
IO.popen(["#{@temp_file.path}"]) { |ls_io|
        ls_io.each_line do |l|
          puts l
        end
}

commands to run:
1.java -jar -Djruby.native.enabled=false /opt/lib/jruby-complete.jar sample.rb
uri:classloader:/jruby/kernel/jruby/process_manager.rb:22: warning: executable? does not in this environment and will return a dummy value

top|head -5
        top: failed tty get
@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 21, 2019

I can confirm with native disabled there is some tty wackiness because top by default is trying to use tty facilities. This definitely is a bug with native.enabled=false. If I run with =true it works ok. This is both with master (9.2.x) and 9.1.17.0 (using jruby-complete.jar -- seemingly complete jar is unrelated to the underlying issue).

@annabackiyam as something to try here does it work if you change your command-line to:

str="top -b|head -5"

You did find an issue but I am wondering if this is your actual issue or you found another issue with native disabled (-b is recommended for top if you plan on using it as part of a pipeline and you are sending it no input).

@enebo enebo changed the title IO.popen(top) doesn't function in 9k IO.popen(cmd) where cmd uses tty facilities fails with native.enabled=false Feb 21, 2019

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 21, 2019

@enebo thank you for the top command tip. My original issue is still not resolved. i.e. any file that I create and add the command and try to execute the file fails with exit code: 127. On the other hand if I execute an existing file with the same command in, it works.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 21, 2019

@enebo Looks like popen subprocess in unable to read the new file that's being created in the parent process.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 22, 2019

@annabackiyam ok. No doubt after the last issue you made sure the tempfile has been closed or flushed to make sure it is really there?

My other random thought is perhaps where the tmpfile is being made somehow has execute disabled on the filesystem...but if that was the case and 1.6 works I would guess then that the paths for tempfile are in completely different places. Seems unlikely.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 22, 2019

@enebo Yes, I flush and close the tempfile and I can see the file content outside the code while it's running.
I have ruled out the file permissions as the first point in my troubleshooting. The same file without any modification is working if I restart my app. i.e. if the file was written and available in the disk before jruby process started, the code is able to execute the file without any issues. I have even tried regular file instead of temp file. If I create a new file and try to execute it in the same process, it doesn't work.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 22, 2019

@annabackiyam just to fully make sure we are talking about the same thing I don't mean chmod but the filesystem itself ala: https://debian-administration.org/article/57/Making_/tmp_non-executable

I don't think this is likely as it would mean that 1.6 would be saving the tempfile in a path not in that filesystem while it would in 9.1 (although @tmpfile.path displayed would prove/disprove the notion). We did used to have some different logic for tempfile but I just don't remember if we had a different base dir for tempfiles in the past (like using HOME/.tmp vs /tmp).

Another question is do you see this consistently in all environments where this is run (e.g. prod + dev)?

Your comment about how the same script runs when it is restarted is interesting but I have no ideas on why that would be....So you keep track of your tempfiles on reboot? How does that pattern work across application restarts? Maybe that will reveal something we have not thought of.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 22, 2019

@enebo Yes, we see that in all environments. We don't keep the file usually in production and the code unlinks it at the end. I do see the difference between 1.6 and 9k that the tempfile is not persisted in 9k.
To rule out the temp file issue, I've created a regular file now. I can see the file as below

# ls -l /var/tmp/RC-5368372-.sh
-rwxrwxrwx. 1 root root 60 Feb 22 19:56 /var/tmp/RC-5368372-.sh
# cat /var/tmp/RC-5368372-.sh
"/bin/cat /var/log/oasg/oasg-cta-filetransfer.log|head -n 5"

File::file? is true for that file in the same process and the execution comes with exit status 127 and there's no output stream for popen.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 22, 2019

@annabackiyam I am stumped on what to suggest. One confusing thing in your last comment if you have a reference to @temp_file but when you try to call path it has already been nil'd out.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 25, 2019

@enebo Please ignore the temp_file path being nil. That was my mistake.
The file check is true, but, the execution doesn't work with exit status 127.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 25, 2019

@annabackiyam can you add an option when running...which if from jruby-complete is:

-Djruby.debug.launch=true

from jruby command-line::

-J-Djruby.debug.launch=true

It should dump out some details of the popen launch parsing and execution setup. Maybe it will give us a new direction.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 25, 2019

@enebo I see this in the logs after enabling debug option:

ShellLauncher: Trying file /sbin/cat
ShellLauncher: Trying file /bin/cat
uri:classloader:/jruby/kernel/jruby/process_manager.rb:22: warning: executable? does not in this environment and will return a dummy value
#!/bin/sh

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 25, 2019

@annabackiyam ok I expected to see more like "found /bin/cat" or something like that.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 25, 2019

@annabackiyam looking I would grep out all ShellLauncher: lines unless those are the only two...If it is only getting Trying then perhaps there is some path where an exception is thrown and then it is getting swallowed above and returhing exit status 127? I expected some lines like "Launching ".

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 25, 2019

@enebo All I see is those 3 lines. I do not see any "Launching" word. I'm running with -Djruby.native.enabled=false as well.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 25, 2019

@annabackiyam ok not as helpful as I hoped. If you are a Java dev you could build a jruby-complete and litter a lot more log()s into org/jruby/util/ShellLauncher.java. That is quite a bit to ask but it will definitely allow you to isolate the issue.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 27, 2019

@enebo I've downloaded the source code from 9.1.13.0 branch and built it locally and added some log in ShellLauncher.java as you had suggested.
The jruby-complete jar that I built gives some error while running any ruby file:
java -jar /Users/6og4oo/JRuby/jruby-complete/jruby/maven/jruby-complete/target/jruby-complete-9.1.13.0-SNAPSHOT.jar helloworld.rb
Unhandled Java exception: java.lang.RuntimeException: Uncompilable source code - Erroneous ctor sym type: org.jruby.RubyBasicObject$INVOKER$s$0$0$method_missing19.
java.lang.RuntimeException: Uncompilable source code - Erroneous ctor sym type: org.jruby.RubyBasicObject$INVOKER$s$0$0$method_missing19.
populate at org/jruby/gen/org$jruby$RubyBasicObject$POPULATOR.java:22
defineAnnotatedMethodsIndividually at org/jruby/RubyModule.java:1060
defineAnnotatedMethods at org/jruby/RubyModule.java:947
createBasicObjectClass at org/jruby/RubyBasicObject.java:205
initRoot at org/jruby/Ruby.java:1314
init at org/jruby/Ruby.java:1162
newInstance at org/jruby/Ruby.java:339
internalRun at org/jruby/Main.java:271
run at org/jruby/Main.java:232
main at org/jruby/Main.java:204

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 27, 2019

@annabackiyam I believe this happened because some times when you compile and there is a syntax error it only partially generates some classes. Try cleaning then rebuilding: mvn clean; mvn -Pcomplete.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 27, 2019

Thanks @enebo. That worked. My next question is: I have added some logs here in ShellLauncher.java.
They are not printed. Where's the starting point for IO.popen to add some logs?

    public POpenProcess(Process child, Ruby runtime, ModeFlags modes) {
        log(runtime,"POpenProcess 10");
@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 27, 2019

-Djruby.debug.launch=true should print them out. Another option is to just use System.out.println.

1 similar comment
@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 27, 2019

-Djruby.debug.launch=true should print them out. Another option is to just use System.out.println.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 28, 2019

@enebo Logging finally works. Not that I could make out anything yet. Just showing it to you.
here's what I see in the logs now:

  ShellLauncher: POpenProcess 10]]

[2019-02-28T16:46:37.762+0000] [glassfish 4.1] [SEVERE] [] [] [tid: _ThreadID=542 _ThreadName=Thread-14] [timeMillis: 1551372397762] [levelValue: 1000] [[
  ShellLauncher: POpenProcess 30]]

[2019-02-28T16:46:37.764+0000] [glassfish 4.1] [SEVERE] [] [] [tid: _ThreadID=542 _ThreadName=Thread-14] [timeMillis: 1551372397764] [levelValue: 1000] [[
  ShellLauncher: POpenProcess 40]]

[2019-02-28T16:46:37.764+0000] [glassfish 4.1] [SEVERE] [] [] [tid: _ThreadID=542 _ThreadName=Thread-14] [timeMillis: 1551372397764] [levelValue: 1000] [[
  ShellLauncher: POpenProcess 60]]```
---------------------------------------------------
```public POpenProcess(Process child, Ruby runtime, ModeFlags modes) {
            log(runtime,"POpenProcess 10");
            LOG.info("POpenProcess 10");
            this.child = child;

            if (modes.isWritable()) {
                log(runtime,"POpenProcess 20");
                this.waitForChild = true;
                prepareOutput(child);
            } else {
                log(runtime,"POpenProcess 30");
                this.waitForChild = false;
                // close process output
                // See JRUBY-3405; hooking up to parent process stdin caused
                // problems for IRB etc using stdin.
                try {child.getOutputStream().close();} catch (IOException ioe) {log(runtime, ioe.getMessage());}
            }

            if (modes.isReadable()) {
                log(runtime,"POpenProcess 40");
                prepareInput(child);
            } else {
                log(runtime,"POpenProcess 50");
                pumpInput(child, runtime);
            }
            log(runtime,"POpenProcess 60");
            pumpInerr(child, runtime);
        }```
@enebo

This comment has been minimized.

Copy link
Member

enebo commented Feb 28, 2019

@annabackiyam It looks like you can see something running or at least to the point it is going to read input. you may want to add logging after pumpInerr to see if it raises an exception (e.g. you will not see that log if it does).

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 28, 2019

@enebo That gets printed as well.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Feb 28, 2019

@enebo Everything gets printed until here:
RubyIO: popen in RubyIO....70

There's no exception at all.

``
@JRubyMethod(name = "popen", required = 1, optional = 2, meta = true)
public static IRubyObject popen(ThreadContext context, IRubyObject recv, IRubyObject[] args, Block block) {
Ruby runtime = context.runtime;

    log(runtime, "popen in RubyIO....10");

    if (runtime.getPosix().isNative() && !Platform.IS_WINDOWS) {
        // new native popen logic
        return PopenExecutor.popen(context, args, (RubyClass)recv, block);
    }
    log(runtime, "popen in RubyIO....20");
    // old JDK popen logic
    IRubyObject pmode = null;
    RubyHash options = null;
    IRubyObject tmp;

    int firstArg = 0;
    int argc = args.length;

    if (argc > 0 && !TypeConverter.checkHashType(runtime, args[0]).isNil()) {
        firstArg++;
        argc--;
    }

    if (argc > 0 && !(tmp = TypeConverter.checkHashType(runtime, args[args.length - 1])).isNil()) {
        options = (RubyHash)tmp;
        argc--;
    }

    if (argc > 1) {
        pmode = args[firstArg + 1];
    }

    RubyIO io = new RubyIO(runtime, (RubyClass) recv);

    io.MakeOpenFile();

    Object pm = vmodeVperm(pmode, runtime.newFixnum(0));
    int[] oflags_p = {0}, fmode_p = {0};
    EncodingUtils.extractModeEncoding(context, io, pm, options, oflags_p, fmode_p);
    ModeFlags modes = ModeFlags.createModeFlags(oflags_p[0]);

    // FIXME: Reprocessing logic twice for now...
    // for 1.9 mode, strip off the trailing options hash, if there
    if (args.length > 1 && args[args.length - 1] instanceof RubyHash) {
        options = (RubyHash)args[args.length - 1];
        IRubyObject[] newArgs = new IRubyObject[args.length - 1];
        System.arraycopy(args, 0, newArgs, 0, args.length - 1);
        args = newArgs;
    }

    Ruby19POpen r19Popen = new Ruby19POpen(runtime, args);

    if ("-".equals(r19Popen.cmd.toString())) {
        throw runtime.newNotImplementedError("popen(\"-\") is unimplemented");
    }

    try {
        ShellLauncher.POpenProcess process;
        if (r19Popen.cmdPlusArgs == null) {
            process = ShellLauncher.popen(runtime, r19Popen.cmd, modes);
        } else {
            process = ShellLauncher.popen(runtime, r19Popen.cmdPlusArgs, r19Popen.env, modes);
        }
        log(runtime, "popen in RubyIO....30");
        checkPopenOptions(options);
        log(runtime, "popen in RubyIO....40");
        io.setupPopen(modes, process);
        log(runtime, "popen in RubyIO....50");
        if (block.isGiven()) {
            ensureYieldClose(context, io, block);
            log(runtime, "popen in RubyIO....60");
            // RubyStatus uses real native status now, so we unshift Java's shifted exit status
            context.setLastExitStatus(RubyProcess.RubyStatus.newProcessStatus(runtime, process.waitFor() << 8, ShellLauncher.getPidFromProcess(process)));
        }
        log(runtime, "popen in RubyIO....70");
        return io;
    } catch (IOException e) {
        log(runtime, e.getMessage());
        throw runtime.newIOErrorFromException(e);
    } catch (InterruptedException e) {
        log(runtime, e.getMessage());
        throw runtime.newThreadError("unexpected interrupt");
    }
}

``

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Mar 5, 2019

@annabackiyam possibly print out info in r19Popen to verify the command looks right and possibly log out where it tries to find the command file to make sure it finds it? Thus far it seems like it is trying to run something but obviously it is not working. It is interesting it appears to be trying to execute something.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Mar 5, 2019

@enebo I see the commands are okay in r19Popen as they are printed.
RubyIO: cmdPlusArgs:sh]] RubyIO: cmdPlusArgs:/tmp/RC--20190305-1679293850-z75kvl.sh]]

Still looking where it tries to find the file in the code

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Mar 5, 2019

@annabackiyam were those both on the same log line or two lines? The first one maybe should have ended up as /bin/sh maybe? Possibly changing your code to be /bin/sh may be a good experiment as well. If that worked for some reason then it might just be not having PATH somehow finding sh. Just brainstorming.

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Mar 6, 2019

@enebo here's what I found out. let me know if that gives any pointer.
If I write anything directly to the file, that works. If I try to access (attr_accessor) anything from the outer class variables, it doesn't work. I'm able to print the same variable in the logs just before writing to the file.
This one doesn't work
str = "#{@cmd.to_exec*","}" log(:INFO,str) @temp_file.write(str) @temp_file.flush @temp_file.chmod(0777) @temp_file.close
This one works
@temp_file.write("/bin/cat /var/log/oasg/oasg-cta-filetransfer.log|head -n 5") @temp_file.flush @temp_file.chmod(0777) @temp_file.close

@annabackiyam

This comment has been minimized.

Copy link
Author

annabackiyam commented Mar 6, 2019

@enebo I think I found the problem finally. If the command has "double quotes", it doesn't like that. Unfortunately, popen doesn't give the exact errror message.
Thanks for all your help.

@enebo

This comment has been minimized.

Copy link
Member

enebo commented Mar 6, 2019

@annabackiyam if you can confirm a snippet script can popen with double quotes on C Ruby then definitely submit that script to us and we can fix it. I am happy you got to the bottom of it. I love to see a mystery solved. Although in the back of my mind I wonder why 1.6 worked...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.