Bug: Timeout always waited before returning message result

[tlf30]

Hello, Troubleshooting slow performance, I noticed that the client will always wait the timeout before returning. I tested with timeouts up to 30 seconds and the behavior is always the same, the client will always wait the full timeout before returning.

Configuring the client with the timeout:

EtherNetIpClientConfig config = EtherNetIpClientConfig.builder(pathParts[0])
                    .setSerialNumber(0x00)
                    .setVendorId(0x00)
                    .setTimeout(Duration.ofSeconds(timeout))
                    .build();

...

 //Build client
CipClient client = new CipClient(config, connectionPath);
client.connect().get(); //Create connection

Getting the result like so:

recvBuff = client.invokeUnconnected(genericService).get();

Is this expected and I need to modify how I am using the client, or is this an issue in the client timeout?

Thank you, Trevor

EDIT: I tested with both connected and unconnected messages, they both have the same behavior.

[kevinherron]

This is not behavior I can replicate.

[tlf30]

Interesting. I was testing on my 1756-ENET, I swapped over to my 1756-EWEB and the issue is not present. Is the timeout sent to the device?

EDIT: Rockwell software does not appear to have the issue with the 1756-ENET. EDIT2 : I can easily replicate on the ENET by swapping to it, my other modules do not seem to show the issue.

[kevinherron]

I'm not sure what is going on. Is the delay present in Wireshark?

I have access to a 1756-ENET/A and /B I could test with if you can give me a self-contained code example to run.

[tlf30]

OK, I'll put together a test program.

[tlf30]

OK, it is actually the client disconnect that hangs:

Sending request with timeout of 10 seconds
Got response after 0.019 seconds
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
Disconnected after 10.065 seconds
Sending request with timeout of 10 seconds
Got response after 0.012 seconds
Disconnected after 10.03 seconds

int timeout = 10;
        String address = "192.168.1.13";

        EtherNetIpClientConfig config = EtherNetIpClientConfig.builder(address)
                .setSerialNumber(0x00)
                .setVendorId(0x00)
                .setTimeout(Duration.ofSeconds(timeout))
                .build();

        CipClient client = new CipClient(config,
                new EPath.PaddedEPath(
                        new PortSegment(1, //Backplane
                                new byte[]{
                                        0x01 //Processor in slot 1
                                }
                        )
                )
        );
        client.connect().get(); //Create connection

        System.out.println("Sending request with timeout of " + timeout + " seconds");
        long start = System.currentTimeMillis();
        //Send get identity request
        ByteBuf recvBuff = client.invoke(new GetAttributesAllService(new EPath.PaddedEPath(
                new LogicalSegment.ClassId(0x01),
                new LogicalSegment.InstanceId(0x01)
        ))).get();

        byte[] encodedBytes = new byte[recvBuff.readableBytes()];
        int readerIndex = recvBuff.readerIndex();
        recvBuff.getBytes(readerIndex, encodedBytes);

        long delta = System.currentTimeMillis() - start;
        float responseTime = delta / 1000f; //Get seconds
        System.out.println("Got response after " + responseTime + " seconds");
        client.disconnect().get();
        delta = System.currentTimeMillis() - start;
        responseTime = delta / 1000f; //Get seconds
        System.out.println("Disconnected after " + responseTime + " seconds");

See attached zip for project files ethernetip-issue69.zip

EDIT: I am using a 1756-ENET/B with firmware 2.7

[kevinherron]

I don't see this with either the A or B.

Sending request with timeout of 10 seconds
Got response after 0.021 seconds
Disconnected after 0.04 seconds

Wireshark cap with both: enip.zip

[kevinherron]

Mmm, actually this is against an EN2T, the ENET/A and ENET/B are in other slots, but this test code doesn't do anything that would actually send a message to those or use the configured connection path.

[kevinherron]

Can you get a Wireshark capture?

[tlf30]

I am sending the message though the ENET, for me, the ENET is the 192.168.1.13, and I am hitting a L55 controller in slot 1.

I am working on a capture, there is a lot of noise in my environment.

[kevinherron]

In this self-contained example the controller is irrelevant, you invoke GetAttributesAll service against the ENET module itself.

[tlf30]

In this self-contained example the controller is irrelevant, you invoke GetAttributesAll service against the ENET module itself.

Yes, that is correct. The EPATH is set to backplane->slot1, but the unconnected message sends the request to the ENET itself, which responds as expected.

Capture (Sorry, there is noise in it): ethernetip-issue69-cap1.zip

[kevinherron]

I can't reproduce... but try with this patch applied to the library:

Subject: [PATCH] List for channelInactive() when disconnecting
---
Index: enip-client/src/main/java/com/digitalpetri/enip/EtherNetIpClient.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/enip-client/src/main/java/com/digitalpetri/enip/EtherNetIpClient.java b/enip-client/src/main/java/com/digitalpetri/enip/EtherNetIpClient.java
--- a/enip-client/src/main/java/com/digitalpetri/enip/EtherNetIpClient.java (revision 26fb24e5e46b657058738072d93491137094f442)
+++ b/enip-client/src/main/java/com/digitalpetri/enip/EtherNetIpClient.java (date 1684950009622)
@@ -298,6 +298,11 @@
                 public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
                     disconnectFuture.complete(null);
                 }
+
+                @Override
+                public void channelInactive(ChannelHandlerContext ctx) {
+                    disconnectFuture.complete(null);
+                }
             });

             CompletableFuture<UnRegisterSession> future = new CompletableFuture<>();

[tlf30]

OK, I applied the patch, but in order to get it to build I had to upgrade netty to 4.1.86.Final. That did fix the issue. I removed the patch and left the upgraded netty and the test failed like it did before. Upgrading netty and applying the patch did fix it.

Are there any consequences to making the inactive event trigger a disconnect?

EDIT: The patch also fixes the issue in my main application as well, which is using both connected and unconnected messages.

[kevinherron]

Are there any consequences to making the inactive event trigger a disconnect?

No, probably should have been there all along, but all the devices I tested with closed the connection dirty with a TCP RST instead of a clean FIN/FIN-ACK/FIN sequence.