1 INFO   NodeMain [main]: NodeMain.main(): portalHost = null
1355 INFO   NodeManager [main]: Starting NodeManager at 02/27/2016 23:37:49 GMT (1456616269792), version: $Name:  $
1357 INFO   NodeManager [main]: Node IP: node2/134.89.36.2
2025 INFO   NodeManager [main]: Node ID has been set to 1598
3234 INFO   PortManager [main]: Found 14 configured ports in properties file
3297 INFO   MOOSPortManager [main]: Found DPA at slot: 0
5178 INFO   MOOSPortManager [main]: Found DPA at slot: 1
6788 INFO   MOOSPortManager [main]: Found DPA at slot: 2
8378 INFO   MOOSPortManager [main]: Found DPA at slot: 3
9966 INFO   MOOSPortManager [main]: No DPA found at slot: 4
9970 INFO   MOOSPortManager [main]: No DPA found at slot: 5
10005 INFO   WDTManager [main]: WDTManager constructor
10006 INFO   MOOSWDTManager [main]: MOOSWDTManager constructor
10166 INFO   SleepManager [main]: SleepManager constructor
10169 INFO   MOOSSleepManager [main]: MOOSSleepManager constructor
11924 INFO   CommsLeaseListener [main]: CommsLeaseListener() complete
11990 INFO   CpuLeaseSleepRollcallListener [main]: CpuLeaseSleepRollcallListener() constructor
12005 INFO   CpuLease [main]: CpuLease() constructor
12013 INFO   CpuLease [Thread-5]: CpuLease started
13975 ERROR  NodeService [main]: Turbinator constructor failed: com.rbnb.sapi.SAPIException: Nesting java.net.ConnectException
14074 INFO   MOOSNodeService [main]: Last MMC reset code: 4
14294 INFO   NodeManager [main]: Starting registry... 
14332 INFO   NodeManager [main]: registry started.
14333 INFO   NodeManager [main]: binding NodeService to rmi://localhost/node
14883 INFO   NodeManager [main]: NodeService is bound to rmi://localhost/node
14909 INFO   MOOSWDTManager [Thread-2]: WDTManager initializing watchdog timer
14978 ERROR  MOOSWDTManager [Thread-2]: !!! Reboot due to watchdog reset !!!
15214 INFO   PortManager [main]: Service jar not specified for port /dev/ttySX0
16060 INFO   PortManager [main]: Starting service...
16807 INFO   MOOSWDTManager [Thread-2]: WDTManager watchdog initialization successful
32413 INFO   BaseInstrumentService [main]: initializeInstrument() for 
33988 WARN   StreamingSBE19 [main]: Did not receive expected confirmation prompt from command: MP
39023 INFO   StreamingSBE19 [main]: Event detection disabled by attribute
39171 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
47322 INFO   PortManager [main]: service started
47844 INFO   NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks
49191 INFO   PortManager [main]: Starting service...
69165 INFO   BaseInstrumentService [main]: initializeInstrument() for 
69167 INFO   WetLabsECO [main]: Initializing...
84537 INFO   WetLabsECO [main]: Initializing completed
84538 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
93570 INFO   PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1827
93572 INFO   PolledInstrumentService [main]: id 1535 slaved to 1827
93590 INFO   PortManager [main]: service started
93593 INFO   NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks
93630 INFO   WetLabsECO [Thread-25]: TEST: ID=1535, trigger sample at 1456616362074
95623 INFO   PortManager [main]: Starting service...
96001 INFO   WetLabsECO [Thread-25]: TEST: ID=1535, got complete sample at + 1456616364446
156751 INFO   BaseInstrumentService [main]: initializeInstrument() for 
158837 INFO   Aquadopp [main]: sendSoftBreak(): instrument in mode 2
165015 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
165121 INFO   Aquadopp [main]: Retrieving Aquadopp state Metadata...
167096 INFO   Aquadopp [main]: sendSoftBreak(): instrument in mode 2
174870 INFO   PortManager [main]: service started
174873 INFO   NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks
175279 INFO   PortManager [main]: Starting service...
176986 INFO   Aquadopp [Thread-34]: sendSoftBreak(): instrument in mode 2
186354 INFO   BaseInstrumentService [main]: initializeInstrument() for 
188288 ERROR  StreamingInstrumentService [Thread-34]: acquireFromStream(), tried startStreaming(): Instrument didn't acknowledge SR command
191216 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
193184 INFO   PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1535
193185 INFO   PolledInstrumentService [main]: id 1524 slaved to 1535
193192 INFO   PortManager [main]: service started
193194 INFO   NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks
193213 INFO   AanderaaO2 [Thread-38]: TT: ID=1524, trigger sample at 1456616461657
194271 INFO   PortManager [main]: Starting service...
229139 INFO   StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600
234763 INFO   BaseInstrumentService [main]: initializeInstrument() for 
234766 INFO   StreamingWorkhorseADCP-1825 [main]: Initializing Workhorse 1825
234776 INFO   StreamingWorkhorseADCP-1825 [main]: Instrument has been pre-configured; ignore configuration attributes
237864 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE?
237950 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
237994 INFO   StreamingWorkhorseADCP-1825 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100)
>
237995 INFO   StreamingWorkhorseADCP-1825 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100)
>
238233 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF?
238272 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
238317 INFO   StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>
238318 INFO   StreamingWorkhorseADCP-1825 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>
238320 INFO   StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>, char 3=1
238321 INFO   StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property char 3=1
238322 INFO   StreamingWorkhorseADCP-1825 [main]: Start pinging
238513 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
241664 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WD?
241702 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
242253 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WF?
242292 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
242824 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WN?
242862 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
243433 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WP?
243472 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
244003 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WS?
244042 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
244574 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WV?
244612 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
245144 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE?
245182 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
245723 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TP?
245762 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
246341 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TS?
246386 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
246913 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EA?
246952 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
247513 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EB?
247552 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
248083 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ED?
248122 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
248693 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ES?
248732 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
249304 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EX?
249342 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
249883 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EZ?
249922 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
250455 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF?
250502 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
251143 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RA?
251164 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
251923 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR?
251966 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 
257528 ERROR  StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 5556 ms outbuf.len=8192 avail: 56 read: 5366Request=RR?
258563 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR?
260814 ERROR  StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR?
261843 INFO   StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR?
264069 ERROR  StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR?
264650 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.<init>()V
   java/lang/Throwable.<init>(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


264881 INFO   PortManager [main]: service started
264884 INFO   NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks
266785 INFO   PortManager [main]: Starting service...
336356 ERROR  DeviceLog [main]: readLogData: data size mismatch
336358 ERROR  DeviceLog [main]:   bytes read from file: 1173
336359 ERROR  DeviceLog [main]:   dataSize in index entry: 1927
336490 INFO   StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600
347184 INFO   BaseInstrumentService [main]: initializeInstrument() for 
347186 INFO   StreamingWorkhorseADCP-1828 [main]: Initializing Workhorse 1828
347198 INFO   StreamingWorkhorseADCP-1828 [main]: Instrument has been pre-configured; ignore configuration attributes
349893 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE?
349933 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
349976 INFO   StreamingWorkhorseADCP-1828 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100)
>
349978 INFO   StreamingWorkhorseADCP-1828 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100)
>
350214 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF?
350253 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
350456 INFO   StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>
350457 INFO   StreamingWorkhorseADCP-1828 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>
350459 INFO   StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec)
>, char 3=1
350460 INFO   StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property char 3=1
350462 INFO   StreamingWorkhorseADCP-1828 [main]: Start pinging
350681 INFO   BaseInstrumentService [main]: done with initializeInstrument() for 
353604 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WD?
353643 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
354204 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WF?
354242 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
354833 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WN?
354872 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
355484 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WP?
355524 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
356073 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WS?
356113 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
356633 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WV?
356672 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
357213 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE?
357252 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
357813 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TP?
357853 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
358393 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TS?
358432 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
359033 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EA?
359073 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
359633 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EB?
359673 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
360213 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ED?
360252 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
360813 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ES?
360852 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
361393 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EX?
361432 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
362033 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EZ?
362072 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
362634 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF?
362673 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
363253 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RA?
363274 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
363853 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR?
363893 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 
369416 ERROR  StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 5520 ms outbuf.len=8192 avail: 1676 read: 3706Request=RR?
372315 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR?
374524 ERROR  StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR?
377764 INFO   StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR?
380024 ERROR  StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR?
380594 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.<init>()V
   java/lang/Throwable.<init>(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