Anton Engman created PLC4X-207:
----------------------------------
Summary: No registered handler found for message TPKTPacket[], ,
using default decode method
Key: PLC4X-207
URL: https://issues.apache.org/jira/browse/PLC4X-207
Project: Apache PLC4X
Issue Type: Bug
Components: API, Driver-Modbus, Driver-S7
Affects Versions: 0.8.0
Reporter: Anton Engman
I am using PLC4X to poll 29 signals from a Siemens S7-300 device, all the
signals are of
data type REAL. Every second I send a request to the PLC asking for the values
and then printing one of the values to the console:
{code:java}
PlcConnection conn =
driverManager.getConnection("s7:tcp://<IP>?remote-rack=0&remote-slot=1&controller-type=S7_300");
PlcReadRequest.Builder builder = conn.readRequestBuilder();
builder.addItem("value1", "DB.50.DBD0:REAL");
.
.
.
builder.addItem("value29", "DB.50.DBD116:REAL");
PlcReadRequest readRequest = builder.build();
while(true)
{
PlcReadResponse r = readRequest.execute().get();
System.out.println(r.getObject("value1"));
Thread.sleep(1000);
}
{code}
Everything works fine for some time, but after >50K requests or 8-12 hours with
the current
polling rate at 1 second the code waits forever at the return value from
PlcReadResponse r
= readRequest.execute().get() and doesn't continue. I enabled Trace logging to
see what's
happening and every time this error occurs I get the following error message:
{code:java}
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Checking
handler HandlerRegistration#65120 for Object of type TPKTPacket
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Handler
HandlerRegistration#65120 has right expected type TPKTPacket, checking condition
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Registration
HandlerRegistration#65120 does not match object TPKTPacket (currently wrapped
to S7MessageResponseData)
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Checking
handler HandlerRegistration#65119 for Object of type TPKTPacket
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Handler
HandlerRegistration#65119 has right expected type TPKTPacket, checking condition
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Registration
HandlerRegistration#65119 does not match object TPKTPacket (currently wrapped
to S7MessageResponseData)
12:56:48.107 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- No registered
handler found for message
TPKTPacket[payload=COTPPacketData[parameters={},payload=S7MessageResponseData[tpduReference=0,parameter=S7ParameterReadVarResponse[numItems=19],payload=S7PayloadReadVarResponse[items={S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={66,61,-103,-102}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={66,65,51,51}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-104,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-120,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-103,-103,-102}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-127,-103,-102}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-106,102,103}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-96,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={66,-8,-26,-124}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={63,101,-95,48}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={0,0,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={63,-101,-114,57}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={68,122,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={65,-102,102,103}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={-66,109,9,123}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={0,0,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={-71,-67,-96,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={0,0,0,0}],S7VarPayloadDataItem[returnCode=OK,transportSize=REAL,dataLength=4,data={0,0,0,0}]}],errorClass=0,errorCode=0],eot=true,tpduRef=0]],
using default decode method{code}
And this error message is the last thing that is printed to my console, it's
like the code
is going into an infinite loop or something.
I used Wireshark to look at the packets coming from the PLC, I thought that
maybe there's
a malformed packet or something that's causing the error message above, but the
packet looks
exactly the same as the packets which are decoded successfully. I have also
experimented with
the connection string, using with and without the controller-type parameter,
but without any
difference.
I've also tried to increase the polling rate, requesting the values every
100ms, and that
will cause the above error to appear after 1-2 hours so it seems like the error
appears based
on the number of requests rather than some time interval.
I have also tried to only poll for 1 signal instead of 29 but the same error
still appears
after >50K requests.
I have a stable connection to my PLC during the entire time using an Ethernet
cable without
any significant delay.
I also discovered that this bug affect Modbus devices and it seems as if the
number of request necessary to produce this problem on a Modbus device is even
lower, only about 10k requests. Here is the error log when the problem occurs
while on Modbus:
{code:java}
11:27:47.570 [nioEventLoopGroup-2-1] DEBUG o.a.plc4x.java.spi.Plc4xNettyWrapper
- Forwarding request to plc
ModbusTcpADU[transactionIdentifier=11266,unitIdentifier=1,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=19000,quantity=2]]
11:27:47.570 [nioEventLoopGroup-2-1] DEBUG
o.a.p.j.s.GeneratedDriverByteToMessageCodec - Sending bytes to PLC for message
ModbusTcpADU[transactionIdentifier=11266,unitIdentifier=1,pdu=ModbusPDUReadHoldingRegistersRequest[startingAddress=19000,quantity=2]]
as data 2c020000000601034a380002
11:27:48.662 [nioEventLoopGroup-2-1] TRACE
o.a.p.j.s.GeneratedDriverByteToMessageCodec - Receiving bytes, trying to decode
Message...
11:27:48.662 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- Decoding
ModbusTcpADU[transactionIdentifier=11266,unitIdentifier=1,pdu=ModbusPDUReadHoldingRegistersResponse[value={67,106,19,29}]]
11:27:48.662 [nioEventLoopGroup-2-1] DEBUG o.a.plc4x.java.spi.Plc4xNettyWrapper
- Removing HandlerRegistration#11256 as its timed out (was set till
2020-07-07T09:27:48.570431800Z)
11:27:48.773 [nioEventLoopGroup-2-1] TRACE o.a.plc4x.java.spi.Plc4xNettyWrapper
- No registered handler found for message
ModbusTcpADU[transactionIdentifier=11266,unitIdentifier=1,pdu=ModbusPDUReadHoldingRegistersResponse[value={67,106,19,29}]],
using default decode method
{code}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
