1 INFO NodeMain [main]: NodeMain.main(): portalHost = null 1355 INFO NodeManager [main]: Starting NodeManager at 02/25/2016 21:12:48 GMT (1456434768691), version: $Name: $ 1357 INFO NodeManager [main]: Node IP: node2/134.89.36.2 2002 INFO NodeManager [main]: Node ID has been set to 1598 3215 INFO PortManager [main]: Found 14 configured ports in properties file 3278 INFO MOOSPortManager [main]: Found DPA at slot: 0 5169 INFO MOOSPortManager [main]: Found DPA at slot: 1 6779 INFO MOOSPortManager [main]: Found DPA at slot: 2 8369 INFO MOOSPortManager [main]: Found DPA at slot: 3 9957 INFO MOOSPortManager [main]: No DPA found at slot: 4 9961 INFO MOOSPortManager [main]: No DPA found at slot: 5 9996 INFO WDTManager [main]: WDTManager constructor 9997 INFO MOOSWDTManager [main]: MOOSWDTManager constructor 10061 INFO SleepManager [main]: SleepManager constructor 10065 INFO MOOSSleepManager [main]: MOOSSleepManager constructor 12135 INFO CommsLeaseListener [main]: CommsLeaseListener() complete 12201 INFO CpuLeaseSleepRollcallListener [main]: CpuLeaseSleepRollcallListener() constructor 12216 INFO CpuLease [main]: CpuLease() constructor 12218 INFO CpuLease [Thread-5]: CpuLease started 14247 ERROR NodeService [main]: Turbinator constructor failed: com.rbnb.sapi.SAPIException: Nesting java.net.ConnectException 14346 INFO MOOSNodeService [main]: Last MMC reset code: 6 14635 INFO NodeManager [main]: Starting registry... 14673 INFO NodeManager [main]: registry started. 14674 INFO NodeManager [main]: binding NodeService to rmi://localhost/node 15165 INFO NodeManager [main]: NodeService is bound to rmi://localhost/node 15305 INFO MOOSWDTManager [Thread-2]: WDTManager initializing watchdog timer 15313 ERROR MOOSWDTManager [Thread-2]: !!! Reboot due to watchdog reset !!! 15486 INFO PortManager [main]: Service jar not specified for port /dev/ttySX0 16381 INFO PortManager [main]: Starting service... 17669 INFO MOOSWDTManager [Thread-2]: WDTManager watchdog initialization successful 31984 INFO BaseInstrumentService [main]: initializeInstrument() for 33559 WARN StreamingSBE19 [main]: Did not receive expected confirmation prompt from command: MP 38594 INFO StreamingSBE19 [main]: Event detection disabled by attribute 38665 INFO BaseInstrumentService [main]: done with initializeInstrument() for 46822 INFO PortManager [main]: service started 47350 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 48146 INFO PortManager [main]: Starting service... 68465 INFO BaseInstrumentService [main]: initializeInstrument() for 68467 INFO WetLabsECO [main]: Initializing... 83900 INFO WetLabsECO [main]: Initializing completed 83901 INFO BaseInstrumentService [main]: done with initializeInstrument() for 92885 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1827 92887 INFO PolledInstrumentService [main]: id 1535 slaved to 1827 92905 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 92906 INFO PortManager [main]: service started 92980 INFO WetLabsECO [Thread-24]: TEST: ID=1535, trigger sample at 1456434860323 95089 INFO PortManager [main]: Starting service... 95353 INFO WetLabsECO [Thread-24]: TEST: ID=1535, got complete sample at + 1456434862697 155032 INFO BaseInstrumentService [main]: initializeInstrument() for 157038 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 163216 INFO BaseInstrumentService [main]: done with initializeInstrument() for 163390 INFO Aquadopp [main]: Retrieving Aquadopp state Metadata... 165367 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 173093 INFO PortManager [main]: service started 173095 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 173604 INFO PortManager [main]: Starting service... 175267 INFO Aquadopp [Thread-34]: sendSoftBreak(): instrument in mode 2 184634 INFO BaseInstrumentService [main]: initializeInstrument() for 186579 ERROR StreamingInstrumentService [Thread-34]: acquireFromStream(), tried startStreaming(): Instrument didn't acknowledge SR command 189587 INFO BaseInstrumentService [main]: done with initializeInstrument() for 191637 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1535 191638 INFO PolledInstrumentService [main]: id 1524 slaved to 1535 191644 INFO PortManager [main]: service started 191645 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 191665 INFO AanderaaO2 [Thread-38]: TT: ID=1524, trigger sample at 1456434959007 192720 INFO PortManager [main]: Starting service... 228029 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 233654 INFO BaseInstrumentService [main]: initializeInstrument() for 233657 INFO StreamingWorkhorseADCP-1825 [main]: Initializing Workhorse 1825 233667 INFO StreamingWorkhorseADCP-1825 [main]: Instrument has been pre-configured; ignore configuration attributes 236234 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 236611 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 236657 INFO StreamingWorkhorseADCP-1825 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 236658 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 236894 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 236933 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 237021 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 237022 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 237024 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 237026 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property char 3=1 237028 INFO StreamingWorkhorseADCP-1825 [main]: Start pinging 237212 INFO BaseInstrumentService [main]: done with initializeInstrument() for 240265 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WD? 240303 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 240885 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WF? 240923 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 241454 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WN? 241493 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 242065 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WP? 242103 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 242634 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WS? 242674 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 243194 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WV? 243233 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 243764 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 243803 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 244345 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TP? 244388 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 244924 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TS? 245011 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 245545 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EA? 245583 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246185 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EB? 246223 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246754 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ED? 246831 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 247365 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ES? 247403 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 247936 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EX? 247979 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 248524 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EZ? 248563 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249094 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 249133 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249724 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RA? 249748 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 250525 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 250563 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 256075 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 5505 ms outbuf.len=8192 avail: 79 read: 5287Request=RR? 257105 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 259325 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 260385 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 262605 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 263192 ERROR StreamingWorkhorseADCP-1825 [main]: getInstrumentMetadata: Exception - java.lang.Exception: sendRequest(RR?) - Maximum retries attempted java.lang.Exception: sendRequest(RR?) - Maximum retries attempted Stack trace: java/lang/Throwable.()V java/lang/Throwable.(Ljava/lang/String;)V org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.sendRequest(Ljava/lang/String;)Ljava/lang/String; org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.getInstrumentStateMetadata()[B org/mbari/siam/core/BaseInstrumentService.getMetadataPayload(I[Ljava/lang/String;)[B org/mbari/siam/core/BaseInstrumentService.getMetadata([BI[Ljava/lang/String;Z)Lorg/mbari/siam/distributed/MetadataPacket; org/mbari/siam/core/BaseInstrumentService.getMetadata([BIZ)Lorg/mbari/siam/distributed/MetadataPacket; org/mbari/siam/core/BaseInstrumentService.prepareToRun()V org/mbari/siam/core/PortManager.scanPort(Lorg/mbari/siam/core/DevicePort;Ljava/lang/String;)V org/mbari/siam/core/PortManager.scanPorts()V org/mbari/siam/core/NodeManager.start(Ljava/lang/String;Ljava/lang/String;)V org/mbari/siam/core/NodeMain.main([Ljava/lang/String;)V 263512 INFO PortManager [main]: service started 263515 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 265565 INFO PortManager [main]: Starting service... 338397 ERROR DeviceLog [main]: readLogData: data size mismatch 338398 ERROR DeviceLog [main]: bytes read from file: 1173 338399 ERROR DeviceLog [main]: dataSize in index entry: 1927 338477 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 349194 INFO BaseInstrumentService [main]: initializeInstrument() for 349197 INFO StreamingWorkhorseADCP-1828 [main]: Initializing Workhorse 1828 349209 INFO StreamingWorkhorseADCP-1828 [main]: Instrument has been pre-configured; ignore configuration attributes 351917 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 351967 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 352042 INFO StreamingWorkhorseADCP-1828 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 352043 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 352295 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 352338 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 352404 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 352405 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 352407 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 352409 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property char 3=1 352410 INFO StreamingWorkhorseADCP-1828 [main]: Start pinging 352592 INFO BaseInstrumentService [main]: done with initializeInstrument() for 355464 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WD? 355504 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 356055 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WF? 356095 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 356655 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WN? 356694 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 357234 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WP? 357273 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 357825 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WS? 357864 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 358404 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WV? 358443 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 359014 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 359054 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 359645 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TP? 359684 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 360255 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TS? 360295 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 360864 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EA? 360915 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 361515 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EB? 361557 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 362115 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ED? 362155 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 362725 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ES? 362764 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 363315 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EX? 363355 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 363947 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EZ? 363990 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 364555 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 364595 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 365175 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RA? 365196 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 365784 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 365884 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 372537 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 6650 ms outbuf.len=8192 avail: 3480 read: 3055Request=RR? 375064 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 377275 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 380535 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 382868 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 383435 ERROR StreamingWorkhorseADCP-1828 [main]: getInstrumentMetadata: Exception - java.lang.Exception: sendRequest(RR?) - Maximum retries attempted java.lang.Exception: sendRequest(RR?) - Maximum retries attempted Stack trace: java/lang/Throwable.()V java/lang/Throwable.(Ljava/lang/String;)V org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.sendRequest(Ljava/lang/String;)Ljava/lang/String; org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.getInstrumentStateMetadata()[B org/mbari/siam/core/BaseInstrumentService.getMetadataPayload(I[Ljava/lang/String;)[B org/mbari/siam/core/BaseInstrumentService.getMetadata([BI[Ljava/lang/String;Z)Lorg/mbari/siam/distributed/MetadataPacket; org/mbari/siam/core/BaseInstrumentService.getMetadata([BIZ)Lorg/mbari/siam/distributed/MetadataPacket; org/mbari/siam/core/BaseInstrumentService.prepareToRun()V org/mbari/siam/core/PortManager.scanPort(Lorg/mbari/siam/core/DevicePort;Ljava/lang/String;)V org/mbari/siam/core/PortManager.scanPorts()V org/mbari/siam/core/NodeManager.start(Ljava/lang/String;Ljava/lang/String;)V org/mbari/siam/core/NodeMain.main([Ljava/lang/String;)V