2 Replies Latest reply on Oct 16, 2006 1:50 AM by hannwei

    JMS connections go down for about a minute periodically

    hannwei

      Hi,

      I am using jboss-4.0.4.GA-Patch1. There are five JMS client programs running outside JBoss. They have a total of nine JMS connections to JBoss that are up all the time. As it is a test system, the connections are idle most of the time. After running JBoss and the programs for several days, I noticed that the JMS connections break about once a day. Adding a connection exception listener helped rebuild the connections, but each connection took about 1 to 1.5 minutes to rebuild. When the system enters production later, such a long connection rebuild time might be hard to tolerate.

      Below is the portion of the JBoss server.log covering the connection breaking period. The period is indicated by "[org.jboss.mq.il.uil2.SocketManager] End WriteTask.run".

      2006-10-13 04:16:57,818 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
      2006-10-13 04:16:57,818 DEBUG [org.hibernate.SQL] select responsepe0_.identifier as identifier19_, responsepe0_.operationIdentifier as operatio2_19_, responsepe0_.firstAttemptTime as firstAtt3_19_, responsepe0_.lastAttemptTime as lastAtte4_19_, responsepe0_.nextTimeoutTime as nextTime5_19_, responsepe0_.attemptCounter as attemptC6_19_ from ResponsePendingIndicator responsepe0_ where responsepe0_.nextTimeoutTime<? order by responsepe0_.nextTimeoutTime limit ?
      2006-10-13 04:16:57,819 DEBUG [org.hibernate.loader.hql.QueryLoader] bindNamedParameters() Fri Oct 13 04:16:57 SGT 2006 -> thresholdTime [1]
      2006-10-13 04:16:57,819 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:16:57,820 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
      2006-10-13 04:16:57,820 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4754163293892608
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
      2006-10-13 04:19:57,923 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
      2006-10-13 04:19:57,924 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-10-13 04:19:57,924 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
      2006-10-13 04:19:57,924 DEBUG [org.hibernate.SQL] select responsepe0_.identifier as identifier19_, responsepe0_.operationIdentifier as operatio2_19_, responsepe0_.firstAttemptTime as firstAtt3_19_, responsepe0_.lastAttemptTime as lastAtte4_19_, responsepe0_.nextTimeoutTime as nextTime5_19_, responsepe0_.attemptCounter as attemptC6_19_ from ResponsePendingIndicator responsepe0_ where responsepe0_.nextTimeoutTime<? order by responsepe0_.nextTimeoutTime limit ?
      2006-10-13 04:19:57,924 DEBUG [org.hibernate.loader.hql.QueryLoader] bindNamedParameters() Fri Oct 13 04:19:57 SGT 2006 -> thresholdTime [1]
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
      2006-10-13 04:19:57,926 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:19:57,927 DEBUG [org.jboss.ejb3.entity.ManagedEntityManagerFactory] ************** closing entity managersession **************
      2006-10-13 04:19:57,927 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:19:58,070 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:19:58,070 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:19:58,070 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:19:58,391 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,391 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,489 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,513 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,513 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,520 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,533 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,597 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,639 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,645 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,689 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,689 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,689 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,759 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,759 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,817 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,854 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin ReadTask.run
      2006-10-13 04:19:58,854 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectInputStream
      2006-10-13 04:19:58,867 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,867 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:19:58,890 DEBUG [org.jboss.mq.il.uil2.SocketManager] Begin WriteTask.run
      2006-10-13 04:19:58,891 DEBUG [org.jboss.mq.il.uil2.SocketManager] Created ObjectOutputStream
      2006-10-13 04:20:00,464 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,464 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,464 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,465 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,465 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,465 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,465 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,466 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,466 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,466 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,467 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,468 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,468 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,469 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,469 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:00,469 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:00,931 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.parentTraceEnabled=true
      2006-10-13 04:20:00,932 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.nestedTraceEnabled=false
      2006-10-13 04:20:00,932 DEBUG [org.jboss.util.NestedThrowable] org.jboss.util.NestedThrowable.detectDuplicateNesting=true
      2006-10-13 04:20:01,064 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Setting up the UILClientIL Connection
      2006-10-13 04:20:01,064 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] The UILClientIL Connection is set up
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,756 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:01,755 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to handle: org.jboss.mq.il.uil2.msgs.ReceiveMsg12863971[msgType: m_receive, msgID: 2009, error: null]
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.sendReply(SocketManager.java:239)
       at org.jboss.mq.il.uil2.ServerSocketManagerHandler.handleMsg(ServerSocketManagerHandler.java:173)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:396)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,961 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to handle: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg26762545[msgType: m_setEnabled, msgID: 2010, error: null]
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.sendReply(SocketManager.java:239)
       at org.jboss.mq.il.uil2.ServerSocketManagerHandler.handleMsg(ServerSocketManagerHandler.java:178)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:396)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,962 DEBUG [org.jboss.mq.il.uil2.SocketManager] Failed to send error reply
      java.io.IOException: Client is not connected
       at org.jboss.mq.il.uil2.SocketManager.internalSendMessage(SocketManager.java:265)
       at org.jboss.mq.il.uil2.SocketManager.access$800(SocketManager.java:52)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(SocketManager.java:409)
       at org.jboss.mq.il.uil2.msgs.BaseMsg.run(BaseMsg.java:392)
       at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:743)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:02,002 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:02,002 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:02,012 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:02,012 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:02,031 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:02,022 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:02,032 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:02,042 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:02,043 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:02,043 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:01,499 DEBUG [org.jboss.mq.il.uil2.ServerSocketManagerHandler] Exiting on IOE
      java.io.EOFException
       at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2670)
       at java.io.ObjectInputStream.readByte(ObjectInputStream.java:864)
       at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317)
       at java.lang.Thread.run(Thread.java:595)
      2006-10-13 04:20:02,047 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:02,098 DEBUG [org.jboss.mq.il.uil2.SocketManager] End ReadTask.run
      2006-10-13 04:20:02,114 DEBUG [org.jboss.mq.il.uil2.SocketManager] End WriteTask.run
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4754163381121024
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
      2006-10-13 04:20:19,220 DEBUG [org.hibernate.SQL] select responsepe0_.identifier as identifier19_, responsepe0_.operationIdentifier as operatio2_19_, responsepe0_.firstAttemptTime as firstAtt3_19_, responsepe0_.lastAttemptTime as lastAtte4_19_, responsepe0_.nextTimeoutTime as nextTime5_19_, responsepe0_.attemptCounter as attemptC6_19_ from ResponsePendingIndicator responsepe0_ where responsepe0_.nextTimeoutTime<? order by responsepe0_.nextTimeoutTime limit ?
      2006-10-13 04:20:19,221 DEBUG [org.hibernate.loader.hql.QueryLoader] bindNamedParameters() Fri Oct 13 04:20:19 SGT 2006 -> thresholdTime [1]
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-10-13 04:20:19,222 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
      


      Below is the log of one of the JMS client programs. It shows the exception listeners of the JMS producer and consumer of the client program being executed upon detecting (java.io.IOException: ping timeout.) and (java.net.SocketTimeoutException: Read timed out).

      GenericMessageConsumer::receiveData() uses queue QUEUE.aps/ePetrolResponseOutput
      SimpleServletBasedConnectionHelper::doResponseHandling() has sent out all the data in the response list
      JMSConnectionExceptionHelper::onException() is notified of the occurrence of No pong received; - nested throwable: (java.io.IOException: ping timeout.)
      JMSConnectionExceptionHelper::onException() is notified of the occurrence of Exiting on IOE; - nested throwable: (java.net.SocketTimeoutException: Read timed out)
      JMSConnectionExceptionHelper::onException() is reinitializaing the JMS participant
      JMSConnectionExceptionHelper::onException() is reinitializaing the JMS participant
      GenericMessageConsumer::receiveData() fails due to Cannot receive ; - nested throwable: (java.net.SocketTimeoutException: Read timed out)
      GenericMessageConsumer::receiveData() fails due to The consumer is closed
      GenericMessageConsumer::receiveData() fails due to The consumer is closed
      GenericMessageConsumer::receiveData() fails due to The consumer is closed
      GenericMessageConsumer::receiveData() fails due to The consumer is closed
      GenericMessageConsumer::receiveData() fails due to The consumer is closed
      JMSConnectionExceptionHelper::onException() has reinitialized the JMS participant
      JMSConnectionExceptionHelper::onException() has reinitialized the JMS participant
      SimpleServletBasedConnectionHelper::doRequestHandling() runs ...
      SimpleServletBasedConnectionHelper::doRequestHandling() sending data to producer ...
      


      This is the source code of JMSConnectionExceptionHelper::onException() that shows what are printed immediately before and after the rebuild of the JMS connections:

       public void onException (JMSException jmsException)
       {
       System.out.println ("JMSConnectionExceptionHelper::onException() is notified of the occurrence of " + jmsException.getMessage ());
      
       try
       {
       System.out.println ("JMSConnectionExceptionHelper::onException() is reinitializaing the JMS participant");
      
       this.jmsParticipant.initialize ();
      
       System.out.println ("JMSConnectionExceptionHelper::onException() has reinitialized the JMS participant");
       } catch (Exception closureException)
       {
       closureException.printStackTrace ();
       }
       }
      


      And this is the initialize() method of the consumer of the JMS client that shows the method only closes the existing failed connection and opens a new connection:

       public synchronized void initialize ()
       throws JMSException
       {
       if (this.initialized == true)
       {
       try
       {
       this.queueConnection.close ();
       } catch (Exception closureException)
       {
       // Do nothing
       }
       }
      
       if (this.activeConsumer == true)
       {
       this.queueConnection =
       this.queueConnectionFactory.createQueueConnection ();
       this.queueConnection.setExceptionListener
       (new JMSConnectionExceptionHelper (this));
       this.queueSession =
       queueConnection.createQueueSession
       (false, QueueSession.AUTO_ACKNOWLEDGE);
       this.queueReceiver = queueSession.createReceiver (this.queue);
       this.queueConnection.start ();
       }
       else
       {
       this.queueConnection =
       this.queueConnectionFactory.createQueueConnection ();
       this.queueConnection.setExceptionListener
       (new JMSConnectionExceptionHelper (this));
       this.queueSession =
       this.queueConnection.createQueueSession
       (false, QueueSession.AUTO_ACKNOWLEDGE);
       this.queueReceiver = queueSession.createReceiver (this.queue);
       this.queueReceiver.setMessageListener (this.messageListener);
       this.queueConnection.start ();
       }
      
       this.initialized = true;
       }
      


      This code fragment of the consumer of the client program shows the consumer was not able to do queueReceiver.receive() for about 50 seonds ("GenericMessageConsumer::receiveData() fails" was printed five times in the client log above) when the initialize() method was being invoked:

       private final static long RECEIVE_TIMEOUT_PERIOD = 60000;
       private final static long RETRY_INTERVAL = 10000;
      


       do
       {
       try
       {
       message = this.queueReceiver.receive (RECEIVE_TIMEOUT_PERIOD);
       } catch (Exception exception)
       {
       System.out.println ("GenericMessageConsumer::receiveData() " +
       "fails due to " +
       exception.getMessage ());
      
       try
       {
       Thread.currentThread ().sleep (RETRY_INTERVAL);
       } catch (Exception sleepException)
       {
       // Do nothing
       }
      
       message = null;
       }
       } while (message == null);
      


      Is the long JMS connection rebuild or recovery time a problem of JBoss? Is there a solution?

      Thanks.

      Hann Wei

        • 1. Re: JMS connections go down for about a minute periodically
          genman

          What are the server settings for the client ping interval and socket read timeout?

          • 2. Re: JMS connections go down for about a minute periodically
            hannwei

             

            "genman" wrote:
            What are the server settings for the client ping interval and socket read timeout?


            They remain the JBoss default values:

             <!-- The ping period in millis -->
             <attribute name="PingPeriod">60000</attribute>
            
             <!-- Ensure this is greater than the ping period -->
             <attribute name="ReadTimeout">120000</attribute>
             <!-- Used to disconnect the client on the clientside if there is no activity
             -->
             <!-- Ensure this is greater than the ping period -->
             <attribute name="ClientReadTimeout">120000</attribute>
            


            I have just noticed that the disconnections have not happened for two consecutive days. So, there were no connection rebuilds or recoveries for two days. The disconnections do not seem periodic these few days.

            jms/uil2-service.xml that contains the configuration above has never been changed.


            Hann Wei