Re: Issue with streamdevice and I/o Intr

[Zimoch Dirk via Tech-talk <tech-talk at aps.anl.gov>]

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.

> 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.

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?

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()

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
> > > 
> > >