2018-12-18T21:48:20.613Z,1545169700.613 [CommandLine](IMPORTANT): got command restart logs 2018-12-18T21:48:21.663Z,1545169701.663 [NAL9602](INFO): GPS fix at 20181218T214819: (36.804486, -121.793480) 2018-12-18T21:48:21.759Z,1545169701.759 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T21:48:21.760Z,1545169701.760 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T21:48:29.829Z,1545169709.829 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T184421/Courier0034.lzma 2018-12-18T21:48:30.632Z,1545169710.632 [DataOverHttps](INFO): Moved sent file to Logs/20181218T184421/Courier0034.lzma.bak 2018-12-18T21:48:30.632Z,1545169710.632 [DataOverHttps](INFO): SBD MOMSN=9086453 2018-12-18T21:48:40.001Z,1545169720.001 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0000.lzma 2018-12-18T21:48:40.775Z,1545169720.775 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0000.lzma.bak 2018-12-18T21:48:40.775Z,1545169720.775 [DataOverHttps](INFO): SBD MOMSN=9086455 2018-12-18T21:48:49.833Z,1545169729.833 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T21:48:49.833Z,1545169729.833 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-18T21:48:50.205Z,1545169730.205 [Rowe_600LCM](INFO): Initializing 2018-12-18T21:48:50.205Z,1545169730.205 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T21:48:50.206Z,1545169730.206 [Rowe_600LCM](INFO): LCM OK 2018-12-18T21:48:50.206Z,1545169730.206 [Rowe_600LCM](INFO): Powering up 2018-12-18T21:48:50.247Z,1545169730.247 [DataOverHttps](INFO): Sending 270 bytes from file Logs/20181218T184421/Express0035.lzma 2018-12-18T21:48:51.043Z,1545169731.043 [DataOverHttps](INFO): Moved sent file to Logs/20181218T184421/Express0035.lzma.bak 2018-12-18T21:48:51.043Z,1545169731.043 [DataOverHttps](INFO): SBD MOMSN=9086458 2018-12-18T21:48:54.400Z,1545169734.400 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T21:48:54.508Z,1545169734.508 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T21:48:54.509Z,1545169734.509 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T21:48:54.510Z,1545169734.510 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T21:48:54.511Z,1545169734.511 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T21:49:01.469Z,1545169741.469 [NAL9602](INFO): Powering down 2018-12-18T21:49:01.599Z,1545169741.599 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Express0001.lzma 2018-12-18T21:49:02.391Z,1545169742.391 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0001.lzma.bak 2018-12-18T21:49:02.391Z,1545169742.391 [DataOverHttps](INFO): SBD MOMSN=9086466 2018-12-18T21:49:02.904Z,1545169742.904 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T21:49:02.904Z,1545169742.904 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T21:49:02.905Z,1545169742.905 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T21:50:50.805Z,1545169850.805 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T21:50:50.805Z,1545169850.805 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-18T21:50:50.805Z,1545169850.805 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T21:50:50.846Z,1545169850.846 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T21:50:51.209Z,1545169851.209 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T21:50:51.435Z,1545169851.435 [Rowe_600LCM](INFO): Powering down 2018-12-18T21:50:52.837Z,1545169852.837 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T21:50:52.837Z,1545169852.837 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-18T21:50:53.049Z,1545169853.049 [Rowe_600LCM](INFO): Initializing 2018-12-18T21:50:53.049Z,1545169853.049 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T21:50:53.050Z,1545169853.050 [Rowe_600LCM](INFO): LCM OK 2018-12-18T21:50:53.050Z,1545169853.050 [Rowe_600LCM](INFO): Powering up 2018-12-18T21:50:57.253Z,1545169857.253 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T21:50:57.365Z,1545169857.365 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T21:50:57.366Z,1545169857.366 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T21:50:57.367Z,1545169857.367 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T21:50:57.368Z,1545169857.368 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T21:54:03.390Z,1545170043.390 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T21:54:03.391Z,1545170043.391 [Default:CheckIn:C.Wait] Stopped 2018-12-18T21:54:03.391Z,1545170043.391 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T21:54:03.391Z,1545170043.391 [Default:CheckIn:D] Running Loop=1 2018-12-18T21:54:03.790Z,1545170043.790 [Default:CheckIn:D] Stopped 2018-12-18T21:54:03.790Z,1545170043.790 [Default:CheckIn:E] Running Loop=1 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.637520 min 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn:E] Stopped 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn] Stopped 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn](INFO): Running loop #5 2018-12-18T21:54:04.202Z,1545170044.202 [Default:CheckIn] Running Loop=5 2018-12-18T21:54:04.203Z,1545170044.203 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T21:54:04.203Z,1545170044.203 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T21:54:08.202Z,1545170048.202 [NAL9602](INFO): Powering up 2018-12-18T21:54:19.071Z,1545170059.071 [NAL9602](INFO): NAL9602 initialized 2018-12-18T21:54:54.271Z,1545170094.271 [NAL9602](INFO): SBD MO Status=2, MOMSN=10857, MT Status=2, MTMSN=0 2018-12-18T21:54:54.272Z,1545170094.272 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T21:55:14.108Z,1545170114.108 [NAL9602](INFO): SBD MO Status=0, MOMSN=10857, MT Status=0, MTMSN=0 2018-12-18T21:55:14.108Z,1545170114.108 [NAL9602](INFO): No messages in MT queue 2018-12-18T21:55:15.310Z,1545170115.310 [NAL9602](INFO): GPS fix at 20181218T215513: (36.802972, -121.786564) 2018-12-18T21:55:15.371Z,1545170115.371 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T21:55:15.371Z,1545170115.371 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T21:55:20.523Z,1545170120.523 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20181218T214820/Courier0003.lzma 2018-12-18T21:55:21.316Z,1545170121.316 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0003.lzma.bak 2018-12-18T21:55:21.316Z,1545170121.316 [DataOverHttps](INFO): SBD MOMSN=9086497 2018-12-18T21:55:31.108Z,1545170131.108 [DataOverHttps](INFO): Sending 456 bytes from file Logs/20181218T214820/Express0004.lzma 2018-12-18T21:55:31.896Z,1545170131.896 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0004.lzma.bak 2018-12-18T21:55:31.896Z,1545170131.896 [DataOverHttps](INFO): SBD MOMSN=9086500 2018-12-18T21:55:32.372Z,1545170132.372 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T21:55:32.372Z,1545170132.372 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T21:55:32.372Z,1545170132.372 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T21:55:50.666Z,1545170150.666 [NAL9602](INFO): Powering down 2018-12-18T21:56:07.985Z,1545170167.985 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T21:56:07.985Z,1545170167.985 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-18T21:56:07.985Z,1545170167.985 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T21:56:08.369Z,1545170168.369 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T21:56:08.389Z,1545170168.389 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T21:56:08.514Z,1545170168.514 [Rowe_600LCM](INFO): Powering down 2018-12-18T21:56:09.916Z,1545170169.916 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T21:56:09.916Z,1545170169.916 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-18T21:56:10.153Z,1545170170.153 [Rowe_600LCM](INFO): Initializing 2018-12-18T21:56:10.154Z,1545170170.154 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T21:56:10.154Z,1545170170.154 [Rowe_600LCM](INFO): LCM OK 2018-12-18T21:56:10.154Z,1545170170.154 [Rowe_600LCM](INFO): Powering up 2018-12-18T21:56:14.335Z,1545170174.335 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T21:56:14.444Z,1545170174.444 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T21:56:14.446Z,1545170174.446 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T21:56:14.447Z,1545170174.447 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T21:56:14.448Z,1545170174.448 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T21:58:10.705Z,1545170290.705 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T21:58:10.705Z,1545170290.705 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-18T21:58:10.705Z,1545170290.705 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T21:58:10.726Z,1545170290.726 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T21:58:11.109Z,1545170291.109 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T21:58:11.312Z,1545170291.312 [Rowe_600LCM](INFO): Powering down 2018-12-18T21:58:12.704Z,1545170292.704 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T21:58:12.704Z,1545170292.704 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-18T21:58:12.931Z,1545170292.931 [Rowe_600LCM](INFO): Initializing 2018-12-18T21:58:12.931Z,1545170292.931 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T21:58:12.931Z,1545170292.931 [Rowe_600LCM](INFO): LCM OK 2018-12-18T21:58:12.932Z,1545170292.932 [Rowe_600LCM](INFO): Powering up 2018-12-18T21:58:17.048Z,1545170297.048 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T21:58:17.177Z,1545170297.177 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T21:58:17.178Z,1545170297.178 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T21:58:17.179Z,1545170297.179 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T21:58:17.180Z,1545170297.180 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:00:32.781Z,1545170432.781 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:00:32.781Z,1545170432.781 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:00:32.782Z,1545170432.782 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:00:32.782Z,1545170432.782 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:00:33.186Z,1545170433.186 [Default:CheckIn:D] Stopped 2018-12-18T22:00:33.186Z,1545170433.186 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:00:33.592Z,1545170433.592 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.127450 min 2018-12-18T22:00:33.592Z,1545170433.592 [Default:CheckIn:E] Stopped 2018-12-18T22:00:33.597Z,1545170433.597 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:00:33.597Z,1545170433.597 [Default:CheckIn] Stopped 2018-12-18T22:00:33.597Z,1545170433.597 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:00:33.597Z,1545170433.597 [Default:CheckIn](INFO): Running loop #6 2018-12-18T22:00:33.597Z,1545170433.597 [Default:CheckIn] Running Loop=6 2018-12-18T22:00:33.598Z,1545170433.598 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:00:33.598Z,1545170433.598 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:00:37.449Z,1545170437.448 [NAL9602](INFO): Powering up 2018-12-18T22:00:48.419Z,1545170448.419 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:01:12.012Z,1545170472.012 [NAL9602](INFO): SBD MO Status=0, MOMSN=10858, MT Status=0, MTMSN=0 2018-12-18T22:01:12.012Z,1545170472.012 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:01:13.213Z,1545170473.213 [NAL9602](INFO): GPS fix at 20181218T215513: (36.802818, -121.786766) 2018-12-18T22:01:13.270Z,1545170473.270 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:01:13.270Z,1545170473.270 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:01:18.709Z,1545170478.709 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0006.lzma 2018-12-18T22:01:19.507Z,1545170479.507 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0006.lzma.bak 2018-12-18T22:01:19.507Z,1545170479.507 [DataOverHttps](INFO): SBD MOMSN=9086513 2018-12-18T22:01:29.193Z,1545170489.193 [DataOverHttps](INFO): Sending 211 bytes from file Logs/20181218T214820/Express0007.lzma 2018-12-18T22:01:29.972Z,1545170489.972 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0007.lzma.bak 2018-12-18T22:01:29.972Z,1545170489.972 [DataOverHttps](INFO): SBD MOMSN=9086516 2018-12-18T22:01:30.458Z,1545170490.458 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:01:30.458Z,1545170490.458 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:01:30.458Z,1545170490.458 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:01:48.354Z,1545170508.354 [NAL9602](INFO): Powering down 2018-12-18T22:04:48.957Z,1545170688.957 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:04:48.957Z,1545170688.957 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-18T22:04:48.957Z,1545170688.957 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:04:49.070Z,1545170689.070 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:04:49.361Z,1545170689.361 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:04:49.627Z,1545170689.627 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:04:51.029Z,1545170691.029 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:04:51.029Z,1545170691.029 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-18T22:04:51.241Z,1545170691.241 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:04:51.242Z,1545170691.242 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:04:51.242Z,1545170691.242 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:04:51.242Z,1545170691.242 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:04:55.445Z,1545170695.445 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:04:55.569Z,1545170695.569 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:04:55.571Z,1545170695.571 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:04:55.572Z,1545170695.572 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:04:55.573Z,1545170695.573 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:06:31.062Z,1545170791.062 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:06:31.062Z,1545170791.062 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:06:31.063Z,1545170791.063 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:06:31.063Z,1545170791.063 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:06:31.455Z,1545170791.455 [Default:CheckIn:D] Stopped 2018-12-18T22:06:31.455Z,1545170791.455 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:06:31.874Z,1545170791.874 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.098608 min 2018-12-18T22:06:31.874Z,1545170791.874 [Default:CheckIn:E] Stopped 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn] Stopped 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn](INFO): Running loop #7 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn] Running Loop=7 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:06:31.875Z,1545170791.875 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:06:35.918Z,1545170795.918 [NAL9602](INFO): Powering up 2018-12-18T22:06:46.846Z,1545170806.846 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:06:51.809Z,1545170811.809 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:06:51.809Z,1545170811.809 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-18T22:06:51.809Z,1545170811.809 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:06:52.140Z,1545170812.140 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:06:52.140Z,1545170812.140 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-18T22:06:52.213Z,1545170812.213 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:06:52.379Z,1545170812.379 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:06:57.244Z,1545170817.244 [NAL9602](INFO): SBD MO Status=0, MOMSN=10859, MT Status=0, MTMSN=0 2018-12-18T22:06:57.244Z,1545170817.244 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:07:21.646Z,1545170841.646 [NAL9602](INFO): GPS fix at 20181218T220719: (36.802787, -121.786854) 2018-12-18T22:07:21.714Z,1545170841.714 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:07:21.714Z,1545170841.714 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:07:26.075Z,1545170846.075 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0009.lzma 2018-12-18T22:07:26.875Z,1545170846.875 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0009.lzma.bak 2018-12-18T22:07:26.875Z,1545170846.875 [DataOverHttps](INFO): SBD MOMSN=9086558 2018-12-18T22:07:35.704Z,1545170855.704 [DataOverHttps](INFO): Sending 265 bytes from file Logs/20181218T214820/Express0010.lzma 2018-12-18T22:07:36.495Z,1545170856.495 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0010.lzma.bak 2018-12-18T22:07:36.495Z,1545170856.495 [DataOverHttps](INFO): SBD MOMSN=9086561 2018-12-18T22:07:36.984Z,1545170856.984 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:07:36.984Z,1545170856.984 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:07:36.984Z,1545170856.984 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:07:56.262Z,1545170876.262 [NAL9602](INFO): Powering down 2018-12-18T22:12:37.350Z,1545171157.350 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:12:37.350Z,1545171157.350 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:12:37.350Z,1545171157.350 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:12:37.351Z,1545171157.351 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:12:37.758Z,1545171157.758 [Default:CheckIn:D] Stopped 2018-12-18T22:12:37.758Z,1545171157.758 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:12:38.162Z,1545171158.162 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.203654 min 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn:E] Stopped 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn] Stopped 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn](INFO): Running loop #8 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn] Running Loop=8 2018-12-18T22:12:38.163Z,1545171158.163 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:12:38.164Z,1545171158.164 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:12:41.358Z,1545171161.358 [NAL9602](INFO): Powering up 2018-12-18T22:12:52.523Z,1545171172.523 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:13:20.920Z,1545171200.920 [NAL9602](INFO): SBD MO Status=2, MOMSN=10860, MT Status=2, MTMSN=0 2018-12-18T22:13:20.920Z,1545171200.920 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T22:14:19.003Z,1545171259.003 [NAL9602](INFO): SBD MO Status=2, MOMSN=10860, MT Status=2, MTMSN=0 2018-12-18T22:14:19.004Z,1545171259.004 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T22:14:47.140Z,1545171287.140 [NAL9602](INFO): SBD MO Status=2, MOMSN=10860, MT Status=2, MTMSN=0 2018-12-18T22:14:47.140Z,1545171287.140 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T22:15:06.340Z,1545171306.340 [NAL9602](INFO): SBD MO Status=0, MOMSN=10860, MT Status=0, MTMSN=0 2018-12-18T22:15:06.340Z,1545171306.340 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:15:07.542Z,1545171307.542 [NAL9602](INFO): GPS fix at 20181218T221505: (36.802818, -121.786882) 2018-12-18T22:15:07.592Z,1545171307.592 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:15:07.593Z,1545171307.593 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:15:11.953Z,1545171311.953 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0012.lzma 2018-12-18T22:15:12.751Z,1545171312.751 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0012.lzma.bak 2018-12-18T22:15:12.751Z,1545171312.751 [DataOverHttps](INFO): SBD MOMSN=9086599 2018-12-18T22:15:21.601Z,1545171321.601 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181218T214820/Express0013.lzma 2018-12-18T22:15:22.391Z,1545171322.391 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0013.lzma.bak 2018-12-18T22:15:22.392Z,1545171322.392 [DataOverHttps](INFO): SBD MOMSN=9086602 2018-12-18T22:15:22.876Z,1545171322.876 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:15:22.876Z,1545171322.876 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:15:22.876Z,1545171322.876 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:15:42.170Z,1545171342.170 [NAL9602](INFO): Powering down 2018-12-18T22:16:51.987Z,1545171411.987 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:16:51.987Z,1545171411.987 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-18T22:16:52.225Z,1545171412.225 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:16:52.225Z,1545171412.225 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:16:52.225Z,1545171412.225 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:16:52.226Z,1545171412.226 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:16:56.398Z,1545171416.398 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:16:56.534Z,1545171416.534 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:16:56.535Z,1545171416.535 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:16:56.536Z,1545171416.536 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:16:56.538Z,1545171416.538 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:20:23.515Z,1545171623.515 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:20:23.515Z,1545171623.515 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:20:23.515Z,1545171623.515 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:20:23.516Z,1545171623.516 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:20:23.962Z,1545171623.962 [Default:CheckIn:D] Stopped 2018-12-18T22:20:23.962Z,1545171623.962 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.973726 min 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn:E] Stopped 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn] Stopped 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn](INFO): Running loop #9 2018-12-18T22:20:31.970Z,1545171631.970 [Default:CheckIn] Running Loop=9 2018-12-18T22:20:31.971Z,1545171631.971 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:20:31.971Z,1545171631.971 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:20:32.410Z,1545171632.410 [NAL9602](INFO): Powering up 2018-12-18T22:20:43.610Z,1545171643.610 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:21:02.812Z,1545171662.812 [NAL9602](INFO): SBD MO Status=0, MOMSN=10861, MT Status=0, MTMSN=0 2018-12-18T22:21:02.812Z,1545171662.812 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:21:32.083Z,1545171692.083 [NAL9602](INFO): GPS fix at 20181218T222131: (36.802749, -121.786867) 2018-12-18T22:21:32.187Z,1545171692.187 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:21:32.187Z,1545171692.187 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:21:40.718Z,1545171700.718 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0015.lzma 2018-12-18T22:21:41.516Z,1545171701.516 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0015.lzma.bak 2018-12-18T22:21:41.517Z,1545171701.517 [DataOverHttps](INFO): SBD MOMSN=9086612 2018-12-18T22:21:58.166Z,1545171718.166 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181218T214820/Express0016.lzma 2018-12-18T22:21:58.965Z,1545171718.965 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0016.lzma.bak 2018-12-18T22:21:58.965Z,1545171718.965 [DataOverHttps](INFO): SBD MOMSN=9086615 2018-12-18T22:21:59.491Z,1545171719.491 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:21:59.492Z,1545171719.492 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:21:59.492Z,1545171719.492 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:22:08.216Z,1545171728.216 [NAL9602](INFO): Powering down 2018-12-18T22:27:00.075Z,1545172020.075 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:27:00.075Z,1545172020.075 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:27:00.075Z,1545172020.075 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:27:00.076Z,1545172020.076 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:27:00.479Z,1545172020.479 [Default:CheckIn:D] Stopped 2018-12-18T22:27:00.479Z,1545172020.479 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:27:04.277Z,1545172024.277 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.582332 min 2018-12-18T22:27:04.277Z,1545172024.277 [Default:CheckIn:E] Stopped 2018-12-18T22:27:04.277Z,1545172024.277 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:27:04.277Z,1545172024.277 [Default:CheckIn] Stopped 2018-12-18T22:27:04.278Z,1545172024.278 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:27:04.278Z,1545172024.278 [Default:CheckIn](INFO): Running loop #10 2018-12-18T22:27:04.278Z,1545172024.278 [Default:CheckIn] Running Loop=10 2018-12-18T22:27:04.278Z,1545172024.278 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:27:04.278Z,1545172024.278 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:27:04.705Z,1545172024.705 [NAL9602](INFO): Powering up 2018-12-18T22:27:15.902Z,1545172035.902 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:27:32.703Z,1545172052.703 [NAL9602](INFO): SBD MO Status=0, MOMSN=10862, MT Status=0, MTMSN=0 2018-12-18T22:27:32.704Z,1545172052.704 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:27:33.906Z,1545172053.906 [NAL9602](INFO): GPS fix at 20181218T222732: (36.802723, -121.786876) 2018-12-18T22:27:33.966Z,1545172053.966 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:27:33.967Z,1545172053.967 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:27:39.128Z,1545172059.128 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181218T214820/Courier0018.lzma 2018-12-18T22:27:39.919Z,1545172059.919 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0018.lzma.bak 2018-12-18T22:27:39.919Z,1545172059.919 [DataOverHttps](INFO): SBD MOMSN=9086644 2018-12-18T22:27:49.943Z,1545172069.943 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20181218T214820/Express0019.lzma 2018-12-18T22:27:50.743Z,1545172070.743 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0019.lzma.bak 2018-12-18T22:27:50.743Z,1545172070.743 [DataOverHttps](INFO): SBD MOMSN=9086648 2018-12-18T22:27:51.218Z,1545172071.218 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:27:51.219Z,1545172071.218 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:27:51.219Z,1545172071.219 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:28:09.478Z,1545172089.478 [NAL9602](INFO): Powering down 2018-12-18T22:32:45.945Z,1545172365.945 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:32:45.945Z,1545172365.945 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-18T22:32:45.945Z,1545172365.945 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:32:45.973Z,1545172365.973 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:32:46.349Z,1545172366.349 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:32:46.581Z,1545172366.581 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:32:47.973Z,1545172367.973 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:32:47.974Z,1545172367.974 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-18T22:32:48.197Z,1545172368.197 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:32:48.197Z,1545172368.197 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:32:48.198Z,1545172368.198 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:32:48.198Z,1545172368.198 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:32:51.972Z,1545172371.972 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:32:51.972Z,1545172371.972 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:32:51.972Z,1545172371.972 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:32:51.972Z,1545172371.972 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:32:52.384Z,1545172372.384 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:32:52.435Z,1545172372.435 [Default:CheckIn:D] Stopped 2018-12-18T22:32:52.435Z,1545172372.435 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:32:52.529Z,1545172372.529 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:32:52.531Z,1545172372.531 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:32:52.532Z,1545172372.532 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:32:52.533Z,1545172372.533 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:32:52.805Z,1545172372.805 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 72.448275 min 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn:E] Stopped 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn] Stopped 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn](INFO): Running loop #11 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn] Running Loop=11 2018-12-18T22:32:52.806Z,1545172372.806 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:32:52.807Z,1545172372.807 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:32:57.798Z,1545172377.798 [NAL9602](INFO): Powering up 2018-12-18T22:33:08.978Z,1545172388.978 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:33:32.171Z,1545172412.171 [NAL9602](INFO): SBD MO Status=2, MOMSN=10863, MT Status=2, MTMSN=0 2018-12-18T22:33:32.172Z,1545172412.172 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T22:33:41.771Z,1545172421.771 [NAL9602](INFO): SBD MO Status=0, MOMSN=10863, MT Status=0, MTMSN=0 2018-12-18T22:33:41.772Z,1545172421.772 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:33:42.974Z,1545172422.974 [NAL9602](INFO): GPS fix at 20181218T223342: (36.802784, -121.786967) 2018-12-18T22:33:43.051Z,1545172423.051 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:33:43.052Z,1545172423.052 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:33:47.956Z,1545172427.956 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0021.lzma 2018-12-18T22:33:48.752Z,1545172428.752 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0021.lzma.bak 2018-12-18T22:33:48.752Z,1545172428.752 [DataOverHttps](INFO): SBD MOMSN=9086652 2018-12-18T22:33:58.878Z,1545172438.878 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20181218T214820/Express0022.lzma 2018-12-18T22:33:59.675Z,1545172439.675 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0022.lzma.bak 2018-12-18T22:33:59.675Z,1545172439.675 [DataOverHttps](INFO): SBD MOMSN=9086655 2018-12-18T22:34:00.144Z,1545172440.144 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:34:00.144Z,1545172440.144 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:34:00.144Z,1545172440.144 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:34:18.191Z,1545172458.191 [NAL9602](INFO): Powering down 2018-12-18T22:37:53.645Z,1545172673.645 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:37:53.645Z,1545172673.645 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-18T22:37:53.645Z,1545172673.645 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:37:53.736Z,1545172673.736 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:37:54.051Z,1545172674.051 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:37:54.261Z,1545172674.261 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:37:55.713Z,1545172675.713 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:37:55.714Z,1545172675.714 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-18T22:37:55.877Z,1545172675.877 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:37:55.877Z,1545172675.877 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:37:55.878Z,1545172675.878 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:37:55.878Z,1545172675.878 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:38:00.002Z,1545172680.002 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:38:00.116Z,1545172680.116 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:38:00.118Z,1545172680.118 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:38:00.119Z,1545172680.119 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:38:00.120Z,1545172680.120 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:39:00.889Z,1545172740.889 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:39:00.889Z,1545172740.889 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:39:00.889Z,1545172740.889 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:39:00.890Z,1545172740.890 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:39:01.278Z,1545172741.278 [Default:CheckIn:D] Stopped 2018-12-18T22:39:01.278Z,1545172741.278 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:39:01.671Z,1545172741.671 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 78.595646 min 2018-12-18T22:39:01.671Z,1545172741.671 [Default:CheckIn:E] Stopped 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn] Stopped 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn](INFO): Running loop #12 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn] Running Loop=12 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:39:01.672Z,1545172741.672 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:39:05.244Z,1545172745.244 [NAL9602](INFO): Powering up 2018-12-18T22:39:16.411Z,1545172756.411 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:39:31.211Z,1545172771.211 [NAL9602](INFO): SBD MO Status=0, MOMSN=10864, MT Status=0, MTMSN=0 2018-12-18T22:39:31.212Z,1545172771.212 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:39:32.414Z,1545172772.414 [NAL9602](INFO): GPS fix at 20181218T223930: (36.802779, -121.786941) 2018-12-18T22:39:32.502Z,1545172772.502 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:39:32.503Z,1545172772.503 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:39:37.551Z,1545172777.551 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0024.lzma 2018-12-18T22:39:38.343Z,1545172778.343 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0024.lzma.bak 2018-12-18T22:39:38.344Z,1545172778.344 [DataOverHttps](INFO): SBD MOMSN=9086694 2018-12-18T22:39:48.390Z,1545172788.390 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20181218T214820/Express0025.lzma 2018-12-18T22:39:49.187Z,1545172789.187 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0025.lzma.bak 2018-12-18T22:39:49.187Z,1545172789.187 [DataOverHttps](INFO): SBD MOMSN=9086697 2018-12-18T22:39:49.666Z,1545172789.666 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:39:49.667Z,1545172789.667 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:39:49.667Z,1545172789.667 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:40:07.534Z,1545172807.534 [NAL9602](INFO): Powering down 2018-12-18T22:41:23.393Z,1545172883.393 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:41:23.393Z,1545172883.393 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-18T22:41:23.393Z,1545172883.393 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:41:23.484Z,1545172883.484 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:41:23.797Z,1545172883.797 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:41:23.990Z,1545172883.990 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:41:24.797Z,1545172884.797 [Rowe_600LCM](FAULT): LCB fault: Software Overcurrent. 2018-12-18T22:41:24.797Z,1545172884.797 [Rowe_600LCM] Hardware Fault, FailCount= 3 2018-12-18T22:41:24.797Z,1545172884.797 [Rowe_600LCM](ERROR): Hardware Fault 2018-12-18T22:41:25.455Z,1545172885.455 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:41:25.456Z,1545172885.456 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-18T22:41:25.605Z,1545172885.605 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:41:25.605Z,1545172885.605 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:41:25.606Z,1545172885.606 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:41:25.606Z,1545172885.606 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:41:29.729Z,1545172889.729 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:41:29.839Z,1545172889.839 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:41:29.840Z,1545172889.840 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:41:29.842Z,1545172889.842 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:41:29.843Z,1545172889.843 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:43:26.149Z,1545173006.149 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:43:26.149Z,1545173006.149 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-18T22:43:26.149Z,1545173006.149 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:43:26.364Z,1545173006.364 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:43:26.553Z,1545173006.553 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:43:26.656Z,1545173006.656 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:43:27.960Z,1545173007.960 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:43:27.961Z,1545173007.961 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-18T22:43:28.273Z,1545173008.273 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:43:28.274Z,1545173008.274 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:43:28.274Z,1545173008.274 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:43:28.274Z,1545173008.274 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:43:32.503Z,1545173012.503 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:43:32.572Z,1545173012.572 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:43:32.574Z,1545173012.574 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:43:32.576Z,1545173012.576 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:43:32.576Z,1545173012.576 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:44:50.309Z,1545173090.309 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:44:50.309Z,1545173090.309 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:44:50.309Z,1545173090.309 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:44:50.310Z,1545173090.310 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:44:50.705Z,1545173090.705 [Default:CheckIn:D] Stopped 2018-12-18T22:44:50.705Z,1545173090.705 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 84.419425 min 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn:E] Stopped 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn] Stopped 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn](INFO): Running loop #13 2018-12-18T22:44:51.115Z,1545173091.115 [Default:CheckIn] Running Loop=13 2018-12-18T22:44:51.116Z,1545173091.116 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:44:51.116Z,1545173091.116 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:44:54.866Z,1545173094.866 [NAL9602](INFO): Powering up 2018-12-18T22:45:06.042Z,1545173106.042 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:45:40.848Z,1545173140.848 [NAL9602](INFO): SBD MO Status=0, MOMSN=10865, MT Status=0, MTMSN=0 2018-12-18T22:45:40.848Z,1545173140.848 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:45:42.046Z,1545173142.046 [NAL9602](INFO): GPS fix at 20181218T224540: (36.802760, -121.786917) 2018-12-18T22:45:42.121Z,1545173142.121 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:45:42.122Z,1545173142.122 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:45:47.002Z,1545173147.002 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181218T214820/Courier0027.lzma 2018-12-18T22:45:47.776Z,1545173147.776 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0027.lzma.bak 2018-12-18T22:45:47.776Z,1545173147.776 [DataOverHttps](INFO): SBD MOMSN=9086730 2018-12-18T22:45:58.089Z,1545173158.089 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20181218T214820/Express0028.lzma 2018-12-18T22:45:58.872Z,1545173158.872 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0028.lzma.bak 2018-12-18T22:45:58.872Z,1545173158.872 [DataOverHttps](INFO): SBD MOMSN=9086734 2018-12-18T22:45:59.370Z,1545173159.370 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:45:59.370Z,1545173159.370 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:45:59.370Z,1545173159.370 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:46:17.210Z,1545173177.210 [NAL9602](INFO): Powering down 2018-12-18T22:46:46.981Z,1545173206.981 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T22:46:46.981Z,1545173206.981 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-18T22:46:46.981Z,1545173206.981 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T22:46:47.274Z,1545173207.274 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T22:46:47.274Z,1545173207.274 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-18T22:46:47.385Z,1545173207.385 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T22:46:47.540Z,1545173207.540 [Rowe_600LCM](INFO): Powering down 2018-12-18T22:50:59.908Z,1545173459.908 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:50:59.908Z,1545173459.908 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:50:59.908Z,1545173459.908 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:50:59.908Z,1545173459.908 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:51:00.319Z,1545173460.319 [Default:CheckIn:D] Stopped 2018-12-18T22:51:00.319Z,1545173460.319 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:51:03.427Z,1545173463.427 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 90.579663 min 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn:E] Stopped 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn] Stopped 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn](INFO): Running loop #14 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn] Running Loop=14 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:51:03.428Z,1545173463.428 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:51:03.860Z,1545173463.860 [NAL9602](INFO): Powering up 2018-12-18T22:51:15.054Z,1545173475.054 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:52:26.663Z,1545173546.663 [NAL9602](INFO): SBD MO Status=0, MOMSN=10866, MT Status=0, MTMSN=0 2018-12-18T22:52:26.664Z,1545173546.664 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:52:27.874Z,1545173547.874 [NAL9602](INFO): GPS fix at 20181218T225226: (36.802752, -121.786910) 2018-12-18T22:52:27.907Z,1545173547.907 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:52:27.907Z,1545173547.907 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:52:32.320Z,1545173552.320 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0030.lzma 2018-12-18T22:52:33.087Z,1545173553.087 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0030.lzma.bak 2018-12-18T22:52:33.087Z,1545173553.087 [DataOverHttps](INFO): SBD MOMSN=9086747 2018-12-18T22:52:42.314Z,1545173562.314 [DataOverHttps](INFO): Sending 239 bytes from file Logs/20181218T214820/Express0031.lzma 2018-12-18T22:52:43.111Z,1545173563.111 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0031.lzma.bak 2018-12-18T22:52:43.111Z,1545173563.111 [DataOverHttps](INFO): SBD MOMSN=9086750 2018-12-18T22:52:43.595Z,1545173563.595 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:52:43.595Z,1545173563.595 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:52:43.596Z,1545173563.596 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:53:02.470Z,1545173582.470 [NAL9602](INFO): Powering down 2018-12-18T22:56:47.868Z,1545173807.868 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T22:56:47.868Z,1545173807.868 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-18T22:56:48.193Z,1545173808.193 [Rowe_600LCM](INFO): Initializing 2018-12-18T22:56:48.193Z,1545173808.193 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T22:56:48.193Z,1545173808.193 [Rowe_600LCM](INFO): LCM OK 2018-12-18T22:56:48.193Z,1545173808.193 [Rowe_600LCM](INFO): Powering up 2018-12-18T22:56:52.433Z,1545173812.433 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T22:56:52.513Z,1545173812.513 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T22:56:52.515Z,1545173812.515 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T22:56:52.516Z,1545173812.516 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T22:56:52.517Z,1545173812.517 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T22:57:44.334Z,1545173864.334 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T22:57:44.334Z,1545173864.334 [Default:CheckIn:C.Wait] Stopped 2018-12-18T22:57:44.335Z,1545173864.335 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T22:57:44.335Z,1545173864.335 [Default:CheckIn:D] Running Loop=1 2018-12-18T22:57:44.751Z,1545173864.751 [Default:CheckIn:D] Stopped 2018-12-18T22:57:44.751Z,1545173864.751 [Default:CheckIn:E] Running Loop=1 2018-12-18T22:57:48.219Z,1545173868.219 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.320199 min 2018-12-18T22:57:48.219Z,1545173868.219 [Default:CheckIn:E] Stopped 2018-12-18T22:57:48.219Z,1545173868.219 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn] Stopped 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn](INFO): Running loop #15 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn] Running Loop=15 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T22:57:48.220Z,1545173868.220 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T22:57:48.662Z,1545173868.662 [NAL9602](INFO): Powering up 2018-12-18T22:57:59.866Z,1545173879.866 [NAL9602](INFO): NAL9602 initialized 2018-12-18T22:58:18.263Z,1545173898.263 [NAL9602](INFO): SBD MO Status=2, MOMSN=10867, MT Status=2, MTMSN=0 2018-12-18T22:58:18.264Z,1545173898.264 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T22:58:29.864Z,1545173909.864 [NAL9602](INFO): SBD MO Status=0, MOMSN=10867, MT Status=0, MTMSN=0 2018-12-18T22:58:29.864Z,1545173909.864 [NAL9602](INFO): No messages in MT queue 2018-12-18T22:58:31.067Z,1545173911.067 [NAL9602](INFO): GPS fix at 20181218T225828: (36.802650, -121.786934) 2018-12-18T22:58:31.170Z,1545173911.170 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T22:58:31.170Z,1545173911.170 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T22:58:36.253Z,1545173916.253 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181218T214820/Courier0033.lzma 2018-12-18T22:58:37.011Z,1545173917.011 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0033.lzma.bak 2018-12-18T22:58:37.011Z,1545173917.011 [DataOverHttps](INFO): SBD MOMSN=9086793 2018-12-18T22:58:47.173Z,1545173927.173 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181218T214820/Express0034.lzma 2018-12-18T22:58:47.959Z,1545173927.959 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0034.lzma.bak 2018-12-18T22:58:47.959Z,1545173927.959 [DataOverHttps](INFO): SBD MOMSN=9086796 2018-12-18T22:58:48.439Z,1545173928.439 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T22:58:48.439Z,1545173928.439 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T22:58:48.439Z,1545173928.439 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T22:59:06.666Z,1545173946.666 [NAL9602](INFO): Powering down 2018-12-18T23:03:48.880Z,1545174228.880 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:03:48.880Z,1545174228.880 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:03:48.880Z,1545174228.880 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:03:48.881Z,1545174228.881 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:03:49.277Z,1545174229.277 [Default:CheckIn:D] Stopped 2018-12-18T23:03:49.277Z,1545174229.277 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.395565 min 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn:E] Stopped 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn] Stopped 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn](INFO): Running loop #16 2018-12-18T23:03:49.659Z,1545174229.659 [Default:CheckIn] Running Loop=16 2018-12-18T23:03:49.660Z,1545174229.660 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:03:49.660Z,1545174229.660 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:03:53.837Z,1545174233.837 [NAL9602](INFO): Powering up 2018-12-18T23:04:04.714Z,1545174244.714 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:05:07.891Z,1545174307.891 [NAL9602](INFO): SBD MO Status=0, MOMSN=10868, MT Status=0, MTMSN=0 2018-12-18T23:05:07.892Z,1545174307.892 [NAL9602](INFO): No messages in MT queue 2018-12-18T23:05:09.098Z,1545174309.098 [NAL9602](INFO): GPS fix at 20181218T230507: (36.802673, -121.786894) 2018-12-18T23:05:09.158Z,1545174309.158 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:05:09.159Z,1545174309.159 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:05:13.939Z,1545174313.939 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181218T214820/Courier0036.lzma 2018-12-18T23:05:14.739Z,1545174314.739 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0036.lzma.bak 2018-12-18T23:05:14.739Z,1545174314.739 [DataOverHttps](INFO): SBD MOMSN=9086800 2018-12-18T23:05:25.296Z,1545174325.296 [DataOverHttps](INFO): Sending 122 bytes from file Logs/20181218T214820/Express0037.lzma 2018-12-18T23:05:26.087Z,1545174326.087 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0037.lzma.bak 2018-12-18T23:05:26.087Z,1545174326.087 [DataOverHttps](INFO): SBD MOMSN=9086803 2018-12-18T23:05:26.653Z,1545174326.653 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:05:26.653Z,1545174326.653 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:05:26.653Z,1545174326.653 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:05:29.425Z,1545174329.425 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:05:29.425Z,1545174329.425 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-18T23:05:29.425Z,1545174329.425 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:05:29.829Z,1545174329.829 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:05:30.006Z,1545174330.006 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:05:30.604Z,1545174330.604 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:05:31.540Z,1545174331.540 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:05:31.540Z,1545174331.540 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-18T23:05:31.621Z,1545174331.621 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:05:31.621Z,1545174331.621 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:05:31.622Z,1545174331.622 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:05:31.622Z,1545174331.622 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:05:35.745Z,1545174335.745 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:05:35.867Z,1545174335.867 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:05:35.868Z,1545174335.868 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:05:35.871Z,1545174335.871 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:05:35.872Z,1545174335.872 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:05:44.218Z,1545174344.218 [NAL9602](INFO): Powering down 2018-12-18T23:07:32.333Z,1545174452.333 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:07:32.333Z,1545174452.333 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-18T23:07:32.333Z,1545174452.333 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:07:32.700Z,1545174452.700 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:07:32.737Z,1545174452.737 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:07:32.854Z,1545174452.854 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:07:34.317Z,1545174454.317 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:07:34.317Z,1545174454.317 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-18T23:07:34.469Z,1545174454.469 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:07:34.469Z,1545174454.469 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:07:34.470Z,1545174454.470 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:07:34.470Z,1545174454.470 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:07:38.590Z,1545174458.590 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:07:38.717Z,1545174458.717 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:07:38.718Z,1545174458.718 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:07:38.719Z,1545174458.719 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:07:38.720Z,1545174458.720 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:10:27.070Z,1545174627.070 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:10:27.071Z,1545174627.071 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:10:27.071Z,1545174627.071 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:10:27.071Z,1545174627.071 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:10:27.492Z,1545174627.492 [Default:CheckIn:D] Stopped 2018-12-18T23:10:27.492Z,1545174627.492 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:10:27.913Z,1545174627.913 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.032544 min 2018-12-18T23:10:27.914Z,1545174627.914 [Default:CheckIn:E] Stopped 2018-12-18T23:10:27.914Z,1545174627.914 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:10:27.914Z,1545174627.914 [Default:CheckIn] Stopped 2018-12-18T23:10:27.915Z,1545174627.915 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:10:27.915Z,1545174627.915 [Default:CheckIn](INFO): Running loop #17 2018-12-18T23:10:27.915Z,1545174627.915 [Default:CheckIn] Running Loop=17 2018-12-18T23:10:27.915Z,1545174627.915 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:10:27.915Z,1545174627.915 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:10:31.630Z,1545174631.630 [NAL9602](INFO): Powering up 2018-12-18T23:10:42.782Z,1545174642.782 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:11:27.994Z,1545174687.994 [NAL9602](INFO): SBD MO Status=2, MOMSN=10869, MT Status=2, MTMSN=0 2018-12-18T23:11:27.994Z,1545174687.994 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T23:11:46.932Z,1545174706.932 [NAL9602](INFO): SBD MO Status=0, MOMSN=10869, MT Status=0, MTMSN=0 2018-12-18T23:11:46.932Z,1545174706.932 [NAL9602](INFO): No messages in MT queue 2018-12-18T23:11:56.936Z,1545174716.936 [NAL9602](INFO): GPS fix at 20181218T231156: (36.802328, -121.787180) 2018-12-18T23:11:56.986Z,1545174716.986 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:11:56.987Z,1545174716.987 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:12:01.960Z,1545174721.960 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181218T214820/Courier0039.lzma 2018-12-18T23:12:02.751Z,1545174722.751 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0039.lzma.bak 2018-12-18T23:12:02.751Z,1545174722.751 [DataOverHttps](INFO): SBD MOMSN=9086846 2018-12-18T23:12:12.780Z,1545174732.780 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20181218T214820/Express0040.lzma 2018-12-18T23:12:13.547Z,1545174733.547 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0040.lzma.bak 2018-12-18T23:12:13.547Z,1545174733.547 [DataOverHttps](INFO): SBD MOMSN=9086849 2018-12-18T23:12:14.046Z,1545174734.046 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:12:14.046Z,1545174734.046 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:12:14.046Z,1545174734.046 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:12:18.993Z,1545174738.993 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:12:18.993Z,1545174738.993 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-18T23:12:18.993Z,1545174738.993 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:12:19.104Z,1545174739.104 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:12:19.397Z,1545174739.397 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:12:19.724Z,1545174739.724 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:12:20.533Z,1545174740.533 [Rowe_600LCM](FAULT): LCB fault: Software Overcurrent. 2018-12-18T23:12:20.533Z,1545174740.533 [Rowe_600LCM] Hardware Fault, FailCount= 3 2018-12-18T23:12:20.533Z,1545174740.533 [Rowe_600LCM](ERROR): Hardware Fault 2018-12-18T23:12:21.113Z,1545174741.113 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:12:21.113Z,1545174741.113 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-18T23:12:21.341Z,1545174741.341 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:12:21.342Z,1545174741.342 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:12:21.342Z,1545174741.342 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:12:21.342Z,1545174741.342 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:12:25.538Z,1545174745.538 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:12:25.660Z,1545174745.660 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:12:25.666Z,1545174745.666 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:12:25.667Z,1545174745.667 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:12:25.668Z,1545174745.668 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:12:32.258Z,1545174752.258 [NAL9602](INFO): Powering down 2018-12-18T23:14:32.061Z,1545174872.061 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:14:32.061Z,1545174872.061 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-18T23:14:32.061Z,1545174872.061 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:14:32.117Z,1545174872.117 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:14:32.465Z,1545174872.465 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:14:32.617Z,1545174872.617 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:14:34.067Z,1545174874.067 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:14:34.067Z,1545174874.067 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-18T23:14:34.233Z,1545174874.233 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:14:34.233Z,1545174874.233 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:14:34.234Z,1545174874.234 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:14:34.234Z,1545174874.234 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:14:38.362Z,1545174878.362 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:14:38.508Z,1545174878.508 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:14:38.509Z,1545174878.509 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:14:38.510Z,1545174878.510 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:14:38.511Z,1545174878.511 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:17:11.709Z,1545175031.709 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:17:11.709Z,1545175031.709 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-18T23:17:11.709Z,1545175031.709 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:17:11.721Z,1545175031.721 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:17:11.722Z,1545175031.722 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-18T23:17:12.113Z,1545175032.113 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:17:12.259Z,1545175032.259 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:17:14.507Z,1545175034.507 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:17:14.508Z,1545175034.508 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:17:14.508Z,1545175034.508 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:17:14.508Z,1545175034.508 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:17:14.908Z,1545175034.908 [Default:CheckIn:D] Stopped 2018-12-18T23:17:14.908Z,1545175034.908 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:17:15.299Z,1545175035.299 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 116.822819 min 2018-12-18T23:17:15.299Z,1545175035.299 [Default:CheckIn:E] Stopped 2018-12-18T23:17:15.299Z,1545175035.299 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:17:15.299Z,1545175035.299 [Default:CheckIn] Stopped 2018-12-18T23:17:15.299Z,1545175035.299 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:17:15.300Z,1545175035.300 [Default:CheckIn](INFO): Running loop #18 2018-12-18T23:17:15.300Z,1545175035.300 [Default:CheckIn] Running Loop=18 2018-12-18T23:17:15.300Z,1545175035.300 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:17:15.300Z,1545175035.300 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:17:18.787Z,1545175038.787 [NAL9602](INFO): Powering up 2018-12-18T23:17:29.666Z,1545175049.666 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:18:18.923Z,1545175098.923 [NAL9602](INFO): SBD MO Status=2, MOMSN=10870, MT Status=2, MTMSN=0 2018-12-18T23:18:18.924Z,1545175098.924 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-12-18T23:22:15.420Z,1545175335.420 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-18T23:17:15.3Z 2018-12-18T23:22:15.420Z,1545175335.420 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:22:15.421Z,1545175335.421 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:22:19.589Z,1545175339.589 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0042.lzma 2018-12-18T23:22:20.387Z,1545175340.387 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0042.lzma.bak 2018-12-18T23:22:20.387Z,1545175340.387 [DataOverHttps](INFO): SBD MOMSN=9086893 2018-12-18T23:22:30.786Z,1545175350.786 [DataOverHttps](INFO): Sending 282 bytes from file Logs/20181218T214820/Express0043.lzma 2018-12-18T23:22:31.571Z,1545175351.571 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0043.lzma.bak 2018-12-18T23:22:31.571Z,1545175351.571 [DataOverHttps](INFO): SBD MOMSN=9086895 2018-12-18T23:22:32.065Z,1545175352.065 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:22:32.065Z,1545175352.065 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:22:32.065Z,1545175352.065 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:22:35.672Z,1545175355.672 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-18T23:23:06.154Z,1545175386.154 [NAL9602](INFO): Powering down 2018-12-18T23:27:11.800Z,1545175631.800 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:27:11.800Z,1545175631.800 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-18T23:27:12.109Z,1545175632.109 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:27:12.109Z,1545175632.109 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:27:12.109Z,1545175632.109 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:27:12.110Z,1545175632.110 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:27:16.349Z,1545175636.349 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:27:16.420Z,1545175636.420 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:27:16.422Z,1545175636.422 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:27:16.423Z,1545175636.423 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:27:16.424Z,1545175636.424 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:27:32.619Z,1545175652.619 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:27:32.619Z,1545175652.619 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:27:32.619Z,1545175652.619 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:27:32.619Z,1545175652.619 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:27:33.083Z,1545175653.083 [Default:CheckIn:D] Stopped 2018-12-18T23:27:33.083Z,1545175653.083 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 127.125732 min 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn:E] Stopped 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn] Stopped 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:27:36.590Z,1545175656.590 [Default:CheckIn](INFO): Running loop #19 2018-12-18T23:27:36.591Z,1545175656.591 [Default:CheckIn] Running Loop=19 2018-12-18T23:27:36.591Z,1545175656.591 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:27:36.591Z,1545175656.591 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:27:37.022Z,1545175657.022 [NAL9602](INFO): Powering up 2018-12-18T23:27:48.214Z,1545175668.214 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:27:49.014Z,1545175669.014 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-18T23:27:49.015Z,1545175669.015 [NAL9602] Data Fault, FailCount= 1 2018-12-18T23:27:49.015Z,1545175669.015 [NAL9602](ERROR): Data Fault 2018-12-18T23:27:49.153Z,1545175669.153 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-18T23:27:49.414Z,1545175669.414 [NAL9602](INFO): Powering down 2018-12-18T23:27:50.296Z,1545175670.296 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-18T23:27:50.298Z,1545175670.298 [NAL9602] No Fault, FailCount= 1 2018-12-18T23:28:19.422Z,1545175699.422 [NAL9602](INFO): Powering up NAL9602 2018-12-18T23:28:30.615Z,1545175710.615 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:32:05.737Z,1545175925.737 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:32:05.737Z,1545175925.737 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-18T23:32:05.737Z,1545175925.737 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:32:06.112Z,1545175926.112 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:32:06.141Z,1545175926.141 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:32:06.246Z,1545175926.246 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:32:07.714Z,1545175927.714 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:32:07.714Z,1545175927.714 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-18T23:32:07.861Z,1545175927.861 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:32:07.861Z,1545175927.861 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:32:07.861Z,1545175927.861 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:32:07.862Z,1545175927.862 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:32:11.989Z,1545175931.989 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:32:12.136Z,1545175932.136 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:32:12.138Z,1545175932.138 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:32:12.139Z,1545175932.139 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:32:12.140Z,1545175932.140 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:32:37.751Z,1545175957.751 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-18T23:27:36.6Z 2018-12-18T23:32:37.751Z,1545175957.751 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:32:37.751Z,1545175957.751 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:32:38.209Z,1545175958.209 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0045.lzma 2018-12-18T23:32:38.988Z,1545175958.988 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0045.lzma.bak 2018-12-18T23:32:38.988Z,1545175958.988 [DataOverHttps](INFO): SBD MOMSN=9086938 2018-12-18T23:32:50.450Z,1545175970.450 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20181218T214820/Express0046.lzma 2018-12-18T23:32:51.247Z,1545175971.247 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0046.lzma.bak 2018-12-18T23:32:51.248Z,1545175971.248 [DataOverHttps](INFO): SBD MOMSN=9086940 2018-12-18T23:32:51.723Z,1545175971.723 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:32:51.723Z,1545175971.723 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:32:51.723Z,1545175971.723 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:33:37.215Z,1545176017.215 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-18T23:34:07.810Z,1545176047.810 [NAL9602](INFO): Powering down 2018-12-18T23:37:52.156Z,1545176272.156 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:37:52.157Z,1545176272.157 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:37:52.157Z,1545176272.157 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:37:52.157Z,1545176272.157 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:37:52.567Z,1545176272.567 [Default:CheckIn:D] Stopped 2018-12-18T23:37:52.567Z,1545176272.567 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:37:52.983Z,1545176272.983 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.450472 min 2018-12-18T23:37:52.983Z,1545176272.983 [Default:CheckIn:E] Stopped 2018-12-18T23:37:52.983Z,1545176272.983 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:37:52.983Z,1545176272.983 [Default:CheckIn] Stopped 2018-12-18T23:37:52.984Z,1545176272.984 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:37:52.984Z,1545176272.984 [Default:CheckIn](INFO): Running loop #20 2018-12-18T23:37:52.984Z,1545176272.984 [Default:CheckIn] Running Loop=20 2018-12-18T23:37:52.984Z,1545176272.984 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:37:52.984Z,1545176272.984 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:37:56.844Z,1545176276.844 [NAL9602](INFO): Powering up 2018-12-18T23:38:07.738Z,1545176287.738 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:38:39.734Z,1545176319.734 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-18T23:38:39.817Z,1545176319.817 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-18T23:38:39.817Z,1545176319.817 [NAL9602] Data Fault, FailCount= 2 2018-12-18T23:38:39.817Z,1545176319.817 [NAL9602](ERROR): Data Fault 2018-12-18T23:38:39.888Z,1545176319.888 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-18T23:38:40.134Z,1545176320.134 [NAL9602](INFO): Powering down 2018-12-18T23:38:41.043Z,1545176321.043 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-18T23:38:41.043Z,1545176321.043 [NAL9602] No Fault, FailCount= 2 2018-12-18T23:39:10.490Z,1545176350.490 [NAL9602](INFO): Powering up NAL9602 2018-12-18T23:39:21.290Z,1545176361.290 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:39:22.091Z,1545176362.091 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-18T23:39:22.091Z,1545176362.091 [NAL9602] Data Fault, FailCount= 3 2018-12-18T23:39:22.091Z,1545176362.091 [NAL9602](ERROR): Data Fault 2018-12-18T23:39:22.178Z,1545176362.178 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-18T23:39:22.491Z,1545176362.491 [NAL9602](INFO): Powering down 2018-12-18T23:39:23.358Z,1545176363.358 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-18T23:39:23.358Z,1545176363.358 [NAL9602] No Fault, FailCount= 3 2018-12-18T23:39:52.891Z,1545176392.891 [NAL9602](INFO): Powering up NAL9602 2018-12-18T23:40:03.806Z,1545176403.806 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:40:45.461Z,1545176445.461 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:40:45.461Z,1545176445.461 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-18T23:40:45.461Z,1545176445.461 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:40:45.845Z,1545176445.845 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:40:45.865Z,1545176445.865 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:40:46.002Z,1545176446.002 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:40:47.428Z,1545176447.428 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:40:47.428Z,1545176447.428 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-18T23:40:47.617Z,1545176447.617 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:40:47.617Z,1545176447.617 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:40:47.618Z,1545176447.618 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:40:47.618Z,1545176447.618 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:40:51.744Z,1545176451.744 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:40:51.908Z,1545176451.908 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:40:51.909Z,1545176451.909 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:40:51.911Z,1545176451.911 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:40:51.911Z,1545176451.911 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:42:53.227Z,1545176573.227 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-18T23:37:52.0Z 2018-12-18T23:42:53.228Z,1545176573.228 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:42:53.228Z,1545176573.228 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:42:57.794Z,1545176577.794 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0048.lzma 2018-12-18T23:42:58.595Z,1545176578.595 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0048.lzma.bak 2018-12-18T23:42:58.596Z,1545176578.596 [DataOverHttps](INFO): SBD MOMSN=9086984 2018-12-18T23:43:08.851Z,1545176588.851 [DataOverHttps](INFO): Sending 312 bytes from file Logs/20181218T214820/Express0049.lzma 2018-12-18T23:43:09.635Z,1545176589.635 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0049.lzma.bak 2018-12-18T23:43:09.635Z,1545176589.635 [DataOverHttps](INFO): SBD MOMSN=9086986 2018-12-18T23:43:10.118Z,1545176590.118 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:43:10.118Z,1545176590.118 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:43:10.118Z,1545176590.118 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:43:14.030Z,1545176594.030 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-18T23:43:44.503Z,1545176624.503 [NAL9602](INFO): Powering down 2018-12-18T23:45:41.769Z,1545176741.769 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:45:41.769Z,1545176741.769 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-18T23:45:41.769Z,1545176741.769 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:45:42.034Z,1545176742.034 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:45:42.173Z,1545176742.173 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:45:42.262Z,1545176742.262 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:45:43.069Z,1545176743.069 [Rowe_600LCM](FAULT): LCB fault: Software Overcurrent. 2018-12-18T23:45:43.069Z,1545176743.069 [Rowe_600LCM] Hardware Fault, FailCount= 3 2018-12-18T23:45:43.069Z,1545176743.069 [Rowe_600LCM](ERROR): Hardware Fault 2018-12-18T23:45:43.628Z,1545176743.628 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:45:43.628Z,1545176743.628 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-18T23:45:43.877Z,1545176743.877 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:45:43.877Z,1545176743.877 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:45:43.878Z,1545176743.878 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:45:43.878Z,1545176743.878 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:45:48.123Z,1545176748.123 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:45:48.196Z,1545176748.196 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:45:48.198Z,1545176748.198 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:45:48.199Z,1545176748.199 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:45:48.200Z,1545176748.200 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:47:44.545Z,1545176864.545 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:47:44.545Z,1545176864.545 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-18T23:47:44.545Z,1545176864.545 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:47:44.949Z,1545176864.949 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:47:44.978Z,1545176864.978 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:47:45.157Z,1545176865.157 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:47:45.965Z,1545176865.965 [Rowe_600LCM](FAULT): LCB fault: Software Overcurrent. 2018-12-18T23:47:45.965Z,1545176865.965 [Rowe_600LCM] Hardware Fault, FailCount= 4 2018-12-18T23:47:45.965Z,1545176865.965 [Rowe_600LCM](ERROR): Hardware Fault 2018-12-18T23:47:46.533Z,1545176866.533 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-18T23:47:46.533Z,1545176866.533 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-18T23:47:46.773Z,1545176866.773 [Rowe_600LCM](INFO): Initializing 2018-12-18T23:47:46.773Z,1545176866.773 [Rowe_600LCM](INFO): Checking LCM 2018-12-18T23:47:46.773Z,1545176866.773 [Rowe_600LCM](INFO): LCM OK 2018-12-18T23:47:46.774Z,1545176866.774 [Rowe_600LCM](INFO): Powering up 2018-12-18T23:47:51.012Z,1545176871.012 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-18T23:47:51.088Z,1545176871.088 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-18T23:47:51.090Z,1545176871.090 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-18T23:47:51.091Z,1545176871.091 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-18T23:47:51.092Z,1545176871.092 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-18T23:48:10.520Z,1545176890.520 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:48:10.520Z,1545176890.520 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:48:10.520Z,1545176890.520 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:48:10.521Z,1545176890.521 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:48:10.905Z,1545176890.905 [Default:CheckIn:D] Stopped 2018-12-18T23:48:10.905Z,1545176890.905 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:48:11.316Z,1545176891.316 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.756104 min 2018-12-18T23:48:11.316Z,1545176891.316 [Default:CheckIn:E] Stopped 2018-12-18T23:48:11.316Z,1545176891.316 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:48:11.317Z,1545176891.317 [Default:CheckIn] Stopped 2018-12-18T23:48:11.317Z,1545176891.317 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:48:11.317Z,1545176891.317 [Default:CheckIn](INFO): Running loop #21 2018-12-18T23:48:11.317Z,1545176891.317 [Default:CheckIn] Running Loop=21 2018-12-18T23:48:11.318Z,1545176891.318 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:48:11.318Z,1545176891.318 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:48:14.898Z,1545176894.898 [NAL9602](INFO): Powering up 2018-12-18T23:48:26.034Z,1545176906.034 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:48:58.034Z,1545176938.034 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-18T23:48:58.109Z,1545176938.109 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-18T23:48:58.109Z,1545176938.109 [NAL9602] Data Fault, FailCount= 4 2018-12-18T23:48:58.109Z,1545176938.109 [NAL9602](ERROR): Data Fault 2018-12-18T23:48:58.229Z,1545176938.229 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-18T23:48:58.434Z,1545176938.434 [NAL9602](INFO): Powering down 2018-12-18T23:48:59.282Z,1545176939.282 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-18T23:48:59.282Z,1545176939.282 [NAL9602] No Fault, FailCount= 4 2018-12-18T23:49:28.499Z,1545176968.499 [NAL9602](INFO): Powering up NAL9602 2018-12-18T23:49:39.702Z,1545176979.702 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:53:11.687Z,1545177191.687 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-18T23:48:11.3Z 2018-12-18T23:53:11.688Z,1545177191.688 [Default:CheckIn:Read_GPS] Stopped 2018-12-18T23:53:11.688Z,1545177191.688 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-18T23:53:16.918Z,1545177196.918 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0051.lzma 2018-12-18T23:53:17.714Z,1545177197.714 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0051.lzma.bak 2018-12-18T23:53:17.714Z,1545177197.714 [DataOverHttps](INFO): SBD MOMSN=9087027 2018-12-18T23:53:27.874Z,1545177207.874 [DataOverHttps](INFO): Sending 333 bytes from file Logs/20181218T214820/Express0052.lzma 2018-12-18T23:53:28.655Z,1545177208.655 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0052.lzma.bak 2018-12-18T23:53:28.655Z,1545177208.655 [DataOverHttps](INFO): SBD MOMSN=9087029 2018-12-18T23:53:29.215Z,1545177209.215 [Default:CheckIn:Read_Iridium] Stopped 2018-12-18T23:53:29.215Z,1545177209.215 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-18T23:53:29.215Z,1545177209.215 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-18T23:53:29.462Z,1545177209.462 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-18T23:54:03.287Z,1545177243.287 [NAL9602](INFO): Powering down 2018-12-18T23:54:30.069Z,1545177270.069 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-18T23:54:30.069Z,1545177270.069 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-18T23:54:30.069Z,1545177270.069 [Rowe_600LCM](ERROR): Communications Fault 2018-12-18T23:54:30.473Z,1545177270.473 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-18T23:54:30.634Z,1545177270.634 [Rowe_600LCM](INFO): Powering down 2018-12-18T23:54:33.033Z,1545177273.033 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-18T23:54:33.033Z,1545177273.033 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-18T23:58:29.588Z,1545177509.588 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-18T23:58:29.588Z,1545177509.588 [Default:CheckIn:C.Wait] Stopped 2018-12-18T23:58:29.588Z,1545177509.588 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-18T23:58:29.588Z,1545177509.588 [Default:CheckIn:D] Running Loop=1 2018-12-18T23:58:29.992Z,1545177509.992 [Default:CheckIn:D] Stopped 2018-12-18T23:58:29.992Z,1545177509.992 [Default:CheckIn:E] Running Loop=1 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.074219 min 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn:E] Stopped 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn] Stopped 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn](INFO): Running loop #22 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn] Running Loop=22 2018-12-18T23:58:33.098Z,1545177513.098 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-18T23:58:33.099Z,1545177513.099 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-18T23:58:33.522Z,1545177513.522 [NAL9602](INFO): Powering up 2018-12-18T23:58:44.722Z,1545177524.722 [NAL9602](INFO): NAL9602 initialized 2018-12-18T23:58:45.522Z,1545177525.522 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-18T23:58:45.522Z,1545177525.522 [NAL9602] Data Fault, FailCount= 5 2018-12-18T23:58:45.522Z,1545177525.522 [NAL9602](ERROR): Data Fault 2018-12-18T23:58:45.604Z,1545177525.604 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-18T23:58:45.604Z,1545177525.604 [CBIT](CRITICAL): Data Fault in component: NAL9602 2018-12-18T23:58:45.922Z,1545177525.922 [NAL9602](INFO): Powering down 2018-12-18T23:58:45.983Z,1545177525.983 [CommandLine](FAULT): Scheduling is paused 2018-12-18T23:58:45.983Z,1545177525.983 [CBIT](INFO): Critical error at 20181218T235845 2018-12-19T00:00:45.559Z,1545177645.559 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:00:45.559Z,1545177645.559 [NAL9602] No Fault, FailCount= 5 2018-12-19T00:00:45.910Z,1545177645.910 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:00:57.114Z,1545177657.114 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:03:34.006Z,1545177814.006 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-18T23:58:33.1Z 2018-12-19T00:03:34.006Z,1545177814.006 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:03:34.006Z,1545177814.006 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:03:39.054Z,1545177819.054 [DataOverHttps](INFO): Sending 92 bytes from file Logs/20181218T214820/Courier0054.lzma 2018-12-19T00:03:39.843Z,1545177819.843 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0054.lzma.bak 2018-12-19T00:03:39.843Z,1545177819.843 [DataOverHttps](INFO): SBD MOMSN=9087076 2018-12-19T00:03:48.800Z,1545177828.800 [DataOverHttps](INFO): Sending 343 bytes from file Logs/20181218T214820/Express0055.lzma 2018-12-19T00:03:49.599Z,1545177829.599 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0055.lzma.bak 2018-12-19T00:03:49.599Z,1545177829.599 [DataOverHttps](INFO): SBD MOMSN=9087079 2018-12-19T00:03:50.090Z,1545177830.090 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:03:50.090Z,1545177830.090 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:03:50.090Z,1545177830.090 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:04:30.140Z,1545177870.140 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:04:30.140Z,1545177870.140 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-19T00:04:30.141Z,1545177870.141 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:04:30.142Z,1545177870.142 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:04:30.142Z,1545177870.142 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:04:30.142Z,1545177870.142 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:04:34.270Z,1545177874.270 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:04:34.336Z,1545177874.336 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:04:34.343Z,1545177874.343 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:04:34.344Z,1545177874.344 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:04:34.345Z,1545177874.345 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:06:00.266Z,1545177960.266 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:06:31.062Z,1545177991.062 [NAL9602](INFO): Powering down 2018-12-19T00:08:50.539Z,1545178130.539 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T00:08:50.539Z,1545178130.539 [Default:CheckIn:C.Wait] Stopped 2018-12-19T00:08:50.539Z,1545178130.539 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T00:08:50.540Z,1545178130.540 [Default:CheckIn:D] Running Loop=1 2018-12-19T00:08:50.979Z,1545178130.979 [Default:CheckIn:D] Stopped 2018-12-19T00:08:50.979Z,1545178130.979 [Default:CheckIn:E] Running Loop=1 2018-12-19T00:08:51.400Z,1545178131.400 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 168.424007 min 2018-12-19T00:08:51.400Z,1545178131.400 [Default:CheckIn:E] Stopped 2018-12-19T00:08:51.400Z,1545178131.400 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn] Stopped 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn](INFO): Running loop #23 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn] Running Loop=23 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T00:08:51.401Z,1545178131.401 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T00:08:52.106Z,1545178132.106 [NAL9602](INFO): Powering up 2018-12-19T00:09:02.914Z,1545178142.914 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:13:51.722Z,1545178431.722 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T00:08:51.4Z 2018-12-19T00:13:51.722Z,1545178431.722 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:13:51.722Z,1545178431.722 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:13:56.766Z,1545178436.766 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0057.lzma 2018-12-19T00:13:57.539Z,1545178437.539 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0057.lzma.bak 2018-12-19T00:13:57.539Z,1545178437.539 [DataOverHttps](INFO): SBD MOMSN=9087123 2018-12-19T00:14:07.472Z,1545178447.472 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:14:07.573Z,1545178447.573 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20181218T214820/Express0058.lzma 2018-12-19T00:14:08.363Z,1545178448.363 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0058.lzma.bak 2018-12-19T00:14:08.363Z,1545178448.363 [DataOverHttps](INFO): SBD MOMSN=9087125 2018-12-19T00:14:08.886Z,1545178448.886 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:14:08.886Z,1545178448.886 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:14:08.886Z,1545178448.886 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:14:37.610Z,1545178477.610 [NAL9602](INFO): Powering down 2018-12-19T00:15:16.097Z,1545178516.097 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:15:16.097Z,1545178516.097 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-19T00:15:16.097Z,1545178516.097 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:15:16.501Z,1545178516.501 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:15:16.545Z,1545178516.545 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:15:16.751Z,1545178516.751 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:15:18.066Z,1545178518.066 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:15:18.066Z,1545178518.066 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-19T00:15:18.365Z,1545178518.365 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:15:18.366Z,1545178518.366 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:15:18.366Z,1545178518.366 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:15:18.366Z,1545178518.366 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:15:22.599Z,1545178522.599 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:15:22.664Z,1545178522.664 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:15:22.665Z,1545178522.665 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:15:22.666Z,1545178522.666 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:15:22.667Z,1545178522.667 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:18:58.233Z,1545178738.233 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:18:58.233Z,1545178738.233 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-19T00:18:58.233Z,1545178738.233 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:18:58.270Z,1545178738.270 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:18:58.637Z,1545178738.637 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:18:58.734Z,1545178738.734 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:19:00.201Z,1545178740.201 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:19:00.201Z,1545178740.201 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-19T00:19:00.349Z,1545178740.349 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:19:00.349Z,1545178740.349 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:19:00.350Z,1545178740.350 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:19:00.350Z,1545178740.350 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:19:04.476Z,1545178744.476 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:19:04.616Z,1545178744.616 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:19:04.618Z,1545178744.618 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:19:04.619Z,1545178744.619 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:19:04.620Z,1545178744.620 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:19:09.410Z,1545178749.410 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T00:19:09.410Z,1545178749.410 [Default:CheckIn:C.Wait] Stopped 2018-12-19T00:19:09.410Z,1545178749.410 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T00:19:09.410Z,1545178749.410 [Default:CheckIn:D] Running Loop=1 2018-12-19T00:19:09.819Z,1545178749.819 [Default:CheckIn:D] Stopped 2018-12-19T00:19:09.819Z,1545178749.819 [Default:CheckIn:E] Running Loop=1 2018-12-19T00:19:10.184Z,1545178750.184 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 178.738005 min 2018-12-19T00:19:10.184Z,1545178750.184 [Default:CheckIn:E] Stopped 2018-12-19T00:19:10.184Z,1545178750.184 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T00:19:10.184Z,1545178750.184 [Default:CheckIn] Stopped 2018-12-19T00:19:10.185Z,1545178750.185 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T00:19:10.185Z,1545178750.185 [Default:CheckIn](INFO): Running loop #24 2018-12-19T00:19:10.185Z,1545178750.185 [Default:CheckIn] Running Loop=24 2018-12-19T00:19:10.185Z,1545178750.185 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T00:19:10.185Z,1545178750.185 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T00:19:14.245Z,1545178754.245 [NAL9602](INFO): Powering up 2018-12-19T00:19:25.114Z,1545178765.114 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:19:25.918Z,1545178765.918 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-19T00:19:25.919Z,1545178765.919 [NAL9602] Data Fault, FailCount= 1 2018-12-19T00:19:25.919Z,1545178765.919 [NAL9602](ERROR): Data Fault 2018-12-19T00:19:25.997Z,1545178765.997 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T00:19:26.315Z,1545178766.315 [NAL9602](INFO): Powering down 2018-12-19T00:19:27.205Z,1545178767.205 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:19:27.205Z,1545178767.205 [NAL9602] No Fault, FailCount= 1 2018-12-19T00:19:56.714Z,1545178796.714 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:20:07.518Z,1545178807.518 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:24:10.343Z,1545179050.343 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T00:19:10.2Z 2018-12-19T00:24:10.343Z,1545179050.343 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:24:10.343Z,1545179050.343 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:24:15.256Z,1545179055.256 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0060.lzma 2018-12-19T00:24:16.048Z,1545179056.048 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0060.lzma.bak 2018-12-19T00:24:16.048Z,1545179056.048 [DataOverHttps](INFO): SBD MOMSN=9087165 2018-12-19T00:24:25.946Z,1545179065.946 [DataOverHttps](INFO): Sending 278 bytes from file Logs/20181218T214820/Express0061.lzma 2018-12-19T00:24:26.711Z,1545179066.711 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0061.lzma.bak 2018-12-19T00:24:26.711Z,1545179066.711 [DataOverHttps](INFO): SBD MOMSN=9087167 2018-12-19T00:24:27.195Z,1545179067.195 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:24:27.195Z,1545179067.195 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:24:27.195Z,1545179067.195 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:25:10.970Z,1545179110.970 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:25:41.446Z,1545179141.446 [NAL9602](INFO): Powering down 2018-12-19T00:27:22.033Z,1545179242.033 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:27:22.033Z,1545179242.033 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-19T00:27:22.033Z,1545179242.033 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:27:22.400Z,1545179242.400 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:27:22.437Z,1545179242.437 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:27:22.534Z,1545179242.534 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:27:23.994Z,1545179243.994 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:27:23.994Z,1545179243.994 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-19T00:27:24.149Z,1545179244.149 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:27:24.149Z,1545179244.149 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:27:24.150Z,1545179244.150 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:27:24.150Z,1545179244.150 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:27:28.273Z,1545179248.273 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:27:28.385Z,1545179248.385 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:27:28.386Z,1545179248.386 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:27:28.387Z,1545179248.387 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:27:28.388Z,1545179248.388 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:29:27.644Z,1545179367.644 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T00:29:27.644Z,1545179367.644 [Default:CheckIn:C.Wait] Stopped 2018-12-19T00:29:27.644Z,1545179367.644 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T00:29:27.644Z,1545179367.644 [Default:CheckIn:D] Running Loop=1 2018-12-19T00:29:28.036Z,1545179368.036 [Default:CheckIn:D] Stopped 2018-12-19T00:29:28.036Z,1545179368.036 [Default:CheckIn:E] Running Loop=1 2018-12-19T00:29:28.462Z,1545179368.462 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 189.041618 min 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn:E] Stopped 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn] Stopped 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn](INFO): Running loop #25 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn] Running Loop=25 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T00:29:28.463Z,1545179368.463 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T00:29:31.998Z,1545179371.998 [NAL9602](INFO): Powering up 2018-12-19T00:29:43.151Z,1545179383.151 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:30:15.138Z,1545179415.138 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-19T00:30:15.221Z,1545179415.221 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-19T00:30:15.221Z,1545179415.221 [NAL9602] Data Fault, FailCount= 2 2018-12-19T00:30:15.221Z,1545179415.221 [NAL9602](ERROR): Data Fault 2018-12-19T00:30:15.343Z,1545179415.343 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T00:30:15.538Z,1545179415.538 [NAL9602](INFO): Powering down 2018-12-19T00:30:16.451Z,1545179416.451 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:30:16.451Z,1545179416.451 [NAL9602] No Fault, FailCount= 2 2018-12-19T00:30:45.586Z,1545179445.586 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:30:56.787Z,1545179456.787 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:30:57.586Z,1545179457.586 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-19T00:30:57.586Z,1545179457.586 [NAL9602] Data Fault, FailCount= 3 2018-12-19T00:30:57.586Z,1545179457.586 [NAL9602](ERROR): Data Fault 2018-12-19T00:30:57.668Z,1545179457.668 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T00:30:57.994Z,1545179457.994 [NAL9602](INFO): Powering down 2018-12-19T00:30:58.873Z,1545179458.873 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:30:58.873Z,1545179458.873 [NAL9602] No Fault, FailCount= 3 2018-12-19T00:31:28.386Z,1545179488.386 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:31:39.210Z,1545179499.210 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:34:28.799Z,1545179668.799 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T00:29:28.5Z 2018-12-19T00:34:28.799Z,1545179668.799 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:34:28.799Z,1545179668.799 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:34:33.552Z,1545179673.552 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0063.lzma 2018-12-19T00:34:34.351Z,1545179674.351 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0063.lzma.bak 2018-12-19T00:34:34.351Z,1545179674.351 [DataOverHttps](INFO): SBD MOMSN=9087213 2018-12-19T00:34:44.554Z,1545179684.554 [DataOverHttps](INFO): Sending 311 bytes from file Logs/20181218T214820/Express0064.lzma 2018-12-19T00:34:45.296Z,1545179685.296 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0064.lzma.bak 2018-12-19T00:34:45.297Z,1545179685.297 [DataOverHttps](INFO): SBD MOMSN=9087215 2018-12-19T00:34:45.818Z,1545179685.818 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:34:45.818Z,1545179685.818 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:34:45.818Z,1545179685.818 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:34:49.622Z,1545179689.622 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:35:20.135Z,1545179720.135 [NAL9602](INFO): Powering down 2018-12-19T00:38:33.185Z,1545179913.185 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:38:33.185Z,1545179913.185 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-19T00:38:33.185Z,1545179913.185 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:38:33.528Z,1545179913.528 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:38:33.589Z,1545179913.589 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:38:33.686Z,1545179913.686 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:38:35.135Z,1545179915.135 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:38:35.135Z,1545179915.135 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-19T00:38:35.301Z,1545179915.301 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:38:35.301Z,1545179915.301 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:38:35.302Z,1545179915.302 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:38:35.302Z,1545179915.302 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:38:39.425Z,1545179919.425 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:38:39.584Z,1545179919.584 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:38:39.585Z,1545179919.585 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:38:39.587Z,1545179919.587 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:38:39.588Z,1545179919.588 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:39:46.255Z,1545179986.255 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T00:39:46.256Z,1545179986.256 [Default:CheckIn:C.Wait] Stopped 2018-12-19T00:39:46.256Z,1545179986.256 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T00:39:46.256Z,1545179986.256 [Default:CheckIn:D] Running Loop=1 2018-12-19T00:39:46.654Z,1545179986.654 [Default:CheckIn:D] Stopped 2018-12-19T00:39:46.654Z,1545179986.654 [Default:CheckIn:E] Running Loop=1 2018-12-19T00:39:47.060Z,1545179987.060 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 199.351921 min 2018-12-19T00:39:47.060Z,1545179987.060 [Default:CheckIn:E] Stopped 2018-12-19T00:39:47.060Z,1545179987.060 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T00:39:47.060Z,1545179987.060 [Default:CheckIn] Stopped 2018-12-19T00:39:47.065Z,1545179987.065 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T00:39:47.065Z,1545179987.065 [Default:CheckIn](INFO): Running loop #26 2018-12-19T00:39:47.065Z,1545179987.065 [Default:CheckIn] Running Loop=26 2018-12-19T00:39:47.065Z,1545179987.065 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T00:39:47.065Z,1545179987.065 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T00:39:51.048Z,1545179991.048 [NAL9602](INFO): Powering up 2018-12-19T00:40:02.190Z,1545180002.190 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:40:34.190Z,1545180034.190 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-19T00:40:34.273Z,1545180034.273 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-19T00:40:34.273Z,1545180034.273 [NAL9602] Data Fault, FailCount= 4 2018-12-19T00:40:34.273Z,1545180034.273 [NAL9602](ERROR): Data Fault 2018-12-19T00:40:34.387Z,1545180034.387 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T00:40:34.590Z,1545180034.590 [NAL9602](INFO): Powering down 2018-12-19T00:40:35.462Z,1545180035.462 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:40:35.462Z,1545180035.462 [NAL9602] No Fault, FailCount= 4 2018-12-19T00:41:04.811Z,1545180064.811 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:41:15.996Z,1545180075.996 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:43:40.325Z,1545180220.325 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:43:40.325Z,1545180220.325 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-19T00:43:40.325Z,1545180220.325 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:43:40.421Z,1545180220.421 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:43:40.421Z,1545180220.421 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-19T00:43:40.729Z,1545180220.729 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:43:40.949Z,1545180220.949 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:44:47.377Z,1545180287.377 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T00:39:47.1Z 2018-12-19T00:44:47.377Z,1545180287.377 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:44:47.377Z,1545180287.377 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:44:51.795Z,1545180291.795 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0066.lzma 2018-12-19T00:44:52.595Z,1545180292.595 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0066.lzma.bak 2018-12-19T00:44:52.595Z,1545180292.595 [DataOverHttps](INFO): SBD MOMSN=9087291 2018-12-19T00:45:01.712Z,1545180301.712 [DataOverHttps](INFO): Sending 343 bytes from file Logs/20181218T214820/Express0067.lzma 2018-12-19T00:45:02.477Z,1545180302.477 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0067.lzma.bak 2018-12-19T00:45:02.477Z,1545180302.477 [DataOverHttps](INFO): SBD MOMSN=9087293 2018-12-19T00:45:02.966Z,1545180302.966 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:45:02.966Z,1545180302.966 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:45:02.966Z,1545180302.966 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:45:06.403Z,1545180306.403 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:45:18.602Z,1545180318.602 [CBIT](IMPORTANT): Beginning ground fault scan 2018-12-19T00:45:29.371Z,1545180329.371 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.013431 CHAN A1 (24V): -0.016425 CHAN A2 (12V): -0.002451 CHAN A3 (5V): -0.001360 CHAN B0 (3.3V): -0.000163 CHAN B1 (3.15aV): -0.000223 CHAN B2 (3.15bV): 0.000007 CHAN B3 (GND): -0.000156 OPEN: -0.000468 Full Scale Calc: 4.765 mA, -1.589 mA 2018-12-19T00:45:36.906Z,1545180336.906 [NAL9602](INFO): Powering down 2018-12-19T00:50:03.633Z,1545180603.633 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T00:50:03.633Z,1545180603.633 [Default:CheckIn:C.Wait] Stopped 2018-12-19T00:50:03.634Z,1545180603.634 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T00:50:03.634Z,1545180603.634 [Default:CheckIn:D] Running Loop=1 2018-12-19T00:50:04.051Z,1545180604.051 [Default:CheckIn:D] Stopped 2018-12-19T00:50:04.051Z,1545180604.051 [Default:CheckIn:E] Running Loop=1 2018-12-19T00:50:07.292Z,1545180607.292 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 209.641862 min 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn:E] Stopped 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn] Stopped 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn](INFO): Running loop #27 2018-12-19T00:50:07.293Z,1545180607.293 [Default:CheckIn] Running Loop=27 2018-12-19T00:50:07.294Z,1545180607.294 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T00:50:07.294Z,1545180607.294 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T00:50:07.724Z,1545180607.724 [NAL9602](INFO): Powering up 2018-12-19T00:50:18.918Z,1545180618.918 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:50:19.718Z,1545180619.718 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-19T00:50:19.718Z,1545180619.718 [NAL9602] Data Fault, FailCount= 5 2018-12-19T00:50:19.718Z,1545180619.718 [NAL9602](ERROR): Data Fault 2018-12-19T00:50:19.818Z,1545180619.818 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T00:50:19.819Z,1545180619.819 [CBIT](CRITICAL): Data Fault in component: NAL9602 2018-12-19T00:50:20.118Z,1545180620.118 [NAL9602](INFO): Powering down 2018-12-19T00:50:20.214Z,1545180620.214 [CBIT](INFO): Critical error at 20181219T005019 2018-12-19T00:52:19.773Z,1545180739.773 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T00:52:19.774Z,1545180739.774 [NAL9602] No Fault, FailCount= 5 2018-12-19T00:52:20.114Z,1545180740.114 [NAL9602](INFO): Powering up NAL9602 2018-12-19T00:52:31.314Z,1545180751.314 [NAL9602](INFO): NAL9602 initialized 2018-12-19T00:53:40.682Z,1545180820.682 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:53:40.682Z,1545180820.682 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-19T00:53:40.794Z,1545180820.794 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:53:40.794Z,1545180820.794 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:53:40.795Z,1545180820.795 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:53:40.795Z,1545180820.795 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:53:44.920Z,1545180824.920 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:53:44.988Z,1545180824.988 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:53:44.989Z,1545180824.989 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:53:44.991Z,1545180824.991 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:53:44.992Z,1545180824.992 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T00:55:11.603Z,1545180911.603 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T00:50:07.3Z 2018-12-19T00:55:11.603Z,1545180911.603 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T00:55:11.603Z,1545180911.603 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T00:55:18.136Z,1545180918.136 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20181218T214820/Courier0069.lzma 2018-12-19T00:55:18.935Z,1545180918.935 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0069.lzma.bak 2018-12-19T00:55:18.935Z,1545180918.935 [DataOverHttps](INFO): SBD MOMSN=9087331 2018-12-19T00:55:28.882Z,1545180928.882 [DataOverHttps](INFO): Sending 396 bytes from file Logs/20181218T214820/Express0070.lzma 2018-12-19T00:55:29.676Z,1545180929.676 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0070.lzma.bak 2018-12-19T00:55:29.677Z,1545180929.677 [DataOverHttps](INFO): SBD MOMSN=9087334 2018-12-19T00:55:30.155Z,1545180930.155 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T00:55:30.156Z,1545180930.156 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T00:55:30.156Z,1545180930.156 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T00:57:35.045Z,1545181055.045 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T00:58:05.542Z,1545181085.542 [NAL9602](INFO): Powering down 2018-12-19T00:58:11.921Z,1545181091.921 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T00:58:11.921Z,1545181091.921 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-19T00:58:11.921Z,1545181091.921 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T00:58:12.061Z,1545181092.061 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T00:58:12.332Z,1545181092.332 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T00:58:12.550Z,1545181092.550 [Rowe_600LCM](INFO): Powering down 2018-12-19T00:58:13.984Z,1545181093.984 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T00:58:13.984Z,1545181093.984 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-19T00:58:14.165Z,1545181094.165 [Rowe_600LCM](INFO): Initializing 2018-12-19T00:58:14.165Z,1545181094.165 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T00:58:14.166Z,1545181094.166 [Rowe_600LCM](INFO): LCM OK 2018-12-19T00:58:14.166Z,1545181094.166 [Rowe_600LCM](INFO): Powering up 2018-12-19T00:58:18.294Z,1545181098.294 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T00:58:18.404Z,1545181098.404 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T00:58:18.410Z,1545181098.410 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T00:58:18.411Z,1545181098.411 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T00:58:18.412Z,1545181098.412 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:00:10.357Z,1545181210.357 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:00:10.357Z,1545181210.357 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-19T01:00:10.357Z,1545181210.357 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:00:10.448Z,1545181210.448 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:00:10.761Z,1545181210.761 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:00:10.954Z,1545181210.954 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:00:12.415Z,1545181212.415 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:00:12.415Z,1545181212.415 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-19T01:00:12.569Z,1545181212.569 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:00:12.569Z,1545181212.569 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:00:12.570Z,1545181212.570 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:00:12.570Z,1545181212.570 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:00:16.691Z,1545181216.691 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:00:16.756Z,1545181216.756 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:00:16.765Z,1545181216.765 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:00:16.766Z,1545181216.766 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:00:16.767Z,1545181216.767 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:00:30.814Z,1545181230.814 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T01:00:30.815Z,1545181230.815 [Default:CheckIn:C.Wait] Stopped 2018-12-19T01:00:30.815Z,1545181230.815 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T01:00:30.815Z,1545181230.815 [Default:CheckIn:D] Running Loop=1 2018-12-19T01:00:31.217Z,1545181231.217 [Default:CheckIn:D] Stopped 2018-12-19T01:00:31.217Z,1545181231.217 [Default:CheckIn:E] Running Loop=1 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 220.094629 min 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn:E] Stopped 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn] Stopped 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn](INFO): Running loop #28 2018-12-19T01:00:31.616Z,1545181231.616 [Default:CheckIn] Running Loop=28 2018-12-19T01:00:31.621Z,1545181231.621 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T01:00:31.621Z,1545181231.621 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T01:00:35.687Z,1545181235.687 [NAL9602](INFO): Powering up 2018-12-19T01:00:46.578Z,1545181246.578 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:01:18.578Z,1545181278.578 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-19T01:01:18.653Z,1545181278.653 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-19T01:01:18.653Z,1545181278.653 [NAL9602] Data Fault, FailCount= 1 2018-12-19T01:01:18.653Z,1545181278.653 [NAL9602](ERROR): Data Fault 2018-12-19T01:01:18.718Z,1545181278.718 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T01:01:18.982Z,1545181278.982 [NAL9602](INFO): Powering down 2018-12-19T01:01:19.873Z,1545181279.873 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T01:01:19.873Z,1545181279.873 [NAL9602] No Fault, FailCount= 1 2018-12-19T01:01:49.370Z,1545181309.370 [NAL9602](INFO): Powering up NAL9602 2018-12-19T01:02:00.170Z,1545181320.170 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:05:32.005Z,1545181532.005 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T01:00:31.6Z 2018-12-19T01:05:32.005Z,1545181532.005 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T01:05:32.005Z,1545181532.005 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T01:05:36.926Z,1545181536.926 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0072.lzma 2018-12-19T01:05:37.728Z,1545181537.728 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0072.lzma.bak 2018-12-19T01:05:37.729Z,1545181537.729 [DataOverHttps](INFO): SBD MOMSN=9087438 2018-12-19T01:05:47.951Z,1545181547.951 [DataOverHttps](INFO): Sending 299 bytes from file Logs/20181218T214820/Express0073.lzma 2018-12-19T01:05:48.735Z,1545181548.735 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0073.lzma.bak 2018-12-19T01:05:48.736Z,1545181548.736 [DataOverHttps](INFO): SBD MOMSN=9087440 2018-12-19T01:05:49.221Z,1545181549.221 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T01:05:49.221Z,1545181549.221 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T01:05:49.221Z,1545181549.221 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T01:05:53.028Z,1545181553.028 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T01:06:00.209Z,1545181560.209 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:06:00.209Z,1545181560.209 [Rowe_600LCM] Communications Fault, FailCount= 3 2018-12-19T01:06:00.209Z,1545181560.209 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:06:00.359Z,1545181560.359 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:06:00.613Z,1545181560.613 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:06:00.762Z,1545181560.762 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:06:01.982Z,1545181561.982 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:06:01.982Z,1545181561.982 [Rowe_600LCM] No Fault, FailCount= 3 2018-12-19T01:06:02.377Z,1545181562.377 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:06:02.377Z,1545181562.377 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:06:02.378Z,1545181562.378 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:06:02.378Z,1545181562.378 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:06:06.507Z,1545181566.507 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:06:06.573Z,1545181566.573 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:06:06.575Z,1545181566.575 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:06:06.576Z,1545181566.576 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:06:06.577Z,1545181566.577 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:06:23.510Z,1545181583.510 [NAL9602](INFO): Powering down 2018-12-19T01:10:49.846Z,1545181849.846 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T01:10:49.846Z,1545181849.846 [Default:CheckIn:C.Wait] Stopped 2018-12-19T01:10:49.846Z,1545181849.846 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T01:10:49.847Z,1545181849.847 [Default:CheckIn:D] Running Loop=1 2018-12-19T01:10:50.234Z,1545181850.234 [Default:CheckIn:D] Stopped 2018-12-19T01:10:50.234Z,1545181850.234 [Default:CheckIn:E] Running Loop=1 2018-12-19T01:10:50.647Z,1545181850.647 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 230.411589 min 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn:E] Stopped 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn] Stopped 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn](INFO): Running loop #29 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn] Running Loop=29 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T01:10:50.648Z,1545181850.648 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T01:10:54.455Z,1545181854.455 [NAL9602](INFO): Powering up 2018-12-19T01:11:05.618Z,1545181865.618 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:11:06.430Z,1545181866.430 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-19T01:11:06.430Z,1545181866.430 [NAL9602] Data Fault, FailCount= 2 2018-12-19T01:11:06.430Z,1545181866.430 [NAL9602](ERROR): Data Fault 2018-12-19T01:11:06.509Z,1545181866.509 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T01:11:06.818Z,1545181866.818 [NAL9602](INFO): Powering down 2018-12-19T01:11:07.693Z,1545181867.693 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T01:11:07.693Z,1545181867.693 [NAL9602] No Fault, FailCount= 2 2018-12-19T01:11:37.222Z,1545181897.222 [NAL9602](INFO): Powering up NAL9602 2018-12-19T01:11:48.418Z,1545181908.418 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:12:49.377Z,1545181969.377 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:12:49.377Z,1545181969.377 [Rowe_600LCM] Communications Fault, FailCount= 4 2018-12-19T01:12:49.377Z,1545181969.377 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:12:49.753Z,1545181969.753 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:12:49.781Z,1545181969.781 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:12:49.903Z,1545181969.903 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:12:54.112Z,1545181974.112 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:12:54.112Z,1545181974.112 [Rowe_600LCM] No Fault, FailCount= 4 2018-12-19T01:12:54.345Z,1545181974.345 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:12:54.345Z,1545181974.345 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:12:54.346Z,1545181974.346 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:12:54.346Z,1545181974.346 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:12:58.471Z,1545181978.471 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:12:58.575Z,1545181978.575 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:12:58.578Z,1545181978.578 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:12:58.579Z,1545181978.579 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:12:58.580Z,1545181978.580 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:15:50.939Z,1545182150.939 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T01:10:50.6Z 2018-12-19T01:15:50.939Z,1545182150.939 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T01:15:50.939Z,1545182150.939 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T01:15:54.904Z,1545182154.904 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0075.lzma 2018-12-19T01:15:55.696Z,1545182155.696 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0075.lzma.bak 2018-12-19T01:15:55.696Z,1545182155.696 [DataOverHttps](INFO): SBD MOMSN=9087475 2018-12-19T01:16:05.738Z,1545182165.738 [DataOverHttps](INFO): Sending 281 bytes from file Logs/20181218T214820/Express0076.lzma 2018-12-19T01:16:06.515Z,1545182166.515 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0076.lzma.bak 2018-12-19T01:16:06.515Z,1545182166.515 [DataOverHttps](INFO): SBD MOMSN=9087477 2018-12-19T01:16:06.993Z,1545182166.993 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T01:16:06.993Z,1545182166.993 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T01:16:06.993Z,1545182166.993 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T01:16:54.474Z,1545182214.474 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T01:17:25.213Z,1545182245.213 [NAL9602](INFO): Powering down 2018-12-19T01:18:11.981Z,1545182291.981 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:18:11.981Z,1545182291.981 [Rowe_600LCM] Communications Fault, FailCount= 5 2018-12-19T01:18:11.981Z,1545182291.981 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:18:12.270Z,1545182292.270 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:18:12.270Z,1545182292.270 [CBIT](FAULT): Communications Fault in component: Rowe_600LCM 2018-12-19T01:18:12.385Z,1545182292.385 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:18:12.486Z,1545182292.486 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:18:13.294Z,1545182293.294 [Rowe_600LCM](FAULT): LCB fault: Software Overcurrent. 2018-12-19T01:18:13.294Z,1545182293.294 [Rowe_600LCM] Hardware Fault, FailCount= 5 2018-12-19T01:18:13.294Z,1545182293.294 [Rowe_600LCM](ERROR): Hardware Fault 2018-12-19T01:21:07.758Z,1545182467.758 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T01:21:07.759Z,1545182467.759 [Default:CheckIn:C.Wait] Stopped 2018-12-19T01:21:07.759Z,1545182467.759 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T01:21:07.759Z,1545182467.759 [Default:CheckIn:D] Running Loop=1 2018-12-19T01:21:08.158Z,1545182468.158 [Default:CheckIn:D] Stopped 2018-12-19T01:21:08.158Z,1545182468.158 [Default:CheckIn:E] Running Loop=1 2018-12-19T01:21:08.566Z,1545182468.566 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 240.710319 min 2018-12-19T01:21:08.566Z,1545182468.566 [Default:CheckIn:E] Stopped 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn] Stopped 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn](INFO): Running loop #30 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn] Running Loop=30 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T01:21:08.567Z,1545182468.567 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T01:21:12.045Z,1545182472.045 [NAL9602](INFO): Powering up 2018-12-19T01:21:22.938Z,1545182482.938 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:21:54.938Z,1545182514.938 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-12-19T01:21:55.013Z,1545182515.013 [NAL9602](FAULT): received: +CSQ:0 OK870, 2, 0, 0, 0 OK 2018-12-19T01:21:55.013Z,1545182515.013 [NAL9602] Data Fault, FailCount= 3 2018-12-19T01:21:55.013Z,1545182515.013 [NAL9602](ERROR): Data Fault 2018-12-19T01:21:55.142Z,1545182515.142 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T01:21:55.334Z,1545182515.334 [NAL9602](INFO): Powering down 2018-12-19T01:21:56.193Z,1545182516.193 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T01:21:56.193Z,1545182516.193 [NAL9602] No Fault, FailCount= 3 2018-12-19T01:22:25.394Z,1545182545.394 [NAL9602](INFO): Powering up NAL9602 2018-12-19T01:22:36.590Z,1545182556.590 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:22:37.394Z,1545182557.394 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-12-19T01:22:37.394Z,1545182557.394 [NAL9602] Data Fault, FailCount= 4 2018-12-19T01:22:37.394Z,1545182557.394 [NAL9602](ERROR): Data Fault 2018-12-19T01:22:37.458Z,1545182557.458 [CBIT](ERROR): Data Fault in component: NAL9602 2018-12-19T01:22:37.786Z,1545182557.786 [NAL9602](INFO): Powering down 2018-12-19T01:22:38.637Z,1545182558.637 [CBIT](INFO): Clearing failed state for component NAL9602 2018-12-19T01:22:38.637Z,1545182558.637 [NAL9602] No Fault, FailCount= 4 2018-12-19T01:23:07.790Z,1545182587.790 [NAL9602](INFO): Powering up NAL9602 2018-12-19T01:23:18.602Z,1545182598.602 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:26:08.711Z,1545182768.711 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T01:21:08.6Z 2018-12-19T01:26:08.711Z,1545182768.711 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T01:26:08.712Z,1545182768.712 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T01:26:12.299Z,1545182772.299 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0078.lzma 2018-12-19T01:26:13.099Z,1545182773.099 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0078.lzma.bak 2018-12-19T01:26:13.099Z,1545182773.099 [DataOverHttps](INFO): SBD MOMSN=9087512 2018-12-19T01:26:21.984Z,1545182781.984 [DataOverHttps](INFO): Sending 386 bytes from file Logs/20181218T214820/Express0079.lzma 2018-12-19T01:26:22.783Z,1545182782.783 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0079.lzma.bak 2018-12-19T01:26:22.784Z,1545182782.784 [DataOverHttps](INFO): SBD MOMSN=9087514 2018-12-19T01:26:23.280Z,1545182783.280 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T01:26:23.281Z,1545182783.281 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T01:26:23.281Z,1545182783.281 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T01:26:26.718Z,1545182786.718 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T01:26:57.214Z,1545182817.214 [NAL9602](INFO): Powering down 2018-12-19T01:28:12.049Z,1545182892.049 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:28:12.050Z,1545182892.050 [Rowe_600LCM] No Fault, FailCount= 5 2018-12-19T01:28:12.349Z,1545182892.349 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:28:12.350Z,1545182892.350 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:28:12.350Z,1545182892.350 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:28:12.350Z,1545182892.350 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:28:16.586Z,1545182896.586 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:28:16.648Z,1545182896.648 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:28:16.650Z,1545182896.650 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:28:16.651Z,1545182896.651 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:28:16.652Z,1545182896.652 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:30:30.333Z,1545183030.333 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:30:30.333Z,1545183030.333 [Rowe_600LCM] Communications Fault, FailCount= 1 2018-12-19T01:30:30.333Z,1545183030.333 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:30:30.409Z,1545183030.409 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:30:30.737Z,1545183030.737 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:30:30.922Z,1545183030.922 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:30:32.456Z,1545183032.456 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:30:32.456Z,1545183032.456 [Rowe_600LCM] No Fault, FailCount= 1 2018-12-19T01:30:32.541Z,1545183032.541 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:30:32.542Z,1545183032.542 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:30:32.542Z,1545183032.542 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:30:32.542Z,1545183032.542 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:30:36.662Z,1545183036.662 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:30:36.787Z,1545183036.787 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:30:36.789Z,1545183036.789 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:30:36.790Z,1545183036.790 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:30:36.791Z,1545183036.791 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:31:23.000Z,1545183084.000 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-12-19T01:31:23.000Z,1545183084.000 [Default:CheckIn:C.Wait] Stopped 2018-12-19T01:31:23.000Z,1545183084.000 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T01:31:24.000Z,1545183084.000 [Default:CheckIn:D] Running Loop=1 2018-12-19T01:31:24.401Z,1545183084.401 [Default:CheckIn:D] Stopped 2018-12-19T01:31:24.401Z,1545183084.401 [Default:CheckIn:E] Running Loop=1 2018-12-19T01:31:24.799Z,1545183084.799 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 250.981038 min 2018-12-19T01:31:24.799Z,1545183084.799 [Default:CheckIn:E] Stopped 2018-12-19T01:31:24.799Z,1545183084.799 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-12-19T01:31:24.799Z,1545183084.799 [Default:CheckIn] Stopped 2018-12-19T01:31:24.799Z,1545183084.799 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T01:31:24.800Z,1545183084.800 [Default:CheckIn](INFO): Running loop #31 2018-12-19T01:31:24.800Z,1545183084.800 [Default:CheckIn] Running Loop=31 2018-12-19T01:31:24.800Z,1545183084.800 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-12-19T01:31:24.800Z,1545183084.800 [Default:CheckIn:Read_GPS] Running Loop=1 2018-12-19T01:31:28.474Z,1545183088.474 [NAL9602](INFO): Powering up 2018-12-19T01:31:39.661Z,1545183099.661 [NAL9602](INFO): NAL9602 initialized 2018-12-19T01:36:24.844Z,1545183384.844 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-12-19T01:31:24.8Z 2018-12-19T01:36:24.844Z,1545183384.844 [Default:CheckIn:Read_GPS] Stopped 2018-12-19T01:36:24.845Z,1545183384.845 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-12-19T01:36:29.270Z,1545183389.270 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181218T214820/Courier0081.lzma 2018-12-19T01:36:30.074Z,1545183390.074 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Courier0081.lzma.bak 2018-12-19T01:36:30.074Z,1545183390.074 [DataOverHttps](INFO): SBD MOMSN=9087555 2018-12-19T01:36:40.252Z,1545183400.252 [DataOverHttps](INFO): Sending 256 bytes from file Logs/20181218T214820/Express0082.lzma 2018-12-19T01:36:41.051Z,1545183401.051 [DataOverHttps](INFO): Moved sent file to Logs/20181218T214820/Express0082.lzma.bak 2018-12-19T01:36:41.052Z,1545183401.052 [DataOverHttps](INFO): SBD MOMSN=9087557 2018-12-19T01:36:41.577Z,1545183401.577 [Default:CheckIn:Read_Iridium] Stopped 2018-12-19T01:36:41.577Z,1545183401.577 [Default:CheckIn:C.Wait] Running Loop=1 2018-12-19T01:36:41.577Z,1545183401.577 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-12-19T01:36:45.460Z,1545183405.460 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-12-19T01:37:15.930Z,1545183435.930 [NAL9602](INFO): Powering down 2018-12-19T01:40:57.857Z,1545183657.857 [Rowe_600LCM](FAULT): Did not receive valid device response within the specified allowable sample time. 2018-12-19T01:40:57.857Z,1545183657.857 [Rowe_600LCM] Communications Fault, FailCount= 2 2018-12-19T01:40:57.857Z,1545183657.857 [Rowe_600LCM](ERROR): Communications Fault 2018-12-19T01:40:58.004Z,1545183658.004 [CBIT](ERROR): Communications Fault in component: Rowe_600LCM 2018-12-19T01:40:58.261Z,1545183658.261 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:40:58.450Z,1545183658.450 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:41:00.013Z,1545183660.013 [CBIT](INFO): Clearing failed state for component Rowe_600LCM 2018-12-19T01:41:00.013Z,1545183660.013 [Rowe_600LCM] No Fault, FailCount= 2 2018-12-19T01:41:00.065Z,1545183660.065 [Rowe_600LCM](INFO): Initializing 2018-12-19T01:41:00.065Z,1545183660.065 [Rowe_600LCM](INFO): Checking LCM 2018-12-19T01:41:00.066Z,1545183660.066 [Rowe_600LCM](INFO): LCM OK 2018-12-19T01:41:00.066Z,1545183660.066 [Rowe_600LCM](INFO): Powering up 2018-12-19T01:41:04.192Z,1545183664.192 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface 2018-12-19T01:41:04.250Z,1545183664.250 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 9600 >& /dev/null & 2018-12-19T01:41:04.251Z,1545183664.251 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track 2018-12-19T01:41:04.252Z,1545183664.252 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity 2018-12-19T01:41:04.255Z,1545183664.255 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe 2018-12-19T01:41:09.857Z,1545183669.857 [CommandLine](IMPORTANT): got command quit 2018-12-19T01:41:10.864Z,1545183670.864 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:10.864Z,1545183670.864 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.025Z,1545183671.025 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-12-19T01:41:11.025Z,1545183671.025 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.026Z,1545183671.026 [CommandLine](INFO): Join timeout helper Thread ID is 3533 2018-12-19T01:41:11.026Z,1545183671.026 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-12-19T01:41:11.026Z,1545183671.026 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.027Z,1545183671.027 [NavChartDb](INFO): Join timeout helper Thread ID is 3534 2018-12-19T01:41:11.345Z,1545183671.345 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:11.345Z,1545183671.345 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.365Z,1545183671.365 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-12-19T01:41:11.365Z,1545183671.365 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.365Z,1545183671.365 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3535 2018-12-19T01:41:11.621Z,1545183671.621 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:11.621Z,1545183671.621 [WetLabsBB2FL](INFO): Powering down 2018-12-19T01:41:11.622Z,1545183671.622 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.625Z,1545183671.625 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-12-19T01:41:11.625Z,1545183671.625 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:11.625Z,1545183671.625 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3536 2018-12-19T01:41:12.189Z,1545183672.189 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:12.189Z,1545183672.189 [CTD_Seabird](INFO): Powering down 2018-12-19T01:41:12.201Z,1545183672.201 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:12.217Z,1545183672.217 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2018-12-19T01:41:12.217Z,1545183672.217 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:12.217Z,1545183672.217 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3537 2018-12-19T01:41:12.345Z,1545183672.345 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:12.345Z,1545183672.345 [CTD_NeilBrown](INFO): Powering down 2018-12-19T01:41:12.357Z,1545183672.357 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:12.366Z,1545183672.366 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler 2018-12-19T01:41:12.366Z,1545183672.366 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:12.366Z,1545183672.366 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 3538 2018-12-19T01:41:13.035Z,1545183673.035 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:13.035Z,1545183673.035 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-12-19T01:41:13.121Z,1545183673.121 [Rowe_600LCM](INFO): Powering down 2018-12-19T01:41:13.122Z,1545183673.122 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.142Z,1545183673.142 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-12-19T01:41:13.142Z,1545183673.142 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.142Z,1545183673.142 [Radio_Surface](INFO): Join timeout helper Thread ID is 3540 2018-12-19T01:41:13.165Z,1545183673.165 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:13.166Z,1545183673.166 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.167Z,1545183673.167 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-12-19T01:41:13.167Z,1545183673.167 [logger ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.168Z,1545183673.168 [logger](INFO): Join timeout helper Thread ID is 3541 2018-12-19T01:41:13.185Z,1545183673.185 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:13.185Z,1545183673.185 [logger ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.198Z,1545183673.198 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-12-19T01:41:13.198Z,1545183673.198 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.198Z,1545183673.198 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-12-19T01:41:13.198Z,1545183673.198 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.198Z,1545183673.198 [controlThread](INFO): Join timeout helper Thread ID is 3542 2018-12-19T01:41:13.206Z,1545183673.206 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-12-19T01:41:13.207Z,1545183673.207 [controlThread](DEBUG): Uninitializing ControlThread 2018-12-19T01:41:13.208Z,1545183673.208 [NAL9602](INFO): Powering down 2018-12-19T01:41:13.210Z,1545183673.210 [PNI_TCM](INFO): Powering down 2018-12-19T01:41:13.298Z,1545183673.298 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2018-12-19T01:41:13.299Z,1545183673.299 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-12-19T01:41:13.299Z,1545183673.299 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-12-19T01:41:13.300Z,1545183673.300 [MissionManager](INFO): Uninitializing Mission Default 2018-12-19T01:41:13.300Z,1545183673.300 [Default] Stopped 2018-12-19T01:41:13.300Z,1545183673.300 [Default](DEBUG): Aggregate::uninitialize Default 2018-12-19T01:41:13.300Z,1545183673.300 [Default:B.GoToSurface] Stopped 2018-12-19T01:41:13.300Z,1545183673.300 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-12-19T01:41:13.300Z,1545183673.300 [Default:CheckIn] Stopped 2018-12-19T01:41:13.300Z,1545183673.300 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-12-19T01:41:13.301Z,1545183673.301 [Default:CheckIn:C.Wait] Stopped 2018-12-19T01:41:13.301Z,1545183673.301 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-12-19T01:41:13.304Z,1545183673.304 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-12-19T01:41:13.304Z,1545183673.304 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-12-19T01:41:13.305Z,1545183673.305 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-12-19T01:41:13.305Z,1545183673.305 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-12-19T01:41:13.306Z,1545183673.306 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-12-19T01:41:13.306Z,1545183673.306 [BuoyancyServo](INFO): Powering down 2018-12-19T01:41:13.317Z,1545183673.317 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-12-19T01:41:13.317Z,1545183673.317 [ElevatorServo](INFO): Powering down 2018-12-19T01:41:13.318Z,1545183673.318 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-12-19T01:41:13.318Z,1545183673.318 [MassServo](INFO): Powering down 2018-12-19T01:41:13.319Z,1545183673.319 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-12-19T01:41:13.319Z,1545183673.319 [RudderServo](INFO): Powering down 2018-12-19T01:41:13.320Z,1545183673.320 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-12-19T01:41:13.320Z,1545183673.320 [ThrusterServo](INFO): Powering down 2018-12-19T01:41:13.321Z,1545183673.321 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-12-19T01:41:13.321Z,1545183673.321 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-12-19T01:41:13.321Z,1545183673.321 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-12-19T01:41:13.322Z,1545183673.322 [CBIT](DEBUG): Powering off loads. 2018-12-19T01:41:13.333Z,1545183673.333 [CBIT](DEBUG): Disabling WDT. 2018-12-19T01:41:13.345Z,1545183673.345 [CBIT](DEBUG): Opening all GF detection circuits. 2018-12-19T01:41:13.346Z,1545183673.346 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.407Z,1545183673.407 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.414Z,1545183673.414 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.460Z,1545183673.460 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.464Z,1545183673.464 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.468Z,1545183673.468 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.497Z,1545183673.497 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-12-19T01:41:13.582Z,1545183673.582 [logger ThreadHandler](INFO): Thread cancelled.