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
_______________________________________________
jboss-user mailing list
[email protected]
https://lists.jboss.org/mailman/listinfo/jboss-user
