]
Victor Langelo commented on WFLY-13607:
---------------------------------------
I haven't been able to find an isolated reproducible case. The best test I have is a
series of ejb invocations returning both small and large results in our test system when
it's running in a datacenter behind a nginx proxy server. All invocations are
via [https://hostname/wildfly-services/.|https://hostname/wildfly-services/app/] It only
happens occasionally but on the same invocation in the sequence. I haven't seen it
when the WildFly server is accessed directly or when it's on the local network with or
without the nginx proxy. We also tested with the server behind a WildFly reverse proxy and
haven't been able to reproduce there either. However, the WildFly reverse proxy
configuration isn't working with client certificate authentication even though the
certificate is being passed in the header to the back end server just like in the nginx
setup. So it may not be exactly the same.
The best I can offer at the moment is a copy of our client application, credentials to our
test server and the sequence of actions I take to reproduce.
"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
Priority: Major
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