[PLC4X-242] nioEventLoopGroup thread leak

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 0.7.0, 0.8.0
• Fix Version/s: 0.10.0
• Component/s: API
• Environment: Linux Raspbian Buster 10.0 / OpenJDK 13
• Assignee: Sebastian Rühl
• Reporter: Adam Rossi
• Created: 25/Aug/20 12:32
• Updated: 03/Dec/21 10:32
• Resolved: 03/Dec/21 10:32

Description

Here is some log output from my program. You can see that the close is called on the DefaultNettyPlcConnection, but I do not see the output from the code modification that I would expect if the closeEventLoopForChannel method was being called (Either logger.info("Channel is closed, closing worker Group also") or logger.warn("Trying to remove EventLoop for Channel {} but have none stored", channel).
 
The nioEventLoopGroup threads continue to persist after every plcConnection. 
 
I hope I have built everything correctly...I checked out your branch with:
 

git clone --single-branch --branch bugfix/close-eventloop-after-channel https://github.com/apache/plc4x.git
 

And wiped out my local m2 maven repository before building the code with:
 

./mvnw install -DskipTests
 

I also removed references to the apache snapshot repo from my project pom and by all appearances I am using the correct 0.8.0-SNAPSHOT jars that are locally built in my local m2 repo. Here is some log info from my test:
 

 

2020-08-24_10:15:43.450 DEBUG PooledPlcDriverManager - Try to borrow an object for url modbus://192.168.0.5:503?unit-identifier=50
2020-08-24_10:15:43.452 INFO  TcpChannelFactory - Configuring Bootstrap with Configuration{}
2020-08-24_10:15:43.458 DEBUG ModbusManager - Connection Metadata:
2020-08-24_10:15:43.459 DEBUG ModbusManager - org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection@185c140
2020-08-24_10:15:43.462 DEBUG Plc4xNettyWrapper - Forwarding request to plc ModbusTcpADU[transactionIdentifier=10,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=67,quantity=1]]
2020-08-24_10:15:43.466 DEBUG GeneratedDriverByteToMessageCodec - Sending bytes to PLC for message ModbusTcpADU[transactionIdentifier=10,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=67,quantity=1]] as data 000a00000006320300430001
2020-08-24_10:15:43.470 DEBUG Plc4xNettyWrapper - Forwarding request to plc ModbusTcpADU[transactionIdentifier=11,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=69,quantity=1]]
2020-08-24_10:15:43.471 DEBUG GeneratedDriverByteToMessageCodec - Sending bytes to PLC for message ModbusTcpADU[transactionIdentifier=11,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=69,quantity=1]] as data 000b00000006320300450001
2020-08-24_10:15:43.480 DEBUG Plc4xNettyWrapper - Forwarding request to plc ModbusTcpADU[transactionIdentifier=12,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=68,quantity=1]]
2020-08-24_10:15:43.481 DEBUG GeneratedDriverByteToMessageCodec - Sending bytes to PLC for message ModbusTcpADU[transactionIdentifier=12,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=68,quantity=1]] as data 000c00000006320300440001
2020-08-24_10:15:43.484 DEBUG Plc4xNettyWrapper - Forwarding request to plc ModbusTcpADU[transactionIdentifier=13,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=66,quantity=1]]
2020-08-24_10:15:43.485 DEBUG GeneratedDriverByteToMessageCodec - Sending bytes to PLC for message ModbusTcpADU[transactionIdentifier=13,unitIdentifier=50,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=66,quantity=1]] as data 000d00000006320300420001
2020-08-24_10:15:43.489 DEBUG PooledPlcDriverManager - close called on org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection@185c140
2020-08-24_10:15:43.490 INFO  ReadModbusTask - Read Modbus Task Completed.
 

Some details from my code:
 
Getting the connection:

PlcConnection plcConnection = pooledDriverManager.getConnection(modbusServerURI);
if (plcConnection.isConnected())

Unknown macro: {                 LOG.trace("The connection is connected");  }

else

Unknown macro: {                 LOG.trace("The connection is not connected. Connecting now...");                 plcConnection.connect();  }

 

Reading the plc and closing the connection:
 

PlcReadRequest.Builder builder = plcConnection.readRequestBuilder();
builder.addItem("devicename", "holding-register:1[8]");
builder.addItem("generatorstate", "holding-register:67");
builder.addItem("batteryvoltage", "holding-register:513[2]");
builder.addItem("batterycurrent", "holding-register:515[2]");
builder.addItem("pvpowerwatts", "holding-register:69[2]");
builder.addItem("pvinputthishourkwh", "holding-register:307[2]");
PlcReadRequest readRequest = builder.build();
PlcReadResponse response;
            try {
                response = readRequest.execute().get(5, TimeUnit.SECONDS);

                //process response

catch (InterruptedException | ExecutionException | TimeoutException ex)

Unknown macro: {                 LOG.error("Error in executing gateway read - interrupted or timed out", ex);             }

        } finally

Unknown macro: {             plcConnection.close();         }

catch (Exception ex)

Unknown macro: {             LOG.error("Error closing modbus connection", ex);         }

        }

Other details: 

 

openjdk version: "13.0.2" 2020-01-15
Linux Version:
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION="10 (buster)"