1 INFO NodeMain [main]: NodeMain.main(): portalHost = null 1356 INFO NodeManager [main]: Starting NodeManager at 10/10/2015 18:44:18 GMT (1444502658752), version: $Name: $ 1358 INFO NodeManager [main]: Node IP: node2/134.89.36.2 2025 INFO NodeManager [main]: Node ID has been set to 1598 3126 INFO PortManager [main]: Found 14 configured ports in properties file 3189 INFO MOOSPortManager [main]: Found DPA at slot: 0 5099 INFO MOOSPortManager [main]: Found DPA at slot: 1 6729 INFO MOOSPortManager [main]: Found DPA at slot: 2 8329 INFO MOOSPortManager [main]: Found DPA at slot: 3 9927 INFO MOOSPortManager [main]: No DPA found at slot: 4 9931 INFO MOOSPortManager [main]: No DPA found at slot: 5 9966 INFO WDTManager [main]: WDTManager constructor 9968 INFO MOOSWDTManager [main]: MOOSWDTManager constructor 10031 INFO SleepManager [main]: SleepManager constructor 10035 INFO MOOSSleepManager [main]: MOOSSleepManager constructor 11735 INFO CommsLeaseListener [main]: CommsLeaseListener() complete 11803 INFO CpuLeaseSleepRollcallListener [main]: CpuLeaseSleepRollcallListener() constructor 11818 INFO CpuLease [main]: CpuLease() constructor 11824 INFO CpuLease [Thread-5]: CpuLease started 13850 ERROR NodeService [main]: Turbinator constructor failed: com.rbnb.sapi.SAPIException: Nesting java.net.ConnectException 13953 INFO MOOSNodeService [main]: Last MMC reset code: 6 14281 INFO NodeManager [main]: Starting registry... 14320 INFO NodeManager [main]: registry started. 14321 INFO NodeManager [main]: binding NodeService to rmi://localhost/node 14834 INFO NodeManager [main]: NodeService is bound to rmi://localhost/node 14861 INFO MOOSWDTManager [Thread-2]: WDTManager initializing watchdog timer 14984 ERROR MOOSWDTManager [Thread-2]: !!! Reboot due to watchdog reset !!! 15364 INFO MOOSWDTManager [Thread-2]: WDTManager watchdog initialization successful 15415 INFO PortManager [main]: Service jar not specified for port /dev/ttySX0 16259 INFO PortManager [main]: Starting service... 32194 INFO BaseInstrumentService [main]: initializeInstrument() for 33769 WARN StreamingSBE19 [main]: Did not receive expected confirmation prompt from command: MP 38804 INFO StreamingSBE19 [main]: Event detection disabled by attribute 38871 INFO BaseInstrumentService [main]: done with initializeInstrument() for 46992 INFO PortManager [main]: service started 47414 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 48150 INFO PortManager [main]: Starting service... 69188 INFO BaseInstrumentService [main]: initializeInstrument() for 69190 INFO WetLabsECO [main]: Initializing... 84628 INFO WetLabsECO [main]: Initializing completed 84629 INFO BaseInstrumentService [main]: done with initializeInstrument() for 93743 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1827 93745 INFO PolledInstrumentService [main]: id 1535 slaved to 1827 93763 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 93765 INFO PortManager [main]: service started 93787 INFO WetLabsECO [Thread-25]: TEST: ID=1535, trigger sample at 1444502751190 95775 INFO PortManager [main]: Starting service... 96189 INFO WetLabsECO [Thread-25]: TEST: ID=1535, got complete sample at + 1444502753593 157002 INFO BaseInstrumentService [main]: initializeInstrument() for 159018 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 165236 INFO BaseInstrumentService [main]: done with initializeInstrument() for 165342 INFO Aquadopp [main]: Retrieving Aquadopp state Metadata... 167327 INFO Aquadopp [main]: sendSoftBreak(): instrument in mode 2 175158 INFO PortManager [main]: service started 175165 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 175609 INFO PortManager [main]: Starting service... 177277 INFO Aquadopp [Thread-34]: sendSoftBreak(): instrument in mode 2 186664 INFO BaseInstrumentService [main]: initializeInstrument() for 191477 INFO BaseInstrumentService [main]: done with initializeInstrument() for 193433 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = 1535 193436 INFO PolledInstrumentService [main]: id 1524 slaved to 1535 193440 INFO PortManager [main]: service started 193484 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 193506 INFO AanderaaO2 [Thread-38]: TT: ID=1524, trigger sample at 1444502850909 194520 INFO PortManager [main]: Starting service... 229537 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 235164 INFO BaseInstrumentService [main]: initializeInstrument() for 235166 INFO StreamingWorkhorseADCP-1825 [main]: Initializing Workhorse 1825 235176 INFO StreamingWorkhorseADCP-1825 [main]: Instrument has been pre-configured; ignore configuration attributes 238145 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 238630 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 238743 INFO StreamingWorkhorseADCP-1825 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 238745 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 238984 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 239023 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 239074 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 239075 INFO StreamingWorkhorseADCP-1825 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 239077 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 239079 INFO StreamingWorkhorseADCP-1825 [main]: initializeInstrument(): property char 3=1 239080 INFO StreamingWorkhorseADCP-1825 [main]: Start pinging 239262 INFO BaseInstrumentService [main]: done with initializeInstrument() for 242805 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WD? 242844 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 243384 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WF? 243423 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 243954 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WN? 244004 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 244613 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WP? 244657 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 245184 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WS? 245223 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 245775 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request WV? 245813 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246344 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TE? 246421 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 246964 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TP? 247003 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 247534 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request TS? 247573 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 248104 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EA? 248143 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 248674 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EB? 248723 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249255 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ED? 249293 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 249863 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request ES? 249906 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 250434 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EX? 250473 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 251024 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request EZ? 251063 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 251594 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CF? 251633 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 252204 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RA? 252229 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 252744 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RR? 252783 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 254245 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RF? 254281 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 254826 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request CB? 254905 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 255454 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request PS0 255481 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 257394 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request PS3 257419 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 258747 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request RF 258789 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 259264 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: wrote request AC 259353 INFO StreamingWorkhorseADCP-1825 [main]: sendRequest: got echo response: 261521 INFO PortManager [main]: service started 261525 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 262607 INFO PortManager [main]: Starting service... 305501 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 316164 INFO BaseInstrumentService [main]: initializeInstrument() for 316166 INFO StreamingWorkhorseADCP-1828 [main]: Initializing Workhorse 1828 316176 INFO StreamingWorkhorseADCP-1828 [main]: Instrument has been pre-configured; ignore configuration attributes 321180 ERROR StreamingWorkhorseADCP-1828 [main]: enterCommandMode caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed out 322985 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 323025 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 323068 INFO StreamingWorkhorseADCP-1828 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 323069 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 323305 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 323344 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 323389 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 323390 INFO StreamingWorkhorseADCP-1828 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 323392 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 323393 INFO StreamingWorkhorseADCP-1828 [main]: initializeInstrument(): property char 3=1 323395 INFO StreamingWorkhorseADCP-1828 [main]: Start pinging 323582 INFO BaseInstrumentService [main]: done with initializeInstrument() for 327054 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WD? 327093 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 327674 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WF? 327713 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 328263 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WN? 328306 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 328835 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WP? 328874 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 329425 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WS? 329463 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 329996 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request WV? 330067 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 330647 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TE? 330713 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 331266 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TP? 331316 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 331856 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request TS? 331907 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 332465 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EA? 332503 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 333044 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EB? 333083 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 333614 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ED? 333653 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 334185 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request ES? 334223 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 334755 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EX? 334795 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 335364 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request EZ? 335403 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 335935 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CF? 335974 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 336524 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RA? 336549 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 337065 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RR? 337104 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 338365 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RF? 338441 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 339025 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request CB? 339064 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 339604 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request PS0 339629 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 341507 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request PS3 341537 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 342874 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request RF 342910 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 343394 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: wrote request AC 343433 INFO StreamingWorkhorseADCP-1828 [main]: sendRequest: got echo response: 345591 INFO PortManager [main]: service started 345595 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 346733 INFO PortManager [main]: Starting service... 379896 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 379897 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 385102 INFO BaseInstrumentService [Thread-34]: Didn't remove sampling thread (total of 0 threads) 386918 INFO Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(): instrument in mode 5 389073 INFO StreamingWorkhorseADCP-0 [main]: getSerialParameters(): baud=9600 393992 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 393997 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX3 394105 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 394108 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 394110 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 394124 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 394144 INFO NodeManager [Thread-1]: Done with serviceRemoved() 394148 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 394744 INFO BaseInstrumentService [main]: initializeInstrument() for 394746 INFO StreamingWorkhorseADCP-1827 [main]: Initializing Workhorse 1827 394758 INFO StreamingWorkhorseADCP-1827 [main]: Instrument has been pre-configured; ignore configuration attributes 397175 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request TE? 398113 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 398171 INFO StreamingWorkhorseADCP-1827 [main]: TE response: TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 398172 INFO StreamingWorkhorseADCP-1827 [main]: getProperty(): response=TE 00:00:10.00 --------- Time per Ensemble (hrs:min:sec.sec/100) > 398415 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request CF? 398454 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 398505 INFO StreamingWorkhorseADCP-1827 [main]: initializeInstrument(): response = CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 398506 INFO StreamingWorkhorseADCP-1827 [main]: getProperty(): response=CF = 11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) > 398508 INFO StreamingWorkhorseADCP-1827 [main]: initializeInstrument(): property=11111 --------------- Flow Ctrl (EnsCyc;PngCyc;Binry;Ser;Rec) >, char 3=1 398509 INFO StreamingWorkhorseADCP-1827 [main]: initializeInstrument(): property char 3=1 398510 INFO StreamingWorkhorseADCP-1827 [main]: Start pinging 398692 INFO BaseInstrumentService [main]: done with initializeInstrument() for 402187 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WD? 402297 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 402864 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WF? 402932 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 403464 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WN? 403503 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 404037 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WP? 404078 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 404647 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WS? 404693 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 405236 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request WV? 405287 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 405847 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request TE? 405894 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 406445 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request TP? 406483 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 407064 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request TS? 407103 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 407645 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request EA? 407690 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 408225 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request EB? 408263 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 408805 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request ED? 408844 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 409375 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request ES? 409413 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 409945 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request EX? 409983 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 410586 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request EZ? 410633 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 411176 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request CF? 411223 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 411776 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request RA? 411847 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 412366 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request RR? 412438 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 413605 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request RF? 413645 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 414205 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request CB? 414245 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 414796 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request PS0 414824 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 416704 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request PS3 416729 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 418036 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request RF 418074 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 418555 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: wrote request AC 418593 INFO StreamingWorkhorseADCP-1827 [main]: sendRequest: got echo response: 420858 INFO PortManager [main]: service started 420865 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 420950 INFO PortManager [main]: Service jar not specified for port /dev/ttySX8 420951 INFO PortManager [main]: Service jar not specified for port /dev/ttySX9 420952 INFO PortManager [main]: Service jar not specified for port /dev/ttySX10 420953 INFO PortManager [main]: Service jar not specified for port /dev/ttySX11 421871 INFO PortManager [main]: Starting service... 421880 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503079284 424270 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503081674 424677 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503082081 433318 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503090722 434105 INFO BaseInstrumentService [main]: initializeInstrument() for 435578 INFO BaseInstrumentService [main]: done with initializeInstrument() for 435731 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503093135 435847 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503093251 439015 INFO PolledInstrumentService [main]: prepareToRun(): sampleMasterId = -1 439017 INFO PolledInstrumentService [main]: id 1599 not slaved 439019 INFO PortManager [main]: service started 439025 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 439115 INFO PortManager [main]: Service jar not specified for port /dev/ttySA2 439226 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 6:51:36 PM 439595 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 36 threads 440108 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 440120 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-74" alive thread: "Thread-73" alive daemon thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-66" alive thread: "Thread-58" alive daemon thread: "Thread-57" alive thread: "Thread-48" alive daemon thread: "Thread-47" alive thread: "Thread-40" alive daemon thread: "Thread-39" alive thread: "Thread-38" alive thread: "Thread-35" alive daemon thread: "Thread-26" alive thread: "Thread-25" alive thread: "Thread-22" alive thread: "Thread-19" alive daemon thread: "Thread-18" alive thread: "Thread-13" alive daemon thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive thread: "main" alive 440287 INFO CommsLeaseListener [Thread-71]: 440991 INFO NodeManager [main]: NodeManager "node" started. 443735 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503101139 446227 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503103631 446299 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503103702 451455 INFO CommsLeaseListener [Thread-77]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 452008 INFO CommsLeaseListener [Thread-77]: ethOff 454579 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503111982 456970 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503114373 457035 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503114439 465522 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503122926 467921 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503125325 467992 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503125396 476173 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503133576 478570 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503135974 478635 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503136038 486942 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503144346 489340 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503146744 489416 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503146819 497746 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503155149 500191 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503157594 500263 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503157667 508546 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503165950 510972 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503168376 511100 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503168504 519357 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503176761 521779 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503179183 521947 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503179351 529348 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503186751 531762 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503189166 531887 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503189291 540150 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503197554 542540 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503199944 542607 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503200011 551161 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503208564 553560 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503210963 553627 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503211031 561830 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503219233 564220 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503221623 564290 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503221694 572589 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503229992 575002 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503232405 575082 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503232485 583358 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503240762 585777 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503243181 585862 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503243266 594168 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503251572 596559 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503253963 596625 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503254029 604989 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503262393 607380 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503264783 607448 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503264852 614987 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503272391 617420 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503274824 617492 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503274895 625901 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503283304 628290 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503285694 628361 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503285765 636562 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503293966 638990 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503296394 639058 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503296462 647416 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503304819 649810 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503307214 649881 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503307285 658159 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503315562 660560 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503317964 660642 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503318045 669048 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503326452 671467 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503328871 671547 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503328951 679764 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503337168 682187 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503339590 682272 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503339676 690580 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503347983 692970 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503350374 693038 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503350442 700572 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503357975 703001 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503360405 703126 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503360530 711387 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503368791 713780 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503371184 713853 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503371257 722288 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503379692 724702 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503382106 724783 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503382187 732965 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503390368 735382 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503392785 735463 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503392867 743852 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503401256 746270 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503403674 746348 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503403751 754628 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503412032 757020 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503414423 757085 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503414489 765407 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503422811 767799 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503425203 767924 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503425328 776239 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503433643 778630 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503436034 778749 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503436153 786319 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503443722 788709 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503446113 788786 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503446189 797042 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503454445 799429 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503456833 799622 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503457026 807776 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503465180 810211 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503467615 810288 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503467692 818585 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503475989 821000 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503478404 821081 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503478485 829376 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503486780 831792 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503489196 831934 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503489337 840184 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503497587 842579 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503499983 842695 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503500099 851009 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503508412 853400 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503510803 853475 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503510879 861832 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503519236 864230 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503521634 864303 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503521707 871810 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503529213 874243 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503531647 874316 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503531720 882592 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503539996 885012 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503542415 885092 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503542496 893438 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503550841 895852 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503553255 895932 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503553335 904282 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503561686 906700 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503564104 906781 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503564185 915011 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503572415 917429 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503574833 917630 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503575033 925817 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503583221 928209 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503585613 928278 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503585682 936597 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503594001 938989 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503596393 939058 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503596462 947395 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503604799 949790 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503607193 949959 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503607362 957412 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503614816 959800 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503617204 959868 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503617272 968203 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503625606 970610 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503628014 970692 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503628096 979006 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503636410 981502 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503638906 981587 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503638991 989808 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503647212 992228 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503649632 992311 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503649715 1000618 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503658022 1003010 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503660413 1003082 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503660486 1011419 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503668823 1013810 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503671213 1013885 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503671288 1022327 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503679731 1024742 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503682146 1024826 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503682230 1033007 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503690410 1035423 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503692826 1035511 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503692915 1039236 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:01:36 PM 1039788 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 1039856 INFO CommsLeaseListener [Thread-71]: 1042995 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503700399 1045412 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503702816 1045499 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503702902 1050874 INFO CommsLeaseListener [Thread-129]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 1051427 INFO CommsLeaseListener [Thread-129]: ethOff 1053802 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503711206 1056423 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503713827 1056489 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503713893 1064629 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503722033 1067070 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503724474 1067133 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503724537 1075428 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503732832 1077880 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503735284 1077949 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503735352 1086328 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503743732 1088720 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503746123 1088788 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503746192 1097023 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503754427 1099421 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503756825 1099491 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503756895 1107895 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503765299 1110291 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503767695 1110363 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503767767 1118633 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503776037 1121052 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503778455 1121132 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503778536 1128612 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503786016 1131087 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503788491 1131178 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503788582 1139407 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503796811 1141822 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503799226 1141942 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503799346 1150250 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503807654 1152645 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503810049 1152712 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503810115 1161059 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503818463 1163450 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503820854 1163527 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503820930 1171847 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503829248 1174239 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503831643 1174306 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503831710 1182615 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503840018 1185032 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503842436 1185112 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503842515 1193421 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503850825 1195830 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503853234 1195912 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503853316 1204225 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503861629 1206620 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503864024 1206819 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503864223 1214222 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503871626 1216619 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503874023 1216687 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503874091 1225050 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503882454 1227439 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503884843 1227520 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503884924 1235842 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503893246 1238240 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503895643 1238314 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503895717 1246619 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503904023 1249010 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503906413 1249076 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503906480 1257437 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503914840 1259830 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503917234 1259897 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503917300 1268235 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503925639 1270702 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503928106 1270783 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503928186 1279065 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503936468 1281482 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503938886 1281646 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503939050 1289840 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503947244 1292259 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503949663 1292341 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503949744 1299824 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503957227 1302251 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503959655 1302333 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503959737 1310749 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503968152 1313140 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503970543 1313217 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503970620 1321521 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503978925 1323950 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503981354 1324109 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503981513 1332257 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444503989661 1334733 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444503992137 1334813 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444503992217 1343033 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504000437 1345456 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504002857 1345538 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504002942 1353929 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504011333 1356329 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504013733 1356394 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504013797 1364660 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504022063 1367050 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504024453 1367128 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504024532 1375467 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504032871 1377919 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504035323 1378011 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504035415 1385553 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504042957 1387949 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504045353 1388017 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504045421 1396344 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504053748 1398809 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504056213 1398876 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504056280 1407036 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504064439 1409431 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504066835 1409505 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504066909 1417849 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504075253 1420246 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504077650 1420320 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504077724 1428750 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504086154 1431167 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504088571 1431297 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504088701 1439435 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504096839 1441852 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504099256 1442022 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504099425 1450276 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504107680 1452670 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504110073 1452745 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504110148 1461074 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504118477 1463470 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504120874 1463542 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504120945 1471076 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504128477 1473470 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504130874 1473541 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504130945 1481929 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504139333 1484320 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504141724 1484492 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504141895 1492666 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504150070 1495146 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504152550 1495223 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504152627 1503447 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504160850 1505908 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504163312 1505993 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504163397 1514379 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504171782 1516770 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504174174 1516847 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504174251 1525083 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504182487 1527480 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504184884 1527638 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504185041 1535893 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504193296 1538290 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504195694 1538377 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504195781 1546670 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504204074 1549060 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504206463 1549131 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504206535 1557475 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504214879 1559870 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504217274 1559948 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504217352 1567462 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504224866 1569850 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504227254 1570007 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504227411 1578291 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504235695 1580693 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504238097 1580777 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504238181 1589076 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504246480 1591492 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504248896 1591582 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504248986 1599862 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504257266 1602297 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504259701 1602379 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504259783 1610693 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504268096 1613129 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504270533 1613198 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504270602 1621491 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504278895 1623879 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504281283 1623951 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504281355 1632370 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504289774 1634867 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504292271 1634949 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504292352 1639246 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:11:36 PM 1639796 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 1640437 INFO CommsLeaseListener [Thread-71]: ethOn 1643145 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504300548 1645568 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504302972 1645650 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504303054 1651454 INFO CommsLeaseListener [Thread-174]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 1651508 INFO CommsLeaseListener [Thread-174]: 1653153 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504310557 1655576 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504312980 1655657 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504313060 1663879 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504321283 1666338 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504323741 1666500 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504323904 1674772 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504332176 1677160 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504334563 1677244 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504334647 1685489 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504342893 1687880 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504345283 1687958 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504345362 1696401 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504353805 1698790 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504356193 1698868 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504356272 1707091 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504364495 1709482 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504366886 1709645 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504367049 1717869 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504375273 1720268 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504377672 1720338 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504377741 1728687 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504386090 1731102 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504388506 1731183 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504388587 1738782 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504396186 1741192 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504398595 1741271 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504398675 1749478 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504406882 1751896 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504409300 1751980 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504409384 1760293 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504417697 1762690 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504420093 1762757 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504420161 1771162 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504428566 1773559 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504430963 1773637 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504431041 1781902 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504439306 1784294 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504441697 1784451 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504441855 1792684 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504450087 1795109 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504452513 1795189 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504452592 1803515 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504460919 1805930 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504463334 1806012 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504463416 1814297 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504471701 1816699 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504474103 1816771 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504474175 1824290 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504481694 1826679 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504484083 1826750 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504484154 1835109 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504492513 1837499 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504494903 1837565 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504494969 1845908 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504503312 1848343 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504505747 1848453 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504505857 1856694 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504514098 1859090 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504516494 1859167 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504516570 1867498 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504524902 1869889 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504527293 1869985 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504527389 1878320 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504535723 1880724 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504538127 1880828 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504538231 1889089 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504546493 1891503 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504548907 1891589 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504548993 1899893 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504557296 1902373 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504559777 1902626 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504560029 1909903 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504567306 1912330 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504569734 1912412 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504569816 1920728 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504578132 1923119 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504580523 1923189 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504580592 1931528 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504588932 1933920 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504591323 1933986 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504591390 1942438 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504599841 1944856 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504602260 1945053 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504602456 1953097 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504610501 1955512 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504612916 1955599 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504613003 1963903 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504621307 1966487 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504623890 1966555 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504623959 1974716 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504632120 1977110 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504634514 1977179 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504634582 1985583 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504642987 1987980 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504645384 1988147 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504645551 1995526 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504652930 1997920 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504655324 1997989 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504655393 2006361 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504663764 2008822 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504666226 2009017 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504666421 2017195 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504674598 2019591 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504676994 2019667 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504677071 2027964 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504685368 2030381 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504687784 2030547 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504687951 2038766 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504696170 2041192 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504698596 2041272 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504698676 2049512 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504706915 2051921 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504709325 2052061 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504709465 2060325 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504717729 2062720 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504720124 2062807 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504720211 2071220 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504728623 2073652 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504731056 2073725 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504731129 2081181 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504738585 2083570 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504740974 2083640 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504741043 2091938 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504749342 2094438 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504751841 2094517 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504751920 2102785 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504760188 2105202 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504762606 2105282 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504762686 2113567 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504770971 2115982 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504773386 2116070 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504773474 2124329 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504781733 2126720 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504784124 2126800 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504784204 2135142 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504792546 2137529 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504794933 2137617 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504795021 2146028 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504803432 2148440 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504805844 2148517 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504805921 2156730 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504814133 2159132 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504816536 2159217 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504816621 2166810 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504824214 2169199 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504826603 2169277 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504826681 2177521 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504834925 2179910 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504837313 2180028 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504837432 2188337 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504845741 2190743 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504848146 2190823 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504848227 2199126 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504856529 2201546 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504858947 2201629 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504859032 2209980 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504867384 2212402 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504869806 2212649 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504870052 2220746 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504878147 2223140 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504880544 2223308 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504880712 2231557 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504888961 2233960 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504891363 2234038 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504891442 2239256 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:21:36 PM 2239815 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 2239926 INFO CommsLeaseListener [Thread-71]: 2242656 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504900060 2245071 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504902475 2245152 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504902555 2250945 INFO CommsLeaseListener [Thread-221]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 2251497 INFO CommsLeaseListener [Thread-221]: ethOff 2252377 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504909781 2254807 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504912211 2254890 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504912293 2263130 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504920533 2265546 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504922950 2265622 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504923026 2273934 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504931338 2276571 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504933975 2276647 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504934051 2284838 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504942242 2287229 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504944633 2287308 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504944712 2295560 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504952964 2297950 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504955354 2298098 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504955502 2306364 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504963767 2308760 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504966163 2308917 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504966321 2317154 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504974558 2319560 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504976964 2319646 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504977050 2327943 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504985347 2330385 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504987788 2330461 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504987865 2337933 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444504995337 2340362 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444504997766 2340455 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444504997859 2348746 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505006150 2351182 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505008586 2351262 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505008666 2359540 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505016944 2361952 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505019355 2362080 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505019484 2369352 INFO NodeService [RMI-ServerConnection:127.0.0.1]: NodeService.scanPort(/dev/ttySX3) 2370477 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505027881 2372062 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Starting service... 2372872 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505030276 2373272 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505030675 2381223 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505038627 2383651 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505041054 2384118 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505041522 2392204 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505049607 2394617 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505052021 2395209 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505052613 2402781 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505060184 2405231 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505062635 2405680 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505063083 2413799 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505071203 2416242 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505073645 2416406 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505073810 2423688 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505081092 2426167 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505083571 2426402 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505083806 2434577 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505091981 2436982 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505094386 2437337 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505094740 2445193 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505102597 2447637 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505105041 2448027 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505105431 2448722 INFO BaseInstrumentService [RMI-ServerConnection:127.0.0.1]: initializeInstrument() for 2450821 INFO Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(): instrument in mode 2 2455968 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505113372 2456996 INFO BaseInstrumentService [RMI-ServerConnection:127.0.0.1]: done with initializeInstrument() for 2457160 INFO Aquadopp [RMI-ServerConnection:127.0.0.1]: Retrieving Aquadopp state Metadata... 2458419 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505115823 2458589 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505115993 2459160 INFO Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(): instrument in mode 2 2466761 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505124165 2467688 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service started 2467694 INFO NodeManager [Thread-1]: serviceInstalled(): invoke remote callbacks 2469150 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505126554 2469312 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505126715 2469887 INFO Aquadopp [Thread-242]: sendSoftBreak(): instrument in mode 2 2477564 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505134967 2480000 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505137404 2480070 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505137474 2488379 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505145782 2490804 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505148207 2490922 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505148326 2499162 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505156566 2501580 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505158984 2501669 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505159072 2509163 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505166567 2511587 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505168991 2511712 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505169116 2519966 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505177370 2522407 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505179810 2522547 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505179951 2530909 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505188312 2533322 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505190725 2533407 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505190810 2541672 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505199075 2544060 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505201464 2544137 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505201541 2552400 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505209804 2554837 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505212241 2554919 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505212323 2563168 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505220572 2565583 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505222987 2565663 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505223066 2573958 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505231362 2576423 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505233827 2576596 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505234000 2584792 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505242195 2587180 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505244583 2587251 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505244654 2594848 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505252251 2597269 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505254673 2597349 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505254752 2605619 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505263023 2608010 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505265414 2608081 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505265485 2616431 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505273834 2618820 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505276224 2618892 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505276295 2627305 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505284709 2629702 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505287106 2629835 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505287239 2637963 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505295367 2640372 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505297776 2640448 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505297852 2648768 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505306172 2651183 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505308586 2651352 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505308755 2659576 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505316980 2661997 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505319401 2662141 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505319545 2670412 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505327816 2672850 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505330254 2673018 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505330421 2681199 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505338603 2683593 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505340997 2683670 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505341074 2691189 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505348593 2693580 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505350984 2693652 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505351055 2702099 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505359503 2704490 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505361894 2704562 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505361966 2712871 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505370275 2715328 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505372686 2715411 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505372814 2723573 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505380977 2725997 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505383400 2726074 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505383477 2734393 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505391796 2736790 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505394194 2736862 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505394266 2745287 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505402691 2747680 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505405084 2747801 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505405205 2756098 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505413502 2758501 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505415904 2758571 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505415975 2766796 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505424200 2769190 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505426594 2769287 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505426691 2776791 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505434195 2779181 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505436585 2779343 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505436746 2787578 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505444982 2789970 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505447374 2790047 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505447451 2798402 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505455806 2800812 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505458216 2800900 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505458303 2809188 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505466591 2811668 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505469071 2811750 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505469153 2819987 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505477391 2822551 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505479955 2822665 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505480068 2830817 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505488220 2833210 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505490614 2833287 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505490691 2839267 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:31:36 PM 2839825 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 2839867 INFO CommsLeaseListener [Thread-71]: 2841633 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505499037 2844030 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505501434 2844107 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505501511 2850884 INFO CommsLeaseListener [Thread-272]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 2851437 INFO CommsLeaseListener [Thread-272]: ethOff 2852472 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505509875 2854882 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505512286 2854969 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505512373 2862583 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505519987 2865064 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505522467 2865148 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505522551 2873185 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505530589 2875602 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505533006 2875797 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505533200 2883988 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505541392 2886532 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505543936 2886607 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505544011 2894957 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505552361 2897350 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505554754 2897421 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505554825 2905713 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505563117 2908157 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505565558 2908259 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505565662 2916463 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505573867 2918960 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505576364 2919038 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505576442 2927214 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505584617 2929610 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505587014 2929818 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505587222 2938003 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505595407 2940412 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505597816 2940492 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505597895 2948004 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505605407 2950512 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505607916 2950608 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505608011 2958802 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505616206 2961282 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505618685 2961380 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505618783 2969610 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505627014 2972027 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505629431 2972109 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505629513 2980425 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505637828 2982824 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505640227 2982892 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505640296 2991258 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505648661 2993650 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505651054 2993718 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505651122 3002122 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505659526 3004510 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505661914 3004582 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505661986 3012905 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505670309 3015332 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505672736 3015412 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505672816 3023603 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505681007 3026022 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505683426 3026102 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505683506 3033610 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505691014 3036027 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505693431 3036110 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505693514 3044416 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505701819 3046810 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505704214 3046882 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505704285 3055318 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505712721 3057759 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505715163 3057835 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505715239 3066037 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505723440 3068497 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505725901 3068573 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505725977 3076825 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505734229 3079251 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505736654 3079435 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505736839 3087615 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505745019 3090010 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505747414 3090081 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505747485 3098462 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505755866 3100883 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505758287 3101052 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505758456 3109218 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505766622 3111637 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505769041 3111842 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505769246 3119212 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505776615 3121622 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505779026 3121710 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505779113 3130024 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505787427 3132706 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505790102 3132775 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505790178 3140850 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505798253 3143294 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505800697 3143387 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505800791 3146745 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3146746 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3151641 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505809045 3151764 INFO BaseInstrumentService [Thread-18]: Didn't remove sampling thread (total of 0 threads) 3154030 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505811434 3154107 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505811510 3155773 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3155781 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX1 3156052 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3156057 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3156065 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3156067 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3156069 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3156071 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3162508 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505819912 3164922 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505822326 3165008 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505822411 3173242 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505830645 3175652 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505833055 3175737 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505833140 3184110 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505841513 3186550 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505843953 3186628 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505844032 3194849 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505852253 3197240 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505854644 3197311 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505854715 3204858 INFO WetLabsECO [Thread-26]: TEST: ID=1535, trigger sample at 1444505862261 3207270 INFO WetLabsECO [Thread-26]: TEST: ID=1535, got complete sample at + 1444505864674 3207366 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505864770 3212895 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3212897 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3213881 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3213882 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX2 3213896 INFO AanderaaO2 [Thread-39]: TT: ID=1524, trigger sample at 1444505871299 3214006 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3214009 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3214015 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3214017 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3214018 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3214019 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3215577 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3226567 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3237178 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3247989 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3258789 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3259315 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3259316 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3260179 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3260181 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX4 3260375 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3260378 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3260385 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3260386 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3260387 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3260389 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3269588 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3280389 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3290430 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3300919 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3300920 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3301209 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3303185 ERROR StreamingInstrumentService [Thread-47]: ERR:stopStreaming() failed: java.lang.InterruptedException 3305934 INFO BaseInstrumentService [Thread-47]: Didn't remove sampling thread (total of 0 threads) 3311979 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3313046 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3313047 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX5 3313145 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3313148 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3313155 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3313157 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3313158 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3313159 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3322778 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3333588 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3344378 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3355208 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3366009 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3375999 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3386801 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3389585 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3389586 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3397608 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3402364 ERROR StreamingWorkhorseADCP-1828 [RMI-ServerConnection:127.0.0.1]: enterCommandMode caught Timeout Exception: org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed out 3403896 ERROR StreamingInstrumentService [Thread-57]: acquire(): TimeoutException from readSample(): org.mbari.siam.distributed.TimeoutException: StreamingWorkhorseADCP.readNextPacket() timed out 3403902 ERROR StreamingInstrumentService [Thread-57]: acquire(): org.mbari.siam.distributed.TimeoutException: StreamingWorkhorseADCP.readNextPacket() timed out:port OK id=1828 3403907 ERROR StreamingInstrumentService [Thread-57]: acquireFromStream() - NoDataException: StreamingWorkhorseADCP.readNextPacket() timed out:port OK 3404345 ERROR StreamingInstrumentService [Thread-57]: ERR:stopStreaming() failed: java.lang.InterruptedException 3404407 INFO BaseInstrumentService [Thread-57]: Didn't remove sampling thread (total of 0 threads) 3408398 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3409182 ERROR BaseInstrumentService [RMI-ServerConnection:127.0.0.1]: Exception while shutting down instrument org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed out Stack trace: java/lang/Throwable.()V java/lang/Throwable.(Ljava/lang/String;)V org/mbari/siam/distributed/TimeoutException.(Ljava/lang/String;)V org/mbari/siam/utils/StreamUtils.skipUntil(Ljava/io/InputStream;[BJI)I org/mbari/siam/utils/StreamUtils.skipUntil(Ljava/io/InputStream;[BJ)I org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.shutdownInstrument()Ljava/lang/String; org/mbari/siam/core/BaseInstrumentService.shutdown()[B org/mbari/siam/core/StreamingInstrumentService.shutdown()[B org/mbari/siam/core/PortManager.removeService(Lorg/mbari/siam/core/DevicePort;Z)[B org/mbari/siam/core/PortManager.closePort(Lorg/mbari/siam/core/DevicePort;Z)[B org/mbari/siam/core/NodeService.shutdownDeviceService([BZ)[B org/mbari/siam/core/NodeService.shutdownDeviceService([B)[B java/lang/reflect/AccessibleObject.invokeL(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; java/lang/reflect/Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; com/ibm/oti/rmi/wire/StreamProtocolServer.dispatch(Lcom/ibm/oti/rmi/wire/CallData;Ljava/io/ObjectInput;)V com/ibm/oti/rmi/wire/StreamProtocolServer.run()V java/lang/Thread.run()V 3410227 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3410228 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX6 3410397 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3410401 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3410405 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3410406 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3410408 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3410409 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3419190 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3429992 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3439276 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:41:36 PM 3439857 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 3439898 INFO CommsLeaseListener [Thread-71]: 3440800 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3450914 INFO CommsLeaseListener [Thread-319]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 3450968 INFO CommsLeaseListener [Thread-319]: 3451697 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3461609 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3462315 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3462316 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3478574 ERROR BaseInstrumentService [RMI-ServerConnection:127.0.0.1]: Exception while shutting down instrument org.mbari.siam.distributed.TimeoutException: SkipUntil() Timed out Stack trace: java/lang/Throwable.()V java/lang/Throwable.(Ljava/lang/String;)V org/mbari/siam/distributed/TimeoutException.(Ljava/lang/String;)V org/mbari/siam/utils/StreamUtils.skipUntil(Ljava/io/InputStream;[BJI)I org/mbari/siam/utils/StreamUtils.skipUntil(Ljava/io/InputStream;[BJ)I org/mbari/siam/devices/workhorse/StreamingWorkhorseADCP.shutdownInstrument()Ljava/lang/String; org/mbari/siam/core/BaseInstrumentService.shutdown()[B org/mbari/siam/core/StreamingInstrumentService.shutdown()[B org/mbari/siam/core/PortManager.removeService(Lorg/mbari/siam/core/DevicePort;Z)[B org/mbari/siam/core/PortManager.closePort(Lorg/mbari/siam/core/DevicePort;Z)[B org/mbari/siam/core/NodeService.shutdownDeviceService([BZ)[B org/mbari/siam/core/NodeService.shutdownDeviceService([B)[B java/lang/reflect/AccessibleObject.invokeL(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; java/lang/reflect/Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; com/ibm/oti/rmi/wire/StreamProtocolServer.dispatch(Lcom/ibm/oti/rmi/wire/CallData;Ljava/io/ObjectInput;)V com/ibm/oti/rmi/wire/StreamProtocolServer.run()V java/lang/Thread.run()V 3478626 ERROR StreamingInstrumentService [Thread-66]: acquire(): TimeoutException from readSample(): org.mbari.siam.distributed.TimeoutException: StreamingWorkhorseADCP.readNextPacket() timed out 3478706 ERROR StreamingInstrumentService [Thread-66]: acquire(): org.mbari.siam.distributed.TimeoutException: StreamingWorkhorseADCP.readNextPacket() timed out:port OK id=1827 3478710 ERROR StreamingInstrumentService [Thread-66]: acquireFromStream() - NoDataException: StreamingWorkhorseADCP.readNextPacket() timed out:port OK 3479125 ERROR StreamingInstrumentService [Thread-66]: ERR:stopStreaming() failed: java.lang.InterruptedException 3479193 INFO BaseInstrumentService [Thread-66]: Didn't remove sampling thread (total of 0 threads) 3479197 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3479562 INFO PortManager [RMI-ServerConnection:127.0.0.1]: service.shutdown() complete 3479563 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: unexportObject() failed for service on port /dev/ttySX7 3479566 ERROR PolledInstrumentService [Thread-26]: sampleLogged(): id=1535, caught org.mbari.siam.distributed.NoDataException: Sevice in shutdown, suspend, or safe state; status=3 3479785 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - postEvent() 3479788 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() - done 3479795 INFO NodeManager [Thread-1]: serviceRemoved(): invoke remote callbacks 3479796 INFO NodeManager [Thread-1]: Done with serviceRemoved() 3479797 INFO DevicePacketAggregator [Thread-6]: serviceRemoved() 3479799 INFO DevicePacketAggregator [Thread-6]: done with serviceRemoved() 3610755 INFO PortManager [RMI-ServerConnection:127.0.0.1]: removeService() 3610756 INFO PortManager [RMI-ServerConnection:127.0.0.1]: Invoke service.shutdown() 3619766 WARN Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(), ack from 'II' command timed out 3623265 WARN Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(), ack from 'II' command timed out 3626765 WARN Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak(), ack from 'II' command timed out 3626766 INFO Aquadopp [RMI-ServerConnection:127.0.0.1]: sendSoftBreak() - instrument not yet in command mode 4039285 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 7:51:36 PM 4039334 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 26 threads 4039438 INFO ThreadUtility [Thread-74]: thread: "Thread-364" alive daemon thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 4039925 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 4040006 INFO CommsLeaseListener [Thread-71]: 4051024 INFO CommsLeaseListener [Thread-366]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 4051066 INFO CommsLeaseListener [Thread-366]: 4639295 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:01:36 PM 4639845 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 4639935 INFO CommsLeaseListener [Thread-71]: 4650954 INFO CommsLeaseListener [Thread-417]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 4651507 INFO CommsLeaseListener [Thread-417]: ethOff 5239306 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:11:36 PM 5239875 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 5239966 INFO CommsLeaseListener [Thread-71]: 5250984 INFO CommsLeaseListener [Thread-465]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 5251026 INFO CommsLeaseListener [Thread-465]: 5839315 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:21:36 PM 5839865 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 5839916 INFO CommsLeaseListener [Thread-71]: 5850934 INFO CommsLeaseListener [Thread-512]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 5850976 INFO CommsLeaseListener [Thread-512]: 6439326 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:31:36 PM 6439875 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 6439916 INFO CommsLeaseListener [Thread-71]: 6450934 INFO CommsLeaseListener [Thread-560]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 6450976 INFO CommsLeaseListener [Thread-560]: 7039336 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:41:36 PM 7039885 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 7040506 INFO CommsLeaseListener [Thread-71]: ethOn 7051524 INFO CommsLeaseListener [Thread-607]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 7051576 INFO CommsLeaseListener [Thread-607]: 7639338 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 7639345 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 8:51:36 PM 7639444 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 7639995 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 7640567 INFO CommsLeaseListener [Thread-71]: ethOn 7651594 INFO CommsLeaseListener [Thread-658]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 7651636 INFO CommsLeaseListener [Thread-658]: 8239355 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:01:36 PM 8239914 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 8239956 INFO CommsLeaseListener [Thread-71]: 8250974 INFO CommsLeaseListener [Thread-706]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 8251026 INFO CommsLeaseListener [Thread-706]: 8839365 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:11:36 PM 8839915 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 8839966 INFO CommsLeaseListener [Thread-71]: 8850984 INFO CommsLeaseListener [Thread-753]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 8851026 INFO CommsLeaseListener [Thread-753]: 9439375 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:21:36 PM 9439925 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 9439966 INFO CommsLeaseListener [Thread-71]: 9450984 INFO CommsLeaseListener [Thread-801]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 9451027 INFO CommsLeaseListener [Thread-801]: 10039386 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:31:36 PM 10039955 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 10040006 INFO CommsLeaseListener [Thread-71]: 10051024 INFO CommsLeaseListener [Thread-847]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 10051066 INFO CommsLeaseListener [Thread-847]: 10639395 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:41:36 PM 10639945 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 10639996 INFO CommsLeaseListener [Thread-71]: 10651014 INFO CommsLeaseListener [Thread-895]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 10651056 INFO CommsLeaseListener [Thread-895]: 11239349 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 11239377 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 11239405 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 9:51:36 PM 11239985 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 11240026 INFO CommsLeaseListener [Thread-71]: 11251044 INFO CommsLeaseListener [Thread-944]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 11251096 INFO CommsLeaseListener [Thread-944]: 11839415 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:01:36 PM 11839965 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 11840015 INFO CommsLeaseListener [Thread-71]: 11851034 INFO CommsLeaseListener [Thread-994]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 11851627 INFO CommsLeaseListener [Thread-994]: ethOff 12439426 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:11:36 PM 12439985 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 12440536 INFO CommsLeaseListener [Thread-71]: ethOn 12451554 INFO CommsLeaseListener [Thread-1041]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 12451596 INFO CommsLeaseListener [Thread-1041]: 13039436 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:21:36 PM 13039985 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 13040026 INFO CommsLeaseListener [Thread-71]: 13051044 INFO CommsLeaseListener [Thread-1088]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 13051086 INFO CommsLeaseListener [Thread-1088]: 13639446 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:31:36 PM 13639995 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 13640036 INFO CommsLeaseListener [Thread-71]: 13651054 INFO CommsLeaseListener [Thread-1136]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 13651096 INFO CommsLeaseListener [Thread-1136]: 14239455 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:41:36 PM 14240005 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 14240046 INFO CommsLeaseListener [Thread-71]: 14251064 INFO CommsLeaseListener [Thread-1184]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 14251106 INFO CommsLeaseListener [Thread-1184]: 14839355 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 14839427 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 14839466 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 10:51:36 PM 14840015 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 14840068 INFO CommsLeaseListener [Thread-71]: 14851094 INFO CommsLeaseListener [Thread-1233]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 14851146 INFO CommsLeaseListener [Thread-1233]: 15439476 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:01:36 PM 15440035 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 15440086 INFO CommsLeaseListener [Thread-71]: 15451104 INFO CommsLeaseListener [Thread-1283]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 15451146 INFO CommsLeaseListener [Thread-1283]: 16039485 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:11:36 PM 16040035 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 16040086 INFO CommsLeaseListener [Thread-71]: 16051104 INFO CommsLeaseListener [Thread-1329]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 16051146 INFO CommsLeaseListener [Thread-1329]: 16639496 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:21:36 PM 16640054 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 16640096 INFO CommsLeaseListener [Thread-71]: 16651114 INFO CommsLeaseListener [Thread-1377]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 16651167 INFO CommsLeaseListener [Thread-1377]: 17239506 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:31:36 PM 17240054 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 17240096 INFO CommsLeaseListener [Thread-71]: 17251114 INFO CommsLeaseListener [Thread-1425]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 17251166 INFO CommsLeaseListener [Thread-1425]: 17839515 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:41:36 PM 17840075 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 17840116 INFO CommsLeaseListener [Thread-71]: 17851134 INFO CommsLeaseListener [Thread-1473]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 17851176 INFO CommsLeaseListener [Thread-1473]: 18439369 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 18439457 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 18439525 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 10, 2015 11:51:36 PM 18440075 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 18440117 INFO CommsLeaseListener [Thread-71]: 18451134 INFO CommsLeaseListener [Thread-1520]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 18451186 INFO CommsLeaseListener [Thread-1520]: 19039536 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:01:36 AM 19040094 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 19040136 INFO CommsLeaseListener [Thread-71]: 19051154 INFO CommsLeaseListener [Thread-1570]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 19051206 INFO CommsLeaseListener [Thread-1570]: 19639546 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:11:36 AM 19640094 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 19640146 INFO CommsLeaseListener [Thread-71]: 19651164 INFO CommsLeaseListener [Thread-1618]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 19651216 INFO CommsLeaseListener [Thread-1618]: 20239555 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:21:36 AM 20240125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 20240176 INFO CommsLeaseListener [Thread-71]: 20251194 INFO CommsLeaseListener [Thread-1666]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 20251246 INFO CommsLeaseListener [Thread-1666]: 20839566 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:31:36 AM 20840125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 20840166 INFO CommsLeaseListener [Thread-71]: 20851184 INFO CommsLeaseListener [Thread-1713]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 20851226 INFO CommsLeaseListener [Thread-1713]: 21439576 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:41:36 AM 21440125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 21440176 INFO CommsLeaseListener [Thread-71]: 21451194 INFO CommsLeaseListener [Thread-1760]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 21451246 INFO CommsLeaseListener [Thread-1760]: 22039379 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 22039402 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 22039586 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:51:36 AM 22040137 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 22040747 INFO CommsLeaseListener [Thread-71]: ethOn 22051764 INFO CommsLeaseListener [Thread-1811]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 22051816 INFO CommsLeaseListener [Thread-1811]: 22639595 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:01:36 AM 22640155 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 22640196 INFO CommsLeaseListener [Thread-71]: 22651214 INFO CommsLeaseListener [Thread-1859]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 22651256 INFO CommsLeaseListener [Thread-1859]: 23239606 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:11:37 AM 23240174 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 23240215 INFO CommsLeaseListener [Thread-71]: 23251234 INFO CommsLeaseListener [Thread-1907]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 23251286 INFO CommsLeaseListener [Thread-1907]: 23839616 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:21:37 AM 23840174 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 23840216 INFO CommsLeaseListener [Thread-71]: 23851235 INFO CommsLeaseListener [Thread-1954]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 23851286 INFO CommsLeaseListener [Thread-1954]: 24439626 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:31:37 AM 24440175 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 24440226 INFO CommsLeaseListener [Thread-71]: 24451244 INFO CommsLeaseListener [Thread-2001]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 24451296 INFO CommsLeaseListener [Thread-2001]: 25039637 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:41:37 AM 25040185 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 25040225 INFO CommsLeaseListener [Thread-71]: 25051244 INFO CommsLeaseListener [Thread-2049]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 25051296 INFO CommsLeaseListener [Thread-2049]: 25639390 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 25639489 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 25639645 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:51:37 AM 25640265 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 25640359 INFO CommsLeaseListener [Thread-71]: 25651384 INFO CommsLeaseListener [Thread-2098]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 25651426 INFO CommsLeaseListener [Thread-2098]: 26239655 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:01:37 AM 26240285 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 26240336 INFO CommsLeaseListener [Thread-71]: 26251354 INFO CommsLeaseListener [Thread-2148]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 26251416 INFO CommsLeaseListener [Thread-2148]: 26839665 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:11:37 AM 26840285 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 26840326 INFO CommsLeaseListener [Thread-71]: 26851344 INFO CommsLeaseListener [Thread-2194]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 26851386 INFO CommsLeaseListener [Thread-2194]: 27439675 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:21:37 AM 27440284 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 27440326 INFO CommsLeaseListener [Thread-71]: 27451344 INFO CommsLeaseListener [Thread-2242]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 27451396 INFO CommsLeaseListener [Thread-2242]: 28039695 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:31:37 AM 28040294 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 28040336 INFO CommsLeaseListener [Thread-71]: 28051354 INFO CommsLeaseListener [Thread-2289]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 28051406 INFO CommsLeaseListener [Thread-2289]: 28639706 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:41:37 AM 28640295 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 28640346 INFO CommsLeaseListener [Thread-71]: 28651364 INFO CommsLeaseListener [Thread-2337]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 28651416 INFO CommsLeaseListener [Thread-2337]: 29239397 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 29239455 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 29239715 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:51:37 AM 29240385 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 29240997 INFO CommsLeaseListener [Thread-71]: ethOn 29252014 INFO CommsLeaseListener [Thread-2389]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 29252056 INFO CommsLeaseListener [Thread-2389]: 29839726 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:01:37 AM 29840304 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 29840346 INFO CommsLeaseListener [Thread-71]: 29851364 INFO CommsLeaseListener [Thread-2435]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 29851416 INFO CommsLeaseListener [Thread-2435]: 30439736 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:11:37 AM 30440305 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 30440346 INFO CommsLeaseListener [Thread-71]: 30451364 INFO CommsLeaseListener [Thread-2483]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 30451406 INFO CommsLeaseListener [Thread-2483]: 31039746 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:21:37 AM 31040314 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 31040356 INFO CommsLeaseListener [Thread-71]: 31051374 INFO CommsLeaseListener [Thread-2531]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 31051426 INFO CommsLeaseListener [Thread-2531]: 31639755 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:31:37 AM 31640314 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 31640356 INFO CommsLeaseListener [Thread-71]: 31651374 INFO CommsLeaseListener [Thread-2578]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 31651426 INFO CommsLeaseListener [Thread-2578]: 32239768 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:41:37 AM 32240335 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 32240386 INFO CommsLeaseListener [Thread-71]: 32251404 INFO CommsLeaseListener [Thread-2625]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 32251977 INFO CommsLeaseListener [Thread-2625]: ethOff 32839405 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 32839477 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 32839776 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:51:37 AM 32840355 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 32840946 INFO CommsLeaseListener [Thread-71]: ethOn 32851964 INFO CommsLeaseListener [Thread-2676]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 32852006 INFO CommsLeaseListener [Thread-2676]: 33439788 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:01:37 AM 33440344 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 33440386 INFO CommsLeaseListener [Thread-71]: 33451404 INFO CommsLeaseListener [Thread-2724]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 33451446 INFO CommsLeaseListener [Thread-2724]: 34039796 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:11:37 AM 34040365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 34040416 INFO CommsLeaseListener [Thread-71]: 34051434 INFO CommsLeaseListener [Thread-2772]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 34051486 INFO CommsLeaseListener [Thread-2772]: 34639805 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:21:37 AM 34640365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 34640416 INFO CommsLeaseListener [Thread-71]: 34651434 INFO CommsLeaseListener [Thread-2819]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 34651486 INFO CommsLeaseListener [Thread-2819]: 35239816 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:31:37 AM 35240365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 35240416 INFO CommsLeaseListener [Thread-71]: 35251434 INFO CommsLeaseListener [Thread-2866]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 35251476 INFO CommsLeaseListener [Thread-2866]: 35839825 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:41:37 AM 35840375 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 35840416 INFO CommsLeaseListener [Thread-71]: 35851434 INFO CommsLeaseListener [Thread-2913]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 35851476 INFO CommsLeaseListener [Thread-2913]: 36439416 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 36439488 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 36439836 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:51:37 AM 36440385 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 36440565 INFO CommsLeaseListener [Thread-71]: 36451584 INFO CommsLeaseListener [Thread-2964]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 36451636 INFO CommsLeaseListener [Thread-2964]: 37039845 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:01:37 AM 37040395 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 37040436 INFO CommsLeaseListener [Thread-71]: 37051454 INFO CommsLeaseListener [Thread-3013]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 37051496 INFO CommsLeaseListener [Thread-3013]: 37639856 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:11:37 AM 37640415 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 37640456 INFO CommsLeaseListener [Thread-71]: 37651474 INFO CommsLeaseListener [Thread-3061]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 37651516 INFO CommsLeaseListener [Thread-3061]: 38239866 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:21:37 AM 38240414 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 38240456 INFO CommsLeaseListener [Thread-71]: 38251474 INFO CommsLeaseListener [Thread-3106]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 38251526 INFO CommsLeaseListener [Thread-3106]: 38839875 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:31:37 AM 38840445 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 38840496 INFO CommsLeaseListener [Thread-71]: 38851514 INFO CommsLeaseListener [Thread-3154]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 38851556 INFO CommsLeaseListener [Thread-3154]: 39439885 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:41:37 AM 39440445 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 39440533 INFO CommsLeaseListener [Thread-71]: 39451554 INFO CommsLeaseListener [Thread-3202]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 39451607 INFO CommsLeaseListener [Thread-3202]: 40039426 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 40039471 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 40039896 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:51:37 AM 40040510 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 40040646 INFO CommsLeaseListener [Thread-71]: 40051664 INFO CommsLeaseListener [Thread-3254]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 40051716 INFO CommsLeaseListener [Thread-3254]: 40639906 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:01:37 AM 40640455 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 40640496 INFO CommsLeaseListener [Thread-71]: 40651514 INFO CommsLeaseListener [Thread-3302]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 40651556 INFO CommsLeaseListener [Thread-3302]: 41239916 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:11:37 AM 41240475 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 41240526 INFO CommsLeaseListener [Thread-71]: 41251544 INFO CommsLeaseListener [Thread-3347]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 41251636 INFO CommsLeaseListener [Thread-3347]: 41839925 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:21:37 AM 41840475 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 41840526 INFO CommsLeaseListener [Thread-71]: 41851545 INFO CommsLeaseListener [Thread-3395]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 41851596 INFO CommsLeaseListener [Thread-3395]: 42439935 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:31:37 AM 42440484 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 42440526 INFO CommsLeaseListener [Thread-71]: 42451544 INFO CommsLeaseListener [Thread-3443]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 42451596 INFO CommsLeaseListener [Thread-3443]: 43039945 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:41:37 AM 43040505 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 43040546 INFO CommsLeaseListener [Thread-71]: 43051564 INFO CommsLeaseListener [Thread-3491]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 43051606 INFO CommsLeaseListener [Thread-3491]: 43639436 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 43639512 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 43639955 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:51:37 AM 43640535 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 43641117 INFO CommsLeaseListener [Thread-71]: ethOn 43652134 INFO CommsLeaseListener [Thread-3542]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 43652176 INFO CommsLeaseListener [Thread-3542]: 44239966 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:01:37 AM 44240575 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 44240626 INFO CommsLeaseListener [Thread-71]: 44251674 INFO CommsLeaseListener [Thread-3589]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 44251716 INFO CommsLeaseListener [Thread-3589]: 44839975 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:11:37 AM 44840525 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 44840576 INFO CommsLeaseListener [Thread-71]: 44851594 INFO CommsLeaseListener [Thread-3636]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 44851636 INFO CommsLeaseListener [Thread-3636]: 45439985 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:21:37 AM 45440535 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 45440586 INFO CommsLeaseListener [Thread-71]: 45451604 INFO CommsLeaseListener [Thread-3684]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 45451656 INFO CommsLeaseListener [Thread-3684]: 46039995 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:31:37 AM 46040555 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 46040607 INFO CommsLeaseListener [Thread-71]: 46051624 INFO CommsLeaseListener [Thread-3732]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 46051666 INFO CommsLeaseListener [Thread-3732]: 46640006 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:41:37 AM 46640565 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 46640616 INFO CommsLeaseListener [Thread-71]: 46651634 INFO CommsLeaseListener [Thread-3778]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 46651676 INFO CommsLeaseListener [Thread-3778]: 47239445 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 47239526 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 47240017 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:51:37 AM 47240598 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 47240726 INFO CommsLeaseListener [Thread-71]: 47251744 INFO CommsLeaseListener [Thread-3830]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 47251786 INFO CommsLeaseListener [Thread-3830]: 47840025 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:01:37 AM 47840574 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 47840616 INFO CommsLeaseListener [Thread-71]: 47851634 INFO CommsLeaseListener [Thread-3877]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 47852207 INFO CommsLeaseListener [Thread-3877]: ethOff 48440036 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:11:37 AM 48440605 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 48440655 INFO CommsLeaseListener [Thread-71]: 48451674 INFO CommsLeaseListener [Thread-3925]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 48451716 INFO CommsLeaseListener [Thread-3925]: 49040045 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:21:37 AM 49040605 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 49040645 INFO CommsLeaseListener [Thread-71]: 49051664 INFO CommsLeaseListener [Thread-3973]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 49051756 INFO CommsLeaseListener [Thread-3973]: 49640056 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:31:37 AM 49640625 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 49640676 INFO CommsLeaseListener [Thread-71]: 49651694 INFO CommsLeaseListener [Thread-4019]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 49651786 INFO CommsLeaseListener [Thread-4019]: 50240065 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:41:37 AM 50240615 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 50240656 INFO CommsLeaseListener [Thread-71]: 50251674 INFO CommsLeaseListener [Thread-4067]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 50251726 INFO CommsLeaseListener [Thread-4067]: 50839457 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 50839568 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 50840076 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:51:37 AM 50840666 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 50840733 INFO CommsLeaseListener [Thread-71]: 50851754 INFO CommsLeaseListener [Thread-4118]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 50851796 INFO CommsLeaseListener [Thread-4118]: 51440085 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:01:37 AM 51440634 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 51440676 INFO CommsLeaseListener [Thread-71]: 51451694 INFO CommsLeaseListener [Thread-4166]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 51451746 INFO CommsLeaseListener [Thread-4166]: 52040095 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:11:37 AM 52040655 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 52040696 INFO CommsLeaseListener [Thread-71]: 52051714 INFO CommsLeaseListener [Thread-4213]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 52051756 INFO CommsLeaseListener [Thread-4213]: 52640105 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:21:37 AM 52640704 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 52640746 INFO CommsLeaseListener [Thread-71]: 52651764 INFO CommsLeaseListener [Thread-4260]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 52651816 INFO CommsLeaseListener [Thread-4260]: 53240116 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:31:37 AM 53240685 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 53241246 INFO CommsLeaseListener [Thread-71]: ethOn 53252264 INFO CommsLeaseListener [Thread-4308]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 53252306 INFO CommsLeaseListener [Thread-4308]: 53840125 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:41:37 AM 53840685 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 53840726 INFO CommsLeaseListener [Thread-71]: 53851744 INFO CommsLeaseListener [Thread-4356]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 53851807 INFO CommsLeaseListener [Thread-4356]: 54439467 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 54439532 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 54440142 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:51:37 AM 54440755 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 54440796 INFO CommsLeaseListener [Thread-71]: 54451814 INFO CommsLeaseListener [Thread-4407]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 54451856 INFO CommsLeaseListener [Thread-4407]: 55040145 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:01:37 AM 55040705 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 55040756 INFO CommsLeaseListener [Thread-71]: 55051774 INFO CommsLeaseListener [Thread-4454]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 55051816 INFO CommsLeaseListener [Thread-4454]: 55640155 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:11:37 AM 55640715 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 55640756 INFO CommsLeaseListener [Thread-71]: 55651774 INFO CommsLeaseListener [Thread-4501]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 55651817 INFO CommsLeaseListener [Thread-4501]: 56240165 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:21:37 AM 56240725 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 56240776 INFO CommsLeaseListener [Thread-71]: 56251794 INFO CommsLeaseListener [Thread-4549]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 56251836 INFO CommsLeaseListener [Thread-4549]: 56840176 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:31:37 AM 56840724 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 56840766 INFO CommsLeaseListener [Thread-71]: 56851784 INFO CommsLeaseListener [Thread-4597]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 56851836 INFO CommsLeaseListener [Thread-4597]: 57440185 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:41:37 AM 57440735 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 57440776 INFO CommsLeaseListener [Thread-71]: 57451794 INFO CommsLeaseListener [Thread-4645]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 57451836 INFO CommsLeaseListener [Thread-4645]: 58039494 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 58039550 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 58040219 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:51:37 AM 58040838 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 58040998 INFO CommsLeaseListener [Thread-71]: 58052024 INFO CommsLeaseListener [Thread-4694]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 58052066 INFO CommsLeaseListener [Thread-4694]: 58640225 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:01:37 AM 58640774 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 58640816 INFO CommsLeaseListener [Thread-71]: 58651834 INFO CommsLeaseListener [Thread-4742]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 58651886 INFO CommsLeaseListener [Thread-4742]: 59240236 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:11:37 AM 59240795 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 59240836 INFO CommsLeaseListener [Thread-71]: 59251854 INFO CommsLeaseListener [Thread-4790]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 59252447 INFO CommsLeaseListener [Thread-4790]: ethOff 59840246 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:21:37 AM 59840805 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 59840856 INFO CommsLeaseListener [Thread-71]: 59851874 INFO CommsLeaseListener [Thread-4838]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 59851966 INFO CommsLeaseListener [Thread-4838]: 60440255 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:31:37 AM 60440804 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 60440846 INFO CommsLeaseListener [Thread-71]: 60451864 INFO CommsLeaseListener [Thread-4886]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 60451916 INFO CommsLeaseListener [Thread-4886]: 61040265 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:41:37 AM 61040814 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 61040856 INFO CommsLeaseListener [Thread-71]: 61051874 INFO CommsLeaseListener [Thread-4932]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 61051916 INFO CommsLeaseListener [Thread-4932]: 61639507 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 61639535 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 61640277 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:51:37 AM 61640898 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 61641446 INFO CommsLeaseListener [Thread-71]: ethOn 61652464 INFO CommsLeaseListener [Thread-4984]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 61652516 INFO CommsLeaseListener [Thread-4984]: 62240286 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:01:37 PM 62240845 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 62240896 INFO CommsLeaseListener [Thread-71]: 62251914 INFO CommsLeaseListener [Thread-5031]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 62251956 INFO CommsLeaseListener [Thread-5031]: 62840295 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:11:37 PM 62840845 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 62840886 INFO CommsLeaseListener [Thread-71]: 62851904 INFO CommsLeaseListener [Thread-5079]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 62851956 INFO CommsLeaseListener [Thread-5079]: 63440306 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:21:37 PM 63440854 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 63440896 INFO CommsLeaseListener [Thread-71]: 63451914 INFO CommsLeaseListener [Thread-5126]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 63451966 INFO CommsLeaseListener [Thread-5126]: 64040316 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:31:37 PM 64040865 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 64040916 INFO CommsLeaseListener [Thread-71]: 64051934 INFO CommsLeaseListener [Thread-5173]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 64051986 INFO CommsLeaseListener [Thread-5173]: 64640326 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:41:37 PM 64640895 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 64640946 INFO CommsLeaseListener [Thread-71]: 64651965 INFO CommsLeaseListener [Thread-5221]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 64652016 INFO CommsLeaseListener [Thread-5221]: 65239517 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 65239585 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 65240337 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 12:51:37 PM 65240905 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 65241486 INFO CommsLeaseListener [Thread-71]: ethOn 65252504 INFO CommsLeaseListener [Thread-5272]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 65253057 INFO CommsLeaseListener [Thread-5272]: ethOff 65840345 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:01:37 PM 65840895 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 65840936 INFO CommsLeaseListener [Thread-71]: 65851954 INFO CommsLeaseListener [Thread-5320]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 65852006 INFO CommsLeaseListener [Thread-5320]: 66440356 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:11:37 PM 66440915 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 66440966 INFO CommsLeaseListener [Thread-71]: 66451984 INFO CommsLeaseListener [Thread-5366]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 66452026 INFO CommsLeaseListener [Thread-5366]: 67040366 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:21:37 PM 67040965 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 67041016 INFO CommsLeaseListener [Thread-71]: 67052034 INFO CommsLeaseListener [Thread-5414]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 67052086 INFO CommsLeaseListener [Thread-5414]: 67640375 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:31:37 PM 67640935 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 67640986 INFO CommsLeaseListener [Thread-71]: 67652004 INFO CommsLeaseListener [Thread-5461]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 67652046 INFO CommsLeaseListener [Thread-5461]: 68240385 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:41:37 PM 68240935 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 68240976 INFO CommsLeaseListener [Thread-71]: 68251994 INFO CommsLeaseListener [Thread-5509]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 68252046 INFO CommsLeaseListener [Thread-5509]: 68839526 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 68839613 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 68840410 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 1:51:37 PM 68841074 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 68841116 INFO CommsLeaseListener [Thread-71]: 68852134 INFO CommsLeaseListener [Thread-5561]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 68852186 INFO CommsLeaseListener [Thread-5561]: 69440415 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:01:37 PM 69440965 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 69441006 INFO CommsLeaseListener [Thread-71]: 69452024 INFO CommsLeaseListener [Thread-5607]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 69452066 INFO CommsLeaseListener [Thread-5607]: 70040425 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:11:37 PM 70040975 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 70041016 INFO CommsLeaseListener [Thread-71]: 70052034 INFO CommsLeaseListener [Thread-5655]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 70052096 INFO CommsLeaseListener [Thread-5655]: 70640436 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:21:37 PM 70641035 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 70641076 INFO CommsLeaseListener [Thread-71]: 70652094 INFO CommsLeaseListener [Thread-5702]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 70652136 INFO CommsLeaseListener [Thread-5702]: 71240445 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:31:37 PM 71241005 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 71241096 INFO CommsLeaseListener [Thread-71]: 71252114 INFO CommsLeaseListener [Thread-5750]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 71252156 INFO CommsLeaseListener [Thread-5750]: 71840455 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:41:37 PM 71841004 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 71841046 INFO CommsLeaseListener [Thread-71]: 71852064 INFO CommsLeaseListener [Thread-5797]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 71852116 INFO CommsLeaseListener [Thread-5797]: 72439544 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 72439616 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 72440465 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 2:51:37 PM 72441045 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 72441086 INFO CommsLeaseListener [Thread-71]: 72452104 INFO CommsLeaseListener [Thread-5848]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 72452146 INFO CommsLeaseListener [Thread-5848]: 73040475 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:01:37 PM 73041025 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 73041087 INFO CommsLeaseListener [Thread-71]: 73052104 INFO CommsLeaseListener [Thread-5896]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 73052156 INFO CommsLeaseListener [Thread-5896]: 73640485 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:11:37 PM 73641045 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 73641096 INFO CommsLeaseListener [Thread-71]: 73652114 INFO CommsLeaseListener [Thread-5944]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 73652206 INFO CommsLeaseListener [Thread-5944]: 74240495 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:21:37 PM 74241055 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 74241106 INFO CommsLeaseListener [Thread-71]: 74252124 INFO CommsLeaseListener [Thread-5991]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 74252166 INFO CommsLeaseListener [Thread-5991]: 74840505 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:31:37 PM 74841055 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 74841096 INFO CommsLeaseListener [Thread-71]: 74852114 INFO CommsLeaseListener [Thread-6038]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 74852157 INFO CommsLeaseListener [Thread-6038]: 75440516 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:41:37 PM 75441085 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 75441136 INFO CommsLeaseListener [Thread-71]: 75452154 INFO CommsLeaseListener [Thread-6085]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 75452196 INFO CommsLeaseListener [Thread-6085]: 76039564 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 76039628 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 76040527 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 3:51:37 PM 76041154 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 76041196 INFO CommsLeaseListener [Thread-71]: 76052214 INFO CommsLeaseListener [Thread-6137]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 76052266 INFO CommsLeaseListener [Thread-6137]: 76640536 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:01:37 PM 76641095 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 76641136 INFO CommsLeaseListener [Thread-71]: 76652154 INFO CommsLeaseListener [Thread-6185]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 76652196 INFO CommsLeaseListener [Thread-6185]: 77240545 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:11:37 PM 77241095 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 77241136 INFO CommsLeaseListener [Thread-71]: 77252154 INFO CommsLeaseListener [Thread-6232]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 77252196 INFO CommsLeaseListener [Thread-6232]: 77840555 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:21:37 PM 77841105 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 77841146 INFO CommsLeaseListener [Thread-71]: 77852164 INFO CommsLeaseListener [Thread-6278]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 77852206 INFO CommsLeaseListener [Thread-6278]: 78440565 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:31:37 PM 78441125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 78441213 INFO CommsLeaseListener [Thread-71]: 78452234 INFO CommsLeaseListener [Thread-6326]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 78452286 INFO CommsLeaseListener [Thread-6326]: 79040575 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:41:37 PM 79041125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 79041176 INFO CommsLeaseListener [Thread-71]: 79052194 INFO CommsLeaseListener [Thread-6374]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 79052236 INFO CommsLeaseListener [Thread-6374]: 79639577 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 79639622 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 79640587 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 4:51:37 PM 79641155 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 79641206 INFO CommsLeaseListener [Thread-71]: 79652224 INFO CommsLeaseListener [Thread-6426]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 79652266 INFO CommsLeaseListener [Thread-6426]: 80240596 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:01:37 PM 80241155 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 80241206 INFO CommsLeaseListener [Thread-71]: 80252224 INFO CommsLeaseListener [Thread-6474]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 80252266 INFO CommsLeaseListener [Thread-6474]: 80840606 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:11:38 PM 80841155 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 80841196 INFO CommsLeaseListener [Thread-71]: 80852214 INFO CommsLeaseListener [Thread-6519]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 80852256 INFO CommsLeaseListener [Thread-6519]: 81440615 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:21:38 PM 81441165 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 81441216 INFO CommsLeaseListener [Thread-71]: 81452234 INFO CommsLeaseListener [Thread-6567]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 81452276 INFO CommsLeaseListener [Thread-6567]: 82040625 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:31:38 PM 82041175 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 82041216 INFO CommsLeaseListener [Thread-71]: 82052234 INFO CommsLeaseListener [Thread-6615]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 82052286 INFO CommsLeaseListener [Thread-6615]: 82640636 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:41:38 PM 82641195 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 82641236 INFO CommsLeaseListener [Thread-71]: 82652254 INFO CommsLeaseListener [Thread-6663]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 82652296 INFO CommsLeaseListener [Thread-6663]: 83239594 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 83239681 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 83240646 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 5:51:38 PM 83241195 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 83241236 INFO CommsLeaseListener [Thread-71]: 83252254 INFO CommsLeaseListener [Thread-6714]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 83252306 INFO CommsLeaseListener [Thread-6714]: 83840655 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:01:38 PM 83841235 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 83841276 INFO CommsLeaseListener [Thread-71]: 83852294 INFO CommsLeaseListener [Thread-6760]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 83852336 INFO CommsLeaseListener [Thread-6760]: 84440666 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:11:38 PM 84441215 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 84441767 INFO CommsLeaseListener [Thread-71]: ethOn 84452784 INFO CommsLeaseListener [Thread-6808]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 84452826 INFO CommsLeaseListener [Thread-6808]: 85040676 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:21:38 PM 85041245 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 85041286 INFO CommsLeaseListener [Thread-71]: 85052304 INFO CommsLeaseListener [Thread-6856]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 85052346 INFO CommsLeaseListener [Thread-6856]: 85640685 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:31:38 PM 85641235 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 85641286 INFO CommsLeaseListener [Thread-71]: 85652304 INFO CommsLeaseListener [Thread-6904]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 85652356 INFO CommsLeaseListener [Thread-6904]: 86240695 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:41:38 PM 86241245 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 86241286 INFO CommsLeaseListener [Thread-71]: 86252304 INFO CommsLeaseListener [Thread-6950]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 86252356 INFO CommsLeaseListener [Thread-6950]: 86839629 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 86839773 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 86840715 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 6:51:38 PM 86841275 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 86841326 INFO CommsLeaseListener [Thread-71]: 86852344 INFO CommsLeaseListener [Thread-7002]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 86852396 INFO CommsLeaseListener [Thread-7002]: 87440726 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:01:38 PM 87441285 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 87441327 INFO CommsLeaseListener [Thread-71]: 87452344 INFO CommsLeaseListener [Thread-7049]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 87452386 INFO CommsLeaseListener [Thread-7049]: 88040735 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:11:38 PM 88041284 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 88041374 INFO CommsLeaseListener [Thread-71]: 88052394 INFO CommsLeaseListener [Thread-7097]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 88052446 INFO CommsLeaseListener [Thread-7097]: 88640745 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:21:38 PM 88641294 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 88641336 INFO CommsLeaseListener [Thread-71]: 88652354 INFO CommsLeaseListener [Thread-7145]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 88652446 INFO CommsLeaseListener [Thread-7145]: 89240756 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:31:38 PM 89241325 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 89241376 INFO CommsLeaseListener [Thread-71]: 89252394 INFO CommsLeaseListener [Thread-7191]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 89252446 INFO CommsLeaseListener [Thread-7191]: 89840765 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:41:38 PM 89841325 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 89841376 INFO CommsLeaseListener [Thread-71]: 89852397 INFO CommsLeaseListener [Thread-7239]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 89852437 INFO CommsLeaseListener [Thread-7239]: 90439635 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 90439671 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 90440776 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 7:51:38 PM 90441394 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 90441446 INFO CommsLeaseListener [Thread-71]: 90452464 INFO CommsLeaseListener [Thread-7291]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 90452516 INFO CommsLeaseListener [Thread-7291]: 91040785 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:01:38 PM 91041365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 91041416 INFO CommsLeaseListener [Thread-71]: 91052434 INFO CommsLeaseListener [Thread-7339]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 91052486 INFO CommsLeaseListener [Thread-7339]: 91640796 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:11:38 PM 91641365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 91641416 INFO CommsLeaseListener [Thread-71]: 91652444 INFO CommsLeaseListener [Thread-7385]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 91652486 INFO CommsLeaseListener [Thread-7385]: 92240805 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:21:38 PM 92241375 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 92241416 INFO CommsLeaseListener [Thread-71]: 92252434 INFO CommsLeaseListener [Thread-7432]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 92252476 INFO CommsLeaseListener [Thread-7432]: 92840815 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:31:38 PM 92841365 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 92841416 INFO CommsLeaseListener [Thread-71]: 92852434 INFO CommsLeaseListener [Thread-7480]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 92852486 INFO CommsLeaseListener [Thread-7480]: 93440826 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:41:38 PM 93441374 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 93441416 INFO CommsLeaseListener [Thread-71]: 93452434 INFO CommsLeaseListener [Thread-7528]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 93452987 INFO CommsLeaseListener [Thread-7528]: ethOff 94039648 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 94039798 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 94040836 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 8:51:38 PM 94041395 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 94041476 INFO CommsLeaseListener [Thread-71]: 94052494 INFO CommsLeaseListener [Thread-7580]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 94052536 INFO CommsLeaseListener [Thread-7580]: 94640846 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:01:38 PM 94641405 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 94641446 INFO CommsLeaseListener [Thread-71]: 94652464 INFO CommsLeaseListener [Thread-7626]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 94652506 INFO CommsLeaseListener [Thread-7626]: 95240855 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:11:38 PM 95241404 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 95241446 INFO CommsLeaseListener [Thread-71]: 95252464 INFO CommsLeaseListener [Thread-7673]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 95252516 INFO CommsLeaseListener [Thread-7673]: 95840865 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:21:38 PM 95841415 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 95841976 INFO CommsLeaseListener [Thread-71]: ethOn 95852994 INFO CommsLeaseListener [Thread-7721]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 95853036 INFO CommsLeaseListener [Thread-7721]: 96440875 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:31:38 PM 96441435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 96441485 INFO CommsLeaseListener [Thread-71]: 96452504 INFO CommsLeaseListener [Thread-7769]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 96452555 INFO CommsLeaseListener [Thread-7769]: 97040885 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:41:38 PM 97041435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 97041516 INFO CommsLeaseListener [Thread-71]: 97052534 INFO CommsLeaseListener [Thread-7817]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 97052576 INFO CommsLeaseListener [Thread-7817]: 97639659 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 97639816 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 97640902 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 9:51:38 PM 97641474 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 97641516 INFO CommsLeaseListener [Thread-71]: 97652534 INFO CommsLeaseListener [Thread-7867]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 97652585 INFO CommsLeaseListener [Thread-7867]: 98240905 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:01:38 PM 98241455 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 98241496 INFO CommsLeaseListener [Thread-71]: 98252514 INFO CommsLeaseListener [Thread-7915]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 98252556 INFO CommsLeaseListener [Thread-7915]: 98840916 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:11:38 PM 98841464 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 98841506 INFO CommsLeaseListener [Thread-71]: 98852524 INFO CommsLeaseListener [Thread-7962]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 98852566 INFO CommsLeaseListener [Thread-7962]: 99440925 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:21:38 PM 99441475 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 99441526 INFO CommsLeaseListener [Thread-71]: 99452544 INFO CommsLeaseListener [Thread-8010]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 99452596 INFO CommsLeaseListener [Thread-8010]: 100040935 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:31:38 PM 100041485 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 100041536 INFO CommsLeaseListener [Thread-71]: 100052554 INFO CommsLeaseListener [Thread-8058]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 100052606 INFO CommsLeaseListener [Thread-8058]: 100640945 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:41:38 PM 100641495 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 100641546 INFO CommsLeaseListener [Thread-71]: 100652565 INFO CommsLeaseListener [Thread-8104]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 100652607 INFO CommsLeaseListener [Thread-8104]: 101239665 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 101239735 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 101240956 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 10:51:38 PM 101241525 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 101241576 INFO CommsLeaseListener [Thread-71]: 101252594 INFO CommsLeaseListener [Thread-8156]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 101252696 INFO CommsLeaseListener [Thread-8156]: 101840965 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:01:38 PM 101841515 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 101841556 INFO CommsLeaseListener [Thread-71]: 101852574 INFO CommsLeaseListener [Thread-8203]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 101852616 INFO CommsLeaseListener [Thread-8203]: 102440975 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:11:38 PM 102441525 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 102442096 INFO CommsLeaseListener [Thread-71]: ethOn 102453114 INFO CommsLeaseListener [Thread-8251]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 102453156 INFO CommsLeaseListener [Thread-8251]: 103040986 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:21:38 PM 103041535 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 103041576 INFO CommsLeaseListener [Thread-71]: 103052594 INFO CommsLeaseListener [Thread-8298]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 103052646 INFO CommsLeaseListener [Thread-8298]: 103640996 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:31:38 PM 103641565 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 103641616 INFO CommsLeaseListener [Thread-71]: 103652634 INFO CommsLeaseListener [Thread-8345]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 103652676 INFO CommsLeaseListener [Thread-8345]: 104241006 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:41:38 PM 104241565 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 104241616 INFO CommsLeaseListener [Thread-71]: 104252634 INFO CommsLeaseListener [Thread-8393]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 104252676 INFO CommsLeaseListener [Thread-8393]: 104839717 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 104839793 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 104841015 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 11, 2015 11:51:38 PM 104841624 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 104841666 INFO CommsLeaseListener [Thread-71]: 104852684 INFO CommsLeaseListener [Thread-8445]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 104852736 INFO CommsLeaseListener [Thread-8445]: 105441025 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:01:38 AM 105441575 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 105441636 INFO CommsLeaseListener [Thread-71]: 105452654 INFO CommsLeaseListener [Thread-8492]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 105452696 INFO CommsLeaseListener [Thread-8492]: 106041035 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:11:38 AM 106041585 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 106041635 INFO CommsLeaseListener [Thread-71]: 106052654 INFO CommsLeaseListener [Thread-8538]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 106052696 INFO CommsLeaseListener [Thread-8538]: 106641045 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:21:38 AM 106641634 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 106641676 INFO CommsLeaseListener [Thread-71]: 106652695 INFO CommsLeaseListener [Thread-8586]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 106653277 INFO CommsLeaseListener [Thread-8586]: ethOff 107241055 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:31:38 AM 107241605 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 107241656 INFO CommsLeaseListener [Thread-71]: 107252674 INFO CommsLeaseListener [Thread-8634]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 107252727 INFO CommsLeaseListener [Thread-8634]: 107841066 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:41:38 AM 107841625 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 107841675 INFO CommsLeaseListener [Thread-71]: 107852694 INFO CommsLeaseListener [Thread-8682]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 107852746 INFO CommsLeaseListener [Thread-8682]: 108439695 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 108440008 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 108441077 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:51:38 AM 108441624 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 108441667 INFO CommsLeaseListener [Thread-71]: 108452684 INFO CommsLeaseListener [Thread-8733]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 108452735 INFO CommsLeaseListener [Thread-8733]: 109041086 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:01:38 AM 109041635 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 109041676 INFO CommsLeaseListener [Thread-71]: 109052694 INFO CommsLeaseListener [Thread-8779]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 109052746 INFO CommsLeaseListener [Thread-8779]: 109641095 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:11:38 AM 109641675 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 109641726 INFO CommsLeaseListener [Thread-71]: 109652744 INFO CommsLeaseListener [Thread-8827]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 109652796 INFO CommsLeaseListener [Thread-8827]: 110241105 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:21:38 AM 110241655 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 110241696 INFO CommsLeaseListener [Thread-71]: 110252714 INFO CommsLeaseListener [Thread-8875]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 110252766 INFO CommsLeaseListener [Thread-8875]: 110841116 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:31:38 AM 110841675 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 110841726 INFO CommsLeaseListener [Thread-71]: 110852744 INFO CommsLeaseListener [Thread-8923]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 110852786 INFO CommsLeaseListener [Thread-8923]: 111441125 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:41:38 AM 111441675 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 111441716 INFO CommsLeaseListener [Thread-71]: 111452745 INFO CommsLeaseListener [Thread-8970]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 111453327 INFO CommsLeaseListener [Thread-8970]: ethOff 112039705 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 112039726 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 112041135 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:51:38 AM 112041685 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 112041736 INFO CommsLeaseListener [Thread-71]: 112052754 INFO CommsLeaseListener [Thread-9020]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 112052796 INFO CommsLeaseListener [Thread-9020]: 112641146 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:01:38 AM 112641695 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 112641736 INFO CommsLeaseListener [Thread-71]: 112652754 INFO CommsLeaseListener [Thread-9068]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 112652796 INFO CommsLeaseListener [Thread-9068]: 113241155 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:11:38 AM 113241715 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 113241756 INFO CommsLeaseListener [Thread-71]: 113252774 INFO CommsLeaseListener [Thread-9116]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 113252826 INFO CommsLeaseListener [Thread-9116]: 113841165 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:21:38 AM 113841715 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 113841766 INFO CommsLeaseListener [Thread-71]: 113852784 INFO CommsLeaseListener [Thread-9164]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 113852826 INFO CommsLeaseListener [Thread-9164]: 114441176 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:31:38 AM 114441725 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 114442277 INFO CommsLeaseListener [Thread-71]: ethOn 114453294 INFO CommsLeaseListener [Thread-9211]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 114453336 INFO CommsLeaseListener [Thread-9211]: 115041185 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:41:38 AM 115041735 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 115041776 INFO CommsLeaseListener [Thread-71]: 115052794 INFO CommsLeaseListener [Thread-9257]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 115052846 INFO CommsLeaseListener [Thread-9257]: 115639725 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 115639817 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 115641196 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:51:38 AM 115641745 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 115641786 INFO CommsLeaseListener [Thread-71]: 115652804 INFO CommsLeaseListener [Thread-9309]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 115652846 INFO CommsLeaseListener [Thread-9309]: 116241205 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:01:38 AM 116241765 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 116241816 INFO CommsLeaseListener [Thread-71]: 116252834 INFO CommsLeaseListener [Thread-9357]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 116252876 INFO CommsLeaseListener [Thread-9357]: 116841215 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:11:38 AM 116841765 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 116841806 INFO CommsLeaseListener [Thread-71]: 116852824 INFO CommsLeaseListener [Thread-9405]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 116853377 INFO CommsLeaseListener [Thread-9405]: ethOff 117441226 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:21:38 AM 117441784 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 117441826 INFO CommsLeaseListener [Thread-71]: 117452844 INFO CommsLeaseListener [Thread-9451]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 117452896 INFO CommsLeaseListener [Thread-9451]: 118041236 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:31:38 AM 118041805 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 118041845 INFO CommsLeaseListener [Thread-71]: 118052864 INFO CommsLeaseListener [Thread-9498]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 118052906 INFO CommsLeaseListener [Thread-9498]: 118641245 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:41:38 AM 118641805 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 118641846 INFO CommsLeaseListener [Thread-71]: 118652864 INFO CommsLeaseListener [Thread-9546]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 118652906 INFO CommsLeaseListener [Thread-9546]: 119239735 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 119239759 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 119241255 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:51:38 AM 119241805 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 119241855 INFO CommsLeaseListener [Thread-71]: 119252874 INFO CommsLeaseListener [Thread-9598]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 119252916 INFO CommsLeaseListener [Thread-9598]: 119841265 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:01:38 AM 119841825 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 119841876 INFO CommsLeaseListener [Thread-71]: 119852894 INFO CommsLeaseListener [Thread-9645]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 119852946 INFO CommsLeaseListener [Thread-9645]: 120441275 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:11:38 AM 120441854 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 120441918 INFO CommsLeaseListener [Thread-71]: 120452934 INFO CommsLeaseListener [Thread-9692]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 120452976 INFO CommsLeaseListener [Thread-9692]: 121041285 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:21:38 AM 121041845 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 121041896 INFO CommsLeaseListener [Thread-71]: 121052915 INFO CommsLeaseListener [Thread-9740]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 121052956 INFO CommsLeaseListener [Thread-9740]: 121641295 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:31:38 AM 121641865 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 121641916 INFO CommsLeaseListener [Thread-71]: 121652934 INFO CommsLeaseListener [Thread-9787]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 121652976 INFO CommsLeaseListener [Thread-9787]: 122241305 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:41:38 AM 122241865 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 122241906 INFO CommsLeaseListener [Thread-71]: 122252924 INFO CommsLeaseListener [Thread-9835]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 122252976 INFO CommsLeaseListener [Thread-9835]: 122839745 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 122839847 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 122841315 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:51:38 AM 122841895 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 122841946 INFO CommsLeaseListener [Thread-71]: 122852965 INFO CommsLeaseListener [Thread-9886]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 122853016 INFO CommsLeaseListener [Thread-9886]: 123441325 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:01:38 AM 123441875 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 123441937 INFO CommsLeaseListener [Thread-71]: 123452954 INFO CommsLeaseListener [Thread-9933]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 123453006 INFO CommsLeaseListener [Thread-9933]: 124041335 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:11:38 AM 124041885 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 124041936 INFO CommsLeaseListener [Thread-71]: 124052954 INFO CommsLeaseListener [Thread-9981]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 124052996 INFO CommsLeaseListener [Thread-9981]: 124641346 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:21:38 AM 124641894 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 124641936 INFO CommsLeaseListener [Thread-71]: 124652954 INFO CommsLeaseListener [Thread-10029]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 124653006 INFO CommsLeaseListener [Thread-10029]: 125241356 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:31:38 AM 125241905 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 125241946 INFO CommsLeaseListener [Thread-71]: 125252964 INFO CommsLeaseListener [Thread-10076]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 125253016 INFO CommsLeaseListener [Thread-10076]: 125841365 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:41:38 AM 125841925 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 125841975 INFO CommsLeaseListener [Thread-71]: 125852994 INFO CommsLeaseListener [Thread-10122]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 125853046 INFO CommsLeaseListener [Thread-10122]: 126439757 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 126439812 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 126441376 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:51:38 AM 126441935 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 126441986 INFO CommsLeaseListener [Thread-71]: 126453004 INFO CommsLeaseListener [Thread-10174]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 126453567 INFO CommsLeaseListener [Thread-10174]: ethOff 127041385 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:01:38 AM 127041935 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 127041986 INFO CommsLeaseListener [Thread-71]: 127053004 INFO CommsLeaseListener [Thread-10222]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 127053557 INFO CommsLeaseListener [Thread-10222]: ethOff 127641395 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:11:38 AM 127641945 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 127641996 INFO CommsLeaseListener [Thread-71]: 127653014 INFO CommsLeaseListener [Thread-10270]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 127653066 INFO CommsLeaseListener [Thread-10270]: 128241405 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:21:38 AM 128241965 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 128242016 INFO CommsLeaseListener [Thread-71]: 128253034 INFO CommsLeaseListener [Thread-10317]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 128253116 INFO CommsLeaseListener [Thread-10317]: 128841415 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:31:38 AM 128841965 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 128842016 INFO CommsLeaseListener [Thread-71]: 128853034 INFO CommsLeaseListener [Thread-10363]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 128853076 INFO CommsLeaseListener [Thread-10363]: 129441426 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:41:38 AM 129441975 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 129442016 INFO CommsLeaseListener [Thread-71]: 129453034 INFO CommsLeaseListener [Thread-10411]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 129453076 INFO CommsLeaseListener [Thread-10411]: 130039768 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 130039812 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 130041435 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:51:38 AM 130041995 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 130042036 INFO CommsLeaseListener [Thread-71]: 130053054 INFO CommsLeaseListener [Thread-10463]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 130053096 INFO CommsLeaseListener [Thread-10463]: 130641446 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:01:38 AM 130642005 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 130642056 INFO CommsLeaseListener [Thread-71]: 130653074 INFO CommsLeaseListener [Thread-10511]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 130653116 INFO CommsLeaseListener [Thread-10511]: 131241455 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:11:38 AM 131242005 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 131242047 INFO CommsLeaseListener [Thread-71]: 131253064 INFO CommsLeaseListener [Thread-10558]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 131253116 INFO CommsLeaseListener [Thread-10558]: 131841465 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:21:38 AM 131842014 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 131842056 INFO CommsLeaseListener [Thread-71]: 131853074 INFO CommsLeaseListener [Thread-10604]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 131853116 INFO CommsLeaseListener [Thread-10604]: 132441475 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:31:38 AM 132442045 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 132442086 INFO CommsLeaseListener [Thread-71]: 132453104 INFO CommsLeaseListener [Thread-10652]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 132453667 INFO CommsLeaseListener [Thread-10652]: ethOff 133041486 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:41:38 AM 133042038 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 133042077 INFO CommsLeaseListener [Thread-71]: 133053094 INFO CommsLeaseListener [Thread-10700]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 133053136 INFO CommsLeaseListener [Thread-10700]: 133639785 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 133639866 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 133641496 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:51:38 AM 133642065 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 133642116 INFO CommsLeaseListener [Thread-71]: 133653134 INFO CommsLeaseListener [Thread-10752]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 133653697 INFO CommsLeaseListener [Thread-10752]: ethOff 134241506 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:01:38 AM 134242075 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 134242126 INFO CommsLeaseListener [Thread-71]: 134253144 INFO CommsLeaseListener [Thread-10798]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 134253196 INFO CommsLeaseListener [Thread-10798]: 134841516 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:11:38 AM 134842064 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 134842106 INFO CommsLeaseListener [Thread-71]: 134853124 INFO CommsLeaseListener [Thread-10845]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 134853176 INFO CommsLeaseListener [Thread-10845]: 135441525 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:21:38 AM 135442085 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 135442126 INFO CommsLeaseListener [Thread-71]: 135453144 INFO CommsLeaseListener [Thread-10893]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 135453186 INFO CommsLeaseListener [Thread-10893]: 136041535 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:31:38 AM 136042085 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 136042176 INFO CommsLeaseListener [Thread-71]: 136053194 INFO CommsLeaseListener [Thread-10941]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 136053236 INFO CommsLeaseListener [Thread-10941]: 136641546 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:41:38 AM 136642094 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 136642136 INFO CommsLeaseListener [Thread-71]: 136653154 INFO CommsLeaseListener [Thread-10989]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 136653206 INFO CommsLeaseListener [Thread-10989]: 137239806 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 25 threads 137239866 INFO ThreadUtility [Thread-74]: thread: "Thread-11032" alive daemon thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 137241555 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:51:38 AM 137242104 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 137242168 INFO CommsLeaseListener [Thread-71]: 137253184 INFO CommsLeaseListener [Thread-11039]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 137253226 INFO CommsLeaseListener [Thread-11039]: 137841565 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:01:38 AM 137842125 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 137842706 INFO CommsLeaseListener [Thread-71]: ethOn 137853724 INFO CommsLeaseListener [Thread-11087]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 137854287 INFO CommsLeaseListener [Thread-11087]: ethOff 138441576 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:11:38 AM 138442145 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 138442196 INFO CommsLeaseListener [Thread-71]: 138453214 INFO CommsLeaseListener [Thread-11134]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 138453256 INFO CommsLeaseListener [Thread-11134]: 139041585 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:21:38 AM 139042144 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 139042186 INFO CommsLeaseListener [Thread-71]: 139053204 INFO CommsLeaseListener [Thread-11182]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 139053256 INFO CommsLeaseListener [Thread-11182]: 139641596 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:31:38 AM 139642144 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 139642186 INFO CommsLeaseListener [Thread-71]: 139653204 INFO CommsLeaseListener [Thread-11229]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 139653246 INFO CommsLeaseListener [Thread-11229]: 140241605 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:41:39 AM 140242165 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 140242216 INFO CommsLeaseListener [Thread-71]: 140253234 INFO CommsLeaseListener [Thread-11276]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 140253286 INFO CommsLeaseListener [Thread-11276]: 140839815 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 140839839 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 140841616 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:51:39 AM 140842175 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 140842226 INFO CommsLeaseListener [Thread-71]: 140853244 INFO CommsLeaseListener [Thread-11328]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 140853286 INFO CommsLeaseListener [Thread-11328]: 141441625 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:01:39 AM 141442175 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 141442736 INFO CommsLeaseListener [Thread-71]: ethOn 141453754 INFO CommsLeaseListener [Thread-11375]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 141453816 INFO CommsLeaseListener [Thread-11375]: 142041635 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:11:39 AM 142042195 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 142042246 INFO CommsLeaseListener [Thread-71]: 142053265 INFO CommsLeaseListener [Thread-11423]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 142053336 INFO CommsLeaseListener [Thread-11423]: 142641645 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:21:39 AM 142642205 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 142642246 INFO CommsLeaseListener [Thread-71]: 142653264 INFO CommsLeaseListener [Thread-11470]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 142653316 INFO CommsLeaseListener [Thread-11470]: 143241655 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:31:39 AM 143242205 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 143242256 INFO CommsLeaseListener [Thread-71]: 143253274 INFO CommsLeaseListener [Thread-11517]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 143253316 INFO CommsLeaseListener [Thread-11517]: 143841665 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:41:39 AM 143842214 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 143842256 INFO CommsLeaseListener [Thread-71]: 143853274 INFO CommsLeaseListener [Thread-11565]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 143853316 INFO CommsLeaseListener [Thread-11565]: 144439825 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 144439890 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 144441676 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 10:51:39 AM 144442235 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 144442286 INFO CommsLeaseListener [Thread-71]: 144453304 INFO CommsLeaseListener [Thread-11617]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 144453346 INFO CommsLeaseListener [Thread-11617]: 145041685 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:01:39 AM 145042235 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 145042276 INFO CommsLeaseListener [Thread-71]: 145053294 INFO CommsLeaseListener [Thread-11664]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 145053336 INFO CommsLeaseListener [Thread-11664]: 145641695 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:11:39 AM 145642245 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 145642295 INFO CommsLeaseListener [Thread-71]: 145653314 INFO CommsLeaseListener [Thread-11710]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 145653356 INFO CommsLeaseListener [Thread-11710]: 146241705 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:21:39 AM 146242255 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 146242295 INFO CommsLeaseListener [Thread-71]: 146253314 INFO CommsLeaseListener [Thread-11758]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 146253356 INFO CommsLeaseListener [Thread-11758]: 146841715 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:31:39 AM 146842265 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 146842353 INFO CommsLeaseListener [Thread-71]: 146853374 INFO CommsLeaseListener [Thread-11806]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 146853416 INFO CommsLeaseListener [Thread-11806]: 147441725 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:41:39 AM 147442295 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 147442336 INFO CommsLeaseListener [Thread-71]: 147453354 INFO CommsLeaseListener [Thread-11854]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 147453406 INFO CommsLeaseListener [Thread-11854]: 148039835 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 148039942 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 148041735 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 11:51:39 AM 148042285 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 148042326 INFO CommsLeaseListener [Thread-71]: 148053344 INFO CommsLeaseListener [Thread-11906]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 148053386 INFO CommsLeaseListener [Thread-11906]: 148641745 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:01:39 PM 148642295 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 148642346 INFO CommsLeaseListener [Thread-71]: 148653364 INFO CommsLeaseListener [Thread-11951]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 148653416 INFO CommsLeaseListener [Thread-11951]: 149241755 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:11:39 PM 149242325 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 149242366 INFO CommsLeaseListener [Thread-71]: 149253384 INFO CommsLeaseListener [Thread-11999]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 149253426 INFO CommsLeaseListener [Thread-11999]: 149841765 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:21:39 PM 149842325 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 149842376 INFO CommsLeaseListener [Thread-71]: 149853394 INFO CommsLeaseListener [Thread-12047]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 149853436 INFO CommsLeaseListener [Thread-12047]: 150441775 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:31:39 PM 150442325 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 150442376 INFO CommsLeaseListener [Thread-71]: 150453394 INFO CommsLeaseListener [Thread-12095]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 150453436 INFO CommsLeaseListener [Thread-12095]: 151041785 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:41:39 PM 151042334 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 151042376 INFO CommsLeaseListener [Thread-71]: 151053394 INFO CommsLeaseListener [Thread-12142]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 151053446 INFO CommsLeaseListener [Thread-12142]: 151639845 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 151639866 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 151641796 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 12:51:39 PM 151642344 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 151642386 INFO CommsLeaseListener [Thread-71]: 151653404 INFO CommsLeaseListener [Thread-12193]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 151653456 INFO CommsLeaseListener [Thread-12193]: 152241806 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:01:39 PM 152242355 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 152242396 INFO CommsLeaseListener [Thread-71]: 152253414 INFO CommsLeaseListener [Thread-12240]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 152253456 INFO CommsLeaseListener [Thread-12240]: 152841815 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:11:39 PM 152842384 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 152842426 INFO CommsLeaseListener [Thread-71]: 152853444 INFO CommsLeaseListener [Thread-12288]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 152854007 INFO CommsLeaseListener [Thread-12288]: ethOff 153441826 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:21:39 PM 153442374 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 153442966 INFO CommsLeaseListener [Thread-71]: ethOn 153453984 INFO CommsLeaseListener [Thread-12336]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 153454027 INFO CommsLeaseListener [Thread-12336]: 154041836 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:31:39 PM 154042405 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 154042446 INFO CommsLeaseListener [Thread-71]: 154053464 INFO CommsLeaseListener [Thread-12383]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 154053506 INFO CommsLeaseListener [Thread-12383]: 154641846 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:41:39 PM 154642435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 154642486 INFO CommsLeaseListener [Thread-71]: 154653504 INFO CommsLeaseListener [Thread-12430]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 154653546 INFO CommsLeaseListener [Thread-12430]: 155239855 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 155239912 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 155241855 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 1:51:39 PM 155242414 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 155242456 INFO CommsLeaseListener [Thread-71]: 155253474 INFO CommsLeaseListener [Thread-12482]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 155253516 INFO CommsLeaseListener [Thread-12482]: 155841866 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:01:39 PM 155842435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 155842486 INFO CommsLeaseListener [Thread-71]: 155853504 INFO CommsLeaseListener [Thread-12529]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 155853556 INFO CommsLeaseListener [Thread-12529]: 156441876 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:11:39 PM 156442435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 156442486 INFO CommsLeaseListener [Thread-71]: 156453504 INFO CommsLeaseListener [Thread-12577]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 156453556 INFO CommsLeaseListener [Thread-12577]: 157041885 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:21:39 PM 157042435 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 157042486 INFO CommsLeaseListener [Thread-71]: 157053504 INFO CommsLeaseListener [Thread-12623]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 157053546 INFO CommsLeaseListener [Thread-12623]: 157641895 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:31:39 PM 157642455 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 157642496 INFO CommsLeaseListener [Thread-71]: 157653514 INFO CommsLeaseListener [Thread-12671]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 157653566 INFO CommsLeaseListener [Thread-12671]: 158241905 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:41:39 PM 158242465 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 158242516 INFO CommsLeaseListener [Thread-71]: 158253534 INFO CommsLeaseListener [Thread-12719]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 158253586 INFO CommsLeaseListener [Thread-12719]: 158839865 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 158839889 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 158841916 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 2:51:39 PM 158842464 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 158842506 INFO CommsLeaseListener [Thread-71]: 158853524 INFO CommsLeaseListener [Thread-12771]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 158853576 INFO CommsLeaseListener [Thread-12771]: 159441926 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:01:39 PM 159442485 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 159442536 INFO CommsLeaseListener [Thread-71]: 159453555 INFO CommsLeaseListener [Thread-12818]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 159453606 INFO CommsLeaseListener [Thread-12818]: 160041935 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:11:39 PM 160042485 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 160042536 INFO CommsLeaseListener [Thread-71]: 160053554 INFO CommsLeaseListener [Thread-12864]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 160053596 INFO CommsLeaseListener [Thread-12864]: 160641945 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:21:39 PM 160642494 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 160642536 INFO CommsLeaseListener [Thread-71]: 160653554 INFO CommsLeaseListener [Thread-12912]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 160653607 INFO CommsLeaseListener [Thread-12912]: 161241955 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:31:39 PM 161242504 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 161242546 INFO CommsLeaseListener [Thread-71]: 161253564 INFO CommsLeaseListener [Thread-12960]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 161253616 INFO CommsLeaseListener [Thread-12960]: 161841965 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:41:39 PM 161842525 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 161842566 INFO CommsLeaseListener [Thread-71]: 161853584 INFO CommsLeaseListener [Thread-13008]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 161853626 INFO CommsLeaseListener [Thread-13008]: 162439875 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 162439937 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 162441975 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 3:51:39 PM 162442524 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 162442566 INFO CommsLeaseListener [Thread-71]: 162453584 INFO CommsLeaseListener [Thread-13059]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 162453636 INFO CommsLeaseListener [Thread-13059]: 163041985 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:01:39 PM 163042534 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 163043137 INFO CommsLeaseListener [Thread-71]: ethOn 163054154 INFO CommsLeaseListener [Thread-13105]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 163054196 INFO CommsLeaseListener [Thread-13105]: 163641995 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:11:39 PM 163642544 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 163642586 INFO CommsLeaseListener [Thread-71]: 163653604 INFO CommsLeaseListener [Thread-13153]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 163653657 INFO CommsLeaseListener [Thread-13153]: 164242005 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:21:39 PM 164242554 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 164242596 INFO CommsLeaseListener [Thread-71]: 164253614 INFO CommsLeaseListener [Thread-13201]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 164253656 INFO CommsLeaseListener [Thread-13201]: 164842016 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:31:39 PM 164842575 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 164842616 INFO CommsLeaseListener [Thread-71]: 164853634 INFO CommsLeaseListener [Thread-13249]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 164853676 INFO CommsLeaseListener [Thread-13249]: 165442026 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:41:39 PM 165442584 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 165442626 INFO CommsLeaseListener [Thread-71]: 165453644 INFO CommsLeaseListener [Thread-13296]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 165453696 INFO CommsLeaseListener [Thread-13296]: 166039885 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 166039946 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 166042036 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 4:51:39 PM 166042584 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 166042626 INFO CommsLeaseListener [Thread-71]: 166053644 INFO CommsLeaseListener [Thread-13347]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 166053707 INFO CommsLeaseListener [Thread-13347]: 166642045 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:01:39 PM 166642594 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 166642636 INFO CommsLeaseListener [Thread-71]: 166653654 INFO CommsLeaseListener [Thread-13394]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 166653696 INFO CommsLeaseListener [Thread-13394]: 167242056 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:11:39 PM 167242625 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 167242676 INFO CommsLeaseListener [Thread-71]: 167253694 INFO CommsLeaseListener [Thread-13442]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 167253736 INFO CommsLeaseListener [Thread-13442]: 167842065 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:21:39 PM 167842615 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 167842706 INFO CommsLeaseListener [Thread-71]: 167853724 INFO CommsLeaseListener [Thread-13490]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 167854297 INFO CommsLeaseListener [Thread-13490]: ethOff 168442075 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:31:39 PM 168442625 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 168442676 INFO CommsLeaseListener [Thread-71]: 168453695 INFO CommsLeaseListener [Thread-13536]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 168453736 INFO CommsLeaseListener [Thread-13536]: 169042086 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:41:39 PM 169042675 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 169042716 INFO CommsLeaseListener [Thread-71]: 169053734 INFO CommsLeaseListener [Thread-13584]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 169053786 INFO CommsLeaseListener [Thread-13584]: 169639895 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 169639916 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 169642096 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 5:51:39 PM 169642705 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 169642755 INFO CommsLeaseListener [Thread-71]: 169653774 INFO CommsLeaseListener [Thread-13635]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 169653816 INFO CommsLeaseListener [Thread-13635]: 170242105 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:01:39 PM 170242654 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 170242697 INFO CommsLeaseListener [Thread-71]: 170253714 INFO CommsLeaseListener [Thread-13683]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 170253766 INFO CommsLeaseListener [Thread-13683]: 170842116 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:11:39 PM 170842675 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 170842726 INFO CommsLeaseListener [Thread-71]: 170853744 INFO CommsLeaseListener [Thread-13730]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 170853786 INFO CommsLeaseListener [Thread-13730]: 171442126 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:21:39 PM 171442685 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 171442736 INFO CommsLeaseListener [Thread-71]: 171453754 INFO CommsLeaseListener [Thread-13777]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 171453797 INFO CommsLeaseListener [Thread-13777]: 172042136 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:31:39 PM 172042695 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 172042746 INFO CommsLeaseListener [Thread-71]: 172053764 INFO CommsLeaseListener [Thread-13825]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 172053856 INFO CommsLeaseListener [Thread-13825]: 172642145 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:41:39 PM 172642695 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 172642783 INFO CommsLeaseListener [Thread-71]: 172653804 INFO CommsLeaseListener [Thread-13873]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 172653847 INFO CommsLeaseListener [Thread-13873]: 173239905 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 173239967 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 173242155 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 6:51:39 PM 173242704 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 173242746 INFO CommsLeaseListener [Thread-71]: 173253764 INFO CommsLeaseListener [Thread-13924]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 173253806 INFO CommsLeaseListener [Thread-13924]: 173842165 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:01:39 PM 173842725 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 173842766 INFO CommsLeaseListener [Thread-71]: 173853784 INFO CommsLeaseListener [Thread-13971]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 173853826 INFO CommsLeaseListener [Thread-13971]: 174442176 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:11:39 PM 174442725 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 174442776 INFO CommsLeaseListener [Thread-71]: 174453794 INFO CommsLeaseListener [Thread-14018]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 174453837 INFO CommsLeaseListener [Thread-14018]: 175042185 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:21:39 PM 175042755 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 175042806 INFO CommsLeaseListener [Thread-71]: 175053824 INFO CommsLeaseListener [Thread-14066]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 175053866 INFO CommsLeaseListener [Thread-14066]: 175642196 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:31:39 PM 175642755 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 175642806 INFO CommsLeaseListener [Thread-71]: 175653824 INFO CommsLeaseListener [Thread-14114]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 175653866 INFO CommsLeaseListener [Thread-14114]: 176242206 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:41:39 PM 176242771 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 176242816 INFO CommsLeaseListener [Thread-71]: 176253834 INFO CommsLeaseListener [Thread-14161]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 176253876 INFO CommsLeaseListener [Thread-14161]: 176839915 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 176839982 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 176842215 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 7:51:39 PM 176842765 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 176842816 INFO CommsLeaseListener [Thread-71]: 176853834 INFO CommsLeaseListener [Thread-14211]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 176854427 INFO CommsLeaseListener [Thread-14211]: ethOff 177442225 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:01:39 PM 177442775 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 177442816 INFO CommsLeaseListener [Thread-71]: 177453834 INFO CommsLeaseListener [Thread-14259]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 177453885 INFO CommsLeaseListener [Thread-14259]: 178042235 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:11:39 PM 178042785 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 178042826 INFO CommsLeaseListener [Thread-71]: 178053844 INFO CommsLeaseListener [Thread-14307]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 178053886 INFO CommsLeaseListener [Thread-14307]: 178642245 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:21:39 PM 178642795 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 178642846 INFO CommsLeaseListener [Thread-71]: 178653864 INFO CommsLeaseListener [Thread-14355]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 178653916 INFO CommsLeaseListener [Thread-14355]: 179242255 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:31:39 PM 179242815 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 179242865 INFO CommsLeaseListener [Thread-71]: 179253884 INFO CommsLeaseListener [Thread-14402]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 179253927 INFO CommsLeaseListener [Thread-14402]: 179842266 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:41:39 PM 179842835 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 179842876 INFO CommsLeaseListener [Thread-71]: 179853894 INFO CommsLeaseListener [Thread-14448]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 179853936 INFO CommsLeaseListener [Thread-14448]: 180439925 INFO ThreadUtility [Thread-74]: ThreadGroup "main" includes about 24 threads 180440063 INFO ThreadUtility [Thread-74]: thread: "RMI-ServerConnection:127.0.0.1" alive daemon thread: "Thread-242" alive interrupted daemon thread: "Thread-74" alive thread: "Thread-72" alive thread: "Thread-71" alive thread: "Thread-70" alive thread: "Thread-67" alive daemon thread: "Thread-39" alive thread: "Thread-26" alive thread: "Thread-22" alive thread: "RMI-Leaser" alive daemon thread: "RMI-ConnectionGC" alive daemon thread: "RMI-Accept:1099" alive daemon thread: "Thread-8" alive thread: "Thread-6" alive thread: "Thread-5" alive thread: "Thread-4" alive thread: "RMI-Accept:1025" alive daemon thread: "RMI-DGC" alive thread: "RMI-Ref GC" alive daemon thread: "Thread-3" alive thread: "Thread-2" alive thread: "Thread-1" alive 180442276 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 8:51:39 PM 180442844 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 180442886 INFO CommsLeaseListener [Thread-71]: 180453904 INFO CommsLeaseListener [Thread-14500]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 180453956 INFO CommsLeaseListener [Thread-14500]: 180916296 ERROR PortManager [RMI-ServerConnection:127.0.0.1]: getPortByName() - no port matching /dev/ttyySX15 181042285 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:01:39 PM 181042835 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 181042916 INFO CommsLeaseListener [Thread-71]: 181053934 INFO CommsLeaseListener [Thread-14548]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 181053986 INFO CommsLeaseListener [Thread-14548]: 181642296 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:11:39 PM 181642875 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 181642916 INFO CommsLeaseListener [Thread-71]: 181653934 INFO CommsLeaseListener [Thread-14596]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 181653976 INFO CommsLeaseListener [Thread-14596]: 182242305 INFO CommsSchedulerTask [Thread-71]: CommsSchedulerTask.run(): Oct 12, 2015 9:21:39 PM 182242865 INFO CommsLeaseListener [Thread-71]: Calling SyncProcessRunner("echo ethOn"); attempt #0 182242906 INFO CommsLeaseListener [Thread-71]: 182253924 INFO CommsLeaseListener [Thread-14642]: SyncProcessRunner.exec("echo ethOff"), connect time = 11 182253976 INFO CommsLeaseListener [Thread-14642]: