Experimental Physics and
Industrial Control System
| 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 <2022> 2023 2024 | Index | 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 <2022> 2023 2024 |
| <== Date ==> | <== Thread ==> |
|---|
| Subject: | Streamdevice discards part of message |
| From: | "Brown, Garth via Tech-talk" <tech-talk at aps.anl.gov> |
| To: | "tech-talk at aps.anl.gov" <tech-talk at aps.anl.gov> |
| Date: | Mon, 17 Oct 2022 22:09:46 +0000 |
|
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;
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
|
- Replies:
- RE: Streamdevice discards part of message Mark Rivers via Tech-talk
- Re: Streamdevice discards part of message Ralph Lange via Tech-talk
- Re: Streamdevice discards part of message Zimoch Dirk (PSI) via Tech-talk
- Navigate by Date:
- Prev: Re: Attocube AMC100 Lang, Keenan C. via Tech-talk
- Next: RE: Streamdevice discards part of message Mark Rivers via Tech-talk
- Index: 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 <2022> 2023 2024
- Navigate by Thread:
- Prev: I/O interrupts documentation Pierrick M Hanlet via Tech-talk
- Next: RE: Streamdevice discards part of message Mark Rivers via Tech-talk
- Index: 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 <2022> 2023 2024
·
Home
·
News
·
About
·
Base
·
Modules
·
Extensions
·
Distributions
·
Download
·
· Search · EPICS V4 · IRMIS · Talk · Bugs · Documents · Links · Licensing ·