4 Replies Latest reply on Oct 1, 2009 8:04 AM by enriqueam

No ping on secondaryBindPort

enriqueam Sep 30, 2009 10:21 AM

Hello there.

I've duplicated this post here from the Messaging forum (http://www.jboss.org/index.html?module=bb&op=viewtopic&t=161838) in case it fits better in this one.

We are running Jboss AS 4.2.3.GA with JBoss Messaging 1.4.4.GA on one box behind a firewall, and we are connecting to one of the topics in the server using a stand alone client running on a different box.

In remoting-bisocket-service.xml we have configured the secondaryBindPort to 4458. This port and the primary port 4457 are open in the firewall, but with a configured timeout of 1 hour.

The problem we are experiencing is that if no message is sent within that timeout window, the firewall does not close port 4457 because of the ping sent from client to server. However, there is no ping on the secondary port and the most worrying thing is that, once the firewall closes 4458 because of the timeout, the problem is logged by jboss remoting in the client with DEBUG level, but JBoss Messaging is NOT notified of this exception. This prevents any further messages posted on the topic to be forwarded to the client, while the client sits there happily thinking that everything is OK.

Summing this up, the problem is that, on one hand, when the secondary bind port times out at the firewall, JBM is not notified, and on the other, there is no ping from server to client that could prevent this from happening.

Any ideas?
Thank you in advance.

1. Re: No ping on secondaryBindPort

enriqueam Sep 30, 2009 11:24 AM (in response to enriqueam)

Just to give a bit of more information, once the port TCP 4458 times out at the firewall and a new message comes in, this is what we get in the trace file

762021 [Timer-1] TRACE org.jboss.remoting.MicroRemoteClientInvoker - SocketClientInvoker[a89ce3, bisocket://192.168.6.1:4457] received InvocationResponse so going to return response's return value of true

762021 [Timer-1] TRACE org.jboss.remoting.ConnectionValidator - ConnectionValidator got successful ping using SocketClientInvoker[a89ce3, bisocket://192.168.6.1:4457]
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - read version 22 from input stream
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - blocking to read invocation from unmarshaller
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Reading
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Stream is already DataInputStream :)
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Created packet ClientDelivery[null]
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Reading packet
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Read packet
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.jms.wireformat.JMSWireFormat - Returning payload: InvocationRequest[127a20c, CALLBACK, OnewayInvocation[InternalInvocation[fff2a2]]]
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - read InvocationRequest[127a20c, CALLBACK, OnewayInvocation[InternalInvocation[fff2a2]]] from unmarshaller
770831 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - about to call SocketServerInvoker[UNINITIALIZED].invoke()
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] received OnewayInvocation[InternalInvocation[fff2a2]]
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - reusing oneway thread pool
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] placing InvocationRequest[127a20c, CALLBACK, InternalInvocation[fff2a2]] in onewayThreadPool
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] received InternalInvocation[fff2a2]
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - handling InternalInvocation where method name = handleCallback
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - ServerInvoker (SocketServerInvoker[UNINITIALIZED]) is being asked to deliver callback on client callback handler with session id of null.
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.ServerInvoker - SocketServerInvoker[UNINITIALIZED] successfully dispatched invocation, returning null from subsystem 'CALLBACK' to client null
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - SocketServerInvoker[UNINITIALIZED].invoke() returned null
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - oneway request, writing no reply on the wire
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - preparing to process next invocation invocation
770832 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - blocking to read version from input stream
770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - org.jboss.jms.client.container.ClientConsumer$HandleMessageRunnable@1927ba1 receiving message delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2 from the remoting layer
770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - org.jboss.jms.client.container.ClientConsumer$HandleMessageRunnable@1927ba1 added message(s) to the buffer are now 1 messages
770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Receiver thread:null listener:EventHandler@8ae45a listenerRunning:false sessionExecutor:org.jboss.messaging.util.OrderedExecutorFactory$ChildExecutor@19646fd
770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - ClientConsumer[8-21b4780g-1-0fi3780g-82997k-110j3] scheduled a new ListenerRunner
770832 [Thread-8] TRACE org.jboss.jms.client.container.SessionAspect - SessionAspect[1b48392] added Delivery[2, delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2] to session state
770832 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - calling listener's onMessage(delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2)

OUR EventHandler.OnMessage() is called

770834 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - SocketException received. This is likely due to client disconnecting and resetting connection.
java.net.SocketException: Connection reset
 at java.net.SocketInputStream.read(SocketInputStream.java:168)
 at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
 at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
 at java.io.FilterInputStream.read(FilterInputStream.java:66)
 at org.jboss.remoting.transport.socket.ServerThread.readVersion(ServerThread.java:879)
 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:546)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:421)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:174)

770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - listener's onMessage() finished
770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Calling postDeliver
770834 [WorkerThread#0[192.168.6.1:4458]] DEBUG org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] closing socketWrapper: ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387]
770835 [Thread-8] TRACE org.jboss.jms.client.container.SessionAspect - SessionAspect[1b48392] auto acknowledging delivery Delivery[2, delegator->JBossMessage[20550829339557890]:PERSISTENT, deliveryId=2]
770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Called postDeliver
770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Called callonMessage
770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - no more messages in buffer, marking listener as not running
770835 [Thread-8] TRACE org.jboss.jms.client.container.ClientConsumer - Exiting run()
770835 [WorkerThread#0[192.168.6.1:4458]] DEBUG org.jboss.jms.server.remoting.ServerSocketWrapper - cannot write CLOSING byte
java.net.SocketException: Broken pipe
 at java.net.SocketOutputStream.socketWrite0(Native Method)
 at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
 at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
 at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
 at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
 at java.io.DataOutputStream.flush(DataOutputStream.java:106)
 at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:521)
 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:174)
770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.SocketWrapper - ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387] closing socket
770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.SocketWrapper - ServerSocketWrapper[Socket[addr=/192.168.6.1,port=4458,localport=41721].14a9387] closed socket
770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] removing itself from clientpool and going to threadpool
770835 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - WorkerThread#0[192.168.6.1:4458] begins to wait
771992 [Timer-0] TRACE org.jboss.remoting.LeasePinger - LeasePinger[5c4o62-sgual5-g08745nr-1-g08746fe-7:SocketClientInvoker[1dc0e7a, bisocket://192.168.6.1:4457](5c4o62-sgual5-g08745nr-1-g08746f9-6)] sending ping to server. Currently managing lease for following clients:
 5c4o62-sgual5-g08745nr-1-g08746ey-4

771992 [Timer-0] TRACE org.jboss.remoting.MicroRemoteClientInvoker - SocketClientInvoker[1dc0e7a, bisocket://192.168.6.1:4457](1) invoking InvocationRequest[1f4e1c6, $PING$]

So after the problem is detected in ServerThread and SocketWrapper has closed the socket, I can see that the ServerThread removes itself from the client pool, notifies it and then it waits (as shown in the last bold line in the trace). What it seems is that ServerThread is never notified because I NEVER get the trace

 WorkerThread#0[192.168.6.1:4458] woke up after wait

as specified in the source code:

while (true)
 {
 try
 {
 if(trace) { log.trace(this + " begins to wait"); }

 wait();

 if(trace) { log.trace(this + " woke up after wait"); }

 break;
 }
 catch (InterruptedException e)
 {
 if (shutdown)
 {
 invoker = null;
 return; // exit thread
 }
 }
 }

Hope it helps.

2. Re: No ping on secondaryBindPort

ron_sigal Sep 30, 2009 7:53 PM (in response to enriqueam)
What you want to do turn on the following parameters in remoting-bisocket-service.xml:



(taken from the recent JBossMessaging release 1.4.0.SP3_CP09), upgrade to Remoting release 2.2.3.SP1 in which the "generalizeSocketException" parameter is introduced, and (possibly - I'm not sure if it's necessary) upgrade JBossMessaging. That should work around the firewall killing idle connections. See JIRA issue JBMESSAGING-1733 "Update settings in remoting-bisocket-service.xml" at https://jira.jboss.org/jira/browse/JBMESSAGING-1733.
Actions
3. Re: No ping on secondaryBindPort

enriqueam Oct 1, 2009 6:25 AM (in response to enriqueam)
Hello Ron,

Thank you for your quick response!

I have downloaded Remoting release 2.2.3.SP1 and replace the existing one in my standalone client and in JBoss As 4.2.3.GA server's libs (in the server configuration for JBoss Messaging 1.4.4.GA)

I have configured remoting-bisocket-service.xml with the attribute values you suggest and have also added the attribute

<attribute name="DisableRemotingChecks">true</attribute>

to connection-factories-service.xml to make sure Messaging accepts the changes in those immutable attributes.

Still no luck. The firewall does not timeout primary port 4457 because there is a ping between client and server. However, the ServerThread running on the client blocks on the secondary bind port, fixed to value 4458, to read the version, as shown in trace line

56411 [WorkerThread#0[192.168.6.1:4458]] TRACE org.jboss.remoting.transport.socket.ServerThread - blocking to read version from input stream

The problem is that if no message is sent, the firewall times out that port and not 4457. Upon a new message is posted on the topic after the port 4458 has timed out at the firewall, the messages is received by the client and then the client and server detects a problem on port 4458. However, the client does not scale the exception to the Messaging ExceptionListener. Instead, it logs out the exception, and just keeps pinging the server on port 4457, which completes successfully every time. As I said, the ServerThread working on port 4458 gets stuck on a call to wait().

From that point on, when a new message is posted on the queue, the client does not receive it.

Should Remoting be informing JBM of the problem if I'm using generalizeSockeException?
Actions
4. Re: No ping on secondaryBindPort

enriqueam Oct 1, 2009 8:04 AM (in response to enriqueam)

Hello Ron,

Please ignore my last post. Ping is sent on that port and firewall does not time it out.

Thank you for help!
Actions

Go to original post