Re: Frequent disconnect and auto-reconnects with Serial ASYN and Stream controlled device

["Zimoch Dirk \(PSI\) via Tech-talk" <tech-talk at aps.anl.gov>]

StreamDevice only disconnects when disconnect is explicitly called in a protocol. Like in 
protocol { out "something"; in "%s"; disconnect; }



On Tue, 2022-02-22 at 14:14 +0000, Mark Rivers via Tech-talk wrote:
> Note that streamDevice does have code that calls pasynManager->queueRequest to disconnect the device:
> 
> https://github.com/paulscherrerinstitute/StreamDevice/blob/94721c2b0e2ae118778d5783bd35cc642f573f60/src/AsynDriverInterface.cc#L1427
> 
> I have not determined where that code is callled from.
> 
> If you enable debugging in streamDevice then you can determine if this code is indeed where pasynManager->queueRequest 
> is being callled to disconnect the device.
> 
> Mark
> 
> 
> From: Mark Rivers <rivers at cars.uchicago.edu>
> Sent: Tuesday, February 22, 2022 8:02 AM
> To: Ashish Sharma <ashish.sharma at iuac.res.in>; tech-talk <tech-talk at aps.anl.gov>
> Subject: Re: Frequent disconnect and auto-reconnects with Serial ASYN and Stream controlled device
>  
> Hi Ashish,
> 
> These messages are the key to understanding the problem.
> 
> 2022/02/17 20:53:15.404 SERIALPORT addr -1 queueRequest priority 3 from lockHolder
> 2022/02/17 20:53:15.404 asynManager connect queueCallback port:SERIALPORT
> 2022/02/17 20:53:15.404 /dev/magnetPSC disconnect
> 2022/02/17 20:53:15.404 Close /dev/magnetPSC connection.
> 
> The first message means that some software has called pasynManager->queueRequest with a priority 3 request.  It is
> printed in this line:
> https://github.com/epics-modules/asyn/blob/a2f59505766f5a19af1afb325fc84b3a1d77552f/asyn/asynDriver/asynManager.c#L1569
> 
> This is the definition of the priorities:
> 
> typedef enum {
>     asynQueuePriorityLow,asynQueuePriorityMedium,asynQueuePriorityHigh,
>     asynQueuePriorityConnect
> }asynQueuePriority;
> 
> So priority 3 is asynQueuePriorityConnect, i.e. specifically a request to disconnect or connect the device.  Clearly
> in this case it is being asked to disconnect the device.
> 
> The second message means that queueRequest has reached the head of the queue and is being executed.  It is printed in
> this line:
> https://github.com/epics-modules/asyn/blob/a2f59505766f5a19af1afb325fc84b3a1d77552f/asyn/asynDriver/asynManager.c#L817
> 
> That results in the drvAsynSerialPort::disconnect() function being called and printing the third message above:
> https://github.com/epics-modules/asyn/blob/a2f59505766f5a19af1afb325fc84b3a1d77552f/asyn/drvAsynSerial/drvAsynSerialPort.c#L719
> 
> That results in the drvAsynSerialPort::closeConnection() function being called and printing the fourth message above:
> https://github.com/epics-modules/asyn/blob/a2f59505766f5a19af1afb325fc84b3a1d77552f/asyn/drvAsynSerial/drvAsynSerialPort.c#L596
> 
> So it appears to me that the disconnect request is being explicitly requested by software outside of asynManager or
> drvAsynSerialPort.  It could be streamDevice, or an asynRecord or other asyn client.
> 
> Mark
> 
> 
> 
> 
> From: Ashish Sharma <ashish.sharma at iuac.res.in>
> Sent: Tuesday, February 22, 2022 12:37 AM
> To: Mark Rivers <rivers at cars.uchicago.edu>; tech-talk <tech-talk at aps.anl.gov>
> Subject: Frequent disconnect and auto-reconnects with Serial ASYN and Stream controlled device
>  
> Hello,
> 
> I have a magnet PS controller which is a Raspberry Pi machine with an IOC server. This server connects to multiple
> RS232 controlled magnet power supplies. The st.cmd file is as follows:
> 
> *********************************************************************************************************************
> !../../bin/linux-arm/magnetPSControlIOC
> 
> #- You may have to change magnetPSControlIOC to something else
> #- everywhere it appears in this file
> 
> < envPaths
> epicsEnvSet(STREAM_PROTOCOL_PATH,"/root/Apps/epics/magnetPSControlIOC/magnetPSControlIOCApp/Db")
> 
> cd "${TOP}"
> 
> ## Register all support components
> dbLoadDatabase "dbd/magnetPSControlIOC.dbd"
> magnetPSControlIOC_registerRecordDeviceDriver pdbbase
> 
> ## Configure the Serial Port
> drvAsynSerialPortConfigure("SERIALPORT","/dev/magnetPSC",0,0,0)
> asynSetOption("SERIALPORT",-1,"baud","500000")
> asynSetOption("SERIALPORT",-1,"bits","8")
> asynSetOption("SERIALPORT",-1,"parity","none")
> asynSetOption("SERIALPORT",-1,"stop","1")
> asynSetOption("SERIALPORT",-1,"clocal","Y")
> asynSetOption("SERIALPORT",-1,"crtscts","N")
> 
> ## Load record instances
> dbLoadRecords("db/magnetPSC.db","PORT=SERIALPORT")
> 
> asynSetTraceMask( "SERIALPORT",0,255)
> 
> cd "${TOP}/iocBoot/${IOC}"
> iocInit
> 
> *******************************************************************************************************
> 
> the .db and .proto file entries are as follows:
> 
> record(bo, PS1:on) {
>         field(DESC, "Turn ON Power Supply 1")
>         field(DTYP, "stream")
>         field(OUT, "@magnetPSC.proto turnON_PS(1) $(PORT)")
>         field(ONAM, "1")
>         field(ZNAM, "0")
>         field(PINI, "NO")
> }
> 
> record(bo, PS1:off) {
>         field(DESC, "Turn OFF Power Supply 1")
>         field(DTYP, "stream")
>         field(OUT, "@magnetPSC.proto turnOFF_PS(1) $(PORT)")
>         field(ONAM, "1")
>         field(ZNAM, "0")
>         field(PINI, "NO")
> }
> 
> *****************************************************************************************************
> turnOFF_PS {
>         out 250 $1;
>         out "F";
>         wait 300;
>         in "X:";
>         in "OK";
>         ExtraInput = Ignore;
> }
> 
> turnON_PS {
>         out 250 $1;
>         out "N";
>         wait 300;
>         in "X:";
>         in "OK";
>         ExtraInput = Ignore;
> }
> 
> *********************************************************************************
> 
> If I do repeated ON / OFF from the GUI, the SERIALPORT gets disconnected and after some time get auto-reconnected. It
> makes this controller very unreliable. With asynSetTraceMask being set, following are the traces I am getting. I can
> see, if I do quick ON/OFF or even do fast analog write (not shown here), then port goes into not connected or
> disconnected mode. After some time it automatically gets connected.
> 
> 
> *************************************************************************************
> 2022/02/17 20:53:15.105 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
> 2022/02/17 20:53:15.105 SERIALPORT schedule queueRequest timeout in 5.000000 seconds
> 2022/02/17 20:53:15.106 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.106 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
> 2022/02/17 20:53:15.106 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
> 2022/02/17 20:53:15.106 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.106 /dev/magnetPSC read.
> 2022/02/17 20:53:15.106 /dev/magnetPSC read 0, return 1
> 2022/02/17 20:53:15.106 SERIALPORT read from low-level driver returned 1
> 2022/02/17 20:53:15.106 SERIALPORT get Eos 0
> 
> 2022/02/17 20:53:15.107 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.107 /dev/magnetPSC write.
> 2022/02/17 20:53:15.107 /dev/magnetPSC write 3
> 
> 2022/02/17 20:53:15.107 wrote 3 to /dev/magnetPSC, return asynSuccess
> 2022/02/17 20:53:15.107 SERIALPORT wrote
> 
> 2022/02/17 20:53:15.107 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.107 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
> 2022/02/17 20:53:15.108 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
> 2022/02/17 20:53:15.108 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.108 /dev/magnetPSC read.
> 2022/02/17 20:53:15.108 /dev/magnetPSC read 0, return 1
> 2022/02/17 20:53:15.108 SERIALPORT read from low-level driver returned 1
> 2022/02/17 20:53:15.108 SERIALPORT get Eos 0
> 
> 2022/02/17 20:53:15.108 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.108 /dev/magnetPSC write.
> 2022/02/17 20:53:15.108 /dev/magnetPSC write 2
> 
> 2022/02/17 20:53:15.109 wrote 2 to /dev/magnetPSC, return asynSuccess
> 2022/02/17 20:53:15.109 SERIALPORT wrote
> 
> 2022/02/17 20:53:15.109 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.404 SERIALPORT addr -1 queueRequest priority 3 from lockHolder
> 2022/02/17 20:53:15.404 asynManager connect queueCallback port:SERIALPORT
> 2022/02/17 20:53:15.404 /dev/magnetPSC disconnect
> 2022/02/17 20:53:15.404 Close /dev/magnetPSC connection.
> 2022/02/17 20:53:15.421699 scanOnce PS1:on lockRequest: port SERIALPORT not connected
> 2022/02/17 20:53:15.427 SERIALPORT addr -1 queueRequest priority 3 not lockHolder
> 2022/02/17 20:53:15.427 asynManager connect queueCallback port:SERIALPORT
> 2022/02/17 20:53:15.427 Open connection to /dev/magnetPSC
> 2022/02/17 20:53:15.428 Opened connection to /dev/magnetPSC
> 2022/02/17 20:53:15.633 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
> 2022/02/17 20:53:15.633 SERIALPORT schedule queueRequest timeout in 5.000000 seconds
> 2022/02/17 20:53:15.633 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.633 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
> 2022/02/17 20:53:15.634 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
> 2022/02/17 20:53:15.634 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.634 /dev/magnetPSC read.
> 2022/02/17 20:53:15.634 /dev/magnetPSC read 0, return 1
> 2022/02/17 20:53:15.634 SERIALPORT read from low-level driver returned 1
> 2022/02/17 20:53:15.634 SERIALPORT get Eos 0
> 
> 2022/02/17 20:53:15.634 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.634 /dev/magnetPSC write.
> 2022/02/17 20:53:15.634 /dev/magnetPSC write 3
> 
> 2022/02/17 20:53:15.635 wrote 3 to /dev/magnetPSC, return asynSuccess
> 2022/02/17 20:53:15.635 SERIALPORT wrote
> 
> 2022/02/17 20:53:15.635 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.635 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
> 2022/02/17 20:53:15.635 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
> 2022/02/17 20:53:15.635 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.635 /dev/magnetPSC read.
> 2022/02/17 20:53:15.636 /dev/magnetPSC read 3
> 
> 2022/02/17 20:53:15.636 /dev/magnetPSC read 3, return 0
> 2022/02/17 20:53:15.636 SERIALPORT read 3 bytes eom=0
> 
> 2022/02/17 20:53:15.636 /dev/magnetPSC read.
> 2022/02/17 20:53:15.636 /dev/magnetPSC read 0, return 1
> 2022/02/17 20:53:15.636 SERIALPORT read from low-level driver returned 1
> 2022/02/17 20:53:15.636 SERIALPORT get Eos 0
> 
> 2022/02/17 20:53:15.636 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.636 /dev/magnetPSC write.
> 2022/02/17 20:53:15.636 /dev/magnetPSC write 2
> 
> 2022/02/17 20:53:15.637 wrote 2 to /dev/magnetPSC, return asynSuccess
> 2022/02/17 20:53:15.637 SERIALPORT wrote
> 
> 2022/02/17 20:53:15.637 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.932 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
> 2022/02/17 20:53:15.932 SERIALPORT schedule queueRequest timeout in 1.000000 seconds
> 2022/02/17 20:53:15.933 asynManager::portThread port=SERIALPORT callback
> 2022/02/17 20:53:15.933 SERIALPORT get Eos 0
> 
> 2022/02/17 20:53:15.933 SERIALPORT set Eos 1
> 
> 2022/02/17 20:53:15.933 /dev/magnetPSC read.
> 2022/02/17 20:53:15.933 Close /dev/magnetPSC connection.
> 2022/02/17 20:53:15.933 SERIALPORT read from low-level driver returned 3
> 2022/02/17 20:53:15.933335 SERIALPORT PS1:off: device SERIALPORT 0 disconnected
> 2022/02/17 20:53:15.933 SERIALPORT set Eos 0
> 
> 2022/02/17 20:53:15.938 SERIALPORT addr -1 queueRequest priority 3 not lockHolder
> 2022/02/17 20:53:15.938 asynManager connect queueCallback port:SERIALPORT
> 2022/02/17 20:53:15.939 Open connection to /dev/magnetPSC
> 2022/02/17 20:53:16.718964 CAS-client PS1:off lockRequest: port SERIALPORT not connected
> 2022/02/17 20:53:35.934 SERIALPORT addr -1 queueRequest priority 3 not lockHolder
> 2022/02/17 20:53:35.934 asynManager connect queueCallback port:SERIALPORT
> 2022/02/17 20:53:35.934 Open connection to /dev/magnetPSC
> 2022/02/17 20:53:35.938 Opened connection to /dev/magnetPSC
> 
> *****************************************************************************************
> 
> 
> In some of your previous posts, I tried to use PINI field with "NO", even I tried to forcibly "disconnect" in .proto
> file. But, the behavior is still the same. It is making the machine operation highly unreliable as we don't know when
> it is responding and when it is not.
> 
> I request you to Please suggest a remedy here.
> 
> My  EPICS base is 7.0.3
> ASYN-4.38
> STREAM 2.4
> 
> Thanks. 
> 
> --
> Ashish Sharma
> Inter-University Accelerator Centre, 
> New Delhi, India
>