BZ #93: Mauve on CACAO/OpenJDK does not timeout correctly

Status fields:

creation_ts:2008-07-27 13:52
component:unspecified
version:default branch
rep_platform:All
op_sys:Linux
bug_status:RESOLVED
resolution:FIXED
reporter:twisti@complang.tuwien.ac.at
This happens when running e.g:

$ java Harness -vm java java.awt.Container.addImpl java.awt.Container.getComponentAt

Comment #1 by twisti@complang.tuwien.ac.at on 2008-07-27 13:56:38

After adding debug output to Harness.java, it seems that closing the in/out streams from
the runner process does not work correctly.

While HotSpot shows this:

TEST: java.awt.Container.getComponentAt
runner_in.readLine();
TimeoutWatcher.run(): shouldContinue=false
TimeoutWatcher.run(): exit
TimeoutWatcher.run(): wait=3000
TimeoutWatcher.run(): shouldContinue=true
this.runnerProcess.destroy();
this.runnerProcess.getInputStream().close();
this.runnerProcess.getErrorStream().close();
this.runnerProcess.getOutputStream().close();
TimeoutWatcher.run(): exit
outputFromTest=null
TimeoutWatcher.stop()
java.lang.Exception: Stack trace
        at java.lang.Thread.dumpStack(Thread.java:1223)
        at Harness$TimeoutWatcher.stop(Harness.java:1464)
        at Harness.initProcess(Harness.java:700)
        at Harness.runTest(Harness.java:822)
        at Harness.processSingleTest(Harness.java:1193)
        at Harness.processTest(Harness.java:919)
        at Harness.runAllTests(Harness.java:725)
        at Harness.main(Harness.java:188)

CACAO shows this:

TEST: java.awt.Container.getComponentAt
runner_in.readLine();
TimeoutWatcher.run(): shouldContinue=false
TimeoutWatcher.run(): exit
TimeoutWatcher.run(): wait=3000
TimeoutWatcher.run(): shouldContinue=true
this.runnerProcess.destroy();
this.runnerProcess.getInputStream().close();
this.runnerProcess.getErrorStream().close();
this.runnerProcess.getOutputStream().close();
TimeoutWatcher.run(): exit
<hang>

Note that:

          outputFromTest = runner_in.readLine();

does not return null on CACAO.

Comment #2 by twisti@complang.tuwien.ac.at on 2008-07-27 14:42:15

Here is a testcase that reproduces the problem:

import java.io.*;

public class PR93 {
    private static Process process = null;
    private static BufferedReader in = null;

    public static void main(String[] args) throws Throwable {
        process = Runtime.getRuntime().exec("java PR93process");
        in = new BufferedReader(new InputStreamReader(process.getInputStream()));
        new PR93Watcher().start();

        System.out.println("PR93: reading from input stream...");
        while (true) {
            String line = in.readLine();
            System.out.println("PR93: line=" + line);

            if (line == null)
                System.exit(0);
        }
    }

    private static class PR93Watcher extends Thread {
        public void run() {
            try {
                System.out.println("PR93Watcher: sleeping 3 second...");
                Thread.sleep(3000);
                System.out.println("PR93Watcher: destroying process...");
                process.destroy();
                System.out.println("PR93Watcher: closing input stream...");
                in.close();
            }
            catch (Exception e) {
                e.printStackTrace();
                System.exit(1);
            }
        }
    }
}

class PR93process {
    public static void main(String[] args) throws Throwable {
        for (int i = 0; i < 10; i++) {
            Thread.sleep(1000);
            System.out.println("PR93process: " + i);
        }
    }
}

Comment #3 by twisti@complang.tuwien.ac.at on 2008-07-27 14:44:44

This is HotSpot's output:

$ java PR93
PR93: reading from input stream...
PR93Watcher: sleeping 3 second...
PR93: line=PR93process: 0
PR93: line=PR93process: 1
PR93Watcher: destroying process...
PR93Watcher: closing input stream...
PR93: line=null

This is CACAO/OpenJDK:

$ java PR93
PR93: reading from input stream...
PR93Watcher: sleeping 3 second...
PR93: line=PR93process: 0
PR93: line=PR93process: 1
PR93Watcher: destroying process...
PR93Watcher: closing input stream...
Exception in thread "main" java.io.IOException: Stream closed
        at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:162)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:272)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:282)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:324)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:176)
        at java.io.InputStreamReader.read(InputStreamReader.java:184)
        at java.io.BufferedReader.fill(BufferedReader.java:153)
        at java.io.BufferedReader.readLine(BufferedReader.java:316)
        at java.io.BufferedReader.readLine(BufferedReader.java:379)
        at PR93.main(PR93.java:14)

This is CACAO/GNU Classpath (which should actually work, as it does with Mauve):

$ cacao PR93
PR93: reading from input stream...
PR93Watcher: sleeping 3 second...
PR93: line=PR93process: 0
PR93: line=PR93process: 1
PR93Watcher: destroying process...
PR93: line=PR93process: 2
PR93Watcher: closing input stream...
Exception in thread "main" java.lang.NullPointerException
   at java.io.BufferedReader.readLine(BufferedReader.java:477)
   at PR93.main(PR93.java:14)

And this is GCJ's output:

$ gij PR93
PR93Watcher: sleeping 3 second...
PR93: reading from input stream...
PR93: line=PR93process: 0
PR93: line=PR93process: 1
PR93Watcher: destroying process...
PR93Watcher: closing input stream...
Exception in thread "main" java.lang.NullPointerException
   at java.io.BufferedReader.readLine(libgcj.so.70)
   at PR93.main(PR93.java:14)

Comment #4 by twisti@complang.tuwien.ac.at on 2008-07-27 15:01:14

When I remove the process.destroy() call, I get the same exception on HotSpot and CACAO:

$ java PR93
PR93: reading from input stream...
PR93Watcher: sleeping 3 second...
PR93: line=PR93process: 0
PR93: line=PR93process: 1
PR93Watcher: closing input stream...
PR93: line=PR93process: 2
Exception in thread "main" java.io.IOException: Stream closed
        at java.io.BufferedReader.ensureOpen(BufferedReader.java:114)
        at java.io.BufferedReader.readLine(BufferedReader.java:309)
        at java.io.BufferedReader.readLine(BufferedReader.java:379)
        at PR93.main(PR93.java:14)

Comment #5 by twisti@complang.tuwien.ac.at on 2008-07-27 15:47:08

Yes, the problem is in Process.destroy().  Still searching...

Comment #6 by twisti@complang.tuwien.ac.at on 2008-07-28 11:33:27

I just found out that HotSpot does not use the HPI interface (the libhpi.so one) on
Linux:

// Because the interruptible IO has been dropped for HotSpot/Linux,
// the following HPI interface is very different from HotSparc.

See:
http://hg.openjdk.java.net/jdk7/jdk7/hotspot/file/tip/src/os/linux/vm/hpi_linux.hpp

Comment #7 by twisti@complang.tuwien.ac.at on 2008-07-28 14:58:00

I found out that readLine() returning null is just luck.  When running it with
-verbose:class, the small delays seem to be enough to get the same exception with
CACAO/OpenJDK.

But I further debugged the problem and attach GDB to the processes and it seems the
problem is not the blocking system call but CACAO/OpenJDK does not handle SIGTERM
properly.  I'm digging further...

Comment #8 by twisti@complang.tuwien.ac.at on 2008-07-28 14:58:54

Typo.  This should read:

...get the same exception *as* with CACAO/OpenJDK.

Comment #9 by twisti@complang.tuwien.ac.at on 2008-07-30 10:39:25

I found the problem.  We don't dispatch the registered signals to the Java handlers.
That's why SIGTERMs have been ignored, which is the signal used by Process.destroy().
Patch coming soon.

Comment #10 by twisti@complang.tuwien.ac.at on 2008-07-30 10:43:06

http://mips.complang.tuwien.ac.at/hg/cacao/rev/91ca9cb09a79

Comment #11 by twisti@complang.tuwien.ac.at on 2008-07-30 13:28:50

I have also added a Mauve test for Process.destroy():

http://sources.redhat.com/ml/mauve-patches/2008/msg00055.html