Experimental Physics and
Industrial Control System

Dirk Zimoch via Tech-talk <[email protected]> · Fri, 15 Feb 2019 10:14:52 +0100

Hi Mark,

I tried it but I have a problem when two or more StreamDevice records

try to access the port concurrently (e.g. both scanned "1 second".

Normally they are queued by queueRequest(), but with

disconnectOnReadTimeout enabled, the second queueRequest fails with

timeout and the ports disconnects.

Need to investigate details...

Dirk

On 14.02.19 20:00, Mark Rivers wrote:

Hi Dirk,

I just did some simple tests.  I have a TCP device, and an IOC with a single asyn record.  The asyn record is reading the device temperature at 1 Hz.

I then disconnect the Ethernet cable from the device, and after some time reconnect it.

This is a test on Linux with the following conditions:

- autoConnect is true
- disconnectOnReadTimeout is not set
- ASYN_TRACE_ERROR and ASYN_TRACEIO_DRIVER are set
- Cable was disconnected for 10 seconds and then reconnected
- It took 16 seconds after reconnecting cable for communication to be restored

************************************
2019/02/14 11:54:58.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:54:58.080 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 11:54:59.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:54:59.080 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 11:55:00.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:00.080 164.54.160.165:10001 read 9             DISCONNECTED HERE
TEMP:30\r\n
2019/02/14 11:55:01.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:03.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:05.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:07.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:09.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:11.079 164.54.160.165:10001 write 7      RECONNECTED HERE
TEMP:?\r
2019/02/14 11:55:13.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:15.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:17.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:19.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:21.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:23.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:25.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:27.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:27.079 quadEMTest:asyn1: Write error, nout=0, 164.54.160.165:10001 write error: Broken pipe
2019/02/14 11:55:27.079 quadEMTest:asyn1: Error 164.54.160.165:10001 disconnected:
2019/02/14 11:55:27.079 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 disconnected:
2019/02/14 11:55:28.079 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 11:55:28.080 164.54.160.165:10001 read 9
TEMP:30\r\n
************************************

This time I set disconnectOnReadTimeout, all other settings are the same.
drvAsynIPPort disconnected on the first read timeout.
It only took 6 seconds for communications to restart after reconnecting the cable.

************************************
2019/02/14 12:12:28.717 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:12:28.718 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:12:29.717 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:12:29.718 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:12:30.717 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:12:30.718 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:12:31.717 164.54.160.165:10001 write 7  DISCONNECTED HERE
TEMP:?\r
2019/02/14 12:12:32.718 quadEMTest:asyn1: Error 164.54.160.165:10001 read error: Resource temporarily unavailable
2019/02/14 12:12:32.718 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 read error: Resource temporarily unavailable

RECONNECTED 10 seconds later, at 12:12:42

2019/02/14 12:12:48.717 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:12:48.718 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:12:49.717 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:12:49.718 164.54.160.165:10001 read 9
TEMP:30\r\n
************************************

This time I disabled disconnectOnReadTimeout, and left the cable disconnected until recv() returned 0, i.e. disconnect.
It took 16 minutes for the OS to disconnect the socket, and thus for asyn to report that the port was disconnected.
I then reconnected the cable and in about 10 seconds communication resumed.

************************************
2019/02/14 12:17:49.511 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:17:50.510 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:17:50.511 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:17:51.510 164.54.160.165:10001 write 7   DISCONNECTED HERE
TEMP:?\r
2019/02/14 12:17:53.510 164.54.160.165:10001 write 7
TEMP:?\r
...
2019/02/14 12:33:21.510 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:33:23.510 164.54.160.165:10001 write 7
TEMP:?\r                                                                                        THIS IS WHEN THE OS CLOSED THE SOCKET IT SHOWS AS DISCONNECTED
2019/02/14 12:33:24.442 quadEMTest:asyn1: Error 164.54.160.165:10001 read error: No route to host
2019/02/14 12:33:24.442 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 read error: No route to host
2019/02/14 12:33:30.460 IP_TetrAMM -1 autoConnect could not connect

Plugged cabled back in about 12:33:40.

2019/02/14 12:33:50.455 IP_TetrAMM -1 port is now connected
2019/02/14 12:33:50.510 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:33:50.511 164.54.160.165:10001 read 9
TEMP:27\r\n
2019/02/14 12:33:51.510 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:33:51.511 164.54.160.165:10001 read 9
TEMP:27\r\n
************************************

I then repeated the tests on Windows

- autoConnect is true
- disconnectOnReadTimeout is not set
- ASYN_TRACE_ERROR and ASYN_TRACEIO_DRIVER are set
- Cable was disconnected for 10 seconds and then reconnected
- It took 7 seconds after reconnecting cable for communication to be restored

************************************
2019/02/14 12:45:59.944 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:45:59.947 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:46:00.944 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:00.947 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:46:01.944 164.54.160.165:10001 write 7   DISCONNECTED HERE
TEMP:?\r
2019/02/14 12:46:03.946 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:05.946 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:07.945 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:09.944 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:11.944 164.54.160.165:10001 write 7  RECONNECTED HERE
TEMP:?\r
2019/02/14 12:46:13.946 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:15.946 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:17.945 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:17.950 quadEMTest:asyn1: Error 164.54.160.165:10001 read error: Unknown error
2019/02/14 12:46:17.950 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 read error: Unknown error
2019/02/14 12:46:18.944 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:46:18.949 164.54.160.165:10001 read 9
TEMP:30\r\n
************************************

This time I set disconnectOnReadTimeout, all other settings are the same.
drvAsynIPPort disconnected on the first read timeout.
It took about 7 seconds for communications to restart after reconnecting the cable.

************************************
2019/02/14 12:49:25.316 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:25.320 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:26.316 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:26.319 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:27.315 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:27.319 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:28.314 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:28.318 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:29.314 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:29.318 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:30.313 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:30.316 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:49:31.314 164.54.160.165:10001 write 7  DISCONNECTED HERE
TEMP:?\r
2019/02/14 12:49:32.317 quadEMTest:asyn1: Error 164.54.160.165:10001 read error: Unknown error
2019/02/14 12:49:32.317 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 read error: Unknown error

Reconnected cable at 12:39:42

2019/02/14 12:49:54.317 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:49:54.321 164.54.160.165:10001 read 9
TEMP:30\r\n
************************************

This time I disabled disconnectOnReadTimeout, and left the cable disconnected until recv() returned 0, i.e. disconnect.
It only took 20 seconds for the OS to disconnect the socket, and thus for asyn to report that the port was disconnected.
I then reconnected the cable and in about 11 seconds communication resumed.

************************************
2019/02/14 12:53:29.724 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:29.728 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:53:30.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:30.728 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:53:31.724 164.54.160.165:10001 write 7  DISCONNECTED HERE
TEMP:?\r
2019/02/14 12:53:33.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:35.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:37.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:39.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:41.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:43.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:45.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:47.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:49.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:53:50.629 quadEMTest:asyn1: Error 164.54.160.165:10001 read error: Unknown error
2019/02/14 12:53:50.630 quadEMTest:asyn1: error  nread 0 164.54.160.165:10001 read error: Unknown error

Reconnected the cable at ~12:54:00

2019/02/14 12:54:11.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:54:11.729 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:54:12.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:54:12.730 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:54:13.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:54:13.730 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:54:14.725 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:54:14.729 164.54.160.165:10001 read 9
TEMP:30\r\n
2019/02/14 12:54:15.723 164.54.160.165:10001 write 7
TEMP:?\r
2019/02/14 12:54:15.727 164.54.160.165:10001 read 9
TEMP:30\r\n
************************************

So the bottom line is that Linux takes about 16 minutes to disconnect the socket when the cable is disconnected.  Windows only takes 20 seconds.

If you set disconnectOnReadTimeout it will immediately disconnect the socket on the first read timeout.  But if autoConnect is true it will keep trying to reconnect on each read or write operation, so it will quickly reconnect when the device is available again.

Mark

-----Original Message-----
From: Mark Rivers
Sent: Thursday, February 14, 2019 11:42 AM
To: 'Dirk Zimoch' <[email protected]>; Torsten Bögershausen <[email protected]>
Cc: [email protected]
Subject: RE: How to detect AsynIPPort disconnect?

Well, not quite what I am looking for. A single read timeout may be cause by a device that is busy or just slow.

But if you set autoConnect=true then even though it disconnected on the read timeout, it will automatically try to reconnect on the next asyn write or read operation, so do you care that it disconnected?

I am going to set up a simple TCP device and do some experiments with disconnectOnReadTimeout, both on Linux and Windows.

Mark

-----Original Message-----
From: Dirk Zimoch <[email protected]>
Sent: Thursday, February 14, 2019 10:11 AM
To: Mark Rivers <[email protected]>; Torsten Bögershausen <[email protected]>
Cc: [email protected]
Subject: Re: How to detect AsynIPPort disconnect?

Hi Mark, Torsten,

On 14.02.19 12:38, Torsten Bögershausen wrote:

What happens then ?

Then the port goes to disconnect state (as shown by dbior) and the exception callback triggers. Also all further read/write commands fail.

Later asyn versions (including 4.34) have an option
"disconnectOnReadTimeout"

Well, not quite what I am looking for. A single read timeout may be cause by a device that is busy or just slow.

On 14.02.19 14:14, Mark Rivers wrote:

Hi Dirk,

The problem you are seeing is due to the behavior of the behavior of recv() on your particular OS.  This is from the man page for recv():

My particular OS is Scientific Linux 6.10.

***************

RETURN VALUE
         These calls return the number of bytes received, or -1 if an error occurred.  In the event of an error, errno is set to indicate the error.  The return value will be 0 when the peer  has  performed an orderly shutdown.

ERRORS
         These are some standard errors generated by the socket layer.  Additional errors may be generated and returned from the underlying protocol modules; see their manual pages.

         EAGAIN or EWOULDBLOCK
                The  socket  is marked nonblocking and the receive operation would block, or a receive timeout had been set and the timeout expired before data was received.  POSIX.1-2001 allows either error to be returned for this case, and does not require these constants to have the same value, so a portable application should check for both possibilities.

***************

For 15 minutes recv() is returning -1 with SOCKERRNO=EAGAIN, EINTR, or EWOULDBLOCK. After 15 minutes recv() finally returns 0, which according to man recv means the peer has performed an orderly shutdown.  Is this on Linux?  The last time I remember testing on Windows the time before recv() returns 0 was much shorter, 30 seconds I think.

It may as well be that for 15 minutes the SendQ of the socket fills up and only when it overflows I get an error.

Also the device does not perform an orderly shutdown.

With devices that shut down their socket this problem does not exist. At least not at this extent. The next send or recv will fail on an orderly shut down connection. (Unfortunately when you don't communicate, you don't know that the connection is closed. E.g. HTTP messages where the server closes the connection after sending the page are only detected when accessing them the next time. Hence the need for the "http"
protocol option in drvAsynIPPortConfigure.)

In my case I simply power off the device. So the socket becomes unresponsive.

Would the SO_KEEPALIVE socket option be a solution (accessible via asynSetOption)?

Dirk

As Torsten suggested, you can use asynSetOption to set the option DisconnectOnReadTimeout=Y.  That way any time a read operation times out it will disconnect the port.  This was added in asyn R4-29.

The following table summarizes the drvAsynIPPort driver asynSetOption keys and values.

Key     Value   Description
disconnectOnReadTimeout N Y     Default=N. If Y then if a read operation times out the driver automatically disconnect the IP port.
hostInfo        <host>:<port>[:localPort] [protocol]    The IP port hostInfo specification using the same syntax as drvAsynIPPortConfigure. This option allows changing at run time the Internet host and port to which this asyn port is connected. The only restriction is that the setting of the COM (TELNET RFC 2217) protocol cannot be changed from that specified with drvAsynIPPortConfigure. This is because if COM is specified in the drvAsynIPPortConfigure command then asynOctet and asynOption interpose interfaces are used, and asynManager does not support removing interpose interfaces.

In addition to these key/value pairs if the COM protocol is used then the drvAsynIPPort driver uses the same key/value pairs as the drvAsynSerialPort driver for specifying the serial parameters, i.e. "baud", "bits", etc.

Mark

________________________________
From: [email protected] <[email protected]> on
behalf of Torsten Bögershausen via Tech-talk <[email protected]>
Sent: Thursday, February 14, 2019 5:38 AM
To: Dirk Zimoch
Cc: EPICS
Subject: Re: How to detect AsynIPPort disconnect?

Am 14.02.2019 um 11:51 schrieb Dirk Zimoch via Tech-talk <[email protected]>:

Hello,

I have a network device connected with drvAsynIPPort. When I switch off the device, the asyn port stays in "connected" state for about 15 minutes.

What happens then ?

Writes to the device report no error, reads time out of course. But the port is still shown as connected. I have an exceptionCallback installed, but that is not triggered.

Later asyn versions (including 4.34) have an option
"disconnectOnReadTimeout"

How can I make asyn find out within a reasonable time if the device is still connected?

Stolen from asynRecord.c:

      case asynRecordDRTO:
          status = pasynRecPvt->pasynOption->setOption(pasynRecPvt->asynOptionPvt,
             pasynUser, "disconnectOnReadTimeout", drto_choices[pasynRec->drto]);
          break;

Using asyn 4.34 and EPICS 7.0.1.

Dirk

HTH

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System