Large delays when writing to tags in PLC

[Steven Barrington]

I have written an application that sends a small amount of data from a PC to a PLC mounted on a remote piece of equipment. The amount of data is quite small - 2 x DINT tags, sent approximately 5 times a second. The application on the PC runs a continuous loop that writes to the 2 tags in the PLC, pauses for 100ms and then writes to the tags again.

I'm experiencing fairly frequent periods (every 10 minutes or so) of a long duration (several seconds or more) where the tags stop being written to in the PLC - anywhere between 3 and 10 seconds. A small delay every now and again of a second or so is not a problem for this particular application, but delays of several seconds make the machine unusable.

The connection between the PC and the PLC is over a WiFi network. The network is fairly stable and apart from the odd dropped packet it works well. There are no long periods or bursts where data is not sent over the network. There is other data on this network (a camera feed and the SCADA reading data from the PLC) and they do not experience these dropouts. The network is only using about 20% of its available bandwidth.

I tried changing the timeout value of the tags and this didn't appear to do anything (I tried 200ms, 500ms, 1000ms and 2000ms). In the end I have just left it to the default value.

I have looked at the log output during some of these incidents (attached). I'm no expert on this at all and so I need some help in deciphering them... but to me it looks like (and I could be wrong) the connection is being lost and these long delays are caused by the time it takes to reconnect.

Is this right or is something else going on? And if it is, why would the connection be dropping out so frequently?

Thanks

[Kyle]

Thanks for using libplctag and especially for including the log files.  The first log file is not conclusive because whatever happened to the connection happened before the log started.  

The second log file has some clear breadcrumbs in it to follow.

Here is the last write:

Info 2025-12-29 11:08:39.138 thread(3) tag(0) INFO send_eip_request:1876 Starting. Info 2025-12-29 11:08:39.138 thread(3) tag(0) INFO send_eip_request:1889 Sending packet of size 66 Info 

2025-12-29 11:08:39.138 thread(3) tag(0) INFO send_eip_request:1890 00000 70 00 2a 00 0a 00 12 00 00 00 00 00 00 00 00 00 Info 

2025-12-29 11:08:39.139 thread(3) tag(0) INFO send_eip_request:1890 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00 Info 

2025-12-29 11:08:39.139 thread(3) tag(0) INFO send_eip_request:1890 00032 a1 00 04 00 03 50 f3 ff b1 00 16 00 3b 22 4d 05 Info 

2025-12-29 11:08:39.139 thread(3) tag(0) INFO send_eip_request:1890 00048 91 07 47 61 6d 65 70 61 64 00 c4 00 01 00 00 49 Info 

2025-12-29 11:08:39.139 thread(3) tag(0) INFO send_eip_request:1890 00064 02 00 Detail 

2025-12-29 11:08:39.139 thread(3) tag(0) DETAIL socket_write:1945 Starting. Detail 2025-12-29 11:08:39.140 thread(3) tag(0) DETAIL socket_write:2072 Done: result = 66. 

The write succeeds. Now that doesn't mean that the PLC got the data. It just means that the operating system told us that it accepted all the data.

But then there is no response for about 2 seconds and then the code gives up.  I assume you were using a timeout of about 2000 milliseconds?   

After that point no packets can be sent and the whole connection is torn down and restarted.  We see an attempt at trying to tear down the connection gently with a Forward Close, but that does not get a response.  Again the OS tells us that the data was accepted to be sent.

Here is the trace:

Warn 2025-12-29 11:08:41.201 thread(2) tag(0) WARN check_write_request_status:1211 Session reported failure of request: PLCTAG_ERR_TIMEOUT. 

2025-12-29 11:08:41.201 thread(2) tag(0) DETAIL check_write_request_status:1229 Write not ready with status PLCTAG_ERR_TIMEOUT. 

Here is where we try to send a Forward Close.

2025-12-29 11:08:41.206 thread(3) tag(0) INFO send_eip_request:1889 Sending packet of size 64 

2025-12-29 11:08:41.207 thread(3) tag(0) INFO send_eip_request:1890 00000 6f 00 28 00 0a 00 12 00 00 00 00 00 a5 60 00 00

2025-12-29 11:08:41.209 thread(3) tag(0) INFO send_eip_request:1890 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00 

2025-12-29 11:08:41.211 thread(2) tag(0) DETAIL tag_raise_event:243 PLCTAG_EVENT_WRITE_COMPLETED raised with status PLCTAG_ERR_TIMEOUT.

2025-12-29 11:08:41.211 thread(2) tag(0) DETAIL tag_raise_event:255 Disabled PLCTAG_EVENT_WRITE_COMPLETE.

2025-12-29 11:08:41.213 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from tag_tickler_func:582.

2025-12-29 11:08:41.216 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from tag_tickler_func:582.

2025-12-29 11:08:41.218 thread(2) tag(11) DETAIL plc_tag_generic_handle_event_callbacks:442 Tag write completed with status PLCTAG_ERR_TIMEOUT.

2025-12-29 11:08:41.220 thread(3) tag(0) DETAIL socket_write:1945 Starting.

2025-12-29 11:08:41.220 thread(2) tag(12) DETAIL tag_tickler_func:550 Tickling tag 12.

2025-12-29 11:08:41.221 thread(3) tag(0) DETAIL socket_write:2072 Done: result = 64.

And above the OS said it was done.  So the OS accepted the data to be sent.

2025-12-29 11:08:41.221 thread(2) tag(12) DETAIL plc_tag_generic_tickler:281 Tickling tag 12.

2025-12-29 11:08:41.228 thread(1) tag(11) INFO plc_tag_abort:1484 Starting.

2025-12-29 11:08:41.233 thread(3) tag(0) INFO send_forward_close_req:2462 Done

2025-12-29 11:08:41.233 thread(3) tag(0) INFO recv_forward_close_resp:2473 Starting

2025-12-29 11:08:41.236 thread(3) tag(0) INFO recv_eip_response:1952 Starting.

2025-12-29 11:08:41.264 thread(3) tag(0) DETAIL socket_read:1807 Starting.

2025-12-29 11:08:41.264 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.

2025-12-29 11:08:41.264 thread(3) tag(0) DETAIL socket_read:1836 Immediate read attempt did not succeed, now wait for select().

2025-12-29 11:08:41.264 thread(2) tag(11) DETAIL tag_tickler_func:603 Skipping tag as it is already locked.

And that is the end of the abort sequence.  

Then we timeout internally trying to get the response from the Forward Close and close the socket.

2025-12-29 11:08:41.429 thread(3) tag(0) DETAIL session_handler:1226 in SESSION_UNREGISTER state.

2025-12-29 11:08:41.429 thread(3) tag(0) INFO session_unregister:783 Starting.

2025-12-29 11:08:41.429 thread(3) tag(0) INFO session_unregister:787 Done.

2025-12-29 11:08:41.429 thread(3) tag(0) DETAIL session_handler:1237 in SESSION_CLOSE_SOCKET state.

2025-12-29 11:08:41.430 thread(3) tag(0) INFO session_close_socket:796 Starting.

2025-12-29 11:08:41.430 thread(3) tag(0) INFO socket_close:2083 Starting.

2025-12-29 11:08:41.430 thread(3) tag(0) INFO socket_close:2119 Done.

2025-12-29 11:08:41.430 thread(3) tag(0) INFO socket_destroy:2128 Starting.

2025-12-29 11:08:41.430 thread(3) tag(0) INFO socket_close:2083 Starting.

2025-12-29 11:08:41.431 thread(3) tag(0) INFO socket_close:2119 Done.

2025-12-29 11:08:41.431 thread(3) tag(0) INFO socket_destroy:2145 Done.

2025-12-29 11:08:41.431 thread(3) tag(0) INFO session_close_socket:804 Done.

2025-12-29 11:08:41.431 thread(3) tag(0) DETAIL session_handler:1252 in SESSION_START_RETRY state.

2025-12-29 11:08:41.431 thread(3) tag(0) DETAIL session_handler:1264 in SESSION_WAIT_RETRY state. 

This leaves the library waiting for a bit before trying to reconnect.

After the wait of 5 seconds, we try again:

2025-12-29 11:08:46.498 thread(3) tag(0) DETAIL session_handler:1264 in SESSION_WAIT_RETRY state.

2025-12-29 11:08:46.498 thread(3) tag(0) DETAIL session_handler:1267 Transitioning to SESSION_OPEN_SOCKET_START.

2025-12-29 11:08:46.499 thread(3) tag(0) DETAIL session_handler:1058 in SESSION_OPEN_SOCKET_START state.

2025-12-29 11:08:46.499 thread(3) tag(0) INFO session_open_socket:644 Starting.

2025-12-29 11:08:46.499 thread(3) tag(0) DETAIL socket_create:1311 Starting. Detail 2025-12-29 11:08:46.501 thread(3) tag(0) DETAIL socket_create:1334 Done.

2025-12-29 11:08:46.501 thread(3) tag(0) DETAIL session_open_socket:678 Using default port 44818.

2025-12-29 11:08:46.501 thread(3) tag(0) DETAIL socket_connect_tcp_start:1355 Starting.

2025-12-29 11:08:46.502 thread(3) tag(0) DETAIL socket_connect_tcp_start:1404 Found numeric IP address: 192.168.1.56

2025-12-29 11:08:46.502 thread(3) tag(0) DETAIL socket_connect_tcp_start:1444 Setting up wake pipe.

2025-12-29 11:08:46.502 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2161 Starting.

2025-12-29 11:08:46.503 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2308 Done.

2025-12-29 11:08:46.503 thread(3) tag(0) DETAIL socket_connect_tcp_start:1475 Socket connection attempt 0 started successfully.

2025-12-29 11:08:46.503 thread(3) tag(0) DETAIL socket_connect_tcp_start:1501 Done.

2025-12-29 11:08:46.504 thread(3) tag(0) INFO session_open_socket:693 Done.

2025-12-29 11:08:46.504 thread(3) tag(0) DETAIL session_handler:1074 Connect started, going to state SESSION_OPEN_SOCKET_WAIT.

2025-12-29 11:08:46.504 thread(3) tag(0) DETAIL session_handler:1086 in SESSION_OPEN_SOCKET_WAIT state.

2025-12-29 11:08:46.504 thread(3) tag(0) DETAIL socket_connect_tcp_check:1518 Starting.

2025-12-29 11:08:46.505 thread(3) tag(0) DETAIL socket_connect_tcp_check:1538 Socket is connected.

2025-12-29 11:08:46.505 thread(3) tag(0) DETAIL socket_connect_tcp_check:1598 Done.

2025-12-29 11:08:46.506 thread(3) tag(0) INFO session_handler:1092 Socket connection succeeded. 

And the TCP connection attempt is successful.

After that we register an EtherNet/IP session:

2025-12-29 11:08:46.506 thread(3) tag(0) DETAIL session_handler:1113 in SESSION_REGISTER state.

2025-12-29 11:08:46.506 thread(3) tag(0) INFO session_register:706 Starting.

2025-12-29 11:08:46.506 thread(3) tag(0) INFO send_eip_request:1876 Starting.

2025-12-29 11:08:46.506 thread(3) tag(0) INFO send_eip_request:1889 Sending packet of size 28

2025-12-29 11:08:46.506 thread(3) tag(0) INFO send_eip_request:1890 00000 65 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00

2025-12-29 11:08:46.506 thread(3) tag(0) INFO send_eip_request:1890 00016 00 00 00 00 00 00 00 00 01 00 00 00

2025-12-29 11:08:46.507 thread(3) tag(0) DETAIL socket_write:1945 Starting.

2025-12-29 11:08:46.507 thread(3) tag(0) DETAIL socket_write:2072 Done: result = 28.

2025-12-29 11:08:46.507 thread(3) tag(0) INFO send_eip_request:1932 Done.

2025-12-29 11:08:46.507 thread(3) tag(0) INFO recv_eip_response:1952 Starting.

2025-12-29 11:08:46.507 thread(3) tag(0) DETAIL socket_read:1807 Starting.

2025-12-29 11:08:46.507 thread(3) tag(0) DETAIL socket_read:1836 Immediate read attempt did not succeed, now wait for select().

2025-12-29 11:08:46.508 thread(3) tag(0) DETAIL socket_read:1864 Socket can read data.

2025-12-29 11:08:46.509 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 24.

2025-12-29 11:08:46.509 thread(3) tag(0) DETAIL socket_read:1807 Starting.

2025-12-29 11:08:46.509 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 4.

2025-12-29 11:08:46.509 thread(3) tag(0) INFO recv_eip_response:2023 request received all needed data (28 bytes of 28).

2025-12-29 11:08:46.509 thread(3) tag(0) INFO recv_eip_response:2025 00000 65 00 04 00 0a 00 13 00 00 00 00 00 00 00 00 00

2025-12-29 11:08:46.509 thread(3) tag(0) INFO recv_eip_response:2025 00016 00 00 00 00 00 00 00 00 01 00 00 00

2025-12-29 11:08:46.510 thread(3) tag(0) INFO recv_eip_response:2032 Done.

2025-12-29 11:08:46.510 thread(3) tag(0) INFO session_register:773 Done. 

Pretty fast response time.  About 1 millisecond.  So there is a PLC there and it is responding at least at the EIP level.

Then things go off the rails.  We try to send a Forward Open:

2025-12-29 11:08:46.510 thread(3) tag(0) INFO send_extended_forward_open_request:2259 Starting

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1876 Starting.

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1889 Sending packet of size 92

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1890 00000 6f 00 44 00 0a 00 13 00 00 00 00 00 a6 60 00 00

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1890 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1890 00032 00 00 00 00 b2 00 34 00 5b 02 20 06 24 01 0a 05

2025-12-29 11:08:46.511 thread(3) tag(0) INFO send_eip_request:1890 00048 00 00 00 00 0a 2e 00 00 3e 5c 3d f3 45 43 50 21

2025-12-29 11:08:46.512 thread(3) tag(0) INFO send_eip_request:1890 00064 01 00 00 00 40 42 0f 00 a2 0f 00 42 40 42 0f 00

2025-12-29 11:08:46.512 thread(3) tag(0) INFO send_eip_request:1890 00080 a2 0f 00 42 a3 03 01 00 20 02 24 01

2025-12-29 11:08:46.512 thread(3) tag(0) DETAIL socket_write:1945 Starting.

2025-12-29 11:08:46.512 thread(3) tag(0) DETAIL socket_write:2072 Done: result = 92.

2025-12-29 11:08:46.512 thread(3) tag(0) INFO send_eip_request:1932 Done.

2025-12-29 11:08:46.512 thread(3) tag(0) INFO send_extended_forward_open_request:2318 Done 

It all looks good. We built the Forward Open request and sent it.

But then... nothing comes back for a looooooong time:

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2023 request received all needed data (70 bytes of 70). 

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2025 00000 6f 00 2e 00 0a 00 13 00 00 00 00 00 a6 60 00 00

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2025 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2025 00032 00 00 00 00 b2 00 1e 00 db 00 00 00 fd 4e f3 ff

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2025 00048 0a 2e 00 00 3e 5c 3d f3 45 43 50 21 40 42 0f 00

2025-12-29 11:08:47.499 thread(3) tag(0) INFO recv_eip_response:2025 00064 40 42 0f 00 00 00

2025-12-29 11:08:47.500 thread(3) tag(0) INFO recv_eip_response:2032 Done.

2025-12-29 11:08:47.500 thread(3) tag(0) INFO receive_forward_open_response:2393 ForwardOpen succeeded with our connection ID 2e0a and the PLC connection ID fff34efd with packet size 4002. 

So when we registered the EIP session layer, we got a response in 1ms.  When we did a Forward Open, it took almost exactly one second to respond.  That is really slow.  Even my PLC/5 responds 4 times faster than that, usually 5 or 6x.  Based on the logs, I can see that the libplctag library is trying again and again to get data but nothing is coming in.  So that one second delay is either in the OS of the PC or in the PLC.  Given that the OS seems responsive, my guess is that it is either the network or the PLC.

To me this says that something is not right with the PLC.  Is it heavily loaded?  What kind of PLC is it?

After this weird delay, we see a tag read go through ("Gamepad"?):

2025-12-29 11:08:47.503 thread(3) tag(0) INFO send_eip_request:1889 Sending packet of size 64

2025-12-29 11:08:47.503 thread(3) tag(0) INFO send_eip_request:1890 00000 70 00 28 00 0a 00 13 00 00 00 00 00 00 00 00 00 

2025-12-29 11:08:47.503 thread(3) tag(0) INFO send_eip_request:1890 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00

2025-12-29 11:08:47.503 thread(3) tag(0) INFO send_eip_request:1890 00032 a1 00 04 00 fd 4e f3 ff b1 00 14 00 3c 22 52 05

2025-12-29 11:08:47.504 thread(3) tag(0) INFO send_eip_request:1890 00048 91 07 47 61 6d 65 70 61 64 00 01 00 00 00 00 00 

2025-12-29 11:08:47.504 thread(3) tag(0) DETAIL socket_write:1945 Starting.

2025-12-29 11:08:47.504 thread(3) tag(0) DETAIL socket_write:2072 Done: result = 64.

2025-12-29 11:08:47.504 thread(3) tag(0) INFO send_eip_request:1932 Done

2025-12-29 11:08:47.504 thread(3) tag(0) INFO recv_eip_response:1952 Starting.

2025-12-29 11:08:47.504 thread(3) tag(0) DETAIL socket_read:1807 Starting.

2025-12-29 11:08:47.504 thread(3) tag(0) DETAIL socket_read:1836 Immediate read attempt did not succeed, now wait for select().

2025-12-29 11:08:47.508 thread(3) tag(0) DETAIL socket_read:1864 Socket can read data.

2025-12-29 11:08:47.508 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 24.

2025-12-29 11:08:47.508 thread(3) tag(0) DETAIL socket_read:1807 Starting.

2025-12-29 11:08:47.508 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 32.

2025-12-29 11:08:47.508 thread(3) tag(0) INFO recv_eip_response:2023 request received all needed data (56 bytes of 56).

2025-12-29 11:08:47.508 thread(3) tag(0) INFO recv_eip_response:2025 00000 70 00 20 00 0a 00 13 00 00 00 00 00 00 00 00 00

2025-12-29 11:08:47.509 thread(3) tag(0) INFO recv_eip_response:2025 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00

2025-12-29 11:08:47.509 thread(3) tag(0) INFO recv_eip_response:2025 00032 a1 00 04 00 0a 2e 00 00 b1 00 0c 00 3c 22 d2 00

2025-12-29 11:08:47.509 thread(3) tag(0) INFO recv_eip_response:2025 00048 00 00 c4 00 00 49 02 00

2025-12-29 11:08:47.509 thread(3) tag(0) INFO recv_eip_response:2032 Done. 

So the response to a tag read of a DINT took 5ms but the response to a Forward Open took ~1000ms???

I would argue that something is not OK with either your network or your PLC. It is possible it is the PC, but the OS responds so quickly to writing data that I suspect it is OK. Plus the PC itself usually has a couple of orders of magnitude more CPU horsepower than the PLC and especially and network module (for ControlLogix).

I would suggest opening a browser to your network module: "http://192.168.1.56:80".  See what the stats say about the network module's CPU load, number of connections, packets per second etc.

Now, why are we always waiting five seconds... that is confusing, but I cannot see the start of the whole process.  

What version of the library are you using?

Best,

Kyle

[Steven Barrington]

Hi Kyle,

Thanks for taking some time to look at this, and thank you for how detailed your response was. I've been trying very hard the last few days to investigate this a bit more. Unfortunately I don't have much information considering how much time I have spent on this...

Firstly, I think the physical WiFi is in pretty good shape but I can't say 100% for sure. I found a function in the WiFi access point mirrors the radio data to WireShark but because I am not on site at the moment (and have to log in remotely) I can only monitor this from one of the clients and it is overwhelming the bandwidth. As an alternative measure, I ran a continuous ping with a fairly small timeout (500ms) to the target PLC. It was pretty good, with only the occasional timeout, and none of them in bursts. Packet loss was less than 0.5%, and there were between 20 and 50 pings every second for many hours. 

On the target PLC, I/O comms utilisation is about 1%. A few weeks ago I increased the timeslice that the PLC uses on comms to 40%. The PLC program is not that huge and it is a new CompactLogix - the scan time is something crazy small like 3us. 

On the web server for the PLC I found a page about the connections, which I found very interesting. I've attached a screenshot of a typical output of this screen (the line with the connection to the PC running the program is highlighted poorly in yellow). The uptime is related to the issue - it resets when we experience these problems (which makes sense with the data you analysed for me, the connection was reset). 

I'm not sure why the "O-T Size" (which I think means originator to target size of data) is 4002 (bytes or bits I assume) for 2 bytes of data. I'm also not sure why the RPI, API and Timeout are the values they are (it could have something to do with the default values I guess). I'm wondering if because the PLC timeout is so much greater that might explain why when there is a timeout from libplctag it takes so long to reconnect. 

I'm going to try and see if tomorrow I can change the timeout on the tag from libplctag to something much bigger, like 30 seconds, and see how we go. Any other input would be much appreciated. 

[Kyle]

Thanks for the screen shot.

Anything that shows a connection class of 1 (left-most column in the image) is either IO or a produced/consumed tag.  Those have small connection buffer sizes (504 bytes) and some missed Rx (receive) packets.  The missed packet numbers look pretty high to me in view of the RPI, 500ms.  Class 1 connections use UDP instead of TCP.  They are lower latency, and can have packet loss.  Delivery of UDP packets is not guaranteed.  They are also limited in size.  Anything over 520 bytes, IIRC, can be split up by the OS and the network hardware and you increase your chances of losing a whole packet.  Hence the small size of the maximum packet size on those connections.

The connection class 3 connections are TCP and are negotiated for maximum connection size.  Libplctag always tries to get the largest buffer possible.  In this case that is 4002 bytes.  Given that it is a *Logix-class machine, it supports packing multiple requests into one large packet.  This size is just the maximum the packet can be.  That much won't be used for smaller requests.

The fact that this is on WiFi is a good data point.  I regularly test across WiFi on my home network and I see weirdly long latency spikes all the time.  It will go along at 10-30ms for a few minutes and then suddenly I'll have latency around 400ms for one blip and then back down again.  WiFi can also drop enough packets in one burst of interference to cause something to choke.  Normally TCP handles this well, but libplctag tries to keep the resource use on the PLCs low and does an internal and connection idle timeout of 5 seconds.  If you have occasional gaps of about 5 seconds, that could be triggering it.  I do not think that is what is happening though because both the OS and libplctag thinks that the TCP connection is up when it appears, after the fact, that it was not.  That is more classic of something on the other end dropping the connection.  

So one possibility I see is that various sources of packet loss and latency could combine from time to time to have a period where the PLC does not see anything for 5 seconds and then it drops the connection.  But because of the same packet loss and latency, the OS does not see this drop and still thinks that the connection is up.  Honestly this doesn't seem that likely, but I have been surprised before!

I have had it on the back burner to increase the connection timeout time that is negotiated and maybe it is time to do something about that.  I might move it to 30 seconds (currently 5).  I do not want to go more than that because the PLC will gum up with dead connections if it cannot clean them out fast enough.  Older PLCs have limits in the low tens of connections.

Is there any chance you can run a ping test over night? Looking at the other tabs in the PLC's web site might help too.  Ethernet stats and some of the other pages might have useful information that might help us understand what is going on.  Look at the CPU load just in case.  You could have a transient spike in load that was not happening when you looked at it recently.

There are some far less likely possibilities that I would leave for later like a full/half-duplex problem with the Ethernet port on a switch in between the PC and PLC.   I really hope this is not the case because you would need to get switch statistics to see if that is happening and it isn't even that obvious in those sometimes.

You may want to make a map of all the network devices between the PC and PLC and see if any of them are shared with the other connections in that screen shot.  Those other connections all have longer uptimes.

Best,

Kyle

[Steven Barrington]

Hi Kyle,

I've got some more info for you, not everything you asked for though because I'm not currently on site and they have been turning the machine off because it has been so unreliable. 

The connections with the longer uptimes are from the SCADA server querying the PLC for data (we are using FactoryTalkView). I suspect the uptimes are larger because the timeout is so big (30s) so the connection never appears to drop out. There is data from another PLC (192.168.1.20) sent from a MSG instruction and some produce/consume to this PLC and if I set the timeout really big it keeps the connection open for a long time too (but if I set the timeout smaller it resets the connection too). This other PLC is having similar comms problems as well, and I suspect the issues are related to the problem I am having with libplctag. I suspect that the WiFi drops a packet that happens to be the MSG instruction and the PLC can't handle this very well and hangs up. I suspect I have fixed the problem by manually triggering a timeout rather than waiting for the MSG instruction, but I haven't had enough time with the machine turned on to say for sure that it has been fixed. 

I changed the timeout value to 5s, 10s and 30s - it didn't change anything. The webpage on the PLC didn't show any change in the timeout values and RPI (which i thought was a bit odd), and kept to the same values as on the previous screenshot that I sent you. 

I managed to take a few more log captures yesterday. This was taken over about half an hour, and these are excerpts that I have pulled out to just before when it appears that the connection to the PLC dropped out. Are these showing the same behaviour that you saw before?

Thanks

Matt

[Kyle]

Hmm, the data point that other machines are losing connections too is useful. That definitely indicates that problems exist either on the PLC or in the network near it.

I think at this point I need to do a release of libplctag with the allowable timeout set to at least 30 seconds instead of 5.

I'll read through these logs and see if anything pops up.

Best,

Kyle

[Kyle]

I release version 2.6.14 today that defaults to 30 seconds for the timeout instead of 5.   Try that and see if it helps!  Thanks for bringing this up!

Best,

Kyle