2019-09-12T21:22:41.798Z,1568323361.798 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-12T21:22:42.829Z,1568323362.829 [DataOverHttps](INFO): Received command:restart logs 2019-09-12T21:22:42.921Z,1568323362.921 [CommandLine](IMPORTANT): got command restart logs 2019-09-12T21:22:46.222Z,1568323366.222 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:22:55.520Z,1568323375.520 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T204816/Courier0021.lzma 2019-09-12T21:22:57.526Z,1568323377.526 [DataOverHttps](INFO): Moved sent file to Logs/20190912T204816/Courier0021.lzma.bak 2019-09-12T21:22:57.527Z,1568323377.527 [DataOverHttps](INFO): SBD MOMSN=11777475 2019-09-12T21:23:18.080Z,1568323398.080 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212225/Courier0000.lzma 2019-09-12T21:23:20.086Z,1568323400.086 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212225/Courier0000.lzma.bak 2019-09-12T21:23:20.086Z,1568323400.086 [DataOverHttps](INFO): SBD MOMSN=11777480 2019-09-12T21:23:40.132Z,1568323420.132 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212225/Courier0003.lzma 2019-09-12T21:23:42.138Z,1568323422.138 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212225/Courier0003.lzma.bak 2019-09-12T21:23:42.139Z,1568323422.139 [DataOverHttps](INFO): SBD MOMSN=11777487 2019-09-12T21:24:04.976Z,1568323444.976 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212242/Courier0000.lzma 2019-09-12T21:24:06.982Z,1568323446.982 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0000.lzma.bak 2019-09-12T21:24:06.982Z,1568323446.982 [DataOverHttps](INFO): SBD MOMSN=11777489 2019-09-12T21:24:30.425Z,1568323470.425 [DataOverHttps](INFO): Sending 182 bytes from file Logs/20190912T204816/Express0019.lzma 2019-09-12T21:24:32.434Z,1568323472.434 [DataOverHttps](INFO): Moved sent file to Logs/20190912T204816/Express0019.lzma.bak 2019-09-12T21:24:32.435Z,1568323472.435 [DataOverHttps](INFO): SBD MOMSN=11777495 2019-09-12T21:24:55.139Z,1568323495.139 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T21:24:55.139Z,1568323495.139 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T21:24:58.153Z,1568323498.153 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T204816/Express0022.lzma 2019-09-12T21:25:00.158Z,1568323500.158 [DataOverHttps](INFO): Moved sent file to Logs/20190912T204816/Express0022.lzma.bak 2019-09-12T21:25:00.159Z,1568323500.159 [DataOverHttps](INFO): SBD MOMSN=11777499 2019-09-12T21:25:23.388Z,1568323523.388 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212225/Express0001.lzma 2019-09-12T21:25:25.395Z,1568323525.395 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212225/Express0001.lzma.bak 2019-09-12T21:25:25.395Z,1568323525.395 [DataOverHttps](INFO): SBD MOMSN=11777501 2019-09-12T21:25:49.489Z,1568323549.489 [DataOverHttps](INFO): Sending 308 bytes from file Logs/20190912T212225/Express0004.lzma 2019-09-12T21:25:51.494Z,1568323551.494 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212225/Express0004.lzma.bak 2019-09-12T21:25:51.495Z,1568323551.495 [DataOverHttps](INFO): SBD MOMSN=11777503 2019-09-12T21:25:57.763Z,1568323557.763 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-12T21:26:13.188Z,1568323573.188 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212242/Express0001.lzma 2019-09-12T21:26:15.194Z,1568323575.194 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0001.lzma.bak 2019-09-12T21:26:15.195Z,1568323575.195 [DataOverHttps](INFO): SBD MOMSN=11777513 2019-09-12T21:26:18.767Z,1568323578.767 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:26:18.767Z,1568323578.767 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19091221270, -0.1, 0.0,1448.9, 0 2019-09-12T21:26:21.244Z,1568323581.244 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:26:21.253Z,1568323581.253 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:26:21.253Z,1568323581.253 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:27:40.413Z,1568323660.413 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-12T21:27:40.413Z,1568323660.413 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,- 2019-09-12T21:29:40.774Z,1568323780.774 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T21:29:40.774Z,1568323780.774 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T21:31:21.794Z,1568323881.794 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:31:21.794Z,1568323881.794 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:31:21.794Z,1568323881.794 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:31:21.795Z,1568323881.795 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:31:22.228Z,1568323882.228 [Default:CheckIn:D] Stopped 2019-09-12T21:31:22.228Z,1568323882.228 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:31:22.596Z,1568323882.596 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 62.726111 min 2019-09-12T21:31:22.596Z,1568323882.596 [Default:CheckIn:E] Stopped 2019-09-12T21:31:22.596Z,1568323882.596 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:31:22.596Z,1568323882.596 [Default:CheckIn] Stopped 2019-09-12T21:31:22.596Z,1568323882.596 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:31:22.617Z,1568323882.617 [Default:CheckIn](INFO): Running loop #10 2019-09-12T21:31:22.617Z,1568323882.617 [Default:CheckIn] Running Loop=10 2019-09-12T21:31:22.617Z,1568323882.617 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:31:22.617Z,1568323882.617 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:31:24.193Z,1568323884.193 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:31:24.580Z,1568323884.580 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213126.00,A,3648.38635,N,12147.12303,W,4.665,172.53,120919,,,D*7D 2019-09-12T21:31:24.582Z,1568323884.582 [NAL9602](INFO): GPS fix at 20190912T213126: (36.806439, -121.785384) 2019-09-12T21:31:24.646Z,1568323884.646 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:31:24.646Z,1568323884.646 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:31:26.082Z,1568323886.082 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:31:28.463Z,1568323888.463 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190912T212242/Courier0003.lzma 2019-09-12T21:31:30.515Z,1568323890.515 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0003.lzma.bak 2019-09-12T21:31:30.515Z,1568323890.515 [DataOverHttps](INFO): SBD MOMSN=11777532 2019-09-12T21:31:45.451Z,1568323905.451 [NAL9602](INFO): SBD MO Status=0, MOMSN=1256, MT Status=0, MTMSN=0 2019-09-12T21:31:45.451Z,1568323905.451 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:31:51.845Z,1568323911.845 [DataOverHttps](INFO): Sending 338 bytes from file Logs/20190912T212242/Express0004.lzma 2019-09-12T21:31:53.851Z,1568323913.851 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0004.lzma.bak 2019-09-12T21:31:53.851Z,1568323913.851 [DataOverHttps](INFO): SBD MOMSN=11777535 2019-09-12T21:31:58.816Z,1568323918.816 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:31:58.816Z,1568323918.816 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:31:58.816Z,1568323918.816 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:32:16.154Z,1568323936.154 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:36:59.461Z,1568324219.461 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:36:59.461Z,1568324219.461 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:36:59.461Z,1568324219.461 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:36:59.461Z,1568324219.461 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:36:59.788Z,1568324219.788 [Default:CheckIn:D] Stopped 2019-09-12T21:36:59.788Z,1568324219.788 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:37:00.196Z,1568324220.196 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 68.352108 min 2019-09-12T21:37:00.196Z,1568324220.196 [Default:CheckIn:E] Stopped 2019-09-12T21:37:00.196Z,1568324220.196 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:37:00.196Z,1568324220.196 [Default:CheckIn] Stopped 2019-09-12T21:37:00.196Z,1568324220.196 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:37:00.197Z,1568324220.197 [Default:CheckIn](INFO): Running loop #11 2019-09-12T21:37:00.209Z,1568324220.209 [Default:CheckIn] Running Loop=11 2019-09-12T21:37:00.209Z,1568324220.209 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:37:00.209Z,1568324220.209 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:37:01.797Z,1568324221.797 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:37:02.192Z,1568324222.192 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213704.00,A,3648.14881,N,12147.22353,W,0.097,212.07,120919,,,D*79 2019-09-12T21:37:02.194Z,1568324222.194 [NAL9602](INFO): GPS fix at 20190912T213704: (36.802480, -121.787059) 2019-09-12T21:37:02.244Z,1568324222.244 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:37:02.244Z,1568324222.244 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:37:04.762Z,1568324224.762 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-12T21:37:04.762Z,1568324224.762 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00 +0.00, 0.00,4413.18 2019-09-12T21:37:05.007Z,1568324225.007 [DataOverHttps](INFO): Sending 60 bytes from file Logs/20190912T212242/Courier0006.lzma 2019-09-12T21:37:07.015Z,1568324227.015 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0006.lzma.bak 2019-09-12T21:37:07.015Z,1568324227.015 [DataOverHttps](INFO): SBD MOMSN=11777547 2019-09-12T21:37:22.494Z,1568324242.494 [NAL9602](INFO): SBD MO Status=0, MOMSN=1257, MT Status=0, MTMSN=0 2019-09-12T21:37:22.496Z,1568324242.496 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:37:30.656Z,1568324250.656 [DataOverHttps](INFO): Sending 117 bytes from file Logs/20190912T212242/Express0007.lzma 2019-09-12T21:37:32.662Z,1568324252.662 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0007.lzma.bak 2019-09-12T21:37:32.662Z,1568324252.662 [DataOverHttps](INFO): SBD MOMSN=11777550 2019-09-12T21:37:37.872Z,1568324257.872 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:37:37.873Z,1568324257.873 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:37:37.873Z,1568324257.873 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:37:53.182Z,1568324273.182 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:41:51.605Z,1568324511.605 [RDI_Pathfinder](ERROR): Failed to parse: : +0.00, +0.00 +0.00, 0.00,4699.04 2019-09-12T21:42:38.470Z,1568324558.470 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:42:38.470Z,1568324558.470 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:42:38.470Z,1568324558.470 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:42:38.471Z,1568324558.471 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:42:38.856Z,1568324558.856 [Default:CheckIn:D] Stopped 2019-09-12T21:42:38.856Z,1568324558.856 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 74.003239 min 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn:E] Stopped 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn] Stopped 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:42:39.263Z,1568324559.263 [Default:CheckIn](INFO): Running loop #12 2019-09-12T21:42:39.264Z,1568324559.264 [Default:CheckIn] Running Loop=12 2019-09-12T21:42:39.264Z,1568324559.264 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:42:39.264Z,1568324559.264 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:42:40.869Z,1568324560.869 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:42:41.256Z,1568324561.256 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214243.00,A,3648.14961,N,12147.22464,W,0.058,246.10,120919,,,D*70 2019-09-12T21:42:41.258Z,1568324561.258 [NAL9602](INFO): GPS fix at 20190912T214243: (36.802493, -121.787077) 2019-09-12T21:42:41.298Z,1568324561.298 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:42:41.298Z,1568324561.298 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:42:48.157Z,1568324568.157 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0009.lzma 2019-09-12T21:42:50.166Z,1568324570.166 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0009.lzma.bak 2019-09-12T21:42:50.166Z,1568324570.166 [DataOverHttps](INFO): SBD MOMSN=11777570 2019-09-12T21:43:00.769Z,1568324580.769 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T21:43:00.773Z,1568324580.773 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T21:43:02.763Z,1568324582.763 [NAL9602](INFO): SBD MO Status=2, MOMSN=1258, MT Status=2, MTMSN=0 2019-09-12T21:43:02.764Z,1568324582.764 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:43:11.636Z,1568324591.636 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T212242/Express0010.lzma 2019-09-12T21:43:13.642Z,1568324593.642 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0010.lzma.bak 2019-09-12T21:43:13.642Z,1568324593.642 [DataOverHttps](INFO): SBD MOMSN=11777573 2019-09-12T21:43:19.402Z,1568324599.402 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:43:19.402Z,1568324599.402 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:43:19.402Z,1568324599.402 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:43:34.283Z,1568324614.283 [NAL9602](INFO): SBD MO Status=2, MOMSN=1258, MT Status=2, MTMSN=0 2019-09-12T21:43:34.283Z,1568324614.283 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:43:57.319Z,1568324637.319 [NAL9602](INFO): SBD MO Status=2, MOMSN=1258, MT Status=2, MTMSN=0 2019-09-12T21:43:57.320Z,1568324637.320 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:44:13.068Z,1568324653.069 [NAL9602](INFO): SBD MO Status=2, MOMSN=1258, MT Status=2, MTMSN=0 2019-09-12T21:44:13.069Z,1568324653.069 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:44:39.773Z,1568324679.773 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T21:44:39.773Z,1568324679.773 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T21:44:51.452Z,1568324691.452 [NAL9602](INFO): SBD MO Status=2, MOMSN=1258, MT Status=2, MTMSN=0 2019-09-12T21:44:51.452Z,1568324691.452 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:45:02.359Z,1568324702.359 [NAL9602](INFO): SBD MO Status=0, MOMSN=1258, MT Status=0, MTMSN=0 2019-09-12T21:45:02.359Z,1568324702.359 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:45:33.071Z,1568324733.071 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:48:19.972Z,1568324899.972 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:48:19.972Z,1568324899.972 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:48:19.972Z,1568324899.972 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:48:19.981Z,1568324899.981 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:48:20.474Z,1568324900.474 [Default:CheckIn:D] Stopped 2019-09-12T21:48:20.474Z,1568324900.474 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:48:20.784Z,1568324900.784 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 79.696867 min 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn:E] Stopped 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn] Stopped 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn](INFO): Running loop #13 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn] Running Loop=13 2019-09-12T21:48:20.785Z,1568324900.785 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:48:20.786Z,1568324900.786 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:48:22.361Z,1568324902.361 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:48:22.752Z,1568324902.752 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214824.00,A,3648.14946,N,12147.22383,W,0.039,246.10,120919,,,D*77 2019-09-12T21:48:22.754Z,1568324902.754 [NAL9602](INFO): GPS fix at 20190912T214824: (36.802491, -121.787064) 2019-09-12T21:48:22.856Z,1568324902.856 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:48:22.857Z,1568324902.857 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:48:27.190Z,1568324907.190 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T212242/Courier0012.lzma 2019-09-12T21:48:29.198Z,1568324909.198 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0012.lzma.bak 2019-09-12T21:48:29.198Z,1568324909.198 [DataOverHttps](INFO): SBD MOMSN=11777586 2019-09-12T21:48:52.777Z,1568324932.777 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190912T212242/Express0013.lzma 2019-09-12T21:48:54.782Z,1568324934.782 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0013.lzma.bak 2019-09-12T21:48:54.783Z,1568324934.783 [DataOverHttps](INFO): SBD MOMSN=11777590 2019-09-12T21:49:00.515Z,1568324940.515 [NAL9602](INFO): SBD MO Status=2, MOMSN=1259, MT Status=2, MTMSN=0 2019-09-12T21:49:00.515Z,1568324940.515 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:49:00.956Z,1568324940.956 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:49:00.956Z,1568324940.956 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:49:00.956Z,1568324940.956 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:49:21.931Z,1568324961.931 [NAL9602](INFO): SBD MO Status=0, MOMSN=1259, MT Status=0, MTMSN=0 2019-09-12T21:49:21.931Z,1568324961.931 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:49:52.632Z,1568324992.632 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:54:01.545Z,1568325241.545 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:54:01.545Z,1568325241.545 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:54:01.545Z,1568325241.545 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:54:01.545Z,1568325241.545 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:54:01.930Z,1568325241.930 [Default:CheckIn:D] Stopped 2019-09-12T21:54:01.930Z,1568325241.930 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:54:02.348Z,1568325242.348 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 85.387817 min 2019-09-12T21:54:02.348Z,1568325242.348 [Default:CheckIn:E] Stopped 2019-09-12T21:54:02.348Z,1568325242.348 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:54:02.348Z,1568325242.348 [Default:CheckIn] Stopped 2019-09-12T21:54:02.353Z,1568325242.353 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:54:02.353Z,1568325242.353 [Default:CheckIn](INFO): Running loop #14 2019-09-12T21:54:02.353Z,1568325242.353 [Default:CheckIn] Running Loop=14 2019-09-12T21:54:02.353Z,1568325242.353 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:54:02.353Z,1568325242.353 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:54:03.933Z,1568325243.933 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:54:04.332Z,1568325244.332 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215406.00,A,3648.17249,N,12147.27399,W,3.032,298.14,120919,,,D*7C 2019-09-12T21:54:04.334Z,1568325244.334 [NAL9602](INFO): GPS fix at 20190912T215406: (36.802875, -121.787900) 2019-09-12T21:54:04.390Z,1568325244.390 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:54:04.390Z,1568325244.390 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:54:05.676Z,1568325245.676 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:54:08.224Z,1568325248.224 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0015.lzma 2019-09-12T21:54:10.234Z,1568325250.234 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0015.lzma.bak 2019-09-12T21:54:10.234Z,1568325250.234 [DataOverHttps](INFO): SBD MOMSN=11777607 2019-09-12T21:54:32.749Z,1568325272.749 [NAL9602](INFO): SBD MO Status=2, MOMSN=1260, MT Status=2, MTMSN=0 2019-09-12T21:54:32.749Z,1568325272.749 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:54:37.312Z,1568325277.312 [DataOverHttps](INFO): Sending 123 bytes from file Logs/20190912T212242/Express0016.lzma 2019-09-12T21:54:39.318Z,1568325279.318 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0016.lzma.bak 2019-09-12T21:54:39.319Z,1568325279.319 [DataOverHttps](INFO): SBD MOMSN=11777611 2019-09-12T21:54:44.492Z,1568325284.492 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:54:44.492Z,1568325284.492 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:54:44.492Z,1568325284.492 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:54:48.499Z,1568325288.499 [NAL9602](INFO): SBD MO Status=0, MOMSN=1260, MT Status=0, MTMSN=0 2019-09-12T21:54:48.499Z,1568325288.499 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:55:19.195Z,1568325319.195 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:56:36.411Z,1568325396.411 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-12T21:56:36.412Z,1568325396.412 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-2768,V 2019-09-12T21:59:45.064Z,1568325585.064 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:59:45.064Z,1568325585.064 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:59:45.064Z,1568325585.064 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:59:45.064Z,1568325585.064 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:59:45.476Z,1568325585.476 [Default:CheckIn:D] Stopped 2019-09-12T21:59:45.476Z,1568325585.476 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:59:45.882Z,1568325585.882 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 91.113574 min 2019-09-12T21:59:45.882Z,1568325585.882 [Default:CheckIn:E] Stopped 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn] Stopped 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn](INFO): Running loop #15 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn] Running Loop=15 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:59:45.883Z,1568325585.883 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:59:47.465Z,1568325587.465 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:59:47.872Z,1568325587.872 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215950.00,A,3648.16704,N,12147.28058,W,0.058,238.66,120919,,,D*7E 2019-09-12T21:59:47.874Z,1568325587.874 [NAL9602](INFO): GPS fix at 20190912T215950: (36.802784, -121.788010) 2019-09-12T21:59:47.920Z,1568325587.920 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:59:47.920Z,1568325587.920 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:59:53.565Z,1568325593.565 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0018.lzma 2019-09-12T21:59:55.574Z,1568325595.574 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0018.lzma.bak 2019-09-12T21:59:55.574Z,1568325595.574 [DataOverHttps](INFO): SBD MOMSN=11777631 2019-09-12T22:00:20.052Z,1568325620.052 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T212242/Express0019.lzma 2019-09-12T22:00:22.058Z,1568325622.058 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0019.lzma.bak 2019-09-12T22:00:22.059Z,1568325622.059 [DataOverHttps](INFO): SBD MOMSN=11777634 2019-09-12T22:00:30.407Z,1568325630.407 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:00:30.407Z,1568325630.407 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:00:32.567Z,1568325632.567 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:00:32.568Z,1568325632.568 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:00:32.568Z,1568325632.568 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:01:09.187Z,1568325669.187 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:01:09.187Z,1568325669.187 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:01:40.737Z,1568325700.737 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-12T22:01:46.407Z,1568325706.407 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-12T22:04:50.572Z,1568325890.572 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:05:21.277Z,1568325921.277 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:05:33.026Z,1568325933.026 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:05:33.026Z,1568325933.026 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:05:33.026Z,1568325933.026 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:05:33.027Z,1568325933.027 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:05:33.429Z,1568325933.429 [Default:CheckIn:D] Stopped 2019-09-12T22:05:33.430Z,1568325933.430 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:05:33.856Z,1568325933.856 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 96.912801 min 2019-09-12T22:05:33.856Z,1568325933.856 [Default:CheckIn:E] Stopped 2019-09-12T22:05:33.856Z,1568325933.856 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:05:33.856Z,1568325933.856 [Default:CheckIn] Stopped 2019-09-12T22:05:33.857Z,1568325933.857 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:05:33.857Z,1568325933.857 [Default:CheckIn](INFO): Running loop #16 2019-09-12T22:05:33.857Z,1568325933.857 [Default:CheckIn] Running Loop=16 2019-09-12T22:05:33.857Z,1568325933.857 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:05:33.857Z,1568325933.857 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:05:35.433Z,1568325935.433 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:05:35.828Z,1568325935.828 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220538.00,A,3648.16505,N,12147.28149,W,0.117,238.66,120919,,,A*77 2019-09-12T22:05:35.830Z,1568325935.830 [NAL9602](INFO): GPS fix at 20190912T220538: (36.802751, -121.788025) 2019-09-12T22:05:35.864Z,1568325935.864 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:05:35.864Z,1568325935.864 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:05:45.757Z,1568325945.757 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212242/Courier0021.lzma 2019-09-12T22:05:47.762Z,1568325947.762 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0021.lzma.bak 2019-09-12T22:05:47.763Z,1568325947.763 [DataOverHttps](INFO): SBD MOMSN=11777644 2019-09-12T22:06:06.526Z,1568325966.526 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:06:06.609Z,1568325966.609 [NAL9602](FAULT): received: +CSQ:0 OK61, 2, 0, 0, 0 OK 2019-09-12T22:06:06.609Z,1568325966.609 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:06:06.609Z,1568325966.609 [NAL9602](ERROR): Data Fault 2019-09-12T22:06:06.697Z,1568325966.697 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:06:06.930Z,1568325966.930 [NAL9602](INFO): Powering down 2019-09-12T22:06:07.808Z,1568325967.808 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:06:07.821Z,1568325967.821 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:06:09.913Z,1568325969.913 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190912T212242/Express0022.lzma 2019-09-12T22:06:11.906Z,1568325971.906 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0022.lzma.bak 2019-09-12T22:06:11.907Z,1568325971.907 [DataOverHttps](INFO): SBD MOMSN=11777647 2019-09-12T22:06:17.069Z,1568325977.069 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:06:17.070Z,1568325977.070 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:06:17.070Z,1568325977.070 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:06:37.246Z,1568325997.246 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:06:48.152Z,1568326008.152 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:07:19.262Z,1568326039.262 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:11:17.670Z,1568326277.670 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:11:17.670Z,1568326277.670 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:11:17.670Z,1568326277.670 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:11:17.670Z,1568326277.670 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:11:18.054Z,1568326278.054 [Default:CheckIn:D] Stopped 2019-09-12T22:11:18.054Z,1568326278.054 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:11:18.470Z,1568326278.470 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.656535 min 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn:E] Stopped 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn] Stopped 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn](INFO): Running loop #17 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn] Running Loop=17 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:11:18.471Z,1568326278.471 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:11:20.061Z,1568326280.061 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:11:20.452Z,1568326280.452 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221121.00,A,3648.16837,N,12147.28055,W,0.214,0.00,120919,,,A*73 2019-09-12T22:11:20.454Z,1568326280.454 [NAL9602](INFO): GPS fix at 20190912T221121: (36.802806, -121.788009) 2019-09-12T22:11:20.524Z,1568326280.524 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:11:20.524Z,1568326280.524 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:11:22.154Z,1568326282.154 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:11:25.287Z,1568326285.287 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0024.lzma 2019-09-12T22:11:27.294Z,1568326287.294 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0024.lzma.bak 2019-09-12T22:11:27.295Z,1568326287.295 [DataOverHttps](INFO): SBD MOMSN=11777667 2019-09-12T22:11:51.489Z,1568326311.489 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190912T212242/Express0025.lzma 2019-09-12T22:11:52.863Z,1568326312.863 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:11:53.496Z,1568326313.496 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0025.lzma.bak 2019-09-12T22:11:53.496Z,1568326313.496 [DataOverHttps](INFO): SBD MOMSN=11777670 2019-09-12T22:11:58.611Z,1568326318.611 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:11:58.611Z,1568326318.611 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:11:58.611Z,1568326318.611 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:12:20.346Z,1568326340.346 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2019-09-12T22:12:20.346Z,1568326340.346 [DropWeight] Hardware Fault, FailCount= 1 2019-09-12T22:12:20.347Z,1568326340.347 [DropWeight](ERROR): Hardware Fault 2019-09-12T22:12:20.427Z,1568326340.427 [CommandLine](FAULT): Scheduling is paused 2019-09-12T22:12:20.427Z,1568326340.427 [CBIT](INFO): Critical error at 20190912T221220 2019-09-12T22:12:20.433Z,1568326340.433 [CBIT](ERROR): Hardware Fault in component: DropWeight 2019-09-12T22:12:20.434Z,1568326340.434 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2019-09-12T22:12:20.779Z,1568326340.779 [CBIT](INFO): Critical error at 20190912T221220 2019-09-12T22:16:59.123Z,1568326619.123 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:16:59.124Z,1568326619.124 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:16:59.124Z,1568326619.124 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:16:59.124Z,1568326619.124 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:16:59.540Z,1568326619.540 [Default:CheckIn:D] Stopped 2019-09-12T22:16:59.540Z,1568326619.540 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:16:59.928Z,1568326619.928 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.347974 min 2019-09-12T22:16:59.928Z,1568326619.928 [Default:CheckIn:E] Stopped 2019-09-12T22:16:59.928Z,1568326619.928 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:16:59.928Z,1568326619.928 [Default:CheckIn] Stopped 2019-09-12T22:16:59.928Z,1568326619.928 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:16:59.945Z,1568326619.945 [Default:CheckIn](INFO): Running loop #18 2019-09-12T22:16:59.945Z,1568326619.945 [Default:CheckIn] Running Loop=18 2019-09-12T22:16:59.945Z,1568326619.945 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:16:59.945Z,1568326619.945 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:17:01.525Z,1568326621.525 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:17:01.919Z,1568326621.919 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221704.00,A,3648.16318,N,12147.27790,W,0.214,150.40,120919,,,A*75 2019-09-12T22:17:01.922Z,1568326621.922 [NAL9602](INFO): GPS fix at 20190912T221704: (36.802720, -121.787965) 2019-09-12T22:17:01.956Z,1568326621.956 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:17:01.956Z,1568326621.956 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:17:07.317Z,1568326627.317 [DataOverHttps](INFO): Sending 170 bytes from file Logs/20190912T212242/Courier0027.lzma 2019-09-12T22:17:09.330Z,1568326629.330 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0027.lzma.bak 2019-09-12T22:17:09.331Z,1568326629.331 [DataOverHttps](INFO): SBD MOMSN=11777681 2019-09-12T22:17:24.235Z,1568326644.235 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:17:24.235Z,1568326644.235 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:17:30.839Z,1568326650.839 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190912T212242/Express0028.lzma 2019-09-12T22:17:32.842Z,1568326652.842 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0028.lzma.bak 2019-09-12T22:17:32.843Z,1568326652.843 [DataOverHttps](INFO): SBD MOMSN=11777686 2019-09-12T22:17:38.820Z,1568326658.820 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:17:38.820Z,1568326658.820 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:17:38.820Z,1568326658.820 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:20:16.776Z,1568326816.776 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T22:20:16.776Z,1568326816.776 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T22:22:09.911Z,1568326929.911 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:22:09.911Z,1568326929.911 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:22:10.316Z,1568326930.316 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:22:39.445Z,1568326959.445 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:22:39.445Z,1568326959.445 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:22:39.445Z,1568326959.445 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:22:39.445Z,1568326959.445 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:22:39.849Z,1568326959.849 [Default:CheckIn:D] Stopped 2019-09-12T22:22:39.849Z,1568326959.849 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:22:40.237Z,1568326960.237 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 114.019792 min 2019-09-12T22:22:40.237Z,1568326960.237 [Default:CheckIn:E] Stopped 2019-09-12T22:22:40.237Z,1568326960.237 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:22:40.237Z,1568326960.237 [Default:CheckIn] Stopped 2019-09-12T22:22:40.237Z,1568326960.237 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:22:40.238Z,1568326960.238 [Default:CheckIn](INFO): Running loop #19 2019-09-12T22:22:40.238Z,1568326960.238 [Default:CheckIn] Running Loop=19 2019-09-12T22:22:40.238Z,1568326960.238 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:22:40.238Z,1568326960.238 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:22:41.845Z,1568326961.845 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:22:42.231Z,1568326962.231 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222244.00,A,3648.16861,N,12147.28244,W,0.019,85.88,120919,,,A*43 2019-09-12T22:22:42.246Z,1568326962.246 [NAL9602](INFO): GPS fix at 20190912T222244: (36.802810, -121.788041) 2019-09-12T22:22:42.276Z,1568326962.276 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:22:42.276Z,1568326962.276 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:22:47.079Z,1568326967.079 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T212242/Courier0030.lzma 2019-09-12T22:22:49.090Z,1568326969.090 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0030.lzma.bak 2019-09-12T22:22:49.091Z,1568326969.091 [DataOverHttps](INFO): SBD MOMSN=11777705 2019-09-12T22:22:59.378Z,1568326979.378 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-12T22:22:59.378Z,1568326979.378 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-2768,-32768,V 2019-09-12T22:23:10.369Z,1568326990.369 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20190912T212242/Express0031.lzma 2019-09-12T22:23:12.377Z,1568326992.377 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0031.lzma.bak 2019-09-12T22:23:12.377Z,1568326992.377 [DataOverHttps](INFO): SBD MOMSN=11777708 2019-09-12T22:23:14.658Z,1568326994.658 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:23:18.371Z,1568326998.371 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:23:18.371Z,1568326998.371 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:23:18.371Z,1568326998.371 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:23:20.781Z,1568327000.781 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-09-12T22:23:20.783Z,1568327000.783 [BPC1](INFO): Received data from all battery sticks. 2019-09-12T22:27:20.390Z,1568327240.390 [CBIT](INFO): Clearing failed state for component DropWeight 2019-09-12T22:27:20.390Z,1568327240.390 [DropWeight] No Fault, FailCount= 1 2019-09-12T22:28:18.917Z,1568327298.917 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:28:18.917Z,1568327298.917 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:28:18.917Z,1568327298.917 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:28:18.917Z,1568327298.917 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:28:19.402Z,1568327299.402 [Default:CheckIn:D] Stopped 2019-09-12T22:28:19.402Z,1568327299.402 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:28:19.729Z,1568327299.729 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.679012 min 2019-09-12T22:28:19.729Z,1568327299.729 [Default:CheckIn:E] Stopped 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn] Stopped 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn](INFO): Running loop #20 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn] Running Loop=20 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:28:19.730Z,1568327299.730 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:28:21.345Z,1568327301.345 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:28:21.736Z,1568327301.736 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222824.00,A,3648.16588,N,12147.27951,W,0.156,355.03,120919,,,A*72 2019-09-12T22:28:21.739Z,1568327301.739 [NAL9602](INFO): GPS fix at 20190912T222824: (36.802765, -121.787992) 2019-09-12T22:28:21.780Z,1568327301.780 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:28:21.780Z,1568327301.780 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:28:27.579Z,1568327307.579 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190912T212242/Courier0033.lzma 2019-09-12T22:28:29.590Z,1568327309.590 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0033.lzma.bak 2019-09-12T22:28:29.591Z,1568327309.591 [DataOverHttps](INFO): SBD MOMSN=11777719 2019-09-12T22:28:51.788Z,1568327331.788 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190912T212242/Express0034.lzma 2019-09-12T22:28:53.794Z,1568327333.794 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0034.lzma.bak 2019-09-12T22:28:53.795Z,1568327333.795 [DataOverHttps](INFO): SBD MOMSN=11777723 2019-09-12T22:28:59.216Z,1568327339.216 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:28:59.216Z,1568327339.216 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:28:59.216Z,1568327339.216 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:30:51.491Z,1568327451.491 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:30:51.492Z,1568327451.492 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:31:35.931Z,1568327495.931 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:31:35.931Z,1568327495.931 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:32:10.271Z,1568327530.271 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:32:10.272Z,1568327530.272 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:33:24.198Z,1568327604.198 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:33:54.902Z,1568327634.902 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:33:59.795Z,1568327639.795 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:33:59.796Z,1568327639.796 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:33:59.796Z,1568327639.796 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:33:59.796Z,1568327639.796 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:34:00.200Z,1568327640.200 [Default:CheckIn:D] Stopped 2019-09-12T22:34:00.200Z,1568327640.200 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:34:00.612Z,1568327640.612 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 125.358976 min 2019-09-12T22:34:00.612Z,1568327640.612 [Default:CheckIn:E] Stopped 2019-09-12T22:34:00.612Z,1568327640.612 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:34:00.612Z,1568327640.612 [Default:CheckIn] Stopped 2019-09-12T22:34:00.612Z,1568327640.612 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:34:00.613Z,1568327640.613 [Default:CheckIn](INFO): Running loop #21 2019-09-12T22:34:00.617Z,1568327640.617 [Default:CheckIn] Running Loop=21 2019-09-12T22:34:00.617Z,1568327640.617 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:34:00.617Z,1568327640.617 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:34:02.185Z,1568327642.185 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:34:02.580Z,1568327642.580 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223404.00,A,3648.16687,N,12147.28685,W,0.797,355.03,120919,,,A*73 2019-09-12T22:34:02.582Z,1568327642.582 [NAL9602](INFO): GPS fix at 20190912T223404: (36.802781, -121.788114) 2019-09-12T22:34:02.620Z,1568327642.620 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:34:02.620Z,1568327642.620 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:34:05.770Z,1568327645.770 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T212242/Courier0036.lzma 2019-09-12T22:34:07.778Z,1568327647.778 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0036.lzma.bak 2019-09-12T22:34:07.779Z,1568327647.779 [DataOverHttps](INFO): SBD MOMSN=11777743 2019-09-12T22:34:33.290Z,1568327673.290 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:34:33.369Z,1568327673.369 [NAL9602](FAULT): received: +CSQ:0 OK61, 2, 0, 0, 0 OK 2019-09-12T22:34:33.369Z,1568327673.369 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:34:33.369Z,1568327673.369 [NAL9602](ERROR): Data Fault 2019-09-12T22:34:33.430Z,1568327673.430 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:34:33.691Z,1568327673.691 [NAL9602](INFO): Powering down 2019-09-12T22:34:34.021Z,1568327674.021 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190912T212242/Express0037.lzma 2019-09-12T22:34:34.539Z,1568327674.539 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:34:34.539Z,1568327674.539 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:34:36.026Z,1568327676.026 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0037.lzma.bak 2019-09-12T22:34:36.027Z,1568327676.027 [DataOverHttps](INFO): SBD MOMSN=11777746 2019-09-12T22:34:41.447Z,1568327681.447 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:34:41.448Z,1568327681.448 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:34:41.448Z,1568327681.448 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:35:03.994Z,1568327703.994 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:35:14.924Z,1568327714.924 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:35:46.014Z,1568327746.014 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:37:33.530Z,1568327853.530 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-12T22:39:41.980Z,1568327981.980 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:39:41.980Z,1568327981.980 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:39:41.980Z,1568327981.980 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:39:41.980Z,1568327981.980 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:39:42.421Z,1568327982.421 [Default:CheckIn:D] Stopped 2019-09-12T22:39:42.421Z,1568327982.421 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:39:42.805Z,1568327982.805 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 131.062240 min 2019-09-12T22:39:42.805Z,1568327982.805 [Default:CheckIn:E] Stopped 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn] Stopped 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn](INFO): Running loop #22 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn] Running Loop=22 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:39:42.806Z,1568327982.806 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:39:44.385Z,1568327984.385 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:39:44.780Z,1568327984.780 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223946.00,A,3648.16511,N,12147.27441,W,0.408,173.27,120919,,,A*74 2019-09-12T22:39:44.782Z,1568327984.782 [NAL9602](INFO): GPS fix at 20190912T223946: (36.802752, -121.787907) 2019-09-12T22:39:44.833Z,1568327984.833 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:39:44.833Z,1568327984.833 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:39:46.902Z,1568327986.902 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:39:47.568Z,1568327987.568 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212242/Courier0039.lzma 2019-09-12T22:39:49.579Z,1568327989.579 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0039.lzma.bak 2019-09-12T22:39:49.579Z,1568327989.579 [DataOverHttps](INFO): SBD MOMSN=11777760 2019-09-12T22:40:10.905Z,1568328010.905 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20190912T212242/Express0040.lzma 2019-09-12T22:40:12.910Z,1568328012.910 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0040.lzma.bak 2019-09-12T22:40:12.911Z,1568328012.911 [DataOverHttps](INFO): SBD MOMSN=11777763 2019-09-12T22:40:17.606Z,1568328017.606 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:40:18.052Z,1568328018.052 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:40:18.053Z,1568328018.053 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:40:18.053Z,1568328018.053 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:45:18.682Z,1568328318.682 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:45:18.682Z,1568328318.682 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:45:18.682Z,1568328318.682 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:45:18.682Z,1568328318.682 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:45:19.057Z,1568328319.057 [Default:CheckIn:D] Stopped 2019-09-12T22:45:19.057Z,1568328319.057 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:45:19.480Z,1568328319.480 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 136.673258 min 2019-09-12T22:45:19.480Z,1568328319.480 [Default:CheckIn:E] Stopped 2019-09-12T22:45:19.480Z,1568328319.480 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:45:19.480Z,1568328319.480 [Default:CheckIn] Stopped 2019-09-12T22:45:19.480Z,1568328319.480 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:45:19.481Z,1568328319.481 [Default:CheckIn](INFO): Running loop #23 2019-09-12T22:45:19.481Z,1568328319.481 [Default:CheckIn] Running Loop=23 2019-09-12T22:45:19.481Z,1568328319.481 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:45:19.481Z,1568328319.481 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:45:21.073Z,1568328321.073 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:45:21.460Z,1568328321.460 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224523.00,A,3648.16607,N,12147.27986,W,0.175,173.27,120919,,,A*71 2019-09-12T22:45:21.462Z,1568328321.462 [NAL9602](INFO): GPS fix at 20190912T224523: (36.802768, -121.787998) 2019-09-12T22:45:21.512Z,1568328321.512 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:45:21.512Z,1568328321.512 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:45:31.728Z,1568328331.728 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212242/Courier0042.lzma 2019-09-12T22:45:33.734Z,1568328333.734 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0042.lzma.bak 2019-09-12T22:45:33.735Z,1568328333.735 [DataOverHttps](INFO): SBD MOMSN=11777783 2019-09-12T22:45:55.073Z,1568328355.073 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20190912T212242/Express0043.lzma 2019-09-12T22:45:57.078Z,1568328357.078 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0043.lzma.bak 2019-09-12T22:45:57.079Z,1568328357.079 [DataOverHttps](INFO): SBD MOMSN=11777786 2019-09-12T22:46:02.302Z,1568328362.302 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:46:02.303Z,1568328362.303 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:46:02.303Z,1568328362.303 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:46:12.780Z,1568328372.780 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:46:12.780Z,1568328372.780 [RDI_Pathfinder](ERROR): Failed to parse: :TS2471882,35.0, -0.1, 0.0,1448.9, 0 2019-09-12T22:46:17.617Z,1568328377.617 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:46:17.617Z,1568328377.617 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:48:27.359Z,1568328507.359 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-12T22:48:27.359Z,1568328507.359 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3268,V 2019-09-12T22:48:28.525Z,1568328508.525 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:48:28.525Z,1568328508.525 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:48:43.528Z,1568328523.528 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-12T22:48:43.528Z,1568328523.528 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00 +0.00, 0.00,8709.83 2019-09-12T22:48:49.942Z,1568328529.942 [NAL9602](INFO): SBD MO Status=2, MOMSN=1261, MT Status=2, MTMSN=0 2019-09-12T22:48:49.942Z,1568328529.942 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:50:23.268Z,1568328623.268 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:50:53.978Z,1568328653.978 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:51:02.926Z,1568328662.926 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:51:02.926Z,1568328662.926 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:51:02.926Z,1568328662.926 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:51:02.926Z,1568328662.926 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:51:03.316Z,1568328663.316 [Default:CheckIn:D] Stopped 2019-09-12T22:51:03.316Z,1568328663.316 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:51:03.731Z,1568328663.731 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 142.410905 min 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn:E] Stopped 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn] Stopped 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn](INFO): Running loop #24 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn] Running Loop=24 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:51:03.732Z,1568328663.732 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:51:05.297Z,1568328665.297 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:51:05.716Z,1568328665.716 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225107.00,A,3648.16766,N,12147.28520,W,0.233,109.70,120919,,,A*75 2019-09-12T22:51:05.726Z,1568328665.726 [NAL9602](INFO): GPS fix at 20190912T225107: (36.802794, -121.788087) 2019-09-12T22:51:05.828Z,1568328665.828 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:51:05.828Z,1568328665.828 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:51:09.134Z,1568328669.134 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0045.lzma 2019-09-12T22:51:11.142Z,1568328671.142 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0045.lzma.bak 2019-09-12T22:51:11.143Z,1568328671.143 [DataOverHttps](INFO): SBD MOMSN=11777797 2019-09-12T22:51:36.394Z,1568328696.394 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:51:36.477Z,1568328696.477 [NAL9602](FAULT): received: +CSQ:0 OK61, 2, 0, 0, 0 OK 2019-09-12T22:51:36.477Z,1568328696.477 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:51:36.477Z,1568328696.477 [NAL9602](ERROR): Data Fault 2019-09-12T22:51:36.552Z,1568328696.552 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:51:36.795Z,1568328696.795 [NAL9602](INFO): Powering down 2019-09-12T22:51:36.877Z,1568328696.877 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190912T212242/Express0046.lzma 2019-09-12T22:51:37.661Z,1568328697.661 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:51:37.661Z,1568328697.661 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:51:38.883Z,1568328698.883 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Express0046.lzma.bak 2019-09-12T22:51:38.883Z,1568328698.883 [DataOverHttps](INFO): SBD MOMSN=11777800 2019-09-12T22:51:44.107Z,1568328704.107 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:51:44.108Z,1568328704.108 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:51:44.108Z,1568328704.108 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:52:07.098Z,1568328727.098 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:52:18.006Z,1568328738.006 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:52:27.720Z,1568328747.720 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-12T22:52:27.721Z,1568328747.721 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-12T22:52:29.456Z,1568328749.456 [CBIT](IMPORTANT): Beginning ground fault scan 2019-09-12T22:52:40.267Z,1568328760.267 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.022311 CHAN A1 (24V): 0.124001 CHAN A2 (12V): 0.030590 CHAN A3 (5V): 0.008508 CHAN B0 (3.3V): 0.005799 CHAN B1 (3.15aV): 0.005046 CHAN B2 (3.15bV): 0.005452 CHAN B3 (GND): -0.004327 OPEN: 0.007359 Full Scale Calc: 4.765 mA, -1.589 mA 2019-09-12T22:52:49.122Z,1568328769.122 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:54:27.705Z,1568328867.705 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:54:27.706Z,1568328867.706 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19091222553382,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-12T22:56:44.762Z,1568329004.762 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:56:44.763Z,1568329004.763 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:56:44.763Z,1568329004.763 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:56:44.763Z,1568329004.763 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:56:45.084Z,1568329005.084 [Default:CheckIn:D] Stopped 2019-09-12T22:56:45.084Z,1568329005.084 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:56:45.544Z,1568329005.544 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 148.107048 min 2019-09-12T22:56:45.544Z,1568329005.544 [Default:CheckIn:E] Stopped 2019-09-12T22:56:45.544Z,1568329005.544 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:56:45.544Z,1568329005.544 [Default:CheckIn] Stopped 2019-09-12T22:56:45.544Z,1568329005.544 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:56:45.545Z,1568329005.545 [Default:CheckIn](INFO): Running loop #25 2019-09-12T22:56:45.553Z,1568329005.553 [Default:CheckIn] Running Loop=25 2019-09-12T22:56:45.553Z,1568329005.553 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:56:45.553Z,1568329005.553 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:56:47.091Z,1568329007.091 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:56:47.484Z,1568329007.484 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225649.00,A,3648.17036,N,12147.27825,W,0.253,258.26,120919,,,A*7E 2019-09-12T22:56:47.486Z,1568329007.486 [NAL9602](INFO): GPS fix at 20190912T225649: (36.802839, -121.787971) 2019-09-12T22:56:47.594Z,1568329007.594 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:56:47.594Z,1568329007.594 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:56:49.325Z,1568329009.325 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:56:58.730Z,1568329018.730 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212242/Courier0048.lzma 2019-09-12T22:57:00.739Z,1568329020.739 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212242/Courier0048.lzma.bak 2019-09-12T22:57:00.739Z,1568329020.739 [DataOverHttps](INFO): SBD MOMSN=11777813 2019-09-12T22:57:20.006Z,1568329040.006 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:57:21.622Z,1568329041.622 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2019-09-12T22:57:21.622Z,1568329041.622 [DropWeight] Hardware Fault, FailCount= 1 2019-09-12T22:57:21.622Z,1568329041.622 [DropWeight](ERROR): Hardware Fault 2019-09-12T22:57:21.701Z,1568329041.701 [CBIT](INFO): Critical error at 20190912T225721 2019-09-12T22:57:21.703Z,1568329041.703 [CBIT](ERROR): Hardware Fault in component: DropWeight 2019-09-12T22:57:21.703Z,1568329041.703 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2019-09-12T22:57:22.060Z,1568329042.060 [CBIT](INFO): Critical error at 20190912T225721 2019-09-12T22:57:30.354Z,1568329050.354 [CommandLine](IMPORTANT): got command quit 2019-09-12T22:57:31.358Z,1568329051.358 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:31.359Z,1568329051.359 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.477Z,1568329051.477 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-09-12T22:57:31.477Z,1568329051.477 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.478Z,1568329051.478 [CommandLine](INFO): Join timeout helper Thread ID is 3295 2019-09-12T22:57:31.478Z,1568329051.478 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-09-12T22:57:31.478Z,1568329051.478 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.479Z,1568329051.479 [NavChartDb](INFO): Join timeout helper Thread ID is 3296 2019-09-12T22:57:31.601Z,1568329051.601 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:31.602Z,1568329051.602 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.617Z,1568329051.617 [ComponentRegistry](INFO): Shutting down WetLabsUBAT ThreadHandler 2019-09-12T22:57:31.617Z,1568329051.617 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.617Z,1568329051.617 [WetLabsUBAT](INFO): Join timeout helper Thread ID is 3297 2019-09-12T22:57:31.669Z,1568329051.669 [WetLabsUBAT ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:31.669Z,1568329051.669 [WetLabsUBAT](INFO): Powering down 2019-09-12T22:57:31.670Z,1568329051.670 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.685Z,1568329051.685 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-09-12T22:57:31.685Z,1568329051.685 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:31.685Z,1568329051.685 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3298 2019-09-12T22:57:32.013Z,1568329052.013 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:32.014Z,1568329052.014 [WetLabsBB2FL](INFO): Powering down 2019-09-12T22:57:32.014Z,1568329052.014 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.033Z,1568329052.033 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-09-12T22:57:32.033Z,1568329052.033 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.033Z,1568329052.033 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3299 2019-09-12T22:57:32.089Z,1568329052.089 [CTD_Seabird](INFO): Powering down 2019-09-12T22:57:32.101Z,1568329052.101 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:32.101Z,1568329052.101 [CTD_Seabird](INFO): Powering down 2019-09-12T22:57:32.122Z,1568329052.122 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.124Z,1568329052.124 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-09-12T22:57:32.124Z,1568329052.124 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.124Z,1568329052.124 [Radio_Surface](INFO): Join timeout helper Thread ID is 3300 2019-09-12T22:57:32.149Z,1568329052.149 [DataOverHttps](INFO): Sending 369 bytes from file Logs/20190912T212242/Express0049.lzma 2019-09-12T22:57:32.485Z,1568329052.485 [Radio_Surface](INFO): Powering down 2019-09-12T22:57:32.486Z,1568329052.486 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:32.486Z,1568329052.486 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.494Z,1568329052.494 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-09-12T22:57:32.494Z,1568329052.494 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:32.494Z,1568329052.494 [DataOverHttps](INFO): Join timeout helper Thread ID is 3301 2019-09-12T22:57:33.149Z,1568329053.149 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:33.153Z,1568329053.153 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.155Z,1568329053.155 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-09-12T22:57:33.155Z,1568329053.155 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.156Z,1568329053.156 [logger](INFO): Join timeout helper Thread ID is 3302 2019-09-12T22:57:33.173Z,1568329053.173 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:33.173Z,1568329053.173 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.194Z,1568329053.194 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-09-12T22:57:33.194Z,1568329053.194 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.194Z,1568329053.194 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-09-12T22:57:33.194Z,1568329053.194 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.194Z,1568329053.194 [controlThread](INFO): Join timeout helper Thread ID is 3303 2019-09-12T22:57:33.321Z,1568329053.321 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T22:57:33.321Z,1568329053.321 [controlThread](DEBUG): Uninitializing ControlThread 2019-09-12T22:57:33.322Z,1568329053.322 [AHRS_M2](INFO): Powering down 2019-09-12T22:57:33.394Z,1568329053.394 [NAL9602](INFO): Powering down 2019-09-12T22:57:33.465Z,1568329053.465 [RDI_Pathfinder](INFO): Powering down 2019-09-12T22:57:33.466Z,1568329053.466 [DAT](INFO): Powering down 2019-09-12T22:57:33.585Z,1568329053.585 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-09-12T22:57:33.586Z,1568329053.586 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-09-12T22:57:33.587Z,1568329053.587 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-09-12T22:57:33.587Z,1568329053.587 [MissionManager](INFO): Uninitializing Mission Default 2019-09-12T22:57:33.587Z,1568329053.587 [Default] Stopped 2019-09-12T22:57:33.588Z,1568329053.588 [Default](DEBUG): Aggregate::uninitialize Default 2019-09-12T22:57:33.588Z,1568329053.588 [Default:B.GoToSurface] Stopped 2019-09-12T22:57:33.588Z,1568329053.588 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-09-12T22:57:33.588Z,1568329053.588 [Default:CheckIn] Stopped 2019-09-12T22:57:33.588Z,1568329053.588 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:57:33.588Z,1568329053.588 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:57:33.590Z,1568329053.590 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-09-12T22:57:33.591Z,1568329053.591 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-09-12T22:57:33.591Z,1568329053.591 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-09-12T22:57:33.591Z,1568329053.591 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-09-12T22:57:33.591Z,1568329053.591 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-09-12T22:57:33.591Z,1568329053.591 [BuoyancyServo](INFO): Powering down 2019-09-12T22:57:33.605Z,1568329053.605 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-09-12T22:57:33.605Z,1568329053.605 [ElevatorServo](INFO): Powering down 2019-09-12T22:57:33.606Z,1568329053.606 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-09-12T22:57:33.606Z,1568329053.606 [MassServo](INFO): Powering down 2019-09-12T22:57:33.607Z,1568329053.607 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-09-12T22:57:33.607Z,1568329053.607 [RudderServo](INFO): Powering down 2019-09-12T22:57:33.607Z,1568329053.607 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-09-12T22:57:33.608Z,1568329053.608 [ThrusterServo](INFO): Powering down 2019-09-12T22:57:33.608Z,1568329053.608 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-09-12T22:57:33.609Z,1568329053.609 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-09-12T22:57:33.609Z,1568329053.609 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-09-12T22:57:33.609Z,1568329053.609 [CBIT](DEBUG): Powering off loads. 2019-09-12T22:57:33.621Z,1568329053.621 [CBIT](DEBUG): Disabling WDT. 2019-09-12T22:57:33.633Z,1568329053.633 [CBIT](DEBUG): Opening all GF detection circuits. 2019-09-12T22:57:33.634Z,1568329053.634 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.738Z,1568329053.738 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.744Z,1568329053.744 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.803Z,1568329053.803 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.804Z,1568329053.804 [WetLabsUBAT](INFO): WetLabs destructor: dataLog is open - close it 2019-09-12T22:57:33.804Z,1568329053.804 [WetLabsUBAT](INFO): WetLabs destructor: done 2019-09-12T22:57:33.857Z,1568329053.857 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.859Z,1568329053.859 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.868Z,1568329053.868 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T22:57:33.968Z,1568329053.968 [logger ThreadHandler](INFO): Thread cancelled.