search

paulscherrerinstitute / StreamDevice

EPICS Driver for message based I/O
GNU General Public License v3.0
28 stars 42 forks source link

Parsing input with %g into ai record #32

Closed hinxx closed 5 years ago

hinxx commented 5 years ago

I have an ai record:

# SOURce1:CCURrent:AMPLitude
record(ai, "$(P)$(R)SOUR:CCUR_R")
{
    field(DESC, "Get current amplitude")
    field(DTYP, "stream")
    field(INP,  "@tldc2200.proto getG(SOUR:CCUR:AMPL) $(PORT) 0")
    field(EGU,  "A")
    field(PREC, "3")
}

The protocol entry for getG() is:

getG {
    out "\$1?";
    in "%g[^\r\n]";
    ExtraInput = Ignore;
}

I get this in the IOC shell when I do dbpf $(ACQ_PREFIX)SOUR:CCUR_R.PROC 1:

2019/04/10 14:30:56.007607 _main_ StreamEpics.cc:735: Stream::process(PBILAB:DC1:SOUR:CCUR_R) start
2019/04/10 14:30:56.007669 _main_ StreamCore.cc:413: StreamCore::startProtocol(PBILAB:DC1:SOUR:CCUR_R, startMode=StartNormal)
2019/04/10 14:30:56.007709 _main_ StreamCore.cc:555: StreamCore::evalCommand(PBILAB:DC1:SOUR:CCUR_R): activeCommand = out
2019/04/10 14:30:56.007746 _main_ StreamCore.cc:603: StreamCore::evalOut: outputLine = "SOUR:CCUR:AMPL?"
2019/04/10 14:30:56.007783 _main_ StreamCore.cc:614: StreamCore::evalOut(PBILAB:DC1:SOUR:CCUR_R): lockRequest(5000)
2019/04/10 14:30:56.007816 _main_ AsynDriverInterface.cc:500: AsynDriverInterface::lockRequest(PBILAB:DC1:SOUR:CCUR_R, 5000 msec)
2019/04/10 14:30:56.007887 _main_ StreamEpics.cc:747: Stream::process(PBILAB:DC1:SOUR:CCUR_R): protocol started
DBR_UCHAR:          1         0x1                 
2019/04/10 14:30:56.007918 DET.DC1 AsynDriverInterface.cc:1511: AsynDriverInterface::handleRequest(PBILAB:DC1:SOUR:CCUR_R) Lock
2019/04/10 14:30:56.007982 DET.DC1 AsynDriverInterface.cc:591: AsynDriverInterface::lockHandler(PBILAB:DC1:SOUR:CCUR_R)
2019/04/10 14:30:56.008011 DET.DC1 StreamCore.cc:820: epics> StreamCore::lockCallback(PBILAB:DC1:SOUR:CCUR_R, status=StreamIoSuccess)
2019/04/10 14:30:56.008048 DET.DC1 AsynDriverInterface.cc:629: AsynDriverInterface::writeRequest(PBILAB:DC1:SOUR:CCUR_R, "SOUR:CCUR:AMPL?", 100 msec)
2019/04/10 14:30:56.008086 DET.DC1 AsynDriverInterface.cc:1511: AsynDriverInterface::handleRequest(PBILAB:DC1:SOUR:CCUR_R) Write
2019/04/10 14:30:56.008110 DET.DC1 AsynDriverInterface.cc:657: AsynDriverInterface::writeHandler(PBILAB:DC1:SOUR:CCUR_R)
2019/04/10 14:30:56.008140 DET.DC1 AsynDriverInterface.cc:673: AsynDriverInterface::writeHandler(PBILAB:DC1:SOUR:CCUR_R): reading old input
2019/04/10 14:30:56.008320 DET.DC1 AsynDriverInterface.cc:719: AsynDriverInterface::writeHandler(PBILAB:DC1:SOUR:CCUR_R): write(..., "SOUR:CCUR:AMPL?", outputSize=15, written=15) [timeout=0.1 sec] = asynSuccess ()
2019/04/10 14:30:56.008390 DET.DC1 AsynDriverInterface.cc:738: AsynDriverInterface::writeHandler(PBILAB:DC1:SOUR:CCUR_R): device is connected
2019/04/10 14:30:56.008415 DET.DC1 StreamCore.cc:864: StreamCore::writeCallback(PBILAB:DC1:SOUR:CCUR_R, status=Success)
2019/04/10 14:30:56.008438 DET.DC1 StreamCore.cc:555: StreamCore::evalCommand(PBILAB:DC1:SOUR:CCUR_R): activeCommand = in
2019/04/10 14:30:56.008460 DET.DC1 AsynDriverInterface.cc:811: AsynDriverInterface::readRequest(PBILAB:DC1:SOUR:CCUR_R, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2019/04/10 14:30:56.008495 DET.DC1 AsynDriverInterface.cc:836: AsynDriverInterface::readRequest PBILAB:DC1:SOUR:CCUR_R: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2019/04/10 14:30:56.008537 DET.DC1 AsynDriverInterface.cc:1511: AsynDriverInterface::handleRequest(PBILAB:DC1:SOUR:CCUR_R) Read
2019/04/10 14:30:56.008565 DET.DC1 AsynDriverInterface.cc:962: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): ioAction=Read read(..., bytesToRead=1, ...) [timeout=1 sec]
2019/04/10 14:30:56.010363 DET.DC1 AsynDriverInterface.cc:970: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): read returned asynSuccess: ioAction=Read received=1, eomReason=CNT, buffer="1"
2019/04/10 14:30:56.010392 DET.DC1 AsynDriverInterface.cc:977: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): device is now connected
2019/04/10 14:30:56.010409 DET.DC1 AsynDriverInterface.cc:1015: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): received 1 of 1 bytes "1" eomReason=CNT
2019/04/10 14:30:56.010427 DET.DC1 StreamCore.cc:953: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R, status=StreamIoSuccess input="1", size=1)
2019/04/10 14:30:56.010448 DET.DC1 StreamCore.cc:1009: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) inputBuffer="1", size 1
2019/04/10 14:30:56.010471 DET.DC1 StreamCore.cc:1090: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) wait for more input
2019/04/10 14:30:56.010498 DET.DC1 AsynDriverInterface.cc:1141: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R) readMore=-1 bytesToRead=63
2019/04/10 14:30:56.010521 DET.DC1 AsynDriverInterface.cc:962: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): ioAction=Read read(..., bytesToRead=63, ...) [timeout=0.1 sec]
2019/04/10 14:30:56.010550 DET.DC1 AsynDriverInterface.cc:970: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): read returned asynSuccess: ioAction=Read received=12, eomReason=END, buffer=".000000E-02<0a>"
2019/04/10 14:30:56.010573 DET.DC1 AsynDriverInterface.cc:977: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): device is now connected
2019/04/10 14:30:56.010595 DET.DC1 AsynDriverInterface.cc:1015: AsynDriverInterface::readHandler(PBILAB:DC1:SOUR:CCUR_R): received 12 of 63 bytes ".000000E-02<0a>" eomReason=END
2019/04/10 14:30:56.010618 DET.DC1 StreamCore.cc:953: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R, status=StreamIoEnd input=".000000E-02<0a>", size=12)
2019/04/10 14:30:56.010641 DET.DC1 StreamCore.cc:1009: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) inputBuffer="1.000000E-02<0a>", size 13
2019/04/10 14:30:56.010662 DET.DC1 StreamCore.cc:1061: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) end flag received
2019/04/10 14:30:56.010683 DET.DC1 StreamCore.cc:1119: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) input line: "1.000000E-02<0a>"
2019/04/10 14:30:56.010705 DET.DC1 StreamCore.cc:1209: StreamCore::matchInput(PBILAB:DC1:SOUR:CCUR_R): format = "%g"
2019/04/10 14:30:56.010727 DET.DC1 StreamEpics.cc:523: streamScanfN(PBILAB:DC1:SOUR:CCUR_R,format=%g,maxStringSize=40)
2019/04/10 14:30:56.010767 DET.DC1 StreamCore.cc:1503: StreamCore::scanValue(PBILAB:DC1:SOUR:CCUR_R, format=%g, double) input="1.000000E-02<0a>"
2019/04/10 14:30:56.010790 DET.DC1 StreamCore.cc:1516: StreamCore::scanValue(PBILAB:DC1:SOUR:CCUR_R) scanned 0.0100000
2019/04/10 14:30:56.010815 DET.DC1 StreamEpics.cc:532: streamScanfN(PBILAB:DC1:SOUR:CCUR_R) success, value="{<14><ae>G<e1>z<84>?"
2019/04/10 14:30:56.010842 DET.DC1 StreamCore.cc:1149: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) match failure
2019/04/10 14:30:56.010863 DET.DC1 StreamCore.cc:513: starting exception handler
2019/04/10 14:30:56.010883 DET.DC1 StreamCore.cc:555: StreamCore::evalCommand(PBILAB:DC1:SOUR:CCUR_R): activeCommand = disconnect
2019/04/10 14:30:56.010906 DET.DC1 AsynDriverInterface.cc:1449: AsynDriverInterface::disconnectRequest PBILAB:DC1:SOUR:CCUR_R
2019/04/10 14:30:56.010932 DET.DC1 AsynDriverInterface.cc:1511: AsynDriverInterface::handleRequest(PBILAB:DC1:SOUR:CCUR_R) Disconnect
2019/04/10 14:30:56.010953 DET.DC1 AsynDriverInterface.cc:1471: AsynDriverInterface::disconnectHandler PBILAB:DC1:SOUR:CCUR_R is not yet disconnected
2019/04/10 14:30:56.011115 DET.DC1 StreamCore.cc:555: StreamCore::evalCommand(PBILAB:DC1:SOUR:CCUR_R): activeCommand = end
2019/04/10 14:30:56.011144 DET.DC1 StreamCore.cc:520: StreamCore::finishProtocol(PBILAB:DC1:SOUR:CCUR_R, status=ScanError) bus owner
2019/04/10 14:30:56.011167 DET.DC1 AsynDriverInterface.cc:611: AsynDriverInterface::unlock(PBILAB:DC1:SOUR:CCUR_R)
2019/04/10 14:30:56.011188 DET.DC1 AsynDriverInterface.cc:1490: AsynDriverInterface::finish(PBILAB:DC1:SOUR:CCUR_R) start
2019/04/10 14:30:56.011209 DET.DC1 AsynDriverInterface.cc:1500: AsynDriverInterface::finish(PBILAB:DC1:SOUR:CCUR_R) done
2019/04/10 14:30:56.011267 cbLow StreamEpics.cc:910: streamRecordProcessCallback(PBILAB:DC1:SOUR:CCUR_R) processing record
2019/04/10 14:30:56.011317 cbLow StreamEpics.cc:715: Stream::process(PBILAB:DC1:SOUR:CCUR_R) error status=CALC (12)
2019/04/10 14:30:56.011368 cbLow StreamEpics.cc:915: streamRecordProcessCallback(PBILAB:DC1:SOUR:CCUR_R) processing record done

I'm especially worried about these lines, from above:

...
2019/04/10 14:30:56.010790 DET.DC1 StreamCore.cc:1516: StreamCore::scanValue(PBILAB:DC1:SOUR:CCUR_R) scanned 0.0100000
2019/04/10 14:30:56.010815 DET.DC1 StreamEpics.cc:532: streamScanfN(PBILAB:DC1:SOUR:CCUR_R) success, value="{<14><ae>G<e1>z<84>?"
2019/04/10 14:30:56.010842 DET.DC1 StreamCore.cc:1149: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) match failure

...

Why did scanned value of 0.0100000 turn into {<14><ae>G<e1>z<84>??

hinxx commented 5 years ago

BTW, this is on Linux, with EPICS R3.15.5, asyn R4-33 and streamDevice 2-7-11, if it matters.

dirk-zimoch commented 5 years ago

On 10.04.19 14:37, Hinko Kočevar wrote:

Why did scanned value of |0.0100000| turn into |{<14>Gz<84>?|?

That are the 8 bytes of 0.0100000 in a double. Don't worry. :-) 0.0100000 = 0x3F847AE147AE147B In little endian: 0x7B 0x14 0xAE 0x47 0xE1 0x7A 0x84 0x3F Of those some are ASCII chars: 0x7B='{' 0x47='G' 0x7A='z' 0x3F='?'

I am more surprised by having "success" followed by "failure":

2019/04/10 14:30:56.010815 DET.DC1 StreamEpics.cc:532: streamScanfN(PBILAB:DC1:SOUR:CCUR_R) success, value="{<14>Gz<84>?" 2019/04/10 14:30:56.010842 DET.DC1 StreamCore.cc:1149: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) match failure

Let me do some tests.

BTW: "%g[^\r\n]" will not read a double followed by a char that is no return or newline, it will read a double followed by the literal string "[^\r\n]".

Also better don't use ExtraInput = Ignore unless absolutely necessary because it robs you of valuable consistency checks. For example if you expect a double like 1.00e-05 but data corruption changes it to 1.00f10 then you get the double 1.00 and the rubbish "f-05". If you ignore the rubbish reading will succeed and you end up with a value which off by 5 orders of magnitude and no error.

dirk-zimoch commented 5 years ago

When I switch on errors (var streamError 1) I see this:

2019/04/10 15:30:26.755120 DET.DC1 StreamEpics.cc:532: streamScanfN(PBILAB:DC1:SOUR:CCUR_R) success, value=""
2019/04/10 15:30:26.755140 DET.DC1 PBILAB:DC1:SOUR:CCUR_R: Input "...000000E-02<0a>" mismatch after 11 bytes
2019/04/10 15:30:26.755158 DET.DC1 PBILAB:DC1:SOUR:CCUR_R: got "<0a>" where "[^" was expected
2019/04/10 15:30:26.755174 DET.DC1 StreamCore.cc:1149: StreamCore::readCallback(PBILAB:DC1:SOUR:CCUR_R) match failure

When I made errors switchable I did not switch it on automatically when debug is on. I will change that in the future. Also errors are off by default because people complained about error flooding. I will switch it back on by default in a future version.

dirk-zimoch commented 5 years ago

Closed by accident.

hinxx commented 5 years ago

Thanks @dirk-zimoch it works now! Couldn't notice my blunder without the var streamError 1..