Experimental Physics and
Industrial Control System

Mark Rivers <[email protected]> · Tue, 27 Feb 2018 14:25:08 +0000

Hi Evan,

I have tried to reproduce your problem with a very simple server, EPICS database and StreamDevice protocol file.  I cannot reproduce the problem, automatic reconnection is working fine in my test.

Here is the test configuration:

- A simple "echo" server.  I am actually using the asyn/testAsynIPServerPort application for the server, but that should not be relevant.  It is simply a TCP server that accepts connections on port 5001 and echoes back every line it receives.

- This database file, stream1.db.  It consists of a stringout record that sends the string "Hello" to the server at 1Hz and a stringin record that reads the reply.
***************************
record(stringout,"$(P)$(R)testOut") {
    field(DTYP, "stream")
    field(OUT, "@stream1.proto stringOut $(PORT) 0 0")
    field(SCAN, "1 second")
    field(VAL, "Hello")
    field(FLNK, "$(P)$(R)testIn")
}

record(stringin,"$(P)$(R)testIn") {
    field(DTYP, "stream")
    field(INP, "@stream1.proto stringIn $(PORT) 0 0")
}
***************************

- This protocol file, stream1.proto
***************************
stringOut {
   out "%s";
}

stringIn {
   in "%s";
}
***************************

This startup script, st.cmd.stream1.  It creates the drvAsynIPPort to port 5001 on my Linux server, and set the asyn trace mask to enable debugging.
***************************
< envPaths
# Tell EPICS all about the record types, device-support modules, drivers,
# etc. in this build from CARS
dbLoadDatabase("../../dbd/CARSLinux.dbd")
CARSLinux_registerRecordDeviceDriver(pdbbase)

drvAsynIPPortConfigure("ECHO","corvette.cars.aps.anl.gov:5001",0,0,0)
asynOctetSetInputEos(ECHO, 0, "\r\n")
asynOctetSetOutputEos(ECHO, 0, "\r\n")
asynSetTraceIOMask(ECHO, 0, 2)
asynSetTraceMask(ECHO, 0, 0XFF)

dbLoadRecords("stream1.db", "P=13TEST:, R=R:, PORT=ECHO")
dbLoadRecords("$(ASYN)/db/asynRecord.db", "P=13TEST:, R=asyn1, PORT=ECHO, ADDR=0, IMAX=80, OMAX=80")

iocInit
***************************

This is the output of the IOC running StreamDevice.  When I started this IOC the echo server was already running.

corvette:CARS/iocBoot/ioc13test>../../bin/linux-x86_64/CARSApp st.cmd.stream1
< envPaths
epicsEnvSet("IOC","ioc13test")
epicsEnvSet("TOP","/home/epics/devel/CARS")
epicsEnvSet("SUPPORT","/corvette/home/epics/devel")
epicsEnvSet("ALLEN_BRADLEY","/corvette/home/epics/devel/allenBradley-2-3")
epicsEnvSet("AREA_DETECTOR","/corvette/home/epics/devel/areaDetector-3-2")
...
epicsEnvSet("STREAM","/corvette/home/epics/devel/stream-2-7-7")
epicsEnvSet("TPMAC","/corvette/home/epics/devel/tpmac-3-11dls5")
epicsEnvSet("VME","/corvette/home/epics/devel/vme-2-8-2")
# Tell EPICS all about the record types, device-support modules, drivers,
# etc. in this build from CARS
dbLoadDatabase("../../dbd/CARSLinux.dbd")
CARSLinux_registerRecordDeviceDriver(pdbbase)

drvAsynIPPortConfigure("ECHO","corvette.cars.aps.anl.gov:5001",0,0,0)
asynOctetSetInputEos(ECHO, 0, "\r\n")
asynOctetSetOutputEos(ECHO, 0, "\r\n")
asynSetTraceIOMask(ECHO, 0, 2)
asynSetTraceMask(ECHO, 0, 0XFF)

dbLoadRecords("stream1.db", "P=13TEST:, R=R:, PORT=ECHO")
dbLoadRecords("/corvette/home/epics/devel/asyn-4-33/db/asynRecord.db", "P=13TEST:, R=asyn1, PORT=ECHO, ADDR=0, IMAX=80, OMAX=80")

iocInit
Starting iocInit
############################################################################
## EPICS R7.0.1.1
## EPICS Base built Jan  3 2018
############################################################################
drvStreamInit: Warning! STREAM_PROTOCOL_PATH not set. Defaults to "."
2018/02/27 08:07:30.607 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:30.607 ECHO schedule queueRequest timeout
2018/02/27 08:07:30.607 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:30.607 ECHO schedule queueRequest timeout
2018/02/27 08:07:30.607 asynManager::portThread port=ECHO callback
2018/02/27 08:07:30.607 13TEST:asyn1: asynCallbackSpecial, type=1
2018/02/27 08:07:30.607 13TEST:asyn1: getOptionCallback() port=ECHO, addr=0
2018/02/27 08:07:30.607 asynManager::portThread port=ECHO callback
2018/02/27 08:07:30.607 13TEST:asyn1: asynCallbackSpecial, type=3
2018/02/27 08:07:30.608 ECHO get Eos 2
\r\n
2018/02/27 08:07:30.608 ECHO get Eos 2
\r\n
cas warning: Configured TCP port was unavailable.
cas warning: Using dynamically assigned TCP port 37476,
cas warning: but now two or more servers share the same UDP port.
cas warning: Depending on your IP kernel this server may not be
cas warning: reachable with UDP unicast (a host's IP in EPICS_CA_ADDR_LIST)
iocRun: All initialization complete
2018-02-27T08:07:31.109 ServerContext configured with not Providers will do nothing!

epics> 2018/02/27 08:07:31.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:31.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:31.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:31.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:31.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:31.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:31.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:31.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:07:31.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:07:31.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:07:31.609 ECHO wrote
Hello\r\n
2018/02/27 08:07:31.609 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:31.610 ECHO schedule queueRequest timeout
2018/02/27 08:07:31.610 asynManager::portThread port=ECHO callback
2018/02/27 08:07:31.610 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:31.610 corvette.cars.aps.anl.gov:5001 read 7
Hello\r\n
2018/02/27 08:07:31.610 ECHO read
Hello\r\n

epics>
epics> 2018/02/27 08:07:32.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:32.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:32.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:32.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:32.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:32.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:32.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:32.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:07:32.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:07:32.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:07:32.609 ECHO wrote
Hello\r\n
2018/02/27 08:07:32.609 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:32.609 ECHO schedule queueRequest timeout
2018/02/27 08:07:32.609 asynManager::portThread port=ECHO callback
2018/02/27 08:07:32.609 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:32.609 corvette.cars.aps.anl.gov:5001 read 7
Hello\r\n
2018/02/27 08:07:32.609 ECHO read
Hello\r\n
...
2018/02/27 08:07:41.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:41.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:41.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:41.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:41.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:41.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:41.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:41.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:07:41.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:07:41.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:07:41.609 ECHO wrote
Hello\r\n

***************************
At this point I closed the echo server.  Note that StreamDevice prints error messages saying that port ECHO is not connected.
***************************

2018/02/27 08:07:41.609 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:41.609 ECHO schedule queueRequest timeout
2018/02/27 08:07:41.609 asynManager::portThread port=ECHO callback
2018/02/27 08:07:41.609 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:41.609 corvette.cars.aps.anl.gov:5001 read 0
2018/02/27 08:07:41.609 Close corvette.cars.aps.anl.gov:5001 connection (fd 6): Read from broken connection
2018/02/27 08:07:41.609 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:07:41.609 ECHO read
2018/02/27 08:07:41.614 ECHO addr -1 queueRequest priority 3 not lockHolder
2018/02/27 08:07:41.615 asynManager connect queueCallback port:ECHO
2018/02/27 08:07:41.615 Open connection to corvette.cars.aps.anl.gov:5001  reason:0  fd:-1
2018/02/27 08:07:41.615 Opened connection to corvette.cars.aps.anl.gov:5001
2018/02/27 08:07:41.615 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:07:42.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:42.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:42.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:42.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:07:42.608 ECHO schedule queueRequest timeout
2018/02/27 08:07:42.608 asynManager::portThread port=ECHO callback
2018/02/27 08:07:42.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:07:42.608 corvette.cars.aps.anl.gov:5001 read 0
2018/02/27 08:07:42.608 Close corvette.cars.aps.anl.gov:5001 connection (fd 6): Read from broken connection
2018/02/27 08:07:42.608 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:07:42.608 ECHO read
2018/02/27 08:07:42.608 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:07:42.608 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:07:42.608155 ECHO 13TEST:R:testOut: write failed because connection was closed by device
2018/02/27 08:07:42.608212 cbLow 13TEST:R:testIn readRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:42.613 ECHO addr -1 queueRequest priority 3 not lockHolder
2018/02/27 08:07:42.613 asynManager connect queueCallback port:ECHO
2018/02/27 08:07:42.613 Open connection to corvette.cars.aps.anl.gov:5001  reason:0  fd:-1
2018/02/27 08:07:43.607857 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:44.607851 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:45.607854 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:46.607887 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:47.607860 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:48.607875 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:49.607840 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:50.607871 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:51.607878 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected

***************************
Sometime around here I restarted the echo server.  StreamDevice continued to print error messages for some time, but then it automatically reconnected and things started working again.
***************************

2018/02/27 08:07:52.607871 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:53.607863 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:54.607882 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:55.607849 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:56.607837 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:57.607858 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:58.607837 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:07:59.607849 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:00.607839 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:01.607851 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:02.607852 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:02.608 ECHO addr -1 queueRequest priority 3 not lockHolder
2018/02/27 08:08:02.608 asynManager connect queueCallback port:ECHO
2018/02/27 08:08:02.608 Open connection to corvette.cars.aps.anl.gov:5001  reason:0  fd:-1
2018/02/27 08:08:02.609 Opened connection to corvette.cars.aps.anl.gov:5001
2018/02/27 08:08:02.609 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:08:03.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:03.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:03.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:03.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:03.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:03.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:03.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:03.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:08:03.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:08:03.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:08:03.609 ECHO wrote
Hello\r\n
2018/02/27 08:08:04.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:04.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:04.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:04.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:04.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:04.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:04.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:04.608 corvette.cars.aps.anl.gov:5001 read 7
Hello\r\n
2018/02/27 08:08:04.608 ECHO read
Hello\r\n
...

***************************
At this point I closed the echo server again, and restarted it a few seconds later.  Note again that StreamDevice prints the error messages, but the port reconnects and it continues normally.
***************************

2018/02/27 08:08:24.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:08:24.609 ECHO wrote
Hello\r\n
2018/02/27 08:08:25.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:25.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:25.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:25.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:25.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:25.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:25.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:25.608 corvette.cars.aps.anl.gov:5001 read 0
2018/02/27 08:08:25.608 Close corvette.cars.aps.anl.gov:5001 connection (fd 6): Read from broken connection
2018/02/27 08:08:25.608 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:08:25.608 ECHO read
2018/02/27 08:08:25.608 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:08:25.608 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:08:25.608126 ECHO 13TEST:R:testOut: write failed because connection was closed by device
2018/02/27 08:08:25.613 ECHO addr -1 queueRequest priority 3 not lockHolder
2018/02/27 08:08:25.613 asynManager connect queueCallback port:ECHO
2018/02/27 08:08:25.613 Open connection to corvette.cars.aps.anl.gov:5001  reason:0  fd:-1
2018/02/27 08:08:26.607863 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:27.607856 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:28.607836 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:29.607870 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:30.607850 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:31.607868 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:32.607850 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:33.607841 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:34.607836 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:35.607849 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:36.607865 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:37.607835 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:38.607862 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:39.607859 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:40.607851 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:41.607838 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:42.607856 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:43.607857 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:44.607863 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:45.607856 scan-1 13TEST:R:testOut lockRequest: pasynManager->queueRequest() failed: port ECHO not connected
2018/02/27 08:08:45.608 ECHO addr -1 queueRequest priority 3 not lockHolder
2018/02/27 08:08:45.608 asynManager connect queueCallback port:ECHO
2018/02/27 08:08:45.608 Open connection to corvette.cars.aps.anl.gov:5001  reason:0  fd:-1
2018/02/27 08:08:45.609 Opened connection to corvette.cars.aps.anl.gov:5001
2018/02/27 08:08:45.609 13TEST:asyn1: exception 0, asynExceptionConnect
2018/02/27 08:08:46.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:46.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:46.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:46.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:46.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:46.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:46.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:46.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:08:46.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:08:46.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
2018/02/27 08:08:46.609 ECHO wrote
Hello\r\n
2018/02/27 08:08:47.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:47.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:47.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:47.608 ECHO addr -1 queueRequest priority 0 not lockHolder
2018/02/27 08:08:47.608 ECHO schedule queueRequest timeout
2018/02/27 08:08:47.608 asynManager::portThread port=ECHO callback
2018/02/27 08:08:47.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:47.608 corvette.cars.aps.anl.gov:5001 read 7
Hello\r\n
2018/02/27 08:08:47.608 ECHO read
Hello\r\n
2018/02/27 08:08:47.608 corvette.cars.aps.anl.gov:5001 read.
2018/02/27 08:08:47.609 corvette.cars.aps.anl.gov:5001 write.
2018/02/27 08:08:47.609 corvette.cars.aps.anl.gov:5001 write 7
Hello\r\n
2018/02/27 08:08:47.609 wrote 7 to corvette.cars.aps.anl.gov:5001, return asynSuccess.
**********************************************************

So in this simple test automatically reconnect when the server shuts down and comes back up is working with StreamDevice.

I think you need to figure out what is different about your system.  Can you create a very simple protocol file and database to test your server with, like this one?

Mark

> -----Original Message-----
> From: Daykin, Evan [mailto:[email protected]]
> Sent: Monday, February 26, 2018 9:01 AM
> To: Mark Rivers <[email protected]>
> Cc: [email protected]
> Subject: RE: Asyn not automatically reconnecting
> 
> Manually reconnecting using the asyn record GUI did not work. The Shell yields:
> 2018/02/26 09:58:54.559 _TEST-RF-DCU-N0001:asyn: queueRequest failed
> 2018/02/26 09:59:00.162 _TEST-RF-DCU-N0001:asyn: special queueRequest timeout
> 
> 
> -----Original Message-----
> From: Mark Rivers [mailto:[email protected]]
> Sent: Friday, February 23, 2018 3:33 PM
> To: Daykin, Evan <[email protected]>
> Cc: [email protected]
> Subject: Re: Asyn not automatically reconnecting
> 
> I am not familiar with this. Can you show me where to find that?
> 
> There is an medm screen for the asyn record in asyn. On the master branch there is also a
> CSS screen I think.  The CNCT field let's you manually connect/disconnect.  You can do
> this with caput as well. Look at the asyn record documentation.
> 
> Mark
> 
> 
> Sent from my iPhone
> 
> On Feb 23, 2018, at 2:13 PM, Daykin, Evan
> <[email protected]<mailto:[email protected]>> wrote:
> 
> When your client shuts down it does so "cleanly", closing the socket?  It looks like it, since
> drvAsynIPPort detected the closed connection immediately, without first getting any
> timeouts, etc.
> 
> Yes, I just verified this with wireshark. The TCP connection is closed gracefully. Netstat on
> both ends shows there is no connection as well.
> 
> When the client comes back up do you see any different messages?
> No, the "...read." message just repeats extremely quickly.
> 
> When the client comes back up you can trying using the asynRecord GUI to try to manually
> reconnect.  Does that work?
> I am not familiar with this. Can you show me where to find that?
> 
> Something else interesting is that rebooting results in the correct behavior; the connection is
> re-established. However, if the controlling process on the client device is killed first, this
> issue persists.
> 
> -Evan
> 
> -----Original Message-----
> From: Mark Rivers [mailto:[email protected]]
> Sent: Friday, February 23, 2018 10:49 AM
> To: Daykin, Evan <[email protected]<mailto:[email protected]>>; tech-
> [email protected]<mailto:[email protected]>
> Subject: Re: Asyn not automatically reconnecting
> 
> Hi Evan,
> 
> 
> When your client shuts down it does so "cleanly", closing the socket?  It looks like it, since
> drvAsynIPPort detected the closed connection immediately, without first getting any
> timeouts, etc.
> 
> 
> When the client comes back up do you see any different messages?
> 
> 
> When the client comes back up you can trying using the asynRecord GUI to try to manually
> reconnect.  Does that work?
> 
> 
> Mark
> 
> 
> 
> ________________________________
> From: Daykin, Evan <[email protected]<mailto:[email protected]>>
> Sent: Friday, February 23, 2018 8:55 AM
> To: Mark Rivers; [email protected]<mailto:[email protected]>
> Subject: RE: Asyn not automatically reconnecting
> 
> 
> Here is the output from the moment I killed the connection:
> 
> 
> 
> 2018/02/23 09:51:47.086 TEST-RF-DCU-N0001 read
> 
> VALUE AMP_WATER_FLOW AMP 2 7.0049e-168\n
> 
> 2018/02/23 09:51:47.087 TEST-RF-DCU-N0001 set Eos 0
> 
> 2018/02/23 09:51:47.087 asynManager::portThread port=TEST-RF-DCU-N0001 callback
> 
> 2018/02/23 09:51:47.087 TEST-RF-DCU-N0001 addr -1 queueRequest priority 0 not
> lockHolder
> 
> 2018/02/23 09:51:47.088 TEST-RF-DCU-N0001 schedule queueRequest timeout
> 
> 2018/02/23 09:51:47.088 asynManager::portThread port=TEST-RF-DCU-N0001 callback
> 
> 2018/02/23 09:51:47.088 test-rf-dcu-n0001.cts:5001 read.
> 
> 2018/02/23 09:51:47.088 test-rf-dcu-n0001.cts:5001 read 0
> 
> 2018/02/23 09:51:47.088 Close test-rf-dcu-n0001.cts:5001 connection (fd 18): Read from
> broken connection
> 
> 2018/02/23 09:51:47.088 _TEST-RF-DCU-N0001:asyn: exception 0,
> asynExceptionConnect
> 
> 2018/02/23 09:51:47.088 TEST-RF-DCU-N0001 read
> 
> 2018/02/23 09:51:47.089 test-rf-dcu-n0001.cts:5001 read.
> 
> 2018/02/23 09:51:47.089 test-rf-dcu-n0001.cts:5001 read.
> 
> 
> 
> The last line then repeats rapidly forever.
> 
> 
> 
> 
> 
> From: Mark Rivers [mailto:[email protected]]
> Sent: Friday, February 23, 2018 9:20 AM
> To: Daykin, Evan <[email protected]<mailto:[email protected]>>; tech-
> [email protected]<mailto:[email protected]>
> Subject: RE: Asyn not automatically reconnecting
> 
> 
> 
> Can you set the asynTraceIOMask to 2 and the asynTraceMask to 0xff on that port just
> before you shut down the client?
> 
> 
> 
> From: Daykin, Evan [mailto:[email protected]]
> Sent: Friday, February 23, 2018 8:18 AM
> To: Mark Rivers
> <[email protected]<mailto:[email protected]><mailto:[email protected].
> edu>>; [email protected]<mailto:[email protected]><mailto:tech-
> [email protected]>
> Subject: RE: Asyn not automatically reconnecting
> 
> 
> 
> Hi Mark,
> 
> 
> 
> Thanks for the reply. We are using asyn 4.33-2 and Stream 2.6-3. The protocol file has a
> ReplyTimeout of 2000ms.
> 
> 
> 
> From: Mark Rivers [mailto:[email protected]]
> Sent: Thursday, February 22, 2018 6:20 PM
> To: Daykin, Evan
> <[email protected]<mailto:[email protected]><mailto:[email protected]>>;
> [email protected]<mailto:[email protected]><mailto:[email protected]>
> Subject: RE: Asyn not automatically reconnecting
> 
> 
> 
> Hi Evan,
> 
> 
> 
> Ø  We have client devices that, when remotely updated and rebooted, the IOC does not
> attempt to reconnect automatically
> 
> Ø  TEST-RF-DCU-N0001 multiDevice:No canBlock:Yes autoConnect:Yes
> 
> Ø  enabled:Yes connected:No numberConnects 1
> 
> Ø  nDevices 0 nQueued 114 blocked:No
> 
> 
> 
> The above information says that indeed autoConnect is set to Yes, and it is currently not
> connected.  The 114 entries in the queue seems strange.
> 
> 
> 
> What version of asyn and what version of StreamDevice are you using?  What you are
> observing does not seem correct.
> 
> 
> 
> What timeouts if any have you specified in your protocol file?
> 
> 
> 
> Mark
> 
> 
> 
> 
> 
> 
> 
> 
> 
> From: [email protected]<mailto:[email protected]><mailto:tech-
> [email protected]> [mailto:[email protected]] On Behalf Of Daykin,
> Evan
> Sent: Thursday, February 22, 2018 4:32 PM
> To: [email protected]<mailto:[email protected]><mailto:[email protected]>
> Subject: Asyn not automatically reconnecting
> 
> 
> 
> Hello,
> 
> 
> 
> Apologies if this has already been asked and answered. We have client devices that, when
> remotely updated and rebooted, the IOC does not attempt to reconnect automatically. Any
> records tied to it simply enter a TIMEOUT_ALARM state, and no asyn or StreamDevice
> error messages are printed.  autoConnect is not specified in drvAsynIPPortconfigure, which,
> according to the documentation, implicitly enables autoConnect/attempting to reconnect
> every 20 seconds.  Does anything else need to be done?
> 
> 
> 
> The devices are configured to communicate using Stream Device.
> 
> Relevant asyn configuration in the startup script:
> 
> -drvAsynIPPortConfigure("TEST-RF-DCU-N0001",  "test-rf-dcu-n0001.cts:5001")
> 
> 
> 
> asynReport after client is disconnected and brought back up:
> 
> TEST-RF-DCU-N0001 multiDevice:No canBlock:Yes autoConnect:Yes
> 
>    enabled:Yes connected:No numberConnects 1
> 
>    nDevices 0 nQueued 114 blocked:No
> 
>    asynManagerLock:No synchronousLock:Yes
> 
>    exceptionActive:No exceptionUsers 2 exceptionNotifys 0
> 
>    traceMask:0x1 traceIOMask:0x0 traceInfoMask:0x1
> 
>    interposeInterfaceList
> 
>        asynOctet pinterface 0x7f0a07506900 drvPvt 0x6c3720
> 
>    interfaceList
> 
>        asynCommon pinterface 0x7f0a07502650 drvPvt 0x6bfe30
> 
>        asynOption pinterface 0x7f0a07502670 drvPvt 0x6bfe30
> 
>        asynOctet pinterface 0x6bff50 drvPvt 0x6bfe30
> 
>    Port test-rf-dcu-n0001.cts:5001: Disconnected
> 
>                    fd: -1
> 
>    Characters written: 127036
> 
>       Characters read: 138000
> 
> 
> 
> -Evan

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System