search

epics-modules / asyn

EPICS module for driver and device support
http://epics-modules.github.io/asyn/
Other
37 stars 74 forks source link

Buffer overflow when using vxi11 and streamdevice #105

Closed jevarlec closed 4 years ago

jevarlec commented 4 years ago

Possibly related to #28

Streamdevice calls pasynOctet->read with bytesToRead=63, read returns asynSuccess and 78 bytes, eomReason=ASYN_EOM_EOS. Calling read again results in segfault.

What was expected: Streamdevice calls pasynOctet->read with bytesToRead=63, read returns asynSuccess and 63 bytes, eomReason=ASYN_EOM_CNT. Streamdevice calls read again to retrieve the remaining bytes.

The issue can be reproduced every time the device returns message longer than 63 bytes.

Streamdevice debug log:

iocRun: All initialization complete
# IOC initialization done
epics> var streamDebug 1
epics> dbpf SIG-GEN-01:BSWV_C1_STAT.PROC 1
epics> 2020/02/17 11:16:42.401400 CAS-client StreamEpics.cc:843: Stream::process(SIG-GEN-01:BSWV_C1_STAT)
2020/02/17 11:16:42.401446 CAS-client StreamEpics.cc:869: Stream::process(SIG-GEN-01:BSWV_C1_STAT) start
2020/02/17 11:16:42.401451 CAS-client StreamCore.cc:411: StreamCore::startProtocol(SIG-GEN-01:BSWV_C1_STAT, startMode=StartNormal)
2020/02/17 11:16:42.401456 CAS-client StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BSWV_C1_STAT): activeCommand = out
2020/02/17 11:16:42.401472 CAS-client StreamCore.cc:592: StreamCore::evalOut: outputLine = "C1:BSWV?<0a>"
2020/02/17 11:16:42.401477 CAS-client StreamCore.cc:603: StreamCore::evalOut(SIG-GEN-01:BSWV_C1_STAT): lockRequest(5000)
2020/02/17 11:16:42.401482 CAS-client AsynDriverInterface.cc:548: AsynDriverInterface::lockRequest(SIG-GEN-01:BSWV_C1_STAT, 5000 msec)
2020/02/17 11:16:42.401499 CAS-client StreamEpics.cc:883: Stream::process(SIG-GEN-01:BSWV_C1_STAT): protocol started
2020/02/17 11:16:42.401585 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BSWV_C1_STAT) Lock
2020/02/17 11:16:42.401619 sigGen01 AsynDriverInterface.cc:589: AsynDriverInterface::lockHandler(SIG-GEN-01:BSWV_C1_STAT)
2020/02/17 11:16:42.401642 sigGen01 StreamCore.cc:812: StreamCore::lockCallback(SIG-GEN-01:BSWV_C1_STAT, StreamIoSuccess)
2020/02/17 11:16:42.401646 sigGen01 AsynDriverInterface.cc:626: AsynDriverInterface::writeRequest(SIG-GEN-01:BSWV_C1_STAT, "C1:BSWV?<0a>", 100 msec)
2020/02/17 11:16:42.401655 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BSWV_C1_STAT) Write
2020/02/17 11:16:42.401659 sigGen01 AsynDriverInterface.cc:648: AsynDriverInterface::writeHandler(SIG-GEN-01:BSWV_C1_STAT)
2020/02/17 11:16:42.401661 sigGen01 AsynDriverInterface.cc:678: AsynDriverInterface::writeHandler(SIG-GEN-01:BSWV_C1_STAT): flushing old input
2020/02/17 11:16:42.574 sigGen01 -1 vxiWrite
C1:BSWV?\n
2020/02/17 11:16:42.573685 sigGen01 AsynDriverInterface.cc:714: AsynDriverInterface::writeHandler(SIG-GEN-01:BSWV_C1_STAT): write(..., "C1:BSWV?<0a>", outputSize=9, written=9) [timeout=0.1 sec] = asynSuccess 
2020/02/17 11:16:42.573698 sigGen01 StreamCore.cc:857: StreamCore::writeCallback(SIG-GEN-01:BSWV_C1_STAT, StreamIoSuccess)
2020/02/17 11:16:42.573702 sigGen01 StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BSWV_C1_STAT): activeCommand = in
2020/02/17 11:16:42.573707 sigGen01 AsynDriverInterface.cc:805: AsynDriverInterface::readRequest(SIG-GEN-01:BSWV_C1_STAT, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2020/02/17 11:16:42.573837 sigGen01 AsynDriverInterface.cc:830: AsynDriverInterface::readRequest SIG-GEN-01:BSWV_C1_STAT: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2020/02/17 11:16:42.573888 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BSWV_C1_STAT) Read
2020/02/17 11:16:42.573928 sigGen01 AsynDriverInterface.cc:889: AsynDriverInterface::readHandler(SIG-GEN-01:BSWV_C1_STAT) input EOS changed from "" to "<0a>"
2020/02/17 11:16:42.573947 sigGen01 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(SIG-GEN-01:BSWV_C1_STAT): ioAction=Read read(..., bytesToRead=63, ...) [timeout=1 sec]
2020/02/17 11:16:42.744 sigGen01 -1 vxiRead
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/17 11:16:42.743865 sigGen01 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(SIG-GEN-01:BSWV_C1_STAT): read returned asynSuccess: ioAction=Read received=78, eomReason=EOS+END, buffer="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0"
2020/02/17 11:16:42.743881 sigGen01 AsynDriverInterface.cc:994: AsynDriverInterface::readHandler(SIG-GEN-01:BSWV_C1_STAT): received 78 of 63 bytes "C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0" eomReason=EOS+END
2020/02/17 11:16:42.743888 sigGen01 StreamCore.cc:943: StreamCore::readCallback(SIG-GEN-01:BSWV_C1_STAT, StreamIoEnd input="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0", size=78)
2020/02/17 11:16:42.743893 sigGen01 StreamCore.cc:993: StreamCore::readCallback(SIG-GEN-01:BSWV_C1_STAT) inputBuffer="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0", size 78
2020/02/17 11:16:42.743900 sigGen01 StreamCore.cc:1038: StreamCore::readCallback(SIG-GEN-01:BSWV_C1_STAT) inTerminator <0a> not found
2020/02/17 11:16:42.743906 sigGen01 StreamCore.cc:1045: StreamCore::readCallback(SIG-GEN-01:BSWV_C1_STAT) end flag received
2020/02/17 11:16:42.743911 sigGen01 StreamCore.cc:1103: StreamCore::readCallback(SIG-GEN-01:BSWV_C1_STAT) input line: "C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0"
2020/02/17 11:16:42.743922 sigGen01 StreamCore.cc:1192: StreamCore::matchInput(SIG-GEN-01:BSWV_C1_STAT): format = "%{SINE|SQUARE|RAMP|PULSE|NOISE|ARB|DC}"
2020/02/17 11:16:42.743942 sigGen01 EnumConverter.cc:154: EnumConverter::scanLong(%{, "ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0")
2020/02/17 11:16:42.743951 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #0 "SINE"
2020/02/17 11:16:42.743954 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #1 "SQUARE"
2020/02/17 11:16:42.743957 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #2 "RAMP"
2020/02/17 11:16:42.743964 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #3 "PULSE"
2020/02/17 11:16:42.743967 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #4 "NOISE"
2020/02/17 11:16:42.743970 sigGen01 EnumConverter.cc:165: EnumConverter::scanLong: check #5 "ARB"
2020/02/17 11:16:42.743973 sigGen01 EnumConverter.cc:181: EnumConverter::scanLong: value 5 matches
2020/02/17 11:16:42.743977 sigGen01 StreamCore.cc:1470: StreamCore::scanValue(SIG-GEN-01:BSWV_C1_STAT, format=%{, long) input="ARB" value=5
2020/02/17 11:16:42.743981 sigGen01 StreamEpics.cc:935: Stream::scan() currentValueLength=3
2020/02/17 11:16:42.743984 sigGen01 StreamEpics.cc:1511: Stream::matchValue(SIG-GEN-01:BSWV_C1_STAT): success, 3 bytes consumed
2020/02/17 11:16:42.743989 sigGen01 StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BSWV_C1_STAT): activeCommand = end
2020/02/17 11:16:42.743995 sigGen01 StreamCore.cc:447: StreamCore::finishProtocol(SIG-GEN-01:BSWV_C1_STAT, Success) bus owner
2020/02/17 11:16:42.744001 sigGen01 AsynDriverInterface.cc:609: AsynDriverInterface::unlock(SIG-GEN-01:BSWV_C1_STAT)
2020/02/17 11:16:42.744006 sigGen01 AsynDriverInterface.cc:1473: AsynDriverInterface::finish(SIG-GEN-01:BSWV_C1_STAT) start
2020/02/17 11:16:42.744011 sigGen01 AsynDriverInterface.cc:1483: AsynDriverInterface::finish(SIG-GEN-01:BSWV_C1_STAT) done
2020/02/17 11:16:42.744015 sigGen01 StreamEpics.cc:969: Stream::protocolFinishHook(SIG-GEN-01:BSWV_C1_STAT, Success)
2020/02/17 11:16:42.744029 sigGen01 AsynDriverInterface.cc:1140: AsynDriverInterface::readHandler(SIG-GEN-01:BSWV_C1_STAT) input EOS restored to ""
2020/02/17 11:16:42.744052 cbLow StreamEpics.cc:1047: recordProcessCallback(SIG-GEN-01:BSWV_C1_STAT) processing record
2020/02/17 11:16:42.744097 cbLow StreamEpics.cc:843: Stream::process(SIG-GEN-01:BSWV_C1_STAT)
2020/02/17 11:16:42.744113 cbLow StreamEpics.cc:857: Stream::process(SIG-GEN-01:BSWV_C1_STAT) ready. convert
2020/02/17 11:16:42.744138 cbLow StreamEpics.cc:1051: recordProcessCallback(SIG-GEN-01:BSWV_C1_STAT) processing record done

Streamdevice protocol used:

Terminator = LF;

getBSWV_WVTP {
    ExtraInput = Ignore;
    out "C\$1:BSWV?";
    in "C\$1:BSWV WVTP,%{SINE|SQUARE|RAMP|PULSE|NOISE|ARB|DC}";
}

Record used:

record (mbbi, "$(DEVICE):BSWV_C$(CHAN)_STAT")
{
  field(DESC, "Query for the type of basic wave")
  field(DTYP, "stream")
  field(INP, "@sigGen.proto getBSWV_WVTP($(CHAN)) $(PORT)")
  field(ZRST, "SINE")
  field(ONST, "SQUARE")
  field(TWST, "RAMP")
  field(THST, "PULSE")
  field(FRST, "NOISE")
  field(FVST, "ARB")
  field(SXST, "DC")
  field(SCAN, "$(SCAN)")
}

It was also tested with the following protocol and waveform record:

Terminator = LF;

getBSWV_WVTP {
    out "C\$1:BSWV?";
    in "%#s";
}
MarkRivers commented 4 years ago

Can you also get the VXI-11 driver trace?

Put these lines right after $(PORT) is created:

asynSetTraceIOMask $(PORT) 0 2 asynSetTraceMask $(PORT) 0 255

jevarlec commented 4 years ago

Here is the trace:

epics> 2020/02/17 16:19:24.500 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/17 16:19:24.500 sigGen01 schedule queueRequest timeout in 5.000000 seconds
2020/02/17 16:19:24.500 asynManager::portThread port=sigGen01 callback
2020/02/17 16:19:24.500 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/17 16:19:24.500 sigGen01 schedule queueRequest timeout in 0.100000 seconds
2020/02/17 16:19:24.500 asynManager::portThread port=sigGen01 callback
2020/02/17 16:19:24.500 sigGen01 -1 vxiWrite numchars 9
2020/02/17 16:19:24.672 sigGen01 -1 vxiWrite
C1:BSWV?\n
2020/02/17 16:19:24.672 sigGen01 addr -1 queueRequest priority 0 from lockHolder
2020/02/17 16:19:24.672 sigGen01 schedule queueRequest timeout in 1.000000 seconds
2020/02/17 16:19:24.672 asynManager::portThread port=sigGen01 callback
2020/02/17 16:19:24.672 sigGen01 vxiSetEos 1
\n
2020/02/17 16:19:24.842 sigGen01 -1 vxiRead
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/17 16:19:24.842 sigGen01 vxiSetEos 0
MarkRivers commented 4 years ago

I don't have a vxi11 device I can use for testing, so I am going to need @jevarlec to do the testing for me.

In drvVxi11.c::vxiRead line 1162 is this:

        devReadP.requestSize = maxchars;

So it appears to be correctly asking for maxchars characters.

Please change line 1198 to this:

                "%s %d vxiRead, maxchars=%d, thisRead=%d\n",pvxiPort->portName,addr, maxchars, thisRead);

Then we can see if clientIoCall is correctly respecting maxchars.

jevarlec commented 4 years ago

Here is the trace after the modification:

epics> 2020/02/17 19:20:33.009 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/17 19:20:33.009 sigGen01 schedule queueRequest timeout in 5.000000 seconds
2020/02/17 19:20:33.009 asynManager::portThread port=sigGen01 callback
2020/02/17 19:20:33.009 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/17 19:20:33.009 sigGen01 schedule queueRequest timeout in 0.100000 seconds
2020/02/17 19:20:33.009 asynManager::portThread port=sigGen01 callback
2020/02/17 19:20:33.009 sigGen01 -1 vxiWrite numchars 9
2020/02/17 19:20:33.179 sigGen01 -1 vxiWrite
C1:BSWV?\n
2020/02/17 19:20:33.179 sigGen01 addr -1 queueRequest priority 0 from lockHolder
2020/02/17 19:20:33.179 sigGen01 schedule queueRequest timeout in 1.000000 seconds
2020/02/17 19:20:33.180 asynManager::portThread port=sigGen01 callback
2020/02/17 19:20:33.180 sigGen01 vxiSetEos 1
\n
2020/02/17 19:20:33.372 sigGen01 -1 vxiRead, maxchars=63, thisRead=79
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/17 19:20:33.372 sigGen01 vxiSetEos 0

I stopped the program at the point where thisRead is being written to:

(gdb) info stack 1
#0  vxiRead (drvPvt=0x6d5690, pasynUser=0x75fe48, data=0x75fd40 "", maxchars=63, 
    nbytesTransfered=0x7ffff312454c, eomReason=0x7ffff31245f4) at ../../asyn/vxi11/drvVxi11.c:1195

(gdb) print devReadP
$12 = {lid = 0, requestSize = 63, io_timeout = 1000, lock_timeout = 0, flags = 128, termChar = 10 '\n'}

(gdb) print devReadR
$13 = {error = 0, reason = 4, data = {data_len = 79, 
    data_val = 0x7fffe4002cc0 "C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n"}}
MarkRivers commented 4 years ago

That certainly looks to me like clientIoCall is not respecting the value of requestSize that was passed to it. You asked for 63 bytes, and it returned 79.

I don't know enough about the rpc code to understand this. What controls the buffer size of devReadR.data.data_val? We could protect against overflowing the data buffer in the memcpy, but it seems like the underlying rpc read is not working correctly?

MarkRivers commented 4 years ago

@norumwe12 can you take a look at this issue?

MarkRivers commented 4 years ago

@jevarlec can you post your startup script, or at least the commands that load the vxi11 driver?

jevarlec commented 4 years ago

Here is an excerpt from the startup script that has to do with vxi11 configuration:

## Connection and database configuration env. variables
epicsEnvSet("PORT", "sigGen01")
epicsEnvSet("ADDR", "10.100.1.230")

## Asyn Configuration
vxi11Configure("$(PORT)", "$(ADDR)", 0, 0, "Inst0")
MarkRivers commented 4 years ago

I believe I may have a solution.

I think there are actually 2 problems:

1) The driver is returning 78 characters when it was only asked for 63. This appears that it may be a bug in the driver. 2) StreamDevice is expecting the driver to return data in smaller pieces than it reads from the device. I don't think the driver is capable of doing this.

Problem 2 is actually more serious. The VXI-11 driver is actually like the TCP driver. When it does a read it gets all of the data currently available from the device. That may be more than StreamDevice is asking for. However, it does not "remember" the additional characters beyond the ones that it returned to StreamDevice, and thus will not return them on the next StreamDevice read.

That capability of returning data in smaller pieces than the device returns is not the responsibility of the low level driver like drvAsynIPPort, drvAsynSerial, or drvVXI11. Rather it is the responsibility of the asynInterposeEos layer. drvAsynIPPortConfigure and drvAsynSerialPortConfigure can automatically set up asynInterposeEos. However, vxi11Configure does not do that. You need to manually add a asynInterposeEosConfig(portName,addr,processIn,processOut) command in your startup script after vxi11Configure if you want to read data in smaller chunks than the device delivers.

Note that you can specify processIn=0 and processOut=0 so it does not actually do any Eos processing. But it will still do the buffering you need. asynInterposeEos always reads from the underlying device with a large buffer size (2048 bytes). Thus it should not have a problem with buffer overflow due to Problem 1) in the driver.

Please try adding asynInterposeEosConfig in your startup script and see if it fixes the problem.

jevarlec commented 4 years ago

Setting asynInterposeEosConfig("$(PORT)", 0, 0, 0) produced the following:

# IOC initialization done
2020/02/19 10:06:19.853 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/19 10:06:19.853 sigGen01 schedule queueRequest timeout in 5.000000 seconds
2020/02/19 10:06:19.853 asynManager::portThread port=sigGen01 callback
2020/02/19 10:06:19.853 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/19 10:06:19.853 sigGen01 schedule queueRequest timeout in 0.100000 seconds
2020/02/19 10:06:19.853 asynManager::portThread port=sigGen01 callback
2020/02/19 10:06:19.853 sigGen01 get Eos 0
2020/02/19 10:06:19.853 sigGen01 set Eos 0
2020/02/19 10:06:19.853 sigGen01 -1 vxiWrite numchars 9
epics> 2020/02/19 10:06:20.022 sigGen01 -1 vxiWrite
C1:BSWV?\n
2020/02/19 10:06:20.022 sigGen01 set Eos 0
2020/02/19 10:06:20.022 sigGen01 addr -1 queueRequest priority 0 from lockHolder
2020/02/19 10:06:20.022 sigGen01 schedule queueRequest timeout in 1.000000 seconds
2020/02/19 10:06:20.022 asynManager::portThread port=sigGen01 callback
2020/02/19 10:06:20.022 sigGen01 vxiSetEos 1
\n
2020/02/19 10:06:20.188 sigGen01 -1 vxiRead, maxchars=63, thisRead=79
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/19 10:06:20.189 sigGen01 vxiSetEos 0

However, since streamdevice needs Eos support, I have tried asynInterposeEosConfig("$(PORT)", 0, 1, 1). This had a more desirable effect:

# IOC initialization done
epics> 2020/02/19 10:08:21.468 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/19 10:08:21.468 sigGen01 schedule queueRequest timeout in 5.000000 seconds
2020/02/19 10:08:21.468 asynManager::portThread port=sigGen01 callback
2020/02/19 10:08:21.468 sigGen01 addr -1 queueRequest priority 0 not lockHolder
2020/02/19 10:08:21.468 sigGen01 schedule queueRequest timeout in 0.100000 seconds
2020/02/19 10:08:21.468 asynManager::portThread port=sigGen01 callback
2020/02/19 10:08:21.468 sigGen01 flush
2020/02/19 10:08:21.468 sigGen01 get Eos 0
2020/02/19 10:08:21.468 sigGen01 set Eos 0
2020/02/19 10:08:21.468 sigGen01 -1 vxiWrite numchars 9
2020/02/19 10:08:21.639 sigGen01 -1 vxiWrite
C1:BSWV?\n
2020/02/19 10:08:21.639 sigGen01 wrote
C1:BSWV?\n
2020/02/19 10:08:21.639 sigGen01 set Eos 0
2020/02/19 10:08:21.639 sigGen01 addr -1 queueRequest priority 0 from lockHolder
2020/02/19 10:08:21.639 sigGen01 schedule queueRequest timeout in 1.000000 seconds
2020/02/19 10:08:21.639 asynManager::portThread port=sigGen01 callback
2020/02/19 10:08:21.639 sigGen01 get Eos 0
2020/02/19 10:08:21.639 sigGen01 set Eos 1
\n
2020/02/19 10:08:21.806 sigGen01 -1 vxiRead, maxchars=2048, thisRead=79
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/19 10:08:21.806 sigGen01 read 79 bytes eom=4
C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,LLEV,-2V,PHSE,0\n
2020/02/19 10:08:21.806 sigGen01 set Eos 0

Now we encounter another problem - ASYN_EOM_END seems to be propagated to the interpose layer and to streamdevice, which means streamdevice stops reading after 63 bytes and we are left with a partial read. Here is the streamDebug log in which eomReason=CNT+END:

epics> var streamDebug 1
epics> 2020/02/19 10:20:45.264221 CAS-client StreamEpics.cc:843: Stream::process(SIG-GEN-01:BasicWaveType_C1_STAT)
2020/02/19 10:20:45.264277 CAS-client StreamEpics.cc:869: Stream::process(SIG-GEN-01:BasicWaveType_C1_STAT) start
2020/02/19 10:20:45.264282 CAS-client StreamCore.cc:411: StreamCore::startProtocol(SIG-GEN-01:BasicWaveType_C1_STAT, startMode=StartNormal)
2020/02/19 10:20:45.264288 CAS-client StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BasicWaveType_C1_STAT): activeCommand = out
2020/02/19 10:20:45.264304 CAS-client StreamCore.cc:592: StreamCore::evalOut: outputLine = "C1:BSWV?<0a>"
2020/02/19 10:20:45.264310 CAS-client StreamCore.cc:603: StreamCore::evalOut(SIG-GEN-01:BasicWaveType_C1_STAT): lockRequest(5000)
2020/02/19 10:20:45.264314 CAS-client AsynDriverInterface.cc:548: AsynDriverInterface::lockRequest(SIG-GEN-01:BasicWaveType_C1_STAT, 5000 msec)
2020/02/19 10:20:45.264327 CAS-client StreamEpics.cc:883: Stream::process(SIG-GEN-01:BasicWaveType_C1_STAT): protocol started
2020/02/19 10:20:45.264355 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BasicWaveType_C1_STAT) Lock
2020/02/19 10:20:45.264364 sigGen01 AsynDriverInterface.cc:589: AsynDriverInterface::lockHandler(SIG-GEN-01:BasicWaveType_C1_STAT)
2020/02/19 10:20:45.264368 sigGen01 StreamCore.cc:812: StreamCore::lockCallback(SIG-GEN-01:BasicWaveType_C1_STAT, StreamIoSuccess)
2020/02/19 10:20:45.264373 sigGen01 AsynDriverInterface.cc:626: AsynDriverInterface::writeRequest(SIG-GEN-01:BasicWaveType_C1_STAT, "C1:BSWV?<0a>", 100 msec)
2020/02/19 10:20:45.264377 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BasicWaveType_C1_STAT) Write
2020/02/19 10:20:45.264380 sigGen01 AsynDriverInterface.cc:648: AsynDriverInterface::writeHandler(SIG-GEN-01:BasicWaveType_C1_STAT)
2020/02/19 10:20:45.264383 sigGen01 AsynDriverInterface.cc:678: AsynDriverInterface::writeHandler(SIG-GEN-01:BasicWaveType_C1_STAT): flushing old input
2020/02/19 10:20:45.461657 sigGen01 AsynDriverInterface.cc:714: AsynDriverInterface::writeHandler(SIG-GEN-01:BasicWaveType_C1_STAT): write(..., "C1:BSWV?<0a>", outputSize=9, written=9) [timeout=0.1 sec] = asynSuccess 
2020/02/19 10:20:45.461686 sigGen01 StreamCore.cc:857: StreamCore::writeCallback(SIG-GEN-01:BasicWaveType_C1_STAT, StreamIoSuccess)
2020/02/19 10:20:45.461690 sigGen01 StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BasicWaveType_C1_STAT): activeCommand = in
2020/02/19 10:20:45.461693 sigGen01 AsynDriverInterface.cc:805: AsynDriverInterface::readRequest(SIG-GEN-01:BasicWaveType_C1_STAT, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2020/02/19 10:20:45.461703 sigGen01 AsynDriverInterface.cc:830: AsynDriverInterface::readRequest SIG-GEN-01:BasicWaveType_C1_STAT: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2020/02/19 10:20:45.461709 sigGen01 AsynDriverInterface.cc:1493: AsynDriverInterface::handleRequest(SIG-GEN-01:BasicWaveType_C1_STAT) Read
2020/02/19 10:20:45.461713 sigGen01 AsynDriverInterface.cc:889: AsynDriverInterface::readHandler(SIG-GEN-01:BasicWaveType_C1_STAT) input EOS changed from "" to "<0a>"
2020/02/19 10:20:45.461716 sigGen01 AsynDriverInterface.cc:948: AsynDriverInterface::readHandler(SIG-GEN-01:BasicWaveType_C1_STAT): ioAction=Read read(..., bytesToRead=63, ...) [timeout=1 sec]
2020/02/19 10:20:45.646545 sigGen01 AsynDriverInterface.cc:956: AsynDriverInterface::readHandler(SIG-GEN-01:BasicWaveType_C1_STAT): read returned asynSuccess: ioAction=Read received=63, eomReason=CNT+END, buffer="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,"
2020/02/19 10:20:45.646607 sigGen01 AsynDriverInterface.cc:994: AsynDriverInterface::readHandler(SIG-GEN-01:BasicWaveType_C1_STAT): received 63 of 63 bytes "C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V," eomReason=CNT+END
2020/02/19 10:20:45.646614 sigGen01 StreamCore.cc:943: StreamCore::readCallback(SIG-GEN-01:BasicWaveType_C1_STAT, StreamIoEnd input="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,", size=63)
2020/02/19 10:20:45.646619 sigGen01 StreamCore.cc:993: StreamCore::readCallback(SIG-GEN-01:BasicWaveType_C1_STAT) inputBuffer="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,", size 63
2020/02/19 10:20:45.646623 sigGen01 StreamCore.cc:1038: StreamCore::readCallback(SIG-GEN-01:BasicWaveType_C1_STAT) inTerminator <0a> not found
2020/02/19 10:20:45.646626 sigGen01 StreamCore.cc:1045: StreamCore::readCallback(SIG-GEN-01:BasicWaveType_C1_STAT) end flag received
2020/02/19 10:20:45.646660 sigGen01 StreamCore.cc:1103: StreamCore::readCallback(SIG-GEN-01:BasicWaveType_C1_STAT) input line: "C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,"
2020/02/19 10:20:45.646686 sigGen01 StreamCore.cc:1192: StreamCore::matchInput(SIG-GEN-01:BasicWaveType_C1_STAT): format = "%#s"
2020/02/19 10:20:45.646722 sigGen01 StreamCore.cc:1534: StreamCore::scanValue(SIG-GEN-01:BasicWaveType_C1_STAT, format=%s, char*, size=64) input="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V," value="C1:BSWV WVTP,ARB,FRQ,1000HZ,PERI,0.001S,AMP,4V,OFST,0V,HLEV,2V,<00>"
2020/02/19 10:20:45.646727 sigGen01 StreamEpics.cc:935: Stream::scan() currentValueLength=63
2020/02/19 10:20:45.646730 sigGen01 StreamEpics.cc:1511: Stream::matchValue(SIG-GEN-01:BasicWaveType_C1_STAT): success, 63 bytes consumed
2020/02/19 10:20:45.646734 sigGen01 StreamCore.cc:544: StreamCore::evalCommand(SIG-GEN-01:BasicWaveType_C1_STAT): activeCommand = end
2020/02/19 10:20:45.646743 sigGen01 StreamCore.cc:447: StreamCore::finishProtocol(SIG-GEN-01:BasicWaveType_C1_STAT, Success) bus owner
2020/02/19 10:20:45.646748 sigGen01 AsynDriverInterface.cc:609: AsynDriverInterface::unlock(SIG-GEN-01:BasicWaveType_C1_STAT)
2020/02/19 10:20:45.646753 sigGen01 AsynDriverInterface.cc:1473: AsynDriverInterface::finish(SIG-GEN-01:BasicWaveType_C1_STAT) start
2020/02/19 10:20:45.646757 sigGen01 AsynDriverInterface.cc:1483: AsynDriverInterface::finish(SIG-GEN-01:BasicWaveType_C1_STAT) done
2020/02/19 10:20:45.646760 sigGen01 StreamEpics.cc:969: Stream::protocolFinishHook(SIG-GEN-01:BasicWaveType_C1_STAT, Success)
2020/02/19 10:20:45.646768 sigGen01 AsynDriverInterface.cc:1140: AsynDriverInterface::readHandler(SIG-GEN-01:BasicWaveType_C1_STAT) input EOS restored to ""
2020/02/19 10:20:45.646844 cbLow StreamEpics.cc:1047: recordProcessCallback(SIG-GEN-01:BasicWaveType_C1_STAT) processing record
2020/02/19 10:20:45.646883 cbLow StreamEpics.cc:843: Stream::process(SIG-GEN-01:BasicWaveType_C1_STAT)
2020/02/19 10:20:45.646886 cbLow StreamEpics.cc:857: Stream::process(SIG-GEN-01:BasicWaveType_C1_STAT) ready. don't convert
2020/02/19 10:20:45.646891 cbLow StreamEpics.cc:1051: recordProcessCallback(SIG-GEN-01:BasicWaveType_C1_STAT) processing record done

vxiRead has ASYN_EOM_END because it actually has read the whole message. But streamdevice does not read the whole message from asynInterposeEos layer, so the latter should not propagate ASYN_EOM_END to streamdevice.

MarkRivers commented 4 years ago

This is beginning to look very much like #28. It seems like the problem is actually in asynInterposeEos which is returning ASYN_EOM_END when it should not.

asynInterposeEos seems to work correctly with drvAsynSerialPort, which does not support ASYN_EOM_END. It also works correctly for drvAsynIPPort, but that driver only returns ASYN_EOM_END if the socket is closed, which is an unusual case.

@jevarlec if you can modify asynInterposeEos to fix the problem I'll be happy to accept a pull request.

jevarlec commented 4 years ago

I can try to fix the problem but can only afford testing with the device I currently have (that is using vxi11). Some one else will have to do further tests with other protocols.