1 INFO NodeMain [main]: NodeMain.main(): portalHost = null 1379 INFO NodeManager [main]: Starting NodeManager at 02/28/2016 17:12:58 GMT (1456679578715), version: $Name: $ 1381 INFO NodeManager [main]: Node IP: node2/134.89.36.2 2051 INFO NodeManager [main]: Node ID has been set to 1598 3265 INFO PortManager [main]: Found 14 configured ports in properties file 3328 INFO MOOSPortManager [main]: Found DPA at slot: 0 5209 INFO MOOSPortManager [main]: Found DPA at slot: 1 6819 INFO MOOSPortManager [main]: Found DPA at slot: 2 8409 INFO MOOSPortManager [main]: Found DPA at slot: 3 9997 INFO MOOSPortManager [main]: No DPA found at slot: 4 10001 INFO MOOSPortManager [main]: No DPA found at slot: 5 10036 INFO WDTManager [main]: WDTManager constructor 10037 INFO MOOSWDTManager [main]: MOOSWDTManager constructor 10101 INFO SleepManager [main]: SleepManager constructor 10104 INFO MOOSSleepManager [main]: MOOSSleepManager constructor 12225 INFO CommsLeaseListener [main]: CommsLeaseListener() complete 12291 INFO CpuLeaseSleepRollcallListener [main]: CpuLeaseSleepRollcallListener() constructor 12306 INFO CpuLease [main]: CpuLease() constructor 12309 INFO CpuLease [Thread-5]: CpuLease started 14226 ERROR NodeService [main]: Turbinator constructor failed: com.rbnb.sapi.SAPIException: Nesting java.net.ConnectException 14325 INFO MOOSNodeService [main]: Last MMC reset code: 4 14535 INFO NodeManager [main]: Starting registry... 14572 INFO NodeManager [main]: registry started. 14574 INFO NodeManager [main]: binding NodeService to rmi://localhost/node 15125 INFO NodeManager [main]: NodeService is bound to rmi://localhost/node 15265 INFO MOOSWDTManager [Thread-2]: WDTManager initializing watchdog timer 15272 ERROR MOOSWDTManager [Thread-2]: !!! Reboot due to watchdog reset !!! 15910 INFO PortManager [main]: Service jar not specified for port /dev/ttySX0 16850 INFO PortManager [main]: Starting service... 16965 INFO MOOSWDTManager [Thread-2]: WDTManager watchdog initialization successful 33184 INFO BaseInstrumentService [main]: initializeInstrument() for 34759 WARN StreamingSBE19 [main]: Did not receive expected confirmation prompt from command: MP 39784 INFO StreamingSBE19 [main]: Event detection disabled by attribute 39855 INFO BaseInstrumentService [main]: done with initializeInstrument() for 47981 INFO PortManager [main]: service started 48595 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 49534 INFO PortManager [main]: Starting service... 69574 INFO BaseInstrumentService [main]: initializeInstrument() for 69576 INFO WetLabsECO [main]: Initializing... 84988 INFO WetLabsECO [main]: Initializing completed 84989 INFO BaseInstrumentService [main]: done with initializeInstrument() for 94016 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1827 94019 INFO PolledInstrumentService [main]: id 1535 slaved to 1827 94037 INFO PortManager [main]: service started 94043 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 94065 INFO WetLabsECO [Thread-25]: TEST: ID=1535, trigger sample at 1456679671409 96102 INFO PortManager [main]: Starting service... 96491 INFO WetLabsECO [Thread-25]: TEST: ID=1535, got complete sample at + 1456679673835 157782 INFO BaseInstrumentService [main]: initializeInstrument() for 159855 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 166036 INFO BaseInstrumentService [main]: done with initializeInstrument() for 166143 INFO Aquadopp [main]: Retrieving Aquadopp state Metadata... 168147 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 175999 INFO PortManager [main]: service started 176054 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 176461 INFO PortManager [main]: Starting service... 178167 INFO Aquadopp [Thread-34]: sendSoftBreak(): instrument in mode 2 187605 INFO BaseInstrumentService [main]: initializeInstrument() for 189539 ERROR StreamingInstrumentService [Thread-34]: acquireFromStream(), tried startStreaming(): Instrument didn't acknowledge SR command 192577 INFO BaseInstrumentService [main]: done with initializeInstrument() for 194527 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1535 194528 INFO PolledInstrumentService [main]: id 1524 slaved to 1535 194533 INFO PortManager [main]: service started 194535 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 194556 INFO AanderaaO2 [Thread-38]: TT: ID=1524, trigger sample at 1456679771899 195620 INFO PortManager [main]: Starting service... 230939 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 236564 INFO BaseInstrumentService [main]: initializeInstrument() for 236566 INFO StreamingWorkhorseADCP-1825 [main]: Initializing Workhorse 1825 236577 INFO StreamingWorkhorseADCP-1825 [main]: Instrument has been pre-configured; ignore configuration attributes 239525 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 239564 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 239607 INFO StreamingWorkhorseADCP-1825 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 239608 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 239844 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 239883 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 239928 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 239929 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 239931 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 239933 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property char 3=1 239934 INFO StreamingWorkhorseADCP-1825 [main]: Start pinging 240162 INFO BaseInstrumentService [main]: done with initializeInstrument() for 243304 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WD? 243343 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 243884 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WF? 243923 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 244474 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WN? 244513 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 245044 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WP? 245083 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 245615 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WS? 245653 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246185 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WV? 246223 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246755 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 246793 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 247335 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TP? 247422 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 247964 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TS? 248040 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 248575 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EA? 248613 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249144 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EB? 249183 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249735 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ED? 249773 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 250305 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ES? 250344 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 250884 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EX? 250923 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 251464 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EZ? 251503 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 252034 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 252073 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 252652 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RA? 252673 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 253434 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 253474 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 259006 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 5525 ms outbuf.len=8192 avail: 79 read: 5303Request=RR? 260055 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 262311 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 263324 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 265527 ERROR StreamingWorkhorseADCP-1825 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 266112 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 266392 INFO PortManager [main]: service started 266395 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 268319 INFO PortManager [main]: Starting service... 338110 ERROR DeviceLog [main]: readLogData: data size mismatch 338111 ERROR DeviceLog [main]: bytes read from file: 1173 338112 ERROR DeviceLog [main]: dataSize in index entry: 1927 338180 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 348864 INFO BaseInstrumentService [main]: initializeInstrument() for 348867 INFO StreamingWorkhorseADCP-1828 [main]: Initializing Workhorse 1828 348876 INFO StreamingWorkhorseADCP-1828 [main]: Instrument has been pre-configured; ignore configuration attributes 351595 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 351634 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 351677 INFO StreamingWorkhorseADCP-1828 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 351679 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 351914 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 351953 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 352002 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 352003 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 352016 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 352017 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property char 3=1 352019 INFO StreamingWorkhorseADCP-1828 [main]: Start pinging 352202 INFO BaseInstrumentService [main]: done with initializeInstrument() for 355084 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WD? 355124 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 355675 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WF? 355714 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 356255 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WN? 356293 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 356824 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WP? 356863 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 357394 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WS? 357434 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 357964 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WV? 358003 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 358564 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 358603 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 359194 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TP? 359252 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 359824 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TS? 359863 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 360424 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EA? 360463 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 361004 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EB? 361043 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 361575 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ED? 361614 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 362194 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ES? 362234 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 362775 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EX? 362814 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 363355 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EZ? 363393 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 363944 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 363983 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 364605 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RA? 364626 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 365206 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 365266 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 371658 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: readUntil() Timed out after 6388 ms outbuf.len=8192 avail: 2757 read: 3484Request=RR? 374504 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 377305 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 380786 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 383535 ERROR StreamingWorkhorseADCP-1828 [main]: sendRequest caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed outRequest=RR? 384105 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