6 Replies Latest reply on Oct 2, 2009 5:18 PM by Bernd Eckenfels

    Weird behavior with ping timeouts

    Martin Newbie

      Hello all,

      I was wondering if anyone has seen the following behavior before, and if anyone knows a solution for it. We appear to have messages that aren't being delivered. The following is a snip of our logs:

      2006-09-15 11:27:59,543 WARN [org.jboss.mq.Connection] Connection failure, use javax.jms.Connection.setExceptionListener() to handle this error and reconnect
      org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
       at org.jboss.mq.Connection$PingTask.run(Connection.java:1277)
       at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
       at java.lang.Thread.run(Thread.java:595)
      Caused by: java.io.IOException: ping timeout.
       ... 3 more
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_ping, msgID: 64
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg1890854[msgType: m_ping, msgID: 64, error: null]
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1158334085647
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.PingMsg9602832[msgType: m_pong, msgID: -2147466927, error: null]
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg9602832[msgType: m_pong, msgID: -2147466927, error: null]
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.PingMsg9602832[msgType: m_pong, msgID: -2147466927, error: null]
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2006-09-15 11:28:06,308 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      2006-09-15 11:28:11,121 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2006-09-15 11:28:11,121 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2006-09-15 11:28:11,121 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1158334092214
      2006-09-15 11:28:11,121 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2006-09-15 11:28:11,121 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      ... traced ping message repeats ...
      2006-09-15 11:28:46,120 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2006-09-15 11:28:46,120 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2006-09-15 11:28:46,120 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1158334126064
      2006-09-15 11:28:46,120 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2006-09-15 11:28:46,120 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      2006-09-15 11:28:59,557 WARN [org.jboss.mq.Connection] Connection failure, use javax.jms.Connection.setExceptionListener() to handle this error and reconnect
      org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
       at org.jboss.mq.Connection$PingTask.run(Connection.java:1277)
       at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
       at java.lang.Thread.run(Thread.java:595)
      Caused by: java.io.IOException: ping timeout.
       ... 3 more
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.SocketManager] Read msgType: m_ping, msgID: 65
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.SocketManager] Read new msg: org.jboss.mq.il.uil2.msgs.PingMsg18189100[msgType: m_ping, msgID: 65, error: null]
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1158334145653
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.SocketManager] Begin internalSendMessage, one-way msg=org.jboss.mq.il.uil2.msgs.PingMsg8764440[msgType: m_pong, msgID: -2147466921, error: null]
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.SocketManager] Write msg: org.jboss.mq.il.uil2.msgs.PingMsg8764440[msgType: m_pong, msgID: -2147466921, error: null]
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.SocketManager] End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.PingMsg8764440[msgType: m_pong, msgID: -2147466921, error: null]
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2006-09-15 11:29:06,323 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      2006-09-15 11:29:11,135 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Begin handleMsg, msgType: 21
      2006-09-15 11:29:11,135 TRACE [org.jboss.mq.server.TracingInterceptor] CALLED : ping
      2006-09-15 11:29:11,135 TRACE [org.jboss.mq.server.TracingInterceptor] ARG : 1158334152238
      2006-09-15 11:29:11,135 TRACE [org.jboss.mq.server.TracingInterceptor] RETURN : ping
      2006-09-15 11:29:11,135 TRACE [org.jboss.mq.il.uil2.ServerSocketManagerHandler] End handleMsg, msgType: 21
      .. more ping messages...
      


      We have 3 different database connections open, in addition to the JMS backend which is still the default Hypersonic one. It appears some of the logged pings are for those. I'm tracing with the following (from READTHISFIRST) but I'm not sure what other diagnostic information to aquire.
      <category name="org.jboss.mq">
       <priority value="TRACE" class="org.jboss.logging.XLevel"/>
      </category>


      My uil2-service.xml contains
      <!-- The ping period in millis -->
       <attribute name="PingPeriod">60000</attribute>
      , so I shouldn't really be having this big of a problem with ping timeouts. After all, the JMS backend is a local database on the same machine, with mostly the default JBoss installer-configured settings.

      Can anyone suggest the problem or even other ways to analyze it? Thank you.

        • 2. Re: Weird behavior with ping timeouts
          Martin Newbie

          Thank you for the reply. Unfortunately, I've already seen that page. This is what it suggested:

          I'm inside the application server, how do I install the exception listener?

          * You don't need to for an MDB, JBoss does it for you.
          * For anything else, you should be using the JMS resource adapter which also does it for you.


          This project already does these. So basically, if in the application server, "This shouldn't happen" is the answer -- which doesn't really help! I still don't understand how the Hypersonic JMS backend would get a ping timeout at all!

          • 3. Re: Weird behavior with ping timeouts
            laurent girault Newbie

            Hello,

            did you manage to fix your problem ?
            I am exactly in the same situation: "No pong received"
            If you get any chance fixing this issue please let me know.

            Thank you

            • 4. Re: Weird behavior with ping timeouts
              Martin Newbie

              Hi,

              Not yet, unfortunately. We've observed that it seems to clear up if we deploy on a Linux server. It seems to be specific with 4.0.4 (It didn't happen with 4.0.1). I inherited the issue on a Windows server, and we're now moving to redeploy on Linux.

              I did discover that the timeouts often occur if the timeout for transactions is set too low for the HSQL database, though it shouldn't be having trouble reconnecting like this.

              Good luck!

              • 5. Re: Weird behavior with ping timeouts
                Vishnu vardhan Newbie

                in my case , my jboss is not in clustered, but why should it need to do the ping and pong, is there some thing i need to do in the configuration to stop this.

                2009-10-02 03:04:53,140 WARN [org.jboss.mq.Connection] Connection failure, use javax.jms.Connection.setExceptionListener() to handle this error and reconnect
                org.jboss.mq.SpyJMSException: No pong received; - nested throwable: (java.io.IOException: ping timeout.)
                 at org.jboss.mq.Connection$PingTask.run(Connection.java:1277)
                 at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:364)
                 at java.lang.Thread.run(Thread.java:595)
                Caused by: java.io.IOException: ping timeout.
                


                • 6. Re: Weird behavior with ping timeouts
                  Bernd Eckenfels Novice

                  First of all, you abolsutely must register an error listener if you want to recover from problems.

                  Usual reasons for this pong timeout are:

                  - long garbage collection times in one of the participating JVMs
                  - delays in the database when you use jdbc persistence
                  - network problems
                  - os virtualization freezes (like vmotion)

                  Greetings
                  Bernd