[
https://issues.apache.org/jira/browse/PLC4X-207?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17156320#comment-17156320
]
Anton Engman commented on PLC4X-207:
------------------------------------
Hello [~jfeinauer],
unfortunately the problem still exists when communicating with the S7 device. I
let the client talk with the S7 twice during different times of the day and it
died in the same manner as before in both cases. The error is not exactly the
same as in the Jira Issue description though since an exception is thrown this
time. Here is the error log:
{code:java}
s7-log.log:925789:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.p.j.s.GeneratedDriverByteToMessageCodec - Receiving bytes, trying to decode
Message...
s7-log.log:925790:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Decoding TPKTPacket[]
s7-log.log:925791:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Checking handler
HandlerRegistration#65045 for Object of type TPKTPacket
s7-log.log:925792:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Handler HandlerRegistration#65045 has
right expected type TPKTPacket, checking conditi
on
s7-log.log:925793:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Registration HandlerRegistration#65045
does not match object TPKTPacket (currently wra
pped to S7MessageResponseData)
s7-log.log:925794:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Checking handler
HandlerRegistration#65046 for Object of type TPKTPacket
s7-log.log:925795:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Handler HandlerRegistration#65046 has
right expected type TPKTPacket, checking conditi
on
s7-log.log:925796:01:06:53.758 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Registration HandlerRegistration#65046
does not match object TPKTPacket (currently wra
pped to S7MessageResponseData)
> s7-log.log:925797:01:06:53.759 [nioEventLoopGroup-2-1] TRACE
> o.a.plc4x.java.spi.Plc4xNettyWrapper - No registered handler found for
> message TPKTPacket[], using default decode method
s7-log.log:925798:01:06:53.759 [nioEventLoopGroup-2-1] WARN
i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and
it reached at the tail of the pipeline. It usu
ally means the last handler in the pipeline did not handle the exception.
s7-log.log:925799:io.netty.handler.codec.DecoderException:
java.lang.IllegalStateException: This should not happen!
s7-log.log:925800: at
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:98)
s7-log.log:925801: at
io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
s7-log.log:925802: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
s7-log.log:925803: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
s7-log.log:925804: at
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
s7-log.log:925805: at
io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321)
s7-log.log:925806: at
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:295)
s7-log.log:925807: at
io.netty.handler.codec.ByteToMessageCodec.channelRead(ByteToMessageCodec.java:103)
s7-log.log:925808: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
s7-log.log:925809: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
s7-log.log:925810: at
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
s7-log.log:925811: at
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
s7-log.log:925812: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
s7-log.log:925813: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
s7-log.log:925814: at
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
s7-log.log:925815: at
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
s7-log.log:925816: at
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
s7-log.log:925817: at
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
s7-log.log:925819: at
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
s7-log.log:925820: at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
s7-log.log:925821: at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
s7-log.log:925822: at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
s7-log.log:925823: at java.base/java.lang.Thread.run(Thread.java:830)
s7-log.log:925824:Caused by: java.lang.IllegalStateException: This should not
happen!
s7-log.log:925825: at
org.apache.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic.decode(S7ProtocolLogic.java:327)
s7-log.log:925826: at
org.apache.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic.decode(S7ProtocolLogic.java:111)
s7-log.log:925827: at
org.apache.plc4x.java.spi.Plc4xNettyWrapper.decode(Plc4xNettyWrapper.java:162)
s7-log.log:925828: at
io.netty.handler.codec.MessageToMessageCodec$2.decode(MessageToMessageCodec.java:81)
s7-log.log:925829: at
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:88)
s7-log.log:925830: ... 23 common frames omitted{code}
This time it throws an exception with the message "This should not happen". As
you can see it happens after about 60K requests.
I also tried communicating with a Modbus device and it died after about 2K
requests with an Timeout Exception:
{code:java}
modbus-log.log:39802:14:25:52.202 [nioEventLoopGroup-2-1] TRACE
o.a.p.j.s.GeneratedDriverByteToMessageCodec - Receiving bytes, trying to decode
Message...
modbus-log.log:39803:14:25:52.202 [nioEventLoopGroup-2-1] TRACE
o.a.plc4x.java.spi.Plc4xNettyWrapper - Decoding ModbusTcpADU[]
modbus-log.log:39804:14:25:52.202 [nioEventLoopGroup-2-1] DEBUG
o.a.plc4x.java.spi.Plc4xNettyWrapper - Removing HandlerRegistration#2064 as its
timed out (was set till 2020-07-12T12:25:5
2.161476200Z)
> modbus-log.log:39805:14:25:52.207 [nioEventLoopGroup-2-1] TRACE
> o.a.plc4x.java.spi.Plc4xNettyWrapper - No registered handler found for
> message ModbusTcpADU[transactionIdentifier=2074,uni
tIdentifier=1,pdu=ModbusPDUReadHoldingRegistersResponse[value={67,107,-69,26}]],
using default decode method
modbus-log.log:39806:java.util.concurrent.ExecutionException:
java.util.concurrent.TimeoutException: Timed out while waiting for response
modbus-log.log:39807: at
java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
modbus-log.log:39808: at
java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2070)
modbus-log.log:39809: at Modbus.<init>(Modbus.java:51)
modbus-log.log:39810: at Main.main(Main.java:31)
modbus-log.log:39811:Caused by: java.util.concurrent.TimeoutException: Timed
out while waiting for response
modbus-log.log:39812: at
org.apache.plc4x.java.spi.internal.HandlerRegistration.handleTimeout(HandlerRegistration.java:83)
modbus-log.log:39813: at
org.apache.plc4x.java.spi.Plc4xNettyWrapper.decode(Plc4xNettyWrapper.java:129)
modbus-log.log:39814: at
io.netty.handler.codec.MessageToMessageCodec$2.decode(MessageToMessageCodec.java:81)
modbus-log.log:39815: at
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:88)
modbus-log.log:39816: at
io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
modbus-log.log:39817: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
modbus-log.log:39818: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
modbus-log.log:39819: at
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
modbus-log.log:39820: at
io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321)
modbus-log.log:39821: at
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:295)
modbus-log.log:39822: at
io.netty.handler.codec.ByteToMessageCodec.channelRead(ByteToMessageCodec.java:103)
modbus-log.log:39823: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
modbus-log.log:39824: at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
modbus-log.log:39825: at
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
{code}
Please let me know if I can provide you with any additional information!
Best regards,
Anton Engman
> No registered handler found for message TPKTPacket[], , using default decode
> method - Communication with S7 and Modbus device hangs
> -----------------------------------------------------------------------------------------------------------------------------------
>
> 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
> Assignee: Julian Feinauer
> Priority: Major
>
> 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)
