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 [[email protected]]
*Odesláno:* 8. dubna 2014 18:47
*Komu:* Mazanec Tomáš; [email protected]
*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:[email protected]]
*Sent:* Tuesday, April 08, 2014 9:20 AM
*To:* Mark Rivers; [email protected]
*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 [[email protected]]
*Odesláno:* 7. dubna 2014 18:36
*Komu:* Mazanec Tomáš; [email protected] <mailto:[email protected]>
*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:*[email protected]
<mailto:[email protected]>
[mailto:[email protected]] *On Behalf Of *Mazanec Tomáš
*Sent:* Monday, April 07, 2014 11:13 AM
*To:* [email protected] <mailto:[email protected]>
*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>
***************************************************************************
***************************************************************************