exec hangs when program not found

[shague]

Michael,

with the exec package, it seems to hang when the program to run is not found.

Debugger shows that the IOexception was not caught and things kept moving forward and the code gets stuck at a wait() in ExecuteWatchdog:ensureStarted(), line 114. So the ManagedProcessExeception was never thrown.

Can you look at [1] to see if we are calling this correctly.

Thanks, Sam

[1] https://github.com/shague/opendaylight-ansible/blob/master/southbound/impl/src/main/java/org/opendaylight/ansible/southbound/AnsibleCommandServiceImpl.java#L82

[main] INFO ch.vorburger.exec.ManagedProcess - Starting Program [ansible-runner, -j, --hosts, localhost, -p, file, run, path] (in working directory /home/shague/git/ansible/southbound/impl/.)
[Exec Default Executor] ERROR ch.vorburger.exec.LoggingExecuteResultHandler - Program [ansible-runner, -j, --hosts, localhost, -p, file, run, path] (in working directory /home/shague/git/ansible/southbound/impl/.) failed unexpectedly
org.apache.commons.exec.ExecuteException: Execution failed (Exit value: -559038737. Caused by java.io.IOException: Cannot run program "ansible-runner" (in directory "."): error=2, No such file or directory)
at org.apache.commons.exec.DefaultExecutor$1.run(DefaultExecutor.java:205)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: Cannot run program "ansible-runner" (in directory "."): error=2, No such file or directory
at java.lang.ProcessBuilder.start(ProcessBuilder.java:1048)
at java.lang.Runtime.exec(Runtime.java:620)
at org.apache.commons.exec.launcher.Java13CommandLauncher.exec(Java13CommandLauncher.java:61)
at org.apache.commons.exec.DefaultExecutor.launch(DefaultExecutor.java:279)
at org.apache.commons.exec.DefaultExecutor.executeInternal(DefaultExecutor.java:336)
at org.apache.commons.exec.DefaultExecutor.access$200(DefaultExecutor.java:48)
at org.apache.commons.exec.DefaultExecutor$1.run(DefaultExecutor.java:200)
... 1 more
Caused by: java.io.IOException: error=2, No such file or directory
at java.lang.UNIXProcess.forkAndExec(Native Method)
at java.lang.UNIXProcess.(UNIXProcess.java:247)
at java.lang.ProcessImpl.start(ProcessImpl.java:134)
at java.lang.ProcessBuilder.start(ProcessBuilder.java:1029)
... 7 more

[vorburger]

@shague your (and @trozet's ...) [1] looks about right, I guess. But there does indeed seem to be bug related to some sort of deadlock when starting a non existant executable - I can reproduce the "hang" with this in ManagedProcessTest :

    @Test(expected = ManagedProcessException.class)
    public void startForMustFailForWrongExecutable() throws Exception {
        ManagedProcess p = new ManagedProcessBuilder("someExec").build();
        p.start();
    }

I'll debug this further when I have a minute, and fix it.

[vorburger]

I've just deployed a 3.1.1 release with this fix to Maven central; it should be available from there shortly.

[shague]

Thanks for the fix. It works well.

[gsylvie]

3.1.1 still hanging for me in this scenario.

import ch.vorburger.exec.ManagedProcess;
import ch.vorburger.exec.ManagedProcessBuilder;
public class Test {
    public static void main(String[] args) throws Exception {
        ManagedProcessBuilder mpb = new ManagedProcessBuilder("cmd-does-not-exist");
        ManagedProcess p = mpb.build();
        p.start();
    }
}

Running "kill -3" against the hung process shows this culprit:

"Exec Default Executor" #19 prio=5 os_prio=0 tid=0x00007ff504464000 nid=0xb69a in Object.wait() [0x00007ff4de4fa000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000071ae65210> (a org.apache.commons.exec.ExecuteWatchdog)
	at java.lang.Object.wait(Object.java:502)
	at org.apache.commons.exec.ExecuteWatchdog.ensureStarted(ExecuteWatchdog.java:229)
	at org.apache.commons.exec.ExecuteWatchdog.isWatching(ExecuteWatchdog.java:196)
	- locked <0x000000071ae65210> (a org.apache.commons.exec.ExecuteWatchdog)
	at ch.vorburger.exec.ManagedProcess.notifyProcessHalted(ManagedProcess.java:374)
	at ch.vorburger.exec.LoggingExecuteResultHandler.onProcessFailed(LoggingExecuteResultHandler.java:57)
	at ch.vorburger.exec.CompositeExecuteResultHandler.onProcessFailed(CompositeExecuteResultHandler.java:63)
	at org.apache.commons.exec.DefaultExecutor$1.run(DefaultExecutor.java:205)
	at java.lang.Thread.run(Thread.java:748)

[gsylvie]

Note: The main thread is terminating properly (and throwing the exception as expected). But seems a background thread is being created and never terminated - causing the "java" process on my system to hang.

[vorburger]

@gsylvie do you want to check if #96 from @cardamon might fix this problem?

[vorburger]

@mosesn do you have any interest to further dig into if this is still a bug that needs to be fixed?

[vorburger]

@gsylvie you are right. I can reproduce this easily in #188, using your example.

However, the likely culprit appears to more something in https://commons.apache.org/proper/commons-exec/ than in this project?

It's probably worth first checking if #179 already fixes this by chance...

[vorburger]

It's probably worth first checking if #179 already fixes this by chance...

Looks like it does! I should definitely get #179 into #105, in that case...