[PLC4X-358] NettyChannelFactory.closeEventLoopForChannel never returns

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 0.11.0
• Component/s: Driver-Modbus, Integration-Kafka-Connect, PLC4J
• Environment: Raspberry Pi CM4, 8Gb RAM, Ubuntu 22.04

Language

Java

• Assignee: Unassigned
• Reporter: Poul
• Created: 28/Oct/22 15:38
• Updated: 09/Nov/22 10:25

Description

I'm polling a modbus device over a RS485 serial connection:

... connectionString":"modbus-rtu:serial:///dev/ttyAMA2?BAUD_RATE=19200&STOP_BITS=1&PARITY=EVEN&unit-identifier=1" 
...
"sources. ... .pollReturnInterval": 5000, 
"jobs. ... .interval": 2000,

It works for a few minutes and then:

[2022-10-28 17:20:50,239] WARN [conveyor12source|task-0] Request finished with exception. Reporting Connection as Broken (org.apache.plc4x.java.utils.connectionpool2.CachedPlcConnection:203)
java.util.concurrent.CancellationException
        at java.base/java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2396)
        at org.apache.plc4x.java.utils.connectionpool2.CachedPlcConnection.lambda$wrapReadWithTimeout$1(CachedPlcConnection.java:105)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
[2022-10-28 17:20:50,603] INFO [conveyor12source|task-0] Channel is closed, closing worker Group also (org.apache.plc4x.java.spi.connection.NettyChannelFactory:150)
[2022-10-28 17:20:50,614] INFO [conveyor12source|task-0] Worker Group was closed successfully! (org.apache.plc4x.java.spi.connection.NettyChannelFactory:155)
[2022-10-28 17:20:50,625] WARN [conveyor12source|task-0] Selector.select() returned prematurely 512 times in a row; rebuilding Selector org.apache.plc4x.java.transport.serial.SerialPollingSelector@1a6dc4ab. (io.netty.channel.nio.NioEventLoop:628)
[2022-10-28 17:20:50,626] INFO [conveyor12source|task-0] Migrated 1 channel(s) to the new Selector. (io.netty.channel.nio.NioEventLoop:499)
[2022-10-28 17:20:50,637] WARN [conveyor12source|task-0] Selector.select() returned prematurely 512 times in a row; rebuilding Selector org.apache.plc4x.java.transport.serial.SerialPollingSelector@2107b3db. (io.netty.channel.nio.NioEventLoop:628) 

The Migrated 1 channel(s) and Selector.select() log entires continues endless.

I've found that the call in NettyChannelFactory to:

@Override    
public void closeEventLoopForChannel(Channel channel) {
        if (eventLoops.containsKey(channel)) {
            logger.info("Channel is closed, closing worker Group also");
            EventLoopGroup eventExecutors = eventLoops.get(channel);
            eventLoops.remove(channel);
            eventExecutors.shutdownGracefully().awaitUninterruptibly();
            logger.info("Worker Group was closed successfully!");
        } else {
            logger.warn("Trying to remove EventLoop for Channel {} but have none stored", channel);
        }
    } 

eventExecutors.shutdownGracefully() never returns even though the above log indicates it did. I've changed the call to:

eventExecutors.shutdownGracefully().addListener(e->{ LoggerFactory.getLogger(NettyChannelFactory.class).info("closeEventLoopForChannel: Worker group finally shut down"); } ); 

in an attempt to eliminate any possible deadlocking.

Any suggestions would be much appreciated.