Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-14726

[GSS](7.0.9 patch) Standalone EJB Client hangs intermittently during SSL handshake

    XMLWordPrintable

Details

    • Support Patch
    • Resolution: Obsolete
    • Major
    • None
    • 7.0.9.CR1, 7.0.9.GA
    • EJB
    • None

    Description

      Customer is seeing intermittent timeout issues when calling EJBs on EAP 7.0.9 using SSL.

      The client side logging shows this warning:

      2018-04-12 11:14:29,931+1000 WARN [org.jboss.ejb.client.remoting.ConfigBasedEJBClientContextSelector] (main) [-] Could not register a EJB receiver for connection to usydasu12459.server:8641
      java.lang.RuntimeException: Operation failed with status WAITING
      at org.jboss.ejb.client.remoting.IoFutureHelper.get(IoFutureHelper.java:94)
      at org.jboss.ejb.client.remoting.ConnectionPool.getConnection(ConnectionPool.java:80)
      at org.jboss.ejb.client.remoting.RemotingConnectionManager.getConnection(RemotingConnectionManager.java:51)
      at org.jboss.ejb.client.remoting.ConfigBasedEJBClientContextSelector.setupEJBReceivers(ConfigBasedEJBClientContextSelector.java:161)
      at org.jboss.ejb.client.remoting.ConfigBasedEJBClientContextSelector.getCurrent(ConfigBasedEJBClientContextSelector.java:118)
      at org.jboss.ejb.client.naming.ejb.EjbNamingContext.createIdentifiableEjbClientContext(EjbNamingContext.java:269)
      ...

      Followed by an EJBCLIENT000025 error.

      On 7.0.4 they were seeing intermittent EJBCLIENT000014: Version handshake not completed for receiver context EJBReceiverContext

      Followed by an EJBCLIENT000025 error.

      The server side logging on 7.0.9 at the time is:

      11:13:38,426 TRACE [org.xnio.nio.selector] (default I/O-18) Beginning select on sun.nio.ch.EPollSelectorImpl@6550822f (with timeout)
      11:13:38,429 TRACE [org.xnio.nio.selector] (default I/O-18) Selected on sun.nio.ch.EPollSelectorImpl@6550822f
      11:13:38,429 TRACE [org.xnio.nio.selector] (default I/O-18) Selected key sun.nio.ch.SelectionKeyImpl@1fc55641 for java.nio.channels.SocketChannel[connected oshut local=/10.97.26.136:8641 remote=/10.138.249.2:65180]
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource org.xnio.nio.NioSocketStreamConnection@af06120
      11:13:38,430 TRACE [org.xnio.nio] (default I/O-18) Cancelling key sun.nio.ch.SelectionKeyImpl@1fc55641 of java.nio.channels.SocketChannel[connected oshut local=/10.97.26.136:8641 remote=/10.138.249.2:65180] (same thread)
      11:13:38,430 TRACE [org.xnio.listener] (default I/O-18) Invoking listener io.undertow.server.AbstractServerConnection$CloseSetter@20073bad on channel io.undertow.protocols.ssl.UndertowSslConnection@302cbd43
      11:13:38,430 DEBUG [io.undertow.request] (default I/O-18) UT005013: An IOException occurred: java.nio.channels.ClosedChannelException
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource org.xnio.nio.NioSocketStreamConnection@af06120
      11:13:38,430 TRACE [org.xnio.listener] (default I/O-18) Invoking listener io.undertow.util.ConnectionUtils$4@6ee7e661 on channel org.xnio.conduits.ConduitStreamSourceChannel@17fae284
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource io.undertow.protocols.ssl.UndertowSslConnection@302cbd43
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource io.undertow.server.protocol.http.HttpServerConnection@4051a6fc
      11:13:38,430 TRACE [org.xnio.nio] (default I/O-18) Running task io.undertow.protocols.ssl.SslConduit$1@2e49cfee
      11:13:38,430 TRACE [org.xnio.listener] (default I/O-18) Invoking listener io.undertow.util.ConnectionUtils$4@6ee7e661 on channel org.xnio.conduits.ConduitStreamSourceChannel@17fae284
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource io.undertow.protocols.ssl.UndertowSslConnection@302cbd43
      11:13:38,430 TRACE [org.xnio.safe-close] (default I/O-18) Closing resource io.undertow.server.protocol.http.HttpServerConnection@4051a6fc
      11:13:38,430 TRACE [org.xnio.nio.selector] (default I/O-18) Beginning select on sun.nio.ch.EPollSelectorImpl@6550822f (with timeout)
      11:13:39,001 TRACE [org.xnio.nio.selector] (default I/O-18) Selected on sun.nio.ch.EPollSelectorImpl@6550822f
      11:13:39,001 TRACE [org.xnio.nio] (default I/O-18) Running task io.undertow.util.DateUtils$2@5d1da991
      11:13:39,001 TRACE [org.xnio.nio.selector] (default I/O-18) Beginning select on sun.nio.ch.EPollSelectorImpl@6550822f (with timeout)
      11:14:29,918 TRACE [org.xnio.nio.selector] (default I/O-18) Selected on sun.nio.ch.EPollSelectorImpl@6550822f
      11:14:29,918 TRACE [org.xnio.nio.selector] (default I/O-18) Selected key sun.nio.ch.SelectionKeyImpl@26144635 for java.nio.channels.SocketChannel[connected local=usydasu12459.macbank/10.97.26.136:8641 remote=/10.97.26.135:42375]
      11:14:29,918 TRACE [org.xnio.listener] (default I/O-18) Invoking listener Delegating channel listener -> Read listener for org.jboss.remoting3.remote.RemotingMessageChannel around org.xnio.channels.AssembledConnectedSslStreamChannel@15c5a59d on channel org.xnio.conduits.ConduitStreamSourceChannel@6599ca7d
      11:14:29,918 TRACE [org.xnio.listener] (default I/O-18) Invoking listener Read listener for org.jboss.remoting3.remote.RemotingMessageChannel around org.xnio.channels.AssembledConnectedSslStreamChannel@15c5a59d on channel org.xnio.channels.AssembledConnectedSslStreamChannel@15c5a59d
      11:14:29,918 TRACE [org.xnio.listener] (default I/O-18) Invoking listener org.jboss.remoting3.remote.RemoteReadListener@61568055 on channel org.jboss.remoting3.remote.RemotingMessageChannel around org.xnio.channels.AssembledConnectedSslStreamChannel@15c5a59d
      11:14:29,918 TRACE [org.xnio.channels.framed] (default I/O-18) Copying message from java.nio.HeapByteBuffer[pos=4 lim=66 cap=8196] into java.nio.DirectByteBuffer[pos=0 lim=8192 cap=8192]
      11:14:29,918 TRACE [org.xnio.nio] (default I/O-18) Running task io.undertow.protocols.ssl.SslConduit$1@3ea44f7a

      Notice the ~1.5 minute delay in EPollSelectorImpl. I believe this thread is waiting for a channel event? but I am not sure what event if it is.

      Attachments

        Activity

          People

            flaviarnn Flavia Rainone
            rhn-support-dstephan David Stephan
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: