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

[Ashish Sharma via Tech-talk <tech-talk at aps.anl.gov>]

Hi Mark, and Zimoch,

After hard reset of the server and subsequently running it for the last few days, I have not encountered any such problems. So, in a way the problem was with the RS232 adapter on the CA server which got fixed upon hard reset.
Thank you for your help in diagnosis. All the logs are clear not now and no unnecessary "disconnect" is seen.

Thanks.
Ashish  

----- Original Message -----
From: "Zimoch Dirk, PSI" <dirk.zimoch at psi.ch>
To: "Mark Rivers" <rivers at cars.uchicago.edu>, "Ashish Sharma" <ashish.sharma at iuac.res.in>, "tech-talk" <tech-talk at aps.anl.gov>
Sent: Tuesday, February 22, 2022 10:21:54 PM
Subject: Re: Frequent disconnect and auto-reconnects with Serial ASYN and Stream controlled device

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
>