2 Replies Latest reply on Mar 20, 2009 10:51 AM by Markus Lutum

    JMS Bridge, Remote Connection Lost

    Markus Lutum Novice

      I already asked a lot in JBM Forum but currently they have not find the issue.

      I use this thread to summarize a short remoting issue. Maybe you guys knows that these stack traces are all about.
      In general I have 2 so called JMS brides deployed on Server X which bridge JMS Messages from Server A to X and the second one X to A.
      So 2 Queues, on each side. the Communication is triggered from X were the bridge is deployed.

      At X I get the Error:

      09:57:05,624 WARN [Bridge] jboss.messaging:name=IncommingBridge_ArcDeSeine,service=Bridge Detected failure on 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:641)
      


      Looking at the debug messages for more Detail I see:
      09:57:02,624 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[null, pingPeriod=2000 ms] connection retries: null
      09:57:02,624 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[SocketClientInvoker[9520f7, sslbisocket://nvc1216:24457], pingPeriod=2000 ms] started
      09:57:02,687 DEBUG [org.jboss.mx.loading.RepositoryClassLoader] Added url: file:/C:/AEOS-IMServer/IMServer/jboss/server/imserver/tmp/aopdynclasses/ucl1109316119710502160/?dynamic=true, to ucl: org.jboss.mx.loading.UnifiedClassLoader3@1ecdec0{ url=null ,addedOrder=13}
      09:57:02,968 INFO [org.jboss.jms.server.bridge.Bridge] jboss.messaging:name=IncommingBridge_ArcDeSeine,service=Bridge Succeeded in connecting to servers
      09:57:05,624 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[SocketClientInvoker[1eebefb, sslbisocket://nvc1217:4457], pingPeriod=2000 ms]'s connections is invalid
      09:57:05,624 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[1eebefb, sslbisocket://nvc1217:4457] from registry
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[1eebefb, sslbisocket://nvc1217:4457] disconnecting ...
      09:57:05,624 WARN [org.jboss.jms.server.bridge.Bridge] jboss.messaging:name=IncommingBridge_ArcDeSeine,service=Bridge Detected failure on 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:641)
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[f9e396[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=nvc1217.nedap.local/10.4.107.217,port=4457,localport=1444]].f9e396] closing
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[1953319[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=nvc1216.nedap.local/10.4.107.216,port=24457,localport=1437]].1953319] closing
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ClientSocketWrapper[4de269[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=nvc1216.nedap.local/10.4.107.216,port=24457,localport=1438]].4de269] closing
      09:57:05,624 DEBUG [org.jboss.remoting.ConnectionValidator] ConnectionValidator[SocketClientInvoker[1eebefb, sslbisocket://nvc1217:4457], pingPeriod=2000 ms] stopped, returning true
      09:57:05,624 DEBUG [org.jboss.remoting.ConnectionValidator] org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask@14b6f24 detected connection failure: stopping LeasePinger
      09:57:05,624 DEBUG [org.jboss.remoting.LeasePinger] LeasePinger[SocketClientInvoker[7edb0f, sslbisocket://nvc1217:4457](a42z60-hxurji-fsimy06l-1-fsin0nkm-4e)] setting disconnect timeout to: -1
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#1[10.4.107.216:1438] closing socketWrapper: ServerSocketWrapper[16dc700[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1438,localport=24457]].16dc700]
      09:57:05,624 DEBUG [org.jboss.jms.server.remoting.ServerSocketWrapper] cannot write CLOSING byte
      java.net.SocketException: Connection closed by remote host
       at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkWrite(Unknown Source)
       at com.sun.net.ssl.internal.ssl.AppOutputStream.write(Unknown Source)
       at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
       at java.io.BufferedOutputStream.flush(Unknown Source)
       at java.io.DataOutputStream.flush(Unknown Source)
       at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:520)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#0[10.4.107.216:1437] closing socketWrapper: ServerSocketWrapper[aa15ea[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1437,localport=24457]].aa15ea]
      09:57:05,624 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[16dc700[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1438,localport=24457]].16dc700] closing
      



      OK now the same issue on the remote node A:
      09:57:03,390 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] Session id for callback handler is a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h
      09:57:03,390 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h] using callbackTimeout value 10000
      09:57:03,390 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[UNITIALIZED] setting server invoker to SocketServerInvoker[0.0.0.0:4457]
      09:57:03,390 DEBUG [org.jboss.remoting.callback.DefaultCallbackErrorHandler] DefaultCallbackErrorHandler[SocketServerInvoker[0.0.0.0:4457]] setting callback handler to ServerInvokerCallbackHandler[a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h]
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting maxPoolSize to 1
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting shouldCheckConnection to false
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting timeout to 10000
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] constructed
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting maxPoolSize to 1
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting shouldCheckConnection to false
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting timeout to 10000
      09:57:03,390 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] :registered a42z60-hxurji-fsimy06l-1-fsin0pbz-4h -> SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524]
      09:57:03,390 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Setting ping frequency to: 214748364
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting maxPoolSize to 1
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting client socket wrapper class name to org.jboss.jms.client.remoting.ClientSocketWrapper
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting shouldCheckConnection to false
      09:57:03,390 DEBUG [org.jboss.remoting.transport.socket.SocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] setting timeout to 10000
      09:57:03,390 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] connecting
      09:57:03,546 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] got control socket( a42z60-hxurji-fsimy06l-1-fsin0pbz-4h): 1c61e31[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1445,localport=10637]]
      09:57:03,546 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Creating semaphore with size 1
      09:57:03,546 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] connected
      09:57:03,546 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] adding callback handler ServerInvokerCallbackHandler[a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h]
      09:57:03,546 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] found calllback handler for remoting session ...-fsin0nkm-4c UID=a42z60-hxurji-fsimy06l-1-fsin0nkm-4c
      09:57:03,546 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] registered connection ConnectionEndpoint[j2-iiq0nisf-1-oziymisf-40lnzg-16z24a] as ...-fsin0nkm-4c
      09:57:03,578 DEBUG [org.jboss.jms.server.security.SecurityMetadataStore] No SecurityMetadadata was available for local_incomingSyncRequests, using default security config
      09:57:06,562 DEBUG [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#4[10.4.107.216:1444] closing socketWrapper: ServerSocketWrapper[1879b5e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1444,localport=4457]].1879b5e]
      09:57:06,562 DEBUG [org.jboss.jms.server.remoting.ServerSocketWrapper] cannot write CLOSING byte
      java.net.SocketException: Connection closed by remote host
       at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkWrite(Unknown Source)
       at com.sun.net.ssl.internal.ssl.AppOutputStream.write(Unknown Source)
       at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
       at java.io.BufferedOutputStream.flush(Unknown Source)
       at java.io.DataOutputStream.flush(Unknown Source)
       at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:520)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
      09:57:06,562 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[1879b5e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1444,localport=4457]].1879b5e] closing
      09:57:07,859 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] from registry
      09:57:07,859 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[676b8d, sslbisocket://10.4.107.216:1292602524] disconnecting ...
      09:57:07,859 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h] shut down
      09:57:07,875 DEBUG [org.jboss.jms.server.connectionmanager.SimpleConnectionManager] unregistered connection ConnectionEndpoint[j2-iiq0nisf-1-oziymisf-40lnzg-16z24a] with remoting session ID ...-fsin0nkm-4c
      09:57:07,875 DEBUG [org.jboss.jms.server.remoting.JMSServerInvocationHandler] removing callback handler ServerInvokerCallbackHandler[a42z60-hxurji-fsimy06l-1-fsin0nkm-4c+a42z60-hxurji-fsimy06l-1-fsin0pbz-4h]
      09:57:07,890 DEBUG [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#6[10.4.107.216:1450] closing socketWrapper: ServerSocketWrapper[1676b1e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1450,localport=4457]].1676b1e]
      09:57:07,890 DEBUG [org.jboss.remoting.transport.socket.ServerThread] WorkerThread#4[10.4.107.216:1449] closing socketWrapper: ServerSocketWrapper[1676b1e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1449,localport=4457]].1676b1e]
      09:57:07,890 DEBUG [org.jboss.jms.server.remoting.ServerSocketWrapper] cannot write CLOSING byte
      java.net.SocketException: Connection closed by remote host
       at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkWrite(Unknown Source)
       at com.sun.net.ssl.internal.ssl.AppOutputStream.write(Unknown Source)
       at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
       at java.io.BufferedOutputStream.flush(Unknown Source)
       at java.io.DataOutputStream.flush(Unknown Source)
       at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:520)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
      09:57:07,890 DEBUG [org.jboss.jms.server.remoting.ServerSocketWrapper] cannot write CLOSING byte
      java.net.SocketException: Connection closed by remote host
       at com.sun.net.ssl.internal.ssl.SSLSocketImpl.checkWrite(Unknown Source)
       at com.sun.net.ssl.internal.ssl.AppOutputStream.write(Unknown Source)
       at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
       at java.io.BufferedOutputStream.flush(Unknown Source)
       at java.io.DataOutputStream.flush(Unknown Source)
       at org.jboss.jms.server.remoting.ServerSocketWrapper.close(ServerSocketWrapper.java:74)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:520)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
      09:57:07,890 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[1676b1e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1450,localport=4457]].1676b1e] closing
      09:57:07,890 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] ServerSocketWrapper[1676b1e[SSL_RSA_WITH_RC4_128_MD5: Socket[addr=/10.4.107.216,port=1449,localport=4457]].1676b1e] closing
      



      Can anyone explain why this happens?
      It happen every few seconds and it seems to be dependent on which system here in our network it is started. On our productive testsystem it happens every 5 seconds. So the bridge started, crashed, waiting for retry, connects again and crashed again after a few second,.....
      On other system this error occurs only each 10 minutes but on all it happens. It happens more often if I add more bridges on X to the other 6 Nodes.
      I have tried forceRemote on X and all other nodes with no effect.
      I have tried the 222SP11 instead of SP11brew this morning with no effect.

      I am using the following invoker configuration:
      <mbean code="org.jboss.remoting.transport.Connector" name="jboss.messaging:service=Connector,transport=sslbisocket" display-name="SSL Bisocket Transport Connector">
      <attribute name="Configuration">
      <config>
      <invoker transport="sslbisocket">
      <attribute name="marshaller" isParam="true">org.jboss.jms.wireformat.JMSWireFormat</attribute>
      <attribute name="unmarshaller" isParam="true">org.jboss.jms.wireformat.JMSWireFormat</attribute>
      <attribute name="dataType" isParam="true">jms</attribute>
      <attribute name="socket.check_connection" isParam="true">false</attribute>
      <attribute name="serverBindAddress">${jboss.bind.address}</attribute>
      <attribute name="serverBindPort">44457</attribute>
      <attribute name="clientSocketClass" isParam="true">org.jboss.jms.client.remoting.ClientSocketWrapper</attribute>
      <attribute name="serverSocketClass">org.jboss.jms.server.remoting.ServerSocketWrapper</attribute>
      <attribute name="serverSocketFactory">jboss.messaging:service=ServerSocketFactory,type=SSL</attribute>
      <attribute name="numberOfCallRetries" isParam="true">1</attribute>
      <attribute name="pingFrequency" isParam="true">214748364</attribute>
      <attribute name="pingWindowFactor" isParam="true">10</attribute>
      <attribute name="onewayThreadPool">org.jboss.jms.server.remoting.DirectThreadPool</attribute>
      <attribute name="stopLeaseOnFailure" isParam="true">true</attribute>
      <attribute name="clientLeasePeriod" isParam="true">10000</attribute>
      <attribute name="timeout" isParam="true">0</attribute>
      <attribute name="numberOfRetries" isParam="true">10</attribute>
      <attribute name="JBM_clientMaxPoolSize" isParam="true">200</attribute>
      <attribute name="callbackTimeout">10000</attribute>
      <attribute name="force_remote" isParam="true">true</attribute>
      </invoker>
      



      ANY IDEAS? Maybe I have to increase some parameters?

        • 1. Re: JMS Bridge, Remote Connection Lost
          Markus Lutum Novice

          It seems that we have fixed this issue but I don't know why....

          After I added the hostnames and ipadresses of all servers and nodes to the host file of the root server X I have not seen the error anymore.

          The question is why is the DNS lookup the problem. Is it to slow? Can you see anything from the logs?

          • 2. Re: JMS Bridge, Remote Connection Lost
            Markus Lutum Novice

            Hi!

            I was to fast. With the definition of ipadresses and names in the windows hosts file it does not happen 3-5 seconds after the cannection is established but it happens from time to time.

            Can I configure this check more robust. Means check and if it seams to be an error check once again after a time before really decide that the remote site is not there anymore....?

            Greets