ModbusClientTCP : Timeout value compared with network trace shows different values

[hemeleerse]

Describe the bug Real timeouts seems to be different from the timeout value set using the setTimeout command

Expected behavior Here's my test:

1. I'm using syncRequest
2. I set the timeout value to 2000 (so 2 seconds) using the setTimeout(2000,30) command.
3. I use the getError method to retrieve the error message out of the response and add a timestamp (hh:mm:ss)
4. I took a network trance using Wireshark (which can calculate the ModBus response time) and I then compared my error logging with the trace: I notice that every time Wireshark reports a response time above 0.2 seconds, a Timeout error ( via getError() on the response) is generated. That is after 1/10th of the TimeOut value set !

To Reproduce

1. set a value for timeout that should trigger a timeout in normal circumstances with your modbus server
2. define in your code some logging of modbus errors (I do it using spiffs) including timestamp.
3. define a mirror port on the switch where your modbus server is connected and plug your pc with Wireshark on this port.
4. start a trace in Wireshark and let it run for a while to capture some timeouts. then stop the trace
5. pick any modbus package, search for 'request response time', click right button and 'add as column'. You'll see the response time of each and every request.
6. now find packets with a response time > 1/10 of the value you set and compare the wireshark timestamp with your Modbus errors. You'll see they align.

[Miq1]

Can we have a verbose log of the client, please? You will have to compile your code with -DLOG_LEVEL=6 or alternatively change the default log level in Logging.h to LOG_LEVEL_VERBOSE. Then the library will send a detailed log with milliseconds timestamps to Serial that may be helpful here.

[hemeleerse]

1.Here's the zipped verbose logfile. Scan for the word BOOKMARK to see timeouts log26042228.zip

2. Per transaction id (for each bookmarked request above) I also attach the Wireshark extract transid890.pdf transid1325.pdf transid1811.pdf transid2717.pdf transid547.pdf

Based on this data, I need to revise my original statement to : "a timeout is generated after 2 seconds although the network trace shows that the response was sent by the server in 0.1 to 0.2 seconds". So why the timeout error ?

FYI, I'm programming using Platform.IO (Arduino) on a M5Stack Core2 (ESP32).

[Miq1]

I am sorry, but after unzipping the log file all I see is binary gibberish. What would the file type be if not ZIP->TXT?

[hemeleerse]

I'll give it another try tomorrow.

Thx Erik

Op do 27 apr. 2023 19:53 schreef Michael Harwerth @.***

:

I am sorry, but after unzipping the log file all I see is binary gibberish. What would the file type be if not ZIP->TXT?

— Reply to this email directly, view it on GitHub https://github.com/eModbus/eModbus/issues/293#issuecomment-1526099418, or unsubscribe https://github.com/notifications/unsubscribe-auth/AI6DSMFBZLI2YSQLXDW572LXDKXA3ANCNFSM6AAAAAAXMUZHP4 . You are receiving this because you authored the thread.Message ID: @.***>

[hemeleerse]

This is the clear text version. log26042228github.txt

[Miq1]

Found the reason for the strange TXT format: I was using UNIX encoding, while you seem to have created the file with some Windows tool, right? So there was a 0x00 byte after every single character.

Anyway, I picked the first BOOKMARK from it an there the log shows:

**BOOKMARK**
[D] 5417337| ModbusClientTCP.cpp  [ 228] handleConnection: Got request from queue
[D] 5417348| ModbusClientTCP.cpp  [ 258] handleConnection: Is connected. Send request.
[V] Request packet: @3FFBA92C/12:
  | 0000: 02 23 00 00 00 06 01 03  01 2C 00 7D              |.#.......,.}    |
[D] 5419361| ModbusClientTCP.cpp  [ 288] handleConnection: Error response.
[D] 5419362| ModbusClientTCP.cpp  [ 344] handleConnection: Request popped from queue.
Error creating request: 3FFB2750 - Timeout
s1.maxsocket = 0
Loop duration is 3518

The timestamp of sending the request is 5417348 (which is the millis() since start), the TIMEOUT is noted at 5419361, which is 2013ms later. So it is obvious the lib did not get the response in time.

But why? I would suggest you trying to get more details. Can you collect the response in Wireshark and print it in hexadecimal, so we are able to check it for correctness? I am particularly interested in the IP and port (if it matches the connection) and the MBAP header bytes. The transaction ID in the case above was 0x0223, it must be in the response MBAP as well.

The root cause must sit in the IP layer I am sure.

[hemeleerse]

Here's the printout for transid 0x0223 HEX (547 DEC) Query-and-response-transid547-expanded.pdf

[Miq1]

Thanks. Looks okay at the first sight. The only explanation I have at the moment is some TCP issue, since the log as you are getting it is possible only if available() on this line in ModbusClientTCP.cpp:380 is never getting true, thus no data is put into the TCP internal buffer.

If the packet was too large for the internal buffer, we at least would get the fitting part - which we are not.

Does the server close the TCP connection immediately upon sending the response? But even then the data must have been received before the close strikes.

Strange.

[hemeleerse]

Issue solved : it seems a delay statement in my code caused the timeout errors. Typical mistake by a typical beginner (me..). Thanks again to all who contribute to this great library !

[Miq1]

Phew! Thanks for posting the solution. I was worrying there might be some serious bug hidden underneath... 😉