Client not stopping gracefully intermittely
Ninju Bohra <ninju-/[email protected]>
| Newsgroups | gmane.comp.java.openjms.user |
|---|---|
| Message-ID | <[email protected]> |
Hello all,
We had using 0.7.6.1 and all was reasonable well, but when we moved to
0.7.7-alpha-3 (to get the fix to bug #1214292) we are now having an
issue that our client applications are not closing gracefully 90% of
the time.
The openJMS client is a Tomcat 5.5.12 webapp and we are using JDK
1.5.0_04-b05 on a WinXP (SP2) box. When we ask Tomcat to STOP, the web
server stops, however the process does not exit due to some non-deamon
threads still running. Some of the threads remaining are named "RMI
Reaper", "Clock Daemon", "ManagedConnectionReaper1" and others.
We are using the openJMS in a non-persistent non-durable
publisher/subscriber mode with the embedded RMI.
Here is the code that is used to start the connection:
private void initalizeJMSConnection() throws NamingException,
JMSException {
String topicName = schemaName + "_Topic";
String providerURL = "rmi://" + hostname + ":" + portNumber +
"/";
properties.put(Context.INITIAL_CONTEXT_FACTORY,
"org.exolab.jms.jndi.InitialContextFactory");
properties.put(Context.PROVIDER_URL, providerURL);
logger.info("Trying to listen to the connection named '" +
topicName
+ "' on the connectionFactory called '"
+ connectionFactoryName
+ "' hosted on JMS located at '"
+ providerURL);
Context jndiContext = new
javax.naming.InitialContext(properties);
connectionFactory = (TopicConnectionFactory)
jndiContext.lookup(connectionFactoryName);
Topic dest = (Topic) jndiContext.lookup(topicName);
connection = connectionFactory.createTopicConnection();
session = connection.createTopicSession(false,
Session.AUTO_ACKNOWLEDGE);
subscriber = session.createSubscriber(dest);
subscriber.setMessageListener(this);
connection.setExceptionListener(this);
connection.start();
logger.info("JMS Connection setup properly");
}
And here is the code to stop/close the connection:
public void stopListening() throws JMSException {
if (connection != null) {
connection.stop();
}
if (subscriber != null) {
subscriber.close();
}
if (session != null) {
session.close();
}
if (connection != null) {
connection.close();
}
}
When the tomcat process does NOT gracefully stop, I do a Ctrl-Break and
get the follow thread dump:
Mar 21, 2006 4:00:45 PM org.apache.coyote.http11.Http11BaseProtocol
destroy
INFO: Stopping Coyote HTTP/1.1 on http-30080
Mar 21, 2006 4:01:20 PM org.apache.catalina.loader.WebappClassLoader
loadClass
INFO: Illegal access: this web application instance has been stopped
already. Could not load resoft.framework.memento.MementoContext$1.
The eventual following stack trace is caus
ed by an error thrown for debugging purposes as well as to attempt to
terminate the thread which caused the illegal access, and has no
functional impact.
Mar 21, 2006 10:01:20 PM
resoft.framework.appsvr.sessionmgmt.AppSessionCtx finalize
INFO: ...AppSessionCtx.finalize()
Mar 21, 2006 4:01:20 PM org.apache.catalina.loader.WebappClassLoader
loadClass
INFO: Illegal access: this web application instance has been stopped
already. Could not load resoft.framework.memento.MementoContext$1.
The eventual following stack trace is caus
ed by an error thrown for debugging purposes as well as to attempt to
terminate the thread which caused the illegal access, and has no
functional impact.
Mar 21, 2006 4:01:20 PM org.apache.catalina.loader.WebappClassLoader
loadClass
INFO: Illegal access: this web application instance has been stopped
already. Could not load
org.exolab.jms.net.connector.DefaultConnectionPool$IdleReaper. The
eventual following
stack trace is caused by an error thrown for debugging purposes as
well as to attempt to terminate the thread which caused the illegal
access, and has no functional impact.
Mar 21, 2006 4:01:20 PM org.apache.catalina.loader.WebappClassLoader
loadClass
INFO: Illegal access: this web application instance has been stopped
already. Could not load
org.exolab.jms.net.connector.DefaultConnectionPool$IdleReaper. The
eventual following
stack trace is caused by an error thrown for debugging purposes as
well as to attempt to terminate the thread which caused the illegal
access, and has no functional impact.
Full thread dump Java HotSpot(TM) Client VM (1.5.0_04-b05 mixed mode):
"DestroyJavaVM" prio=5 tid=0x00038220 nid=0x151c waiting on condition
[0x00000000..0x0007fae8]
"TP-Processor4" daemon prio=5 tid=0x2c6c85f0 nid=0x1458 in
Object.wait() [0x2db6f000..0x2db6fae8]
at java.lang.Object.wait(Native Method)
- waiting on <0x06004ba8> (a
org.apache.jk.common.ChannelSocket)
at java.lang.Object.wait(Object.java:474)
at
org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:287)
- locked <0x06004ba8> (a org.apache.jk.common.ChannelSocket)
at
org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:637)
at
org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:847)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
"http-30080-Processor4" daemon prio=5 tid=0x2cbc86c0 nid=0x1078 waiting
on condition [0x2d9ef000..0x2d9ef9e8]
at java.lang.Thread.sleep(Native Method)
at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:61)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
"ManagedConnectionReaper1" daemon prio=5 tid=0x2cd4ee58 nid=0x15d8 in
Object.wait() [0x2d82f000..0x2d82fd68]
at java.lang.Object.wait(Native Method)
- waiting on <0x05ed1ca8> (a
EDU.oswego.cs.dl.util.concurrent.ClockDaemon)
at
EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(Unknown Source)
- locked <0x05ed1ca8> (a
EDU.oswego.cs.dl.util.concurrent.ClockDaemon)
at
EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(Unknown
Source)
at java.lang.Thread.run(Thread.java:595)
"RMI LeaseChecker" daemon prio=5 tid=0x2c950188 nid=0xfc4 waiting on
condition [0x2d7ef000..0x2d7ef9e8]
at java.lang.Thread.sleep(Native Method)
at sun.rmi.transport.DGCImpl$LeaseChecker.run(DGCImpl.java:310)
at java.lang.Thread.run(Thread.java:595)
"RMI TCP Connection(1)-10.3.81.25" daemon prio=5 tid=0x2cd588a0
nid=0x384 runnable [0x2d7af000..0x2d7afa68]
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:235)
- locked <0x05ecd338> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(FilterInputStream.java:66)
at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:442)
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)
at java.lang.Thread.run(Thread.java:595)
"RMI Reaper" prio=5 tid=0x2d1f95f0 nid=0x5ac in Object.wait()
[0x2d76f000..0x2d76fb68]
at java.lang.Object.wait(Native Method)
- waiting on <0x059383f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x059383f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at
sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:336)
at java.lang.Thread.run(Thread.java:595)
"RMI ConnectionExpiration-[10.3.81.25:1099]" daemon prio=5
tid=0x2d1f8c70 nid=0x380 waiting on condition [0x2d72f000..0x2d72fbe8]
at java.lang.Thread.sleep(Native Method)
at
sun.rmi.transport.tcp.TCPChannel$Reaper.run(TCPChannel.java:447)
at java.lang.Thread.run(Thread.java:595)
"GC Daemon" daemon prio=2 tid=0x2c84a678 nid=0x3a4 in Object.wait()
[0x2d6ef000..0x2d6efae8]
at java.lang.Object.wait(Native Method)
- waiting on <0x06032f78> (a sun.misc.GC$LatencyLock)
at sun.misc.GC$Daemon.run(GC.java:100)
- locked <0x06032f78> (a sun.misc.GC$LatencyLock)
"RMI RenewClean-[10.3.81.25:1099]" daemon prio=5 tid=0x2c84a4f8
nid=0xfe0 in Object.wait() [0x2d6af000..0x2d6afc68]
at java.lang.Object.wait(Native Method)
- waiting on <0x0602fe30> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x0602fe30> (a java.lang.ref.ReferenceQueue$Lock)
at
sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:500)
at java.lang.Thread.run(Thread.java:595)
"Clock Daemon" daemon prio=10 tid=0x2cd970f8 nid=0x17f0 waiting on
condition [0x2d62f000..0x2d62fd68]
at java.lang.Thread.sleep(Native Method)
at org.exolab.jms.common.uuid.Clock.run(Clock.java:210)
"RMI TCP Accept-0" daemon prio=5 tid=0x2c9345c8 nid=0x7d8 runnable
[0x2ccef000..0x2ccefbe8]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x05938db0> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at
sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:334)
at java.lang.Thread.run(Thread.java:595)
"Timer-0" daemon prio=5 tid=0x2c9340c8 nid=0xd54 in Object.wait()
[0x2ccaf000..0x2ccafc68]
at java.lang.Object.wait(Native Method)
- waiting on <0x059385c0> (a java.util.TaskQueue)
at java.lang.Object.wait(Object.java:474)
at java.util.TimerThread.mainLoop(Timer.java:483)
- locked <0x059385c0> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)
"Low Memory Detector" daemon prio=5 tid=0x00a937d0 nid=0x7e0 runnable
[0x00000000..0x00000000]
"CompilerThread0" daemon prio=10 tid=0x00a923a8 nid=0x15b0 waiting on
condition [0x00000000..0x2c5ff6cc]
"Signal Dispatcher" daemon prio=10 tid=0x00a91730 nid=0x10dc waiting on
condition [0x00000000..0x00000000]
"Finalizer" daemon prio=9 tid=0x00a88bf0 nid=0x1444 in Object.wait()
[0x2c57f000..0x2c57fa68]
at java.lang.Object.wait(Native Method)
- waiting on <0x058f0768> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x058f0768> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x00a87760 nid=0x710 in
Object.wait() [0x0099f000..0x0099fae8]
at java.lang.Object.wait(Native Method)
- waiting on <0x058f0690> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x058f0690> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x00a84da8 nid=0x468 runnable
"VM Periodic Task Thread" prio=10 tid=0x2c93abd8 nid=0x7a0 waiting on
condition
Now for the 10% of the time that works, I get the following output on
the client-side as the application exits:
[FINE]: 2006-03-21 21:56:56.169 GMT #31 Thread[13]
org.exolab.jms.net.connector.DefaultConnectionPool:reapIdleConnections()
Reaping idle connection, URI=rmi://127.0.0.1:1099/, local
URI=rmi:9d5cccd0-bf4a-1004-8c27-d9e01280e2d2
[INFO]: 2006-03-21 21:57:43.936 GMT #34 Thread[main,5,main] null
resoft.framework.database.DatabaseCtx:logout()
Shutting down of DatabaseCtx...
[INFO]: 2006-03-21 21:57:43.967 GMT #35 Thread[main,5,main] null
resoft.framework.database.synchronization.listener.ChangeMessageListener:stopListening()
Found the object:
//10.3.81.25:1099//org.exolab.jms.net.rmi.RMIInvokerFactory
[FINE]: 2006-03-21 21:57:48.952 GMT #37 Thread[13]
org.exolab.jms.net.connector.DefaultConnectionPool:reapIdleConnections()
Reaping idle connection, URI=rmi://10.3.81.25:1099/, local
URI=rmi:9d5d1af0-bf4a-1004-8c27-d9e01280e2d2
And the application exits gracefully.
Any ideas as to what might be causing the client NOT to exit
gracefully?
Thanx in advance,
Ninju
__________________________________________________
Do You Yahoo!?
Tired of spam? Yahoo! Mail has the best spam protection around
http://mail.yahoo.com
-------------------------------------------------------
This SF.Net email is sponsored by xPML, a groundbreaking scripting language
that extends applications into web and mobile media. Attend the live webcast
and join the prime developer group breaking into this new coding territory!
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642