4 Replies Latest reply on Apr 15, 2019 12:39 PM by Galder Zamarreño

    Intermittent SocketTimeoutException during GetOperation

    Prateek Kumar Newbie

      Cross posted at distributed caching - Infinispan throwing intermittent SocketTimeoutException during GetOperation - Stack Overflow

       

      Using jboss/infinispan-server:9.4.0.Final (Docker Hub) in standalone server mode with replication, and the clients connect via hotrod.

       

      Here's from our gradle file:

      infinispan_version = "9.4.0.Final"

      ...

      'infinispan': [

      "org.infinispan:infinispan-core:$infinispan_version",

      "org.infinispan:infinispan-client-hotrod:$infinispan_version"

      ],

       

      Here is how each client code (java) connects to the cache over hotrod:

       

      ConfigurationBuilder builder = new ConfigurationBuilder();

      builder.forceReturnValues(false).addServer().host("infinispan_hostname").port(11222);

      BasicCacheContainer manager = new RemoteCacheManager(builder.build(), true);

      BasicCache<Object, Object> ourCache = manager.getCache("OUR_CACHE");

       

      Here's the relevant xml:

       

      <subsystem xmlns="urn:infinispan:server:core:9.3" default-cache-container="local">

                  <cache-container name="local" default-cache="default" statistics="true">       

                     <global-state/>

       

                      <local-cache name="OUR_CACHE">

                                     <expiration lifespan="-1"/>

                                     <locking isolation="SERIALIZABLE" acquire-timeout="30000" concurrency-level="1000" striping="false"/>

                                     <file-store relative-to="cachestore.root" path="server" max-entries="-1" purge="false" passivation="false" preload="true" fetch-state="true"/>

                                     <memory>

                                           <binary size="100000000" eviction="MEMORY"/>

                                     </memory>

                                     </local-cache>

                 </cache-container>

      </subsystem>

       

      Occasionally, we get the following exception at DEBUG level (say after every 30 min), but most of the time it works as expected. It seems to be waiting synchronously at the ourCache.get("key") method till the timeout of 60s.

      However, if we retry the operation immediately afterwards, it works correctly and there's no error. Was hoping someone could please help me understand what is the cause.

       

      2019-03-06 07:15:47,668 ERROR:Error occurred when .."our app data message". : java.net.SocketTimeoutException: GetOperation{OUR_CACHE, key=[B0x033E22742D663039..[37], flags=0} timed out after 60000 ms

      org.infinispan.client.hotrod.exceptions.TransportException: java.net.SocketTimeoutException: GetOperation{OUR_CACHE, key=[B0x033E22742D663039..[37], flags=0} timed out after 60000 ms

      at org.infinispan.client.hotrod.impl.Util.rewrap(Util.java:54) ~[infinispan-client-hotrod-9.4.0.Final.jar:9.4.0.Final]

      at org.infinispan.client.hotrod.impl.Util.await(Util.java:27) ~[infinispan-client-hotrod-9.4.0.Final.jar:9.4.0.Final]

      at org.infinispan.client.hotrod.impl.RemoteCacheImpl.get(RemoteCacheImpl.java:418) ~[infinispan-client-hotrod-9.4.0.Final.jar:9.4.0.Final]

      at ... our app jar's stacktrace

      at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) [servlet-api.jar:?]

      at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [servlet-api.jar:?]

      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [catalina.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.35]

      at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-websocket.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.35]

      at ... our app jar's stacktrace

      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.35]

      at ... our app jar's stacktrace

      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.35]

      at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) [log4j-web-2.10.0.jar:2.10.0]

      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.35]

      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.35]

      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [catalina.jar:8.5.35]

      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:8.5.35]

      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493) [catalina.jar:8.5.35]

      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [catalina.jar:8.5.35]

      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) [catalina.jar:8.5.35]

      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [catalina.jar:8.5.35]

      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [catalina.jar:8.5.35]

      at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800) [tomcat-coyote.jar:8.5.35]

      at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-coyote.jar:8.5.35]

      at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806) [tomcat-coyote.jar:8.5.35]

      at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498) [tomcat-coyote.jar:8.5.35]

      at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:8.5.35]

      at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]

      at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]

      at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.5.35]

      at java.lang.Thread.run(Unknown Source) [?:?]

      Caused by: java.net.SocketTimeoutException: GetOperation{OUR_CACHE, key=[B0x033E22742D663039..[37], flags=0} timed out after 60000 ms

      at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:172) ~[infinispan-client-hotrod-9.4.0.Final.jar:9.4.0.Final]

      at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38) ~[netty-common-4.1.28.Final.jar:4.1.28.Final]

      at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:127) ~[netty-common-4.1.28.Final.jar:4.1.28.Final]

      at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.28.Final.jar:4.1.28.Final]

      at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.28.Final.jar:4.1.28.Final]

      at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:322) ~[netty-transport-native-epoll-4.1.28.Final-linux-x86_64.jar:4.1.28.Final]

      at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.28.Final.jar:4.1.28.Final]

      at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?]

      at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?]

      ... 1 more

       

      Was hoping someone could please advise on what is the root cause, and the potential fix.

      Thanks,

      _Prateek