[Bug]: modbus read timeout, CachedPlcConnectionManager will not create a new connect

[jackxuhaijun]

What happened?

@ToString
@PlcEntity
public class LiftReadData {

    @PlcTag("441139")
    public int heartBeat;

    @PlcTag("441141")
    public int online;

    @PlcTag("441143")
    public int workModel;

    @PlcTag("441145:DINT")
    public int feedback;

    @PlcTag("441149:DINT")
    public int taskNo;

    @PlcTag("441153")
    public int taskStatus;

    @PlcTag("441155")
    public int action;

    @PlcTag("441157")
    public int currentFloor;

    @PlcTag("441159")
    public int signal;

    @PlcTag("441161")
    public int carSignal;

    @PlcTag("441163")
    public int goodSignal;

    @PlcTag("441165")
    public int runState;

    @PlcTag("441167")
    public int blockSignal;

    @PlcTag("441169:DINT")
    public int sensor;

    @PlcTag("441173")
    public int alarmCode;

    @PlcTag("441175:DINT")
    public int height;

    @PlcTag("441179")
    public int palletType;

    @PlcTag("441181")
    public int destFloor;

    @PlcTag("441183")
    public int backup;
}

    @SneakyThrows
    public LiftReadData readData(Area area) {
        LiftReadData readData = null;
        try {
            readData = entityManager.read(LiftReadData.class, "modbus-tcp:tcp://192.168.50.100:502?request-timeout=1000");
        } catch (Exception e) {
            log.info("PLC4X {} read exception", area);
            throw new RuntimeException(e);
        }
        log.info("PLC4X {} read {}", area, readData);
        return readData;
    }

the entityManger is built like that:
this.entityManager = new PlcEntityManager(CachedPlcConnectionManager.getBuilder().build());

hello, I am using the Modbus-TCP protocol with a read timeout of 1 second. The on-site network frequently experiences packet loss, causing the connection to remain in the TIME_WAIT state. When attempting to reconnect, no new connection is created, and there is no network communication at all. Instead, a timeout exception is thrown immediately.
this is the exception:

java.lang.RuntimeException: org.apache.plc4x.java.opm.OPMException: Unexpected error during processing
	at com.zikoo.rcs.server.lift.LiftService.getWriteData(LiftService.java:113) ~[zk-lift-1.1.0.jar!/:?]
	at com.zikoo.rcs.server.lift.LiftService$$FastClassBySpringCGLIB$$8ad9a247.invoke(<generated>) ~[zk-lift-1.1.0.jar!/:?]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.27.jar!/:5.3.27]
	at org.springframework.aop.framework.CglibAopProxy.invokeMethod(CglibAopProxy.java:386) ~[spring-aop-5.3.27.jar!/:5.3.27]
	at org.springframework.aop.framework.CglibAopProxy.access$000(CglibAopProxy.java:85) ~[spring-aop-5.3.27.jar!/:5.3.27]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:704) ~[spring-aop-5.3.27.jar!/:5.3.27]
	at com.zikoo.rcs.server.lift.LiftService$$EnhancerBySpringCGLIB$$7fa53755.getWriteData(<generated>) ~[zk-lift-1.1.0.jar!/:?]
	at com.zikoo.rcs.server.lift.LiftServer.getWriteData(LiftServer.java:82) ~[zk-lift-1.1.0.jar!/:?]
	at com.zikoo.rcs.server.lift.LiftServer.getWriteData(LiftServer.java:25) ~[zk-lift-1.1.0.jar!/:?]
	at com.zikoo.rcs.server.lift.LiftServerHandler.handle(LiftServerHandler.java:22) ~[lift-api-1.1.0.jar!/:?]
	at com.zikoo.rcs.api.ServerHandler.internalInvoke(ServerHandler.java:219) ~[core-2.0.0.jar!/:?]
	at com.zikoo.rcs.api.ServerHandler.run(ServerHandler.java:150) ~[core-2.0.0.jar!/:?]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.27.jar!/:5.3.27]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) ~[?:?]
Caused by: org.apache.plc4x.java.opm.OPMException: Unexpected error during processing
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.refetchAllFields(PlcEntityInterceptor.java:255) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:171) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:126) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.read(PlcEntityManager.java:106) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at com.zikoo.rcs.server.lift.LiftService.getWriteData(LiftService.java:109) ~[zk-lift-1.1.0.jar!/:?]
	... 18 more
Caused by: org.apache.plc4x.java.opm.OPMException: Timeout during fetching values
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.getFromFuture(PlcEntityInterceptor.java:563) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.getPlcReadResponse(PlcEntityInterceptor.java:539) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.refetchAllFields(PlcEntityInterceptor.java:237) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:171) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:126) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.read(PlcEntityManager.java:106) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at com.zikoo.rcs.server.lift.LiftService.getWriteData(LiftService.java:109) ~[zk-lift-1.1.0.jar!/:?]
	... 18 more
Caused by: java.util.concurrent.TimeoutException
	at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1886) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2021) ~[?:?]
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.getFromFuture(PlcEntityInterceptor.java:556) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.getPlcReadResponse(PlcEntityInterceptor.java:539) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityInterceptor.refetchAllFields(PlcEntityInterceptor.java:237) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:171) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.connect(PlcEntityManager.java:126) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at org.apache.plc4x.java.opm.PlcEntityManager.read(PlcEntityManager.java:106) ~[plc4j-opm-0.11.0.jar!/:0.11.0]
	at com.zikoo.rcs.server.lift.LiftService.getWriteData(LiftService.java:109) ~[zk-lift-1.1.0.jar!/:?]
	... 18 more

then i change to use DefaultPlcConnectManager。Am I using the wrong method? I am using DefaultPlcConnectionManager and noticed that the read operation takes a long time—about 2 seconds per read. 99% of the time is spent on close rather than on communication.

---ts=2025-03-27 10:55:30;thread_name=scheduling-2;id=32;is_daemon=false;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@69d0a921
    `---[2064.984999ms] org.apache.plc4x.java.opm.PlcEntityInterceptor:refetchAllFields()
        +---[0.00% 0.069478ms ] org.slf4j.Logger:trace() #206
        +---[0.00% min=0.002407ms,max=0.022089ms,total=0.071885ms,count=19] org.apache.plc4x.java.opm.PlcTag:value() #215
        +---[0.00% min=0.002534ms,max=0.029857ms,total=0.079953ms,count=19] org.apache.plc4x.java.opm.OpmUtils:getOrResolveAddress() #215
        +---[0.37% 7.588448ms ] org.apache.plc4x.java.api.PlcConnectionManager:getConnection() #218
        +---[0.00% 0.018007ms ] org.apache.plc4x.java.api.PlcConnection:readRequestBuilder() #221
        +---[0.00% 0.098804ms ] org.apache.plc4x.java.api.messages.PlcReadRequest$Builder:build() #233
        +---[0.00% 0.005795ms ] org.slf4j.Logger:trace() #235
        +---[2.00% 41.225971ms ] org.apache.plc4x.java.opm.PlcEntityInterceptor:getPlcReadResponse() #237
        +---[0.00% 0.034456ms ] org.apache.plc4x.java.api.messages.PlcReadResponse:getTagNames() #240
        +---[0.00% min=0.001821ms,max=0.03375ms,total=0.080386ms,count=19] org.apache.plc4x.java.api.messages.PlcReadResponse:getObject() #244
        +---[0.00% min=0.001607ms,max=0.009401ms,total=0.041055ms,count=19] org.slf4j.Logger:trace() #244
        +---[0.00% min=0.001786ms,max=0.0118ms,total=0.04597ms,count=19] org.apache.commons.lang3.StringUtils:substringAfterLast() #245
        +---[0.01% min=0.003761ms,max=0.126271ms,total=0.210518ms,count=19] org.apache.plc4x.java.opm.PlcEntityInterceptor:setField() #247
        `---[97.44% 2012.201544ms ] org.apache.plc4x.java.api.PlcConnection:close() #252

---ts=2025-03-27 11:09:16;thread_name=scheduling-8;id=92;is_daemon=false;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@69d0a921
    `---[2011.964249ms] org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection:close()
        +---[0.00% 0.003388ms ] org.slf4j.Logger:debug() #166
        +---[0.00% 0.002451ms ] io.netty.channel.Channel:pipeline() #167
        +---[0.00% 0.001272ms ] org.apache.plc4x.java.spi.events.DisconnectEvent:<init>() #167
        +---[0.00% 0.013551ms ] io.netty.channel.ChannelPipeline:fireUserEventTriggered() #167
        +---[0.00% 0.001759ms ] io.netty.channel.Channel:isOpen() #177
        +---[0.00% 9.23E-4ms ] io.netty.channel.Channel:pipeline() #179
        +---[0.00% 0.001188ms ] org.apache.plc4x.java.spi.events.CloseConnectionEvent:<init>() #179
        +---[0.00% 0.001087ms ] io.netty.channel.ChannelPipeline:fireUserEventTriggered() #179
        +---[0.00% 0.005052ms ] io.netty.channel.Channel:close() #180
        +---[0.13% 2.694647ms ] io.netty.channel.ChannelFuture:awaitUninterruptibly() #180
        `---[99.86% 2009.164249ms ] org.apache.plc4x.java.spi.connection.ChannelFactory:closeEventLoopForChannel() #193

`---ts=2025-03-27 11:17:22;thread_name=scheduling-2;id=32;is_daemon=false;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@69d0a921
    `---[2009.474521ms] org.apache.plc4x.java.spi.connection.NettyChannelFactory:closeEventLoopForChannel()
        +---[0.01% 0.170689ms ] org.slf4j.Logger:info() #154
        +---[0.00% 0.003794ms ] io.netty.channel.EventLoopGroup:shutdownGracefully() #157
        +---[99.98% 2009.065832ms ] io.netty.util.concurrent.Future:awaitUninterruptibly() #157
        `---[0.01% 0.156067ms ] org.slf4j.Logger:info() #158

the source code why awaitUninterruptibly 2000ms？I remove this is ok？

I would like to ask how to properly use PLC4J to read multiple devices using the Modbus-TCP protocol in cases where ReadTimeout frequently occurs, ensuring both speed and reliability.

Version

v.0.11.0

Programming Languages

• plc4c
• plc4go
• plc4j
• plc4net
• plc4py

Protocols

• AB-Ethernet
• ADS /AMS
• BACnet/IP
• C-Bus
• CANopen
• EtherNet/IP
• Firmata
• IEC-69870
• KNXnet/IP
• Modbus
• OPC-UA
• Profinet
• S7

[chrisdutz]

Indeed this seems to be a common problem with various of our drivers ... gracefully handling disconnects, network problems etc. and allowing a quick recovery.

[jackxuhaijun]

Indeed this seems to be a common problem with various of our drivers ... gracefully handling disconnects, network problems etc. and allowing a quick recovery.
Thank you very much for your prompt reply！
Based on my observations, when using DefaultPlcConnectionManager, a new connection is established after each read operation. In contrast, CachedPlcConnectionManager reuses connections, but if the socket is in the TIME_WAIT state, no communication occurs. In this case, a new CachedPlcConnectionManager needs to be created. However, the old CachedPlcConnectionManager is not properly released, leading to thread leaks and port occupation. If this happens frequently, it can result in too many threads, eventually causing an OOM (Out of Memory) issue.
So now I don’t know the best way to use it. Do you have any suggestions?

[chrisdutz]

Well ... I would say that creation of new connections is not related to the read operation, but to the call of "getConnection" ... the DefaultDriverManager simply creates a new connection and the CachedDriverManager uses the DefaultDriverManager to create a connection, but then keeps it active.

But yes ... I guess all of our drivers could use a dedicated overwork to detect the disconnected state as well as terminate waiting futures as soon as a disconnect happens. I think currently if you start a read operation and then pull the plug, that the readRequest's future will not be cancelled, even if the connection allmost instantly is notified. In this case the Future will timeout.

However ... a lot of the complexity is related to Netty stuff ... and implementing something that instantly terminates would also require quite a rewrite.

Also are we running super low on people still wanting to invest their time here without ... we are currently trying to find ways to incentivise active addressing of bugs and refactorings (Still waiting for final approval of Apache Trademarks team before we can make this official) ... but if your company benefits of Apache PLC4X you already might want to spend a few minutes on if you would be willing to financially support the project.

[yancyang1989-gif]

Indeed this seems to be a common problem with various of our drivers ... gracefully handling disconnects, network problems etc. and allowing a quick recovery.
Thank you very much for your prompt reply！
Based on my observations, when using DefaultPlcConnectionManager, a new connection is established after each read operation. In contrast, CachedPlcConnectionManager reuses connections, but if the socket is in the TIME_WAIT state, no communication occurs. In this case, a new CachedPlcConnectionManager needs to be created. However, the old CachedPlcConnectionManager is not properly released, leading to thread leaks and port occupation. If this happens frequently, it can result in too many threads, eventually causing an OOM (Out of Memory) issue.
So now I don’t know the best way to use it. Do you have any suggestions?

I think when the connection is accidentally broken, catching the exception by try catch when trying getConnection again, executing CachedPlcConnectionManager.removeCachedConnection in the catch, and doing getConnection again, it is fine.