JMS connections go down for about a minute periodically
hannwei Oct 12, 2006 11:56 PMHi,
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