-
1. Re: JBM clustering scenario
jbabad Feb 19, 2009 12:49 PM (in response to jbabad)I'm giving this one a nudge - to see if anyone has experience similar issues.
It appears that I'm more likely to get messages stuck if the receiver client attempts to fail-over and then times out after 60 seconds.
It is a though something loses track of the correct node IDs to use when pulling messages across the cluster and it's only by seqeuentially restarting the cluster that they reset correctly.
I'd appreciate if someone can say what the client does after timing out waiting for fail-over to start.
Thanks. -
2. Re: JBM clustering scenario
clebert.suconic Feb 19, 2009 9:23 PM (in response to jbabad)There is a FAQ somewhere about killing versus stopping the server.
You could set a flag to start failover after a clean shutdown, but usually failover will take place after a kill -9. -
3. Re: JBM clustering scenario
gaohoward Feb 19, 2009 11:52 PM (in response to jbabad)
11:08:13,730 INFO @Thread-10 failureDetected(FailoverCommandCenter.java:117) [FailoverCommandCenter
] JBoss Messaging server failure detected - waiting for failover to complete...
Can you turn on 'trace' log level and post more logs around this line? Thanks. -
4. Re: JBM clustering scenario
jbabad Feb 20, 2009 6:36 AM (in response to jbabad)Thanks.
This is a trace from the sending client - with the logging set to DEBUG. I've not yet managed to get a trace from the receiver
as I can't repeat the problem at will.
I can see where the client thinks that the connection to the server has gone away and where it reconnects.
Where can we set/tune the parameters that control ping timeout and the number of retries?
If the receiver client were to do something similar, would it then get a new connection, but "somehow" miss processing some messages that had already been pulled across to that node? Basically, when the connection is renewed, how does it decide where to pick up from?10:57:37,100 DEBUG @main (com.test.jee.jms.client.JmsSenderImpl.sendMessage(JmsSenderImpl.java:70)) [JmsSenderImpl] sendMessage:: ENTRY - 0 ://192.168.8.117:4457/?JB 10:57:39,061 DEBUG @Timer-4 (org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask.run(ConnectionValidator.java:674)) [ConnectionValidator] ConnectionValidator[SocketClientInvoker[f8395f, bisocket://192.168.8.117:4457], pingPeriod=2000 ms]'s connections is invalid 10:57:39,360 DEBUG @Timer-4 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed SocketClientInvoker[f8395f, bisocket://192.168.8.117:4457] from registry 10:57:39,360 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[f8395f, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,362 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52940].1263db] closing socket 10:57:39,362 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52940].1263db] closed socket 10:57:39,362 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.118,port=4457,localport=45268].1469658] closing socket 10:57:39,659 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.118,port=4457,localport=45268].1469658] closed socket 10:57:39,659 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52935].23bdd1] closing socket 10:57:39,659 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52935].23bdd1] closed socket 10:57:39,659 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.118,port=4457,localport=45273].830122] closing socket 10:57:39,660 DEBUG @Timer-4 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.118,port=4457,localport=45273].830122] closed socket 10:57:39,660 DEBUG @Timer-4 (org.jboss.remoting.ConnectionValidator.doStop(ConnectionValidator.java:616)) [ConnectionValidator] ConnectionValidator[SocketClientInvoker[f8395f, bisocket://192.168.8.117:4457], pingPeriod=2000 ms] stopped, returning true 10:57:39,660 DEBUG @Timer-4 (org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask.run(ConnectionValidator.java:680)) [ConnectionValidator] org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask@bf7916 detected connection failure: stopping LeasePinger 10:57:39,660 DEBUG @Timer-4 (org.jboss.remoting.LeasePinger.setDisconnectTimeout(LeasePinger.java:285)) [LeasePinger] LeasePinger[SocketClientInvoker[ee1ede, bisocket://192.168.8.117:4457](5c4o83h-59bpys-freqzo4j-1-freqzoni-f)] setting disconnect timeout to: -1 10:57:39,366 DEBUG @Thread-10 (org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:74)) [FailoverCommandCenter] failure detected by ConnectionFailureListener[FailoverCommandCenter[ConnectionState[3b-u3b0perf-1-9fvfoerf-3vjl04-938o4c5]]] java.lang.Exception: Could not connect to server! at org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask.run(ConnectionValidator.java:676) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) 10:57:39,701 DEBUG @Timer-4 (org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask.run(ConnectionValidator.java:686)) [ConnectionValidator] ConnectionValidator[SocketClientInvoker[f8395f, bisocket://192.168.8.117:4457], pingPeriod=2000 ms] shut down lease pinger 10:57:39,742 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.handleInternalInvocation(ServerInvoker.java:1754)) [ServerInvoker] ServerInvoker (SocketServerInvoker[192.168.8.125:1034117969]) removing client callback handler with session id of 5c4o83h-59bpys-freqzo4j-1-freqzonh-d+5c4o83h-59bpys-freqzo4j-1-freqzoop-i. 10:57:39,743 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.destroyControlConnection(BisocketServerInvoker.java:479)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] shutting down control connection: 5c4o83h-59bpys-freqzo4j-1-freqzoop-i 10:57:39,743 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@b9b8d0 from registry 10:57:39,743 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:453)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] stopped threads in clientpool 10:57:39,743 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:464)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] stopped threads in threadpool 10:57:39,744 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:469)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] exiting 10:57:39,744 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.stop(ServerInvoker.java:989)) [ServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] stopped 10:57:39,747 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed SocketClientInvoker[ee1ede, bisocket://192.168.8.117:4457] from registry 10:57:39,747 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[ee1ede, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,748 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52941].bfed5a] closing socket 10:57:39,748 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52941].bfed5a] closed socket 10:57:39,748 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:127)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52936].10c3a08] closing socket 10:57:39,749 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketWrapper.close(SocketWrapper.java:129)) [SocketWrapper] ClientSocketWrapper[Socket[addr=/192.168.8.117,port=4457,localport=52936].10c3a08] closed socket 10:57:39,749 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed SocketClientInvoker[1e12f6d, bisocket://192.168.8.117:4457] from registry 10:57:39,749 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[1e12f6d, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,749 INFO @Thread-10 (org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:117)) [FailoverCommandCenter] JBoss Messaging server failure detected - waiting for failover to complete... 10:57:39,751 DEBUG @main (com.test.jee.jms.client.JmsSenderImpl.sendMessage(JmsSenderImpl.java:79)) [JmsSenderImpl] sendMessage:: EXIT 10:57:39,752 DEBUG @main (com.test.jee.jms.client.JmsSenderApp.sendMessages(JmsSenderApp.java:21)) [JmsSenderApp] sendMessages:: Message: 320 10:57:39,755 DEBUG @main (com.test.jee.jms.client.JmsSenderImpl.sendMessage(JmsSenderImpl.java:70)) [JmsSenderImpl] sendMessage:: ENTRY - 0 ://192.168.8.117:4457/?JB 10:57:39,759 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.establishLease(MicroRemoteClientInvoker.java:438)) [MicroRemoteClientInvoker] SocketClientInvoker[55d93d, bisocket://192.168.8.118:4457] added client with session ID 5c4o83h-59bpys-freqzo4j-1-freqzzc6-9i to the lease pinger 10:57:39,760 DEBUG @Thread-10 (org.jboss.remoting.Client.addListener(Client.java:960)) [Client] starting callback Connector: InvokerLocator [bisocket://192.168.8.125:1689108489/callback?callbackServerHost=192.168.8.125&callbackServerPort=1689108489&callbackServerProtocol=bisocket&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=5c4o83h-59bpys-freqzo4j-1-freqzzcf-9l&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper] 10:57:39,850 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.createServerSocketFactory(ServerInvoker.java:1498)) [ServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory. 10:57:39,851 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.createServerSocketFactory(ServerInvoker.java:1504)) [ServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] created server socket factory javax.net.DefaultServerSocketFactory@113beb5 10:57:39,852 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.setup(BisocketServerInvoker.java:659)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] setting pingFrequency to 214748364 10:57:39,852 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.setup(BisocketServerInvoker.java:677)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] setting pingWindowFactor to 10 10:57:39,852 DEBUG @Thread-10 (org.jboss.remoting.transport.Connector.start(Connector.java:354)) [Connector] org.jboss.remoting.transport.Connector@ed5d9d started 10:57:39,853 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.handleInternalInvocation(ServerInvoker.java:1745)) [ServerInvoker] ServerInvoker (SocketServerInvoker[192.168.8.125:1689108489]) added client callback handler CallbackManager[9b688e] with session id of 5c4o83h-59bpys-freqzo4j-1-freqzzc6-9i+5c4o83h-59bpys-freqzo4j-1-freqzzf0-9m and callback handle object of null. 10:57:39,853 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@5e8d7d from registry 10:57:39,853 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:560)) [BisocketClientInvoker] getting secondary locator 10:57:39,851 DEBUG @Finalizer (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[ee1ede, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,856 DEBUG @Finalizer (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[ee1ede, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,856 DEBUG @Finalizer (org.jboss.remoting.ServerInvoker.stop(ServerInvoker.java:989)) [ServerInvoker] SocketServerInvoker[192.168.8.125:1034117969] stopped 10:57:39,858 DEBUG @Finalizer (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[1e12f6d, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,858 DEBUG @Finalizer (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.disconnect(MicroSocketClientInvoker.java:384)) [MicroSocketClientInvoker] SocketClientInvoker[1e12f6d, bisocket://192.168.8.117:4457] disconnecting ... 10:57:39,862 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:568)) [BisocketClientInvoker] secondary locator: InvokerLocator [null://192.168.8.118:47524/?] 10:57:39,863 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:379)) [BisocketServerInvoker] creating control connection: InvokerLocator [null://192.168.8.118:47524/?] 10:57:39,866 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:463)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] created control connection (5c4o83h-59bpys-freqzo4j-1-freqzzf0-9m): Socket[addr=/192.168.8.118,port=47524,localport=41033] 10:58:39,914 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.handleInternalInvocation(ServerInvoker.java:1754)) [ServerInvoker] ServerInvoker (SocketServerInvoker[192.168.8.125:1689108489]) removing client callback handler with session id of 5c4o83h-59bpys-freqzo4j-1-freqzzc6-9i+5c4o83h-59bpys-freqzo4j-1-freqzzf0-9m. 10:58:39,915 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.destroyControlConnection(BisocketServerInvoker.java:479)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] shutting down control connection: 5c4o83h-59bpys-freqzo4j-1-freqzzf0-9m 10:58:39,915 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@103fcaa from registry 10:58:39,915 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:453)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] stopped threads in clientpool 10:58:39,915 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:464)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] stopped threads in threadpool 10:58:39,916 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketServerInvoker.cleanup(SocketServerInvoker.java:469)) [SocketServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] exiting 10:58:39,916 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.stop(ServerInvoker.java:989)) [ServerInvoker] SocketServerInvoker[192.168.8.125:1689108489] stopped 10:58:39,916 DEBUG @Thread-10 (org.jboss.remoting.LeasePinger.setDisconnectTimeout(LeasePinger.java:285)) [LeasePinger] LeasePinger[SocketClientInvoker[55d93d, bisocket://192.168.8.118:4457](5c4o83h-59bpys-freqzo4j-1-freqzo5f-4)] setting disconnect timeout to: -1 10:58:39,920 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:632)) [InvokerRegistry] decremented SocketClientInvoker[55d93d, bisocket://192.168.8.118:4457]'s count, current count 1 10:58:39,921 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:632)) [InvokerRegistry] decremented SocketClientInvoker[6b9c84, bisocket://192.168.8.118:4457]'s count, current count 1 10:58:39,922 DEBUG @Thread-10 (org.jboss.jms.client.container.ClusteringAspect.handleCreateConnectionDelegate(ClusteringAspect.java:194)) [ClusteringAspect] Client attempted failover, but no failover attempt has been detected on the server side. We will now try again on the original server in case there was a temporary glitch on the client--server network 10:58:41,929 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:545)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting maxPoolSize to 200 10:58:41,930 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,930 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,930 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,931 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.<init>(MicroSocketClientInvoker.java:278)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] constructed 10:58:41,931 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:545)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting maxPoolSize to 200 10:58:41,932 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,933 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,933 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,933 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.<init>(BisocketClientInvoker.java:181)) [BisocketClientInvoker] Setting ping frequency to: 214748364 10:58:41,933 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:283)) [MicroRemoteClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] connecting 10:58:41,934 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.initPool(MicroSocketClientInvoker.java:1011)) [MicroSocketClientInvoker] Creating semaphore with size 200 10:58:41,934 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:297)) [MicroRemoteClientInvoker] SocketClientInvoker[39060b, bisocket://192.168.8.117:4457] connected 10:58:41,942 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:545)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting maxPoolSize to 1 10:58:41,943 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,943 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,944 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,944 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.<init>(MicroSocketClientInvoker.java:278)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] constructed 10:58:41,944 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:545)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting maxPoolSize to 1 10:58:41,945 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,945 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,945 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,945 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.<init>(BisocketClientInvoker.java:181)) [BisocketClientInvoker] Setting ping frequency to: 214748364 10:58:41,946 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:283)) [MicroRemoteClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] connecting 10:58:41,946 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.initPool(MicroSocketClientInvoker.java:1011)) [MicroSocketClientInvoker] Creating semaphore with size 1 10:58:41,946 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:297)) [MicroRemoteClientInvoker] SocketClientInvoker[166c114, bisocket://192.168.8.117:4457] connected 10:58:41,948 DEBUG @Thread-10 (org.jboss.remoting.Client.addListener(Client.java:960)) [Client] starting callback Connector: InvokerLocator [bisocket://192.168.8.125:997103908/callback?callbackServerHost=192.168.8.125&callbackServerPort=997103908&callbackServerProtocol=bisocket&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=5c4o83h-59bpys-freqzo4j-1-frer1bbv-9t&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper] 10:58:41,951 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.createServerSocketFactory(ServerInvoker.java:1498)) [ServerInvoker] SocketServerInvoker[192.168.8.125:997103908] did not find server socket factory configuration as mbean service or classname. Creating default server socket factory. 10:58:41,951 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.createServerSocketFactory(ServerInvoker.java:1504)) [ServerInvoker] SocketServerInvoker[192.168.8.125:997103908] created server socket factory javax.net.DefaultServerSocketFactory@113beb5 10:58:41,952 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.setup(BisocketServerInvoker.java:659)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:997103908] setting pingFrequency to 214748364 10:58:41,952 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.setup(BisocketServerInvoker.java:677)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:997103908] setting pingWindowFactor to 10 10:58:41,952 DEBUG @Thread-10 (org.jboss.remoting.transport.Connector.start(Connector.java:354)) [Connector] org.jboss.remoting.transport.Connector@b31a7c started 10:58:41,953 DEBUG @Thread-10 (org.jboss.remoting.ServerInvoker.handleInternalInvocation(ServerInvoker.java:1745)) [ServerInvoker] ServerInvoker (SocketServerInvoker[192.168.8.125:997103908]) added client callback handler CallbackManager[509df8] with session id of 5c4o83h-59bpys-freqzo4j-1-frer1bba-9p+5c4o83h-59bpys-freqzo4j-1-frer1bc0-9u and callback handle object of null. 10:58:41,953 DEBUG @Thread-10 (org.jboss.remoting.InvokerRegistry.decrementClientInvokerCounter(InvokerRegistry.java:628)) [InvokerRegistry] removed org.jboss.remoting.transport.local.LocalClientInvoker@8fcc7b from registry 10:58:41,953 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:560)) [BisocketClientInvoker] getting secondary locator 10:58:41,956 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.getSecondaryLocator(BisocketClientInvoker.java:568)) [BisocketClientInvoker] secondary locator: InvokerLocator [null://192.168.8.117:42993/?] 10:58:41,956 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:379)) [BisocketServerInvoker] creating control connection: InvokerLocator [null://192.168.8.117:42993/?] 10:58:41,957 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketServerInvoker.createControlConnection(BisocketServerInvoker.java:463)) [BisocketServerInvoker] SocketServerInvoker[192.168.8.125:997103908] created control connection (5c4o83h-59bpys-freqzo4j-1-frer1bc0-9u): Socket[addr=/192.168.8.117,port=42993,localport=50314] 10:58:41,969 DEBUG @Thread-10 (org.jboss.remoting.ConnectionValidator.<init>(ConnectionValidator.java:264)) [ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] created 10:58:41,969 DEBUG @Thread-10 (org.jboss.remoting.ConnectionValidator.start(ConnectionValidator.java:504)) [ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] timeout: 1000 10:58:41,969 DEBUG @Thread-10 (org.jboss.remoting.ConnectionValidator.start(ConnectionValidator.java:505)) [ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] ping retries: 1 10:58:41,970 DEBUG @Thread-10 (org.jboss.remoting.ConnectionValidator.start(ConnectionValidator.java:506)) [ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] connection retries: null 10:58:41,973 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,973 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,973 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,974 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.<init>(MicroSocketClientInvoker.java:278)) [MicroSocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] constructed 10:58:41,975 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:562)) [MicroSocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper 10:58:41,975 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.configureParameters(MicroSocketClientInvoker.java:571)) [MicroSocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting shouldCheckConnection to false 10:58:41,976 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.SocketClientInvoker.configureParameters(SocketClientInvoker.java:98)) [SocketClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] setting timeout to 0 10:58:41,976 DEBUG @Thread-10 (org.jboss.remoting.transport.bisocket.BisocketClientInvoker.<init>(BisocketClientInvoker.java:181)) [BisocketClientInvoker] Setting ping frequency to: 214748364 10:58:41,976 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:283)) [MicroRemoteClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] connecting 10:58:41,976 DEBUG @Thread-10 (org.jboss.remoting.transport.socket.MicroSocketClientInvoker.initPool(MicroSocketClientInvoker.java:1011)) [MicroSocketClientInvoker] Creating semaphore with size 50 10:58:41,977 DEBUG @Thread-10 (org.jboss.remoting.MicroRemoteClientInvoker.connect(MicroRemoteClientInvoker.java:297)) [MicroRemoteClientInvoker] SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457] connected 10:58:41,977 DEBUG @Thread-10 (org.jboss.remoting.ConnectionValidator.start(ConnectionValidator.java:528)) [ConnectionValidator] ConnectionValidator[SocketClientInvoker[1e6696c, bisocket://192.168.8.117:4457], pingPeriod=2000 ms] started 10:58:41,984 INFO @Thread-10 (org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:177)) [FailoverCommandCenter] JBoss Messaging failover complete 10:58:41,984 DEBUG @Thread-10 (org.jboss.jms.client.FailoverCommandCenter.failureDetected(FailoverCommandCenter.java:201)) [FailoverCommandCenter] FailoverCommandCenter[ConnectionState[8b-0qx1perf-1-9fvfoerf-3vjl04-938o4c5]] completed successful failover 10:58:42,020 DEBUG @main (com.test.jee.jms.client.JmsSenderImpl.sendMessage(JmsSenderImpl.java:79)) [JmsSenderImpl] sendMessage:: EXIT 10:58:42,020 DEBUG @main (com.test.jee.jms.client.JmsSenderApp.sendMessages(JmsSenderApp.java:21)) [JmsSenderApp] sendMessages:: Message: 321 10:58:42,020 DEBUG @main (com.test.jee.jms.client.JmsSenderImpl.sendMessage(JmsSenderImpl.java:70)) [JmsSenderImpl] sendMessage:: ENTRY - 0 ://192.168.8.117:4457/?JB
-
5. Re: JBM clustering scenario
jbabad Feb 20, 2009 8:32 AM (in response to jbabad)Hi,
For completeness I've managed to get a receiver client-side log where it stops picking up messages.
The first set of messages are from a successful receipt, then next set of messages are from the next message on after which it stops receiving.
If you need more logs then I've got the whole log file, but there about 5M of it.
Thanks again.
Successful2009-02-20 14:07:48,047 DEBUG [com.test.jee.jms.client.JmsReceiverImpl] (main) receiveMessage:: Received Message: 1 ://192.168.8.118:4457/?JB ID:JBM-d34f9a62-a745-4d64-8150-66908c8c73e7 2009-02-20 14:07:48,047 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5] receiving, timeout = 10000 2009-02-20 14:07:48,048 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5]: receive, timeout 10000 ms, blocking poll on queue 2009-02-20 14:07:48,048 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5] received delegator->JBossMessage[20236384659475424]:PERSISTENT, deliveryId=174 after being blocked on buffer 2009-02-20 14:07:48,048 TRACE [org.jboss.jms.client.container.SessionAspect] (main) sending acknowlegment transactionally, queueing on resource manager 2009-02-20 14:07:48,048 TRACE [org.jboss.jms.tx.ResourceManager] (main) adding Delivery[174, delegator->JBossMessage[20236384659475424]:PERSISTENT, deliveryId=174] to transaction LocalTx[c5-b1isxerf-1-9s9sxerf-jb9mhx-h38o4c5] 2009-02-20 14:07:48,048 TRACE [org.jboss.jms.tx.ResourceManager] (main) getting transaction for LocalTx[c5-b1isxerf-1-9s9sxerf-jb9mhx-h38o4c5] 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) Post deliver returned true 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5]: message delegator->JBossMessage[20236384659475424]:PERSISTENT, deliveryId=174 is not expired, pushing it to the caller 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5] receive() returning delegator->JBossMessage[20236384659475424]:PERSISTENT, deliveryId=174 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.tx.ResourceManager] (main) committing LocalTx[c5-b1isxerf-1-9s9sxerf-jb9mhx-h38o4c5] 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.tx.ResourceManager] (main) getting transaction for LocalTx[c5-b1isxerf-1-9s9sxerf-jb9mhx-h38o4c5] 2009-02-20 14:07:48,049 TRACE [org.jboss.jms.client.FailoverValve2] (main) FailoverValve[29461068] entering 2009-02-20 14:07:48,050 TRACE [org.jboss.jms.client.FailoverValve2] (main) FailoverValve[29461068] entered 2009-02-20 14:07:48,050 TRACE [org.jboss.jms.client.delegate.DelegateSupport] (main) ConnectionDelegate[6169134, ID=wg-pbtsverf-1-v0axoerf-sysedk-a38o4c5, SID=1] invoking org.jboss.jms.wireformat.ConnectionSendTransactionRequest@2c7ac5 synchronously on server using Client[27134372] 2009-02-20 14:07:48,050 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] (main) SocketClientInvoker[cd2e33, bisocket://192.168.8.118:4457](1) invoking InvocationRequest[303a60, JMS, org.jboss.jms.wireformat.ConnectionSendTransactionRequest@2c7ac5] 2009-02-20 14:07:48,050 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (main) SocketClientInvoker[cd2e33, bisocket://192.168.8.118:4457] obtained semaphore: 199
Failed2009-02-20 14:07:48,059 DEBUG [com.test.jee.jms.client.JmsReceiverImpl] (main) receiveMessage:: Received Message: 1 ://192.168.8.118:4457/?JB ID:JBM-30c12dee-f29f-4dc2-b3f7-2543239523c1 2009-02-20 14:07:48,059 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5] receiving, timeout = 10000 2009-02-20 14:07:48,059 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5]: receive, timeout 10000 ms, blocking poll on queue 2009-02-20 14:07:48,059 TRACE [org.jboss.jms.client.container.ClientConsumer] (main) ClientConsumer[yg-uitsverf-1-v0axoerf-sysedk-a38o4c5] waiting on main lock, timeout 10000 ms 2009-02-20 14:07:49,036 TRACE [org.jboss.remoting.ConnectionValidator] (Timer-2) ConnectionValidator[SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457], pingPeriod=2000 ms] sending PING tied to lease 2009-02-20 14:07:49,037 TRACE [org.jboss.remoting.ConnectionValidator] (Timer-2) pinging, sending InvocationRequest[1854b38, self, $PING$] over SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] 2009-02-20 14:07:49,037 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457](1) invoking InvocationRequest[1854b38, self, $PING$] 2009-02-20 14:07:49,037 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] obtained semaphore: 49 2009-02-20 14:07:49,038 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/192.168.8.118,port=4457,localport=46665].cfe049] 2009-02-20 14:07:49,038 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] writing version 22 on output stream 2009-02-20 14:07:49,038 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] writing invocation to marshaller 2009-02-20 14:07:49,038 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Writing InvocationRequest[1854b38, self, $PING$] 2009-02-20 14:07:49,038 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Stream is a DataOutputStream 2009-02-20 14:07:49,038 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Writing packet: SerializedPacket[InvocationRequest[1854b38, self, $PING$]] 2009-02-20 14:07:49,039 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Wrote packet 2009-02-20 14:07:49,039 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] done writing invocation to marshaller 2009-02-20 14:07:49,039 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] reading version from input stream 2009-02-20 14:07:49,039 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] read version 22 from input stream 2009-02-20 14:07:49,039 TRACE [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (Timer-2) SocketClientInvoker[3b1f38, bisocket://192.168.8.118:4457] reading response from unmarshaller 2009-02-20 14:07:49,039 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Reading 2009-02-20 14:07:49,040 TRACE [org.jboss.jms.wireformat.JMSWireFormat] (Timer-2) Stream is already DataInputStream :)
-
6. Re: JBM clustering scenario
mykl Dec 10, 2009 6:23 AM (in response to jbabad)Hi, jbabad!
Did you manage to solve the problem? Looks like we have the same problem on the client side. JMS server is on JBoss, client is on WebLogic.