-
Support Patch
-
Resolution: Obsolete
-
Major
-
None
-
7.0.9.CR1, 7.0.9.GA
-
None
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.