6 Replies Latest reply on Dec 14, 2006 7:42 AM by hskiran

    ping timeout after successful reconnect to server

    catherine lo Newbie

      JBoss version : 4.0.1SP1

      I have a JMS Client that register to exceptionListener. But I got ping timeout exception even though successfully reconnect to server.

      Here is part of my code:

      private class ExceptionListenerImpl implements ExceptionListener {
       public void onException(JMSException ex) {
       currentThread = Thread.currentThread();
       logger.info("JMS provider failure detected: " + ex.getMessage());
      
       boolean restartInvoker = true;
       while (restartInvoker && running) {
       logger.debug("Trying to reconnect to JMS provider");
      
       try {
       try {
       Thread.sleep(reconnectInterval);
       } catch (InterruptedException ie) {
       return;
       }
      
       // Reboot container
       stopConnection();
       createConnection();
      
       restartInvoker = false;
       logger.debug("Successfully reconnect to JMS");
       } catch (Exception e) {
       logger.error("Reconnect failed: JMS provider failure detected " + e.getMessage());
       }
       }
       currentThread = null;
      }
      }
      


      Here is the error:
      org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping time
      out.)
      at org.jboss.mq.Connection.asynchFailure(Connection.java:436)
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1385)
      at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
      at java.lang.Thread.run(Unknown Source)
      Caused by: java.io.IOException: ping timeout.
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1377)
      ... 2 more


      Refered to this page : http://wiki.jboss.org/wiki/Wiki.jsp?page=IGetIOExceptionPingTimeoutHowDoIFixIt and added log4j.category.org.jboss.mq=TRACE#org.jboss.logging.XLevel to get the trace.

      Seems like the old connection (ConnectionToken:ID:8/e6705f73a40518b6c1840f7c417e267e) is still running although I have successfully reconnected to the server with a new connection (ConnectionToken:4/2fe5a18970c262e7de045654896421c7). Am I right?

      Here is the trace:

      TRACE: 2005-08-17 18:35:55,975 [Connection] PING 1124274955975 Connection@30931963[token=ConnectionT
      oken:4/2fe5a18970c262e7de045654896421c7 rcvstate=STARTED]
      ...
      TRACE: 2005-08-17 18:35:55,985 [Connection] PONG serverTime=1124274955975 Connection@30931963[token=
      ConnectionToken:4/2fe5a18970c262e7de045654896421c7 rcvstate=STARTED]

      TRACE: 2005-08-17 18:35:09,629 [Connection] Notified of failure reason=Connection Failed Connection@
      29232906[token=ConnectionToken:ID:8/e6705f73a40518b6c1840f7c417e267e rcvstate=STOPPED]
      java.io.IOException: ping timeout.
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1377)
      at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
      at java.lang.Thread.run(Unknown Source)
      WARN : 2005-08-17 18:35:09,629 [Connection] Connection failure:
      org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping time
      out.)
      at org.jboss.mq.Connection.asynchFailure(Connection.java:436)
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1385)
      at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
      at java.lang.Thread.run(Unknown Source)
      Caused by: java.io.IOException: ping timeout.
      at org.jboss.mq.Connection$PingTask.run(Connection.java:1377)
      ... 2 more


      I really have no idea on how to fix this problem. Please help. Thanks.

        • 1. Re: ping timeout after successful reconnect to server
          Adrian Brock Master

          Unfortunately, you have been singled out as an example:
          http://www.jboss.org/index.html?module=bb&op=viewtopic&t=68044
          http://wiki.jboss.org/wiki/Wiki.jsp?page=JBossHelp

          http://wiki.jboss.org/wiki/Wiki.jsp?page=BadPostShort
          So you don't post the most important information, i.e. what does this do:

          stopConnection();


          You also don't show the history of the problematic connection.
          i.e. where is the previous logging for this connection:
          ConnectionToken:ID:8/e6705f73a40518b6c1840f7c417e267e


          I can tell just by looking at the client id (number 8),
          that it was actually created AFTER the one that is working (number 4)
          TRACE: 2005-08-17 18:35:55,985 [Connection] PONG serverTime=1124274955975 Connection@30931963[token=
          ConnectionToken:4/2fe5a18970c262e7de045654896421c7 rcvstate=STARTED]


          • 2. Re: ping timeout after successful reconnect to server
            catherine lo Newbie

            Hi,
            Thanks for the reply.

            Here is the code for createConnection
            [Code]
            protected void createConnection() throws NamingException, JMSException {
            logger.debug("establish the connection...");
            InitialContext iniCtx = new InitialContext(properties);
            Object tmp = iniCtx.lookup("ConnectionFactory");
            qcf = (QueueConnectionFactory) tmp;
            stateQueue = (Queue) iniCtx.lookup("queue/StateQueue");
            usageQueue = (Queue) iniCtx.lookup("queue/UsageQueue");
            errorQueue = (Queue) iniCtx.lookup("queue/ErrorQueue");
            queueConnection = qcf.createQueueConnection();
            queueConnection.setExceptionListener(exListener);
            queueConnection.start();
            }
            [/Code]


            Here is the code for stopConnection

            [Code]
            protected void stopConnection() {
            try {
            if (queueConnection != null) {
            queueConnection.setExceptionListener(null);
            queueConnection.stop();
            queueConnection.close();
            }
            } catch (Exception ex) {
            logger.error("Error when try to stop Connection = " + ex.getMessage());
            }

            if (queueConnection != null)
            queueConnection = null;
            }
            [/Code]


            I have recaptured the TRACE, so the connection token ID is different from the previous one that I posted previously.


            Here is part of the trace when I started the client, the connection token Id (15):

            TRACE: 2005-08-18 09:44:23,343 [Connection] PING 1124329463343 Connection@31822120[token=ConnectionT
            oken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STARTED]
            TRACE: 2005-08-18 09:44:23,343 [SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.i
            l.uil2.msgs.PingMsg33431531[msgType: m_ping, msgID: 8, error: null]
            TRACE: 2005-08-18 09:44:23,343 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg33431531[msgType: m_ping, msgID: 8, error: null]
            TRACE: 2005-08-18 09:44:23,343 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.PingMsg33431531[msgType: m_ping, msgID: 8, error: null]
            TRACE: 2005-08-18 09:44:23,353 [SocketManager$ReadTask] Read msgType: m_pong, msgID: -2147480190
            TRACE: 2005-08-18 09:44:23,353 [SocketManager$ReadTask] Read new msg: org.jboss.mq.il.uil2.msgs.Ping
            Msg14780827[msgType: m_pong, msgID: -2147480190, error: null]
            TRACE: 2005-08-18 09:44:23,353 [UILClientILService] Begin handleMsg, msgType: 24
            TRACE: 2005-08-18 09:44:23,353 [Connection] PONG serverTime=1124329463353 Connection@31822120[token=
            ConnectionToken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STARTED]


            Here is the trace when I stoped the server, and client was able to detect the connection failure:

            INFO : 2005-08-18 09:45:13,465 [JMSManager$ExceptionListenerImpl] JMS provider failure detected: Exiting on IOE; - nested throwable: (java.net.SocketException: Connection reset)
            DEBUG: 2005-08-18 09:45:13,465 [JMSManager$ExceptionListenerImpl] Trying to reconnect to JMS provider
            TRACE: 2005-08-18 09:45:23,349 [Connection] PING 1124329523349 Connection@31822120[token=ConnectionToken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STARTED]
            TRACE: 2005-08-18 09:45:23,359 [Connection] Notified of failure reason=Connection Failed Connection@31822120[token=ConnectionToken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STARTED]
            java.io.IOException: Client is not connected
            at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:233)
            at org.jboss.mq.il.uil2.SocketManager.sendReply(SocketManager.java:219)
            at org.jboss.mq.il.uil2.UILServerIL.ping(UILServerIL.java:462)
            at org.jboss.mq.Connection.pingServer(Connection.java:927)
            at org.jboss.mq.Connection$PingTask.run(Connection.java:1381)
            at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
            at java.lang.Thread.run(Unknown Source)
            TRACE: 2005-08-18 09:45:23,470 [Connection] Stopping connection Connection@31822120[token=ConnectionToken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STOPPED]
            ERROR: 2005-08-18 09:45:23,480 [JMSManager] Error when try to stop Connection = Cannot disable the connection with the JMS server; - nested throwable: (java.io.IOException: Client is not connected)
            DEBUG: 2005-08-18 09:45:23,500 [JMSManager] establish the connection...
            DEBUG: 2005-08-18 09:45:24,481 [NamingContext] Failed to connect to 192.168.7.51:1099
            javax.naming.CommunicationException: Failed to connect to server 192.168.7.51:1099 [Root exception is javax.naming.ServiceUnavailableException: Failed to connect to server 192.168.7.51:1099 [Root exception is java.net.ConnectException: Connection refused: connect]]
            at org.jnp.interfaces.NamingContext.getServer(NamingContext.java:215)
            at org.jnp.interfaces.NamingContext.checkRef(NamingContext.java:1227)
            at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:527)
            at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:520)
            at javax.naming.InitialContext.lookup(Unknown Source)
            at com.streetspace.webstation.client.JMSManager.createConnection(JMSManager.java:85)
            at com.streetspace.webstation.client.JMSManager$ExceptionListenerImpl.connectThread(JMSManag
            er.java:216)
            at com.streetspace.webstation.client.JMSManager$ExceptionListenerImpl.onException(JMSManager
            .java:191)
            at org.jboss.mq.Connection.asynchFailure(Connection.java:446)
            at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(UILClientILService.java:145)
            at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(SocketManager.java:406)
            at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:338)
            at java.lang.Thread.run(Unknown Source)
            Caused by: javax.naming.ServiceUnavailableException: Failed to connect to server 192.168.7.51:1099 [
            Root exception is java.net.ConnectException: Connection refused: connect]
            at org.jnp.interfaces.NamingContext.getServer(NamingContext.java:189)
            ... 12 more
            Caused by: java.net.ConnectException: Connection refused: connect
            at java.net.PlainSocketImpl.socketConnect(Native Method)
            at java.net.PlainSocketImpl.doConnect(Unknown Source)
            at java.net.PlainSocketImpl.connectToAddress(Unknown Source)
            at java.net.PlainSocketImpl.connect(Unknown Source)
            at java.net.Socket.connect(Unknown Source)
            at java.net.Socket.connect(Unknown Source)
            at java.net.Socket.(Unknown Source)
            at java.net.Socket.(Unknown Source)
            at org.jnp.interfaces.TimedSocketFactory.createSocket(TimedSocketFactory.java:69)
            at org.jnp.interfaces.TimedSocketFactory.createSocket(TimedSocketFactory.java:62)
            at org.jnp.interfaces.NamingContext.getServer(NamingContext.java:185)
            ... 12 more
            ERROR: 2005-08-18 09:45:29,769 [JMSManager$ExceptionListenerImpl] Reconnect failed: JMS provider failure detected Receive timed out


            Here is the trace when I started back the server and client tried to reconnect back to the JMS provider. A new connection with connection token Id (2) started:

            DEBUG: 2005-08-18 09:47:36,871 [JMSManager$ExceptionListenerImpl] Trying to reconnect to JMS provider
            DEBUG: 2005-08-18 09:47:46,876 [JMSManager] establish the connection...
            DEBUG: 2005-08-18 09:47:46,906 [SpyConnectionFactoryObjectFactory] Extracting SpyConnectionFactory from reference
            DEBUG: 2005-08-18 09:47:46,926 [SpyConnectionFactoryObjectFactory] The GenericConnectionFactory is:
            GenericConnectionFactory[server=org.jboss.mq.il.uil2.UILServerIL@32784a connectionProperties={UIL_ADDRESS_KEY=192.168.7.51, UIL_CHUNKSIZE_KEY=1000000, UIL_TCPNODELAY_KEY=yes, ClientILService=org.jboss
            .mq.il.uil2.UILClientILService, UIL_PORT_KEY=8093, UIL_BUFFERSIZE_KEY=2048, PingPeriod=60000}]
            DEBUG: 2005-08-18 09:47:46,936 [SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
            DEBUG: 2005-08-18 09:47:46,956 [SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
            DEBUG: 2005-08-18 09:47:46,966 [SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
            TRACE: 2005-08-18 09:47:46,976 [Connection] Connection Initializing userName=null Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:46,976 [Connection] Getting the serverIL Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:46,976 [Connection] serverIL=org.jboss.mq.il.uil2.UILServerIL@14e8cee Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:46,976 [Connection] Authenticating user null Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:46,976 [UILServerIL] Connecting to : klws20-51/192.168.7.51:8093
            TRACE: 2005-08-18 09:47:46,986 [UILServerIL] Connecting with addr=192.168.7.51, port=8093, localAddr=null, localPort=0, socketFactory=javax.net.DefaultSocketFactory@140c281, enableTcpNoDelay=true, bufferSize=2048, chunkSize=1000000
            TRACE: 2005-08-18 09:47:46,986 [UILServerIL] Begin connect loop, maxRetries=10, delay=0
            TRACE: 2005-08-18 09:47:46,996 [SocketManager] start called
            java.lang.Exception: Start stack trace
            at org.jboss.mq.il.uil2.SocketManager.start(SocketManager.java:96)
            at org.jboss.mq.il.uil2.UILServerIL.createConnection(UILServerIL.java:666)
            at org.jboss.mq.il.uil2.UILServerIL.getSocketMgr(UILServerIL.java:532)
            at org.jboss.mq.il.uil2.UILServerIL.authenticate(UILServerIL.java:334)
            at org.jboss.mq.Connection.authenticate(Connection.java:1160)
            at org.jboss.mq.Connection.(Connection.java:255)
            at org.jboss.mq.Connection.(Connection.java:332)
            at org.jboss.mq.SpyConnection.(SpyConnection.java:66)
            at org.jboss.mq.SpyConnectionFactory.createConnection(SpyConnectionFactory.java:87)
            at org.jboss.mq.SpyConnectionFactory.createQueueConnection(SpyConnectionFactory.java:124)
            at com.streetspace.webstation.client.JMSManager.createConnection(JMSManager.java:90)
            at com.streetspace.webstation.client.JMSManager$ExceptionListenerImpl.connectThread(JMSManager.java:216)
            at com.streetspace.webstation.client.JMSManager$ExceptionListenerImpl.onException(JMSManager.java:191)
            at org.jboss.mq.Connection.asynchFailure(Connection.java:446)
            at org.jboss.mq.il.uil2.UILClientILService.asynchFailure(UILClientILService.java:145)
            at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleStop(SocketManager.java:406)
            at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:338)
            at java.lang.Thread.run(Unknown Source)
            TRACE: 2005-08-18 09:47:47,006 [SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.m
            q.il.uil2.msgs.CheckUserMsg12376621[msgType: m_authenticate, msgID: 10, error: null]
            DEBUG: 2005-08-18 09:47:47,016 [SocketManager$WriteTask] Begin WriteTask.run
            DEBUG: 2005-08-18 09:47:47,016 [SocketManager$ReadTask] Begin ReadTask.run
            DEBUG: 2005-08-18 09:47:47,016 [SocketManager$WriteTask] Created ObjectOutputStream
            TRACE: 2005-08-18 09:47:47,026 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.CheckU
            serMsg12376621[msgType: m_authenticate, msgID: 10, error: null]
            DEBUG: 2005-08-18 09:47:47,026 [SocketManager$ReadTask] Created ObjectInputStream
            TRACE: 2005-08-18 09:47:47,026 [SocketManager$ReadTask] Read msgType: m_authenticate, msgID: 10
            TRACE: 2005-08-18 09:47:47,036 [SocketManager$ReadTask] Found replyMap msg: org.jboss.mq.il.uil2.msg
            s.CheckUserMsg12376621[msgType: m_authenticate, msgID: 10, error: null]
            TRACE: 2005-08-18 09:47:47,036 [SocketManager$ReadTask] Read msg reply: org.jboss.mq.il.uil2.msgs.Ch
            eckUserMsg12376621[msgType: m_authenticate, msgID: 10, error: null]
            TRACE: 2005-08-18 09:47:47,036 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.CheckUserMsg12376621[msgType: m_authenticate, msgID: 10, error: null]
            TRACE: 2005-08-18 09:47:47,036 [Connection] Starting the client il Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,046 [GenericConnectionFactory] Handing out ClientIL: org.jboss.mq.il.uil2.UILClientILService
            DEBUG: 2005-08-18 09:47:47,046 [UILClientILService] Starting
            TRACE: 2005-08-18 09:47:47,056 [Connection] Using client id org.jboss.mq.il.uil2.UILClientILService@97d01f Connection@1049443[clientID=null rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,056 [SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.m
            q.il.uil2.msgs.ConnectionTokenMsg14721926[msgType: m_setSpyDistributedConnection, msgID: 11, error:
            null]
            TRACE: 2005-08-18 09:47:47,056 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg14721926[msgType: m_setSpyDistributedConnection, msgID: 11, error: null]
            TRACE: 2005-08-18 09:47:47,076 [SocketManager$ReadTask] Read msgType: m_setSpyDistributedConnection, msgID: 11
            TRACE: 2005-08-18 09:47:47,076 [SocketManager$ReadTask] Found replyMap msg: org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg14721926[msgType: m_setSpyDistributedConnection, msgID: 11, error: null]
            TRACE: 2005-08-18 09:47:47,076 [SocketManager$ReadTask] Read msg reply: org.jboss.mq.il.uil2.msgs.ConnectionTokenMsg14721926[msgType: m_setSpyDistributedConnection, msgID: 11, error: null]
            TRACE: 2005-08-18 09:47:47,076 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.ConnectionTokenMsg14721926[msgType: m_setSpyDistributedConnection, msgID: 11, error: null]
            TRACE: 2005-08-18 09:47:47,076 [Connection] Creating XAResourceManager Connection@1049443[token=Conn
            ectionToken:null/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,086 [Connection] Starting the ping thread Connection@1049443[token=ConnectionToken:null/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,086 [Connection] Connection establishment successful Connection@1049443[token=ConnectionToken:null/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,086 [Connection] Checking clientID=null Connection@1049443[token=ConnectionToken:null/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,096 [Connection] Ask for an id Connection@1049443[token=ConnectionToken:null/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,096 [SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.m
            q.il.uil2.msgs.GetIDMsg23668144[msgType: m_getID, msgID: 12, error: null]
            TRACE: 2005-08-18 09:47:47,096 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.GetIDMsg23668144[msgType: m_getID, msgID: 12, error: null]
            TRACE: 2005-08-18 09:47:47,106 [SocketManager$ReadTask] Read msgType: m_getID, msgID: 12
            TRACE: 2005-08-18 09:47:47,106 [SocketManager$ReadTask] Found replyMap msg: org.jboss.mq.il.uil2.msg
            s.GetIDMsg23668144[msgType: m_getID, msgID: 12, error: null]
            TRACE: 2005-08-18 09:47:47,106 [SocketManager$ReadTask] Read msg reply: org.jboss.mq.il.uil2.msgs.GetIDMsg23668144[msgType: m_getID, msgID: 12, error: null]
            TRACE: 2005-08-18 09:47:47,106 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.GetIDMsg23668144[msgType: m_getID, msgID: 12, error: null]
            TRACE: 2005-08-18 09:47:47,116 [Connection] ClientID established Connection@1049443[token=ConnectionToken:ID:2/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STOPPED]
            TRACE: 2005-08-18 09:47:47,116 [Connection] Starting connection Connection@1049443[token=ConnectionToken:ID:2/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STARTED]
            TRACE: 2005-08-18 09:47:47,116 [SocketManager] Begin internalSendMessage, round-trip msg=org.jboss.m
            q.il.uil2.msgs.EnableConnectionMsg2719739[msgType: m_setEnabled, msgID: 13, error: null]
            TRACE: 2005-08-18 09:47:47,126 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.Enable
            ConnectionMsg2719739[msgType: m_setEnabled, msgID: 13, error: null]
            TRACE: 2005-08-18 09:47:47,126 [SocketManager$ReadTask] Read msgType: m_setEnabled, msgID: 13
            TRACE: 2005-08-18 09:47:47,126 [SocketManager$ReadTask] Found replyMap msg: org.jboss.mq.il.uil2.msg
            s.EnableConnectionMsg2719739[msgType: m_setEnabled, msgID: 13, error: null]
            TRACE: 2005-08-18 09:47:47,126 [SocketManager$ReadTask] Read msg reply: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg2719739[msgType: m_setEnabled, msgID: 13, error: null]
            TRACE: 2005-08-18 09:47:47,126 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.EnableConnectionMsg2719739[msgType: m_setEnabled, msgID: 13, error: null]
            DEBUG: 2005-08-18 09:47:47,136 [JMSManager$ExceptionListenerImpl] Successfully reconnect to JMS


            Here is the trace I got instantly after successfully reconnect to JMS:

            TRACE: 2005-08-18 09:47:47,136 [Connection] Notified of failure reason=Connection Failed Connection@31822120[token=ConnectionToken:ID:15/704e049760ee15c515267c87a72b044b rcvstate=STOPPED]
            java.io.IOException: ping timeout.
            at org.jboss.mq.Connection$PingTask.run(Connection.java:1377)
            at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
            at java.lang.Thread.run(Unknown Source)
            WARN : 2005-08-18 09:47:47,136 [Connection] Connection failure:
            org.jboss.mq.SpyJMSException: Connection Failed; - nested throwable: (java.io.IOException: ping time
            out.)
            at org.jboss.mq.Connection.asynchFailure(Connection.java:436)
            at org.jboss.mq.Connection$PingTask.run(Connection.java:1385)
            at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
            at java.lang.Thread.run(Unknown Source)
            Caused by: java.io.IOException: ping timeout.
            at org.jboss.mq.Connection$PingTask.run(Connection.java:1377)
            ... 2 more
            TRACE: 2005-08-18 09:47:47,146 [SocketManager$WriteTask] WriteTask was interrupted
            java.lang.InterruptedException
            at java.lang.Object.wait(Native Method)
            at java.lang.Object.wait(Unknown Source)
            at EDU.oswego.cs.dl.util.concurrent.LinkedQueue.take(LinkedQueue.java:122)
            at org.jboss.mq.il.uil2.SocketManager$WriteTask.run(SocketManager.java:485)
            at java.lang.Thread.run(Unknown Source)
            DEBUG: 2005-08-18 09:47:47,146 [SocketManager$ReadTask] End ReadTask.run
            DEBUG: 2005-08-18 09:47:47,146 [SocketManager$WriteTask] End WriteTask.run
            TRACE: 2005-08-18 09:47:47,146 [Connection] PING 1124329667146 Connection@1049443[token=ConnectionToken:ID:2/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STARTED]
            TRACE: 2005-08-18 09:47:47,156 [SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.i
            l.uil2.msgs.PingMsg9523050[msgType: m_ping, msgID: 14, error: null]
            TRACE: 2005-08-18 09:47:47,156 [SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msg
            s.PingMsg9523050[msgType: m_ping, msgID: 14, error: null]
            TRACE: 2005-08-18 09:47:47,156 [SocketManager$WriteTask] Write msg: org.jboss.mq.il.uil2.msgs.PingMs
            g9523050[msgType: m_ping, msgID: 14, error: null]
            TRACE: 2005-08-18 09:47:47,156 [SocketManager$ReadTask] Read msgType: m_pong, msgID: -2147483642
            TRACE: 2005-08-18 09:47:47,156 [SocketManager$ReadTask] Read new msg: org.jboss.mq.il.uil2.msgs.Ping
            Msg32820206[msgType: m_pong, msgID: -2147483642, error: null]
            TRACE: 2005-08-18 09:47:47,166 [UILClientILService] Begin handleMsg, msgType: 24
            TRACE: 2005-08-18 09:47:47,166 [Connection] PONG serverTime=1124329667156 Connection@1049443[token=ConnectionToken:ID:2/ab48c86f41f1f3ab8b7be5243a1eeb29 rcvstate=STARTED]

            Any idea why the client receive notification on connection failure for Connection Token Id 15?
            How to resolve this problem?
            Please let me know if the information that I provided is insufficient.
            Please help. Thanks

            • 3. Re: ping timeout after successful reconnect to server
              Adrian Brock Master

              Incredible.

              You don't even have to enable TRACE logging to see the problem,
              because you have your own error message (lacking a stacktrace).


              ERROR: 2005-08-18 09:45:23,480 [JMSManager] Error when try to stop Connection = Cannot disable the connection with the JMS server; - nested throwable: (java.io.IOException: Client is not connected)


              I've augmented the FAQ with this question, usually it is session.close().
              http://wiki.jboss.org/wiki/Wiki.jsp?page=IGetIOExceptionPingTimeoutHowDoIFixIt

              Although this is really a "How do I code Java" FAQ.
              Your code gets chosen as "WHAT NOT TO DO".

              • 4. Re: ping timeout after successful reconnect to server
                catherine lo Newbie

                Hi,
                Thanks for the reply.

                It works. Thank you very much.

                • 5. Re: ping timeout after successful reconnect to server
                  vbijjargi Newbie

                  Hi,

                  I am still getting the same error. Could you please help me out.


                  my connect method is as below:

                  public void connectToQueue() throws NamingException, JMSException {
                  log.info("connecting to JMS Queue");

                  try {

                  // Get appserver IP and port from application session
                  appServerIP = (String) applicationSession.getProperty(SC.JBOSS_SERVER_IP);
                  jmsPort = (String) applicationSession.getProperty(SC.JMS_PORT);

                  // get connection properties and context
                  properties = new Properties();
                  properties.put(Context.INITIAL_CONTEXT_FACTORY, SC.INITIAL_CONTEXT_FACTORY);
                  properties.put(Context.URL_PKG_PREFIXES, SC.URL_PKG_PREFIXES);
                  properties.put(Context.PROVIDER_URL, SC.PROVIDER_URL_PROTOCOL + appServerIP + ":"+ jmsPort);
                  iniCtx = new InitialContext(properties);

                  // get connected to the JMS queue
                  queueConnection = ((QueueConnectionFactory) iniCtx.lookup("ConnectionFactory")).createQueueConnection();
                  queueConnection.start();
                  connectedToQueue = true;

                  log.debug("connected with JMS queue");
                  } catch (NamingException ne) {
                  log.error("exception in connectToQueue method -" + ne);
                  connectedToQueue = false;
                  throw ne;
                  } catch (JMSException jmse) {
                  log.error("exception in connectToQueue method -" + jmse);
                  connectedToQueue = false;
                  throw jmse;
                  }
                  }

                  Now it reads the messages from queue. I have more than 10 messages per second and suddenly I get the pong timeout message. It appears periodically.

                  Please help

                  • 6. Re: ping timeout after successful reconnect to server
                    hskiran Newbie

                    Hi Cathernilo,

                    Even I am facing the same problem, the pong timeout exception which u received.

                    If you have the full implementation of the ExceptionListenerImpl class, can you pls paste it here.

                    Thanks.
                    hskiran