Getting ping timeout trying to connect to a Queue

[mcgourty]

The application is using a NON-Persistent Queue. After the application runs for 2-3 days we're getting
the following exception: org.jboss.mq.SpyJMSException: Exiting on IOE; - nested throwable: (java.io.EOFException)

The application has an exception listener registered and is notified of this exception.

It closes the queue and attempts to reconnect but after successfully recreating and starting the queue JBoss is reporting
the follwing exception: java.io.IOException: ping timeout. The application can never successfully reconnect to the queue.

All of the software is running in the same JVM. Running on Windows 2003

Not sure if we're correctly handling the error in our app and whether this is a defect JBossMQ.

Here are snippets from our logs:

JBoss Log

23:49:00,421 INFO [Server] Release ID: JBoss [WonderLand] 3.2.5 (build: CVSTag=JBoss_3_2_5 date=200406251954)
.
.
.
01:29:42,983 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Exiting on IOE; - nested throwable: (java.io.EOFException)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(Ljava.lang.String;Ljava.lang.Throwable;)V(UILClientILService.java:145)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(Ljava.lang.String;Ljava.lang.Throwable;)V(SocketManager.java:398)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.run()V(SocketManager.java:332)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.EOFException
at java.io.ObjectInputStream$BlockDataInputStream.readByte()B(Optimized Method)
at java.io.ObjectInputStream.readByte()B(Optimized Method)
at org.jboss.mq.il.uil2.SocketManager$ReadTask.run()V(SocketManager.java:279)
... 2 more
01:29:42,983 ERROR [TlMessageChannel] TLQueueExceptionListener onException() org.jboss.mq.SpyJMSException: Exiting on IOE; - nested throwable: (java.io.EOFException)
01:29:43,014 ERROR [TlMessageChannel] stopQConnection() exception: org.jboss.mq.SpyJMSException: Cannot disable the connection with the JMS server; - nested throwable: (java.io.IOException: Client is not connected)
01:31:05,327 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: Client is not connected)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1378)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run()V(ClockDaemon.java:364)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.IOException: Client is not connected
at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(Lorg.jboss.mq.il.uil2.msgs.BaseMsg;Z)V(Optimized Method)
at org.jboss.mq.il.uil2.SocketManager.sendReply(Lorg.jboss.mq.il.uil2.msgs.BaseMsg;)V(Optimized Method)
at org.jboss.mq.il.uil2.UILServerIL.ping(Lorg.jboss.mq.ConnectionToken;J)V(Optimized Method)
at org.jboss.mq.Connection.pingServer(J)V(Optimized Method)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1374)
... 3 more
01:32:05,342 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping timeout.)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1378)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run()V(ClockDaemon.java:364)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.IOException: ping timeout.
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1370)
... 3 more
01:33:05,342 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping timeout.)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1378)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run()V(ClockDaemon.java:364)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.IOException: ping timeout.
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1370)
... 3 more
01:34:05,342 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping timeout.)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1378)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run()V(ClockDaemon.java:364)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.IOException: ping timeout.
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1370)
... 3 more
01:35:05,342 WARN [Connection] Connection failure:
org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping timeout.)
at org.jboss.mq.Connection.asynchFailure(Ljava.lang.String;Ljava.lang.Exception;)V(Connection.java:429)
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1378)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run()V(ClockDaemon.java:364)
at java.lang.Thread.run()V(Unknown Source)
at java.lang.Thread.startThreadFromVM(Ljava.lang.Thread;)V(Unknown Source)
Caused by: java.io.IOException: ping timeout.
at org.jboss.mq.Connection$PingTask.run()V(Connection.java:1370)
... 3 more



Application Log

2004-12-21 01:29:42,983 -0600 ERROR [TlMessageChannel] - TLQueueExceptionListener onException() org.jboss.mq.SpyJMSException: Exiting on IOE; - nested throwable: (java.io.EOFException)
2004-12-21 01:29:43,014 -0600 ERROR [TlMessageChannel] - stopQConnection() exception: org.jboss.mq.SpyJMSException: Cannot disable the connection with the JMS server; - nested throwable: (java.io.IOException: Client is not connected)
2004-12-21 01:29:43,014 -0600 INFO [TlMessageChannel] - TLQueueExceptionListener onException() starting TLQueue.....
2004-12-21 01:29:43,014 -0600 INFO [TlMessageChannel] - TLQueueExceptionListener onException() started TLQueue



Here is the relevant portion of code:

private void createTLQComponents() throws JMSException {
logger.debug("createTLQComponents() creating .....");
createQConnection();
createQSession();
createQSender();
logger.debug("createTLQComponents() created");
}

private void createQConnection() throws JMSException {
qConnection = qcf.createQueueConnection(TransactionLinkMessageServer.USER_NAME,
TransactionLinkMessageServer.PASSWORD);
qConnection.setExceptionListener(queueExceptionListener);
}

private void createQSession() throws JMSException {
qSession = qConnection.createQueueSession(false,Session.AUTO_ACKNOWLEDGE);
}

private void createQSender() throws JMSException {
qSender = qSession.createSender(tlQueue);
qSender.setTimeToLive(TransactionLinkMessageServer.NEVER_EXPIRE);
qSender.setDeliveryMode(DeliveryMode.NON_PERSISTENT);
}

private void stopConnections() {
logger.debug("stopping JMS connections .....");
stopTopicConnection();
stopQConnection();
logger.debug("stopped JMS connections");
}

private void stopQConnection() {
logger.debug("stopping Queue connections .....");
try {
qSender.close();
qSession.close();
qConnection.close();
} catch (JMSException e) {
logger.error("stopQConnection() exception: " + e);
}
logger.debug("stopped Queue connections");
}


public class TLQueueExceptionListener implements ExceptionListener {
public synchronized void onException(JMSException e) {
logger.error("TLQueueExceptionListener onException() " + e);
try {
stopQConnection();
createTLQComponents();
logger.info("TLQueueExceptionListener onException() starting TLQueue.....");
qConnection.start();
logger.info("TLQueueExceptionListener onException() started TLQueue");
} catch (JMSException e1) {
logger.error("TLQueueExceptionListener onException() " + e1);
}
}
}

[ehansen]

I did not see a reply relevant to this post, so I would like to raise it again... what can cause this to ping timeout to happen?

I have the same symptoms... the appliation will run for several days without problem, the whammo, these exceptions appear and the app is dead. It happened last night in the middle of the night, when noone was on using the system.

Thanks for any insight into this issue.
Eric-


using jboss v3.2.4

[mcgourty]

After reviewing the recovery logic in our app I believe that we are encountering a deadlock in the 'onException' method of our Queue Exception Listener.

Because we never set the exception listener to null when before closing the queue connection in our exception listener it triggers another JMSException (the queue is already closed - it got a EOF Exception).

The onException method is invoked again, since the method is synchronized it blocks the caller which is JBoss and I believe that this prevents the PingTask from being stopped and so we continue to get Ping Timeouts.