NullPointerException in org.jboss.jms.server.endpoint.Server

[bob_walker99]

I'm using JBoss AS 4.2.2/JBM 1.4.0 on Linux SLES 9 x86_64 with Java 1.6.0_06. I have a single queue that a remote command line client pumps messages at, and a Jetty instance that has a Thread that implements MessageListener.

I'm seeing this in my server log, which coincides with the last point my MessageListener has onMessage called for the last time. My ExceptionListener never gets called, and my consumer is removed from the Queue.

2008-11-05 20:12:16,381 ERROR [org.jboss.messaging.util.ExceptionUtil] ConnectionEndpoint[wcy1-jk2s66nf-1-18ofs1nf-rplxnw-f20a] close [9r12-1f2pe6nf-1-18ofs1nf-rplxnw-f20a]
 java.lang.NullPointerException
 at org.jboss.jms.server.endpoint.ServerSessionEndpoint.localClose(ServerSessionEndpoint.java:1192)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.close(ServerConnectionEndpoint.java:385)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.closeConsumersForClientVMID(SimpleConnectionManager.java:377)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.handleClientFailure(SimpleConnectionManager.java:173)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.handleConnectionException(SimpleConnectionManager.java:200)
 at org.jboss.remoting.ConnectionNotifier.connectionLost(ConnectionNotifier.java:50)
 at org.jboss.remoting.Lease.notifyClientLost(Lease.java:211)
 at org.jboss.remoting.Lease.access$500(Lease.java:39)
 at org.jboss.remoting.Lease$LeaseTimerTask.run(Lease.java:249)
 at java.util.TimerThread.mainLoop(Timer.java:512)
 at java.util.TimerThread.run(Timer.java:462)
 2008-11-05 20:12:16,491 ERROR [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] Failed to close connection
 org.jboss.jms.exception.MessagingJMSException: A failure has occurred during processing of the request. Please consult the server logs for more details. ConnectionEndpoint[wcy1-jk2s66nf-1-18ofs1nf-rplxnw-f20a] close [9r12-1f2pe6nf-1-18ofs1nf-rplxnw-f20a]
 at org.jboss.messaging.util.ExceptionUtil.handleJMSInvocation(ExceptionUtil.java:72)
 at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.close(ServerConnectionEndpoint.java:432)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.closeConsumersForClientVMID(SimpleConnectionManager.java:377)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.handleClientFailure(SimpleConnectionManager.java:173)
 at org.jboss.jms.server.connectionmanager.SimpleConnectionManager.handleConnectionException(SimpleConnectionManager.java:200)
 at org.jboss.remoting.ConnectionNotifier.connectionLost(ConnectionNotifier.java:50)
 at org.jboss.remoting.Lease.notifyClientLost(Lease.java:211)
 at org.jboss.remoting.Lease.access$500(Lease.java:39)
 at org.jboss.remoting.Lease$LeaseTimerTask.run(Lease.java:249)
 at java.util.TimerThread.mainLoop(Timer.java:512)
 at java.util.TimerThread.run(Timer.java:462)

I'm also seeing this a lot:

A problem has been detected with the connection to remote client a0ac-y95htn-fn6xm53g-1-fn6xm6n0-4, jmsClientID=null. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.

I'm tracing all my connection and session creation and disposal , and for the life of me I can't find anywhere where I'm not cleaning up my connections when I should be. The sending client is over a remote VPN, so it's possible that is the cause of a network failure, but I'm led to believe this is a reliable link that other traffic uses without issue.

I guess I have 2 questions:
1) what is the cause of the NPE, and can I do anything to resolve it?
and
2) Is there a way to pass a meaningful string to JBM to identify my clients more usefully so that I can track down where the connection was made from and what I might be doing wrongly? I tried calling setClientID on the connection when I create it, but I never see the value I set in the JBM logs.

Alternatively is there a function of the AS MBean interface that will allow me to see current connections / client resources in use?

Many thanks,

Bob

[ataylor]

The first thing i would do is upgrade to the latest 1.4 version to see if it fixes the problem.

[timfox]

Also make sure you use the correct version of jboss remoting on both the client and server side as specified in the installation instructions.

Wrong remoting is the biggest cause of errors like this.

[bob_walker99]

Sorry, In my rush to post I got that wrong: I am using JBM 1.4.0.SP3 and remoting 2.2.2.SP4 - I understand those are the latest / correct versions aren't they?

[bob_walker99]

(to clarify, I have those version on both client and server)

[bob_walker99]

I am getting a slightly different error today, but the result to my client is the same - the MessageListener is removed from the queue, and I get nothing on my ExceptionListener.

This is in my client logs at the point at which it fails:

2008-11-06 15:07:09,672 org.jboss.jms.client.container.ClientConsumer - Failed to deliver message
 org.jboss.jms.exception.MessagingJMSException: Failed to invoke
 at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$acknowledgeDelivery$aop(ClientSessionDelegate.java:172)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.acknowledgeDelivery(ClientSessionDelegate.java)
 at org.jboss.jms.client.container.SessionAspect.ackDelivery(SessionAspect.java:844)
 at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:338)
 at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect19.invoke(SessionAspect19.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_1255239194451907669.invokeNext(ClientSessionDelegate$postDeliver_1255239194451907669.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_1255239194451907669.invokeNext(ClientSessionDelegate$postDeliver_1255239194451907669.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:183)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:976)
 at org.jboss.messaging.util.JBMExecutor$TCLExecutor.run(JBMExecutor.java:78)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:619)
 Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id uul2-btw8b7nf-1-18ofs1nf-rplxnw-f20a
 at org.jboss.jms.wireformat.SessionAcknowledgeDeliveryRequest.serverInvoke(SessionAcknowledgeDeliveryRequest.java:75)
 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:795)
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:573)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:387)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:166)
 at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:163)
 at org.jboss.remoting.Client.invoke(Client.java:1634)
 at org.jboss.remoting.Client.invoke(Client.java:548)
 at org.jboss.remoting.Client.invoke(Client.java:536)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
 ... 23 more
2008-11-06 15:07:09,672 org.jboss.jms.client.container.ClientConsumer - Failed to deliver message
 org.jboss.jms.exception.MessagingJMSException: Failed to invoke
 at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.org$jboss$jms$client$delegate$ClientSessionDelegate$acknowledgeDelivery$aop(ClientSessionDelegate.java:172)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.invokeNext(ClientSessionDelegate$acknowledgeDelivery_N5825751487881460811.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.acknowledgeDelivery(ClientSessionDelegate.java)
 at org.jboss.jms.client.container.SessionAspect.ackDelivery(SessionAspect.java:844)
 at org.jboss.jms.client.container.SessionAspect.handlePostDeliver(SessionAspect.java:338)
 at org.jboss.aop.advice.org.jboss.jms.client.container.SessionAspect19.invoke(SessionAspect19.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_1255239194451907669.invokeNext(ClientSessionDelegate$postDeliver_1255239194451907669.java)
 at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
 at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
 at org.jboss.jms.client.delegate.ClientSessionDelegate$postDeliver_1255239194451907669.invokeNext(ClientSessionDelegate$postDeliver_1255239194451907669.java)
 at org.jboss.jms.client.delegate.ClientSessionDelegate.postDeliver(ClientSessionDelegate.java)
 at org.jboss.jms.client.container.ClientConsumer.callOnMessage(ClientConsumer.java:183)
 at org.jboss.jms.client.container.ClientConsumer$ListenerRunner.run(ClientConsumer.java:976)
 at org.jboss.messaging.util.JBMExecutor$TCLExecutor.run(JBMExecutor.java:78)
 at EDU.oswego.cs.dl.util.concurrent.QueuedExecutor$RunLoop.run(QueuedExecutor.java:89)
 at java.lang.Thread.run(Thread.java:619)
 Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id uul2-btw8b7nf-1-18ofs1nf-rplxnw-f20a
 at org.jboss.jms.wireformat.SessionAcknowledgeDeliveryRequest.serverInvoke(SessionAcknowledgeDeliveryRequest.java:75)
 at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
 at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:795)
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:573)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:387)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:166)
 at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:163)
 at org.jboss.remoting.Client.invoke(Client.java:1634)
 at org.jboss.remoting.Client.invoke(Client.java:548)
 at org.jboss.remoting.Client.invoke(Client.java:536)
 at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
 ... 23 more

And this in my server logs:

2008-11-06 15:06:05,666 WARN [org.jboss.jms.server.endpoint.ServerSessionEndpoint] Timed out waiting for last message
2008-11-06 15:06:16,088 WARN [org.jboss.jms.server.endpoint.ServerSessionEndpoint] Timed out waiting for last message
2008-11-06 15:06:39,652 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - first pass <Thu, 6 Nov 2008 15:06:39>
2008-11-06 15:06:39,652 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] StatusModule: first pass
2008-11-06 15:06:39,652 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
2008-11-06 15:06:39,652 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
2008-11-06 15:06:49,654 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] Periodic recovery - second pass <Thu, 6 Nov 2008 15:06:49>
2008-11-06 15:06:49,654 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AtomicActionRecoveryModule: Second pass
2008-11-06 15:06:49,654 DEBUG [com.arjuna.ats.txoj.logging.txojLoggerI18N] [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
2008-11-06 15:06:49,654 DEBUG [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
2008-11-06 15:06:52,808 DEBUG [org.jboss.remoting.ConnectionNotifier] Server connection lost to client (session id = a02f-zcx09c-fn7b8v1n-1-fn7b8wl6-d
2008-11-06 15:06:52,892 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[982d2e, bisocket://10.0.2.15:1281345487] from registry
2008-11-06 15:06:52,897 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[982d2e, bisocket://10.0.2.15:1281345487] disconnecting ...
2008-11-06 15:06:52,906 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a02f-zcx09c-fn7b8v1n-1-fn7b8wl6-d+a02f-zcx09c-fn7b8v1n-1-fn7b8wls-g] shut down
2008-11-06 15:06:52,919 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] A problem has been detected with the connection to remote client a02f-zcx09c-fn7b8v1n-1-fn7b8wl6-d, jmsClientID=b-cfw8b7nf-1-n1v8b7nf-c90xcz-f20a. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.
2008-11-06 15:06:52,919 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] clearing up state for connection ConnectionEndpoint[tul2-9tw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:06:52,922 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[e430db, bisocket://10.0.2.15:1281495413] from registry
2008-11-06 15:06:52,922 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e430db, bisocket://10.0.2.15:1281495413] disconnecting ...
2008-11-06 15:07:08,155 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[tul2-9tw8b7nf-1-18ofs1nf-rplxnw-f20a] with remoting session ID ...-fn7b8wpd-n
2008-11-06 15:07:08,155 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] cleared up state for connection ConnectionEndpoint[tul2-9tw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,155 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] clearing up state for connection ConnectionEndpoint[hul2-dfw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,157 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[97c808, bisocket://10.0.2.15:1279737688] from registry
2008-11-06 15:07:08,157 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[97c808, bisocket://10.0.2.15:1279737688] disconnecting ...
2008-11-06 15:07:08,182 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[hul2-dfw8b7nf-1-18ofs1nf-rplxnw-f20a] with remoting session ID ...-fn7b8vv2-4
2008-11-06 15:07:08,182 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] cleared up state for connection ConnectionEndpoint[hul2-dfw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,182 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] clearing up state for connection ConnectionEndpoint[pul2-cpw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,251 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[e3b938, bisocket://10.0.2.15:1281439670] from registry
2008-11-06 15:07:08,251 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[e3b938, bisocket://10.0.2.15:1281439670] disconnecting ...
2008-11-06 15:07:08,252 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[pul2-cpw8b7nf-1-18ofs1nf-rplxnw-f20a] with remoting session ID ...-fn7b8woe-i
2008-11-06 15:07:08,252 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] cleared up state for connection ConnectionEndpoint[pul2-cpw8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,252 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] clearing up state for connection ConnectionEndpoint[lul2-aow8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,285 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[lul2-aow8b7nf-1-18ofs1nf-rplxnw-f20a] with remoting session ID ...-fn7b8wl6-d
2008-11-06 15:07:08,285 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] cleared up state for connection ConnectionEndpoint[lul2-aow8b7nf-1-18ofs1nf-rplxnw-f20a]
2008-11-06 15:07:08,290 DEBUG [org.jboss.remoting.ConnectionNotifier] Server connection lost to client (session id = a02f-zcx09c-fn7b8v1n-1-fn7b8woe-i
2008-11-06 15:07:08,304 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a02f-zcx09c-fn7b8v1n-1-fn7b8woe-i+a02f-zcx09c-fn7b8v1n-1-fn7b8wp1-l] shut down
2008-11-06 15:07:08,304 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] ConnectionManager[11da858] cannot look up remoting session ID a02f-zcx09c-fn7b8v1n-1-fn7b8woe-i
2008-11-06 15:07:08,304 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] A problem has been detected with the connection to remote client a02f-zcx09c-fn7b8v1n-1-fn7b8woe-i, jmsClientID=null. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.
2008-11-06 15:07:08,306 DEBUG [org.jboss.remoting.ConnectionNotifier] Server connection lost to client (session id = a02f-zcx09c-fn7b8v1n-1-fn7b8vv2-4
2008-11-06 15:07:08,308 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a02f-zcx09c-fn7b8v1n-1-fn7b8vv2-4+a02f-zcx09c-fn7b8v1n-1-fn7b8w9g-9] shut down
2008-11-06 15:07:08,313 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] ConnectionManager[11da858] cannot look up remoting session ID a02f-zcx09c-fn7b8v1n-1-fn7b8vv2-4
2008-11-06 15:07:08,313 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] A problem has been detected with the connection to remote client a02f-zcx09c-fn7b8v1n-1-fn7b8vv2-4, jmsClientID=null. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.
2008-11-06 15:07:08,313 DEBUG [org.jboss.remoting.ConnectionNotifier] Server connection lost to client (session id = a02f-zcx09c-fn7b8v1n-1-fn7b8wpd-n
2008-11-06 15:07:08,320 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a02f-zcx09c-fn7b8v1n-1-fn7b8wpd-n+a02f-zcx09c-fn7b8v1n-1-fn7b8ws9-q] shut down
2008-11-06 15:07:08,320 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] ConnectionManager[11da858] cannot look up remoting session ID a02f-zcx09c-fn7b8v1n-1-fn7b8wpd-n
2008-11-06 15:07:08,320 WARN [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] A problem has been detected with the connection to remote client a02f-zcx09c-fn7b8v1n-1-fn7b8wpd-n, jmsClientID=null. It is possible the client has exited without closing its connection(s) or the network has failed. All connection resources corresponding to that client process will now be removed.

My last successful onMessage logs this:

2008-11-06 15:07:08,132 [@8f8acd0].onMessage() + JBossConnection->ConnectionDelegate[1046322576, ID=tul2-9tw8b7nf-1-18ofs1nf-rplxnw-f20a, SID=0]

I notice that the server log reports that it is "clearing up state for connection ConnectionEndpoint[[tul2-9tw8b7nf-1-18ofs1nf-rplxnw-f20a]", which seems to match the identifier on my logged onMessage connection, but it does not report a problem with that connection.


To give a little more background info, the remote client is pushing a relatively large number of messages (around 20,000) across a VPN to this server ; the listener is on the same machine as the server but running in a separate Java process under Jetty. the messages are text messages, sometimes up to 1Mb, but not always.

Let me know if I can provide more info. I'm going to struggle to produce a test case, but if you can give me some hints as to where I should be looking for the cause of this I would be grateful. As I say, I'm as sure as I can be that I'm closing all my sessions and connections (apart from the listener one) as soon as I've finished with them, I'm not using my sessions or connections across threads, I'm at a loss as to where to go from here.

Thanks in advance for any pointers,

Regards,

Bob

[ataylor]

If you say you're closing all the connections and you think the vpn is quite stable then the clients being disconnected could be caused by something else. I know remoting has some ping settings that might be affecting things.You could try changing some of these

[bob_walker99]

Thanks Andy,

Could you elaborate a little please? I assume you are talking about the values set in remoting-bisocket-service.xml?

The documentation warns quite emphatically about changing values in that file:

http://www.redhat.com/docs/en-US/JBoss_Enterprise_Application_Platform/4.3.0.cp02/html/JBoss_Messaging_User_Guide/conf.connector.html

If you could give me a little guidance as to what you are thinking may be the problem, and in what way I might change the values I'd appreciate it.

Regards,

Bob

[timfox]

Have you tried a more recent release? (These are available in SVN but not binary).

Or you could wait for a week or so for the next binary release.

We've fixed a lot of stuff and a lot of stuff has been fixed in remoting since the release you're using.

[bob_walker99]

Hi Folks,

You may have seen from my other thread, but I upgraded to 5.0.0/1.4.1 finally.

I'm still having issues, although it's a definite improvement. I'm now getting notification on my ExceptionListener, which is at least giving me the opportunity to recover, but I'm none the wiser as to what the cause is.


Client log when this happens:

 2008-12-15 06:32:54,888 ExceptionHandler caught: Failure on underlying remoting connection
 javax.jms.JMSException: Failure on underlying remoting connection
 at org.jboss.jms.client.remoting.ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:102)
 at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:633)

Corresponding server log:

 2008-12-15 06:32:54,897 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkerThread#2[10.0.2.15:10516]) unregistered connection ConnectionEndpoint[j141-ukulkqof-1-0pp05nof-n0uuo5-f20a] with remoting session ID ...-foqklucl-11br
2008-12-15 06:32:54,899 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkerThread#6[10.0.2.15:19102]) removing callback handler ServerInvokerCallbackHandler[a02f-8lsaer-fonms7bi-1-foqklucl-11br+a02f-8lsaer-fonms7bi-1-foqkluhw-11bu]
2008-12-15 06:32:54,899 DEBUG [org.jboss.remoting.InvokerRegistry] (WorkerThread#6[10.0.2.15:19102]) removed SocketClientInvoker[1308c6c9, bisocket://10.0.2.15:779745218] from registry
2008-12-15 06:32:54,900 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#6[10.0.2.15:19102]) SocketClientInvoker[1308c6c9, bisocket://10.0.2.15:779745218] disconnecting ...
2008-12-15 06:32:54,928 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkerThread#4[10.0.2.15:10519]) Session id for callback handler is a02f-8lsaer-fonms7bi-1-foqr1fun-11d2+a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5
2008-12-15 06:32:54,928 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] (WorkerThread#4[10.0.2.15:10519]) ServerInvokerCallbackHandler[a02f-8lsaer-fonms7bi-1-foqr1fun-11d2+a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5] using callbackTimeout value 10000
2008-12-15 06:32:54,928 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkerThread#4[10.0.2.15:10519]) DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[shikotsu:4457]
2008-12-15 06:32:54,928 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] (WorkerThread#4[10.0.2.15:10519]) DefaultCallbackErrorHandler[SocketServerInvoker[shikotsu:4457]] setting callback handler to ServerInvokerCallbackHandler[a02f-8lsaer-fonms7bi-1-foqr1fun-11d2+a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5]
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting maxPoolSize to 1
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting shouldCheckConnection to false
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting timeout to 10000
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] constructed
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting maxPoolSize to 1
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting shouldCheckConnection to false
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] setting timeout to 10000
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] :registered a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5 -> SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058]
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) Setting ping frequency to: 214748364
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] connecting
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) got control socket( a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5): Socket[addr=/10.0.2.15,port=11022,localport=25572]
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (WorkerThread#4[10.0.2.15:10519]) Creating semaphore with size 1
2008-12-15 06:32:54,935 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] (WorkerThread#4[10.0.2.15:10519]) SocketClientInvoker[2f3a842b, bisocket://10.0.2.15:543833058] connected
2008-12-15 06:32:54,935 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkerThread#4[10.0.2.15:10519]) adding callback handler ServerInvokerCallbackHandler[a02f-8lsaer-fonms7bi-1-foqr1fun-11d2+a02f-8lsaer-fonms7bi-1-foqr1fuv-11d5]
2008-12-15 06:32:54,936 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] (WorkerThread#2[10.0.2.15:10516]) found calllback handler for remoting session ...-foqr1fun-11d2 UID=a02f-8lsaer-fonms7bi-1-foqr1fun-11d2
2008-12-15 06:32:54,936 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] (WorkerThread#2[10.0.2.15:10516]) registered connection ConnectionEndpoint[q241-cvf1rqof-1-0pp05nof-n0uuo5-f20a] as ...-foqr1fun-11d2
2008-12-15 06:32:54,937 DEBUG [org.jboss.jms.server.jbosssx.JBossASSecurityMetadataStore] (WorkerThread#2[10.0.2.15:10516]) No SecurityMetadadata was available for SHIKTrackback, using default security config

I don't know if this is related or not, but I'm still seeing

"A problem has been detected with the connection to remote client..."

messages, and additionally several of these:

Asked to terminate invoker lease for client session id a02f-8lsaer-fonms7bi-1-fonms878-6, but lease for this id could not be found.: {}

Is this sufficient information to aid in a diagnosis?

Let me know if I can help more.

All the best,

Bob

[clebert.suconic]

"A problem has been detected with the connection to remote client..."

This is just saying your client died and pending ACKs are being returned to the queue.

Is there a way you can replicate this?

[bob_walker99]

Hi Clebert,

Not easily, no - the setup is quite complex and when I've tried in the past it works fine on a local dev machine. Would turning on trace logging in JBAS be of any assistance?

Thanks,

Bob

[clebert.suconic]

You sure there isn't anything on the production system, like firewals, rotten misconfigured routers / switches.. or anything like that?

I think you would get more info from tracing on orb.jboss.remoting tracing (since it looks a remoting/network issue).

You may try org.jboss.messaging / org.jboss.jms as well.

[bob_walker99]

Hi Clebert,

I've managed to set up a similar environment locally, and I'm seeing similar, if not identical, behaviour here. (to clarify: I'm on a Windows XP client here, so the OS is different from my server that I'm having trouble with, but I believe all the other components: JVM version, jboss versions, my code versions, are the same).

I get this in my server log coinciding with the exception received by my client listener:

2008-12-23 13:11:41,142 ERROR [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#5[192.168.11.9:4788]) WorkerThread#5[192.168.11.9:4788] exception occurred during first invocation
java.io.EOFException
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:691)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:522)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:230)

Additionally, I see this immediately after in my stdout log:

INFO | jvm 1 | 2008/12/23 13:11:41 | 13:11:41,220 WARN [ServerInvoker] Asked to terminate invoker lease for client session id 5c4ob9-6pgfut-fp2kgtux-1-fp2kgwqn-6, but lease for this id could not be found.: {5c4ob9-2tedlu-fp2kipht-1-fp2kisdj-6=org.jboss.remoting.Lease@1854254}

All the JMS communication in my local environment is local, no other machines are involved.

Let me know if I can provide any more info.

Regards,

Bob