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.

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

fix(plc4j/drivers/s7): fix Camel tries to reconnect immediately because of event order #1879

Merged
merged 2 commits into from
Nov 11, 2024

Conversation

jmeierhofer
Copy link
Contributor

This PR fixes an ordering issue for the user event listeners. The isConnected method does return false for less than 1ms which causes an exception because the connection is discared immediately, ignoring that it's not fully connected yet.

  1. MAIN-Thread: Camel Plc4XEndpoint.setupConnection(): Connection is established and waits for the sessionSetupCompleteFuture to complete.
  2. CHILD-Thread: S7HMuxImpl.userEventTriggered() is called and the super.userEventTriggered() method calls all user event listeners
  3. CHILD-Thread: DefaultNettyPlcConnection.getChannelHandler......userEventTriggered() is called, which completes the sessionSetupCompleteFuture.
  4. MAIN-Thread: Camel Plc4XEndpoint.setupConnection() method continues and checks if S7HPlcConnection.isConnected() but the IS_CONNECTED was not set yet and so the connection is closed immediately
  5. CHILD-Thread: S7HMuxImpl.userEventTriggered() method continues and sets the IS_CONNECTED

By moving the super.userEventTriggered() to the end of the method, the order of the above steps changes to 1, 2, 5, 3, 4 and the bug does not happen.

Log:

2024-11-08 10:45:16,107  INFO | main                 | o.a.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic    | S7 Driver running in ACTIVE mode.
2024-11-08 10:45:16,108  INFO | main                 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | 10:45:16.108880 userEventTriggered: Multiplexor Event: org.apache.plc4x.java.spi.events.ConnectEvent@6caa4dc5
2024-11-08 10:45:16,112  INFO | ioEventLoopGroup-2-1 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | Unregistered of channel: PRIMARY
2024-11-08 10:45:16,112  INFO | ioEventLoopGroup-2-1 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | io.netty.channel.embedded.EmbeddedEventLoop@325cf450
2024-11-08 10:45:16,159  WARN | ioEventLoopGroup-3-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.net.SocketException: Connection reset
	at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:401)
	at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:434)
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:255)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:356)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
	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:1583)
2024-11-08 10:45:16,163  INFO | ioEventLoopGroup-3-1 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | Unregistered of channel: PRIMARY
2024-11-08 10:45:16,164  INFO | ioEventLoopGroup-3-1 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | 10:45:16.164222400 userEventTriggered: Multiplexor Event: org.apache.plc4x.java.spi.events.DisconnectedEvent@1b78b777
2024-11-08 10:45:16,164  INFO | ioEventLoopGroup-3-1 | org.apache.plc4x.java.s7.readwrite.protocol.S7HMuxImpl  | io.netty.channel.embedded.EmbeddedEventLoop@325cf450
2024-11-08 10:45:16,827  INFO | plc4x-s7ha-thread-1  | o.a.plc4x.java.s7.readwrite.protocol.S7HPlcConnection   | Creating prymary connection.
2024-11-08 10:45:16,860  INFO | plc4x-s7ha-thread-1  | org.apache.plc4x.java.transport.tcp.TcpChannelFactory   | Configuring Bootstrap with org.apache.plc4x.java.s7.readwrite.configuration.S7TcpTransportConfiguration@2d24cdd9
2024-11-08 10:45:16,896  INFO | plc4x-s7ha-thread-1  | o.a.plc4x.java.s7.readwrite.protocol.S7ProtocolLogic    | S7 Driver running in ACTIVE mode.

…ecause the IS_CONNECTED attribute is set 1ms from a child thread (after the S7HPlcConnection assumes the connection is fully established)
@sruehl
Copy link
Contributor

sruehl commented Nov 8, 2024

thanks for your PR, LGTM

Copy link
Contributor

@splatch splatch left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, it is better to call our logic first!

@sruehl
Copy link
Contributor

sruehl commented Nov 11, 2024

k, ty for the PR

@sruehl sruehl merged commit 0ad7a7b into apache:develop Nov 11, 2024
@jmeierhofer jmeierhofer deleted the bugfix-connected-event-order branch November 11, 2024 12:31
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants