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
