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:	Strangeness in ai/mbbiDirect with StreamDevice on PINI
From:	"Leblanc, Gregory via Tech-talk" <tech-talk at aps.anl.gov>
To:	"tech-talk at aps.anl.gov" <tech-talk at aps.anl.gov>
Date:	Mon, 26 Jun 2023 19:34:54 +0000

Hi folks,

I'm still working on getting these Heinzinger PCU 50-300 supplies doing everything I want using EPICS.  Today I thought I'd try reading the status word from the supply, so I added an mbbiDirect record.  The custom sections of my .db file now read:

record(ai, "$(P)$(R)GetCurrent") {
    field(DESC, "Read output current")
    field(DTYP, "stream")
    field(INP, "@devPCU50_300.proto getCurrent $(PORT) $(A)")
    # field(SCAN, "1 second")
    field(SCAN, "Passive")
    # field(PINI, "YES")
    field(EGU, "Amps")
    field(ESLO, "0.001")
    field(LINR, "SLOPE")
}

record(ao, "$(P)$(R)SetCurrent") {
    field(DESC, "Write output current")
    field(DTYP, "stream")
    # field(SCAN, "1 second")
    field(SCAN, "Passive")
    field(OUT, "@devPCU50_300.proto setCurrent(%d) $(PORT) $(A)")
    field(PINI, "YES")
    field(VAL, "0")
    # field(FLNK, "$(P)$(R)GetCurrent")
    field(EGU, "Amps")
    field(ESLO, "0.001")
    field(LINR, "SLOPE")
}

record(mbbiDirect, "$(P)$(R)StatusRegister") {
    field(DESC, "Status Register")
    field(NOBT, "24")
    field(DTYP, "stream")
    field(INP,  "@devPCU50_300.proto getStatus $(PORT) $(A)")
    field(PINI, "YES")
    field(SCAN, "Passive")
}

But I'm seeing some unexpected behavior, somehow related to my other records.  Above, the PINI field for the GetCurrent record is commented out.  When I start the IOC in this state, the StatusRegister record is properly populated.  If I set PINI to YES and start the IOC, the StatusRegister record is not properly populated.  Running the command 'dbtr PCU50_300testStatusRegister' on the "broken" startup will update it so that it has the correct status.  I've watched the console output when launching st.cmd, and browsed the logfiles that I generated, but I can't spot what I'm doing wrong.  I've attached a logfile where I have the problem, and another where I don't.  My .db, .proto, and st.cmd are at: https://github.com/leblancOUAL/PCU_50-300/

I feel like the root cause is that somehow the replies to the different serial commands are getting mixed up, but I can't see how that's possible.  It is more likely that I've done something silly along the way.  Any hints for troubleshooting are greatly appreciated!
     Greg

--
Gregory Leblanc
Accelerator Engineer
Edwards Accelerator Lab - Ohio University
123 University Terrace
Athens, OH 45701 USA
leblanc at ohio.edu
M: (401) 52-OUAL1 or (401) 526-8251

2023/06/26 12:46:58 StreamEpics.cc:451: drvStreamInit()
2023/06/26 12:46:58 StreamEpics.cc:473: StreamProtocolParser::path = /home/leblanc/EPICS/PCU50-300/db
2023/06/26 12:46:58.682991 _main_ StreamEpics.cc:588: streamInitRecord(PCU50_300testSetCurrent): SEVR=0
2023/06/26 12:46:58.683028 _main_ StreamEpics.cc:593: streamInitRecord(PCU50_300testSetCurrent): create new Stream object
2023/06/26 12:46:58.683180 _main_ StreamEpics.cc:623: streamInitRecord(PCU50_300testSetCurrent): calling initRecord
2023/06/26 12:46:58.683209 _main_ StreamEpics.cc:775: Stream::initRecord PCU50_300testSetCurrent: parse link string "devPCU50_300.proto setCurrent(%d) USB0 0"
2023/06/26 12:46:58.683226 _main_ StreamEpics.cc:807: Stream::initRecord PCU50_300testSetCurrent: filename="devPCU50_300.proto" protocol="setCurrent(%d)" bus="USB0" addr=0 params=""
2023/06/26 12:46:58.683239 _main_ StreamEpics.cc:827: Stream::initRecord PCU50_300testSetCurrent: attachBus("USB0", 0, "")
2023/06/26 12:46:58.683254 _main_ StreamBusInterface.cc:65: StreamBusInterface::find(PCU50_300testSetCurrent, USB0, 0, "")
2023/06/26 12:46:58.683266 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check DebugInterface
2023/06/26 12:46:58.683281 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DebugInterface does not match
2023/06/26 12:46:58.683292 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check DummyInterface
2023/06/26 12:46:58.683304 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DummyInterface does not match
2023/06/26 12:46:58.683314 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check AsynDriverInterface
2023/06/26 12:46:58.683327 _main_ AsynDriverInterface.cc:369: AsynDriverInterface::getBusInterface(PCU50_300testSetCurrent, USB0, 0)
2023/06/26 12:46:58.683340 _main_ AsynDriverInterface.cc:285: AsynDriverInterface(PCU50_300testSetCurrent)
2023/06/26 12:46:58.683349 _main_ AsynDriverInterface.cc:299: AsynDriverInterface(PCU50_300testSetCurrent) createAsynUser
2023/06/26 12:46:58.683362 _main_ AsynDriverInterface.cc:310: AsynDriverInterface(PCU50_300testSetCurrent) epicsTimerQueueActive::allocate(true)
2023/06/26 12:46:58.683375 _main_ AsynDriverInterface.cc:314: AsynDriverInterface(PCU50_300testSetCurrent) timerQueue->createTimer()
2023/06/26 12:46:58.683384 _main_ AsynDriverInterface.cc:318: AsynDriverInterface(PCU50_300testSetCurrent) done
2023/06/26 12:46:58.683397 _main_ AsynDriverInterface.cc:451: PCU50_300testSetCurrent: AsynDriverInterface::connectToBus(USB0, 0): pasynManager->connectDevice(0x16fd858, USB0, 0) = asynSuccess
2023/06/26 12:46:58.683413 _main_ AsynDriverInterface.cc:523: PCU50_300testSetCurrent: AsynDriverInterface::connectToBus(USB0, 0): device is now connected
2023/06/26 12:46:58.683425 _main_ AsynDriverInterface.cc:374: AsynDriverInterface::getBusInterface(USB0, 0): new interface allocated
2023/06/26 12:46:58.683435 _main_ StreamBusInterface.cc:74: StreamBusInterface::find AsynDriverInterface matches
2023/06/26 12:46:58.683452 _main_ StreamCore.cc:167: StreamCore::attachBus(busname="USB0", addr=0, param="") businterface=0x1710760
2023/06/26 12:46:58.683463 _main_ StreamEpics.cc:837: Stream::initRecord PCU50_300testSetCurrent: parse("devPCU50_300.proto", "setCurrent(%d)")
2023/06/26 12:46:58.683497 _main_ StreamCore.cc:229: StreamCore::parse "setCurrent(%d)" -> "setCurrent[7m<00>[27m%d"
2023/06/26 12:46:58.683511 _main_ StreamProtocol.cc:207: StreamProtocolParser::readFile: try '/home/leblanc/EPICS/PCU50-300/db/devPCU50_300.proto'
2023/06/26 12:46:58.683539 _main_ StreamProtocol.cc:210: StreamProtocolParser::readFile: found '/home/leblanc/EPICS/PCU50-300/db/devPCU50_300.proto'
2023/06/26 12:46:58.683590 _main_ StreamProtocol.cc:782: new Protocol(name="getidn", line=1)
2023/06/26 12:46:58.683618 _main_ StreamProtocol.cc:782: new Protocol(name="cmd", line=7)
2023/06/26 12:46:58.683634 _main_ StreamProtocol.cc:782: new Protocol(name="setd", line=11)
2023/06/26 12:46:58.683651 _main_ StreamProtocol.cc:782: new Protocol(name="getd", line=14)
2023/06/26 12:46:58.683688 _main_ StreamProtocol.cc:782: new Protocol(name="getcurrent", line=20)
2023/06/26 12:46:58.683711 _main_ StreamProtocol.cc:782: new Protocol(name="getvoltage", line=25)
2023/06/26 12:46:58.683729 _main_ StreamProtocol.cc:782: new Protocol(name="setcurrent", line=30)
2023/06/26 12:46:58.683745 _main_ StreamProtocol.cc:782: new Protocol(name="setstandby", line=34)
2023/06/26 12:46:58.683760 _main_ StreamProtocol.cc:782: new Protocol(name="seton", line=38)
2023/06/26 12:46:58.683796 _main_ StreamProtocol.cc:782: new Protocol(name="setoff", line=42)
2023/06/26 12:46:58.683830 _main_ StreamProtocol.cc:782: new Protocol(name="getstatus", line=46)
2023/06/26 12:46:58.683858 _main_ StreamProtocol.cc:782: new Protocol(name="setcurrent", line=30)
2023/06/26 12:46:58.683870 _main_ StreamProtocol.cc:797: StreamProtocolParser::Protocol::Protocol $1="%d"
2023/06/26 12:46:58.683905 _main_ StreamEpics.cc:868: Stream::initRecord PCU50_300testSetCurrent: initialize the first time
2023/06/26 12:46:58.683924 _main_ StreamEpics.cc:635: streamInitRecord(PCU50_300testSetCurrent) done status=0x2
2023/06/26 12:46:58.683937 _main_ StreamEpics.cc:588: streamInitRecord(PCU50_300testStatusRegister): SEVR=3
2023/06/26 12:46:58.683947 _main_ StreamEpics.cc:593: streamInitRecord(PCU50_300testStatusRegister): create new Stream object
2023/06/26 12:46:58.683961 _main_ StreamEpics.cc:623: streamInitRecord(PCU50_300testStatusRegister): calling initRecord
2023/06/26 12:46:58.683971 _main_ StreamEpics.cc:775: Stream::initRecord PCU50_300testStatusRegister: parse link string "devPCU50_300.proto getStatus USB0 0"
2023/06/26 12:46:58.683981 _main_ StreamEpics.cc:807: Stream::initRecord PCU50_300testStatusRegister: filename="devPCU50_300.proto" protocol="getStatus" bus="USB0" addr=0 params=""
2023/06/26 12:46:58.683991 _main_ StreamEpics.cc:827: Stream::initRecord PCU50_300testStatusRegister: attachBus("USB0", 0, "")
2023/06/26 12:46:58.684001 _main_ StreamBusInterface.cc:65: StreamBusInterface::find(PCU50_300testStatusRegister, USB0, 0, "")
2023/06/26 12:46:58.684012 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check DebugInterface
2023/06/26 12:46:58.684021 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DebugInterface does not match
2023/06/26 12:46:58.684031 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check DummyInterface
2023/06/26 12:46:58.684040 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DummyInterface does not match
2023/06/26 12:46:58.684060 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check AsynDriverInterface
2023/06/26 12:46:58.684074 _main_ AsynDriverInterface.cc:369: AsynDriverInterface::getBusInterface(PCU50_300testStatusRegister, USB0, 0)
2023/06/26 12:46:58.684085 _main_ AsynDriverInterface.cc:285: AsynDriverInterface(PCU50_300testStatusRegister)
2023/06/26 12:46:58.684094 _main_ AsynDriverInterface.cc:299: AsynDriverInterface(PCU50_300testStatusRegister) createAsynUser
2023/06/26 12:46:58.684106 _main_ AsynDriverInterface.cc:310: AsynDriverInterface(PCU50_300testStatusRegister) epicsTimerQueueActive::allocate(true)
2023/06/26 12:46:58.684117 _main_ AsynDriverInterface.cc:314: AsynDriverInterface(PCU50_300testStatusRegister) timerQueue->createTimer()
2023/06/26 12:46:58.684126 _main_ AsynDriverInterface.cc:318: AsynDriverInterface(PCU50_300testStatusRegister) done
2023/06/26 12:46:58.684136 _main_ AsynDriverInterface.cc:451: PCU50_300testStatusRegister: AsynDriverInterface::connectToBus(USB0, 0): pasynManager->connectDevice(0x1711778, USB0, 0) = asynSuccess
2023/06/26 12:46:58.684150 _main_ AsynDriverInterface.cc:523: PCU50_300testStatusRegister: AsynDriverInterface::connectToBus(USB0, 0): device is now connected
2023/06/26 12:46:58.684161 _main_ AsynDriverInterface.cc:374: AsynDriverInterface::getBusInterface(USB0, 0): new interface allocated
2023/06/26 12:46:58.684171 _main_ StreamBusInterface.cc:74: StreamBusInterface::find AsynDriverInterface matches
2023/06/26 12:46:58.684187 _main_ StreamCore.cc:167: StreamCore::attachBus(busname="USB0", addr=0, param="") businterface=0x17115a0
2023/06/26 12:46:58.684198 _main_ StreamEpics.cc:837: Stream::initRecord PCU50_300testStatusRegister: parse("devPCU50_300.proto", "getStatus")
2023/06/26 12:46:58.684209 _main_ StreamProtocol.cc:782: new Protocol(name="getstatus", line=46)
2023/06/26 12:46:58.684224 _main_ StreamEpics.cc:868: Stream::initRecord PCU50_300testStatusRegister: initialize the first time
2023/06/26 12:46:58.684236 _main_ StreamEpics.cc:635: streamInitRecord(PCU50_300testStatusRegister) done status=0x2
2023/06/26 12:46:59.185953 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testSetCurrent)
2023/06/26 12:46:59.186085 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testSetCurrent) start
2023/06/26 12:46:59.186106 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testSetCurrent, startMode=StartNormal)
2023/06/26 12:46:59.186126 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testSetCurrent): activeCommand = out
2023/06/26 12:46:59.186142 _main_ StreamCore.cc:689: StreamCore::formatOutput(PCU50_300testSetCurrent): format = %d
2023/06/26 12:46:59.186153 _main_ StreamEpics.cc:1173: Stream::formatValue(PCU50_300testSetCurrent, format=%d, fieldaddr=(nil)
2023/06/26 12:46:59.186165 _main_ StreamEpics.cc:1298: Stream::formatValue(PCU50_300testSetCurrent) format=%d type=DBF_LONG
2023/06/26 12:46:59.186177 _main_ StreamEpics.cc:693: streamPrintf(PCU50_300testSetCurrent,format=%d)
2023/06/26 12:46:59.186193 _main_ StreamCore.cc:777: StreamCore::printValue(PCU50_300testSetCurrent, %d, 0 = 0x0): "DA 0,0"
2023/06/26 12:46:59.186205 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "DA 0,0"
2023/06/26 12:46:59.186215 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testSetCurrent): lockRequest(5000)
2023/06/26 12:46:59.186226 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testSetCurrent, 5000 msec)
2023/06/26 12:46:59.186266 _main_ StreamEpics.cc:948: Stream::process(PCU50_300testSetCurrent): protocol started
2023/06/26 12:46:59.186286 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:46:59.186296 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testStatusRegister) start
2023/06/26 12:46:59.186306 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testStatusRegister, startMode=StartNormal)
2023/06/26 12:46:59.186316 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = out
2023/06/26 12:46:59.186327 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "S1H"
2023/06/26 12:46:59.186336 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testStatusRegister): lockRequest(5000)
2023/06/26 12:46:59.186369 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testStatusRegister, 5000 msec)
2023/06/26 12:46:59.186328 USB0 AsynDriverInterface.cc:590: AsynDriverInterface::lockHandler(PCU50_300testSetCurrent)
2023/06/26 12:46:59.186395 2023/06/26 12:46:59.186509 _main_ StreamEpics.cc:948: Stream::process(PCU50_300testStatusRegister): protocol started
USB0 StreamCore.cc:832: StreamCore::lockCallback(PCU50_300testSetCurrent, StreamIoSuccess)
2023/06/26 12:46:59.186561 USB0 AsynDriverInterface.cc:627: AsynDriverInterface::writeRequest(PCU50_300testSetCurrent, "DA 0,0", 100 msec)
2023/06/26 12:46:59.186616 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent)
2023/06/26 12:46:59.186628 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent): reading old input
2023/06/26 12:46:59.186902 USB0 AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent): write(..., "DA 0,0", outputSize=6, written=6) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:46:59.186933 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testSetCurrent, StreamIoSuccess)
2023/06/26 12:46:59.186947 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testSetCurrent): activeCommand = end
2023/06/26 12:46:59.186979 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testSetCurrent, Success) bus owner
2023/06/26 12:46:59.186991 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testSetCurrent)
2023/06/26 12:46:59.187002 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testSetCurrent) start
2023/06/26 12:46:59.187012 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testSetCurrent) done
2023/06/26 12:46:59.187021 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testSetCurrent, Success)
2023/06/26 12:46:59.187065 USB0 AsynDriverInterface.cc:590: AsynDriverInterface::lockHandler(PCU50_300testStatusRegister)
2023/06/26 12:46:59.187110 USB0 StreamCore.cc:832: StreamCore::lockCallback(PCU50_300testStatusRegister, StreamIoSuccess)
2023/06/26 12:46:59.187122 USB0 AsynDriverInterface.cc:627: AsynDriverInterface::writeRequest(PCU50_300testStatusRegister, "S1H", 100 msec)
2023/06/26 12:46:59.187144 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister)
2023/06/26 12:46:59.187155 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): reading old input
2023/06/26 12:46:59.187176 cbLow StreamEpics.cc:1112: recordProcessCallback(PCU50_300testSetCurrent) processing record
2023/06/26 12:46:59.187308 USB0 AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): write(..., "S1H", outputSize=3, written=3) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:46:59.187436 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testStatusRegister, StreamIoSuccess)
2023/06/26 12:46:59.187454 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = in
2023/06/26 12:46:59.187471 USB0 AsynDriverInterface.cc:806: AsynDriverInterface::readRequest(PCU50_300testStatusRegister, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2023/06/26 12:46:59.187507 USB0 AsynDriverInterface.cc:831: AsynDriverInterface::readRequest PCU50_300testStatusRegister: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2023/06/26 12:46:59.187592 cbLow StreamEpics.cc:908: Stream::process(PCU50_300testSetCurrent)
2023/06/26 12:46:59.187608 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testSetCurrent) ready. don't convert
2023/06/26 12:46:59.187665 cbLow StreamEpics.cc:1116: recordProcessCallback(PCU50_300testSetCurrent) processing record done
2023/06/26 12:46:59.206457 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(1 bytes, timeout=1 sec) returned status asynSuccess: received=1 bytes, eomReason=CNT, buffer="4"
2023/06/26 12:46:59.206565 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 1 of 1 bytes "4" eomReason=CNT
2023/06/26 12:46:59.206581 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoSuccess input="4", size=1)
2023/06/26 12:46:59.206593 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="4", size 1
2023/06/26 12:46:59.206603 USB0 StreamCore.cc:1096: StreamCore::readCallback(PCU50_300testStatusRegister) wait for more input
2023/06/26 12:46:59.206613 USB0 AsynDriverInterface.cc:1123: AsynDriverInterface::readHandler(PCU50_300testStatusRegister) readMore=-1 bytesToRead=63
2023/06/26 12:46:59.206625 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(63 bytes, timeout=0.1 sec) returned status asynSuccess: received=5 bytes, eomReason=EOS, buffer="08000"
2023/06/26 12:46:59.206638 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 5 of 63 bytes "08000" eomReason=EOS
2023/06/26 12:46:59.206648 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoEnd input="08000", size=5)
2023/06/26 12:46:59.206658 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="408000", size 6
2023/06/26 12:46:59.206690 USB0 StreamCore.cc:1067: StreamCore::readCallback(PCU50_300testStatusRegister) end flag received
2023/06/26 12:46:59.206701 USB0 StreamCore.cc:1127: StreamCore::readCallback(PCU50_300testStatusRegister) input line: "408000"
2023/06/26 12:46:59.206720 USB0 StreamCore.cc:1216: StreamCore::matchInput(PCU50_300testStatusRegister): format = "%d"
2023/06/26 12:46:59.206745 USB0 StreamCore.cc:1494: StreamCore::scanValue(PCU50_300testStatusRegister, format=%d, long) input="408000" value=408000
2023/06/26 12:46:59.206756 USB0 StreamEpics.cc:1000: Stream::scan() currentValueLength=6
2023/06/26 12:46:59.206766 USB0 StreamEpics.cc:1572: Stream::matchValue(PCU50_300testStatusRegister): success, 6 bytes consumed
2023/06/26 12:46:59.206778 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = end
2023/06/26 12:46:59.206788 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testStatusRegister, Success) bus owner
2023/06/26 12:46:59.206798 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testStatusRegister)
2023/06/26 12:46:59.206809 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testStatusRegister) start
2023/06/26 12:46:59.206820 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testStatusRegister) done
2023/06/26 12:46:59.206830 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testStatusRegister, Success)
2023/06/26 12:46:59.206910 cbLow StreamEpics.cc:1112: recordProcessCallback(PCU50_300testStatusRegister) processing record
2023/06/26 12:46:59.206995 cbLow StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:46:59.207007 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testStatusRegister) ready. don't convert
2023/06/26 12:46:59.207023 cbLow StreamEpics.cc:1116: recordProcessCallback(PCU50_300testStatusRegister) processing record done

2023/06/26 12:37:12 StreamEpics.cc:451: drvStreamInit()
2023/06/26 12:37:12 StreamEpics.cc:473: StreamProtocolParser::path = /home/leblanc/EPICS/PCU50-300/db
2023/06/26 12:37:12.497297 _main_ StreamEpics.cc:588: streamInitRecord(PCU50_300testGetCurrent): SEVR=3
2023/06/26 12:37:12.497340 _main_ StreamEpics.cc:593: streamInitRecord(PCU50_300testGetCurrent): create new Stream object
2023/06/26 12:37:12.497477 _main_ StreamEpics.cc:623: streamInitRecord(PCU50_300testGetCurrent): calling initRecord
2023/06/26 12:37:12.497498 _main_ StreamEpics.cc:775: Stream::initRecord PCU50_300testGetCurrent: parse link string "devPCU50_300.proto getCurrent USB0 0"
2023/06/26 12:37:12.497515 _main_ StreamEpics.cc:807: Stream::initRecord PCU50_300testGetCurrent: filename="devPCU50_300.proto" protocol="getCurrent" bus="USB0" addr=0 params=""
2023/06/26 12:37:12.497528 _main_ StreamEpics.cc:827: Stream::initRecord PCU50_300testGetCurrent: attachBus("USB0", 0, "")
2023/06/26 12:37:12.497542 _main_ StreamBusInterface.cc:65: StreamBusInterface::find(PCU50_300testGetCurrent, USB0, 0, "")
2023/06/26 12:37:12.497554 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testGetCurrent check DebugInterface
2023/06/26 12:37:12.497569 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DebugInterface does not match
2023/06/26 12:37:12.497579 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testGetCurrent check DummyInterface
2023/06/26 12:37:12.497591 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DummyInterface does not match
2023/06/26 12:37:12.497601 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testGetCurrent check AsynDriverInterface
2023/06/26 12:37:12.497613 _main_ AsynDriverInterface.cc:369: AsynDriverInterface::getBusInterface(PCU50_300testGetCurrent, USB0, 0)
2023/06/26 12:37:12.497630 _main_ AsynDriverInterface.cc:285: AsynDriverInterface(PCU50_300testGetCurrent)
2023/06/26 12:37:12.497641 _main_ AsynDriverInterface.cc:299: AsynDriverInterface(PCU50_300testGetCurrent) createAsynUser
2023/06/26 12:37:12.497653 _main_ AsynDriverInterface.cc:310: AsynDriverInterface(PCU50_300testGetCurrent) epicsTimerQueueActive::allocate(true)
2023/06/26 12:37:12.497664 _main_ AsynDriverInterface.cc:314: AsynDriverInterface(PCU50_300testGetCurrent) timerQueue->createTimer()
2023/06/26 12:37:12.497675 _main_ AsynDriverInterface.cc:318: AsynDriverInterface(PCU50_300testGetCurrent) done
2023/06/26 12:37:12.497688 _main_ AsynDriverInterface.cc:451: PCU50_300testGetCurrent: AsynDriverInterface::connectToBus(USB0, 0): pasynManager->connectDevice(0x6f7898, USB0, 0) = asynSuccess
2023/06/26 12:37:12.497705 _main_ AsynDriverInterface.cc:523: PCU50_300testGetCurrent: AsynDriverInterface::connectToBus(USB0, 0): device is now connected
2023/06/26 12:37:12.497716 _main_ AsynDriverInterface.cc:374: AsynDriverInterface::getBusInterface(USB0, 0): new interface allocated
2023/06/26 12:37:12.497728 _main_ StreamBusInterface.cc:74: StreamBusInterface::find AsynDriverInterface matches
2023/06/26 12:37:12.497745 _main_ StreamCore.cc:167: StreamCore::attachBus(busname="USB0", addr=0, param="") businterface=0x70aff0
2023/06/26 12:37:12.497756 _main_ StreamEpics.cc:837: Stream::initRecord PCU50_300testGetCurrent: parse("devPCU50_300.proto", "getCurrent")
2023/06/26 12:37:12.497779 _main_ StreamProtocol.cc:207: StreamProtocolParser::readFile: try '/home/leblanc/EPICS/PCU50-300/db/devPCU50_300.proto'
2023/06/26 12:37:12.497806 _main_ StreamProtocol.cc:210: StreamProtocolParser::readFile: found '/home/leblanc/EPICS/PCU50-300/db/devPCU50_300.proto'
2023/06/26 12:37:12.497884 _main_ StreamProtocol.cc:782: new Protocol(name="getidn", line=1)
2023/06/26 12:37:12.497933 _main_ StreamProtocol.cc:782: new Protocol(name="cmd", line=7)
2023/06/26 12:37:12.497950 _main_ StreamProtocol.cc:782: new Protocol(name="setd", line=11)
2023/06/26 12:37:12.497965 _main_ StreamProtocol.cc:782: new Protocol(name="getd", line=14)
2023/06/26 12:37:12.497988 _main_ StreamProtocol.cc:782: new Protocol(name="getcurrent", line=20)
2023/06/26 12:37:12.498006 _main_ StreamProtocol.cc:782: new Protocol(name="getvoltage", line=25)
2023/06/26 12:37:12.498043 _main_ StreamProtocol.cc:782: new Protocol(name="setcurrent", line=30)
2023/06/26 12:37:12.498061 _main_ StreamProtocol.cc:782: new Protocol(name="setstandby", line=34)
2023/06/26 12:37:12.498088 _main_ StreamProtocol.cc:782: new Protocol(name="seton", line=38)
2023/06/26 12:37:12.498122 _main_ StreamProtocol.cc:782: new Protocol(name="setoff", line=42)
2023/06/26 12:37:12.498140 _main_ StreamProtocol.cc:782: new Protocol(name="getstatus", line=46)
2023/06/26 12:37:12.498171 _main_ StreamProtocol.cc:782: new Protocol(name="getcurrent", line=20)
2023/06/26 12:37:12.498212 _main_ StreamEpics.cc:868: Stream::initRecord PCU50_300testGetCurrent: initialize the first time
2023/06/26 12:37:12.498233 _main_ StreamEpics.cc:635: streamInitRecord(PCU50_300testGetCurrent) done status=0x2
2023/06/26 12:37:12.498247 _main_ StreamEpics.cc:588: streamInitRecord(PCU50_300testSetCurrent): SEVR=0
2023/06/26 12:37:12.498258 _main_ StreamEpics.cc:593: streamInitRecord(PCU50_300testSetCurrent): create new Stream object
2023/06/26 12:37:12.498272 _main_ StreamEpics.cc:623: streamInitRecord(PCU50_300testSetCurrent): calling initRecord
2023/06/26 12:37:12.498283 _main_ StreamEpics.cc:775: Stream::initRecord PCU50_300testSetCurrent: parse link string "devPCU50_300.proto setCurrent(%d) USB0 0"
2023/06/26 12:37:12.498294 _main_ StreamEpics.cc:807: Stream::initRecord PCU50_300testSetCurrent: filename="devPCU50_300.proto" protocol="setCurrent(%d)" bus="USB0" addr=0 params=""
2023/06/26 12:37:12.498305 _main_ StreamEpics.cc:827: Stream::initRecord PCU50_300testSetCurrent: attachBus("USB0", 0, "")
2023/06/26 12:37:12.498315 _main_ StreamBusInterface.cc:65: StreamBusInterface::find(PCU50_300testSetCurrent, USB0, 0, "")
2023/06/26 12:37:12.498325 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check DebugInterface
2023/06/26 12:37:12.498336 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DebugInterface does not match
2023/06/26 12:37:12.498346 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check DummyInterface
2023/06/26 12:37:12.498355 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DummyInterface does not match
2023/06/26 12:37:12.498365 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testSetCurrent check AsynDriverInterface
2023/06/26 12:37:12.498374 _main_ AsynDriverInterface.cc:369: AsynDriverInterface::getBusInterface(PCU50_300testSetCurrent, USB0, 0)
2023/06/26 12:37:12.498385 _main_ AsynDriverInterface.cc:285: AsynDriverInterface(PCU50_300testSetCurrent)
2023/06/26 12:37:12.498395 _main_ AsynDriverInterface.cc:299: AsynDriverInterface(PCU50_300testSetCurrent) createAsynUser
2023/06/26 12:37:12.498408 _main_ AsynDriverInterface.cc:310: AsynDriverInterface(PCU50_300testSetCurrent) epicsTimerQueueActive::allocate(true)
2023/06/26 12:37:12.498419 _main_ AsynDriverInterface.cc:314: AsynDriverInterface(PCU50_300testSetCurrent) timerQueue->createTimer()
2023/06/26 12:37:12.498430 _main_ AsynDriverInterface.cc:318: AsynDriverInterface(PCU50_300testSetCurrent) done
2023/06/26 12:37:12.498440 _main_ AsynDriverInterface.cc:451: PCU50_300testSetCurrent: AsynDriverInterface::connectToBus(USB0, 0): pasynManager->connectDevice(0x70c008, USB0, 0) = asynSuccess
2023/06/26 12:37:12.498453 _main_ AsynDriverInterface.cc:523: PCU50_300testSetCurrent: AsynDriverInterface::connectToBus(USB0, 0): device is now connected
2023/06/26 12:37:12.498464 _main_ AsynDriverInterface.cc:374: AsynDriverInterface::getBusInterface(USB0, 0): new interface allocated
2023/06/26 12:37:12.498474 _main_ StreamBusInterface.cc:74: StreamBusInterface::find AsynDriverInterface matches
2023/06/26 12:37:12.498485 _main_ StreamCore.cc:167: StreamCore::attachBus(busname="USB0", addr=0, param="") businterface=0x70be30
2023/06/26 12:37:12.498496 _main_ StreamEpics.cc:837: Stream::initRecord PCU50_300testSetCurrent: parse("devPCU50_300.proto", "setCurrent(%d)")
2023/06/26 12:37:12.498515 _main_ StreamCore.cc:229: StreamCore::parse "setCurrent(%d)" -> "setCurrent[7m<00>[27m%d"
2023/06/26 12:37:12.498534 _main_ StreamProtocol.cc:782: new Protocol(name="setcurrent", line=30)
2023/06/26 12:37:12.498546 _main_ StreamProtocol.cc:797: StreamProtocolParser::Protocol::Protocol $1="%d"
2023/06/26 12:37:12.498562 _main_ StreamEpics.cc:868: Stream::initRecord PCU50_300testSetCurrent: initialize the first time
2023/06/26 12:37:12.498576 _main_ StreamEpics.cc:635: streamInitRecord(PCU50_300testSetCurrent) done status=0x2
2023/06/26 12:37:12.498590 _main_ StreamEpics.cc:588: streamInitRecord(PCU50_300testStatusRegister): SEVR=3
2023/06/26 12:37:12.498601 _main_ StreamEpics.cc:593: streamInitRecord(PCU50_300testStatusRegister): create new Stream object
2023/06/26 12:37:12.498615 _main_ StreamEpics.cc:623: streamInitRecord(PCU50_300testStatusRegister): calling initRecord
2023/06/26 12:37:12.498625 _main_ StreamEpics.cc:775: Stream::initRecord PCU50_300testStatusRegister: parse link string "devPCU50_300.proto getStatus USB0 0"
2023/06/26 12:37:12.498636 _main_ StreamEpics.cc:807: Stream::initRecord PCU50_300testStatusRegister: filename="devPCU50_300.proto" protocol="getStatus" bus="USB0" addr=0 params=""
2023/06/26 12:37:12.498647 _main_ StreamEpics.cc:827: Stream::initRecord PCU50_300testStatusRegister: attachBus("USB0", 0, "")
2023/06/26 12:37:12.498657 _main_ StreamBusInterface.cc:65: StreamBusInterface::find(PCU50_300testStatusRegister, USB0, 0, "")
2023/06/26 12:37:12.498667 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check DebugInterface
2023/06/26 12:37:12.498677 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DebugInterface does not match
2023/06/26 12:37:12.498687 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check DummyInterface
2023/06/26 12:37:12.498697 _main_ StreamBusInterface.cc:74: StreamBusInterface::find DummyInterface does not match
2023/06/26 12:37:12.498706 _main_ StreamBusInterface.cc:71: StreamBusInterface::find PCU50_300testStatusRegister check AsynDriverInterface
2023/06/26 12:37:12.498716 _main_ AsynDriverInterface.cc:369: AsynDriverInterface::getBusInterface(PCU50_300testStatusRegister, USB0, 0)
2023/06/26 12:37:12.498732 _main_ AsynDriverInterface.cc:285: AsynDriverInterface(PCU50_300testStatusRegister)
2023/06/26 12:37:12.498743 _main_ AsynDriverInterface.cc:299: AsynDriverInterface(PCU50_300testStatusRegister) createAsynUser
2023/06/26 12:37:12.498754 _main_ AsynDriverInterface.cc:310: AsynDriverInterface(PCU50_300testStatusRegister) epicsTimerQueueActive::allocate(true)
2023/06/26 12:37:12.498765 _main_ AsynDriverInterface.cc:314: AsynDriverInterface(PCU50_300testStatusRegister) timerQueue->createTimer()
2023/06/26 12:37:12.498776 _main_ AsynDriverInterface.cc:318: AsynDriverInterface(PCU50_300testStatusRegister) done
2023/06/26 12:37:12.498786 _main_ AsynDriverInterface.cc:451: PCU50_300testStatusRegister: AsynDriverInterface::connectToBus(USB0, 0): pasynManager->connectDevice(0x70e178, USB0, 0) = asynSuccess
2023/06/26 12:37:12.498799 _main_ AsynDriverInterface.cc:523: PCU50_300testStatusRegister: AsynDriverInterface::connectToBus(USB0, 0): device is now connected
2023/06/26 12:37:12.498810 _main_ AsynDriverInterface.cc:374: AsynDriverInterface::getBusInterface(USB0, 0): new interface allocated
2023/06/26 12:37:12.498821 _main_ StreamBusInterface.cc:74: StreamBusInterface::find AsynDriverInterface matches
2023/06/26 12:37:12.498831 _main_ StreamCore.cc:167: StreamCore::attachBus(busname="USB0", addr=0, param="") businterface=0x70dfa0
2023/06/26 12:37:12.498841 _main_ StreamEpics.cc:837: Stream::initRecord PCU50_300testStatusRegister: parse("devPCU50_300.proto", "getStatus")
2023/06/26 12:37:12.498853 _main_ StreamProtocol.cc:782: new Protocol(name="getstatus", line=46)
2023/06/26 12:37:12.498867 _main_ StreamEpics.cc:868: Stream::initRecord PCU50_300testStatusRegister: initialize the first time
2023/06/26 12:37:12.498879 _main_ StreamEpics.cc:635: streamInitRecord(PCU50_300testStatusRegister) done status=0x2
2023/06/26 12:37:12.999949 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testGetCurrent)
2023/06/26 12:37:13.000122 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testGetCurrent) start
2023/06/26 12:37:13.000142 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testGetCurrent, startMode=StartNormal)
2023/06/26 12:37:13.000158 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testGetCurrent): activeCommand = out
2023/06/26 12:37:13.000175 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "AD 0"
2023/06/26 12:37:13.000186 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testGetCurrent): lockRequest(5000)
2023/06/26 12:37:13.000197 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testGetCurrent, 5000 msec)
2023/06/26 12:37:13.000236 _main_ StreamEpics.cc:948: Stream::process(PCU50_300testGetCurrent): protocol started
2023/06/26 12:37:13.000261 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testSetCurrent)
2023/06/26 12:37:13.000273 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testSetCurrent) start
2023/06/26 12:37:13.000283 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testSetCurrent, startMode=StartNormal)
2023/06/26 12:37:13.000293 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testSetCurrent): activeCommand = out
2023/06/26 12:37:13.000304 _main_ StreamCore.cc:689: StreamCore::formatOutput(PCU50_300testSetCurrent): format = %d
2023/06/26 12:37:13.000315 _main_ StreamEpics.cc:1173: Stream::formatValue(PCU50_300testSetCurrent, format=%d, fieldaddr=(nil)
2023/06/26 12:37:13.000293 2023/06/26 12:37:13.000336 _main_ StreamEpics.cc:1298: Stream::formatValue(PCU50_300testSetCurrent) format=%d type=DBF_LONG
USB0 2023/06/26 12:37:13.000354 AsynDriverInterface.cc:590: _main_ AsynDriverInterface::lockHandler(PCU50_300testGetCurrent)
StreamEpics.cc:693: 2023/06/26 12:37:13.000410 USB0 StreamCore.cc:832: streamPrintf(PCU50_300testSetCurrent,format=%d)
StreamCore::lockCallback(PCU50_300testGetCurrent, StreamIoSuccess)
2023/06/26 12:37:13.000442 _main_ StreamCore.cc:777: StreamCore::printValue(PCU50_300testSetCurrent, %d, 0 = 0x0): "DA 0,0"
2023/06/26 12:37:13.000478 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "DA 0,0"
2023/06/26 12:37:13.000489 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testSetCurrent): lockRequest(5000)
2023/06/26 12:37:13.000499 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testSetCurrent, 5000 msec)
2023/06/26 12:37:13.000460 USB0 2023/06/26 12:37:13.000524 AsynDriverInterface.cc:627: _main_ AsynDriverInterface::writeRequest(PCU50_300testGetCurrent, "AD 0", 100 msec)
StreamEpics.cc:948: Stream::process(PCU50_300testSetCurrent): protocol started
2023/06/26 12:37:13.000564 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testGetCurrent)
2023/06/26 12:37:13.000584 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testGetCurrent): reading old input
2023/06/26 12:37:13.000570 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:37:13.000619 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testStatusRegister) start
2023/06/26 12:37:13.000630 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testStatusRegister, startMode=StartNormal)
2023/06/26 12:37:13.000640 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = out
2023/06/26 12:37:13.000651 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "S1H"
2023/06/26 12:37:13.000661 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testStatusRegister): lockRequest(5000)
2023/06/26 12:37:13.000670 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testStatusRegister, 5000 msec)
2023/06/26 12:37:13.000684 _main_ StreamEpics.cc:948: Stream::process(PCU50_300testStatusRegister): protocol started
2023/06/26 12:37:13.000887 USB0 AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testGetCurrent): write(..., "AD 0", outputSize=4, written=4) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:37:13.000946 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testGetCurrent, StreamIoSuccess)
2023/06/26 12:37:13.000960 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testGetCurrent): activeCommand = in
2023/06/26 12:37:13.000974 USB0 AsynDriverInterface.cc:806: AsynDriverInterface::readRequest(PCU50_300testGetCurrent, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2023/06/26 12:37:13.001078 USB0 AsynDriverInterface.cc:831: AsynDriverInterface::readRequest PCU50_300testGetCurrent: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2023/06/26 12:37:13.016932 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testGetCurrent): ioAction=Read read(1 bytes, timeout=1 sec) returned status asynSuccess: received=1 bytes, eomReason=CNT, buffer="0"
2023/06/26 12:37:13.017001 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testGetCurrent): received 1 of 1 bytes "0" eomReason=CNT
2023/06/26 12:37:13.017017 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testGetCurrent, StreamIoSuccess input="0", size=1)
2023/06/26 12:37:13.017097 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testGetCurrent) inputBuffer="0", size 1
2023/06/26 12:37:13.017113 USB0 StreamCore.cc:1096: StreamCore::readCallback(PCU50_300testGetCurrent) wait for more input
2023/06/26 12:37:13.017124 USB0 AsynDriverInterface.cc:1123: AsynDriverInterface::readHandler(PCU50_300testGetCurrent) readMore=-1 bytesToRead=63
2023/06/26 12:37:13.017136 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testGetCurrent): ioAction=Read read(63 bytes, timeout=0.1 sec) returned status asynSuccess: received=5 bytes, eomReason=EOS, buffer="00000"
2023/06/26 12:37:13.017152 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testGetCurrent): received 5 of 63 bytes "00000" eomReason=EOS
2023/06/26 12:37:13.017163 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testGetCurrent, StreamIoEnd input="00000", size=5)
2023/06/26 12:37:13.017173 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testGetCurrent) inputBuffer="000000", size 6
2023/06/26 12:37:13.017183 USB0 StreamCore.cc:1067: StreamCore::readCallback(PCU50_300testGetCurrent) end flag received
2023/06/26 12:37:13.017194 USB0 StreamCore.cc:1127: StreamCore::readCallback(PCU50_300testGetCurrent) input line: "000000"
2023/06/26 12:37:13.017213 USB0 StreamCore.cc:1216: StreamCore::matchInput(PCU50_300testGetCurrent): format = "%d"
2023/06/26 12:37:13.017239 USB0 StreamCore.cc:1494: StreamCore::scanValue(PCU50_300testGetCurrent, format=%d, long) input="000000" value=0
2023/06/26 12:37:13.017251 USB0 StreamEpics.cc:1000: Stream::scan() currentValueLength=6
2023/06/26 12:37:13.017262 USB0 StreamEpics.cc:1572: Stream::matchValue(PCU50_300testGetCurrent): success, 6 bytes consumed
2023/06/26 12:37:13.017274 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testGetCurrent): activeCommand = end
2023/06/26 12:37:13.017286 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testGetCurrent, Success) bus owner
2023/06/26 12:37:13.017297 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testGetCurrent)
2023/06/26 12:37:13.017311 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testGetCurrent) start
2023/06/26 12:37:13.017322 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testGetCurrent) done
2023/06/26 12:37:13.017332 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testGetCurrent, Success)
2023/06/26 12:37:13.017366 USB0 AsynDriverInterface.cc:590: AsynDriverInterface::lockHandler(PCU50_300testSetCurrent)
2023/06/26 12:37:13.017380 USB0 StreamCore.cc:832: StreamCore::lockCallback(PCU50_300testSetCurrent, StreamIoSuccess)
2023/06/26 12:37:13.017391 USB0 AsynDriverInterface.cc:627: AsynDriverInterface::writeRequest(PCU50_300testSetCurrent, "DA 0,0", 100 msec)
2023/06/26 12:37:13.017420 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent)
2023/06/26 12:37:13.017454 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent): reading old input
2023/06/26 12:37:13.017481 cbLow StreamEpics.cc:1112: recordProcessCallback(PCU50_300testGetCurrent) processing record
2023/06/26 12:37:13.017571 cbLow StreamEpics.cc:908: Stream::process(PCU50_300testGetCurrent)
2023/06/26 12:37:13.017586 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testGetCurrent) ready. don't convert
2023/06/26 12:37:13.017618 cbLow StreamEpics.cc:1116: recordProcessCallback(PCU50_300testGetCurrent) processing record done
2023/06/26 12:37:13.017637 USB0 AsynDriverInterface.cc:672: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent): flushing 1 bytes: "[7m<0d>[27m"
2023/06/26 12:37:13.017740 USB0 AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testSetCurrent): write(..., "DA 0,0", outputSize=6, written=6) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:37:13.017761 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testSetCurrent, StreamIoSuccess)
2023/06/26 12:37:13.017773 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testSetCurrent): activeCommand = end
2023/06/26 12:37:13.017784 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testSetCurrent, Success) bus owner
2023/06/26 12:37:13.017795 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testSetCurrent)
2023/06/26 12:37:13.017805 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testSetCurrent) start
2023/06/26 12:37:13.017816 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testSetCurrent) done
2023/06/26 12:37:13.017826 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testSetCurrent, Success)
2023/06/26 12:37:13.017850 USB0 AsynDriverInterface.cc:590: AsynDriverInterface::lockHandler(PCU50_300testStatusRegister)
2023/06/26 12:37:13.017894 2023/06/26 12:37:13.017897 USB0 cbLow StreamCore.cc:832: StreamEpics.cc:1112: StreamCore::lockCallback(PCU50_300testStatusRegister, StreamIoSuccess)
recordProcessCallback(PCU50_300testSetCurrent) processing record
2023/06/26 12:37:13.017968 2023/06/26 12:37:13.017988 USB0 AsynDriverInterface.cc:627: cbLow AsynDriverInterface::writeRequest(PCU50_300testStatusRegister, "S1H", 100 msec)
StreamEpics.cc:908: Stream::process(PCU50_300testSetCurrent)
2023/06/26 12:37:13.018022 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister)
2023/06/26 12:37:13.018040 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): reading old input
2023/06/26 12:37:13.018026 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testSetCurrent) ready. don't convert
2023/06/26 12:37:13.018117 2023/06/26 12:37:13.018164 cbLow StreamEpics.cc:1116: USB0 recordProcessCallback(PCU50_300testSetCurrent) processing record done
AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): write(..., "S1H", outputSize=3, written=3) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:37:13.018220 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testStatusRegister, StreamIoSuccess)
2023/06/26 12:37:13.018233 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = in
2023/06/26 12:37:13.018244 USB0 AsynDriverInterface.cc:806: AsynDriverInterface::readRequest(PCU50_300testStatusRegister, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2023/06/26 12:37:13.018264 USB0 AsynDriverInterface.cc:831: AsynDriverInterface::readRequest PCU50_300testStatusRegister: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2023/06/26 12:37:13.033226 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(1 bytes, timeout=1 sec) returned status asynSuccess: received=1 bytes, eomReason=CNT, buffer="0"
2023/06/26 12:37:13.033374 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 1 of 1 bytes "0" eomReason=CNT
2023/06/26 12:37:13.033409 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoSuccess input="0", size=1)
2023/06/26 12:37:13.033422 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="0", size 1
2023/06/26 12:37:13.033432 USB0 StreamCore.cc:1096: StreamCore::readCallback(PCU50_300testStatusRegister) wait for more input
2023/06/26 12:37:13.033442 USB0 AsynDriverInterface.cc:1123: AsynDriverInterface::readHandler(PCU50_300testStatusRegister) readMore=-1 bytesToRead=63
2023/06/26 12:37:13.049004 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(63 bytes, timeout=0.1 sec) returned status asynSuccess: received=5 bytes, eomReason=EOS, buffer="00000"
2023/06/26 12:37:13.049109 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 5 of 63 bytes "00000" eomReason=EOS
2023/06/26 12:37:13.049128 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoEnd input="00000", size=5)
2023/06/26 12:37:13.049141 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="000000", size 6
2023/06/26 12:37:13.049151 USB0 StreamCore.cc:1067: StreamCore::readCallback(PCU50_300testStatusRegister) end flag received
2023/06/26 12:37:13.049162 USB0 StreamCore.cc:1127: StreamCore::readCallback(PCU50_300testStatusRegister) input line: "000000"
2023/06/26 12:37:13.049175 USB0 StreamCore.cc:1216: StreamCore::matchInput(PCU50_300testStatusRegister): format = "%d"
2023/06/26 12:37:13.049189 USB0 StreamCore.cc:1494: StreamCore::scanValue(PCU50_300testStatusRegister, format=%d, long) input="000000" value=0
2023/06/26 12:37:13.049200 USB0 StreamEpics.cc:1000: Stream::scan() currentValueLength=6
2023/06/26 12:37:13.049211 USB0 StreamEpics.cc:1572: Stream::matchValue(PCU50_300testStatusRegister): success, 6 bytes consumed
2023/06/26 12:37:13.049222 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = end
2023/06/26 12:37:13.049232 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testStatusRegister, Success) bus owner
2023/06/26 12:37:13.049243 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testStatusRegister)
2023/06/26 12:37:13.049256 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testStatusRegister) start
2023/06/26 12:37:13.049267 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testStatusRegister) done
2023/06/26 12:37:13.049277 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testStatusRegister, Success)
2023/06/26 12:37:13.049333 cbLow StreamEpics.cc:1112: recordProcessCallback(PCU50_300testStatusRegister) processing record
2023/06/26 12:37:13.049412 cbLow StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:37:13.049426 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testStatusRegister) ready. don't convert
2023/06/26 12:37:13.049444 cbLow StreamEpics.cc:1116: recordProcessCallback(PCU50_300testStatusRegister) processing record done
2023/06/26 12:40:40.842101 _main_ StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:40:40.842223 _main_ StreamEpics.cc:934: Stream::process(PCU50_300testStatusRegister) start
2023/06/26 12:40:40.842237 _main_ StreamCore.cc:429: StreamCore::startProtocol(PCU50_300testStatusRegister, startMode=StartNormal)
2023/06/26 12:40:40.842255 _main_ StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = out
2023/06/26 12:40:40.842267 _main_ StreamCore.cc:612: StreamCore::evalOut: outputLine = "S1H"
2023/06/26 12:40:40.842275 _main_ StreamCore.cc:623: StreamCore::evalOut(PCU50_300testStatusRegister): lockRequest(5000)
2023/06/26 12:40:40.842285 _main_ AsynDriverInterface.cc:549: AsynDriverInterface::lockRequest(PCU50_300testStatusRegister, 5000 msec)
2023/06/26 12:40:40.842321 _main_ StreamEpics.cc:948: Stream::process(PCU50_300testStatusRegister): protocol started
2023/06/26 12:40:40.842366 USB0 AsynDriverInterface.cc:590: AsynDriverInterface::lockHandler(PCU50_300testStatusRegister)
2023/06/26 12:40:40.842385 USB0 StreamCore.cc:832: StreamCore::lockCallback(PCU50_300testStatusRegister, StreamIoSuccess)
2023/06/26 12:40:40.842397 USB0 AsynDriverInterface.cc:627: AsynDriverInterface::writeRequest(PCU50_300testStatusRegister, "S1H", 100 msec)
2023/06/26 12:40:40.842459 USB0 AsynDriverInterface.cc:649: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister)
2023/06/26 12:40:40.842472 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): reading old input
2023/06/26 12:40:40.842485 USB0 AsynDriverInterface.cc:672: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): flushing 6 bytes: "[7m<0d>[27m08000"
2023/06/26 12:40:40.842497 USB0 AsynDriverInterface.cc:667: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): reading old input
2023/06/26 12:40:40.842723 USB0 AsynDriverInterface.cc:672: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): flushing 1 bytes: "[7m<0d>[27m"
2023/06/26 12:40:40.842801 USB0 AsynDriverInterface.cc:715: AsynDriverInterface::writeHandler(PCU50_300testStatusRegister): write(..., "S1H", outputSize=3, written=3) [timeout=0.1 sec] = asynSuccess 
2023/06/26 12:40:40.842827 USB0 StreamCore.cc:877: StreamCore::writeCallback(PCU50_300testStatusRegister, StreamIoSuccess)
2023/06/26 12:40:40.842839 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = in
2023/06/26 12:40:40.842850 USB0 AsynDriverInterface.cc:806: AsynDriverInterface::readRequest(PCU50_300testStatusRegister, 1000 msec reply, 100 msec read, expect 0 bytes, async=no)
2023/06/26 12:40:40.842871 USB0 AsynDriverInterface.cc:831: AsynDriverInterface::readRequest PCU50_300testStatusRegister: queueRequest(..., priority=0, queueTimeout=1 sec) = asynSuccess [async=false] 
2023/06/26 12:40:40.860265 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(1 bytes, timeout=1 sec) returned status asynSuccess: received=1 bytes, eomReason=CNT, buffer="4"
2023/06/26 12:40:40.860373 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 1 of 1 bytes "4" eomReason=CNT
2023/06/26 12:40:40.860390 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoSuccess input="4", size=1)
2023/06/26 12:40:40.860422 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="4", size 1
2023/06/26 12:40:40.860452 USB0 StreamCore.cc:1096: StreamCore::readCallback(PCU50_300testStatusRegister) wait for more input
2023/06/26 12:40:40.860462 USB0 AsynDriverInterface.cc:1123: AsynDriverInterface::readHandler(PCU50_300testStatusRegister) readMore=-1 bytesToRead=63
2023/06/26 12:40:40.860473 USB0 AsynDriverInterface.cc:951: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): ioAction=Read read(63 bytes, timeout=0.1 sec) returned status asynSuccess: received=5 bytes, eomReason=EOS, buffer="08000"
2023/06/26 12:40:40.860488 USB0 AsynDriverInterface.cc:990: AsynDriverInterface::readHandler(PCU50_300testStatusRegister): received 5 of 63 bytes "08000" eomReason=EOS
2023/06/26 12:40:40.860499 USB0 StreamCore.cc:963: StreamCore::readCallback(PCU50_300testStatusRegister, StreamIoEnd input="08000", size=5)
2023/06/26 12:40:40.860509 USB0 StreamCore.cc:1015: StreamCore::readCallback(PCU50_300testStatusRegister) inputBuffer="408000", size 6
2023/06/26 12:40:40.860519 USB0 StreamCore.cc:1067: StreamCore::readCallback(PCU50_300testStatusRegister) end flag received
2023/06/26 12:40:40.860528 USB0 StreamCore.cc:1127: StreamCore::readCallback(PCU50_300testStatusRegister) input line: "408000"
2023/06/26 12:40:40.860540 USB0 StreamCore.cc:1216: StreamCore::matchInput(PCU50_300testStatusRegister): format = "%d"
2023/06/26 12:40:40.860554 USB0 StreamCore.cc:1494: StreamCore::scanValue(PCU50_300testStatusRegister, format=%d, long) input="408000" value=408000
2023/06/26 12:40:40.860584 USB0 StreamEpics.cc:1000: Stream::scan() currentValueLength=6
2023/06/26 12:40:40.860595 USB0 StreamEpics.cc:1572: Stream::matchValue(PCU50_300testStatusRegister): success, 6 bytes consumed
2023/06/26 12:40:40.860606 USB0 StreamCore.cc:564: StreamCore::evalCommand(PCU50_300testStatusRegister): activeCommand = end
2023/06/26 12:40:40.860616 USB0 StreamCore.cc:465: StreamCore::finishProtocol(PCU50_300testStatusRegister, Success) bus owner
2023/06/26 12:40:40.860626 USB0 AsynDriverInterface.cc:610: AsynDriverInterface::unlock(PCU50_300testStatusRegister)
2023/06/26 12:40:40.860638 USB0 AsynDriverInterface.cc:1468: AsynDriverInterface::finish(PCU50_300testStatusRegister) start
2023/06/26 12:40:40.860650 USB0 AsynDriverInterface.cc:1478: AsynDriverInterface::finish(PCU50_300testStatusRegister) done
2023/06/26 12:40:40.860659 USB0 StreamEpics.cc:1034: Stream::protocolFinishHook(PCU50_300testStatusRegister, Success)
2023/06/26 12:40:40.860702 cbLow StreamEpics.cc:1112: recordProcessCallback(PCU50_300testStatusRegister) processing record
2023/06/26 12:40:40.860764 cbLow StreamEpics.cc:908: Stream::process(PCU50_300testStatusRegister)
2023/06/26 12:40:40.860777 cbLow StreamEpics.cc:922: Stream::process(PCU50_300testStatusRegister) ready. don't convert
2023/06/26 12:40:40.860793 cbLow StreamEpics.cc:1116: recordProcessCallback(PCU50_300testStatusRegister) processing record done

Replies:: Re: Strangeness in ai/mbbiDirect with StreamDevice on PINI Michael Davidsaver via Tech-talk; Re: Strangeness in ai/mbbiDirect with StreamDevice on PINI Zimoch Dirk via Tech-talk

Navigate by Date:: Prev: Strangeness in ai/mbbiDirect with StreamDevice on PINI Leblanc, Gregory via Tech-talk; Next: Re: Strangeness in ai/mbbiDirect with StreamDevice on PINI Michael Davidsaver 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: Strangeness in ai/mbbiDirect with StreamDevice on PINI Leblanc, Gregory via Tech-talk; Next: Re: Strangeness in ai/mbbiDirect with StreamDevice on PINI Michael Davidsaver 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

ANJ, 27 Jun 2023

· Home · News · About · Base · Modules · Extensions · Distributions · Download ·
· Search · EPICS V4 · IRMIS · Talk · Bugs · Documents · Links · Licensing ·

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System