Confused on Server#shutdownTcpServer()

[Laird Nelson]

I think this might just be a misunderstanding on my part.

I am writing a Maven H2 plugin.  One of the goals it has is the ability to spawn a TCP server (i.e. not just start it up in-process, but launch a new VM on localhost that invokes org.h2.tools.Server's main method and supplies it with arguments like -tcp, -tcpPort, etc.).

So I have code that uses ProcessBuilder and org.h2.tools.Server to spawn a new TCP server.  Works great; survives even after the spawning VM exits.  I can connect to it from various database clients.

Now, I also have code that invokes Server#shutdownTcpServer().

But attempts to shut down a spawned H2 server using Server#shutdownTcpServer() don't work.  Well, they do issue a STOP_SERVER command properly, but the process does not exit.  If the spawned server has -trace turned on, you can see all the "close" statements.  But after it's done closing everything, the process just hangs around.  I don't know why.

Remember, I'm not holding any references to the Process.  I can, for example, spawn the process in one JVM (it launches another JVM to start up the TCP server), and then from yet another JVM issue the Server#shutdownTcpServer() call.  The process remains alive, even after Server#shutdownTcpServer() has returned.

I feel like I must be doing something wrong here, perhaps in my usage of ProcessBuilder.  Before I spend the time to attempt to come up with a test case, has anyone else seen funny behavior from Server#shutdownTcpServer()?  Are there obvious problems with my approach?

Best,
Laird

[Laird Nelson]

I've added another test case to show what I mean and have attached the whole thing as a Maven project again.

Here's the relevant test:

@Test
  public void testSpawnAndShutdown() throws Exception {
    final File temp = new File(System.getProperty("java.io.tmpdir"));

    final File javaHome = new File(System.getProperty("java.home"));
    final File bin = new File(javaHome, "bin");
    final File java = new File(bin, "java");

    final ProtectionDomain pd = Server.class.getProtectionDomain();
    assertNotNull(pd);
    final CodeSource cs = pd.getCodeSource();
    assertNotNull(cs);
    final URL location = cs.getLocation();
    assertNotNull(location);
    final File h2JarFile = new File(location.toURI());

    final String[] args = new String[] { java.getAbsolutePath(), "-cp", h2JarFile.getAbsolutePath(), Server.class.getName(), "-tcp", "-baseDir", temp.getAbsolutePath(), "-trace" };
    final ProcessBuilder pb = new ProcessBuilder(args);
    final Process p = pb.start();
    assertNotNull(p);

    org.h2.server.TcpServer.shutdown("tcp://localhost:9092", null, false, false);

    System.out.println("Shutdown complete...but not really!");

    assertEquals(0, p.exitValue()); // XXX kaboom

  }

On my MacBook Pro, the last assertEquals() fails reliably--shutdown completes, as you can see, but the process does not in fact exit.  You can see this for yourself by doing a ps -ef | grep h2.

Like I said, I'm not sure if this is a bug or if it's just me not using ProcessBuilder correctly.

Best,
Laird

[Noel Grandin]

Could you try connecting to the offending process and getting a stack dump. VisualVM should do the trick. That should tell us which thread is the problem.

> --
> You received this message because you are subscribed to the Google Groups "H2 Database" group.
> To view this discussion on the web visit https://groups.google.com/d/msg/h2-database/-/YO2aKN5RwE0J.
> To post to this group, send email to h2-da...@googlegroups.com.
> To unsubscribe from this group, send email to h2-database...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/h2-database?hl=en.
>

[Laird Nelson]

To be clear, you want me to hook up to the killing process, or the process to be killed?  I assume you mean the running TCP server that I am trying to kill.

Best,
Laird

[Laird Nelson]

OK, stand back.  I opened up JVisualVM.  I connected it to the H2 server that I had previously started with the following command line:

java -cp ~/.m2/repository/com/h2database/h2/1.3.160/h2-1.3.160.jar org.h2.tools.Server -tcp

Then I ran a one-liner Java program that has the following call in it:

TcpServer.shutdown(String.format("tcp://%s:9092", java.net.InetAddress.getLocalHost().getHostAddress()), null, true, false);

This program ran and exited normally.  If it matters, I ran it as a JUnit test, but I can't see how that would make a difference.

Then from the Threads tab in JVisualVM I pressed the Thread Dump button and the results are below.  Thanks for looking into this.

Best,
Laird

2011-10-28 16:24:56
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.1-b02-384 mixed mode):

"RMI TCP Connection(3)-192.168.5.248" daemon prio=9 tid=10b92b800 nid=0x10d816000 runnable [10d815000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
    - locked <7f40a2040> (a java.io.BufferedInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:66)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:517)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - <7f46a8650> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"JMX server connection timeout 22" daemon prio=9 tid=101801000 nid=0x10d713000 in Object.wait() [10d712000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <7f44e27c0> (a [I)
    at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:150)
    - locked <7f44e27c0> (a [I)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - None

"RMI Scheduler(0)" daemon prio=9 tid=106813000 nid=0x10d610000 waiting on condition [10d60f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <7f44e2808> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
    at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - None

"RMI TCP Connection(1)-192.168.5.248" daemon prio=9 tid=10681f800 nid=0x10d50d000 runnable [10d50c000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
    - locked <7f45e3148> (a java.io.BufferedInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:66)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:517)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - <7f4540150> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"RMI TCP Accept-0" daemon prio=9 tid=107374800 nid=0x10d40a000 runnable [10d409000]
   java.lang.Thread.State: RUNNABLE
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
    - locked <7f44e4b40> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:462)
    at java.net.ServerSocket.accept(ServerSocket.java:430)
    at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:34)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - None

"Poller SunPKCS11-Darwin" daemon prio=1 tid=10b92c800 nid=0x10d307000 waiting on condition [10d306000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at sun.security.pkcs11.SunPKCS11$TokenPoller.run(SunPKCS11.java:692)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - None

"Attach Listener" daemon prio=9 tid=10b92b000 nid=0x10d204000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"DestroyJavaVM" prio=5 tid=1068cb000 nid=0x100501000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"H2 TCP Server (tcp://192.168.5.248:9092)" prio=5 tid=107367800 nid=0x10d101000 runnable [10d100000]
   java.lang.Thread.State: RUNNABLE
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
    - locked <7f44e4bb8> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:462)
    at java.net.ServerSocket.accept(ServerSocket.java:430)
    at org.h2.server.TcpServer.listen(TcpServer.java:239)
    at org.h2.tools.Server.run(Server.java:451)
    at java.lang.Thread.run(Thread.java:680)

   Locked ownable synchronizers:
    - None

"Low Memory Detector" daemon prio=5 tid=1070d7800 nid=0x10c60d000 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread1" daemon prio=9 tid=1070d6800 nid=0x10c50a000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread0" daemon prio=9 tid=1070d6000 nid=0x10c407000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" daemon prio=9 tid=1070d5000 nid=0x10c304000 runnable [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Surrogate Locker Thread (Concurrent GC)" daemon prio=5 tid=1070d4800 nid=0x10c201000 waiting on condition [00000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Finalizer" daemon prio=8 tid=1070cf800 nid=0x10abf8000 in Object.wait() [10abf7000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <7f44e5308> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <7f44e5308> (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)

   Locked ownable synchronizers:
    - None

"Reference Handler" daemon prio=10 tid=1070cf000 nid=0x10aaf5000 in Object.wait() [10aaf4000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <7f44e3908> (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 <7f44e3908> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"VM Thread" prio=9 tid=1070ca000 nid=0x10a9f2000 runnable

"Gang worker#0 (Parallel GC Threads)" prio=9 tid=106800000 nid=0x102501000 runnable

"Gang worker#1 (Parallel GC Threads)" prio=9 tid=107000000 nid=0x102604000 runnable

"Gang worker#2 (Parallel GC Threads)" prio=9 tid=107001000 nid=0x102707000 runnable

"Gang worker#3 (Parallel GC Threads)" prio=9 tid=107001800 nid=0x106102000 runnable

"Concurrent Mark-Sweep GC Thread" prio=9 tid=10707c800 nid=0x10a501000 runnable
"VM Periodic Task Thread" prio=10 tid=1070e9000 nid=0x10c710000 waiting on condition

"Exception Catcher Thread" prio=10 tid=101802000 nid=0x1017f9000 runnable
JNI global references: 1282

[Noel Grandin]

Hmm, I'm not entirely sure there is a bug here.
It looks like the server does not have enough time to finish starting
up before the shutdown command executes.
The shutdown command thinks that the server is not there, so it just
completes normally.
I suspect that if you put Thread.sleep(500) between start() and
stop(), everything will be fine.

Either way, I will try your test case on monday when I'm back at my
regular machine.

Regards, Noel.

[Laird Nelson]

Hmm; I've now tried it by spawning an H2 tcp server the "normal" way, e.g. from the command line.  So the thing has all day to start and settle in.  :-)

Then I run my one-line shutdown program (TcpServer.shutdown()).  Same result: the shutdown program completes normally; the server stays up.

Thanks for the help here.

Best,
Laird

[Laird Nelson]

Just some follow up.

I've launched an H2 1.3.161 TCP server from the command line using:

java -cp /Users/ljnelson/lib/h2.jar org.h2.tools.Server -baseDir /Users/ljnelson -trace -tcp -tcpPort 9092

I give it a few seconds to get settled.

Then I debugged my one-line test case and set a breakpoint on TcpServer.shutdown().  I confirmed that this is indeed connecting to the server and sending it a CALL STOP_SERVER() command.  The shutdown() call completes normally and the test case passes.

Meanwhile, on the server side, the server spits this out and then stays up:

org.h2.server.TcpServerThread@7290cb03 Connect
org.h2.server.TcpServerThread@7290cb03 Connected
org.h2.server.TcpServerThread@7290cb03 Close
org.h2.server.TcpServerThread@7290cb03 Disconnect
org.h2.server.TcpServerThread@7290cb03 Close

So the server is receiving and processing the client's call.  But it won't shut down.

Thanks again for the help so far.

Best,
Laird

[Laird Nelson]

Password issue; I was passing null (since on the command line shutdown script I don't pass tcpPassword at all so I figured that null was the proper thing to pass here); the server needed the empty string (""), which must be the management password?  Even though a user isn't specified during shutdown?  Anyway.  Thanks and sorry.

As an aside, in order to debug the server I needed to modify the Build.java file to actually supply the -g argument to the compiler and rebuild H2 from source; I didn't see anywhere that it was possible to cause this to happen programmatically.

Best,
Laird

[Thomas Mueller]

Hi,

> Works great; survives even after the spawning VM exits.

Hm, I think on some operating systems the process will be killed when
the spawning VM exits.

> the process just hangs around.  I don't know why.

I suggest to use "jps -l" to get the process id, and the "jstack -l
<pid>" to get the full thread dump. Or use "kill -QUIT <pid>" (Linux).
Then post the full thread dump. Any non-daemon thread will keep the
process alive.

> Remember, I'm not holding any references to the Process.

This doesn't matter.

Regards,
Thomas

[Laird Nelson]

On Tuesday, November 1, 2011 4:21:46 PM UTC-4, Thomas Mueller wrote:

Hm, I think on some operating systems the process will be killed when
the spawning VM exits.

Which OSes?  I'm not observing that on Windows or Mac OSX for what it's worth.

Best,
Laird

[Thomas Mueller]

Hi,

Please note you need to use shutdownForce to force closing existing connections.

 

I can't reproduce the problem. What I do is:

    java -cp . org.h2.tools.Server -trace -tcp -tcpPort 9092

and then from another process

    java -cp . org.h2.tools.Server -tcpShutdown "tcp://localhost:9092"

Could you try that? If it doesn't stop for you, could you run

    jps -l

and then

    jstack -l <pid>

To get the full thread dump, and paste the result?

Regards,

Thomas

[kensystem]

Since I too have had this question/issue, I tried this.. it worked!
(nut using "-tcpShutdownForce", not "-shutdownForce" which Thomas gave
probably from memory). I never could figure out why it would stay
running, but with connection-pools, Thomas's explanation makes sense
(and -tcpShutdownForce seems to be required).

A simple Linux init script I use:

#!/bin/bash
#
# h2db
#
# chkconfig: - 80 20
# description: H2DB
# processname: h2db
# pidfile: /var/run/hsdb.pid
# config: /var/tomcat/conf/

H2_HOME="/var/tomcat/h2db/h2-1.3.159.jar"
H2_DATA="/var/tomcat/h2db/"

# Source function library.
. /etc/init.d/functions

RETVAL=$?

start() {
echo -n $"Starting H2DB"
daemon --user www "java -Xmx256M -Dh2.queryCacheSize=0 -
Dh2.returnLobObjects=false -Dh2.objectCacheSize=50000 -
Dh2.pageSize=8192 -Dh2.maxMemoryRows=100000 -cp $H2_HOME
org.h2.tools.Server -tcpAllowOthers -tcpPort 9101 -baseDir $H2_DATA &"
RETVAL=$?
echo
[ $RETVAL = 0 ] && touch /var/lock/subsys/h2db
}
stop() {
echo -n $"Stopping H2DB"
daemon --user www "java -cp $H2_HOME org.h2.tools.Server -
tcpShutdownForce -tcpShutdown \"tcp://localhost:9101\" "
RETVAL=$?
echo
[ $RETVAL = 0 ] && rm -f /var/lock/subsys/h2db
}

case "$1" in
start)
start
;;
restart)
stop
start
;;
stop)
stop
;;
esac


exit $RETVAL

[Thomas Mueller]

Hi,

Which OSes?  I'm not observing that on Windows or Mac OSX for what it's worth.

Actually I'm not sure. It is my interpretation of this bug: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4717969

Regards,

Thomas

[Laird Nelson]

On Friday, November 4, 2011 2:15:19 AM UTC-4, Thomas Mueller wrote:

I can't reproduce the problem.

As I remarked in a separate post, it was a password problem.

When you start the tcp server from the command line without specifying a password, then the effective password that H2 needs to log in to the management database is the empty string ("").

TcpServer.shutdown() takes a password parameter.  I was passing null instead of the empty string, so the server was rejecting the shutdown request.

Best,
Laird

[Laird Nelson]

On Sunday, November 6, 2011 5:35:18 AM UTC-5, Thomas Mueller wrote:

Which OSes?  I'm not observing that on Windows or Mac OSX for what it's worth.

Actually I'm not sure. It is my interpretation of this bug: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4717969

Right; that's not quite the same thing here.   If my process spawner stuck around, and I tried to kill it, then bug 4717969 (superseded by bug 4109888) might mean that my process spawner would die, but not the process it spawned.

In my case, my process spawner wouldn't live long enough anyway to be killed.  :-)

I've now verified the process behavior on Mac OSX, Windows and Linux.  You can see the (extremely early, raw) results of my labor here: http://github.com/ljnelson/h2-maven-plugin

Best,
Laird

--
http://about.me/lairdnelson

[Thomas Mueller]

Hi,

Yes, currently unused connection stay open when using the built-in connection pool.

Regards,

Thomas