CachedPlcConnectionManager should drop a connection after an amount of seconds of inactivity ?

[foxpluto]

I got a problem using the CachedPlcConnectionManager which raise a question, let me describe the problem first:

Problem I found

I start using the new CachedPlcConnectionManager of the 0.11.0. I wrote some code like:

    try (var plcConnection = cachedPlcConnectionManager.getConnection(plcConnectionString)) {
        if (plcConnection.isConnected()) {
            // Do stuff
        } else  {
            log.error("PLC is not connected");
        }
    } catch (Exception e){
        log.error("Generic, and very BAD, exception in reading DataBlock", e);
        throw e;
    }

And I got some nice read and write.... but I have a problem. If don't get any connection from the CachedPlcConnectionManager after more or less 20 seconds I got:

[WARN ] 18:16:10.961 io.netty.channel.DefaultChannelPipeline.onUnhandledInboundException() - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
 io.netty.handler.timeout.ReadTimeoutException: null
[INFO ] 18:16:10.990 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.channelUnregistered() - io.netty.channel.embedded.EmbeddedEventLoop@2432de5e

And if I try to read again I got an exception:

[DEBUG] 18:16:48.540 org.apache.plc4x.java.utils.cache.CachedPlcConnectionManager.getConnection() - Reusing exising connection
[INFO ] 18:16:48.541 it.fox.chronos.plc.fetchers.FetcherImpl.readData() - PLC Connection Info: org.apache.plc4x.java.s7.readwrite.connection.S7HDefaultNettyPlcConnection@685ab2a6
[DEBUG] 18:16:48.541 it.fox.chronos.plc.fetchers.FetcherImpl.lambda$4() - Reading request with: %DB300:1360.0:STRING(10) %DB300:1360.0:STRING(10)
[INFO ] 18:16:48.546 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.userEventTriggered() - 18:16:48.546284  userEventTriggered: S7HMuxImpl#0 Event: org.apache.plc4x.java.spi.events.DisconnectEvent@7718111b
[INFO ] 18:16:48.546 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.userEventTriggered() - DisconnectEvent
[INFO ] 18:16:48.552 org.apache.plc4x.java.transport.tcp.TcpChannelFactory.configureBootstrap() - Configuring Bootstrap with Configuration{local-rack=1, local-slot=1, local-tsap=0, remote-rack=0, remote-slot=0, remote-rack2=0, remote-slot2=0, remote-tsap=0, pduSize=1024, maxAmqCaller=8, maxAmqCallee=8, controllerType=null, readTimeOut=8, ping=false, pingTime=-1, retryTime=4}
[INFO ] 18:16:48.636 org.apache.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic.onConnect() - S7 Driver running in ACTIVE mode.
[INFO ] 18:16:48.636 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.userEventTriggered() - 18:16:48.636969  userEventTriggered: S7HMuxImpl#0 Event: org.apache.plc4x.java.spi.events.ConnectEvent@5562d74e
[INFO ] 18:16:48.637 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.userEventTriggered() - java.util.NoSuchElementException: watchdog
[INFO ] 18:16:49.150 org.apache.plc4x.java.s7.readwrite.connection.S7HMuxImpl.userEventTriggered() - 18:16:49.150572  userEventTriggered: S7HMuxImpl#0 Event: org.apache.plc4x.java.spi.events.ConnectedEvent@4f23f805
[ERROR] 18:16:49.151 it.fox.chronos.plc.fetchers.FetcherImpl.readData() - Execution exception in reading DataBlock
 java.util.concurrent.ExecutionException: org.apache.plc4x.java.api.exceptions.PlcRuntimeException: Disconnected
        at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
        at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
        at it.fox.chronos.plc.fetchers.FetcherImpl.readData(FetcherImpl.java:226) [main/:?]
        at it.fox.chronos.api.PlcReadApiImpl.getMemoryRaw(PlcReadApiImpl.java:39) [main/:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) [spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:196) [spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) [spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.validation.beanvalidation.MethodValidationInterceptor.invoke(MethodValidationInterceptor.java:141) [spring-context-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184) [spring-aop-6.0.11.jar:6.0.11]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:244) [spring-aop-6.0.11.jar:6.0.11]
        at jdk.proxy4.$Proxy163.getMemoryRaw(Unknown Source) [?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:884) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1081) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:974) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1011) [spring-webmvc-6.0.11.jar:6.0.11]
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:903) [spring-webmvc-6.0.11.jar:6.0.11]
        at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:564) [tomcat-embed-core-10.1.11.jar:6.0]
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) [spring-webmvc-6.0.11.jar:6.0.11]
        at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) [tomcat-embed-core-10.1.11.jar:6.0]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) [tomcat-embed-websocket-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) [spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) [spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) [spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) [spring-web-6.0.11.jar:6.0.11]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) [spring-web-6.0.11.jar:6.0.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:166) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:341) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:391) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-10.1.11.jar:10.1.11]
        at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.apache.plc4x.java.api.exceptions.PlcRuntimeException: Disconnected
        at org.apache.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic.read(S7ProtocolLogic.java:247) ~[plc4j-driver-s7-0.11.0.jar:0.11.0]
        at org.apache.plc4x.java.spi.optimizer.BaseOptimizer.send(BaseOptimizer.java:152) ~[plc4j-spi-0.11.0.jar:0.11.0]
        at org.apache.plc4x.java.spi.optimizer.BaseOptimizer.optimizedRead(BaseOptimizer.java:109) ~[plc4j-spi-0.11.0.jar:0.11.0]
        at org.apache.plc4x.java.spi.connection.AbstractPlcConnection.read(AbstractPlcConnection.java:178) ~[plc4j-spi-0.11.0.jar:0.11.0]
        at org.apache.plc4x.java.spi.messages.DefaultPlcReadRequest.execute(DefaultPlcReadRequest.java:55) ~[plc4j-spi-0.11.0.jar:0.11.0]
        at org.apache.plc4x.java.utils.cache.LeasedPlcConnection$2$1.execute(LeasedPlcConnection.java:113) ~[plc4j-connection-cache-0.11.0.jar:0.11.0]
        ... 67 more
[ERROR] 18:16:49.160 it.fox.chronos.api.PlcReadApiImpl.getMemoryRaw() - java.util.concurrent.ExecutionException: org.apache.plc4x.java.api.exceptions.PlcRuntimeException: Disconnected

The strange thing here is that, in the first line before the exception there is: "Reusing existing connection" but the connection was dropped few seconds before?

Question

Shouldn't be up to the CachedPlcConnectionManager take care that if a connection is dropped by inactivity this connection will never be provided to the client any more and fire up a new one?

Thanks,
S.