Re: Processing a record a in loop

[David Michel <dmichel76@googlemail.com>]

Here are some trace I've just collected:

IOC boot:
-------------

#!../../bin/linux-x86_64/streamTest
## You may have to change streamTest to something else
## everywhere it appears in this file
< envPaths
epicsEnvSet("ARCH","linux-x86_64")
epicsEnvSet("IOC","iocstreamTest")
epicsEnvSet("TOP","/home/davidmichel/Project/experimental/device/driver")
epicsEnvSet("EPICS_BASE","/usr/local/epics/base-3.14.12.3")
epicsEnvSet("STREAMDEVICE","/usr/local/epics/support/stream/current")
epicsEnvSet("ASYN","/usr/local/epics/support/asyn/current")
cd /home/davidmichel/Project/experimental/device/driver
## Register all support components
dbLoadDatabase "dbd/streamTest.dbd"
streamTest_registerRecordDeviceDriver pdbbase
## Register NewFocus 8742 pico motor controller
epicsEnvSet("STREAM_PROTOCOL_PATH","/home/davidmichel/Project/experimental/device/driver/protocols")
drvAsynIPPortConfigure("MC1","192.168.42.240:23")
## debug tracing
asynSetTraceIOMask("MC1",0,0xFF)
asynSetTraceMask("MC1",0,0xFF)
## Load record instances
dbLoadRecords("db/device_driver.db","DEVICE=MC1")
dbLoadRecords("db/axis.db","DEVICE=MC1, AXIS=1")

cd /home/davidmichel/Project/experimental/device/driver/iocBoot/iocstreamTest
iocInit
Starting iocInit
############################################################################
## EPICS R3.14.12.3 $Date: Mon 2012-12-17 14:11:47 -0600$
## EPICS Base built Aug  8 2013
############################################################################
2014/09/05 14:14:45.181 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.181 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.181 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.181 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.181 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.181 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.181 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.182 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.182 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.182 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.182 192.168.42.240:23 read.
2014/09/05 14:14:45.182 192.168.42.240:23 read 6
����

\377\375\003\377\373\001

ff fd 03 ff fb 01
2014/09/05 14:14:45.182 MC1 read
����

\377\375\003\377\373\001cas warning: Configured TCP port was unavailable.
cas warning: Using dynamically assigned TCP port 44650,
cas warning: but now two or more servers share the same UDP port.
cas warning: Depending on your IP kernel this server may not be
cas warning: reachable with UDP unicast (a host's IP in EPICS_CA_ADDR_LIST)


ff fd 03 ff fb 01
2014/09/05 14:14:45.182 192.168.42.240:23 read.
iocRun: All initialization complete
## Start any sequence programs
#seq sncxxx,"user=davidmichelHost"
2014/09/05 14:14:45.183 MC1 get Eos 0

2014/09/05 14:14:45.183 MC1 set Eos 0

2014/09/05 14:14:45.183 192.168.42.240:23 write.
2014/09/05 14:14:45.183 192.168.42.240:23 write 5
1AC?
1AC?\r

31 41 43 3f 0d
2014/09/05 14:14:45.183 wrote 5 to 192.168.42.240:23, return asynSuccess.
2014/09/05 14:14:45.183 MC1 wrote
1AC?
1AC?\r

31 41 43 3f 0d
2014/09/05 14:14:45.183 MC1 set Eos 0

2014/09/05 14:14:45.183 MC1 addr -1 queueRequest priority 0 from lockHolder
2014/09/05 14:14:45.183 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.183 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.183 MC1 get Eos 0

2014/09/05 14:14:45.183 MC1 set Eos 2


\r\n

0d 0a
2014/09/05 14:14:45.183 192.168.42.240:23 read.
2014/09/05 14:14:45.184 192.168.42.240:23 read 8
100000

100000\r\n

31 30 30 30 30 30 0d 0a
2014/09/05 14:14:45.184 MC1 read
100000

100000\r\n

31 30 30 30 30 30 0d 0a
2014/09/05 14:14:45.184 MC1 set Eos 0

2014/09/05 14:14:45.184 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.184 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.184 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.184 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.184 192.168.42.240:23 read.
2014/09/05 14:14:45.185 MC1 get Eos 0

2014/09/05 14:14:45.185 MC1 set Eos 0

2014/09/05 14:14:45.185 192.168.42.240:23 write.
2014/09/05 14:14:45.185 192.168.42.240:23 write 5
1VA?
1VA?\r

31 56 41 3f 0d
2014/09/05 14:14:45.185 wrote 5 to 192.168.42.240:23, return asynSuccess.
2014/09/05 14:14:45.185 MC1 wrote
1VA?
1VA?\r

31 56 41 3f 0d
2014/09/05 14:14:45.185 MC1 set Eos 0

2014/09/05 14:14:45.185 MC1 addr -1 queueRequest priority 0 from lockHolder
2014/09/05 14:14:45.185 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.185 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.185 MC1 get Eos 0

2014/09/05 14:14:45.185 MC1 set Eos 2


\r\n

0d 0a
2014/09/05 14:14:45.185 192.168.42.240:23 read.
2014/09/05 14:14:45.186 192.168.42.240:23 read 6
2000

2000\r\n

32 30 30 30 0d 0a
2014/09/05 14:14:45.186 MC1 read
2000

2000\r\n

32 30 30 30 0d 0a
2014/09/05 14:14:45.186 MC1 set Eos 0

2014/09/05 14:14:45.186 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.186 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 14:14:45.186 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.186 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.186 192.168.42.240:23 read.
2014/09/05 14:14:45.187 MC1 get Eos 0

2014/09/05 14:14:45.187 MC1 set Eos 0

2014/09/05 14:14:45.187 192.168.42.240:23 write.
2014/09/05 14:14:45.188 192.168.42.240:23 write 8
IPADDR?
IPADDR?\r

49 50 41 44 44 52 3f 0d
2014/09/05 14:14:45.188 wrote 8 to 192.168.42.240:23, return asynSuccess.
2014/09/05 14:14:45.188 MC1 wrote
IPADDR?
IPADDR?\r

49 50 41 44 44 52 3f 0d
2014/09/05 14:14:45.188 MC1 set Eos 0

2014/09/05 14:14:45.188 MC1 addr -1 queueRequest priority 0 from lockHolder
2014/09/05 14:14:45.188 MC1 schedule queueRequest timeout
2014/09/05 14:14:45.188 asynManager::portThread port=MC1 callback
2014/09/05 14:14:45.188 MC1 get Eos 0

2014/09/05 14:14:45.188 MC1 set Eos 2


\r\n

0d 0a
2014/09/05 14:14:45.188 192.168.42.240:23 read.
2014/09/05 14:14:45.188 192.168.42.240:23 read 16
192.168.42.240

192.168.42.240\r\n

31 39 32 2e 31 36 38 2e 34 32 2e 32 34 30 0d 0a
2014/09/05 14:14:45.189 MC1 read
192.168.42.240

192.168.42.240\r\n

31 39 32 2e 31 36 38 2e 34 32 2e 32 34 30 0d 0a
2014/09/05 14:14:45.189 MC1 set Eos 0

epics>

IOC shell output when error occurs
--------------------------------------------------

2014/09/05 15:17:51.953 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 15:17:51.953 MC1 schedule queueRequest timeout
2014/09/05 15:17:51.953 asynManager::portThread port=MC1 callback
2014/09/05 15:17:51.953 MC1 addr -1 queueRequest priority 0 not lockHolder
2014/09/05 15:17:51.953 MC1 schedule queueRequest timeout
2014/09/05 15:17:51.953 asynManager::portThread port=MC1 callback
2014/09/05 15:17:51.953 192.168.42.240:23 read.
2014/09/05 15:17:51.954 MC1 get Eos 0

2014/09/05 15:17:51.954 MC1 set Eos 0

2014/09/05 15:17:51.954 192.168.42.240:23 write.
2014/09/05 15:17:51.954 192.168.42.240:23 write 5
1MD?
1MD?\r

31 4d 44 3f 0d
2014/09/05 15:17:51.954 wrote 5 to 192.168.42.240:23, return asynSuccess.
2014/09/05 15:17:51.954 MC1 wrote
1MD?
1MD?\r

31 4d 44 3f 0d
2014/09/05 15:17:51.954 MC1 set Eos 0

2014/09/05 15:17:51.954 MC1 addr -1 queueRequest priority 0 from lockHolder
2014/09/05 15:17:51.954 MC1 schedule queueRequest timeout
2014/09/05 15:17:51.954 asynManager::portThread port=MC1 callback
2014/09/05 15:17:51.954 MC1 get Eos 0

2014/09/05 15:17:51.954 MC1 set Eos 2


\r\n

0d 0a
2014/09/05 15:17:51.954 192.168.42.240:23 read.

2014/09/05 15:17:51.954712 MC1 MC1:A1_DONE: No reply from device within 1000 ms
2014/09/05 15:17:51.955 MC1 set Eos 0

asynReport 10 "MC1" when "no reply" error occurs
-------------------------------------------------------------------------

MC1 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 1 exceptionNotifys 0
    interposeInterfaceList
        asynOctet pinterface 0x7f8e7d51d400 drvPvt 0x1e1f9d0
    interfaceList
        asynCommon pinterface 0x7f8e7d51a8c0 drvPvt 0x1d9abe0
        asynOctet pinterface 0x1d9acc8 drvPvt 0x1d9abe0
    Port 192.168.42.240:23: Connected
                    fd: 4
    Characters written: 49373
       Characters read: 28848

---
Dr. David Michel
Address: 8 Viking Drive, Didcot, OX11 9RD, Oxfordshire
Mobile: 0789 670 98 01 - Home: 0123 581 46 93

On 5 September 2014 14:33, David Michel <dmichel76@googlemail.com> wrote:

Hi Mark,

About to gather all the info you requested.... 

Quick question though, how do you use/set ASYN_TRACE_FLOW ? I cannot find anything showing how to set this up?

David

---
Dr. David Michel
Address: 8 Viking Drive, Didcot, OX11 9RD, Oxfordshire
Mobile: 0789 670 98 01 - Home: 0123 581 46 93

On 4 September 2014 14:07, Mark Rivers <rivers@cars.uchicago.edu> wrote:

> although very useful, it didn't really as everything appears normal until the connection is lost...

It would be interesting to see what happens when you let it run for a long time after the errors start.  Initially you should get a message about "temporarily unavailable".  But if the connection is really dead then eventually the OS should determine this and then asyn will report that the port is disconnected.  If the autoconnect flag is 1 then it will try to open the socket again.  In some ways that would be equivalent to restarting the IOC.

Can you send the complete asynTrace output with the ASYN_TRACEIO_DRIVER, ASYN_TRACE_ERROR, and ASYN_TRACE_FLOW bits set?  Set the timeout to 2 seconds or so to minimize the output.

Mark

________________________________
From: tech-talk-bounces@aps.anl.gov [tech-talk-bounces@aps.anl.gov] on behalf of David Michel [dmichel76@googlemail.com]
Sent: Thursday, September 04, 2014 4:19 AM
To: Emmanuel Mayssat
Cc: EPICS mailing list
Subject: Re: Processing a record a in loop

Hi Emmanuel,

Yes it's an ethernet link using a standard "dumb" network switch and you're quite right about the debugging asynTrace... although very useful, it didn't really as everything appears normal until the connection is lost...

What did you mean exactly with a point-to-point connection? Did you mean no switch and using crossover ethernet cable between the IOC and the device?

Interestingly, the device has a USB port as well. Although I've not tried that with the IOC, the supplier provide a windows app to control the device which works like a charm using the USB port. I've not tried the windows app with the ethernet connection yet though.

So, I was about to try the EPICS IOC with the USB interface, try the windows app with the ethernet interface - this might help me find where the fault lies. Also, I was about to write a simple python script to control the device without EPICS and see If I can reproduce the problem this way or not.

David



On 4 September 2014 00:17, Emmanuel Mayssat <emayssat@epicsqt.org<mailto:emayssat@epicsqt.org>> wrote:
Are you using an ethernet link between your IOC and your device?
If so, I have seen this behavior quite a few times.
The first thing to try in this case is to set a point to point connection between the IOC and the controlled device.

The asynTrace will not help you except to report that... you have lost connection.

I think you should share more about your setup.
--
Emmanuel



________________________________
Date: Wed, 3 Sep 2014 12:02:01 +0100

Subject: Processing a record a in loop
From: dmichel76@googlemail.com<mailto:dmichel76@googlemail.com>
To: tech-talk@aps.anl.gov<mailto:tech-talk@aps.anl.gov>

Hi All,

I'm using StreamDevice to talk to a custom device that doesn't support I/O interrupt so one has to keep sending commands to it to get status information.

Problem is that after a while (~ couple of hours), the device's buffer fills up and doesn't reply anymore. Increasing the ReplyTimeOut improves things slightly, but the problem still eventually occurs.

One potential solution would be to send the next command only once the previous one has returned in a loop (instead of using a set frequency).

Making the record FWD link to itself doesn't seem to do it... I started something using purely database trickery with a FANOUT record set with a fixed SCAN field and disabling it depending on whether the streamdevice record has finished processing or not... but it's getting messy

Is there an elegant way of doing this?

David