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

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

Hello Zimoch,

/dev/magnetPSC is a udev rule for ttyACM0: SUBSYSTEM=="tty", ATTRS{idVendor}=="04d8", ATTRS{idProduct}=="00df", SYMLINK+="magnetPSC"

There is a custom firmware running on Raspberry Pi which is converting the commands and sending them via RS232 interface. We have been using them over our own C based Client-Server control system and such an abrupt disconnection-reconnetion problem has not been reported. We are now trying to migrate our control system to EPICS.

I tried to make changes in AsynDriverInterface.cc as per your suggestion to get detailed errors. I still don't see the detailed errors. I am not sure who is forcing the serial connection to be closed?

Now the traces appear like the following when I used /dev/ttyACM0 instead of udev rule:

********************************************************************
epics> 2022/02/18 00:38:34.676 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
2022/02/18 00:38:34.676 SERIALPORT schedule queueRequest timeout in 5.000000 seconds
2022/02/18 00:38:34.677 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:34.677 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
2022/02/18 00:38:34.677 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
2022/02/18 00:38:34.677 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:34.677 /dev/ttyACM0 read.
2022/02/18 00:38:34.677 /dev/ttyACM0 read 7

2022/02/18 00:38:34.678 /dev/ttyACM0 read 7, return 0
2022/02/18 00:38:34.678 SERIALPORT read 7 bytes eom=0

2022/02/18 00:38:34.678 /dev/ttyACM0 read.
2022/02/18 00:38:34.678 /dev/ttyACM0 read 0, return 1
2022/02/18 00:38:34.678 SERIALPORT read from low-level driver returned 1
2022/02/18 00:38:34.678 SERIALPORT get Eos 0

2022/02/18 00:38:34.678 SERIALPORT set Eos 0

2022/02/18 00:38:34.678 /dev/ttyACM0 write.
2022/02/18 00:38:34.678 /dev/ttyACM0 write 3

2022/02/18 00:38:34.679 wrote 3 to /dev/ttyACM0, return asynSuccess
2022/02/18 00:38:34.679 SERIALPORT wrote

2022/02/18 00:38:34.679 SERIALPORT set Eos 0

2022/02/18 00:38:34.679 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
2022/02/18 00:38:34.679 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
2022/02/18 00:38:34.679 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:34.679 /dev/ttyACM0 read.
2022/02/18 00:38:34.680 /dev/ttyACM0 read 0, return 1
2022/02/18 00:38:34.680 SERIALPORT read from low-level driver returned 1
2022/02/18 00:38:34.680 SERIALPORT get Eos 0

2022/02/18 00:38:34.680 SERIALPORT set Eos 0

2022/02/18 00:38:34.680 /dev/ttyACM0 write.
2022/02/18 00:38:34.680 /dev/ttyACM0 write 2

2022/02/18 00:38:34.680 wrote 2 to /dev/ttyACM0, return asynSuccess
2022/02/18 00:38:34.680 SERIALPORT wrote

2022/02/18 00:38:34.680 SERIALPORT set Eos 0

2022/02/18 00:38:34.976 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
2022/02/18 00:38:34.976 SERIALPORT schedule queueRequest timeout in 1.000000 seconds
2022/02/18 00:38:34.976 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:34.976 SERIALPORT get Eos 0

2022/02/18 00:38:34.976 SERIALPORT set Eos 1

2022/02/18 00:38:34.977 /dev/ttyACM0 read.
2022/02/18 00:38:34.977 /dev/ttyACM0 read 6

2022/02/18 00:38:34.977 /dev/ttyACM0 read 6, return 0
2022/02/18 00:38:34.977 SERIALPORT read 6 bytes eom=0

2022/02/18 00:38:34.977 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
2022/02/18 00:38:34.977 SERIALPORT schedule queueRequest timeout in 1.000000 seconds
2022/02/18 00:38:34.977 SERIALPORT set Eos 0

2022/02/18 00:38:34.977 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:34.978 SERIALPORT get Eos 0

2022/02/18 00:38:34.978 SERIALPORT set Eos 1

2022/02/18 00:38:34.978 SERIALPORT set Eos 0

2022/02/18 00:38:35.432 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
2022/02/18 00:38:35.432 SERIALPORT schedule queueRequest timeout in 5.000000 seconds
2022/02/18 00:38:35.432 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:35.432 SERIALPORT addr -1 queueRequest priority 0 not lockHolder
2022/02/18 00:38:35.433 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
2022/02/18 00:38:35.433 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:35.433 /dev/ttyACM0 read.
2022/02/18 00:38:35.433 /dev/ttyACM0 read 0, return 1
2022/02/18 00:38:35.433 SERIALPORT read from low-level driver returned 1
2022/02/18 00:38:35.433 SERIALPORT get Eos 0

2022/02/18 00:38:35.433 SERIALPORT set Eos 0

2022/02/18 00:38:35.433 /dev/ttyACM0 write.
2022/02/18 00:38:35.434 /dev/ttyACM0 write 3

2022/02/18 00:38:35.434 wrote 3 to /dev/ttyACM0, return asynSuccess
2022/02/18 00:38:35.434 SERIALPORT wrote

2022/02/18 00:38:35.434 SERIALPORT set Eos 0

2022/02/18 00:38:35.434 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
2022/02/18 00:38:35.434 SERIALPORT schedule queueRequest timeout in 0.100000 seconds
2022/02/18 00:38:35.434 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:35.434 /dev/ttyACM0 read.
2022/02/18 00:38:35.434 /dev/ttyACM0 read 0, return 1
2022/02/18 00:38:35.435 SERIALPORT read from low-level driver returned 1
2022/02/18 00:38:35.435 SERIALPORT get Eos 0

2022/02/18 00:38:35.435 SERIALPORT set Eos 0

2022/02/18 00:38:35.435 /dev/ttyACM0 write.
2022/02/18 00:38:35.435 /dev/ttyACM0 write 2

2022/02/18 00:38:35.435 wrote 2 to /dev/ttyACM0, return asynSuccess
2022/02/18 00:38:35.435 SERIALPORT wrote

2022/02/18 00:38:35.435 SERIALPORT set Eos 0

2022/02/18 00:38:35.731 SERIALPORT addr -1 queueRequest priority 0 from lockHolder
2022/02/18 00:38:35.731 SERIALPORT schedule queueRequest timeout in 1.000000 seconds
2022/02/18 00:38:35.731 asynManager::portThread port=SERIALPORT callback
2022/02/18 00:38:35.731 SERIALPORT get Eos 0

2022/02/18 00:38:35.731 SERIALPORT set Eos 1

2022/02/18 00:38:35.731 /dev/ttyACM0 read.
2022/02/18 00:38:35.732 Close /dev/ttyACM0 connection.
2022/02/18 00:38:35.732 SERIALPORT read from low-level driver returned 3
2022/02/18 00:38:35.731998 SERIALPORT PS1:off: device SERIALPORT 0 disconnected
2022/02/18 00:38:35.732 SERIALPORT set Eos 0

2022/02/18 00:38:35.737 SERIALPORT addr -1 queueRequest priority 3 not lockHolder
2022/02/18 00:38:35.737 asynManager connect queueCallback port:SERIALPORT
2022/02/18 00:38:35.737 Open connection to /dev/ttyACM0
2022/02/18 00:38:36.300795 CAS-client PS1:on lockRequest: port SERIALPORT not connected
2022/02/18 00:38:37.830841 CAS-client PS1:off lockRequest: port SERIALPORT not connected
2022/02/18 00:38:55.732 SERIALPORT addr -1 queueRequest priority 3 not lockHolder
2022/02/18 00:38:55.733 asynManager connect queueCallback port:SERIALPORT
2022/02/18 00:38:55.733 Open connection to /dev/ttyACM0
2022/02/18 00:38:55.736 Opened connection to /dev/ttyACM0

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

Please help.


Thanks.
-
Ashish


----- Original Message -----
From: "Zimoch Dirk (PSI)" 
To: "Ashish Sharma" , "Mark Rivers" , "tech-talk" 
Sent: Tuesday, February 22, 2022 2:09:24 PM
Subject: Re: Frequent disconnect and auto-reconnects with Serial ASYN and Stream controlled device

Hello Ashish,

The messages

2022/02/17 20:53:15.933 /dev/magnetPSC read
2022/02/17 20:53:15.933 Close /dev/magnetPSC connection.

both come from drvAsynSerialPort.c. In its readIt() function, I see that is prints "<portname> read" at the beginning.
It then should have shown "<portname> read , return " but doesn't. Instread it seems to go into
the error branch which then calls closeConnection().

The next message
2022/02/17 20:53:15.933 SERIALPORT read from low-level driver returned 3

comes from asynInterposeEos.c, reporting an error while trying to read the terminator.

Unfortunately StreamDevice does not print any error message from asyn in the case that read() fails and the device ends
up disconnected (AsynDriverInterface.cc line 1083). Maybe you want to change the code to see the error message:

diff --git a/src/AsynDriverInterface.cc b/src/AsynDriverInterface.cc
index 312324b..91c12df 100644
--- a/src/AsynDriverInterface.cc
+++ b/src/AsynDriverInterface.cc
@@ -1081,8 +1081,8 @@ readHandler()
                 break;
             case asynError:
                 if (!connected) {
-                    error("%s: device %s disconnected\n",
-                        clientName(), name());
+                    error("%s: device %s disconnected: %s\n",
+                        clientName(), name(), pasynUser->errorMessage);
                         disconnectCallback();
                 }
                 else

I suspect that there is some problem reading from your /dev/magnetPSC. However, I do not know how your magnetPSC is
supposed to behave.

Dirk


On Tue, 2022-02-22 at 12:07 +0530, Ashish Sharma via Tech-talk wrote:
> 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
>