[Messaging, JMS & JBossMQ] - JMS connections go down for about a minute periodically
by 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
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3978060#3978060
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=3978060
19 years, 8 months