RE: Streamdevice 2.6 autoconnection failure using drvAsynSerialPort

[Mazanec Tomáš <Tomas.Mazanec@eli-beams.eu>]

In synApps 5.7, if the usb-serial device is physically disconnected, while the IOC is running, the command:
asynReport(10, PORT) says the asyn port is still connected:

PORT multiDevice:No canBlock:Yes autoConnect:Yes
    enabled:Yes connected:Yes numberConnects 1
    nDevices 0 nQueued 0 blocked:No
    asynManagerLock:No synchronousLock:Yes
    exceptionActive:No exceptionUsers 2 exceptionNotifys 0
    interposeInterfaceList
        asynOctet pinterface 0x7fbbfb51f6a0 drvPvt 0x1489670
    interfaceList
        asynCommon pinterface 0x7fbbfb51ca80 drvPvt 0x1486740
        asynOption pinterface 0x7fbbfb51caa0 drvPvt 0x1486740
        asynOctet pinterface 0x7fbbfb51ee40 drvPvt 0x1486740
Serial line /dev/ttyUSBPIC: Connected
                    fd: 5
    Characters written: 164
       Characters read: 287

What also happens, and I didn't noticed, is IOC's process takes 100% CPU usage and traceFlow bit within traceMask in Asyn reports hundreds of these lines in a second:
2014/04/10 13:06:39.575 /dev/ttyUSBPIC read.
2014/04/10 13:06:39.575 /dev/ttyUSBPIC read.
2014/04/10 13:06:39.575 /dev/ttyUSBPIC read.
2014/04/10 13:06:39.575 /dev/ttyUSBPIC read.
2014/04/10 13:06:39.575 /dev/ttyUSBPIC read.

However, an attempt to reconnect asyn port with asynRecord ends with no success and this messsage output:
2014/04/10 13:04:32.374 EEE:asynrec: special queueRequest timeout


Thanks,
Tomas

---

Od: Mark Rivers [rivers@cars.uchicago.edu]
Odesláno: 8. dubna 2014 18:47
Komu: Mazanec Tomáš; tech-talk@aps.anl.gov
Předmět: RE: Streamdevice 2.6 autoconnection failure using drvAsynSerialPort

In synApps 5.7 what happens if you use an asynRecord to force the asynPort to reconnect.  Does StreamDevice then start working?

 

When the device is disconnected does asyn report that it is disconnected?  Use the following command when the device is disconnected:

 

asynReport 10 ASYN_PORT_NAME

 

Mark

 

 

 

From: Mazanec Tomáš [mailto:Tomas.Mazanec@eli-beams.eu]
Sent: Tuesday, April 08, 2014 9:20 AM
To: Mark Rivers; tech-talk@aps.anl.gov
Subject: RE: Streamdevice 2.6 autoconnection failure using drvAsynSerialPort

 

Hi Mark

Thanks for a quick response.

The IOC runs on Scientific Linux 6.5 x86-64 and its default kernel.  Yes, I have upgraded it (from 6.4 to 6.5) prior to SynApps upgrade.

Linux udev system is configured in a way that my usb-serial device gets always the same device name (/dev/ttyUSBPIC) no matter what other devices are present (major, minor device numbers can change).

I've double-checked Asyn 4.21 re-connection ability using asynRecord (.CNCT, .PCNCT).
It works fine, so the issue might be a glitch in the new StreamDevice.

Nevertheless, I've kept SynApps-5-6 installed and compared re-connection behavior to 5.7.
The older version is fine -- If my usb-serial device is physically disconnected, IOC with SynApps-5-6 reports:

2014/04/07 16:55:20.994 PORT EEE:volts: connection closed in write
2014/04/07 16:55:25.994 PORT EEE:volts: pasynCommon->connect() failed: /dev/ttyUSBPIC Can't open  No such device
2014/04/07 16:55:25.994 PORT EEE:volts: Protocol aborted

and when the usb-serial device is connected back, R/W operations continue as usual.

Whereas with the new version (5.7), IOC shell is kind of silent unless I try to reload StreamDevice protocol :

epics> streamReload EEE:volts
2014/04/08 11:46:52.567355 _main_ StreamCore::finishProtocol(EEE:volts): Still waiting for writeSuccess()
2014/04/08 11:46:52.567398 _main_ EEE:volts: Protocol aborted

or unless I try to use StreamDevice's connect command (through the EEE:CONNECT PV):

epics> dbpf EEE:CONNECT 1
DBR_STRING:          "ON"    
epics> 2014/04/07 17:10:06.446437 timerQueue EEE:CONNECT: Connect failed
2014/04/07 17:10:06.446482 timerQueue EEE:CONNECT: Protocol aborted
?2014/04/07 17:10:07.536724 timerQueue EEE:CONNECT: Connect failed
?2014/04/07 17:10:07.536747 timerQueue EEE:CONNECT: Protocol aborted

but the connection is not re-established anyway. Furthermore, protocol reload makes IOC shell stuck.

There is an older post about different connection issue, but also with StreamDevice & Asyn.
So, with the new version (5.7), I've checked whether the timerQueue thread is OK and checked for any locked mutexes.
The thread is OK.
There is a mutex reported as locked once the usb-serial device is diconnected, however it remains locked when the device is connected back.

epics> epicsMutexShowAll 1
ellCount(&mutexList) 112 ellCount(&freeList) 0
epicsMutexId 0x1d5bfd0 source ../../asyn/asynDriver/asynManager.c line 1868

No mutexes remain locked after the usb-device re-connection with the older version (5.6). But this could be just a result of the issue.

Tomas

---

Od: Mark Rivers [rivers@cars.uchicago.edu]
Odesláno: 7. dubna 2014 18:36
Komu: Mazanec Tomáš; tech-talk@aps.anl.gov
Předmět: RE: Streamdevice 2.6 autoconnection failure using drvAsynSerialPort

Hi Tomas,

 

There were no substantive changes in the drvAsynSerialPort code between asyn 4.18 and asyn 4.21.  SVN tag 1917 is asyn 4.18 and tag 2203 is asyn 4.21.

 

Here are the differences:

 

corvette:asyn/asyn/drvAsynSerial>svn diff -r1917:2203 drvAsynSerialPort*

Index: drvAsynSerialPort.c

===================================================================

--- drvAsynSerialPort.c (revision 1917)

+++ drvAsynSerialPort.c (revision 2203)

@@ -103,12 +103,12 @@

     if ((ioctl(tty->fd, FIOBAUDRATE, tty->baud) < 0)

      && (ioctl(tty->fd, SIO_BAUD_SET, tty->baud) < 0)) {

         epicsSnprintf(pasynUser->errorMessage, pasynUser->errorMessageSize,

-                                "SIO_BAUD_SET failed: %s\n", strerror(errno));

+                                "SIO_BAUD_SET failed: %s", strerror(errno));

         return asynError;

     }

     if (ioctl(tty->fd, SIO_HW_OPTS_SET, tty->termios.c_cflag) < 0) {

         epicsSnprintf(pasynUser->errorMessage, pasynUser->errorMessageSize,

-                               "SIO_HW_OPTS_SET failed: %s\n", strerror(errno));

+                               "SIO_HW_OPTS_SET failed: %s", strerror(errno));

         return asynError;

     }

#else

@@ -116,7 +116,7 @@

     tty->termios.c_cflag |= CREAD;

     if (tcsetattr(tty->fd, TCSANOW, &tty->termios) < 0) {

         epicsSnprintf(pasynUser->errorMessage, pasynUser->errorMessageSize,

-                                   "tcsetattr failed: %s\n", strerror(errno));

+                                   "tcsetattr failed: %s", strerror(errno));

         return asynError;

     }

#endif

@@ -253,12 +253,12 @@

         }

         if(cfsetispeed(&tty->termios,baudCode) < 0 ) {

             epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

-                "cfsetispeed returned %s\n",strerror(errno));

+                "cfsetispeed returned %s",strerror(errno));

             return asynError;

         }

         if(cfsetospeed(&tty->termios,baudCode) < 0 ) {

             epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

-                "cfsetospeed returned %s\n",strerror(errno));

+                "cfsetospeed returned %s",strerror(errno));

             return asynError;

         }

         }

@@ -452,7 +452,7 @@

     tcflush(tty->fd, TCOFLUSH);

#endif

#ifdef vxWorks

-    ioctl(tty->fd, FIOCANCEL, NULL);

+    ioctl(tty->fd, FIOCANCEL, 0);

     /*

      * Since it is possible, though unlikely, that we got here before the

      * slow system call actually started, we arrange to poke the thread

@@ -509,14 +509,14 @@

      */

     if ((tty->fd = open(tty->serialDeviceName, O_RDWR|O_NOCTTY|O_NONBLOCK, 0)) < 0) {

         epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

-                            "%s Can't open  %s\n",

+                            "%s Can't open  %s",

                                     tty->serialDeviceName, strerror(errno));

         return asynError;

     }

#if defined(FD_CLOEXEC) && !defined(vxWorks)

     if (fcntl(tty->fd, F_SETFD, FD_CLOEXEC) < 0) {

         epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

-                            "Can't set %s close-on-exec flag: %s\n",

+                            "Can't set %s close-on-exec flag: %s",

                                     tty->serialDeviceName, strerror(errno));

         close(tty->fd);

         tty->fd = -1;

@@ -578,7 +578,7 @@

     asynPrint(pasynUser, ASYN_TRACE_FLOW,

                             "%s write.\n", tty->serialDeviceName);

     asynPrintIO(pasynUser, ASYN_TRACEIO_DRIVER, data, numchars,

-                            "%s write %d\n", tty->serialDeviceName, numchars);

+                            "%s write %lu\n", tty->serialDeviceName, (unsigned long)numchars);

     if (tty->fd < 0) {

         epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

                                 "%s disconnected:", tty->serialDeviceName);

@@ -672,7 +672,7 @@

     }

     if (maxchars <= 0) {

         epicsSnprintf(pasynUser->errorMessage,pasynUser->errorMessageSize,

-            "%s maxchars %d Why <=0?\n",tty->serialDeviceName,(int)maxchars);

+            "%s maxchars %d Why <=0?",tty->serialDeviceName,(int)maxchars);

         return asynError;

     }

     if (tty->readTimeout != pasynUser->timeout) {

@@ -775,8 +775,8 @@

        data[nRead] = 0;

     else if (gotEom)

         *gotEom = ASYN_EOM_CNT;

-    asynPrint(pasynUser, ASYN_TRACE_FLOW, "%s read %d, return %d\n",

-                            tty->serialDeviceName, *nbytesTransfered, status);

+    asynPrint(pasynUser, ASYN_TRACE_FLOW, "%s read %lu, return %d\n",

+                            tty->serialDeviceName, (unsigned long)*nbytesTransfered, status);

     return status;

}

 

So the changes are removing “\n” from the end of epicsSNprintf formats, and some other minor changes to avoid compiler warnings.

 

Is this on Linux?

 

Have you upgraded the OS?

 

I think any change in behavior is likely due either to a change in StreamDevice or a change in the OS, and not due to any change in asyn.

 

Mark

 

 

 

From: tech-talk-bounces@aps.anl.gov [mailto:tech-talk-bounces@aps.anl.gov] On Behalf Of Mazanec Tomáš
Sent: Monday, April 07, 2014 11:13 AM
To: tech-talk@aps.anl.gov
Subject: Streamdevice 2.6 autoconnection failure using drvAsynSerialPort

 

Hello

Automatic re-connection seems to be broken with recent streamdevice & asyn.

Recently, we upgraded SynApps from 5.6 to version 5.7 and so streamdevice 2.5.1 & Asyn 4.18 to streamdevice 2.6 & Asyn 4.21.

One of IOCs here is using serial port ( as /dev/ttyUSBxxx ) and device controlled by it disconnects often.
With SynApps 5.6, everything ran smoothly. After the upgrade to SynApps 5.7, the IOC is not able to reconnect anymore.

As far as I've tested, drvAsynIPPort reconnects well with both SynApps 5.6 and 5.7, so its just serial port variant which is affected.

Could you anyone address this issue and provide some hints or fix.

Regards,

Tomas Mazanec

ELI Beamlines Czech Republic
http://www.eli-beams.eu
+420 26605 2566
+420 601 555 066

Address:
Institute of Physics, Academy of Sciences
Na Slovance 2
182 21 Prague
Czech Republic


***************************************************************************
*** DB template file:

record(ai, "$(NAME):volts")
{
    field(DTYP, "stream")
    field(INP, "@$(SCONF) get_volts $(ASYNPORT)")
    field(SCAN, "5 second")
    field(PINI, "YES")
    field(VAL, "0")
    field(PREC, "2")
    field(EGU, "V")
}

record(bo, "$(NAME):CONNECT") {
  field(DTYP, "stream")
  field(OUT, "@$(SCONF) connect $(ASYNPORT)")
  field(PINI, "NO")
  field(HIGH, "0.1")
  field(ZNAM, "OFF")
  field(ONAM, "ON")
}


***************************************************************************
*** streamdev protocol file:

get_volts    {out "\x11\x3f\x76\x04"; in "\x76%f\x04\x00" }

connect {
    ExtraInput = Ignore;
    connect 1000;
}


***************************************************************************
*** EPICS IOC shell LOG file:

epicsEnvSet("SYSNAME","EEE")
# streamdevice protocol file-name
epicsEnvSet("SYSSCONF","proto.sdp")
# name of asyndriver port (arbitrary)
epicsEnvSet("SYSASYNPORT","PORT")
# For streamdevice
epicsEnvSet STREAM_PROTOCOL_PATH :protocols:./cfg
 
# Setup asyn driver 
drvAsynSerialPortConfigure ("PORT","/dev/ttyUSBPIC", 0, 1, 0)
asynSetOption ("PORT", 0, "baud", "9600")
asynSetOption ("PORT", 0, "bits", "8")
asynSetOption ("PORT", 0, "parity", "none")
asynSetOption ("PORT", 0, "stop", "1")
 
asynReport(1, "PORT")
PORT multiDevice:No canBlock:Yes autoConnect:No
    enabled:Yes connected:No numberConnects 0
    nDevices 0 nQueued 0 blocked:No
    asynManagerLock:No synchronousLock:No
    exceptionActive:No exceptionUsers 1 exceptionNotifys 0
Serial line /dev/ttyUSBPIC: Disconnected
                    fd: -1
    Characters written: 0
       Characters read: 0
 
asynSetTraceIOMask("PORT",0,0x4)
asynSetTraceMask("PORT",0,0x9)
 
dbLoadRecords("aaa.template","NAME=EEE, SCONF=proto.sdp, ASYNPORT=PORT")
 
iocInit()
Starting iocInit
############################################################################
## EPICS R3.14.12.4 $Date: Mon 2013-12-16 15:51:45 -0600$
## EPICS Base built Mar 11 2014
############################################################################
iocRun: All initialization complete
 
2014/04/07 17:07:24.528 /dev/ttyUSBPIC write 4
 
11 3f 76 04 
2014/04/07 17:07:24.542 /dev/ttyUSBPIC read 1
 
76 
2014/04/07 17:07:24.543 /dev/ttyUSBPIC read 1
 
35 
2014/04/07 17:07:24.544 /dev/ttyUSBPIC read 1
 
2e 
2014/04/07 17:07:24.545 /dev/ttyUSBPIC read 1
 
31 
2014/04/07 17:07:24.547 /dev/ttyUSBPIC read 1
 
39 
2014/04/07 17:07:24.548 /dev/ttyUSBPIC read 1
 
04 
2014/04/07 17:07:24.549 /dev/ttyUSBPIC read 1
 
00 
2014/04/07 17:07:29.026 /dev/ttyUSBPIC write 4
 
11 3f 76 04 
2014/04/07 17:07:29.039 /dev/ttyUSBPIC read 1
 
76 
2014/04/07 17:07:29.041 /dev/ttyUSBPIC read 2
 
35 2e 
2014/04/07 17:07:29.042 /dev/ttyUSBPIC read 1
 
31 
2014/04/07 17:07:29.043 /dev/ttyUSBPIC read 1
 
39 
2014/04/07 17:07:29.044 /dev/ttyUSBPIC read 1
 
04 
2014/04/07 17:07:29.046 /dev/ttyUSBPIC read 1
 
00 
epics> 
epics> 
epics> 
epics> scanppl
Records with SCAN = '5 second' (0 over-runs):
    EEE:volts                   
epics> dbgf EEE:volts
DBR_DOUBLE:         5.19               
epics> 
epics> dbpr EEE:volts 111
ACKS: INVALID       ACKT: YES           ADEL: 0             ALST: 5.19          
AOFF: 0             ASG:                ASLO: 1             ASP: (nil)          
BKPT: 00            DESC:               DISA: 0             DISP: 0             
DISS: NO_ALARM      DISV: 1             DPVT: 0x1911dd0     DSET: 0x7fa011b09a40
DTYP: stream        EGU: V              EGUF: 0             EGUL: 0             
EOFF: 0             ESLO: 1             EVNT: 0             FLNK:CONSTANT 0     
HHSV: NO_ALARM      HIGH: 0             HIHI: 0             HOPR: 0             
HSV: NO_ALARM       HYST: 0             INIT: 0             
INP:INST_IO @proto.sdp get_volts PORT   LALM: 5.19          LBRK: 0             
LCNT: 11            LINR: NO CONVERSION LLSV: NO_ALARM      LOLO: 0             
LOPR: 0             LOW: 0              LSET: 0x1917c90     LSV: NO_ALARM       
MDEL: 0             
MLIS: 30 69 02 b0 9f 7f 00 00 30 69 02 b0 9f 7f 00 00 01 00 00 00               
MLOK: 40 76 90 01 00 00 00 00           MLST: 5.19          NAME: EEE:volts     
NSEV: NO_ALARM      NSTA: NO_ALARM      ORAW: 0             PACT: 1             
PBRK: (nil)         PHAS: 0             PINI: YES           PPN: (nil)          
PPNR: (nil)         PREC: 2             PRIO: LOW           PROC: 0             
PUTF: 0             RDES: 0x1885ff0     ROFF: 0             RPRO: 0             
RSET: 0x7fa0118c7a80                    RVAL: 0             SCAN: 5 second      
SDIS:CONSTANT       SEVR: INVALID       SIML:CONSTANT       SIMM: NO            
SIMS: NO_ALARM      SIOL:CONSTANT       SMOO: 0             SPVT: 0x1913f00     
STAT: SCAN          SVAL: 0             TIME: 2014-04-07 17:07:34.247219579     
TPRO: 0             TSE: 0              TSEL:CONSTANT       UDF: 0              
VAL: 5.19           
epics> 
epics> dbgf EEE:volts.SEVR
DBR_STRING:          "INVALID"          
epics> 
epics> dbpf EEE:CONNECT 1
DBR_STRING:          "ON"     
epics> ?[31;1m2014/04/07 17:10:06.446437 timerQueue EEE:CONNECT: Connect failed
?[0m?[31;1m2014/04/07 17:10:06.446482 timerQueue EEE:CONNECT: Protocol aborted
?[0m?[31;1m2014/04/07 17:10:07.536724 timerQueue EEE:CONNECT: Connect failed
?[0m?[31;1m2014/04/07 17:10:07.536747 timerQueue EEE:CONNECT: Protocol aborted
?[0m
epics> 
epics> var streamDebug 1
epics> dbpf EEE:CONNECT 1
2014/04/07 17:10:35.596373 _main_ StreamEpics.cc:711: Stream::process(EEE:CONNECT) start
2014/04/07 17:10:35.596411 _main_ StreamCore.cc:410: StreamCore::startProtocol(EEE:CONNECT, startMode=StartNormal)
2014/04/07 17:10:35.596426 _main_ StreamCore.cc:552: StreamCore::evalCommand(EEE:CONNECT): activeCommand = connect
2014/04/07 17:10:35.596436 _main_ AsynDriverInterface.cc:1347: AsynDriverInterface::connectRequest EEE:CONNECT
2014/04/07 17:10:35.596446 _main_ StreamEpics.cc:723: Stream::process(EEE:CONNECT): protocol started
DBR_STRING:          "ON"     
epics> 2014/04/07 17:10:36.591508 timerQueue AsynDriverInterface.cc:1473: AsynDriverInterface::handleTimeout(EEE:CONNECT)
?[31;1m2014/04/07 17:10:36.591531 timerQueue EEE:CONNECT: Connect failed
?[0m2014/04/07 17:10:36.591539 timerQueue StreamCore.cc:517: StreamCore::finishProtocol(EEE:CONNECT, status=Fault) not bus owner
2014/04/07 17:10:36.591545 timerQueue AsynDriverInterface.cc:1416: AsynDriverInterface::finish(EEE:CONNECT) start
2014/04/07 17:10:36.591551 timerQueue AsynDriverInterface.cc:1426: AsynDriverInterface::finish(EEE:CONNECT) done
?[31;1m2014/04/07 17:10:36.591557 timerQueue EEE:CONNECT: Protocol aborted
?[0m2014/04/07 17:10:36.591589 cbLow StreamEpics.cc:896: streamRecordProcessCallback(EEE:CONNECT) processing record
2014/04/07 17:10:36.591622 cbLow StreamEpics.cc:691: Stream::process(EEE:CONNECT) error status=UDF (17)
2014/04/07 17:10:36.591646 cbLow StreamEpics.cc:901: streamRecordProcessCallback(EEE:CONNECT) processing record done
2014/04/07 17:10:36.686741 cbLow StreamEpics.cc:711: Stream::process(EEE:CONNECT) start
2014/04/07 17:10:36.686766 cbLow StreamCore.cc:410: StreamCore::startProtocol(EEE:CONNECT, startMode=StartNormal)
2014/04/07 17:10:36.686779 cbLow StreamCore.cc:552: StreamCore::evalCommand(EEE:CONNECT): activeCommand = connect
2014/04/07 17:10:36.686785 cbLow AsynDriverInterface.cc:1347: AsynDriverInterface::connectRequest EEE:CONNECT
2014/04/07 17:10:36.686796 cbLow StreamEpics.cc:723: Stream::process(EEE:CONNECT): protocol started
2014/04/07 17:10:37.681881 timerQueue AsynDriverInterface.cc:1473: AsynDriverInterface::handleTimeout(EEE:CONNECT)
?[31;1m2014/04/07 17:10:37.681901 timerQueue EEE:CONNECT: Connect failed
?[0m2014/04/07 17:10:37.681909 timerQueue StreamCore.cc:517: StreamCore::finishProtocol(EEE:CONNECT, status=Fault) not bus owner
2014/04/07 17:10:37.681916 timerQueue AsynDriverInterface.cc:1416: AsynDriverInterface::finish(EEE:CONNECT) start
2014/04/07 17:10:37.681922 timerQueue AsynDriverInterface.cc:1426: AsynDriverInterface::finish(EEE:CONNECT) done
?[31;1m2014/04/07 17:10:37.681927 timerQueue EEE:CONNECT: Protocol aborted
?[0m2014/04/07 17:10:37.681958 cbLow StreamEpics.cc:896: streamRecordProcessCallback(EEE:CONNECT) processing record
2014/04/07 17:10:37.681981 cbLow StreamEpics.cc:691: Stream::process(EEE:CONNECT) error status=UDF (17)
2014/04/07 17:10:37.681994 cbLow StreamEpics.cc:901: streamRecordProcessCallback(EEE:CONNECT) processing record done
 
epics> 
epics> dbgf EEE:volts.SEVR
DBR_STRING:          "INVALID"          
epics> 
epics> 
 
***************************************************************************

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