[jboss-jira] [JBoss JIRA] (WFLY-13607) "SSL read loop detected" during remote EJB call; remote call blocks forever

[Kyle MacLeod (Jira)]

Kyle MacLeod created WFLY-13607:
-----------------------------------

             Summary: "SSL read loop detected" during remote EJB call; remote call blocks forever
                 Key: WFLY-13607
                 URL: https://issues.redhat.com/browse/WFLY-13607
             Project: WildFly
          Issue Type: Bug
          Components: Web (Undertow)
    Affects Versions: 19.1.0.Final
            Reporter: Kyle MacLeod
            Assignee: Flavia Rainone


Summary: "SSL read loop detected" during remote EJB call; remote call blocks forever

h3. Problem Description

We are transferring data over an EJB request. The data returned from the EJB call ranges from 1-4MB in size.
During one of these transfers, we are hitting some sort of race/timing condition which results in a "UT005076: SSL read loop detected" ERROR log. 
After the read loop detected log, the remote call blocks forever. Something is broken with the cleanup.
Unfortunately, this is only happening on some of our servers. It's difficult to reproduce - and I don't have a test case for it.

Other notes:

* The issue is seen on the client side. The client is a java standalone client. All are running in docker containers. The issue is seen both running under docker-compose and under kubernetes.
* The issue is seen with the 19.0.1.Final wildfly-client-all jar. It is NOT seen when we revert back to 18.0.0.Final wildfly-client-all jar.* It looks to me like an issue in either SslConduit or WildflyClientInputStream. There were commits post-18.0.0.Final which hit code in this area.

h3. Logs

What we see in the log file is these two back-to-back errors from the same thread:

{code:language=|borderStyle=solid|theme=RDark|linenumbers=true|collapse=false}
2020-06-09 15:04:30,378 ERROR [io.undertow.request] [AgentServerModelRegistrationStateChangeNotification-pool-21-thread-1] UT005076: SSL read loop detected. This should not happen, please report this to the Undertow developers. Current state SslConduit{state=4, outstandingTasks=0, wrappedData=null, dataToUnwrap=null, unwrappedData=null}
2020-06-09 15:04:30,552 ERROR [io.undertow.request] [AgentServerModelRegistrationStateChangeNotification-pool-21-thread-1] UT005076: SSL read loop detected. This should not happen, please report this to the Undertow developers. Current state SslConduit{state=30692, outstandingTasks=0, wrappedData=null, dataToUnwrap=null, unwrappedData=null}
{code}

And then that same thread gets blocked forever, stuck waiting for the lock at org.wildfly.httpclient.common.WildflyClientInputStream.read(WildflyClientInputStream.java:147)

{code:language=|borderStyle=solid|theme=RDark|linenumbers=true|collapse=true}
"AgentServerModelRegistrationStateChangeNotification-pool-21-thread-1" #40 prio=5 os_prio=0 tid=0x00007f5cac9f8000 nid=0x47 in Object.wait() [0x00007f5c8b1d5000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at org.wildfly.httpclient.common.WildflyClientInputStream.read(WildflyClientInputStream.java:147)
    - locked <0x00000000ed9475a8> (a java.lang.Object)
    at java.io.FilterInputStream.read(FilterInputStream.java:133)
    at org.jboss.marshalling.SimpleDataInput.readFully(SimpleDataInput.java:175)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadByteArray(RiverUnmarshaller.java:1622)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadArray(RiverUnmarshaller.java:1690)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:355)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:231)
    at org.jboss.marshalling.river.RiverUnmarshaller.readFields(RiverUnmarshaller.java:1864)
    at org.jboss.marshalling.river.RiverUnmarshaller.doInitSerializable(RiverUnmarshaller.java:1778)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1406)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:283)
    at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:216)
    at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:41)
    at org.wildfly.httpclient.ejb.HttpEJBReceiver$2.getResult(HttpEJBReceiver.java:207)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:613)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.protocol.remote.RemotingEJBClientInterceptor.handleInvocationResult(RemotingEJBClientInterceptor.java:57)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:615)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.client.TransactionPostDiscoveryInterceptor.handleInvocationResult(TransactionPostDiscoveryInterceptor.java:148)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:615)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.client.DiscoveryEJBClientInterceptor.handleInvocationResult(DiscoveryEJBClientInterceptor.java:137)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:615)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.client.NamingEJBClientInterceptor.handleInvocationResult(NamingEJBClientInterceptor.java:87)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:615)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.client.TransactionInterceptor.handleInvocationResult(TransactionInterceptor.java:212)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:615)
    at org.jboss.ejb.client.EJBClientInvocationContext.getResult(EJBClientInvocationContext.java:544)
    at org.jboss.ejb.client.EJBClientInvocationContext.awaitResponse(EJBClientInvocationContext.java:986)
    at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:191)
    at org.jboss.ejb.client.EJBInvocationHandler.invoke(EJBInvocationHandler.java:125)
    at com.sun.proxy.$Proxy24.getAdapterArchive(Unknown Source)
    at com.nakina.agent.application.adaptermanager.internal.dataservice.AgentRemoteAdapterArchiveRepositoryImpl$FakeRemoteIterator.next(AgentRemoteAdapterArchiveRepositoryImpl.java:226)
    at com.nakina.agent.application.adaptermanager.internal.dataservice.AgentRemoteAdapterArchiveRepositoryImpl$FakeRemoteIterator.next(AgentRemoteAdapterArchiveRepositoryImpl.java:189)
    at com.nakina.adaptermanager.AdapterManagerImpl.addToLocalRepository(AdapterManagerImpl.java:506)
    at com.nakina.adaptermanager.AdapterManagerImpl.synchronizeLocalRepository(AdapterManagerImpl.java:617)
    at com.nakina.adaptermanager.AdapterManagerImpl.initialize(AdapterManagerImpl.java:373)
    at com.nakina.agent.application.adaptermanager.internal.dataservice.AdapterManagerFactoryImpl.getAdapterManager(AdapterManagerFactoryImpl.java:66)
    - locked <0x00000000c07fa748> (a java.lang.Object)
    at com.nakina.agent.application.adaptermanager.internal.action.StartAdapterManagerAction.execute(StartAdapterManagerAction.java:54)
    at com.nakina.oss.server.af.app.action.DefaultActionManager.executeRequest(DefaultActionManager.java:176)
    ...
    at com.nakina.oss.server.af.app.message.DefaultMessageReceiver.execute(DefaultMessageReceiver.java:65)
    at com.nakina.oss.server.af.app.action.DefaultActionManager.executeRequest(DefaultActionManager.java:176)
    at com.nakina.oss.server.af.app.message.DefaultMessageReceiver.onMessage(DefaultMessageReceiver.java:154)
    at com.nakina.oss.server.af.app.impl.LocalMessageSenderImpl$SenderRunnable.run(LocalMessageSenderImpl.java:189)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
{code}

h3. Other information:

Java version:

{code:language=|borderStyle=solid|theme=RDark|linenumbers=true|collapse=false}
$ java -version
openjdk version "1.8.0_252"
OpenJDK Runtime Environment (build 1.8.0_252-b09)
OpenJDK 64-Bit Server VM (build 25.252-b09, mixed mode)
{code}

Wildfly server version:

{code:language=|borderStyle=solid|theme=RDark|linenumbers=true|collapse=false}
WFLYSRV0049: WildFly Full 19.1.0.Final (WildFly Core 11.1.1.Final) starting
{code}

wildfly-client-all version:

* 19.0.1.Final wildfly-client-all jar. 
* NOT seen when we revert back to 18.0.0.Final wildfly-client-all jar





--
This message was sent by Atlassian Jira
(v7.13.8#713008)