RE: Network reconnection issue using modbus over asyn

[Mark Rivers via Tech-talk <tech-talk at aps.anl.gov>]

Hi Paul,

 

I was able to do some tests today.  The first device I tested was a Koyo Direct Logic 205 PLC.  I tested disconnecting the Ethernet cable for 1 minute and for 30 minutes.  I repeated each test 3 times.

 

This is the important part of the startup script.  Note that I enabled “disconnectOnReadTimeout”.  There are 5 Modbus drivers doing input operations and polling the PLC at 10 Hz.

 

drvAsynIPPortConfigure("Koyo","10.54.160.50:502",0,0,0)

asynSetOption("Koyo",0, "disconnectOnReadTimeout", "Y")

modbusInterposeConfig("Koyo",0,0)

 

# NOTE: We use octal numbers for the start address and length (leading zeros)

#       to be consistent with the PLC nomenclature.  This is optional, decimal

#       numbers (no leading zero) or hex numbers can also be used.

 

# The DL205 has bit access to the Xn inputs at Modbus offset 4000 (octal)

# Read 32 bits (X0-X37).  Function code=2.

drvModbusAsynConfigure("K1_Xn_Bit",      "Koyo", 0, 2,  04000, 040,   "UINT16",  100, "Koyo")

 

# The DL205 has bit access to the Xn words at Modbus offset 40400 (octal)

# Access the same 32 bits (X0-X37) as word inputs.  Function code=4.

drvModbusAsynConfigure("K1_Xn_In_Word",  "Koyo", 0, 4,  040400, 02,   "UINT16",  100, "Koyo")

 

# The DL205 has bit access to the Yn outputs at Modbus offset 4000 (octal)

# Read 32 bits (Y0-Y37).  Function code=1.

drvModbusAsynConfigure("K1_Yn_In_Bit",   "Koyo", 0, 1,  04000, 040,   "UINT16",  100, "Koyo")

 

# The DL205 has bit access to the Yn outputs at Modbus offset 4000 (octal)

# Write 32 bits (Y0-Y37).  Function code=5.

drvModbusAsynConfigure("K1_Yn_Out_Bit",  "Koyo", 0, 5,  04000, 040,   "UINT16",    1, "Koyo")

 

# The DL205 has bit access to the Cn bits at Modbus offset 6000 (octal)

# Access 256 bits (C0-C377) as inputs.  Function code=1.

drvModbusAsynConfigure("K1_Cn_In_Bit",   "Koyo", 0, 1,  06000, 0400,  "UINT16",  100, "Koyo")

 

# Access the same 256 bits (C0-C377) as outputs.  Function code=5.

drvModbusAsynConfigure("K1_Cn_Out_Bit",  "Koyo", 0, 5,  06000, 0400,  "UINT16",    1, "Koyo")

 

# The DL205 has bit access to the Cn words at Modbus offset 40600 (octal)

# Access 256 bits (C0-C377) as inputs.  Function code=3.

drvModbusAsynConfigure("K1_Cn_In_Word",   "Koyo", 0, 3,  040600, 020, "UINT16",  100, "Koyo")

 

# Access the same 256 bits (C0-C377) as outputs.  Function code=6.

drvModbusAsynConfigure("K1_Cn_Out_Word",  "Koyo", 0, 6,  040600, 020, "UINT16",    1, "Koyo")

 

The first disconnect was at 11:33:01.  There are 2 messages from each Modbus driver.  The first error is read or timeout, and the second is a queueRequest failure because the underlying port has disconnected after the timeout.

 

2023/11/20 11:33:01.754 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 11:33:01.810 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

2023/11/20 11:33:01.830 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

2023/11/20 11:33:01.838 drvModbusAsyn::doModbusIO port K1_Xn_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

2023/11/20 11:33:01.847 drvModbusAsyn::doModbusIO port K1_Xn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

2023/11/20 11:33:01.854 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest failed: port Koyo not connected, nwrite=0/6, nread=0

2023/11/20 11:33:01.910 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest failed: port Koyo not connected, nwrite=0/6, nread=0

2023/11/20 11:33:01.930 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest failed: port Koyo not connected, nwrite=0/6, nread=0

2023/11/20 11:33:01.938 drvModbusAsyn::doModbusIO port K1_Xn_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest failed: port Koyo not connected, nwrite=0/6, nread=0

2023/11/20 11:33:01.947 drvModbusAsyn::doModbusIO port K1_Xn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest failed: port Koyo not connected, nwrite=0/6, nread=0

 

I reconnected the cable at about 1 minute later at 11:34:01. It took an additional 85 seconds before the driver recovered.

 

2023/11/20 11:35:17.276 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit writeRead status back to normal having had 125 errors, nwrite=6/6, nread=6

2023/11/20 11:35:17.338 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit writeRead status back to normal having had 125 errors, nwrite=6/6, nread=34

2023/11/20 11:35:17.361 drvModbusAsyn::doModbusIO port K1_Cn_In_Word writeRead status back to normal having had 125 errors, nwrite=6/6, nread=34

2023/11/20 11:35:17.369 drvModbusAsyn::doModbusIO port K1_Xn_Bit writeRead status back to normal having had 125 errors, nwrite=6/6, nread=6

2023/11/20 11:35:17.377 drvModbusAsyn::doModbusIO port K1_Xn_In_Word writeRead status back to normal having had 125 errors, nwrite=6/6, nread=6

 

This is the second time I disconnected for 60 seconds.  For brevity I only show the first 2 error messages.

 

2023/11/20 11:36:13.646 drvModbusAsyn::doModbusIO port K1_Xn_In_Word error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 11:36:13.647 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

 

I reconnected the cable at about 60 seconds later at 11:37:13. It took about another 70 seconds before the driver recovered.

 

2023/11/20 11:38:22.565 drvModbusAsyn::doModbusIO port K1_Xn_In_Word writeRead status back to normal having had 119 errors, nwrite=6/6, nread=6

2023/11/20 11:38:22.573 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit writeRead status back to normal having had 119 errors, nwrite=6/6, nread=6

 

This is the third time I disconnected the cable for 60 seconds.

 

2023/11/20 11:38:53.778 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 11:38:53.785 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

 

I reconnected the cable about 60 seconds later at 11:39:55.  This time the driver recovered within about 6 seconds.

 

2023/11/20 11:40:01.096 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit writeRead status back to normal having had 63 errors, nwrite=6/6, nread=34

2023/11/20 11:40:01.110 drvModbusAsyn::doModbusIO port K1_Cn_In_Word writeRead status back to normal having had 63 errors, nwrite=6/6, nread=34

2023/11/20 11:40:01.118 drvModbusAsyn::doModbusIO port K1_Xn_Bit writeRead status back to normal having had 63 errors, nwrite=6/6, nread=6

2023/11/20 11:40:01.126 drvModbusAsyn::doModbusIO port K1_Xn_In_Word writeRead status back to normal having had 63 errors, nwrite=6/6, nread=6

2023/11/20 11:40:01.134 drvModbusAsyn::doModbusIO port K1_Yn_In_Bit writeRead status back to normal having had 63 errors, nwrite=6/6, nread=6

 

I then did 3 tests where I left the cable disconnected for 30 minutes.

 

This is the first test with 30 minute disconnect.

 

2023/11/20 11:41:08.070 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 11:41:08.077 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

2023/11/20 11:45:27.934 Koyo -1 autoConnect could not connect: Can't connect to 10.54.160.50:502: Connection timed out

 

I reconnected the cable after a little over 30 minutes.  The driver recovered in less than a minute.

 

2023/11/20 12:14:29.424 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit writeRead status back to normal having had 1821 errors, nwrite=6/6, nread=34

2023/11/20 12:14:29.438 drvModbusAsyn::doModbusIO port K1_Cn_In_Word writeRead status back to normal having had 1821 errors, nwrite=6/6, nread=34

 

This is the second test with 30 minute disconnection.

 

2023/11/20 12:15:06.041 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 12:15:06.048 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

 

The cable was reconnected about 12:45:06 and the driver recovered in a few seconds.

 

[Mon Nov 20 12:45:23 2023] 2023/11/20 12:45:23.675 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit writeRead status back to normal having had 1654 errors, nwrite=6/6, nread=34

[Mon Nov 20 12:45:23 2023] 2023/11/20 12:45:23.689 drvModbusAsyn::doModbusIO port K1_Cn_In_Word writeRead status back to normal having had 1654 errors, nwrite=6/6, nread=34

 

This is the third test with 30 minute disconnection.

 

2023/11/20 12:45:53.567 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit error calling writeRead, error=10.54.160.50:502 read error: Resource temporarily unavailable, nwrite=6/6, nread=0

2023/11/20 12:45:53.580 drvModbusAsyn::doModbusIO port K1_Cn_In_Word error calling writeRead, error=asynManager::queueLockPort queueRequest timed out, nwrite=0/6, nread=0

 

The driver recovered in less than a minute after reconnecting the cable.

 

2023/11/20 13:16:12.295 drvModbusAsyn::doModbusIO port K1_Cn_In_Bit writeRead status back to normal having had 1655 errors, nwrite=6/6, nread=34

2023/11/20 13:16:12.308 drvModbusAsyn::doModbusIO port K1_Cn_In_Word writeRead status back to normal having had 1655 errors, nwrite=6/6, nread=34

 

I also tested with a LabJack-T8 analog and digital I/O device.

 

I observed very similar behavior to the Koyo PLC in most cases.  It reconnected OK whether the disconnection was 1 minute or 30 minutes.  However, in 2 cases it would never reconnect.

When this happened I observed the following:

• Attempting a manual telnet from Linux to port 502 (Modbus port) just hung.  It did not give either a connection message or a connection refused message.  I waited several minutes and saw no response.
• Restarting the IOC did not work, it could not connect to the device.
• Only power-cycling the device fixed the problem.
• I think this indicated that the device has a bug, and that sometimes disconnecting the Ethernet cable leaves it in an unusable state. 

 

I conclude that the EPICS Modbus driver appears to be behaving correctly when the network cable is disconnected for either 1 minute or 30 minutes, since it behaves fine with the Koyo PLC.  It does fail sometimes with the Labjack device, but that is clearly a problem with the LabJack, since it requires a power-cycle to fix.

 

Your PLC may also have issues with the network stack when the Ethernet cable is disconnected, and hence the connection is not cleanly closed.

 

Mark

 

 

From: Paul Richardson - STFC UKRI <paul.richardson at stfc.ac.uk>
Sent: Friday, November 17, 2023 7:59 AM
To: Mark Rivers <rivers at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: RE: Network reconnection issue using modbus over asyn

 

Hi Mark,

Yes, this issue is caused by disconnecting the network cable at the PLC end, so the connection is not closed cleanly. Asyn.CNCT reports Disconnect, just once, the moment the cable is removed.

If I leave it disconnected for roughly up to a minute, the connection is always re-established and asyn.CNCT reports Connect, just once, as expected.

The problem only seems to occur when I leave the cable disconnected for longer, usually 5 mins or more. Sometimes upon re-connection it works Ok, but more often than not on re-connection the asyn.CNCT status repeatedly flips between Connect and Disconnect. Looking at the socket (using netstat -at) for the PLC port it reports CLOSE_WAIT, interspersed with ESTABLISHED.

I’m currently using asyn4-38 and modbus-R2-4. One of the first things I tried was using more up to date versions, so I downloaded asyn-R4-43 and modbus-R2-11, but the problem still occurred.

 

Regards

Paul

 

 

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: Friday, November 17, 2023 1:32 PM
To: Richardson, Paul (STFC,RAL,CLF) <paul.richardson at stfc.ac.uk>
Cc: tech-talk at aps.anl.gov
Subject: Re: Network reconnection issue using modbus over asyn

 

If I understand correctly this happens when you disconnect the cable. So the PLC has not cleanly closed the connection, correct? 

 

Do you see the problem when you disconnect the cable for a shorter amount of time, say 15 seconds?

 

What you should see is a single message for each asyn port that the connection is down, and then a single message when it is back up again.

 

I will test early next week to verify that is what I see.

What versions of asyn and Modbus are you using?

Mark

 

Sent from my iPhone

 

On Nov 17, 2023, at 6:50 AM, Paul Richardson - STFC UKRI via Tech-talk <tech-talk at aps.anl.gov> wrote:



Hi,

I’m having problems with an epics IOC re-establishing network connections to a PLIZ PLC, after a network cable disconnection, then reconnection 10 minutes or so later. The IOC is running on a Ubuntu 22.04 PC and communicating to the PLC using modbus interpose layer and asyn over TCP/IP.

After re-connection, the Asyn.CNCT PV repeatedly reports Connect then Disconnect. This can go on for approx. 20 mins before finally the problem resolves itself and the connection remains Connected. During this period of instability, whilst I can happily ping the PLC, the IOC is unable to read any of its values through modbus. This would make sense if the PLC has closed its socket.

When the issue occurs, I’ve examined the network socket for port 502 (the PLC port) using netstat -at | grep 502. This reports the socket is an a CLOSE_WAIT state. I understand this indicates the PLC has closed its connection, but the socket is still open at the IOC end. I’m unsure how to get asyn to recognise this situation and resolve it, maybe by closing the socket and establishing a new one?

I had hoped using asynSetOption("$(PORT)", 0, "disconnectOnReadTimeout", "Y"), would resolve the issue but it didn’t.

Other options I’ve tried include:

Adjusting the linuc tcp_keepalive_time from 7200 s (120 mins) to 20 s, using /sbin/sysctl -e net.ipv4.tcp_keepalive_time = 20, but it didn’t help

disabling/enabling asyn disconnectOnReadTimeout() and moving its position in st.cmd

varying modbusInterposeConfig() read write timeout

enabling/disabling noProcessEos in drvAsynIPPortConfigure()

but the problem remains.

 

Below is a section of my st.cmd

epicsEnvSet("DEVICE_IP", "109.0.201.1")

epicsEnvSet("DEVICE_PORT", "502")

epicsEnvSet("PORT", "PILZ")

 

drvAsynIPPortConfigure("$(PORT)","$(DEVICE_IP):$(DEVICE_PORT)",0,0,1) #IP address of simulated plc

asynSetOption("$(PORT)", 0, "disconnectOnReadTimeout", "Y")

modbusInterposeConfig("$(PORT)",0,0,0)

drvModbusAsynConfigure("BI", "$(PORT)", 0, 3, 107, 56, 0, 100, "pilz")

 

## Load record instances

dbLoadRecords("$(ASYN)/db/asynRecord.db", "P=$(SHORT_NM), R=:Asyn, PORT=$(PORT), ADDR=0, IMAX=20, OMAX=20")

 

I think the cause of the problem is the PLC closes the socket, but asyn in the IOC is leaving it open. How do I get asyn to recognise the CLOSE_WAIT status of the socket, close it then establishes a new one? I’m wondering if this may be an issue with modbus interposed in the asyn?

Any help or advice would be much appreciate, thanks.

 

Kind regards

Paul Richardson