Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: Modbus RTU over TCP read fail in loop #1443

Closed
2 of 16 tasks
AleiynikovPavel opened this issue Mar 5, 2024 · 7 comments
Closed
2 of 16 tasks

[Bug]: Modbus RTU over TCP read fail in loop #1443

AleiynikovPavel opened this issue Mar 5, 2024 · 7 comments
Assignees
@chrisdutz
Labels
awaiting-feedback This label is applied when an issue has been opened and we need more information from the issuer. bug java Pull requests that update Java code Modbus https://plc4x.apache.org/users/protocols/modbus.html

Comments

@AleiynikovPavel
Copy link

AleiynikovPavel commented Mar 5, 2024 •
edited
Loading

What happened?

Error decoding TCP package after N read requests.

Example code causing the bug

Description

  • I get an error both on the real device and on the Modbus Slave Simulator running with option -m enc
  • I always get it at the 20th iteration of the loop presented in the code example
  • There is no error if you execute only one request per loop iteration (comment out the second request)
  • There are also no errors in modbus-tcp mode
  • There is also no error if both the first and second commands request the same number of registers

Code

package org.test.plc4j;

import org.apache.plc4x.java.DefaultPlcDriverManager;
import org.apache.plc4x.java.api.exceptions.PlcConnectionException;

import java.util.concurrent.ExecutionException;

public class Main {

    public static void main(String[] args) throws PlcConnectionException {
        var connection = new DefaultPlcDriverManager().getConnection("modbus-rtu:tcp:https://localhost:502");
        for (int i = 0; i < 45; i++) {
            try {
                connection.readRequestBuilder()
                        .addTagAddress("1", "input-register:1[125]").build().execute().get();
            } catch (InterruptedException | ExecutionException e) {
                System.err.println("Failed command 1 on iteration " + i);
            }
            try {
                connection.readRequestBuilder()
                        .addTagAddress("1", "input-register:1[50]").build().execute().get();
            } catch (InterruptedException | ExecutionException e) {
                System.err.println("Failed command 2 on iteration " + i);
            }
        }
    }

}

Output log

21:49:50.787 [nioEventLoopGroup-2-1] WARN org.apache.plc4x.java.spi.GeneratedDriverByteToMessageCodec -- Error decoding package with content [0104fa000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000]: Index 240 out of bounds for length 240
java.lang.ArrayIndexOutOfBoundsException: Index 240 out of bounds for length 240
	at com.github.jinahya.bit.io.ArrayByteInput.read(ArrayByteInput.java:106)
	at com.github.jinahya.bit.io.DefaultBitInput.read(DefaultBitInput.java:57)
	at com.github.jinahya.bit.io.AbstractBitInput.unsigned8(AbstractBitInput.java:63)
	at com.github.jinahya.bit.io.AbstractBitInput.unsigned16(AbstractBitInput.java:92)
	at com.github.jinahya.bit.io.AbstractBitInput.readInt(AbstractBitInput.java:135)
	at com.github.jinahya.bit.io.AbstractBitInput.readInt(AbstractBitInput.java:118)
	at com.github.jinahya.bit.io.AbstractBitInput.readByte(AbstractBitInput.java:106)
	at org.apache.plc4x.java.spi.generation.ReadBufferByteBased.readSignedByte(ReadBufferByteBased.java:388)
	at org.apache.plc4x.java.spi.generation.ReadBuffer.readByte(ReadBuffer.java:44)
	at org.apache.plc4x.java.spi.generation.ReadBufferByteBased.readByteArray(ReadBufferByteBased.java:126)
	at org.apache.plc4x.java.modbus.readwrite.ModbusPDUReadInputRegistersResponse.staticParseModbusPDUBuilder(ModbusPDUReadInputRegistersResponse.java:112)
	at org.apache.plc4x.java.modbus.readwrite.ModbusPDU.staticParse(ModbusPDU.java:171)
	at org.apache.plc4x.java.modbus.readwrite.ModbusRtuADU.lambda$0(ModbusRtuADU.java:132)
	at org.apache.plc4x.java.spi.codegen.io.DataReaderComplexDefault.read(DataReaderComplexDefault.java:70)
	at org.apache.plc4x.java.spi.codegen.io.DataReaderComplexDefault.read(DataReaderComplexDefault.java:61)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple.lambda$0(FieldReaderSimple.java:34)
	at org.apache.plc4x.java.spi.codegen.FieldCommons.switchParseByteOrderIfNecessary(FieldCommons.java:52)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple.readSimpleField(FieldReaderSimple.java:34)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderFactory.readSimpleField(FieldReaderFactory.java:133)
	at org.apache.plc4x.java.modbus.readwrite.ModbusRtuADU.staticParseModbusADUBuilder(ModbusRtuADU.java:129)
	at org.apache.plc4x.java.modbus.readwrite.ModbusADU.staticParse(ModbusADU.java:117)
	at org.apache.plc4x.java.modbus.readwrite.ModbusADU.staticParse(ModbusADU.java:103)
	at org.apache.plc4x.java.modbus.rtu.ModbusRtuDriver.lambda$0(ModbusRtuDriver.java:130)
	at org.apache.plc4x.java.spi.GeneratedDriverByteToMessageCodec.decode(GeneratedDriverByteToMessageCodec.java:87)
	at io.netty.handler.codec.ByteToMessageCodec$1.decode(ByteToMessageCodec.java:42)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
	at io.netty.handler.codec.ByteToMessageCodec.channelRead(ByteToMessageCodec.java:103)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)
21:49:50.789 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple -- reading field address
21:49:50.790 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple -- reading field pdu
21:49:50.790 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.spi.codegen.fields.FieldReaderDiscriminator -- reading field errorFlag
21:49:50.790 [nioEventLoopGroup-2-1] DEBUG org.apache.plc4x.java.spi.codegen.fields.FieldReaderDiscriminator -- reading field functionFlag
21:49:50.790 [nioEventLoopGroup-2-1] WARN org.apache.plc4x.java.spi.GeneratedDriverByteToMessageCodec -- Error decoding package with content [00000000000000000000000000f0a3]: Unsupported case for discriminated type parameters [errorFlag=false functionFlag=0 response=true]
org.apache.plc4x.java.spi.generation.ParseException: Unsupported case for discriminated type parameters [errorFlag=false functionFlag=0 response=true]
	at org.apache.plc4x.java.modbus.readwrite.ModbusPDU.staticParse(ModbusPDU.java:310)
	at org.apache.plc4x.java.modbus.readwrite.ModbusRtuADU.lambda$0(ModbusRtuADU.java:132)
	at org.apache.plc4x.java.spi.codegen.io.DataReaderComplexDefault.read(DataReaderComplexDefault.java:70)
	at org.apache.plc4x.java.spi.codegen.io.DataReaderComplexDefault.read(DataReaderComplexDefault.java:61)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple.lambda$0(FieldReaderSimple.java:34)
	at org.apache.plc4x.java.spi.codegen.FieldCommons.switchParseByteOrderIfNecessary(FieldCommons.java:52)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderSimple.readSimpleField(FieldReaderSimple.java:34)
	at org.apache.plc4x.java.spi.codegen.fields.FieldReaderFactory.readSimpleField(FieldReaderFactory.java:133)
	at org.apache.plc4x.java.modbus.readwrite.ModbusRtuADU.staticParseModbusADUBuilder(ModbusRtuADU.java:129)
	at org.apache.plc4x.java.modbus.readwrite.ModbusADU.staticParse(ModbusADU.java:117)
	at org.apache.plc4x.java.modbus.readwrite.ModbusADU.staticParse(ModbusADU.java:103)
	at org.apache.plc4x.java.modbus.rtu.ModbusRtuDriver.lambda$0(ModbusRtuDriver.java:130)
	at org.apache.plc4x.java.spi.GeneratedDriverByteToMessageCodec.decode(GeneratedDriverByteToMessageCodec.java:87)
	at io.netty.handler.codec.ByteToMessageCodec$1.decode(ByteToMessageCodec.java:42)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
	at io.netty.handler.codec.ByteToMessageCodec.channelRead(ByteToMessageCodec.java:103)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)
Failed command 1 on iteration 20

Full log file

Version

v0.12.0

Programming Languages

  • plc4j
  • plc4go
  • plc4c
  • plc4net

Protocols

  • AB-Ethernet
  • ADS /AMS
  • BACnet/IP
  • CANopen
  • DeltaV
  • DF1
  • EtherNet/IP
  • Firmata
  • KNXnet/IP
  • Modbus
  • OPC-UA
  • S7
@chrisdutz chrisdutz self-assigned this Jun 21, 2024
@splatch splatch added java Pull requests that update Java code Modbus https://plc4x.apache.org/users/protocols/modbus.html labels Jul 5, 2024
@chrisdutz
Copy link
Contributor

I was able to reproduce this error using a linux vm and connecting to that ... will investigate.

@AleiynikovPavel
Copy link
Author

I was able to reproduce this error using a linux vm and connecting to that ... will investigate.

Yes, the test program and modas simulator were launched on Linux 6.1.71-1-MANJARO

@chrisdutz
Copy link
Contributor

Ok ... so running the example program produces this output in wireshark:
modbus-rtu-issue1443.pcapng.zip
I couldn't see anything fishy in it, so now I guess I'll have to go into the driver as it obviously isn't a mis-behaving slave.

@chrisdutz
Copy link
Contributor

Ok ... progress ... So if I output the size of a message in the buffer in side ByteLengthEstimator I can see all successful read responses for request 1 are 255 bytes large, in message 20 for some reason only 240 bytes make it into the buffer and the byte-length estimator therefore keeps on reporting "-1" (Not enough). However the missing bytes don't seem to be added.

@chrisdutz
Copy link
Contributor

Ok .. mainly leaving this info here for myself if I don't finish it today:
If I put a logging breakpoint in NioSocketChannel.doReadBytes to output the "writableBytes" I see this:

Reading 2048 bytes
Reading 2048 bytes
Reading 1024 bytes
Reading 1024 bytes
Reading 512 bytes
Reading 512 bytes
Reading 496 bytes
Reading 496 bytes
Reading 480 bytes
Reading 480 bytes
Reading 464 bytes
Reading 464 bytes
Reading 448 bytes
Reading 448 bytes
Reading 432 bytes
Reading 432 bytes
Reading 416 bytes
Reading 416 bytes
Reading 400 bytes
Reading 400 bytes
Reading 384 bytes
Reading 384 bytes
Reading 368 bytes
Reading 368 bytes
Reading 352 bytes
Reading 352 bytes
Reading 336 bytes
Reading 336 bytes
Reading 320 bytes
Reading 320 bytes
Reading 304 bytes
Reading 304 bytes
Reading 288 bytes
Reading 288 bytes
Reading 272 bytes
Reading 272 bytes
Reading 256 bytes
Reading 256 bytes
Reading 256 bytes
Reading 256 bytes
Reading 240 bytes

So for some reason the buffer is shrinking and starting with the 20th iteration of your program, the amount of available buffer space becomes less than the packet needs to be parsed and that's when things go south. I need to find out why the buffer is not freed.

chrisdutz added a commit that referenced this issue Aug 2, 2024
@chrisdutz
fix: Added a manual call to compaction, if parsing fails for an Array…
9410635 
…IndexOutOfBounds exception.

#1443
@chrisdutz
Copy link
Contributor

Ok ... so it turns out that in the failure case, the ByteLengthEstimator didn't throw a ParseException but an ArrayIndexOutOfBoundsException, so I added a handler for that, that also manually calls compaction of the netty buffers. This now made the application iterate through all 45 rounds. Even updating that to run 450 times caused no issues.

Please try try if my changes resolved your issues.

@chrisdutz chrisdutz added awaiting-feedback This label is applied when an issue has been opened and we need more information from the issuer. and removed working on it labels Aug 2, 2024
@AleiynikovPavel
Copy link
Author

I checked your fix on several similar examples. I didn't see any problems. Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@chrisdutz chrisdutz

Labels
awaiting-feedback This label is applied when an issue has been opened and we need more information from the issuer. bug java Pull requests that update Java code Modbus https://plc4x.apache.org/users/protocols/modbus.html
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@splatch @chrisdutz @AleiynikovPavel