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

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

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