Re: Issue with streamdevice and I/o Intr

[Florian Feldbauer via Tech-talk <tech-talk at aps.anl.gov>]

Hey Dirk,

On 7/4/23 11:55, Zimoch Dirk wrote:
> On Tue, 2023-07-04 at 11:09 +0200, Florian Feldbauer wrote:
> > Hey Dirk,
> >
> > thanks for the detailed explanation.
> > I worked with StreamDevice and I/O intr a lot before, but always with
> > the asynSerialPort as lower level driver.
> >
> > Just to be clear: Let's assume my input record with "I/O Intr" is the
> > only record reading on the bus, do I need to create a polling on the bus
> > myself or does StreamDevice internally create a polling thread?
> StreamDevice does it automatically. In fact, ALL "I/O Intr" try to poll the bus.
> The first one that gets the bus just cancels the poll of all others. This way,
> the "I/O Intr" record with the fastest poll rate is effectively the one which
> does the polling.
>
> > Thx for the advice with the eomReason, I changed my driver accordingly.
> > My protocol and record now look like this:
> >
> > Terminator = '';
> > recv {
> >     MaxInput = 4;
> >     in  0x07 $1 "%r";
> > }
> >
> > record( longin, "CAN${N}:TEST:R" ) {
> >     field( DTYP, "stream" )
> >     field( SCAN, "I/O Intr" )
> >     field( INP,  "@can.proto recv(0x00) ${port}" )
> > }
> Your protocol expects 3 bytes, 0x07 0x00 and one byte data. But it received 4
> bytes, 0x07 0x00 0x00 0x15. Thus one byte is left and makes the protocol fail.
>
> Using %2r should give you the signed 16 bit integer value 0x0015.
Oh, ok, I thought "%r" would read up to 4 bytes and not just one.
I should read the doc more carefully. I updated the protocol accordingly.


> > The first two bytes contain the 11bit CAN arbitration ID followed by the
> > up to 8 data bytes.
> > We have one device that sends 32bit floats via CAN bus, which is why we
> > use the raw format, so we can parse those values later with the %R
> > format converter.
> Be aware that %r and %R both cannot fail and thus only the input length can
> distinguish between the two formats. You will not be able to separate %4r from
> %4R if the first two bytes are the same.
Yes, I'm aware of this, but the first 2 bytes (CAN bus arbitration ID) 
will be unique for each device on the bus
and also later on the data bytes will contain specific information on 
which type of data we received.
The current protocol is just for a very simple testing procedure.


> I find it strange that in the log below you send 4 bytes (0x07 0x00 0x00 0x15)
> but receive 5 (0x07 0x00 0x00 0x15 0x00). Is everything correct in your driver?
The additional 0x00 at the end was due to a bug I introduced when 
setting eomReason to ASYN_EOM_END.
This is now fixed and I get 0x07 0x00 0x00 0x15 from the driver. 
Unfortunately everything else stayed the same.

> I still don't see messages from asynReadHandler. Strange. Does your driver not
> pass the data through asynOctetBase? Look how drvAsynSerialPort links to
> asynOctetBase in drvAsynSerialPortConfigure: pasynOctetBase->initialize()
I wrote my driver as a derived class from the AsynPortDriver, 
overloading the read/write Octet methods.
473 drvAsynCAN::drvAsynCAN( char const* portName, char const* interface, 
int autoConnect ) :
474   asynPortDriver( portName,
475                   0, // maxAddr
476                   asynCommonMask | asynOctetMask | asynDrvUserMask, 
// Interface mask
477                   asynCommonMask | asynOctetMask,  // Interrupt mask
478                   ASYN_CANBLOCK, // asynFlags
479                   autoConnect,  // Autoconnect
480                   0,   // Default priority
481                   0 ), // Default stack size
482   fd_(-1)
483 {

The constructor of the base class calls the pasynOctetBase->initialize() 
method.
  Florian


> If not using pasynOctetBase, your read function will not call
> callInterruptUsers() unless you explicitly do it yourself and thus "I/O Intr"
> records will not receive anything.
>
> Dirk
>
> > My IOC has 2 CAN interfaces and I was trying to send a frame from can0
> > to can1 or vise versa.
> >
> >
> > Here is the complete log from Stream:
> >
> > epics> dbpf CAN0:TEST:W 21
> > 2023/07/04 11:03:07.127321 _main_ StreamEpics.cc:908:
> > Stream::process(CAN0:TEST:W)
> > 2023/07/04 11:03:07.127508 _main_ StreamEpics.cc:934:
> > Stream::process(CAN0:TEST:W) start
> > 2023/07/04 11:03:07.127628 _main_ StreamCore.cc:429:
> > StreamCore::startProtocol(CAN0:TEST:W, startMode=StartNormal)
> > 2023/07/04 11:03:07.127725 _main_ StreamCore.cc:564:
> > StreamCore::evalCommand(CAN0:TEST:W): activeCommand = out
> > 2023/07/04 11:03:07.127828 _main_ StreamCore.cc:689:
> > StreamCore::formatOutput(CAN0:TEST:W): format = %.2r
> > 2023/07/04 11:03:07.127945 _main_ StreamEpics.cc:1173:
> > Stream::formatValue(CAN0:TEST:W, format=%r, fieldaddr=(nil)
> > 2023/07/04 11:03:07.128054 _main_ StreamEpics.cc:1298:
> > Stream::formatValue(CAN0:TEST:W) format=%r type=DBF_LONG
> > 2023/07/04 11:03:07.128166 _main_ StreamEpics.cc:693:
> > streamPrintf(CAN0:TEST:W,format=%r)
> > 2023/07/04 11:03:07.128284 _main_ StreamCore.cc:777:
> > StreamCore::printValue(CAN0:TEST:W, %r, 21 = 0x15): "<07><00><00><15>"
> > 2023/07/04 11:03:07.128402 _main_ StreamCore.cc:612:
> > StreamCore::evalOut: outputLine = "<07><00><00><15>"
> > 2023/07/04 11:03:07.128503 _main_ StreamCore.cc:623:
> > StreamCore::evalOut(CAN0:TEST:W): lockRequest(5000)
> > 2023/07/04 11:03:07.128599 _main_ AsynDriverInterface.cc:549:
> > AsynDriverInterface::lockRequest(CAN0:TEST:W, 5000 msec)
> > 2023/07/04 11:03:07.128739 _main_ StreamEpics.cc:948:
> > Stream::process(CAN0:TEST:W): protocol started
> > 2023/07/04 11:03:07.128794 can0 AsynDriverInterface.cc:590:
> > AsynDriverInterface::lockHandler(CAN0:TEST:W)
> > DBF_LONG:           21 = 0x15
> > 2023/07/04 11:03:07.129004 can0 StreamCore.cc:832:
> > StreamCore::lockCallback(CAN0:TEST:W, StreamIoSuccess)
> > 2023/07/04 11:03:07.129122 can0 AsynDriverInterface.cc:627:
> > AsynDriverInterface::writeRequest(CAN0:TEST:W, "<07><00><00><15>", 300 msec)
> > epics> 2023/07/04 11:03:07.129265 can0 AsynDriverInterface.cc:649:
> > AsynDriverInterface::writeHandler(CAN0:TEST:W)
> > 2023/07/04 11:03:07.129375 can0 AsynDriverInterface.cc:667:
> > AsynDriverInterface::writeHandler(CAN0:TEST:W): reading old input
> > 2023/07/04 11:03:07.130 can0: wrote 4 bytes to can0, return asynSuccess
> > 2023/07/04 11:03:07.129714 can0 AsynDriverInterface.cc:715:
> > AsynDriverInterface::writeHandler(CAN0:TEST:W): write(...,
> > "<07><00><00><15>", outputSize=4, written=4) [timeout=0.3 sec] =
> > asynSuccess
> > 2023/07/04 11:03:07.129844 can0 StreamCore.cc:877:
> > StreamCore::writeCallback(CAN0:TEST:W, StreamIoSuccess)
> > 2023/07/04 11:03:07.129948 can0 StreamCore.cc:564:
> > StreamCore::evalCommand(CAN0:TEST:W): activeCommand = end
> > 2023/07/04 11:03:07.130403 can0 StreamCore.cc:465:
> > StreamCore::finishProtocol(CAN0:TEST:W, Success) bus owner
> > 2023/07/04 11:03:07.130508 can0 AsynDriverInterface.cc:610:
> > AsynDriverInterface::unlock(CAN0:TEST:W)
> > 2023/07/04 11:03:07.130606 can0 AsynDriverInterface.cc:1468:
> > AsynDriverInterface::finish(CAN0:TEST:W) start
> > 2023/07/04 11:03:07.130697 can0 AsynDriverInterface.cc:1478:
> > AsynDriverInterface::finish(CAN0:TEST:W) done
> > 2023/07/04 11:03:07.130792 can0 StreamEpics.cc:1034:
> > Stream::protocolFinishHook(CAN0:TEST:W, Success)
> > 2023/07/04 11:03:07.130967 cbLow StreamEpics.cc:1112:
> > recordProcessCallback(CAN0:TEST:W) processing record
> > 2023/07/04 11:03:07.131135 cbLow StreamEpics.cc:908:
> > Stream::process(CAN0:TEST:W)
> > 2023/07/04 11:03:07.131230 cbLow StreamEpics.cc:922:
> > Stream::process(CAN0:TEST:W) ready. don't convert
> > 2023/07/04 11:03:07.131344 cbLow StreamEpics.cc:1116:
> > recordProcessCallback(CAN0:TEST:W) processing record done
> > 2023/07/04 11:03:07.484 can1: read 5 bytes from can1, return asynSuccess
> > 2023/07/04 11:03:07.483786 can1 AsynDriverInterface.cc:951:
> > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead read(4
> > bytes, timeout=0 sec) returned status asynSuccess: received=5 bytes,
> > eomReason=END, buffer="<07><00><00><15><00>"
> > 2023/07/04 11:03:07.483917 can1 AsynDriverInterface.cc:977:
> > AsynDriverInterface::readHandler(CAN1:TEST:R): AsyncRead poll: received
> > 5 of 4 bytes "<07><00><00><15><00>" eomReason=END [data ignored]
> > 2023/07/04 11:03:07.484024 can1 AsynDriverInterface.cc:1123:
> > AsynDriverInterface::readHandler(CAN1:TEST:R) readMore=-1 bytesToRead=63
> > 2023/07/04 11:03:07.484160 can1 AsynDriverInterface.cc:951:
> > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead
> > read(63 bytes, timeout=0.5 sec) returned status asynTimeout: received=0
> > bytes, eomReason=NONE, buffer=""
> > 2023/07/04 11:03:07.484273 can1 AsynDriverInterface.cc:1051:
> > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead,
> > timeout [0.5 sec] after 0 of 63 bytes ""
> > 2023/07/04 11:03:07.484397 can1 StreamCore.cc:963:
> > StreamCore::readCallback(CAN1:TEST:R, StreamIoTimeout input="", size=0)
> > 2023/07/04 11:03:07.484504 can1 StreamCore.cc:1015:
> > StreamCore::readCallback(CAN1:TEST:R) inputBuffer="", size 0
> > 2023/07/04 11:03:07.484806 can1 StreamCore.cc:1108:
> > StreamCore::readCallback(CAN1:TEST:R) async timeout: just restart
> > 2023/07/04 11:03:07.484975 can1 AsynDriverInterface.cc:806:
> > AsynDriverInterface::readRequest(CAN1:TEST:R, 500 msec reply, 500 msec
> > read, expect 4 bytes, async=yes)
> > 2023/07/04 11:03:07.485125 can1 AsynDriverInterface.cc:831:
> > AsynDriverInterface::readRequest CAN1:TEST:R: queueRequest(...,
> > priority=0, queueTimeout=-1 sec) = asynSuccess [async=true]
> >
> > Setting eomReason to ASYN_EOM_END seems to attach a 0 to the received
> > data, but it still should match the %r format converter.
> >
> > Cheres,
> > Florian
> >
> >
> > On 7/4/23 10:45, Zimoch Dirk wrote:
> > > Hi Florian,
> > >
> > > For "I/O Intr" records, StreamDevice uses intrCallbackOctet but still needs to
> > > poll the device, because despite its name, intrCallbackOctet does not deliver
> > > any data asynchronously when nobody reads synchronously. The "I/O Intr" records
> > > receives ALL input, regardless of the active reader, which may be the record
> > > itself, some other StreamDevice Record or even non-StreamDevice records or any
> > > other software calling asynOctet->read on that port.
> > >
> > > Thus, to avoid receiving the data twice, in case the intrCallbackOctet receiver
> > > is the polling record, StreamDevice discards the input received with the polled
> > > read and only uses the input received with intrCallbackOctet.
> > >
> > > As ALL "I/O Intr" StreamDevice records receive ALL input, they all match the
> > > input against their 'in' commands. Only those records  which could match the
> > > input successfully are processed. All others silently ignore the input!
> > >
> > > The intrCallbackOctet input log messages should show up in the logs BEFORE the
> > > message form the polled read (because asyn calls the interrupt callbacks before
> > > returning from read). What do you have in the logs right before the first line
> > > you posted? Anything from AsynDriverInterface::asynReadHandler() and
> > > StreamCore::readCallback()?
> > >
> > >
> > > As StreamDevice did not receive a termination signal, it assumes there may be
> > > more input and tries to read it. But that results in a timeout, which is then
> > > interpreted as a termination signal, because no InTerminator is used.
> > >
> > > This is probably not what you want. If the message never exceeds one CAN frame,
> > > set eomReason to ASYN_EOM_END. This avoids wasting time on another read attempt.
> > > If you may have messages that span multiple frames and have a method to find out
> > > when this is the case in your driver, do that. Otherwise waiting for timeout (or
> > > InTerminator or maxInput) is in fact the only way.
> > >
> > > Now the question is why the input is rejected. Hard to say without knowing your
> > > protocol. What do you have in your 'in' command?
> > >
> > > Dirk
> > >
> > >
> > > On Tue, 2023-07-04 at 09:05 +0200, Florian Feldbauer via Tech-talk wrote:
> > > > Hey all,
> > > >
> > > > we have some devices controlled via CAN bus.
> > > > Since CAN bus is based on the transmission of 1-8 bytes, I wrote an
> > > > AsynPortDriver with an asynOctet interface as lower level driver.
> > > >
> > > > I wanted to use StreamDevice as higher level driver defining the actual
> > > > payload data that is tranmitted between our PC and the devices.
> > > >
> > > > Sending and receiving messages in principal works, but I have an issue
> > > > with I/O Interrupts and I don't know why.
> > > > Setting the streamDebug variable to 1, I see the following output from
> > > > StreamDevice:
> > > >
> > > > 2023/07/04 08:54:44.301618 can1 AsynDriverInterface.cc:951:
> > > > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead
> > > > read(63 bytes, timeout=0 sec) returned status asynSuccess: received=4
> > > > bytes, eomReason=NONE, buffer="<07><00><00><ea>"
> > > > 2023/07/04 08:54:44.301765 can1 AsynDriverInterface.cc:977:
> > > > AsynDriverInterface::readHandler(CAN1:TEST:R): AsyncRead poll: received
> > > > 4 of 63 bytes "<07><00><00><ea>" eomReason=NONE [data ignored]
> > > > 2023/07/04 08:54:44.301889 can1 AsynDriverInterface.cc:1123:
> > > > AsynDriverInterface::readHandler(CAN1:TEST:R) readMore=-1 bytesToRead=63
> > > > 2023/07/04 08:54:44.302015 can1 AsynDriverInterface.cc:951:
> > > > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead
> > > > read(63 bytes, timeout=0.5 sec) returned status asynTimeout: received=0
> > > > bytes, eomReason=NONE, buffer=""
> > > > 2023/07/04 08:54:44.302140 can1 AsynDriverInterface.cc:1051:
> > > > AsynDriverInterface::readHandler(CAN1:TEST:R): ioAction=AsyncRead,
> > > > timeout [0.5 sec] after 0 of 63 bytes ""
> > > > 2023/07/04 08:54:44.302262 can1 StreamCore.cc:963:
> > > > StreamCore::readCallback(CAN1:TEST:R, StreamIoTimeout input="", size=0)
> > > > 2023/07/04 08:54:44.302378 can1 StreamCore.cc:1015:
> > > > StreamCore::readCallback(CAN1:TEST:R) inputBuffer="", size 0
> > > > 2023/07/04 08:54:44.302490 can1 StreamCore.cc:1067:
> > > > StreamCore::readCallback(CAN1:TEST:R) end flag received
> > > > 2023/07/04 08:54:44.302605 can1 StreamCore.cc:1127:
> > > > StreamCore::readCallback(CAN1:TEST:R) input line: ""
> > > > 2023/07/04 08:54:44.302726 can1 StreamCore.cc:1151:
> > > > StreamCore::readCallback(CAN1:TEST:R) async match failure: just restart
> > > > 2023/07/04 08:54:44.302847 can1 AsynDriverInterface.cc:806:
> > > > AsynDriverInterface::readRequest(CAN1:TEST:R, 500 msec reply, 500 msec
> > > > read, expect 0 bytes, async=yes)
> > > > 2023/07/04 08:54:44.302964 can1 AsynDriverInterface.cc:831:
> > > > AsynDriverInterface::readRequest CAN1:TEST:R: queueRequest(...,
> > > > priority=0, queueTimeout=-1 sec) = asynSuccess [async=true]
> > > >
> > > > The readHandler reads the message from the bus but ignores it. According
> > > > to the comments in the code it is ignored because the asyncReadHandler
> > > > should also receive this message and handle the I/O interrupt, but it
> > > > seems the Interrupt callback is not executed.
> > > > Any idea why the callbacks don't work?
> > > >
> > > > I'm using
> > > > base 7.0.6.1
> > > > stream 2.8.24
> > > > asyn (current HEAD on master branch)
> > > >
> > > > Cheers,
> > > > Florian
--
Ruhr-Universität Bochum
AG der Experimentalphysik I
Dr. Florian Feldbauer
NB 2/131 / Fach 125
Universitätsstr. 150
D-44801 Bochum

Office: NB 2/134
Phone:  (+49)234 / 32-23563
Fax:    (+49)234 / 32-14170
https://paluma.ruhr-uni-bochum.de