Summary: "SSL read loop detected" during remote EJB call; remote call blocks forever
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.
Logs
What we see in the log file is these two back-to-back errors from the same thread:
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}
And then that same thread gets blocked forever, stuck waiting for the lock at org.wildfly.httpclient.common.WildflyClientInputStream.read(WildflyClientInputStream.java:147)
"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)
Other information:
Java version:
$ 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)
Wildfly server version:
WFLYSRV0049: WildFly Full 19.1.0.Final (WildFly Core 11.1.1.Final) starting
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
- is incorporated by
-
WFLY-16215 Upgrade wildfly-http-ejb-client from 1.1.10.Final to 1.1.11.Final
-
- Closed
-
