[JBoss Messaging] - QueueConnectionFactory.createQueueConnection is bloked
by slogger
I am using JBoss Messaging 1.4.0.SP3 on Jboss AS 4.2.1 GA (non-clustered installation).
Jboss messaging uses remoting 2.2.2 SP7 (http://www.jboss.com/index.html?module=bb&op=viewtopic&t=134659).
The JBoss Messaging configuration is defualt.
The network connections are very unstable. Some period of time all works correctly, than receiving/sending stop working at all.
For example, it has sample client code:
@Test public void test() throws Exception {
| Properties props = new Properties();
| props.setProperty("java.naming.factory.initial", "org.jnp.interfaces.NamingContextFactory");
| props.setProperty("java.naming.provider.url", "10.0.0.166:1199");
| props.setProperty("java.naming.factory.url.pkgs", "org.jnp.interfaces");
| InitialContext jmsContext = new InitialContext(props);
| QueueConnectionFactory qcf = (QueueConnectionFactory) jmsContext.lookup("ConnectionFactory");
| log.trace("After lookup QueueConnectionFactory");
| QueueConnection connection = qcf.createQueueConnection(Sender.JMS_USER, Sender.JMS_USER_PWD);
| log.trace("After create QueueConnection");
| javax.jms.Queue queue = (javax.jms.Queue) jmsContext.lookup("queue/Region66");
| log.trace("After looked queue");
| QueueSession session = connection.createQueueSession(false, QueueSession.CLIENT_ACKNOWLEDGE);
| log.trace("After creating session");
| QueueReceiver receiver = session.createReceiver(queue);
| log.trace("After creating receiver");
| connection.start();
| log.trace("1");
| connection.close();
| log.trace("2");
| }
It lasts to line -> log.trace("After lookup QueueConnectionFactory");
Thus client code is bloked on this line:
QueueConnection connection = qcf.createQueueConnection(Sender.JMS_USER, Sender.JMS_USER_PWD);
It is client log:
| 2008-05-05 19:49:42,734 DEBUG [com.guest.ejb.remote.TestFailed] After lookup QueueConnectionFactory
| 2008-05-05 19:49:42,937 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:42,937 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:42,937 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:42,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] constructed
| 2008-05-05 19:49:42,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:42,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:42,953 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:42,968 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Setting ping frequency to: 214748364
| 2008-05-05 19:49:42,984 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] connecting
| 2008-05-05 19:49:42,984 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] added new pool ([]) as ServerAddress[10.0.0.166:4457, NO enableTcpNoDelay timeout 0 ms]
| 2008-05-05 19:49:42,984 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] connected
| 2008-05-05 19:49:43,140 TRACE [org.jboss.jms.client.delegate.DelegateSupport] ConnectionFactoryDelegate[jboss.messaging.connectionfactory:service=ConnectionFactory, SID=0] invoking ConnectionFactoryGetClientAOPStackRequest[a17083] synchronously on server using Client[14800362]
| 2008-05-05 19:49:43,140 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[a31e1b, JMS, ConnectionFactoryGetClientAOPStackRequest[a17083]]
| 2008-05-05 19:49:43,156 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] getting a socket, usedPooled: 0
| 2008-05-05 19:49:43,156 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] creating socket 0, attempt 1
| 2008-05-05 19:49:43,156 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] created socket: Socket[addr=/10.0.0.166,port=4457,localport=3393]
| 2008-05-05 19:49:43,171 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/10.0.0.166,port=4457,localport=3393], using timeout 0
| 2008-05-05 19:49:43,171 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403] setting timeout to 0
| 2008-05-05 19:49:43,171 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:43,171 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:43,171 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[a31e1b, JMS, ConnectionFactoryGetClientAOPStackRequest[a17083]]
| 2008-05-05 19:49:43,187 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:43,187 TRACE [org.jboss.jms.wireformat.JMSWireFormat] JBM Request
| 2008-05-05 19:49:43,187 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: ConnectionFactoryGetClientAOPStackRequest[a17083]
| 2008-05-05 19:49:43,187 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:43,187 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:43,187 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:43,187 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] read version 22 from input stream
| 2008-05-05 19:49:43,187 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] reading response from unmarshaller
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet ConnectionFactoryGetClientAOPStackResponse[null]
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:49:43,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationResponse[17653ae, ConnectionFactoryGetClientAOPStackResponse[18618 bytes]]
| 2008-05-05 19:49:43,203 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] returned ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403] to pool
| 2008-05-05 19:49:43,203 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] received response InvocationResponse[17653ae, ConnectionFactoryGetClientAOPStackResponse[18618 bytes]]
| 2008-05-05 19:49:43,203 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[1e13d52, bisocket://10.0.0.166:4457] received InvocationResponse so going to return response's return value of ConnectionFactoryGetClientAOPStackResponse[18618 bytes]
| 2008-05-05 19:49:43,218 TRACE [org.jboss.jms.client.delegate.DelegateSupport] ConnectionFactoryDelegate[jboss.messaging.connectionfactory:service=ConnectionFactory, SID=0] got server response for ConnectionFactoryGetClientAOPStackRequest[a17083]: ConnectionFactoryGetClientAOPStackResponse[18618 bytes]
| 2008-05-05 19:49:43,937 TRACE [org.jboss.jms.client.remoting.JMSRemotingConnection] JMSRemotingConnection[bisocket://10.0.0.166:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] created
| 2008-05-05 19:49:43,937 TRACE [org.jboss.jms.client.remoting.JMSRemotingConnection] JMSRemotingConnection[bisocket://10.0.0.166:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] created client
| 2008-05-05 19:49:43,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting maxPoolSize to 200
| 2008-05-05 19:49:43,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:43,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:43,953 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:43,953 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] constructed
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting maxPoolSize to 200
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Setting ping frequency to: 214748364
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] connecting
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] using pool ([ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]]) already defined for ServerAddress[10.0.0.166:4457, NO enableTcpNoDelay timeout 0 ms]
| 2008-05-05 19:49:43,968 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] connected
| 2008-05-05 19:49:43,984 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] sending initial lease ping to server to determine if server has leasing enabled.
| 2008-05-05 19:49:43,984 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[1113622, $PING$]
| 2008-05-05 19:49:43,984 TRACE [org.jboss.remoting.marshal.MarshalFactory] Could not find marshaller for data type 'jms'. Object in collection is null
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.marshal.MarshalFactory] Could not look up marshaller by data type ('jms'). Will try to load dynamically.
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.marshal.MarshalFactory] Found marshaller by loading locally.
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] got a socket, usedPooled: 1
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:44,000 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:44,000 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[1113622, $PING$]
| 2008-05-05 19:49:44,000 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:44,015 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationRequest[1113622, $PING$]]
| 2008-05-05 19:49:44,015 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:44,015 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:44,015 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:44,015 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] read version 22 from input stream
| 2008-05-05 19:49:44,015 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading response from unmarshaller
| 2008-05-05 19:49:44,015 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:49:44,015 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:49:44,015 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:49:44,031 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:49:44,031 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:49:44,031 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationResponse[18bf072, InvocationResponse[56f631, true]]
| 2008-05-05 19:49:44,031 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] returned ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403] to pool
| 2008-05-05 19:49:44,031 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received response InvocationResponse[18bf072, InvocationResponse[56f631, true]]
| 2008-05-05 19:49:44,046 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received InvocationResponse so going to return response's return value of InvocationResponse[56f631, true]
| 2008-05-05 19:49:44,046 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] server does have leasing enabled (with default lease period of 10000) and will start a new lease pinger.
| 2008-05-05 19:49:44,046 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] adding new client with session ID a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4 and lease period 10000
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] sending ping to server. Currently managing lease for following clients:
| a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4
|
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[26dbec, $PING$]
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] got a socket, usedPooled: 1
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:44,062 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:44,062 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[26dbec, $PING$]
| 2008-05-05 19:49:44,078 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:44,078 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationRequest[26dbec, $PING$]]
| 2008-05-05 19:49:44,078 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:44,078 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:44,078 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:44,093 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] read version 22 from input stream
| 2008-05-05 19:49:44,093 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading response from unmarshaller
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:49:44,093 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationResponse[2af081, InvocationResponse[113a53d, true]]
| 2008-05-05 19:49:44,093 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] returned ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403] to pool
| 2008-05-05 19:49:44,093 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received response InvocationResponse[2af081, InvocationResponse[113a53d, true]]
| 2008-05-05 19:49:44,109 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received InvocationResponse so going to return response's return value of InvocationResponse[113a53d, true]
| 2008-05-05 19:49:44,109 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] successfully pinged the server
| 2008-05-05 19:49:44,109 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] starting lease timer with ping period of 10000
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting maxPoolSize to 1
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] constructed
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting maxPoolSize to 1
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting shouldCheckConnection to false
| 2008-05-05 19:49:44,125 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] setting timeout to 0
| 2008-05-05 19:49:44,140 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Setting ping frequency to: 214748364
| 2008-05-05 19:49:44,140 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] connecting
| 2008-05-05 19:49:44,140 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] using pool ([ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]]) already defined for ServerAddress[10.0.0.166:4457, NO enableTcpNoDelay timeout 0 ms]
| 2008-05-05 19:49:44,140 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[c5495e, bisocket://10.0.0.166:4457] connected
| 2008-05-05 19:49:44,140 TRACE [org.jboss.jms.client.remoting.JMSRemotingConnection] JMSRemotingConnection[bisocket://10.0.0.166:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=10000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat] is doing push callbacks
| 2008-05-05 19:49:44,140 DEBUG [org.jboss.remoting.Client] starting callback Connector: InvokerLocator [bisocket://10.0.0.226:1489232572/callback?guid=a006a-zg7j8n-ffv8ao6l-1-ffv8ap8s-8&callbackServerProtocol=bisocket&callbackServerHost=10.0.0.226&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper&datatype=jms&callbackServerPort=1489232572&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&isCallbackServer=true]
| 2008-05-05 19:49:44,250 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory.
| 2008-05-05 19:49:44,250 DEBUG [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] created server socket factory javax.net.DefaultServerSocketFactory@f9c40
| 2008-05-05 19:49:44,250 DEBUG [org.jboss.remoting.transport.Connector] org.jboss.remoting.transport.Connector@71dc3d started
| 2008-05-05 19:49:44,265 TRACE [org.jboss.remoting.transport.local.LocalClientInvoker] Using local client invoker for invocation.
| 2008-05-05 19:49:44,265 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] received InternalInvocation[110c31]
| 2008-05-05 19:49:44,265 TRACE [org.jboss.remoting.ServerInvoker] handling InternalInvocation where method name = addClientListener
| 2008-05-05 19:49:44,281 DEBUG [org.jboss.remoting.ServerInvoker] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) added client callback handler CallbackManager[787d6a] with session id of a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4+a006a-zg7j8n-ffv8ao6l-1-ffv8apbu-9 and callback handle object of null.
| 2008-05-05 19:49:44,281 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[UNINITIALIZED] successfully dispatched invocation, returning null from subsystem 'JMS' to client a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4
| 2008-05-05 19:49:44,281 TRACE [org.jboss.remoting.InvokerRegistry] destroying client invoker InvokerLocator [bisocket://10.0.0.226:1489232572/callback?callbackServerHost=10.0.0.226&callbackServerPort=1489232572&callbackServerProtocol=bisocket&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=a006a-zg7j8n-ffv8ao6l-1-ffv8ap8s-8&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper], config {}
| 2008-05-05 19:49:44,281 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@1976011 from registry
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.InvokerRegistry] disconnecting org.jboss.remoting.transport.local.LocalClientInvoker@1976011
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[1878144, JMS, InternalInvocation[137d090]]
| 2008-05-05 19:49:44,296 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] getting secondary locator
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[15db314, InternalInvocation[97eded]]
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] got a socket, usedPooled: 1
| 2008-05-05 19:49:44,296 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:44,312 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:44,312 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[15db314, InternalInvocation[97eded]]
| 2008-05-05 19:49:44,312 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:44,312 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationRequest[15db314, InternalInvocation[97eded]]]
| 2008-05-05 19:49:44,312 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:44,312 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:44,312 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:44,312 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] read version 22 from input stream
| 2008-05-05 19:49:44,328 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading response from unmarshaller
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:49:44,328 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationResponse[16f144c, InvokerLocator [null://10.0.0.166:2737/null]]
| 2008-05-05 19:49:44,328 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] returned ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403] to pool
| 2008-05-05 19:49:44,328 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received response InvocationResponse[16f144c, InvokerLocator [null://10.0.0.166:2737/null]]
| 2008-05-05 19:49:44,343 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received InvocationResponse so going to return response's return value of InvokerLocator [null://10.0.0.166:2737/null]
| 2008-05-05 19:49:44,343 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] secondary locator: InvokerLocator [null://10.0.0.166:2737/null]
| 2008-05-05 19:49:44,343 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] creating control connection: InvokerLocator [null://10.0.0.166:2737/null]
| 2008-05-05 19:49:44,343 DEBUG [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] created control connection: Socket[addr=/10.0.0.166,port=2737,localport=3394]
| 2008-05-05 19:49:44,359 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3393].698403]
| 2008-05-05 19:49:44,359 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] got a socket, usedPooled: 1
| 2008-05-05 19:49:44,359 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:44,359 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:44,359 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[1878144, JMS, InternalInvocation[137d090]]
| 2008-05-05 19:49:44,375 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:44,375 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationRequest[1878144, JMS, InternalInvocation[137d090]]]
| 2008-05-05 19:49:44,375 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:44,375 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:44,390 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:54,109 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] sending ping to server. Currently managing lease for following clients:
| a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4
|
| 2008-05-05 19:49:54,109 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](1) invoking InvocationRequest[aadc97, $PING$]
| 2008-05-05 19:49:54,109 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] getting a socket, usedPooled: 1
| 2008-05-05 19:49:54,109 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] creating socket 1, attempt 1
| 2008-05-05 19:49:54,125 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] created socket: Socket[addr=/10.0.0.166,port=4457,localport=3395]
| 2008-05-05 19:49:54,125 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/10.0.0.166,port=4457,localport=3395], using timeout 0
| 2008-05-05 19:49:54,125 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3395].178460d] setting timeout to 0
| 2008-05-05 19:49:54,125 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing version 22 on output stream
| 2008-05-05 19:49:54,125 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] writing invocation to marshaller
| 2008-05-05 19:49:54,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationRequest[aadc97, $PING$]
| 2008-05-05 19:49:54,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:49:54,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationRequest[aadc97, $PING$]]
| 2008-05-05 19:49:54,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:49:54,140 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] done writing invocation to marshaller
| 2008-05-05 19:49:54,140 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading version from input stream
| 2008-05-05 19:49:54,140 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] read version 22 from input stream
| 2008-05-05 19:49:54,140 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] reading response from unmarshaller
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:49:54,140 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationResponse[bac9b9, InvocationResponse[111b910, true]]
| 2008-05-05 19:49:54,140 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] returned ClientSocketWrapper[Socket[addr=/10.0.0.166,port=4457,localport=3395].178460d] to pool
| 2008-05-05 19:49:54,156 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received response InvocationResponse[bac9b9, InvocationResponse[111b910, true]]
| 2008-05-05 19:49:54,156 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457] received InvocationResponse so going to return response's return value of InvocationResponse[111b910, true]
| 2008-05-05 19:49:54,156 TRACE [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[e1899b, bisocket://10.0.0.166:4457](a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)] successfully pinged the server
|
|
It is repeated periodically during the unlimited time.
It is server log:
2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] accepted Socket[addr=/10.0.0.226,port=3393,localport=4457]
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] trying to get a worker thread from threadpool for processing
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] got WorkerThread#26[10.0.0.226:3334] from threadpool
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] reusing WorkerThread#26[10.0.0.226:3334]
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#26[10.0.0.226:3393] has notified on mutex
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] passed through ServerSocketRefresh.release()
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#26[10.0.0.226:3393] woke up after wait
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] is going to wait on serverSocket.accept()
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] beginning dorun()
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating the socket wrapper
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] constructing org.jboss.jms.server.remoting.ServerSocketWrapper instance for Socket[addr=/10.0.0.226,port=3393,localport=4457], using timeout 0
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[Socket[addr=/10.0.0.226,port=3393,localport=4457].11792ef] setting timeout to 0
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] processing first invocation without acknowledging
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:33,281 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet ConnectionFactoryGetClientAOPStackRequest[afc0dd]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[9f0102, JMS, ConnectionFactoryGetClientAOPStackRequest[afc0dd]]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[9f0102, JMS, ConnectionFactoryGetClientAOPStackRequest[afc0dd]] from unmarshaller
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received ConnectionFactoryGetClientAOPStackRequest[afc0dd]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] dispatching InvocationRequest[9f0102, JMS, ConnectionFactoryGetClientAOPStackRequest[afc0dd]] from client null to subsystem 'JMS'
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.server.remoting.JMSServerInvocationHandler] invoking InvocationRequest[9f0102, JMS, ConnectionFactoryGetClientAOPStackRequest[afc0dd]]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] successfully dispatched invocation, returning ConnectionFactoryGetClientAOPStackResponse[18618 bytes] from subsystem 'JMS' to client null
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned ConnectionFactoryGetClientAOPStackResponse[18618 bytes]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[fb59cf, ConnectionFactoryGetClientAOPStackResponse[18618 bytes]]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] JBM Response
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: ConnectionFactoryGetClientAOPStackResponse[18618 bytes]
| 2008-05-05 19:53:33,296 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:33,296 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[1c54b7e, $PING$]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[1c54b7e, $PING$] from unmarshaller
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received $PING$
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for client session id: a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.Lease] Starting lease for client invoker (session id = a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6) with lease window time of 20000
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.ServerInvoker] No lease established for client session id (a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6), so starting a new one.
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] returning InvocationResponse[1df5bda, true]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvocationResponse[1df5bda, true]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[107506d, InvocationResponse[1df5bda, true]]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[107506d, InvocationResponse[1df5bda, true]]]
| 2008-05-05 19:53:34,125 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:34,125 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[1b1d760, $PING$]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[1b1d760, $PING$] from unmarshaller
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received $PING$
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for client session id: a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.ServerInvoker] Updated lease for client session id (a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] returning InvocationResponse[b30152, true]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvocationResponse[b30152, true]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[1bafe0, InvocationResponse[b30152, true]]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[1bafe0, InvocationResponse[b30152, true]]]
| 2008-05-05 19:53:34,203 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:34,203 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[17c295b, InternalInvocation[7f1b41]]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[17c295b, InternalInvocation[7f1b41]] from unmarshaller
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received InternalInvocation[7f1b41]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] successfully dispatched invocation, returning InvokerLocator [null://10.0.0.166:2737/null] from subsystem 'null' to client null
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvokerLocator [null://10.0.0.166:2737/null]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[d64ab5, InvokerLocator [null://10.0.0.166:2737/null]]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[d64ab5, InvokerLocator [null://10.0.0.166:2737/null]]]
| 2008-05-05 19:53:34,421 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:34,421 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:34,500 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[c2cc2c, JMS, InternalInvocation[ea8e55]]
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[c2cc2c, JMS, InternalInvocation[ea8e55]] from unmarshaller
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received InternalInvocation[ea8e55]
| 2008-05-05 19:53:34,500 TRACE [org.jboss.remoting.ServerInvoker] handling InternalInvocation where method name = addListener
| 2008-05-05 19:53:34,500 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4+a006a-zg7j8n-ffv8ao6l-1-ffv8apbu-9
| 2008-05-05 19:53:34,500 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[10.0.0.166:4457]
| 2008-05-05 19:53:34,500 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[10.0.0.166:4457]] setting callback handler to ServerInvokerCallbackHandler[a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-4+a006a-zg7j8n-ffv8ao6l-1-ffv8apbu-9]
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] accepted Socket[addr=/10.0.0.226,port=3395,localport=4457]
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] trying to get a worker thread from threadpool for processing
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] got WorkerThread#24[10.0.0.188:38263] from threadpool
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] reusing WorkerThread#24[10.0.0.188:38263]
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#24[10.0.0.226:3395] has notified on mutex
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] passed through ServerSocketRefresh.release()
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#24[10.0.0.226:3395] woke up after wait
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] SocketServerInvoker[10.0.0.166:4457] is going to wait on serverSocket.accept()
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] beginning dorun()
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating the socket wrapper
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] constructing org.jboss.jms.server.remoting.ServerSocketWrapper instance for Socket[addr=/10.0.0.226,port=3395,localport=4457], using timeout 0
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[Socket[addr=/10.0.0.226,port=3395,localport=4457].126792d] setting timeout to 0
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] processing first invocation without acknowledging
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:44,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[dd9397, $PING$]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[dd9397, $PING$] from unmarshaller
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received $PING$
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for client session id: a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.ServerInvoker] Updated lease for client session id (a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] returning InvocationResponse[104b063, true]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvocationResponse[104b063, true]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[d8341a, InvocationResponse[104b063, true]]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[d8341a, InvocationResponse[104b063, true]]]
| 2008-05-05 19:53:44,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:44,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[692fe3, $PING$]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[692fe3, $PING$] from unmarshaller
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received $PING$
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for client session id: a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.ServerInvoker] Updated lease for client session id (a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] returning InvocationResponse[1c7011e, true]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvocationResponse[1c7011e, true]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[1a7634, InvocationResponse[1c7011e, true]]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[1a7634, InvocationResponse[1c7011e, true]]]
| 2008-05-05 19:53:54,250 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:53:54,250 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Returning payload: InvocationRequest[d56b9d, $PING$]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[d56b9d, $PING$] from unmarshaller
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[10.0.0.166:4457].invoke()
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] received $PING$
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for client session id: a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.ServerInvoker] Updated lease for client session id (a006a-zg7j8n-ffv8ao6l-1-ffv8ap35-6)
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[10.0.0.166:4457] returning InvocationResponse[18c410f, true]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[10.0.0.166:4457].invoke() returned InvocationResponse[18c410f, true]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing InvocationResponse[10346bb, InvocationResponse[18c410f, true]]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is a DataOutputStream
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Writing packet: SerializedPacket[InvocationResponse[10346bb, InvocationResponse[18c410f, true]]]
| 2008-05-05 19:54:04,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Wrote packet
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation
| 2008-05-05 19:54:04,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream
| 2008-05-05 19:54:14,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream
| 2008-05-05 19:54:14,234 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Stream is already DataInputStream :)
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Created packet SerializedPacket[null]
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Reading packet
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Read packet
| 2008-05-05 19:54:14,234 TRACE [org.jboss.jms.wireformat.JMSWireFormat] Retur
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4148683#4148683
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4148683
16 years, 4 months
[JBoss Messaging] - Re: OutOfMemoryError with JBoss Messaging
by harish43
Andy,
Sorry for the delay in responding to your request. I have a simple testcase to reproduce the issue.
I have run two tests with the queue example that comes with the JBoss Messaging distribution. The first test was to use the queue example to connect to a JBoss Messaging instance and the second test was to use the same queue example to connect to a JBossMQ instance. I used version 1.4.1.Beta1 of JBM in and version 4.0 of JBossMQ. The JBoss server version is 4.2.2.GA.
I enhanced the queue example to do the following steps 1 million times.
1. Lookup /ConnectionFactory
2. Lookup Queue
3. Create Connection
4. Create Session
5. Create Producer
6. Create Text Message
7. Send message
8. Create Consumer
9. Start the connection
10. Receive text message
11. Close connection
The JBossMQ test was twice as fast and consumed less memory overall. I had given 1GB for Eden and 1GB for old generation and the JBossMQ test used less than 80 MB of old generation throughout the test. I didn't see any of the MQ or remoting classes grow in number or size throughput the test.
In the JBM test the memory usage grew gradually over time and it used more than 400MB. I noticed the following classes grew.
At the beginning of the test
680 ..... 49k ..... org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask (CL #4)
680 ..... 5k ...... org.jboss.remoting.transport.bisocket.BisocketClientInvoker$BooleanHolder (CL #4)
7 ....... 8k ...... java.util.TimerTask[]
At the end of the test
689030 .. 49793k .. org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask (CL #4)
689030 .. 6055k ... org.jboss.remoting.transport.bisocket.BisocketClientInvoker$BooleanHolder (CL #4)
7 ....... 4102k ... java.util.TimerTask[]
The destinations-service.xml file is as below:
<?xml version="1.0" encoding="UTF-8"?>
<!--
Messaging Destinations deployment descriptor.
$Id: destinations-service.xml 1930 2007-01-09 18:16:04Z timfox $
-->
<!--
The Default Dead Letter Queue. This destination is a dependency of an EJB MDB container.
-->
<mbean code="org.jboss.jms.server.destination.QueueService"
name="jboss.messaging.destination:service=Queue,name=DLQ"
xmbean-dd="xmdesc/Queue-xmbean.xml">
<depends optional-attribute-name="ServerPeer">jboss.messaging:service=ServerPeer
jboss.messaging:service=PostOffice
<!--
The Default Expiry Queue.
-->
<mbean code="org.jboss.jms.server.destination.QueueService"
name="jboss.messaging.destination:service=Queue,name=ExpiryQueue"
xmbean-dd="xmdesc/Queue-xmbean.xml">
<depends optional-attribute-name="ServerPeer">jboss.messaging:service=ServerPeer
jboss.messaging:service=PostOffice
<mbean code="org.jboss.jms.server.destination.QueueService"
name="jboss.messaging.destination:service=Queue,name=testQueue"
xmbean-dd="xmdesc/Queue-xmbean.xml">
<depends optional-attribute-name="ServerPeer">jboss.messaging:service=ServerPeer
jboss.messaging:service=PostOffice
The connection-factories-service.xml file is as below:
<?xml version="1.0" encoding="UTF-8"?>
<!--
Messaging Connection Factories deployment descriptor.
$Id: connection-factories-service.xml 3332 2007-11-15 09:32:43Z timfox $
-->
<!-- The default connection factory does not support automatic failover or load balancing-
this is so we can maintain compatiblity with applications written for JBoss MQ which use this
connection factory.
-->
<mbean code="org.jboss.jms.server.connectionfactory.ConnectionFactory"
name="jboss.messaging.connectionfactory:service=ConnectionFactory"
xmbean-dd="xmdesc/ConnectionFactory-xmbean.xml">
<depends optional-attribute-name="ServerPeer">jboss.messaging:service=ServerPeer
<depends optional-attribute-name="Connector">jboss.messaging:service=Connector,transport=bisocket
jboss.messaging:service=PostOffice
/ConnectionFactory
/XAConnectionFactory
java:/ConnectionFactory
java:/XAConnectionFactory
I haven't modified the remoting-bisocket-service.xml and the messaging-service.xml files and the only change I made to the mysql-persistence-service.xml file is to set the Clustered attribute of the Post Office to false.
The modified queue example is below:
package org.jboss.example.jms.queue;
import javax.jms.Connection;
import javax.jms.ConnectionFactory;
import javax.jms.JMSException;
import javax.jms.MessageConsumer;
import javax.jms.MessageProducer;
import javax.jms.Queue;
import javax.jms.Session;
import javax.jms.TextMessage;
import javax.naming.InitialContext;
import org.jboss.example.jms.common.ExampleSupport;
/**
* This example creates a JMS Connection to a JBoss Messaging instance and uses it to create a
* session and a message producer, which sends a message to the queue "queue/testQueue". Then, the
* example uses the same connection to create a consumer that that reads a single message from the
* queue. The example is considered successful if the message consumer receives without any error
* the message that was sent by the producer.
*
* Since this example is also used by the smoke test, it is essential that the VM exits with exit
* code 0 in case of successful execution and a non-zero value on failure.
*
* @author Ovidiu Feodorov
* @author Luc Texier
* @author Tim Fox
* @version $Revision: 2868 $
*
* $Id: QueueExample.java 2868 2007-07-10 20:22:16Z timfox $
*/
public class QueueExample extends ExampleSupport
{
public void example() throws Exception
{
String destinationName = getDestinationJNDIName();
InitialContext ic = null;
ConnectionFactory cf = null;
Connection connection = null;
try
{
for(long i = 0; i < 1000000; i++) {
ic = new InitialContext();
cf = (ConnectionFactory)ic.lookup("/ConnectionFactory");
Queue queue = (Queue)ic.lookup(destinationName);
log("Queue " + destinationName + " exists");
connection = cf.createConnection();
Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE);
MessageProducer sender = session.createProducer(queue);
TextMessage message = session.createTextMessage("Hello!");
sender.send(message);
log("Message #" + i);
log("The message was successfully sent to the " + queue.getQueueName() + " queue");
MessageConsumer consumer = session.createConsumer(queue);
connection.start();
message = (TextMessage)consumer.receive();
log("Received message: " + message.getText());
assertEquals("Hello!", message.getText());
displayProviderInfo(connection.getMetaData());
closeConnection(connection);
}
}
finally
{
if(ic != null)
{
try
{
ic.close();
}
catch(Exception e)
{
throw e;
}
}
// ALWAYS close your connection in a finally block to avoid leaks.
// Closing connection also takes care of closing its related objects e.g. sessions.
closeConnection(connection);
}
}
private void closeConnection(Connection con)
{
try
{
if (con != null)
{
con.close();
}
}
catch(JMSException jmse)
{
log("Could not close connection " + con +" exception was " + jmse);
}
}
protected boolean isQueueExample()
{
return true;
}
public static void main(String[] args)
{
new QueueExample().run();
}
}
I have also tried with moving the two lookups to outside of the for loop with similar results.
The question I have is why are the org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask and the org.jboss.remoting.transport.bisocket.BisocketClientInvoker$BooleanHolder classes are growing over time?
Please let me know if you need any more information.
Harish.
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4148677#4148677
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4148677
16 years, 4 months