search

apache / plc4x

PLC4X The Industrial IoT adapter
https://plc4x.apache.org/
Apache License 2.0
1.21k stars 393 forks source link

[Bug]: EtherNet/IP protocol throw exception when close the connection #1697

Open meichf opened 2 weeks ago

meichf commented 2 weeks ago

What happened?

I created a connection using the EtherNet/IP protocol. After reading the data, I needed to release the connection and called the close method of the PlcConnection, which resulted in an error.


2024-07-09 14:30:07.545 ERROR 55068 --- [ntLoopGroup-2-1] o.a.p.j.s.c.DefaultNettyPlcConnection    : unknown error, close the connection

java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394) ~[na:na]
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426) ~[na:na]
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:256) ~[netty-buffer-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at java.base/java.lang.Thread.run(Thread.java:842) ~[na:na]

2024-07-09 14:30:07.558  WARN 55068 --- [ntLoopGroup-2-1] io.netty.channel.DefaultChannelPipeline  : An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.

java.io.IOException: Broken pipe
    at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:na]
    at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62) ~[na:na]
    at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:132) ~[na:na]
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:76) ~[na:na]
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:53) ~[na:na]
    at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:532) ~[na:na]
    at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:415) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:931) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:895) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:921) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:907) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:893) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.ChannelDuplexHandler.flush(ChannelDuplexHandler.java:127) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:923) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:941) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:966) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:934) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:984) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at org.apache.plc4x.java.spi.internal.DefaultConversationContext.sendToWire(DefaultConversationContext.java:70) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at org.apache.plc4x.java.spi.internal.DefaultSendRequestContext.handle(DefaultSendRequestContext.java:107) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at org.apache.plc4x.java.spi.internal.DefaultSendRequestContext.handle(DefaultSendRequestContext.java:1) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at org.apache.plc4x.java.eip.base.protocol.EipProtocolLogic.onDisconnectUnregisterSession(EipProtocolLogic.java:423) ~[classes/:na]
    at org.apache.plc4x.java.eip.base.protocol.EipProtocolLogic.onDisconnect(EipProtocolLogic.java:405) ~[classes/:na]
    at org.apache.plc4x.java.spi.Plc4xNettyWrapper.userEventTriggered(Plc4xNettyWrapper.java:201) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:398) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:376) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:368) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.ChannelInboundHandlerAdapter.userEventTriggered(ChannelInboundHandlerAdapter.java:117) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection$1$1.userEventTriggered(DefaultNettyPlcConnection.java:251) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:400) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:376) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:368) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.userEventTriggered(DefaultChannelPipeline.java:1428) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:396) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:376) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline.fireUserEventTriggered(DefaultChannelPipeline.java:913) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection.close(DefaultNettyPlcConnection.java:167) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at org.apache.plc4x.java.spi.connection.DefaultNettyPlcConnection$1$2.exceptionCaught(DefaultNettyPlcConnection.java:261) ~[plc4j-spi-0.12.0.jar:0.12.0]
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:317) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.handleReadException(AbstractNioByteChannel.java:125) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:177) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.90.Final.jar:4.1.90.Final]
    at java.base/java.lang.Thread.run(Thread.java:842) ~[na:na]

2024-07-09 14:30:17.564 ERROR 55068 --- [ntLoopGroup-2-1] o.a.p.j.s.c.DefaultNettyPlcConnection    : Timeout while trying to close connection
2024-07-09 14:30:17.566  INFO 55068 --- [ntLoopGroup-2-1] o.a.p.j.s.c.NettyChannelFactory          : Channel is closed, closing worker Group also

### Version

v0.12.0

### Programming Languages

- [X] plc4j
- [ ] plc4go
- [ ] plc4c
- [ ] plc4net

### Protocols

- [ ] AB-Ethernet
- [ ] ADS /AMS
- [ ] BACnet/IP
- [ ] CANopen
- [ ] DeltaV
- [ ] DF1
- [X] EtherNet/IP
- [ ] Firmata
- [ ] KNXnet/IP
- [ ] Modbus
- [ ] OPC-UA
- [ ] S7
chrisdutz commented 2 weeks ago

Could you please attach a wireshark recording of the disconnect part? ... I would assume that when disconnecting sometimes 2 requests are being sent by the driver ... one do disconnect the CIP session and then a second one to disconnect the EIP session ... however in my case I never get a response for the second disconnect ... possibly your device behaves differently.

Also could you please tell us which type of device you are using?

meichf commented 2 weeks ago

My device is Rockwell Allen-Bradley 1756-L71

wireshark-disconnect-part
chrisdutz commented 2 weeks ago

Aaaah .. an unconnected send ... that only does one disconnect on EIP level ... but yeah your PLC also doesn't reply ... it just hangs up as soon as it receives the "goodbye" from the client (How rude ;-) )... I'll try to have a look on Friday (Or someone else, if he beats me to it)

chrisdutz commented 2 weeks ago

Having a closer look it seems that the remote hangs up without even acknowledging having received the request to hang up. I am not quite sure how we can prevent this from appearing in your logs.

chrisdutz commented 1 day ago

And instead of closing the connection, have you thought of using the connection-cache to keep the connection open for the next time you need to read from the PLC?

chrisdutz commented 1 day ago

Ok ... I wraped the sending of a disconnection request with a try-catch block ... I think it should "handle" the problem (It's sort of not really a problem, it's just "rude"). Please test and give us feedback, if we can close this issue.