#9 Program hangs on exit

[libzhark]

Using the example code in a simple, the application will hang before exiting.
*****
import java.io.IOException;

import expectj.ExpectJ;
import expectj.ExpectJException;
import expectj.Spawn;
import expectj.TimeoutException;

public class SshTest {

/**
* @param args
*/
public static void main(String[] args) {
ExpectJ expectinator = new ExpectJ(15);

try {
// Fork the process
Spawn shell = expectinator.spawn("/bin/sh");

// Talk to it
shell.send("echo Chunder\n");
shell.expect("Chunder");
shell.send("exit\n");
shell.expectClose();
} catch (IOException e) {
// TODO Auto-generated catch block
e.printStackTrace();
} catch (TimeoutException e) {
// TODO Auto-generated catch block
e.printStackTrace();
} catch (ExpectJException e) {
// TODO Auto-generated catch block
e.printStackTrace();
}

System.out.println("done");

}

}
*****
After printing "done", the application will wait for about 15 (or whatever timeout is supplied in the ExpectJ constructor) seconds before actually exiting.

[libzhark]

This is using 2.0.7 under Ubuntu 9.10, OpenJDK (IcedTea6 1.8.2)

[libzhark]

Same issue using Sun Java 1.6.0_22-b04

[Johan Walles]

Hi!

Can you please send SIGQUIT to the JVM after it has printed "done" but before it has exited?

It will then produce a thread dump on stdout. Please post that thread dump here.

Regards //Johan

[libzhark]

I upped the ExceptJ timeout to 45 seconds to give me more time to find the PID. Full stdout dump is below:

Chunder
done
2010-11-11 09:19:05
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.1-b03 mixed mode):

"DestroyJavaVM" prio=10 tid=0x00007f85d806d000 nid=0xc37 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"ExpectJ Timer Thread, 45000ms" prio=10 tid=0x00007f85d806c800 nid=0xc50 in Object.wait() [0x00007f85ddfc4000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f860c4ac188> (a expectj.Timer)
at expectj.Timer.run(Timer.java:112)
- locked <0x00007f860c4ac188> (a expectj.Timer)
at java.lang.Thread.run(Thread.java:662)

"ExpectJ Timer Thread, 45000ms" prio=10 tid=0x0000000040e2e000 nid=0xc4d in Object.wait() [0x00007f85de2e4000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f860c35e5a8> (a expectj.Timer)
at expectj.Timer.run(Timer.java:112)
- locked <0x00007f860c35e5a8> (a expectj.Timer)
at java.lang.Thread.run(Thread.java:662)

"Low Memory Detector" daemon prio=10 tid=0x0000000040df6000 nid=0xc48 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x0000000040df2800 nid=0xc47 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x0000000040def000 nid=0xc46 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000040dec800 nid=0xc45 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000040dcd000 nid=0xc42 in Object.wait() [0x00007f85deb2b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f860c2411f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00007f860c2411f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000040dc5800 nid=0xc41 in Object.wait() [0x00007f85dec2c000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f860c241050> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x00007f860c241050> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0000000040dc1000 nid=0xc40 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000040d77000 nid=0xc38 runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000040d78800 nid=0xc39 runnable

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040d7a800 nid=0xc3a runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040d7c800 nid=0xc3b runnable

"VM Periodic Task Thread" prio=10 tid=0x0000000040e01000 nid=0xc49 waiting on condition

JNI global references: 993

Heap
PSYoungGen total 17536K, used 3040K [0x00007f860c240000, 0x00007f860d5d0000, 0x00007f861fb90000)
eden space 15040K, 20% used [0x00007f860c240000,0x00007f860c538200,0x00007f860d0f0000)
from space 2496K, 0% used [0x00007f860d360000,0x00007f860d360000,0x00007f860d5d0000)
to space 2496K, 0% used [0x00007f860d0f0000,0x00007f860d0f0000,0x00007f860d360000)
PSOldGen total 40064K, used 0K [0x00007f85e4f90000, 0x00007f85e76b0000, 0x00007f860c240000)
object space 40064K, 0% used [0x00007f85e4f90000,0x00007f85e4f90000,0x00007f85e76b0000)
PSPermGen total 21248K, used 3891K [0x00007f85dfb90000, 0x00007f85e1050000, 0x00007f85e4f90000)
object space 21248K, 18% used [0x00007f85dfb90000,0x00007f85dff5ccc0,0x00007f85e1050000)

[libzhark]

I've got this fixed, atleast for my system. There were two problems I found. First, the Timer object in SpawnableHelper was never being closed. Second, the Timer created inside of Spawn.explectClose(long) had a race condition. In this function, the call to tm.close() was kicking off the notify() for the Timer before the thread created by the tm.startTimer() cal had a chance to get in to its wait(). Below is a diff that fixes this on my system. The SpawnableHelper change I'm confident about. The Spawn change I dont think will cause any race conditions on other systems, with the new STARTING state of the Timer, but I could be wrong.

Index: /expectj/Timer.java

===================================================================

--- /expectj/Timer.java (revision 0)

+++ /expectj/Timer.java (revision 1)

@@ -25,23 +25,28 @@

* Timer not started.

*/

public static final int NOT_STARTED = 0;

/**

+ * Timer not started.

+ */

+ public static final int STARTING = 1;

+

+ /**

* Timer started and still running.

*/

- public static final int STARTED = 1;

+ public static final int STARTED = 2;

/**

* Timer timed out.

*/

- public static final int TIMEDOUT = 2;

+ public static final int TIMEDOUT = 3;

/**

* Timer interrupted.

*/

- public static final int INTERRUPTED = 3;

+ public static final int INTERRUPTED = 4;

/**

* Stores the current status of Timer

*/

private int currentStatus = NOT_STARTED;

@@ -75,11 +80,11 @@

/**

* Starts the timer

*/

public void startTimer() {

thread = new Thread(this, "ExpectJ Timer Thread, " + timeOut + "ms");

- currentStatus = STARTED;

+ currentStatus = STARTING;

thread.start();

}

/**

* Return timer status. Can be one of {@link #NOT_STARTED}, {@link #STARTED},

@@ -95,10 +100,17 @@

* Close the timer prematurely. The event listener won't get any

* notifications.

*/

public void close() {

synchronized (this) {

+ if (currentStatus==STARTING)

+ {

+ try {

+ this.wait();

+ } catch (InterruptedException e) {

+ }

+ }

done = true;

this.notify();

}

}

@@ -107,18 +119,23 @@

*/

public void run() {

try {

// Sleep for the specified time

synchronized (this) {

+ currentStatus = STARTED;

+ this.notify();

this.wait(timeOut);

if (done) {

+ currentStatus = NOT_STARTED;

+ this.notify();

// We've been nicely asked to quit

return;

}

// Jag Utha Shaitan, Its time to invoke the listener

currentStatus = TIMEDOUT;

+ this.notify();

listener.timerTimedOut();

}

} catch (InterruptedException iexp) {

currentStatus = INTERRUPTED;

listener.timerInterrupted(iexp);

Index: /expectj/SpawnableHelper.java

===================================================================

--- /expectj/SpawnableHelper.java (revision 0)

+++ /expectj/SpawnableHelper.java (revision 1)

@@ -191,10 +191,13 @@

systemErr.source().close();

} catch (IOException e) {

LOG.warn("Closing stderr source failed", e);

}

}

+ if (timer != null) {

+ timer.close();

+ }

}

/**

* @return a channel from which data produced by the spawn can be read

*/