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
