[jboss-user] [Messaging, JMS & JBossMQ] - JMS connections go down for about a minute periodically

Thursday, 12 October 2006

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#...

Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

[jboss-user] [Messaging, JMS & JBossMQ] - JMS connections go down for about a minute periodically