4 Replies Latest reply on Oct 1, 2009 8:04 AM by Enrique Alonso-Martin

    No ping on secondaryBindPort

    Enrique Alonso-Martin Newbie

      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
          Enrique Alonso-Martin Newbie

          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 Master

            What you want to do turn on the following parameters in remoting-bisocket-service.xml:

             <!--
             <attribute name="numberOfCallRetries" isParam="true">5</attribute>
             <attribute name="pingFrequency" isParam="true">30000</attribute>
             <attribute name="pingWindowFactor" isParam="true">71582</attribute>
             <attribute name="generalizeSocketException" isParam="true">true</attribute>
             -->
            


            (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.

            • 3. Re: No ping on secondaryBindPort
              Enrique Alonso-Martin Newbie

              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?


              • 4. Re: No ping on secondaryBindPort
                Enrique Alonso-Martin Newbie

                Hello Ron,

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

                Thank you for help!