RE: Streamdevice discards part of message

[Mark Rivers via Tech-talk <tech-talk at aps.anl.gov>]

What value did you use for noProcessEos when you created the asynPortDriver?

 

What happens if instead of setting the terminator in the protocol file you set it with asynOctetSetInputEos in your startup script?

 

Mark

 

 

From: Tech-talk <tech-talk-bounces at aps.anl.gov> On Behalf Of Brown, Garth via Tech-talk
Sent: Monday, October 17, 2022 5:10 PM
To: tech-talk at aps.anl.gov
Subject: Streamdevice discards part of message

 

streamdevice R2.8.9

asyn R4.39

base R7.0.3.1

 

With a line that contains the line terminator in 3 places, the part of the message before the first line terminator is dropped. I've tried some variations of line terminator in the protocol file and via asynRecord, with no effect or losing data entirely.

It's a very simple protocol that passes pieces of a longer message along as a string/waveform to an asub record for reassembly and decoding. The protocol file is:

 

InTerminator  = CR LF;

OutTerminator = CR;

ReplyTimeout  =  2000;

ReadTimeout   =  10000;

WriteTimeout  =  10000;

ExtraInput    = Ignore;

 

MODULE_DATA       {     in    "MSG \$1,%s";     }

 

The PV that uses it:

record(waveform,"$(P):STREAM_READER")

{

      field(DESC, "Read data from module $(N)")

      field(DTYP, "stream")

      field(INP, "@p_blm.proto MODULE_DATA($(N)) $(PORT) 1")

      field(SCAN, "I/O Intr")

      field(NELM, "512")

      field(FTVL, "CHAR")

}

 

When I turn on asyn traceIODriver and traceIOEscape, I see the whole thing:

2022/10/17 14:45:38.502 ts-b912-nw06:2009 read 252

MSG 3,#3117000b0C01f42cb9690009497B0002A4AF0000051B000001180000000000000027420400003F4CCCCD41A0F5C33F08B80041B5E2804480000040400\r\nMSG 3,#31090000000000041A000004040000043BE1FE0447F4790447EAB5041398C0041398C0041398C004410180CC209384BC208D8DCC208CF6D\r\n\r\n

 

But only the part between the first and seconds \r\n's makes it to the waveform record:

>camonitor PBLM:LTU0:739:STREAM_READER -S

PBLM:LTU0:739:STREAM_READER 2022-10-17 14:48:45.883766 #31090000000000041A000004040000043BEBC20447F6EA0447FE3D04194ED004194ED004194ED0044674F05C1A05844C19B6C59C19BE156  

PBLM:LTU0:739:STREAM_READER 2022-10-17 14:48:46.903834 #31090000000000041A000004040000043BF0A40447F6EA0447ED2604194ED004194ED004194ED0044674F05C19C4FEBC19B7ADDC19BDF53

 

Here's the output when streamDebug=1, filtered for the PV prefix which is also the asyn port name, PBLM:LTU0:739. The IOC has dozens of different devices, so full output is very cluttered.

 

2022/10/17 14:31:51.955033 PBLM:LTU0:73 AsynDriverInterface.cc:1176: AsynDriverInterface::asynReadHandler(PBLM:LTU0:739:STREAM_READER, buffer="MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400<0d><0a>MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>", received=252 eomReason=NONE) ioAction=AsyncRead

2022/10/17 14:31:51.955096 PBLM:LTU0:73 StreamCore.cc:944: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER, StreamIoSuccess input="MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400<0d><0a>MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>", size=252)

2022/10/17 14:31:51.955110 PBLM:LTU0:73 2022/10/17 14:31:51.955110 LBLM:LTUH:43 StreamCore.cc:994: StreamCore.cc:544: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inputBuffer="MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400<0d><0a>MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>", size 252

2022/10/17 14:31:51.955121 PBLM:LTU0:73 StreamCore.cc:1036: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inTerminator <0d><0a> at position 128

2022/10/17 14:31:51.955135 PBLM:LTU0:73 StreamCore.cc:1104: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) input line: "MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400"

2022/10/17 14:31:51.955143 PBLM:LTU0:73 StreamCore.cc:1193: StreamCore::matchInput(PBLM:LTU0:739:STREAM_READER): format = "%s"

2022/10/17 14:31:51.955163 PBLM:LTU0:73 StreamCore.cc:1535: StreamCore::scanValue(PBLM:LTU0:739:STREAM_READER, format=%s, char*, size=123) input="#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400" value="#3117000b0C01f42cb9690009463C0002A3500000051B000001180000000000000027420400003F4CCCCD41A0F5C34108B80042153B204480000040400<00>"

2022/10/17 14:31:51.955188 PBLM:LTU0:73 StreamEpics.cc:1543: Stream::matchValue(PBLM:LTU0:739:STREAM_READER): success, 122 bytes consumed

2022/10/17 14:31:51.955190 cbLow 2022/10/17 14:31:51.955204 PBLM:LTU0:73 StreamCore.cc:1110: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) unpared input left: "MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>"

StreamEpics.cc:1079: 2022/10/17 14:31:51.955215 PBLM:LTU0:73 StreamCore.cc:544: StreamCore::evalCommand(PBLM:LTU0:739:STREAM_READER): activeCommand = end

2022/10/17 14:31:51.955225 PBLM:LTU0:73 StreamCore.cc:447: StreamCore::finishProtocol(PBLM:LTU0:739:STREAM_READER, Success) not bus owner

2022/10/17 14:31:51.955229 PBLM:LTU0:73 AsynDriverInterface.cc:1473: 2022/10/17 14:31:51.955229 cbLow AsynDriverInterface::finish(PBLM:LTU0:739:STREAM_READER) start

AsynDriverInterface::finish(PBLM:LTU0:739:STREAM_READER) done

2022/10/17 14:31:51.955288 cbLow StreamEpics.cc:1088: 2022/10/17 14:31:51.955301 LBLM:LTUH:43 2022/10/17 14:31:51.955303 PBLM:LTU0:73 StreamEpics.cc:1001: Stream::protocolFinishHook(PBLM:LTU0:739:STREAM_READER, Success)

2022/10/17 14:31:51.955315 PBLM:LTU0:73 AsynDriverInterface.cc:1257: AsynDriverInterface::asynReadHandler(PBLM:LTU0:739:STREAM_READER) readMore=0, ioAction=None

2022/10/17 14:31:51.955431 cbLow StreamEpics.cc:1079: recordProcessCallback(PBLM:LTU0:739:STREAM_READER) processing record

Stream::process(PBLM:LTU0:739:STREAM_READER)

2022/10/17 14:31:51.955460 cbLow StreamEpics.cc:889: Stream::process(PBLM:LTU0:739:STREAM_READER) ready. don't convert

2022/10/17 14:31:51.955470 cbLow StreamEpics.cc:1083: recordProcessCallback(PBLM:LTU0:739:STREAM_READER) processing record done

2022/10/17 14:31:51.955493 cbLow StreamEpics.cc:1088: recordProcessCallback(PBLM:LTU0:739:STREAM_READER) restart async protocol

2022/10/17 14:31:51.955498 cbLow StreamCore.cc:411: StreamCore::startProtocol(PBLM:LTU0:739:STREAM_READER, startMode=StartAsync)

2022/10/17 14:31:51.955519 cbLow StreamCore.cc:544: StreamCore::evalCommand(PBLM:LTU0:739:STREAM_READER): activeCommand = in

2022/10/17 14:31:51.955558 cbLow StreamCore.cc:901: StreamCore::evalIn(PBLM:LTU0:739:STREAM_READER): early input: MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>

2022/10/17 14:31:51.955570 cbLow StreamCore.cc:944: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER, StreamIoSuccess input="", size=0)

2022/10/17 14:31:51.955590 cbLow 2022/10/17 14:31:51.955592 LBLM:LTUH:43 2022/10/17 14:31:51.955589 PBLM:LTU0:73 StreamCore.cc:994: StreamCore.cc:1110: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inputBuffer="MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<0d><0a><0d><0a>", size 122

2022/10/17 14:31:51.955614 cbLow StreamCore.cc:1036: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inTerminator <0d><0a> at position 118

StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) input line: "MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879"

StreamCore.cc:1193: StreamCore::matchInput(PBLM:LTU0:739:STREAM_READER): format = "%s"

StreamCore::scanValue(PBLM:LTU0:739:STREAM_READER, format=%s, char*, size=113) input="#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879" value="#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879<00>"

2022/10/17 14:31:51.955809 cbLow StreamEpics.cc:1543: Stream::matchValue(PBLM:LTU0:739:STREAM_READER): success, 112 bytes consumed

2022/10/17 14:31:51.955816 cbLow StreamCore.cc:1110: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) unpared input left: "<0d><0a>"

AsynDriverInterface.cc:830: 2022/10/17 14:31:51.955861 cbLow StreamCore.cc:544: StreamCore::evalCommand(PBLM:LTU0:739:STREAM_READER): activeCommand = end

2022/10/17 14:31:51.955870 cbLow StreamCore.cc:447: StreamCore::finishProtocol(PBLM:LTU0:739:STREAM_READER, Success) not bus owner

AsynDriverInterface.cc:1257: 2022/10/17 14:31:51.955908 cbLow AsynDriverInterface.cc:1473: AsynDriverInterface::finish(PBLM:LTU0:739:STREAM_READER) start

AsynDriverInterface.cc:1483: 2022/10/17 14:31:51.955943 PBLM:LTU0:73 AsynDriverInterface::finish(PBLM:LTU0:739:STREAM_READER) done

2022/10/17 14:31:51.955954 cbLow StreamEpics.cc:1001: Stream::protocolFinishHook(PBLM:LTU0:739:STREAM_READER, Success)

2022/10/17 14:31:51.956129 cbLow StreamEpics.cc:1079: recordProcessCallback(PBLM:LTU0:739:STREAM_READER) processing record

2022/10/17 14:31:51.956143 cbLow StreamEpics.cc:875: Stream::process(PBLM:LTU0:739:STREAM_READER)

2022/10/17 14:31:51.956157 cbLow StreamEpics.cc:889: Stream::process(PBLM:LTU0:739:STREAM_READER) ready. don't convert

2022/10/17 14:31:51.956185 cbLow StreamEpics.cc:1083: recordProcessCallback(PBLM:LTU0:739:STREAM_READER) processing record done

recordProcessCallback(PBLM:LTU0:739:STREAM_READER) restart async protocol

2022/10/17 14:31:51.956226 cbLow 2022/10/17 14:31:51.956236 PBLM:LTU0:73 StreamCore.cc:411: StreamCore.cc:1128: StreamCore::startProtocol(PBLM:LTU0:739:STREAM_READER, startMode=StartAsync)

2022/10/17 14:31:51.956254 cbLow StreamCore.cc:544: StreamCore::evalCommand(PBLM:LTU0:739:STREAM_READER): activeCommand = in

2022/10/17 14:31:51.956263 cbLow StreamCore.cc:901: StreamCore::evalIn(PBLM:LTU0:739:STREAM_READER): early input: <0d><0a>

2022/10/17 14:31:51.956271 cbLow StreamCore.cc:944: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER, StreamIoSuccess input="", size=0)

2022/10/17 14:31:51.956280 cbLow StreamCore.cc:994: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inputBuffer="<0d><0a>", size 2

2022/10/17 14:31:51.956288 cbLow StreamCore.cc:1036: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) inTerminator <0d><0a> at position 0

2022/10/17 14:31:51.956296 cbLow StreamCore.cc:1104: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) input line: ""

2022/10/17 14:31:51.956304 cbLow StreamCore.cc:1128: StreamCore::readCallback(PBLM:LTU0:739:STREAM_READER) async match failure: just restart

2022/10/17 14:31:51.956312 cbLow AsynDriverInterface.cc:805: AsynDriverInterface::readRequest(PBLM:LTU0:739:STREAM_READER, 2000 msec reply, 10000 msec read, expect 0 bytes, async=yes)

2022/10/17 14:31:51.956321 cbLow AsynDriverInterface.cc:830: AsynDriverInterface::readRequest PBLM:LTU0:739:STREAM_READER: queueRequest(..., priority=0, queueTimeout=-1 sec) = asynError [async=true] asynManager::queueRequest is already queued

2022/10/17 14:31:51.956581 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=63, eomReason=CNT, buffer="MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000"

2022/10/17 14:31:51.956587 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 63 of 63 bytes "MSG 1,#3117000b0C01f42cb9690009463C0002A3500000051B000001180000" eomReason=CNT [data ignored]

2022/10/17 14:31:51.956591 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956608 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

2022/10/17 14:31:51.956617 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=63, eomReason=CNT, buffer="000000000027420400003F4CCCCD41A0F5C34108B80042153B2044800000404"

2022/10/17 14:31:51.956623 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 63 of 63 bytes "000000000027420400003F4CCCCD41A0F5C34108B80042153B2044800000404" eomReason=CNT [data ignored]

2022/10/17 14:31:51.956627 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956631 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

2022/10/17 14:31:51.956636 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=2, eomReason=EOS, buffer="00"

2022/10/17 14:31:51.956640 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 2 of 63 bytes "00" eomReason=EOS [data ignored]

2022/10/17 14:31:51.956650 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956654 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

2022/10/17 14:31:51.956661 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=63, eomReason=CNT, buffer="MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04"

2022/10/17 14:31:51.956666 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 63 of 63 bytes "MSG 1,#31090000000000041A000004040000043BE1FE0447F95B0447FBCC04" eomReason=CNT [data ignored]

2022/10/17 14:31:51.956670 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956674 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

2022/10/17 14:31:51.956681 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=55, eomReason=EOS, buffer="194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879"

2022/10/17 14:31:51.956689 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 55 of 63 bytes "194ED004194ED004194ED0044674F05C19D3C11C19AB2F0C19AC879" eomReason=EOS [data ignored]

2022/10/17 14:31:51.956701 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956708 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

2022/10/17 14:31:51.956714 PBLM:LTU0:73 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): read returned asynSuccess: ioAction=AsyncRead received=0, eomReason=EOS, buffer=""

2022/10/17 14:31:51.956718 PBLM:LTU0:73 AsynDriverInterface.cc:981: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): AsyncRead poll: received 0 of 63 bytes "" eomReason=EOS [data ignored]

2022/10/17 14:31:51.956722 PBLM:LTU0:73 AsynDriverInterface.cc:1127: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER) readMore=-1 bytesToRead=63

2022/10/17 14:31:51.956726 PBLM:LTU0:73 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(PBLM:LTU0:739:STREAM_READER): ioAction=AsyncRead read(..., bytesToRead=63, ...) [timeout=10 sec]

 

Thanks,

Garth