2019-11-14T18:23:38.345Z,1573755818.345 [DataOverHttps](INFO): Received command:restart logs 2019-11-14T18:23:38.358Z,1573755818.358 [CommandLine](IMPORTANT): got command restart logs 2019-11-14T18:26:35.251Z,1573755995.251 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T18:26:35.251Z,1573755995.251 [Default:CheckIn:C.Wait] Stopped 2019-11-14T18:26:35.251Z,1573755995.251 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T18:26:35.252Z,1573755995.252 [Default:CheckIn:D] Running Loop=1 2019-11-14T18:26:35.645Z,1573755995.645 [Default:CheckIn:D] Stopped 2019-11-14T18:26:35.645Z,1573755995.645 [Default:CheckIn:E] Running Loop=1 2019-11-14T18:26:36.116Z,1573755996.116 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.714886 min 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn:E] Stopped 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn] Stopped 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn](INFO): Running loop #4 2019-11-14T18:26:36.125Z,1573755996.125 [Default:CheckIn] Running Loop=4 2019-11-14T18:26:36.126Z,1573755996.126 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T18:26:36.126Z,1573755996.126 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T18:26:38.064Z,1573755998.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182640.00,A,3648.36393,N,12150.34480,W,8.942,229.91,141119,,,A*77 2019-11-14T18:26:38.084Z,1573755998.084 [NAL9602](INFO): GPS fix at 20191114T182640: (36.806066, -121.839080) 2019-11-14T18:26:38.201Z,1573755998.201 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T18:26:38.201Z,1573755998.201 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T18:27:14.972Z,1573756034.972 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191114T132832/Courier0055.lzma 2019-11-14T18:27:16.983Z,1573756036.983 [DataOverHttps](INFO): Moved sent file to Logs/20191114T132832/Courier0055.lzma.bak 2019-11-14T18:27:16.983Z,1573756036.983 [DataOverHttps](INFO): SBD MOMSN=12018120 2019-11-14T18:28:04.173Z,1573756084.173 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20191114T182338/Courier0000.lzma 2019-11-14T18:28:06.178Z,1573756086.178 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0000.lzma.bak 2019-11-14T18:28:06.178Z,1573756086.178 [DataOverHttps](INFO): SBD MOMSN=12018279 2019-11-14T18:28:55.832Z,1573756135.832 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191114T182338/Courier0004.lzma 2019-11-14T18:28:57.838Z,1573756137.838 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0004.lzma.bak 2019-11-14T18:28:57.838Z,1573756137.838 [DataOverHttps](INFO): SBD MOMSN=12018440 2019-11-14T18:29:44.821Z,1573756184.821 [DataOverHttps](INFO): Sending 180 bytes from file Logs/20191114T132832/Express0056.lzma 2019-11-14T18:29:46.823Z,1573756186.823 [DataOverHttps](INFO): Moved sent file to Logs/20191114T132832/Express0056.lzma.bak 2019-11-14T18:29:46.823Z,1573756186.823 [DataOverHttps](INFO): SBD MOMSN=12018603 2019-11-14T18:30:35.229Z,1573756235.229 [DataOverHttps](INFO): Sending 341 bytes from file Logs/20191114T182338/Express0001.lzma 2019-11-14T18:30:37.234Z,1573756237.234 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0001.lzma.bak 2019-11-14T18:30:37.235Z,1573756237.235 [DataOverHttps](INFO): SBD MOMSN=12018763 2019-11-14T18:31:34.268Z,1573756294.268 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191114T182338/Express0006.lzma 2019-11-14T18:31:36.276Z,1573756296.276 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0006.lzma.bak 2019-11-14T18:31:36.276Z,1573756296.276 [DataOverHttps](INFO): SBD MOMSN=12018919 2019-11-14T18:31:37.588Z,1573756297.588 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T18:31:37.588Z,1573756297.588 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T18:31:37.588Z,1573756297.588 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T18:31:40.778Z,1573756300.778 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T18:32:11.482Z,1573756331.482 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T18:36:38.241Z,1573756598.241 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T18:36:38.241Z,1573756598.241 [Default:CheckIn:C.Wait] Stopped 2019-11-14T18:36:38.241Z,1573756598.241 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T18:36:38.241Z,1573756598.241 [Default:CheckIn:D] Running Loop=1 2019-11-14T18:36:38.623Z,1573756598.623 [Default:CheckIn:D] Stopped 2019-11-14T18:36:38.623Z,1573756598.623 [Default:CheckIn:E] Running Loop=1 2019-11-14T18:36:39.040Z,1573756599.040 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.764514 min 2019-11-14T18:36:39.040Z,1573756599.040 [Default:CheckIn:E] Stopped 2019-11-14T18:36:39.040Z,1573756599.040 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T18:36:39.040Z,1573756599.040 [Default:CheckIn] Stopped 2019-11-14T18:36:39.041Z,1573756599.041 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T18:36:39.041Z,1573756599.041 [Default:CheckIn](INFO): Running loop #5 2019-11-14T18:36:39.041Z,1573756599.041 [Default:CheckIn] Running Loop=5 2019-11-14T18:36:39.041Z,1573756599.041 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T18:36:39.041Z,1573756599.041 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T18:36:41.028Z,1573756601.028 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183642.00,A,3648.55482,N,12149.40209,W,1.400,300.18,141119,,,A*73 2019-11-14T18:36:41.043Z,1573756601.043 [NAL9602](INFO): GPS fix at 20191114T183642: (36.809247, -121.823368) 2019-11-14T18:36:41.078Z,1573756601.078 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T18:36:41.078Z,1573756601.078 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T18:36:48.361Z,1573756608.361 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0003.lzma 2019-11-14T18:36:50.366Z,1573756610.366 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0003.lzma.bak 2019-11-14T18:36:50.367Z,1573756610.367 [DataOverHttps](INFO): SBD MOMSN=12019572 2019-11-14T18:37:08.121Z,1573756628.121 [DataOverHttps](INFO): Sending 232 bytes from file Logs/20191114T182338/Express0005.lzma 2019-11-14T18:37:10.126Z,1573756630.126 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0005.lzma.bak 2019-11-14T18:37:10.126Z,1573756630.126 [DataOverHttps](INFO): SBD MOMSN=12019575 2019-11-14T18:37:11.412Z,1573756631.412 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T18:37:11.412Z,1573756631.412 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T18:37:11.412Z,1573756631.412 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T18:37:11.791Z,1573756631.791 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T18:37:11.869Z,1573756631.869 [NAL9602](FAULT): received: +CSQ:0 OK53, 2, 0, 0, 0 OK 2019-11-14T18:37:11.870Z,1573756631.870 [NAL9602] Data Fault, FailCount= 1 2019-11-14T18:37:11.870Z,1573756631.870 [NAL9602](ERROR): Data Fault 2019-11-14T18:37:11.961Z,1573756631.961 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T18:37:12.190Z,1573756632.190 [NAL9602](INFO): Powering down 2019-11-14T18:37:13.040Z,1573756633.040 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T18:37:13.040Z,1573756633.040 [NAL9602] No Fault, FailCount= 1 2019-11-14T18:37:42.486Z,1573756662.486 [NAL9602](INFO): Powering up NAL9602 2019-11-14T18:37:53.394Z,1573756673.394 [NAL9602](INFO): NAL9602 initialized 2019-11-14T18:38:24.502Z,1573756704.502 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T18:39:48.194Z,1573756788.194 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T18:39:48.194Z,1573756788.194 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T18:42:12.015Z,1573756932.015 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T18:42:12.016Z,1573756932.016 [Default:CheckIn:C.Wait] Stopped 2019-11-14T18:42:12.016Z,1573756932.016 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T18:42:12.016Z,1573756932.016 [Default:CheckIn:D] Running Loop=1 2019-11-14T18:42:12.398Z,1573756932.398 [Default:CheckIn:D] Stopped 2019-11-14T18:42:12.398Z,1573756932.398 [Default:CheckIn:E] Running Loop=1 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.327425 min 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn:E] Stopped 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn] Stopped 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T18:42:12.866Z,1573756932.866 [Default:CheckIn](INFO): Running loop #6 2019-11-14T18:42:12.867Z,1573756932.867 [Default:CheckIn] Running Loop=6 2019-11-14T18:42:12.867Z,1573756932.867 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T18:42:12.867Z,1573756932.867 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T18:42:14.802Z,1573756934.802 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184215.00,A,3648.60637,N,12149.45450,W,0.894,321.62,141119,,,A*79 2019-11-14T18:42:14.804Z,1573756934.804 [NAL9602](INFO): GPS fix at 20191114T184215: (36.810106, -121.824242) 2019-11-14T18:42:14.885Z,1573756934.885 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T18:42:14.885Z,1573756934.885 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T18:42:16.414Z,1573756936.414 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T18:42:22.981Z,1573756942.981 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0009.lzma 2019-11-14T18:42:24.986Z,1573756944.986 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0009.lzma.bak 2019-11-14T18:42:24.987Z,1573756944.987 [DataOverHttps](INFO): SBD MOMSN=12019597 2019-11-14T18:42:42.569Z,1573756962.569 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20191114T182338/Express0010.lzma 2019-11-14T18:42:44.574Z,1573756964.574 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0010.lzma.bak 2019-11-14T18:42:44.575Z,1573756964.575 [DataOverHttps](INFO): SBD MOMSN=12019600 2019-11-14T18:42:45.955Z,1573756965.955 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T18:42:45.955Z,1573756965.955 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T18:42:45.955Z,1573756965.955 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T18:42:47.126Z,1573756967.126 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T18:47:46.546Z,1573757266.546 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T18:47:46.546Z,1573757266.546 [Default:CheckIn:C.Wait] Stopped 2019-11-14T18:47:46.546Z,1573757266.546 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T18:47:46.546Z,1573757266.546 [Default:CheckIn:D] Running Loop=1 2019-11-14T18:47:46.949Z,1573757266.949 [Default:CheckIn:D] Stopped 2019-11-14T18:47:46.949Z,1573757266.949 [Default:CheckIn:E] Running Loop=1 2019-11-14T18:47:47.349Z,1573757267.349 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.903284 min 2019-11-14T18:47:47.349Z,1573757267.349 [Default:CheckIn:E] Stopped 2019-11-14T18:47:47.349Z,1573757267.349 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T18:47:47.349Z,1573757267.349 [Default:CheckIn] Stopped 2019-11-14T18:47:47.350Z,1573757267.350 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T18:47:47.350Z,1573757267.350 [Default:CheckIn](INFO): Running loop #7 2019-11-14T18:47:47.350Z,1573757267.350 [Default:CheckIn] Running Loop=7 2019-11-14T18:47:47.350Z,1573757267.350 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T18:47:47.350Z,1573757267.350 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T18:47:49.336Z,1573757269.336 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184751.00,A,3648.61786,N,12149.49013,W,1.244,313.16,141119,,,A*7D 2019-11-14T18:47:49.338Z,1573757269.338 [NAL9602](INFO): GPS fix at 20191114T184751: (36.810298, -121.824836) 2019-11-14T18:47:49.391Z,1573757269.391 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T18:47:49.391Z,1573757269.391 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T18:47:52.188Z,1573757272.188 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T18:47:52.188Z,1573757272.188 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T18:47:57.124Z,1573757277.124 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0012.lzma 2019-11-14T18:47:59.130Z,1573757279.130 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0012.lzma.bak 2019-11-14T18:47:59.131Z,1573757279.131 [DataOverHttps](INFO): SBD MOMSN=12020275 2019-11-14T18:48:06.707Z,1573757286.707 [NAL9602](INFO): SBD MO Status=2, MOMSN=5153, MT Status=2, MTMSN=0 2019-11-14T18:48:06.708Z,1573757286.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T18:48:37.838Z,1573757317.838 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20191114T182338/Express0013.lzma 2019-11-14T18:48:39.844Z,1573757319.844 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0013.lzma.bak 2019-11-14T18:48:39.845Z,1573757319.845 [DataOverHttps](INFO): SBD MOMSN=12020439 2019-11-14T18:48:41.099Z,1573757321.099 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T18:48:41.100Z,1573757321.100 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T18:48:41.100Z,1573757321.100 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T18:49:32.776Z,1573757372.776 [NAL9602](INFO): SBD MO Status=2, MOMSN=5153, MT Status=2, MTMSN=0 2019-11-14T18:49:32.776Z,1573757372.776 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T18:51:21.855Z,1573757481.855 [NAL9602](INFO): SBD MO Status=0, MOMSN=5153, MT Status=0, MTMSN=0 2019-11-14T18:51:21.856Z,1573757481.856 [NAL9602](INFO): No messages in MT queue 2019-11-14T18:51:21.856Z,1573757481.856 [NAL9602](INFO): Failure count cleared after critical for NAL9602 2019-11-14T18:51:52.554Z,1573757512.554 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T18:53:41.656Z,1573757621.656 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T18:53:41.657Z,1573757621.657 [Default:CheckIn:C.Wait] Stopped 2019-11-14T18:53:41.657Z,1573757621.657 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T18:53:41.657Z,1573757621.657 [Default:CheckIn:D] Running Loop=1 2019-11-14T18:53:42.076Z,1573757622.076 [Default:CheckIn:D] Stopped 2019-11-14T18:53:42.076Z,1573757622.076 [Default:CheckIn:E] Running Loop=1 2019-11-14T18:53:42.480Z,1573757622.480 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.822066 min 2019-11-14T18:53:42.480Z,1573757622.480 [Default:CheckIn:E] Stopped 2019-11-14T18:53:42.480Z,1573757622.480 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T18:53:42.480Z,1573757622.480 [Default:CheckIn] Stopped 2019-11-14T18:53:42.481Z,1573757622.481 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T18:53:42.481Z,1573757622.481 [Default:CheckIn](INFO): Running loop #8 2019-11-14T18:53:42.481Z,1573757622.481 [Default:CheckIn] Running Loop=8 2019-11-14T18:53:42.481Z,1573757622.481 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T18:53:42.481Z,1573757622.481 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T18:53:44.468Z,1573757624.468 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185346.00,A,3648.38836,N,12148.48544,W,26.747,101.20,141119,,,A*46 2019-11-14T18:53:44.470Z,1573757624.470 [NAL9602](INFO): GPS fix at 20191114T185346: (36.806473, -121.808091) 2019-11-14T18:53:44.514Z,1573757624.514 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T18:53:44.515Z,1573757624.515 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T18:54:32.143Z,1573757672.143 [NAL9602](INFO): SBD MO Status=0, MOMSN=5154, MT Status=0, MTMSN=0 2019-11-14T18:54:32.144Z,1573757672.144 [NAL9602](INFO): No messages in MT queue 2019-11-14T18:55:02.866Z,1573757702.866 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T18:56:09.558Z,1573757769.558 [RDI_Pathfinder](ERROR): Failed to parse:.00, 0.00, 0.00, 0.00, 0.00 2019-11-14T18:57:23.424Z,1573757843.424 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0015.lzma 2019-11-14T18:57:25.430Z,1573757845.430 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0015.lzma.bak 2019-11-14T18:57:25.431Z,1573757845.431 [DataOverHttps](INFO): SBD MOMSN=12022039 2019-11-14T18:58:22.057Z,1573757902.057 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20191114T182338/Express0016.lzma 2019-11-14T18:58:24.062Z,1573757904.062 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0016.lzma.bak 2019-11-14T18:58:24.063Z,1573757904.063 [DataOverHttps](INFO): SBD MOMSN=12022203 2019-11-14T18:58:25.300Z,1573757905.300 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T18:58:25.301Z,1573757905.301 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T18:58:25.301Z,1573757905.301 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T18:58:54.856Z,1573757934.856 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T18:58:54.856Z,1573757934.856 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-3:BE,-32768,-32768,-32768,V 2019-11-14T18:59:48.560Z,1573757988.560 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T18:59:48.560Z,1573757988.560 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T19:03:25.956Z,1573758205.956 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:03:25.956Z,1573758205.956 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:03:25.956Z,1573758205.956 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:03:25.956Z,1573758205.956 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:03:26.368Z,1573758206.368 [Default:CheckIn:D] Stopped 2019-11-14T19:03:26.368Z,1573758206.368 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:03:26.773Z,1573758206.773 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.560262 min 2019-11-14T19:03:26.773Z,1573758206.773 [Default:CheckIn:E] Stopped 2019-11-14T19:03:26.773Z,1573758206.773 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:03:26.773Z,1573758206.773 [Default:CheckIn] Stopped 2019-11-14T19:03:26.774Z,1573758206.774 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:03:26.774Z,1573758206.774 [Default:CheckIn](INFO): Running loop #9 2019-11-14T19:03:26.774Z,1573758206.774 [Default:CheckIn] Running Loop=9 2019-11-14T19:03:26.774Z,1573758206.774 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:03:26.774Z,1573758206.774 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:03:28.756Z,1573758208.756 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190330.00,A,3648.16413,N,12147.21581,W,0.058,231.02,141119,,,D*75 2019-11-14T19:03:28.758Z,1573758208.758 [NAL9602](INFO): GPS fix at 20191114T190330: (36.802735, -121.786930) 2019-11-14T19:03:28.788Z,1573758208.788 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:03:28.788Z,1573758208.788 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:03:34.471Z,1573758214.471 [NAL9602](INFO): SBD MO Status=0, MOMSN=5155, MT Status=0, MTMSN=0 2019-11-14T19:03:34.471Z,1573758214.471 [NAL9602](INFO): No messages in MT queue 2019-11-14T19:03:45.748Z,1573758225.748 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0018.lzma 2019-11-14T19:03:47.754Z,1573758227.754 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0018.lzma.bak 2019-11-14T19:03:47.754Z,1573758227.754 [DataOverHttps](INFO): SBD MOMSN=12023146 2019-11-14T19:04:05.171Z,1573758245.171 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:04:45.249Z,1573758285.249 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20191114T182338/Express0019.lzma 2019-11-14T19:04:47.254Z,1573758287.254 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0019.lzma.bak 2019-11-14T19:04:47.255Z,1573758287.255 [DataOverHttps](INFO): SBD MOMSN=12023307 2019-11-14T19:04:48.480Z,1573758288.480 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:04:48.480Z,1573758288.480 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:04:48.480Z,1573758288.480 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:09:49.090Z,1573758589.090 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:09:49.090Z,1573758589.090 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:09:49.090Z,1573758589.090 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:09:49.091Z,1573758589.091 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:09:49.511Z,1573758589.511 [Default:CheckIn:D] Stopped 2019-11-14T19:09:49.511Z,1573758589.511 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.945984 min 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn:E] Stopped 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn] Stopped 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn](INFO): Running loop #10 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn] Running Loop=10 2019-11-14T19:09:49.906Z,1573758589.906 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:09:49.907Z,1573758589.907 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:09:51.870Z,1573758591.870 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190953.00,A,3648.15562,N,12147.22091,W,0.019,211.80,141119,,,D*74 2019-11-14T19:09:51.873Z,1573758591.873 [NAL9602](INFO): GPS fix at 20191114T190953: (36.802594, -121.787015) 2019-11-14T19:09:51.976Z,1573758591.976 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:09:51.976Z,1573758591.976 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:10:18.969Z,1573758618.969 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0021.lzma 2019-11-14T19:10:20.975Z,1573758620.975 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0021.lzma.bak 2019-11-14T19:10:20.975Z,1573758620.975 [DataOverHttps](INFO): SBD MOMSN=12024246 2019-11-14T19:10:54.519Z,1573758654.519 [NAL9602](INFO): SBD MO Status=0, MOMSN=5156, MT Status=0, MTMSN=0 2019-11-14T19:10:54.519Z,1573758654.519 [NAL9602](INFO): No messages in MT queue 2019-11-14T19:11:19.673Z,1573758679.673 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191114T182338/Express0022.lzma 2019-11-14T19:11:21.678Z,1573758681.678 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0022.lzma.bak 2019-11-14T19:11:21.679Z,1573758681.679 [DataOverHttps](INFO): SBD MOMSN=12024411 2019-11-14T19:11:22.867Z,1573758682.867 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:11:22.868Z,1573758682.868 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:11:22.868Z,1573758682.868 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:11:25.218Z,1573758685.218 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:13:52.744Z,1573758832.744 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-14T19:13:52.750Z,1573758832.750 [BPC1](INFO): Received data from all battery sticks. 2019-11-14T19:16:23.445Z,1573758983.445 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:16:23.445Z,1573758983.445 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:16:23.445Z,1573758983.445 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:16:23.445Z,1573758983.445 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:16:23.856Z,1573758983.856 [Default:CheckIn:D] Stopped 2019-11-14T19:16:23.856Z,1573758983.856 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:16:24.253Z,1573758984.253 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 72.518408 min 2019-11-14T19:16:24.253Z,1573758984.253 [Default:CheckIn:E] Stopped 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn] Stopped 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn](INFO): Running loop #11 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn] Running Loop=11 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:16:24.254Z,1573758984.254 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:16:26.240Z,1573758986.240 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191628.00,A,3648.17581,N,12147.27977,W,0.156,300.85,141119,,,D*73 2019-11-14T19:16:26.242Z,1573758986.242 [NAL9602](INFO): GPS fix at 20191114T191628: (36.802930, -121.787996) 2019-11-14T19:16:26.286Z,1573758986.286 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:16:26.286Z,1573758986.286 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:16:34.293Z,1573758994.293 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20191114T182338/Courier0024.lzma 2019-11-14T19:16:36.298Z,1573758996.298 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0024.lzma.bak 2019-11-14T19:16:36.299Z,1573758996.299 [DataOverHttps](INFO): SBD MOMSN=12038356 2019-11-14T19:16:46.048Z,1573759006.048 [NAL9602](INFO): SBD MO Status=0, MOMSN=5157, MT Status=0, MTMSN=0 2019-11-14T19:16:46.048Z,1573759006.048 [NAL9602](INFO): No messages in MT queue 2019-11-14T19:17:05.521Z,1573759025.521 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191114T182338/Express0025.lzma 2019-11-14T19:17:07.527Z,1573759027.527 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0025.lzma.bak 2019-11-14T19:17:07.527Z,1573759027.527 [DataOverHttps](INFO): SBD MOMSN=12038828 2019-11-14T19:17:08.700Z,1573759028.700 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:17:08.700Z,1573759028.700 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:17:08.700Z,1573759028.700 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:17:16.754Z,1573759036.754 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:20:25.883Z,1573759225.883 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T19:20:25.883Z,1573759225.883 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-2768,-32768,V 2019-11-14T19:22:09.291Z,1573759329.291 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:22:09.291Z,1573759329.291 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:22:09.292Z,1573759329.292 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:22:09.292Z,1573759329.292 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:22:09.676Z,1573759329.676 [Default:CheckIn:D] Stopped 2019-11-14T19:22:09.676Z,1573759329.676 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:22:10.098Z,1573759330.098 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 78.282064 min 2019-11-14T19:22:10.098Z,1573759330.098 [Default:CheckIn:E] Stopped 2019-11-14T19:22:10.098Z,1573759330.098 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:22:10.098Z,1573759330.098 [Default:CheckIn] Stopped 2019-11-14T19:22:10.099Z,1573759330.099 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:22:10.099Z,1573759330.099 [Default:CheckIn](INFO): Running loop #12 2019-11-14T19:22:10.099Z,1573759330.099 [Default:CheckIn] Running Loop=12 2019-11-14T19:22:10.099Z,1573759330.099 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:22:10.099Z,1573759330.099 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:22:12.084Z,1573759332.084 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192214.00,A,3648.17699,N,12147.27884,W,0.039,266.66,141119,,,D*78 2019-11-14T19:22:12.097Z,1573759332.097 [NAL9602](INFO): GPS fix at 20191114T192214: (36.802950, -121.787981) 2019-11-14T19:22:12.131Z,1573759332.131 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:22:12.131Z,1573759332.131 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:22:19.829Z,1573759339.829 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0027.lzma 2019-11-14T19:22:21.834Z,1573759341.834 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0027.lzma.bak 2019-11-14T19:22:21.835Z,1573759341.835 [DataOverHttps](INFO): SBD MOMSN=12042899 2019-11-14T19:23:05.433Z,1573759385.433 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0028.lzma 2019-11-14T19:23:07.438Z,1573759387.438 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0028.lzma.bak 2019-11-14T19:23:07.439Z,1573759387.439 [DataOverHttps](INFO): SBD MOMSN=12043580 2019-11-14T19:23:08.692Z,1573759388.692 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:23:08.692Z,1573759388.692 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:23:08.692Z,1573759388.692 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:27:00.198Z,1573759620.198 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T19:27:00.198Z,1573759620.198 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T19:27:14.697Z,1573759634.697 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T19:27:45.394Z,1573759665.394 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:28:09.281Z,1573759689.281 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:28:09.281Z,1573759689.281 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:28:09.281Z,1573759689.281 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:28:09.282Z,1573759689.282 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:28:09.683Z,1573759689.683 [Default:CheckIn:D] Stopped 2019-11-14T19:28:09.683Z,1573759689.683 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:28:10.077Z,1573759690.077 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 84.282186 min 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn:E] Stopped 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn] Stopped 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn](INFO): Running loop #13 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn] Running Loop=13 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:28:10.078Z,1573759690.078 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:28:12.064Z,1573759692.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192814.00,A,3648.16479,N,12147.28311,W,0.194,216.77,141119,,,A*73 2019-11-14T19:28:12.067Z,1573759692.067 [NAL9602](INFO): GPS fix at 20191114T192814: (36.802746, -121.788052) 2019-11-14T19:28:12.121Z,1573759692.121 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:28:12.121Z,1573759692.121 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:28:19.852Z,1573759699.852 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0030.lzma 2019-11-14T19:28:21.858Z,1573759701.858 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0030.lzma.bak 2019-11-14T19:28:21.859Z,1573759701.859 [DataOverHttps](INFO): SBD MOMSN=12047179 2019-11-14T19:28:39.305Z,1573759719.305 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20191114T182338/Express0031.lzma 2019-11-14T19:28:41.311Z,1573759721.311 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0031.lzma.bak 2019-11-14T19:28:41.311Z,1573759721.311 [DataOverHttps](INFO): SBD MOMSN=12047339 2019-11-14T19:28:42.788Z,1573759722.788 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T19:28:42.861Z,1573759722.861 [NAL9602](FAULT): received: +CSQ:0 OK57, 0, 0, 0, 0 OK 2019-11-14T19:28:42.861Z,1573759722.861 [NAL9602] Data Fault, FailCount= 1 2019-11-14T19:28:42.861Z,1573759722.861 [NAL9602](ERROR): Data Fault 2019-11-14T19:28:42.930Z,1573759722.930 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:28:42.930Z,1573759722.930 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:28:42.930Z,1573759722.930 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:28:42.951Z,1573759722.951 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T19:28:43.182Z,1573759723.182 [NAL9602](INFO): Powering down 2019-11-14T19:28:44.070Z,1573759724.070 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T19:28:44.070Z,1573759724.070 [NAL9602] No Fault, FailCount= 1 2019-11-14T19:29:13.474Z,1573759753.474 [NAL9602](INFO): Powering up NAL9602 2019-11-14T19:29:24.382Z,1573759764.382 [NAL9602](INFO): NAL9602 initialized 2019-11-14T19:29:34.522Z,1573759774.522 [CBIT](IMPORTANT): Beginning ground fault scan 2019-11-14T19:29:45.424Z,1573759785.424 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.014344 CHAN A1 (24V): 0.064332 CHAN A2 (12V): 0.019311 CHAN A3 (5V): 0.006719 CHAN B0 (3.3V): 0.004583 CHAN B1 (3.15aV): 0.004272 CHAN B2 (3.15bV): 0.004742 CHAN B3 (GND): 0.000986 OPEN: 0.005956 Full Scale Calc: 4.765 mA, -1.589 mA 2019-11-14T19:29:55.490Z,1573759795.490 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:33:43.405Z,1573760023.405 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:33:43.405Z,1573760023.405 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:33:43.405Z,1573760023.405 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:33:43.405Z,1573760023.405 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:33:43.861Z,1573760023.861 [Default:CheckIn:D] Stopped 2019-11-14T19:33:43.861Z,1573760023.861 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.851823 min 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn:E] Stopped 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn] Stopped 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:33:44.219Z,1573760024.219 [Default:CheckIn](INFO): Running loop #14 2019-11-14T19:33:44.220Z,1573760024.220 [Default:CheckIn] Running Loop=14 2019-11-14T19:33:44.220Z,1573760024.220 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:33:44.220Z,1573760024.220 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:33:46.212Z,1573760026.212 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193348.00,A,3648.16015,N,12147.27822,W,0.214,0.00,141119,,,A*74 2019-11-14T19:33:46.214Z,1573760026.214 [NAL9602](INFO): GPS fix at 20191114T193348: (36.802669, -121.787970) 2019-11-14T19:33:46.252Z,1573760026.252 [RDI_Pathfinder](ERROR): Failed to parse: 00, 0.00, 0.00, 0.00, 0.00 2019-11-14T19:33:46.261Z,1573760026.261 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:33:46.261Z,1573760026.261 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:33:48.230Z,1573760028.230 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T19:34:14.752Z,1573760054.752 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T182338/Courier0033.lzma 2019-11-14T19:34:16.758Z,1573760056.758 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0033.lzma.bak 2019-11-14T19:34:16.759Z,1573760056.759 [DataOverHttps](INFO): SBD MOMSN=12050364 2019-11-14T19:34:18.934Z,1573760058.934 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:34:48.077Z,1573760088.077 [DataOverHttps](INFO): Sending 363 bytes from file Logs/20191114T182338/Express0034.lzma 2019-11-14T19:34:50.083Z,1573760090.083 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0034.lzma.bak 2019-11-14T19:34:50.083Z,1573760090.083 [DataOverHttps](INFO): SBD MOMSN=12050683 2019-11-14T19:34:51.312Z,1573760091.312 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:34:51.312Z,1573760091.312 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:34:51.312Z,1573760091.312 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:39:51.900Z,1573760391.900 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:39:51.900Z,1573760391.900 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:39:51.900Z,1573760391.900 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:39:51.900Z,1573760391.900 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:39:52.300Z,1573760392.300 [Default:CheckIn:D] Stopped 2019-11-14T19:39:52.300Z,1573760392.300 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:39:52.689Z,1573760392.689 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 95.992464 min 2019-11-14T19:39:52.689Z,1573760392.689 [Default:CheckIn:E] Stopped 2019-11-14T19:39:52.689Z,1573760392.689 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn] Stopped 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn](INFO): Running loop #15 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn] Running Loop=15 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:39:52.690Z,1573760392.690 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:39:54.697Z,1573760394.697 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193956.00,A,3648.16485,N,12147.28413,W,0.214,347.42,141119,,,A*7B 2019-11-14T19:39:54.699Z,1573760394.699 [NAL9602](INFO): GPS fix at 20191114T193956: (36.802748, -121.788069) 2019-11-14T19:39:54.723Z,1573760394.723 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:39:54.723Z,1573760394.723 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:40:32.364Z,1573760432.364 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T182338/Courier0036.lzma 2019-11-14T19:40:34.370Z,1573760434.370 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0036.lzma.bak 2019-11-14T19:40:34.371Z,1573760434.371 [DataOverHttps](INFO): SBD MOMSN=12053225 2019-11-14T19:40:55.374Z,1573760455.374 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20191114T182338/Express0037.lzma 2019-11-14T19:40:57.379Z,1573760457.379 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0037.lzma.bak 2019-11-14T19:40:57.379Z,1573760457.379 [DataOverHttps](INFO): SBD MOMSN=12053387 2019-11-14T19:40:58.572Z,1573760458.572 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:40:58.572Z,1573760458.572 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:40:58.572Z,1573760458.572 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:41:18.349Z,1573760478.349 [NAL9602](INFO): SBD MO Status=0, MOMSN=5158, MT Status=0, MTMSN=0 2019-11-14T19:41:18.349Z,1573760478.349 [NAL9602](INFO): No messages in MT queue 2019-11-14T19:41:49.046Z,1573760509.046 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:45:06.252Z,1573760706.252 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T19:45:06.252Z,1573760706.252 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111419460953,35.0, -0.1, 0.0, 0 2019-11-14T19:45:59.198Z,1573760759.198 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:45:59.198Z,1573760759.198 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:45:59.199Z,1573760759.199 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:45:59.199Z,1573760759.199 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:45:59.573Z,1573760759.573 [Default:CheckIn:D] Stopped 2019-11-14T19:45:59.573Z,1573760759.573 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.113688 min 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn:E] Stopped 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn] Stopped 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn](INFO): Running loop #16 2019-11-14T19:45:59.987Z,1573760759.987 [Default:CheckIn] Running Loop=16 2019-11-14T19:45:59.988Z,1573760759.988 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:45:59.988Z,1573760759.988 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:46:01.968Z,1573760761.968 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194603.00,A,3648.16440,N,12147.28024,W,0.078,347.42,141119,,,A*72 2019-11-14T19:46:01.970Z,1573760761.970 [NAL9602](INFO): GPS fix at 20191114T194603: (36.802740, -121.788004) 2019-11-14T19:46:02.027Z,1573760762.027 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:46:02.027Z,1573760762.027 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:46:19.028Z,1573760779.028 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0039.lzma 2019-11-14T19:46:21.034Z,1573760781.034 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0039.lzma.bak 2019-11-14T19:46:21.035Z,1573760781.035 [DataOverHttps](INFO): SBD MOMSN=12055579 2019-11-14T19:46:40.433Z,1573760800.433 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0040.lzma 2019-11-14T19:46:42.439Z,1573760802.439 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0040.lzma.bak 2019-11-14T19:46:42.439Z,1573760802.439 [DataOverHttps](INFO): SBD MOMSN=12055740 2019-11-14T19:46:43.636Z,1573760803.636 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:46:43.636Z,1573760803.636 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:46:43.636Z,1573760803.636 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:48:40.802Z,1573760920.802 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T19:48:40.802Z,1573760920.802 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T19:50:54.891Z,1573761054.891 [NAL9602](INFO): SBD MO Status=2, MOMSN=5159, MT Status=2, MTMSN=0 2019-11-14T19:50:54.892Z,1573761054.892 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T19:51:04.580Z,1573761064.580 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T19:51:35.290Z,1573761095.290 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:51:44.204Z,1573761104.204 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:51:44.204Z,1573761104.204 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:51:44.204Z,1573761104.204 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:51:44.204Z,1573761104.204 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:51:44.601Z,1573761104.601 [Default:CheckIn:D] Stopped 2019-11-14T19:51:44.601Z,1573761104.601 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 107.864152 min 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn:E] Stopped 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn] Stopped 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn](INFO): Running loop #17 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn] Running Loop=17 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:51:45.023Z,1573761105.023 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:51:47.008Z,1573761107.008 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195149.00,A,3648.16954,N,12147.28250,W,0.058,222.72,141119,,,A*70 2019-11-14T19:51:47.010Z,1573761107.010 [NAL9602](INFO): GPS fix at 20191114T195149: (36.802826, -121.788042) 2019-11-14T19:51:47.045Z,1573761107.045 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:51:47.045Z,1573761107.045 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:51:55.124Z,1573761115.124 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0042.lzma 2019-11-14T19:51:57.131Z,1573761117.131 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0042.lzma.bak 2019-11-14T19:51:57.131Z,1573761117.131 [DataOverHttps](INFO): SBD MOMSN=12057526 2019-11-14T19:52:14.481Z,1573761134.481 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0043.lzma 2019-11-14T19:52:16.486Z,1573761136.486 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0043.lzma.bak 2019-11-14T19:52:16.487Z,1573761136.487 [DataOverHttps](INFO): SBD MOMSN=12057536 2019-11-14T19:52:17.710Z,1573761137.710 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T19:52:17.793Z,1573761137.793 [NAL9602](FAULT): received: +CSQ:0 OK59, 2, 0, 0, 0 OK 2019-11-14T19:52:17.793Z,1573761137.793 [NAL9602] Data Fault, FailCount= 1 2019-11-14T19:52:17.793Z,1573761137.793 [NAL9602](ERROR): Data Fault 2019-11-14T19:52:17.848Z,1573761137.848 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:52:17.848Z,1573761137.848 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:52:17.848Z,1573761137.848 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:52:17.866Z,1573761137.866 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T19:52:18.133Z,1573761138.133 [NAL9602](INFO): Powering down 2019-11-14T19:52:18.969Z,1573761138.969 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T19:52:18.969Z,1573761138.969 [NAL9602] No Fault, FailCount= 1 2019-11-14T19:52:48.414Z,1573761168.414 [NAL9602](INFO): Powering up NAL9602 2019-11-14T19:52:59.322Z,1573761179.322 [NAL9602](INFO): NAL9602 initialized 2019-11-14T19:53:30.439Z,1573761210.439 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:56:01.184Z,1573761361.184 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T19:56:01.184Z,1573761361.184 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T19:57:18.351Z,1573761438.351 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T19:57:18.351Z,1573761438.351 [Default:CheckIn:C.Wait] Stopped 2019-11-14T19:57:18.351Z,1573761438.351 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T19:57:18.352Z,1573761438.352 [Default:CheckIn:D] Running Loop=1 2019-11-14T19:57:18.732Z,1573761438.732 [Default:CheckIn:D] Stopped 2019-11-14T19:57:18.732Z,1573761438.732 [Default:CheckIn:E] Running Loop=1 2019-11-14T19:57:19.185Z,1573761439.185 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.433008 min 2019-11-14T19:57:19.185Z,1573761439.185 [Default:CheckIn:E] Stopped 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn] Stopped 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn](INFO): Running loop #18 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn] Running Loop=18 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T19:57:19.186Z,1573761439.186 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T19:57:21.140Z,1573761441.140 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195722.00,A,3648.16480,N,12147.28189,W,0.272,191.71,141119,,,A*7A 2019-11-14T19:57:21.152Z,1573761441.152 [NAL9602](INFO): GPS fix at 20191114T195722: (36.802747, -121.788032) 2019-11-14T19:57:21.175Z,1573761441.175 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T19:57:21.175Z,1573761441.175 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T19:57:23.296Z,1573761443.296 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T19:57:28.572Z,1573761448.572 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0045.lzma 2019-11-14T19:57:30.579Z,1573761450.579 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0045.lzma.bak 2019-11-14T19:57:30.579Z,1573761450.579 [DataOverHttps](INFO): SBD MOMSN=12059493 2019-11-14T19:57:47.997Z,1573761467.997 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191114T182338/Express0046.lzma 2019-11-14T19:57:49.991Z,1573761469.991 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0046.lzma.bak 2019-11-14T19:57:49.991Z,1573761469.991 [DataOverHttps](INFO): SBD MOMSN=12059632 2019-11-14T19:57:51.188Z,1573761471.188 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T19:57:51.189Z,1573761471.189 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T19:57:51.189Z,1573761471.189 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T19:57:53.986Z,1573761473.986 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T19:58:10.178Z,1573761490.178 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T19:58:10.178Z,1573761490.178 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T20:00:50.160Z,1573761650.160 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:00:50.160Z,1573761650.160 [RDI_Pathfinder](ERROR): Failed to parse: :TS 2019-11-14T20:02:51.824Z,1573761771.824 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:02:51.824Z,1573761771.824 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:02:51.824Z,1573761771.824 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:02:51.825Z,1573761771.825 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:02:52.190Z,1573761772.190 [Default:CheckIn:D] Stopped 2019-11-14T20:02:52.190Z,1573761772.190 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:02:52.588Z,1573761772.588 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 118.990625 min 2019-11-14T20:02:52.588Z,1573761772.588 [Default:CheckIn:E] Stopped 2019-11-14T20:02:52.588Z,1573761772.588 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:02:52.588Z,1573761772.588 [Default:CheckIn] Stopped 2019-11-14T20:02:52.588Z,1573761772.588 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:02:52.589Z,1573761772.589 [Default:CheckIn](INFO): Running loop #19 2019-11-14T20:02:52.589Z,1573761772.589 [Default:CheckIn] Running Loop=19 2019-11-14T20:02:52.589Z,1573761772.589 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:02:52.589Z,1573761772.589 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:02:54.612Z,1573761774.612 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200256.00,A,3648.16615,N,12147.28618,W,0.525,191.71,141119,,,A*77 2019-11-14T20:02:54.636Z,1573761774.636 [NAL9602](INFO): GPS fix at 20191114T200256: (36.802769, -121.788103) 2019-11-14T20:02:54.708Z,1573761774.708 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:02:54.709Z,1573761774.709 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:03:02.778Z,1573761782.778 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T182338/Courier0048.lzma 2019-11-14T20:03:04.779Z,1573761784.779 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0048.lzma.bak 2019-11-14T20:03:04.780Z,1573761784.780 [DataOverHttps](INFO): SBD MOMSN=12062397 2019-11-14T20:03:32.181Z,1573761812.181 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20191114T182338/Express0049.lzma 2019-11-14T20:03:34.187Z,1573761814.187 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0049.lzma.bak 2019-11-14T20:03:34.187Z,1573761814.187 [DataOverHttps](INFO): SBD MOMSN=12062544 2019-11-14T20:03:35.372Z,1573761815.372 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:03:35.372Z,1573761815.372 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:03:35.372Z,1573761815.372 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:07:56.318Z,1573762076.318 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:08:27.017Z,1573762107.017 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:08:35.952Z,1573762115.952 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:08:35.952Z,1573762115.952 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:08:35.952Z,1573762115.952 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:08:35.952Z,1573762115.952 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:08:36.355Z,1573762116.355 [Default:CheckIn:D] Stopped 2019-11-14T20:08:36.355Z,1573762116.355 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.726709 min 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn:E] Stopped 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn] Stopped 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:08:36.743Z,1573762116.743 [Default:CheckIn](INFO): Running loop #20 2019-11-14T20:08:36.744Z,1573762116.744 [Default:CheckIn] Running Loop=20 2019-11-14T20:08:36.744Z,1573762116.744 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:08:36.744Z,1573762116.744 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:08:38.755Z,1573762118.755 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200840.00,A,3648.16303,N,12147.28529,W,0.117,191.71,141119,,,A*7C 2019-11-14T20:08:38.757Z,1573762118.757 [NAL9602](INFO): GPS fix at 20191114T200840: (36.802717, -121.788088) 2019-11-14T20:08:38.780Z,1573762118.780 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:08:38.780Z,1573762118.780 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:08:46.620Z,1573762126.620 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T182338/Courier0051.lzma 2019-11-14T20:08:48.627Z,1573762128.627 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0051.lzma.bak 2019-11-14T20:08:48.627Z,1573762128.627 [DataOverHttps](INFO): SBD MOMSN=12064239 2019-11-14T20:09:09.458Z,1573762149.458 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T20:09:09.541Z,1573762149.541 [NAL9602](FAULT): received: +CSQ:0 OK59, 2, 0, 0, 0 OK 2019-11-14T20:09:09.542Z,1573762149.542 [NAL9602] Data Fault, FailCount= 1 2019-11-14T20:09:09.542Z,1573762149.542 [NAL9602](ERROR): Data Fault 2019-11-14T20:09:09.609Z,1573762149.609 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T20:09:09.866Z,1573762149.866 [NAL9602](INFO): Powering down 2019-11-14T20:09:10.425Z,1573762150.425 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0052.lzma 2019-11-14T20:09:10.711Z,1573762150.711 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T20:09:10.711Z,1573762150.711 [NAL9602] No Fault, FailCount= 1 2019-11-14T20:09:12.430Z,1573762152.430 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0052.lzma.bak 2019-11-14T20:09:12.431Z,1573762152.431 [DataOverHttps](INFO): SBD MOMSN=12064242 2019-11-14T20:09:13.984Z,1573762153.984 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:09:13.984Z,1573762153.984 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:09:13.984Z,1573762153.984 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:09:40.166Z,1573762180.166 [NAL9602](INFO): Powering up NAL9602 2019-11-14T20:09:51.074Z,1573762191.074 [NAL9602](INFO): NAL9602 initialized 2019-11-14T20:10:22.190Z,1573762222.190 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:14:14.530Z,1573762454.530 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:14:14.530Z,1573762454.530 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:14:14.530Z,1573762454.530 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:14:14.531Z,1573762454.531 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:14:14.956Z,1573762454.956 [Default:CheckIn:D] Stopped 2019-11-14T20:14:14.956Z,1573762454.956 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:14:15.329Z,1573762455.329 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.370060 min 2019-11-14T20:14:15.329Z,1573762455.329 [Default:CheckIn:E] Stopped 2019-11-14T20:14:15.329Z,1573762455.329 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn] Stopped 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn](INFO): Running loop #21 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn] Running Loop=21 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:14:15.330Z,1573762455.330 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:14:17.333Z,1573762457.333 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201419.00,A,3648.15218,N,12147.29850,W,0.447,227.15,141119,,,A*7B 2019-11-14T20:14:17.335Z,1573762457.335 [NAL9602](INFO): GPS fix at 20191114T201419: (36.802536, -121.788308) 2019-11-14T20:14:17.358Z,1573762457.358 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:14:17.359Z,1573762457.359 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:14:19.342Z,1573762459.342 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:14:25.312Z,1573762465.312 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0054.lzma 2019-11-14T20:14:27.318Z,1573762467.318 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0054.lzma.bak 2019-11-14T20:14:27.319Z,1573762467.319 [DataOverHttps](INFO): SBD MOMSN=12064252 2019-11-14T20:14:44.569Z,1573762484.569 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191114T182338/Express0055.lzma 2019-11-14T20:14:46.575Z,1573762486.575 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0055.lzma.bak 2019-11-14T20:14:46.575Z,1573762486.575 [DataOverHttps](INFO): SBD MOMSN=12064256 2019-11-14T20:14:48.064Z,1573762488.064 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:14:48.064Z,1573762488.064 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:14:48.064Z,1573762488.064 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:14:50.046Z,1573762490.046 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:19:06.206Z,1573762746.206 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:19:06.206Z,1573762746.206 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420200953,35.0, -0.1, 09, 0 2019-11-14T20:19:48.629Z,1573762788.629 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:19:48.629Z,1573762788.629 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:19:48.630Z,1573762788.630 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:19:48.630Z,1573762788.630 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:19:49.039Z,1573762789.039 [Default:CheckIn:D] Stopped 2019-11-14T20:19:49.039Z,1573762789.039 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 135.938110 min 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn:E] Stopped 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn] Stopped 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn](INFO): Running loop #22 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn] Running Loop=22 2019-11-14T20:19:49.456Z,1573762789.456 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:19:49.457Z,1573762789.457 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:19:51.432Z,1573762791.432 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201953.00,A,3648.16753,N,12147.28848,W,0.078,227.15,141119,,,A*71 2019-11-14T20:19:51.434Z,1573762791.434 [NAL9602](INFO): GPS fix at 20191114T201953: (36.802792, -121.788141) 2019-11-14T20:19:51.486Z,1573762791.486 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:19:51.486Z,1573762791.486 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:19:59.828Z,1573762799.828 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0057.lzma 2019-11-14T20:20:01.834Z,1573762801.834 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0057.lzma.bak 2019-11-14T20:20:01.835Z,1573762801.835 [DataOverHttps](INFO): SBD MOMSN=12064294 2019-11-14T20:20:19.277Z,1573762819.277 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20191114T182338/Express0058.lzma 2019-11-14T20:20:21.283Z,1573762821.283 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0058.lzma.bak 2019-11-14T20:20:21.283Z,1573762821.283 [DataOverHttps](INFO): SBD MOMSN=12064298 2019-11-14T20:20:22.572Z,1573762822.572 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:20:22.572Z,1573762822.572 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:20:22.572Z,1573762822.572 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:21:26.014Z,1573762886.014 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-14T20:21:26.016Z,1573762886.016 [BPC1](INFO): Received data from all battery sticks. 2019-11-14T20:22:42.802Z,1573762962.802 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2019-11-14T20:22:42.802Z,1573762962.802 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768-32768,V 2019-11-14T20:24:53.620Z,1573763093.620 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:25:23.152Z,1573763123.152 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:25:23.152Z,1573763123.152 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:25:23.152Z,1573763123.152 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:25:23.152Z,1573763123.152 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:25:23.550Z,1573763123.550 [Default:CheckIn:D] Stopped 2019-11-14T20:25:23.550Z,1573763123.550 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.513298 min 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn:E] Stopped 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn] Stopped 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn](INFO): Running loop #23 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn] Running Loop=23 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:25:23.964Z,1573763123.964 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:25:24.326Z,1573763124.326 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:25:25.944Z,1573763125.944 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202527.00,A,3648.16183,N,12147.28619,W,0.078,185.58,141119,,,A*7E 2019-11-14T20:25:25.946Z,1573763125.946 [NAL9602](INFO): GPS fix at 20191114T202527: (36.802697, -121.788103) 2019-11-14T20:25:26.020Z,1573763126.020 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:25:26.020Z,1573763126.020 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:25:33.369Z,1573763133.369 [DataOverHttps](INFO): Sending 82 bytes from file Logs/20191114T182338/Courier0060.lzma 2019-11-14T20:25:35.375Z,1573763135.375 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0060.lzma.bak 2019-11-14T20:25:35.375Z,1573763135.375 [DataOverHttps](INFO): SBD MOMSN=12064368 2019-11-14T20:25:53.009Z,1573763153.009 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0061.lzma 2019-11-14T20:25:55.014Z,1573763155.014 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0061.lzma.bak 2019-11-14T20:25:55.015Z,1573763155.015 [DataOverHttps](INFO): SBD MOMSN=12064371 2019-11-14T20:25:56.284Z,1573763156.284 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:25:56.284Z,1573763156.284 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:25:56.284Z,1573763156.284 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:26:04.794Z,1573763164.794 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:26:04.794Z,1573763164.794 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420270853,35.0, -0.1, 0.0, 0 2019-11-14T20:26:24.148Z,1573763184.148 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:26:24.148Z,1573763184.148 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420272753,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-14T20:30:28.542Z,1573763428.542 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:30:56.944Z,1573763456.944 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:30:56.944Z,1573763456.944 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:30:56.944Z,1573763456.944 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:30:56.957Z,1573763456.957 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:30:57.338Z,1573763457.338 [Default:CheckIn:D] Stopped 2019-11-14T20:30:57.338Z,1573763457.338 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.076432 min 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn:E] Stopped 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn] Stopped 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn](INFO): Running loop #24 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn] Running Loop=24 2019-11-14T20:30:57.690Z,1573763457.690 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:30:57.691Z,1573763457.691 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:30:59.667Z,1573763459.667 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203101.00,A,3648.16458,N,12147.28614,W,1.419,185.58,141119,,,A*73 2019-11-14T20:30:59.669Z,1573763459.669 [NAL9602](INFO): GPS fix at 20191114T203101: (36.802743, -121.788102) 2019-11-14T20:30:59.694Z,1573763459.694 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:30:59.694Z,1573763459.694 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:31:07.352Z,1573763467.352 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0063.lzma 2019-11-14T20:31:09.359Z,1573763469.359 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0063.lzma.bak 2019-11-14T20:31:09.359Z,1573763469.359 [DataOverHttps](INFO): SBD MOMSN=12064380 2019-11-14T20:31:26.729Z,1573763486.729 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0064.lzma 2019-11-14T20:31:28.735Z,1573763488.735 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0064.lzma.bak 2019-11-14T20:31:28.735Z,1573763488.735 [DataOverHttps](INFO): SBD MOMSN=12064383 2019-11-14T20:31:29.999Z,1573763489.999 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:31:29.999Z,1573763489.999 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:31:29.999Z,1573763489.999 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:31:31.578Z,1573763491.578 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:36:30.568Z,1573763790.568 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:36:30.568Z,1573763790.568 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:36:30.568Z,1573763790.568 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:36:30.568Z,1573763790.568 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:36:30.985Z,1573763790.985 [Default:CheckIn:D] Stopped 2019-11-14T20:36:30.985Z,1573763790.985 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 152.637207 min 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn:E] Stopped 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn] Stopped 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn](INFO): Running loop #25 2019-11-14T20:36:31.382Z,1573763791.382 [Default:CheckIn] Running Loop=25 2019-11-14T20:36:31.383Z,1573763791.383 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:36:31.383Z,1573763791.383 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:36:33.372Z,1573763793.372 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203635.00,A,3648.16713,N,12147.28208,W,0.117,203.09,141119,,,A*75 2019-11-14T20:36:33.374Z,1573763793.374 [NAL9602](INFO): GPS fix at 20191114T203635: (36.802785, -121.788035) 2019-11-14T20:36:33.398Z,1573763793.398 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:36:33.399Z,1573763793.399 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:36:41.448Z,1573763801.448 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0066.lzma 2019-11-14T20:36:43.455Z,1573763803.455 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0066.lzma.bak 2019-11-14T20:36:43.455Z,1573763803.455 [DataOverHttps](INFO): SBD MOMSN=12064394 2019-11-14T20:37:01.309Z,1573763821.309 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20191114T182338/Express0067.lzma 2019-11-14T20:37:03.315Z,1573763823.315 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0067.lzma.bak 2019-11-14T20:37:03.315Z,1573763823.315 [DataOverHttps](INFO): SBD MOMSN=12064397 2019-11-14T20:37:04.074Z,1573763824.074 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T20:37:04.149Z,1573763824.149 [NAL9602](FAULT): received: +CSQ:0 OK59, 2, 0, 0, 0 OK 2019-11-14T20:37:04.149Z,1573763824.149 [NAL9602] Data Fault, FailCount= 1 2019-11-14T20:37:04.149Z,1573763824.149 [NAL9602](ERROR): Data Fault 2019-11-14T20:37:04.208Z,1573763824.208 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T20:37:04.474Z,1573763824.474 [NAL9602](INFO): Powering down 2019-11-14T20:37:04.498Z,1573763824.498 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:37:04.499Z,1573763824.499 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:37:04.499Z,1573763824.499 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:37:05.325Z,1573763825.325 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T20:37:05.325Z,1573763825.325 [NAL9602] No Fault, FailCount= 1 2019-11-14T20:37:10.156Z,1573763830.156 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:37:10.157Z,1573763830.157 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420381353.0,1448.9, 0 2019-11-14T20:37:34.791Z,1573763854.791 [NAL9602](INFO): Powering up NAL9602 2019-11-14T20:37:45.682Z,1573763865.682 [NAL9602](INFO): NAL9602 initialized 2019-11-14T20:38:16.796Z,1573763896.796 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:42:05.110Z,1573764125.110 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:42:05.110Z,1573764125.110 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:42:05.110Z,1573764125.110 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:42:05.110Z,1573764125.110 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:42:05.504Z,1573764125.504 [Default:CheckIn:D] Stopped 2019-11-14T20:42:05.504Z,1573764125.504 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:42:05.930Z,1573764125.930 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.212533 min 2019-11-14T20:42:05.930Z,1573764125.930 [Default:CheckIn:E] Stopped 2019-11-14T20:42:05.930Z,1573764125.930 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:42:05.930Z,1573764125.930 [Default:CheckIn] Stopped 2019-11-14T20:42:05.930Z,1573764125.930 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:42:05.931Z,1573764125.931 [Default:CheckIn](INFO): Running loop #26 2019-11-14T20:42:05.931Z,1573764125.931 [Default:CheckIn] Running Loop=26 2019-11-14T20:42:05.931Z,1573764125.931 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:42:05.931Z,1573764125.931 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:42:07.900Z,1573764127.900 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204208.00,A,3648.17726,N,12147.28448,W,1.322,351.02,141119,,,A*75 2019-11-14T20:42:07.902Z,1573764127.902 [NAL9602](INFO): GPS fix at 20191114T204208: (36.802954, -121.788075) 2019-11-14T20:42:07.926Z,1573764127.926 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:42:07.926Z,1573764127.926 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:42:10.316Z,1573764130.316 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:42:15.484Z,1573764135.484 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T182338/Courier0069.lzma 2019-11-14T20:42:17.490Z,1573764137.490 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0069.lzma.bak 2019-11-14T20:42:17.491Z,1573764137.491 [DataOverHttps](INFO): SBD MOMSN=12064404 2019-11-14T20:42:41.026Z,1573764161.026 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:43:10.037Z,1573764190.037 [DataOverHttps](INFO): Sending 165 bytes from file Logs/20191114T182338/Express0070.lzma 2019-11-14T20:43:12.043Z,1573764192.043 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0070.lzma.bak 2019-11-14T20:43:12.043Z,1573764192.043 [DataOverHttps](INFO): SBD MOMSN=12064407 2019-11-14T20:43:13.408Z,1573764193.408 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:43:13.408Z,1573764193.408 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:43:13.408Z,1573764193.408 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:48:13.984Z,1573764493.984 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:48:13.984Z,1573764493.984 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:48:13.984Z,1573764493.984 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:48:13.984Z,1573764493.984 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:48:14.392Z,1573764494.392 [Default:CheckIn:D] Stopped 2019-11-14T20:48:14.392Z,1573764494.392 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:48:14.841Z,1573764494.841 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 164.360661 min 2019-11-14T20:48:14.841Z,1573764494.841 [Default:CheckIn:E] Stopped 2019-11-14T20:48:14.841Z,1573764494.841 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn] Stopped 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn](INFO): Running loop #27 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn] Running Loop=27 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:48:14.842Z,1573764494.842 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:48:16.784Z,1573764496.784 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204817.00,A,3648.17078,N,12147.28309,W,0.058,348.88,141119,,,A*7A 2019-11-14T20:48:16.786Z,1573764496.786 [NAL9602](INFO): GPS fix at 20191114T204817: (36.802846, -121.788051) 2019-11-14T20:48:16.820Z,1573764496.820 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:48:16.820Z,1573764496.820 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:48:24.852Z,1573764504.852 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191114T182338/Courier0072.lzma 2019-11-14T20:48:26.859Z,1573764506.859 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0072.lzma.bak 2019-11-14T20:48:26.859Z,1573764506.859 [DataOverHttps](INFO): SBD MOMSN=12064421 2019-11-14T20:48:44.261Z,1573764524.261 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20191114T182338/Express0073.lzma 2019-11-14T20:48:46.266Z,1573764526.266 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0073.lzma.bak 2019-11-14T20:48:46.267Z,1573764526.267 [DataOverHttps](INFO): SBD MOMSN=12064423 2019-11-14T20:48:47.540Z,1573764527.540 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:48:47.540Z,1573764527.540 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:48:47.540Z,1573764527.540 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:49:55.835Z,1573764595.835 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T20:49:55.835Z,1573764595.835 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3268,-32768,V 2019-11-14T20:50:24.086Z,1573764624.086 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-14T20:51:17.030Z,1573764677.030 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420522053,35.0, -0.1, 0.0,1448.9, 0 2019-11-14T20:51:30.783Z,1573764690.783 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-14T20:51:30.784Z,1573764690.784 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, +0.00, 0.00,8965.58 2019-11-14T20:53:18.618Z,1573764798.618 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:53:48.162Z,1573764828.162 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:53:48.162Z,1573764828.162 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:53:48.162Z,1573764828.162 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:53:48.162Z,1573764828.162 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:53:48.553Z,1573764828.553 [Default:CheckIn:D] Stopped 2019-11-14T20:53:48.553Z,1573764828.553 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:53:48.937Z,1573764828.937 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 169.930013 min 2019-11-14T20:53:48.937Z,1573764828.937 [Default:CheckIn:E] Stopped 2019-11-14T20:53:48.937Z,1573764828.937 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:53:48.937Z,1573764828.937 [Default:CheckIn] Stopped 2019-11-14T20:53:48.937Z,1573764828.937 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:53:48.938Z,1573764828.938 [Default:CheckIn](INFO): Running loop #28 2019-11-14T20:53:48.938Z,1573764828.938 [Default:CheckIn] Running Loop=28 2019-11-14T20:53:48.938Z,1573764828.938 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:53:48.938Z,1573764828.938 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:53:49.316Z,1573764829.316 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:53:49.771Z,1573764829.771 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T20:53:49.771Z,1573764829.771 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111420545353,35.0, -0.1,448.9, 0 2019-11-14T20:53:50.946Z,1573764830.946 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205353.00,A,3648.16765,N,12147.28250,W,0.214,348.88,141119,,,A*7D 2019-11-14T20:53:50.948Z,1573764830.948 [NAL9602](INFO): GPS fix at 20191114T205353: (36.802794, -121.788042) 2019-11-14T20:53:50.982Z,1573764830.982 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:53:50.983Z,1573764830.983 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:53:59.060Z,1573764839.060 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0075.lzma 2019-11-14T20:54:01.067Z,1573764841.067 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0075.lzma.bak 2019-11-14T20:54:01.067Z,1573764841.067 [DataOverHttps](INFO): SBD MOMSN=12064427 2019-11-14T20:54:18.445Z,1573764858.445 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0076.lzma 2019-11-14T20:54:20.451Z,1573764860.451 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0076.lzma.bak 2019-11-14T20:54:20.451Z,1573764860.451 [DataOverHttps](INFO): SBD MOMSN=12064430 2019-11-14T20:54:21.645Z,1573764861.645 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T20:54:21.725Z,1573764861.725 [NAL9602](FAULT): received: +CSQ:0 OK59, 2, 0, 0, 0 OK 2019-11-14T20:54:21.726Z,1573764861.726 [NAL9602] Data Fault, FailCount= 1 2019-11-14T20:54:21.726Z,1573764861.726 [NAL9602](ERROR): Data Fault 2019-11-14T20:54:21.816Z,1573764861.816 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:54:21.816Z,1573764861.816 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:54:21.816Z,1573764861.816 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:54:21.825Z,1573764861.825 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T20:54:22.046Z,1573764862.046 [NAL9602](INFO): Powering down 2019-11-14T20:54:22.916Z,1573764862.916 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T20:54:22.916Z,1573764862.916 [NAL9602] No Fault, FailCount= 1 2019-11-14T20:54:52.342Z,1573764892.342 [NAL9602](INFO): Powering up NAL9602 2019-11-14T20:55:03.270Z,1573764903.270 [NAL9602](INFO): NAL9602 initialized 2019-11-14T20:55:15.831Z,1573764915.831 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T20:55:15.831Z,1573764915.831 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768V 2019-11-14T20:55:34.366Z,1573764934.366 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T20:55:49.778Z,1573764949.778 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T20:59:22.251Z,1573765162.251 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T20:59:22.252Z,1573765162.252 [Default:CheckIn:C.Wait] Stopped 2019-11-14T20:59:22.252Z,1573765162.252 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T20:59:22.252Z,1573765162.252 [Default:CheckIn:D] Running Loop=1 2019-11-14T20:59:22.650Z,1573765162.650 [Default:CheckIn:D] Stopped 2019-11-14T20:59:22.650Z,1573765162.650 [Default:CheckIn:E] Running Loop=1 2019-11-14T20:59:23.069Z,1573765163.069 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 175.498291 min 2019-11-14T20:59:23.069Z,1573765163.069 [Default:CheckIn:E] Stopped 2019-11-14T20:59:23.069Z,1573765163.069 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T20:59:23.069Z,1573765163.069 [Default:CheckIn] Stopped 2019-11-14T20:59:23.069Z,1573765163.069 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T20:59:23.070Z,1573765163.070 [Default:CheckIn](INFO): Running loop #29 2019-11-14T20:59:23.070Z,1573765163.070 [Default:CheckIn] Running Loop=29 2019-11-14T20:59:23.070Z,1573765163.070 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T20:59:23.070Z,1573765163.070 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T20:59:25.052Z,1573765165.052 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205926.00,A,3648.16534,N,12147.28350,W,0.389,0.00,141119,,,A*78 2019-11-14T20:59:25.054Z,1573765165.054 [NAL9602](INFO): GPS fix at 20191114T205926: (36.802756, -121.788058) 2019-11-14T20:59:25.106Z,1573765165.106 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T20:59:25.106Z,1573765165.106 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T20:59:27.475Z,1573765167.475 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T20:59:33.044Z,1573765173.044 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0078.lzma 2019-11-14T20:59:35.051Z,1573765175.051 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0078.lzma.bak 2019-11-14T20:59:35.051Z,1573765175.051 [DataOverHttps](INFO): SBD MOMSN=12064445 2019-11-14T20:59:52.457Z,1573765192.457 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20191114T182338/Express0079.lzma 2019-11-14T20:59:54.463Z,1573765194.463 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0079.lzma.bak 2019-11-14T20:59:54.463Z,1573765194.463 [DataOverHttps](INFO): SBD MOMSN=12064448 2019-11-14T20:59:55.819Z,1573765195.819 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T20:59:55.819Z,1573765195.819 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T20:59:55.819Z,1573765195.819 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T20:59:58.174Z,1573765198.174 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:02:29.298Z,1573765349.298 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-11-14T21:04:56.380Z,1573765496.380 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:04:56.380Z,1573765496.380 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:04:56.380Z,1573765496.380 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:04:56.380Z,1573765496.380 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:04:56.796Z,1573765496.796 [Default:CheckIn:D] Stopped 2019-11-14T21:04:56.796Z,1573765496.796 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 181.067399 min 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn:E] Stopped 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn] Stopped 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:04:57.239Z,1573765497.239 [Default:CheckIn](INFO): Running loop #30 2019-11-14T21:04:57.240Z,1573765497.240 [Default:CheckIn] Running Loop=30 2019-11-14T21:04:57.240Z,1573765497.240 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:04:57.240Z,1573765497.240 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:04:59.180Z,1573765499.180 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210501.00,A,3648.17180,N,12147.28052,W,0.233,0.00,141119,,,A*7E 2019-11-14T21:04:59.182Z,1573765499.182 [NAL9602](INFO): GPS fix at 20191114T210501: (36.802863, -121.788009) 2019-11-14T21:04:59.264Z,1573765499.264 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:04:59.264Z,1573765499.264 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:05:07.396Z,1573765507.396 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0081.lzma 2019-11-14T21:05:09.403Z,1573765509.403 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0081.lzma.bak 2019-11-14T21:05:09.403Z,1573765509.403 [DataOverHttps](INFO): SBD MOMSN=12064455 2019-11-14T21:05:26.845Z,1573765526.845 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0082.lzma 2019-11-14T21:05:28.851Z,1573765528.851 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0082.lzma.bak 2019-11-14T21:05:28.851Z,1573765528.851 [DataOverHttps](INFO): SBD MOMSN=12064462 2019-11-14T21:05:30.023Z,1573765530.023 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:05:30.023Z,1573765530.023 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:05:30.023Z,1573765530.023 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:07:57.831Z,1573765677.831 [NAL9602](INFO): SBD MO Status=2, MOMSN=5159, MT Status=2, MTMSN=0 2019-11-14T21:07:57.832Z,1573765677.832 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:08:03.099Z,1573765683.099 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T21:08:03.099Z,1573765683.099 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T21:08:17.223Z,1573765697.223 [NAL9602](INFO): SBD MO Status=0, MOMSN=5159, MT Status=0, MTMSN=0 2019-11-14T21:08:17.224Z,1573765697.224 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:08:47.926Z,1573765727.926 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:10:30.604Z,1573765830.604 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:10:30.604Z,1573765830.604 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:10:30.604Z,1573765830.604 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:10:30.604Z,1573765830.604 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:10:30.996Z,1573765830.996 [Default:CheckIn:D] Stopped 2019-11-14T21:10:30.996Z,1573765830.996 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:10:31.397Z,1573765831.397 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 186.637402 min 2019-11-14T21:10:31.397Z,1573765831.397 [Default:CheckIn:E] Stopped 2019-11-14T21:10:31.397Z,1573765831.397 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:10:31.397Z,1573765831.397 [Default:CheckIn] Stopped 2019-11-14T21:10:31.397Z,1573765831.397 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:10:31.398Z,1573765831.398 [Default:CheckIn](INFO): Running loop #31 2019-11-14T21:10:31.398Z,1573765831.398 [Default:CheckIn] Running Loop=31 2019-11-14T21:10:31.398Z,1573765831.398 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:10:31.398Z,1573765831.398 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:10:33.386Z,1573765833.386 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211035.00,A,3648.16852,N,12147.28484,W,0.564,0.00,141119,,,A*70 2019-11-14T21:10:33.388Z,1573765833.388 [NAL9602](INFO): GPS fix at 20191114T211035: (36.802809, -121.788081) 2019-11-14T21:10:33.424Z,1573765833.424 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:10:33.424Z,1573765833.424 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:10:40.644Z,1573765840.644 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0084.lzma 2019-11-14T21:10:42.651Z,1573765842.651 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0084.lzma.bak 2019-11-14T21:10:42.651Z,1573765842.651 [DataOverHttps](INFO): SBD MOMSN=12064471 2019-11-14T21:11:01.233Z,1573765861.233 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0085.lzma 2019-11-14T21:11:03.239Z,1573765863.239 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0085.lzma.bak 2019-11-14T21:11:03.239Z,1573765863.239 [DataOverHttps](INFO): SBD MOMSN=12064474 2019-11-14T21:11:04.584Z,1573765864.584 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:11:04.584Z,1573765864.584 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:11:04.584Z,1573765864.584 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:12:59.760Z,1573765979.760 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T21:12:59.765Z,1573765979.765 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3768,V 2019-11-14T21:15:35.644Z,1573766135.644 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T21:15:37.301Z,1573766137.301 [RDI_Pathfinder](ERROR): only read 0 of 4 data items 2019-11-14T21:15:37.301Z,1573766137.301 [RDI_Pathfinder](ERROR): Failed to parse: :RA 0.00, 0.00, 0.00 2019-11-14T21:16:05.168Z,1573766165.168 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:16:05.168Z,1573766165.168 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:16:05.168Z,1573766165.168 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:16:05.168Z,1573766165.168 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:16:05.572Z,1573766165.572 [Default:CheckIn:D] Stopped 2019-11-14T21:16:05.572Z,1573766165.572 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:16:05.989Z,1573766165.989 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 192.213672 min 2019-11-14T21:16:05.989Z,1573766165.989 [Default:CheckIn:E] Stopped 2019-11-14T21:16:05.989Z,1573766165.989 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:16:05.989Z,1573766165.989 [Default:CheckIn] Stopped 2019-11-14T21:16:05.989Z,1573766165.989 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:16:05.990Z,1573766165.990 [Default:CheckIn](INFO): Running loop #32 2019-11-14T21:16:05.990Z,1573766165.990 [Default:CheckIn] Running Loop=32 2019-11-14T21:16:05.990Z,1573766165.990 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:16:05.990Z,1573766165.990 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:16:06.350Z,1573766166.350 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:16:07.972Z,1573766167.972 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211610.00,A,3648.16895,N,12147.28317,W,0.214,0.00,141119,,,A*77 2019-11-14T21:16:07.974Z,1573766167.974 [NAL9602](INFO): GPS fix at 20191114T211610: (36.802816, -121.788053) 2019-11-14T21:16:07.998Z,1573766167.998 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:16:07.998Z,1573766167.998 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:16:16.872Z,1573766176.872 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0087.lzma 2019-11-14T21:16:18.875Z,1573766178.875 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0087.lzma.bak 2019-11-14T21:16:18.875Z,1573766178.875 [DataOverHttps](INFO): SBD MOMSN=12064484 2019-11-14T21:16:28.575Z,1573766188.575 [NAL9602](INFO): SBD MO Status=2, MOMSN=5160, MT Status=2, MTMSN=0 2019-11-14T21:16:28.575Z,1573766188.575 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:16:36.217Z,1573766196.217 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0088.lzma 2019-11-14T21:16:38.223Z,1573766198.223 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0088.lzma.bak 2019-11-14T21:16:38.223Z,1573766198.223 [DataOverHttps](INFO): SBD MOMSN=12064487 2019-11-14T21:16:39.512Z,1573766199.512 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:16:39.512Z,1573766199.512 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:16:39.512Z,1573766199.512 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:16:42.767Z,1573766202.767 [NAL9602](INFO): SBD MO Status=0, MOMSN=5160, MT Status=0, MTMSN=0 2019-11-14T21:16:42.768Z,1573766202.768 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:17:13.438Z,1573766233.438 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:19:21.955Z,1573766361.955 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00,10633.95 2019-11-14T21:20:01.115Z,1573766401.115 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T21:20:01.115Z,1573766401.115 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111421210453,35.0, -0.1, 0.0,10 2019-11-14T21:21:21.120Z,1573766481.120 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T21:21:21.121Z,1573766481.121 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T21:21:40.148Z,1573766500.148 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:21:40.148Z,1573766500.148 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:21:40.148Z,1573766500.148 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:21:40.148Z,1573766500.148 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:21:40.520Z,1573766500.520 [Default:CheckIn:D] Stopped 2019-11-14T21:21:40.520Z,1573766500.520 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:21:40.936Z,1573766500.936 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 197.796126 min 2019-11-14T21:21:40.936Z,1573766500.936 [Default:CheckIn:E] Stopped 2019-11-14T21:21:40.937Z,1573766500.937 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:21:40.937Z,1573766500.937 [Default:CheckIn] Stopped 2019-11-14T21:21:40.937Z,1573766500.937 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:21:40.937Z,1573766500.937 [Default:CheckIn](INFO): Running loop #33 2019-11-14T21:21:40.937Z,1573766500.937 [Default:CheckIn] Running Loop=33 2019-11-14T21:21:40.938Z,1573766500.938 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:21:40.938Z,1573766500.938 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:21:42.916Z,1573766502.916 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212145.00,A,3648.17038,N,12147.28329,W,0.272,0.00,141119,,,A*70 2019-11-14T21:21:42.918Z,1573766502.918 [NAL9602](INFO): GPS fix at 20191114T212145: (36.802840, -121.788055) 2019-11-14T21:21:42.952Z,1573766502.952 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:21:42.952Z,1573766502.952 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:21:51.108Z,1573766511.108 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0090.lzma 2019-11-14T21:21:53.119Z,1573766513.119 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0090.lzma.bak 2019-11-14T21:21:53.119Z,1573766513.119 [DataOverHttps](INFO): SBD MOMSN=12064549 2019-11-14T21:22:00.748Z,1573766520.748 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-14T21:22:00.748Z,1573766520.748 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, , +0.00, 0.00,10793.79 2019-11-14T21:22:10.481Z,1573766530.481 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20191114T182338/Express0091.lzma 2019-11-14T21:22:12.487Z,1573766532.487 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0091.lzma.bak 2019-11-14T21:22:12.487Z,1573766532.487 [DataOverHttps](INFO): SBD MOMSN=12064553 2019-11-14T21:22:13.633Z,1573766533.633 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:22:13.633Z,1573766533.633 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:22:13.633Z,1573766533.633 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:24:58.444Z,1573766698.444 [NAL9602](INFO): SBD MO Status=2, MOMSN=5161, MT Status=2, MTMSN=0 2019-11-14T21:24:58.444Z,1573766698.444 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:25:59.484Z,1573766759.484 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T21:25:59.484Z,1573766759.484 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T21:26:07.932Z,1573766767.932 [NAL9602](INFO): SBD MO Status=0, MOMSN=5161, MT Status=0, MTMSN=0 2019-11-14T21:26:07.932Z,1573766767.932 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:26:38.640Z,1573766798.640 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:27:14.296Z,1573766834.296 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:27:14.296Z,1573766834.296 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:27:14.296Z,1573766834.296 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:27:14.296Z,1573766834.296 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:27:14.741Z,1573766834.741 [Default:CheckIn:D] Stopped 2019-11-14T21:27:14.742Z,1573766834.742 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:27:15.084Z,1573766835.084 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 203.366195 min 2019-11-14T21:27:15.084Z,1573766835.084 [Default:CheckIn:E] Stopped 2019-11-14T21:27:15.084Z,1573766835.084 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:27:15.084Z,1573766835.084 [Default:CheckIn] Stopped 2019-11-14T21:27:15.085Z,1573766835.085 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:27:15.085Z,1573766835.085 [Default:CheckIn](INFO): Running loop #34 2019-11-14T21:27:15.085Z,1573766835.085 [Default:CheckIn] Running Loop=34 2019-11-14T21:27:15.085Z,1573766835.085 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:27:15.085Z,1573766835.085 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:27:17.040Z,1573766837.040 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212719.00,A,3648.17033,N,12147.28915,W,0.603,0.00,141119,,,A*73 2019-11-14T21:27:17.042Z,1573766837.042 [NAL9602](INFO): GPS fix at 20191114T212719: (36.802839, -121.788152) 2019-11-14T21:27:17.095Z,1573766837.095 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:27:17.096Z,1573766837.096 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:27:17.876Z,1573766837.876 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:27:17.876Z,1573766837.876 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:27:17.877Z,1573766837.877 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:27:24.763Z,1573766844.763 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-14T21:27:24.763Z,1573766844.763 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0. +0.00, +0.00, 0.00,11117.47 2019-11-14T21:27:41.274Z,1573766861.274 [NAL9602](INFO): SBD MO Status=0, MOMSN=5162, MT Status=0, MTMSN=0 2019-11-14T21:27:41.274Z,1573766861.274 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:28:11.978Z,1573766891.978 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:29:00.107Z,1573766940.107 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-14T21:29:00.109Z,1573766940.109 [BPC1](INFO): Received data from all battery sticks. 2019-11-14T21:31:03.735Z,1573767063.735 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T21:31:03.735Z,1573767063.735 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3278,V 2019-11-14T21:32:18.471Z,1573767138.471 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:32:18.471Z,1573767138.471 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:32:18.471Z,1573767138.471 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:32:18.471Z,1573767138.471 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:32:18.866Z,1573767138.866 [Default:CheckIn:D] Stopped 2019-11-14T21:32:18.866Z,1573767138.866 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 208.435221 min 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn:E] Stopped 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn] Stopped 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:32:19.283Z,1573767139.283 [Default:CheckIn](INFO): Running loop #35 2019-11-14T21:32:19.284Z,1573767139.284 [Default:CheckIn] Running Loop=35 2019-11-14T21:32:19.284Z,1573767139.284 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:32:19.284Z,1573767139.284 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:32:21.260Z,1573767141.260 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213223.00,A,3648.17057,N,12147.28649,W,0.019,0.00,141119,,,A*77 2019-11-14T21:32:21.272Z,1573767141.272 [NAL9602](INFO): GPS fix at 20191114T213223: (36.802843, -121.788108) 2019-11-14T21:32:21.295Z,1573767141.295 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:32:21.295Z,1573767141.295 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:32:29.592Z,1573767149.592 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0093.lzma 2019-11-14T21:32:31.611Z,1573767151.611 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0093.lzma.bak 2019-11-14T21:32:31.611Z,1573767151.611 [DataOverHttps](INFO): SBD MOMSN=12064635 2019-11-14T21:32:49.269Z,1573767169.269 [DataOverHttps](INFO): Sending 82 bytes from file Logs/20191114T182338/Courier0096.lzma 2019-11-14T21:32:51.275Z,1573767171.275 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0096.lzma.bak 2019-11-14T21:32:51.275Z,1573767171.275 [DataOverHttps](INFO): SBD MOMSN=12064638 2019-11-14T21:33:10.905Z,1573767190.905 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0094.lzma 2019-11-14T21:33:12.911Z,1573767192.911 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0094.lzma.bak 2019-11-14T21:33:12.911Z,1573767192.911 [DataOverHttps](INFO): SBD MOMSN=12064641 2019-11-14T21:33:17.432Z,1573767197.432 [NAL9602](INFO): SBD MO Status=2, MOMSN=5163, MT Status=2, MTMSN=0 2019-11-14T21:33:17.432Z,1573767197.432 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:33:30.804Z,1573767210.804 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0097.lzma 2019-11-14T21:33:32.811Z,1573767212.811 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0097.lzma.bak 2019-11-14T21:33:32.811Z,1573767212.811 [DataOverHttps](INFO): SBD MOMSN=12064644 2019-11-14T21:33:34.036Z,1573767214.036 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:33:34.036Z,1573767214.036 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:33:34.036Z,1573767214.036 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:34:02.734Z,1573767242.734 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T21:34:02.734Z,1573767242.734 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T21:34:06.321Z,1573767246.321 [NAL9602](INFO): SBD MO Status=2, MOMSN=5163, MT Status=2, MTMSN=0 2019-11-14T21:34:06.321Z,1573767246.321 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:35:20.655Z,1573767320.655 [NAL9602](INFO): SBD MO Status=0, MOMSN=5163, MT Status=0, MTMSN=0 2019-11-14T21:35:20.656Z,1573767320.656 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:35:51.354Z,1573767351.354 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:36:39.084Z,1573767399.084 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T21:36:39.084Z,1573767399.084 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-32BE,-32768,-32768,-32768,V 2019-11-14T21:38:34.596Z,1573767514.596 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:38:34.596Z,1573767514.596 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:38:34.597Z,1573767514.597 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:38:34.597Z,1573767514.597 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:38:35.016Z,1573767515.016 [Default:CheckIn:D] Stopped 2019-11-14T21:38:35.017Z,1573767515.017 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:38:35.411Z,1573767515.411 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 214.704411 min 2019-11-14T21:38:35.411Z,1573767515.411 [Default:CheckIn:E] Stopped 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn] Stopped 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn](INFO): Running loop #36 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn] Running Loop=36 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:38:35.412Z,1573767515.412 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:38:37.400Z,1573767517.400 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213839.00,A,3648.17262,N,12147.28662,W,0.175,0.00,141119,,,A*70 2019-11-14T21:38:37.402Z,1573767517.402 [NAL9602](INFO): GPS fix at 20191114T213839: (36.802877, -121.788110) 2019-11-14T21:38:37.432Z,1573767517.432 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:38:37.432Z,1573767517.432 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:38:45.489Z,1573767525.489 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0099.lzma 2019-11-14T21:38:47.495Z,1573767527.495 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0099.lzma.bak 2019-11-14T21:38:47.495Z,1573767527.495 [DataOverHttps](INFO): SBD MOMSN=12064657 2019-11-14T21:39:08.709Z,1573767548.709 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0100.lzma 2019-11-14T21:39:10.719Z,1573767550.719 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0100.lzma.bak 2019-11-14T21:39:10.720Z,1573767550.720 [DataOverHttps](INFO): SBD MOMSN=12064660 2019-11-14T21:39:12.215Z,1573767552.215 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:39:12.215Z,1573767552.215 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:39:12.215Z,1573767552.215 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:40:21.728Z,1573767621.728 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T21:42:22.878Z,1573767742.878 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:42:22.879Z,1573767742.879 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:42:58.444Z,1573767778.444 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:42:58.444Z,1573767778.444 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:43:50.150Z,1573767830.150 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:43:50.150Z,1573767830.150 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:43:50.556Z,1573767830.556 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T21:44:12.817Z,1573767852.817 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:44:12.818Z,1573767852.818 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:44:12.818Z,1573767852.818 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:44:12.818Z,1573767852.818 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:44:13.202Z,1573767853.202 [Default:CheckIn:D] Stopped 2019-11-14T21:44:13.203Z,1573767853.203 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:44:13.606Z,1573767853.606 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 220.340837 min 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn:E] Stopped 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn] Stopped 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn](INFO): Running loop #37 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn] Running Loop=37 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:44:13.607Z,1573767853.607 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:44:15.604Z,1573767855.604 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214417.00,A,3648.16773,N,12147.28325,W,0.408,0.00,141119,,,A*7A 2019-11-14T21:44:15.606Z,1573767855.606 [NAL9602](INFO): GPS fix at 20191114T214417: (36.802796, -121.788054) 2019-11-14T21:44:15.650Z,1573767855.650 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:44:15.650Z,1573767855.650 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:44:23.268Z,1573767863.268 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0102.lzma 2019-11-14T21:44:23.801Z,1573767863.801 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-11-14T21:44:23.801Z,1573767863.801 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-11-14T21:44:23.801Z,1573767863.801 [RDI_Pathfinder](ERROR): Communications Fault 2019-11-14T21:44:23.801Z,1573767863.801 [RDI_Pathfinder](ERROR): Failed to parse: 2019-11-14T21:44:23.848Z,1573767863.848 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-11-14T21:44:24.185Z,1573767864.185 [RDI_Pathfinder](INFO): Powering down 2019-11-14T21:44:24.937Z,1573767864.937 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-11-14T21:44:24.937Z,1573767864.937 [RDI_Pathfinder] No Fault, FailCount= 1 2019-11-14T21:44:25.275Z,1573767865.275 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0102.lzma.bak 2019-11-14T21:44:25.275Z,1573767865.275 [DataOverHttps](INFO): SBD MOMSN=12064667 2019-11-14T21:44:38.650Z,1573767878.650 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-11-14T21:44:42.317Z,1573767882.317 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20191114T182338/Express0103.lzma 2019-11-14T21:44:44.323Z,1573767884.323 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0103.lzma.bak 2019-11-14T21:44:44.323Z,1573767884.323 [DataOverHttps](INFO): SBD MOMSN=12064670 2019-11-14T21:44:45.532Z,1573767885.532 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:44:45.532Z,1573767885.532 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:44:45.532Z,1573767885.532 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:44:47.514Z,1573767887.514 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T21:45:44.908Z,1573767944.908 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-14T21:47:00.498Z,1573768020.498 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2019-11-14T21:47:00.498Z,1573768020.498 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768-32768,V 2019-11-14T21:49:46.104Z,1573768186.104 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:49:46.104Z,1573768186.104 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:49:46.104Z,1573768186.104 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:49:46.104Z,1573768186.104 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:49:46.511Z,1573768186.511 [Default:CheckIn:D] Stopped 2019-11-14T21:49:46.511Z,1573768186.511 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 225.895980 min 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn:E] Stopped 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn] Stopped 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:49:46.922Z,1573768186.922 [Default:CheckIn](INFO): Running loop #38 2019-11-14T21:49:46.923Z,1573768186.923 [Default:CheckIn] Running Loop=38 2019-11-14T21:49:46.923Z,1573768186.923 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:49:46.923Z,1573768186.923 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:49:48.908Z,1573768188.908 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214951.00,A,3648.16918,N,12147.28299,W,0.117,221.26,141119,,,A*7E 2019-11-14T21:49:48.910Z,1573768188.910 [NAL9602](INFO): GPS fix at 20191114T214951: (36.802820, -121.788050) 2019-11-14T21:49:48.954Z,1573768188.954 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:49:48.954Z,1573768188.954 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:49:57.040Z,1573768197.040 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0105.lzma 2019-11-14T21:49:59.047Z,1573768199.047 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0105.lzma.bak 2019-11-14T21:49:59.047Z,1573768199.047 [DataOverHttps](INFO): SBD MOMSN=12064680 2019-11-14T21:50:16.349Z,1573768216.349 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0106.lzma 2019-11-14T21:50:18.355Z,1573768218.355 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0106.lzma.bak 2019-11-14T21:50:18.355Z,1573768218.355 [DataOverHttps](INFO): SBD MOMSN=12064683 2019-11-14T21:50:19.650Z,1573768219.650 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:50:19.650Z,1573768219.650 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:50:19.650Z,1573768219.650 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:52:17.172Z,1573768337.172 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:52:17.172Z,1573768337.172 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:52:43.028Z,1573768363.028 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:52:43.028Z,1573768363.028 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:53:11.716Z,1573768391.716 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:53:11.716Z,1573768391.716 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:54:25.240Z,1573768465.240 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:54:25.240Z,1573768465.240 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:54:37.772Z,1573768477.772 [NAL9602](INFO): SBD MO Status=2, MOMSN=5164, MT Status=2, MTMSN=0 2019-11-14T21:54:37.772Z,1573768477.772 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T21:55:04.427Z,1573768504.427 [NAL9602](INFO): SBD MO Status=0, MOMSN=5164, MT Status=0, MTMSN=0 2019-11-14T21:55:04.427Z,1573768504.427 [NAL9602](INFO): No messages in MT queue 2019-11-14T21:55:20.211Z,1573768520.211 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T21:55:20.211Z,1573768520.211 [Default:CheckIn:C.Wait] Stopped 2019-11-14T21:55:20.211Z,1573768520.211 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T21:55:20.211Z,1573768520.211 [Default:CheckIn:D] Running Loop=1 2019-11-14T21:55:20.627Z,1573768520.627 [Default:CheckIn:D] Stopped 2019-11-14T21:55:20.627Z,1573768520.627 [Default:CheckIn:E] Running Loop=1 2019-11-14T21:55:21.020Z,1573768521.020 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 231.464583 min 2019-11-14T21:55:21.020Z,1573768521.020 [Default:CheckIn:E] Stopped 2019-11-14T21:55:21.020Z,1573768521.020 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T21:55:21.020Z,1573768521.020 [Default:CheckIn] Stopped 2019-11-14T21:55:21.049Z,1573768521.049 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T21:55:21.049Z,1573768521.049 [Default:CheckIn](INFO): Running loop #39 2019-11-14T21:55:21.049Z,1573768521.049 [Default:CheckIn] Running Loop=39 2019-11-14T21:55:21.050Z,1573768521.050 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T21:55:21.050Z,1573768521.050 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T21:55:23.020Z,1573768523.020 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215525.00,A,3648.16527,N,12147.28086,W,0.175,311.96,141119,,,A*71 2019-11-14T21:55:23.026Z,1573768523.026 [NAL9602](INFO): GPS fix at 20191114T215525: (36.802754, -121.788014) 2019-11-14T21:55:23.056Z,1573768523.056 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T21:55:23.056Z,1573768523.056 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T21:55:31.188Z,1573768531.188 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0108.lzma 2019-11-14T21:55:33.195Z,1573768533.195 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0108.lzma.bak 2019-11-14T21:55:33.195Z,1573768533.195 [DataOverHttps](INFO): SBD MOMSN=12064692 2019-11-14T21:55:50.545Z,1573768550.545 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0109.lzma 2019-11-14T21:55:52.551Z,1573768552.551 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0109.lzma.bak 2019-11-14T21:55:52.551Z,1573768552.551 [DataOverHttps](INFO): SBD MOMSN=12064695 2019-11-14T21:55:53.760Z,1573768553.760 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T21:55:53.760Z,1573768553.760 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T21:55:53.760Z,1573768553.760 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T21:55:55.734Z,1573768555.734 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:00:54.359Z,1573768854.359 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:00:54.359Z,1573768854.359 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:00:54.359Z,1573768854.359 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:00:54.359Z,1573768854.359 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:00:54.800Z,1573768854.800 [Default:CheckIn:D] Stopped 2019-11-14T22:00:54.800Z,1573768854.800 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:00:55.167Z,1573768855.167 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 237.034131 min 2019-11-14T22:00:55.167Z,1573768855.167 [Default:CheckIn:E] Stopped 2019-11-14T22:00:55.167Z,1573768855.167 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:00:55.167Z,1573768855.167 [Default:CheckIn] Stopped 2019-11-14T22:00:55.168Z,1573768855.168 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:00:55.168Z,1573768855.168 [Default:CheckIn](INFO): Running loop #40 2019-11-14T22:00:55.168Z,1573768855.168 [Default:CheckIn] Running Loop=40 2019-11-14T22:00:55.168Z,1573768855.168 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:00:55.168Z,1573768855.168 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:00:57.156Z,1573768857.156 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220059.00,A,3648.16625,N,12147.28023,W,0.156,311.96,141119,,,A*76 2019-11-14T22:00:57.158Z,1573768857.158 [NAL9602](INFO): GPS fix at 20191114T220059: (36.802771, -121.788004) 2019-11-14T22:00:57.214Z,1573768857.214 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:00:57.214Z,1573768857.214 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:01:05.303Z,1573768865.303 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0111.lzma 2019-11-14T22:01:07.307Z,1573768867.307 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0111.lzma.bak 2019-11-14T22:01:07.307Z,1573768867.307 [DataOverHttps](INFO): SBD MOMSN=12064708 2019-11-14T22:01:16.140Z,1573768876.140 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:01:16.141Z,1573768876.141 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:01:24.697Z,1573768884.697 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0112.lzma 2019-11-14T22:01:26.703Z,1573768886.703 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0112.lzma.bak 2019-11-14T22:01:26.703Z,1573768886.703 [DataOverHttps](INFO): SBD MOMSN=12064713 2019-11-14T22:01:27.907Z,1573768887.907 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:01:27.907Z,1573768887.907 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:01:27.907Z,1573768887.907 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:01:37.555Z,1573768897.555 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:01:37.556Z,1573768897.556 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:01:42.836Z,1573768902.836 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-14T22:01:51.696Z,1573768911.696 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:01:51.696Z,1573768911.696 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:02:14.724Z,1573768934.724 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:02:14.724Z,1573768934.724 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:02:32.091Z,1573768952.091 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:02:32.092Z,1573768952.092 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:03:18.148Z,1573768998.148 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:03:18.148Z,1573768998.148 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:03:35.527Z,1573769015.527 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:03:35.527Z,1573769015.527 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:03:57.335Z,1573769037.335 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:03:57.336Z,1573769037.336 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:04:51.072Z,1573769091.072 [NAL9602](INFO): SBD MO Status=2, MOMSN=5165, MT Status=2, MTMSN=0 2019-11-14T22:04:51.072Z,1573769091.072 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T22:05:59.346Z,1573769159.346 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T22:06:28.489Z,1573769188.489 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:06:28.493Z,1573769188.493 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:06:28.493Z,1573769188.493 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:06:28.494Z,1573769188.494 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:06:28.874Z,1573769188.874 [Default:CheckIn:D] Stopped 2019-11-14T22:06:28.874Z,1573769188.874 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 242.602035 min 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn:E] Stopped 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn] Stopped 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn](INFO): Running loop #41 2019-11-14T22:06:29.274Z,1573769189.274 [Default:CheckIn] Running Loop=41 2019-11-14T22:06:29.275Z,1573769189.275 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:06:29.275Z,1573769189.275 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:06:31.264Z,1573769191.264 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220633.00,A,3648.16493,N,12147.27603,W,0.350,304.19,141119,,,A*7F 2019-11-14T22:06:31.266Z,1573769191.266 [NAL9602](INFO): GPS fix at 20191114T220633: (36.802749, -121.787934) 2019-11-14T22:06:31.309Z,1573769191.309 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:06:31.309Z,1573769191.309 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:06:38.996Z,1573769198.996 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0114.lzma 2019-11-14T22:06:41.003Z,1573769201.003 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0114.lzma.bak 2019-11-14T22:06:41.003Z,1573769201.003 [DataOverHttps](INFO): SBD MOMSN=12064740 2019-11-14T22:06:58.305Z,1573769218.305 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0115.lzma 2019-11-14T22:07:00.311Z,1573769220.311 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0115.lzma.bak 2019-11-14T22:07:00.311Z,1573769220.311 [DataOverHttps](INFO): SBD MOMSN=12064743 2019-11-14T22:07:01.620Z,1573769221.620 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:07:01.621Z,1573769221.621 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:07:01.621Z,1573769221.621 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:07:03.578Z,1573769223.578 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:07:54.904Z,1573769274.904 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T22:07:54.904Z,1573769274.904 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111422085829,35.0, -0.1, .9, 0 2019-11-14T22:12:02.205Z,1573769522.205 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:12:02.205Z,1573769522.205 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:12:02.205Z,1573769522.205 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:12:02.205Z,1573769522.205 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:12:02.626Z,1573769522.626 [Default:CheckIn:D] Stopped 2019-11-14T22:12:02.626Z,1573769522.626 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 248.164567 min 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn:E] Stopped 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn] Stopped 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn](INFO): Running loop #42 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn] Running Loop=42 2019-11-14T22:12:03.010Z,1573769523.010 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:12:03.011Z,1573769523.011 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:12:05.014Z,1573769525.014 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221207.00,A,3648.16321,N,12147.28256,W,0.253,304.19,141119,,,A*7A 2019-11-14T22:12:05.016Z,1573769525.016 [NAL9602](INFO): GPS fix at 20191114T221207: (36.802720, -121.788043) 2019-11-14T22:12:05.040Z,1573769525.040 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:12:05.040Z,1573769525.040 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:12:23.216Z,1573769543.216 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0117.lzma 2019-11-14T22:12:25.223Z,1573769545.223 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0117.lzma.bak 2019-11-14T22:12:25.223Z,1573769545.223 [DataOverHttps](INFO): SBD MOMSN=12064814 2019-11-14T22:12:35.706Z,1573769555.706 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T22:12:35.785Z,1573769555.785 [NAL9602](FAULT): received: +CSQ:0 OK65, 2, 0, 0, 0 OK 2019-11-14T22:12:35.785Z,1573769555.785 [NAL9602] Data Fault, FailCount= 1 2019-11-14T22:12:35.785Z,1573769555.785 [NAL9602](ERROR): Data Fault 2019-11-14T22:12:35.877Z,1573769555.877 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T22:12:36.114Z,1573769556.114 [NAL9602](INFO): Powering down 2019-11-14T22:12:36.977Z,1573769556.977 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T22:12:36.977Z,1573769556.977 [NAL9602] No Fault, FailCount= 1 2019-11-14T22:12:44.937Z,1573769564.937 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191114T182338/Express0118.lzma 2019-11-14T22:12:46.943Z,1573769566.943 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0118.lzma.bak 2019-11-14T22:12:46.943Z,1573769566.943 [DataOverHttps](INFO): SBD MOMSN=12064817 2019-11-14T22:12:48.273Z,1573769568.273 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:12:48.273Z,1573769568.273 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:12:48.273Z,1573769568.273 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:13:06.431Z,1573769586.431 [NAL9602](INFO): Powering up NAL9602 2019-11-14T22:13:17.342Z,1573769597.342 [NAL9602](INFO): NAL9602 initialized 2019-11-14T22:13:48.481Z,1573769628.481 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:17:48.892Z,1573769868.892 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:17:48.892Z,1573769868.892 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:17:48.892Z,1573769868.892 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:17:48.893Z,1573769868.893 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:17:49.284Z,1573769869.284 [Default:CheckIn:D] Stopped 2019-11-14T22:17:49.284Z,1573769869.284 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:17:49.697Z,1573769869.697 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 253.942187 min 2019-11-14T22:17:49.697Z,1573769869.697 [Default:CheckIn:E] Stopped 2019-11-14T22:17:49.697Z,1573769869.697 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:17:49.697Z,1573769869.697 [Default:CheckIn] Stopped 2019-11-14T22:17:49.698Z,1573769869.698 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:17:49.698Z,1573769869.698 [Default:CheckIn](INFO): Running loop #43 2019-11-14T22:17:49.698Z,1573769869.698 [Default:CheckIn] Running Loop=43 2019-11-14T22:17:49.698Z,1573769869.698 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:17:49.698Z,1573769869.698 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:17:51.680Z,1573769871.680 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221753.00,A,3648.16890,N,12147.27962,W,0.933,21.48,141119,,,A*41 2019-11-14T22:17:51.683Z,1573769871.683 [NAL9602](INFO): GPS fix at 20191114T221753: (36.802815, -121.787994) 2019-11-14T22:17:51.734Z,1573769871.734 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:17:51.734Z,1573769871.734 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:17:53.298Z,1573769873.298 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T22:17:59.776Z,1573769879.776 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0120.lzma 2019-11-14T22:18:01.783Z,1573769881.783 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0120.lzma.bak 2019-11-14T22:18:01.784Z,1573769881.784 [DataOverHttps](INFO): SBD MOMSN=12064822 2019-11-14T22:18:19.177Z,1573769899.177 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191114T182338/Express0121.lzma 2019-11-14T22:18:21.183Z,1573769901.183 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0121.lzma.bak 2019-11-14T22:18:21.183Z,1573769901.183 [DataOverHttps](INFO): SBD MOMSN=12064826 2019-11-14T22:18:22.449Z,1573769902.449 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:18:22.450Z,1573769902.450 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:18:22.451Z,1573769902.451 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:18:24.004Z,1573769904.004 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:23:22.989Z,1573770202.989 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:23:22.989Z,1573770202.989 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:23:22.990Z,1573770202.990 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:23:22.990Z,1573770202.990 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:23:23.399Z,1573770203.399 [Default:CheckIn:D] Stopped 2019-11-14T22:23:23.399Z,1573770203.399 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 259.510775 min 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn:E] Stopped 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn] Stopped 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:23:23.823Z,1573770203.823 [Default:CheckIn](INFO): Running loop #44 2019-11-14T22:23:23.824Z,1573770203.824 [Default:CheckIn] Running Loop=44 2019-11-14T22:23:23.824Z,1573770203.824 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:23:23.824Z,1573770203.824 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:23:25.790Z,1573770205.790 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222327.00,A,3648.16532,N,12147.28629,W,0.175,21.48,141119,,,A*45 2019-11-14T22:23:25.792Z,1573770205.792 [NAL9602](INFO): GPS fix at 20191114T222327: (36.802755, -121.788105) 2019-11-14T22:23:25.826Z,1573770205.826 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:23:25.826Z,1573770205.826 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:23:33.128Z,1573770213.128 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0123.lzma 2019-11-14T22:23:35.151Z,1573770215.151 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0123.lzma.bak 2019-11-14T22:23:35.151Z,1573770215.151 [DataOverHttps](INFO): SBD MOMSN=12064842 2019-11-14T22:23:52.785Z,1573770232.785 [DataOverHttps](INFO): Sending 199 bytes from file Logs/20191114T182338/Express0124.lzma 2019-11-14T22:23:54.791Z,1573770234.791 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0124.lzma.bak 2019-11-14T22:23:54.791Z,1573770234.791 [DataOverHttps](INFO): SBD MOMSN=12064845 2019-11-14T22:23:56.124Z,1573770236.124 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:23:56.124Z,1573770236.124 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:23:56.124Z,1573770236.124 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:25:48.833Z,1573770348.833 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T22:25:48.833Z,1573770348.833 [RDI_Pathfinder](ERROR): Failed to parse: :TS2265229,35.0, -0.1, 0.0,1448.9, 0 2019-11-14T22:28:28.402Z,1573770508.402 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T22:28:56.724Z,1573770536.724 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:28:56.724Z,1573770536.724 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:28:56.724Z,1573770536.724 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:28:56.725Z,1573770536.725 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:28:57.186Z,1573770537.186 [Default:CheckIn:D] Stopped 2019-11-14T22:28:57.187Z,1573770537.187 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:28:57.540Z,1573770537.540 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 265.073910 min 2019-11-14T22:28:57.540Z,1573770537.540 [Default:CheckIn:E] Stopped 2019-11-14T22:28:57.540Z,1573770537.540 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn] Stopped 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn](INFO): Running loop #45 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn] Running Loop=45 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:28:57.541Z,1573770537.541 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:28:59.512Z,1573770539.512 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222901.00,A,3648.16572,N,12147.28430,W,0.797,5.80,141119,,,A*7D 2019-11-14T22:28:59.515Z,1573770539.515 [NAL9602](INFO): GPS fix at 20191114T222901: (36.802762, -121.788072) 2019-11-14T22:28:59.571Z,1573770539.571 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:28:59.571Z,1573770539.571 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:29:07.252Z,1573770547.252 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0126.lzma 2019-11-14T22:29:09.263Z,1573770549.263 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0126.lzma.bak 2019-11-14T22:29:09.263Z,1573770549.263 [DataOverHttps](INFO): SBD MOMSN=12064851 2019-11-14T22:29:09.606Z,1573770549.606 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2019-11-14T22:29:09.606Z,1573770549.606 [DropWeight] Hardware Fault, FailCount= 1 2019-11-14T22:29:09.606Z,1573770549.606 [DropWeight](ERROR): Hardware Fault 2019-11-14T22:29:09.695Z,1573770549.695 [CommandLine](FAULT): Scheduling is paused 2019-11-14T22:29:09.695Z,1573770549.695 [CBIT](INFO): Critical error at 20191114T222909 2019-11-14T22:29:09.701Z,1573770549.701 [CBIT](ERROR): Hardware Fault in component: DropWeight 2019-11-14T22:29:09.702Z,1573770549.702 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2019-11-14T22:29:10.043Z,1573770550.043 [CBIT](INFO): Critical error at 20191114T222909 2019-11-14T22:29:26.586Z,1573770566.586 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20191114T182338/Express0127.lzma 2019-11-14T22:29:28.591Z,1573770568.591 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0127.lzma.bak 2019-11-14T22:29:28.591Z,1573770568.591 [DataOverHttps](INFO): SBD MOMSN=12064858 2019-11-14T22:29:29.846Z,1573770569.846 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:29:29.846Z,1573770569.846 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:29:29.846Z,1573770569.846 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:29:31.830Z,1573770571.830 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:30:30.458Z,1573770630.458 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-14T22:30:30.458Z,1573770630.458 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , + +0.00, 0.00,2751.66 2019-11-14T22:33:10.453Z,1573770790.453 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T22:34:30.459Z,1573770870.459 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:34:30.459Z,1573770870.459 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:34:30.459Z,1573770870.459 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:34:30.460Z,1573770870.460 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:34:30.834Z,1573770870.834 [Default:CheckIn:D] Stopped 2019-11-14T22:34:30.834Z,1573770870.834 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 270.634701 min 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn:E] Stopped 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn] Stopped 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn](INFO): Running loop #46 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn] Running Loop=46 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:34:31.238Z,1573770871.238 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:34:33.232Z,1573770873.232 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223435.00,A,3648.16458,N,12147.27738,W,0.389,5.80,141119,,,A*70 2019-11-14T22:34:33.234Z,1573770873.234 [NAL9602](INFO): GPS fix at 20191114T223435: (36.802743, -121.787956) 2019-11-14T22:34:33.275Z,1573770873.275 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:34:33.275Z,1573770873.275 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:34:40.661Z,1573770880.661 [DataOverHttps](INFO): Sending 172 bytes from file Logs/20191114T182338/Courier0129.lzma 2019-11-14T22:34:42.667Z,1573770882.667 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0129.lzma.bak 2019-11-14T22:34:42.667Z,1573770882.667 [DataOverHttps](INFO): SBD MOMSN=12064866 2019-11-14T22:35:01.869Z,1573770901.869 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20191114T182338/Express0130.lzma 2019-11-14T22:35:03.875Z,1573770903.875 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0130.lzma.bak 2019-11-14T22:35:03.875Z,1573770903.875 [DataOverHttps](INFO): SBD MOMSN=12064871 2019-11-14T22:35:03.926Z,1573770903.926 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-14T22:35:04.009Z,1573770904.009 [NAL9602](FAULT): received: +CSQ:0 OK65, 2, 0, 0, 0 OK 2019-11-14T22:35:04.009Z,1573770904.009 [NAL9602] Data Fault, FailCount= 1 2019-11-14T22:35:04.009Z,1573770904.009 [NAL9602](ERROR): Data Fault 2019-11-14T22:35:04.080Z,1573770904.080 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-14T22:35:04.334Z,1573770904.334 [NAL9602](INFO): Powering down 2019-11-14T22:35:05.176Z,1573770905.176 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:35:05.176Z,1573770905.176 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:35:05.176Z,1573770905.176 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:35:05.184Z,1573770905.184 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-14T22:35:05.185Z,1573770905.185 [NAL9602] No Fault, FailCount= 1 2019-11-14T22:35:06.811Z,1573770906.811 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-14T22:35:06.812Z,1573770906.812 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, +0.00, +0.00 2019-11-14T22:35:34.628Z,1573770934.628 [NAL9602](INFO): Powering up NAL9602 2019-11-14T22:35:45.542Z,1573770945.542 [NAL9602](INFO): NAL9602 initialized 2019-11-14T22:36:16.648Z,1573770976.648 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:36:34.054Z,1573770994.054 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-14T22:36:34.056Z,1573770994.056 [BPC1](INFO): Received data from all battery sticks. 2019-11-14T22:37:47.172Z,1573771067.172 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T22:37:47.173Z,1573771067.173 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111422385029,35.0, -0.1, 0.0, 0 2019-11-14T22:40:05.775Z,1573771205.775 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:40:05.775Z,1573771205.775 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:40:05.775Z,1573771205.775 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:40:05.775Z,1573771205.775 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:40:06.160Z,1573771206.160 [Default:CheckIn:D] Stopped 2019-11-14T22:40:06.160Z,1573771206.160 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:40:06.604Z,1573771206.604 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 276.223470 min 2019-11-14T22:40:06.604Z,1573771206.604 [Default:CheckIn:E] Stopped 2019-11-14T22:40:06.604Z,1573771206.604 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:40:06.604Z,1573771206.604 [Default:CheckIn] Stopped 2019-11-14T22:40:06.605Z,1573771206.605 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:40:06.605Z,1573771206.605 [Default:CheckIn](INFO): Running loop #47 2019-11-14T22:40:06.606Z,1573771206.606 [Default:CheckIn] Running Loop=47 2019-11-14T22:40:06.608Z,1573771206.608 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:40:06.608Z,1573771206.608 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:40:08.557Z,1573771208.557 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224009.00,A,3648.16469,N,12147.28174,W,0.175,166.03,141119,,,A*71 2019-11-14T22:40:08.559Z,1573771208.559 [NAL9602](INFO): GPS fix at 20191114T224009: (36.802745, -121.788029) 2019-11-14T22:40:08.614Z,1573771208.614 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:40:08.614Z,1573771208.614 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:40:10.174Z,1573771210.174 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T22:40:17.076Z,1573771217.076 [DataOverHttps](INFO): Sending 82 bytes from file Logs/20191114T182338/Courier0132.lzma 2019-11-14T22:40:19.087Z,1573771219.087 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0132.lzma.bak 2019-11-14T22:40:19.088Z,1573771219.088 [DataOverHttps](INFO): SBD MOMSN=12064882 2019-11-14T22:40:36.489Z,1573771236.489 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191114T182338/Express0133.lzma 2019-11-14T22:40:38.495Z,1573771238.495 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0133.lzma.bak 2019-11-14T22:40:38.495Z,1573771238.495 [DataOverHttps](INFO): SBD MOMSN=12064885 2019-11-14T22:40:39.712Z,1573771239.712 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:40:39.712Z,1573771239.712 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:40:39.712Z,1573771239.712 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:40:40.882Z,1573771240.882 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:44:09.814Z,1573771449.814 [CBIT](INFO): Clearing failed state for component DropWeight 2019-11-14T22:44:09.814Z,1573771449.814 [DropWeight] No Fault, FailCount= 1 2019-11-14T22:45:40.313Z,1573771540.313 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:45:40.313Z,1573771540.313 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:45:40.313Z,1573771540.313 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:45:40.313Z,1573771540.313 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:45:40.710Z,1573771540.710 [Default:CheckIn:D] Stopped 2019-11-14T22:45:40.711Z,1573771540.711 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:45:41.110Z,1573771541.110 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 281.799316 min 2019-11-14T22:45:41.110Z,1573771541.110 [Default:CheckIn:E] Stopped 2019-11-14T22:45:41.110Z,1573771541.110 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:45:41.110Z,1573771541.110 [Default:CheckIn] Stopped 2019-11-14T22:45:41.111Z,1573771541.111 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:45:41.111Z,1573771541.111 [Default:CheckIn](INFO): Running loop #48 2019-11-14T22:45:41.111Z,1573771541.111 [Default:CheckIn] Running Loop=48 2019-11-14T22:45:41.111Z,1573771541.111 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:45:41.111Z,1573771541.111 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:45:43.108Z,1573771543.108 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224545.00,A,3648.16589,N,12147.28332,W,0.505,47.19,141119,,,A*49 2019-11-14T22:45:43.121Z,1573771543.121 [NAL9602](INFO): GPS fix at 20191114T224545: (36.802765, -121.788055) 2019-11-14T22:45:43.145Z,1573771543.145 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:45:43.145Z,1573771543.145 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:45:50.828Z,1573771550.828 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0135.lzma 2019-11-14T22:45:52.835Z,1573771552.835 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0135.lzma.bak 2019-11-14T22:45:52.835Z,1573771552.835 [DataOverHttps](INFO): SBD MOMSN=12064893 2019-11-14T22:45:56.435Z,1573771556.435 [NAL9602](INFO): SBD MO Status=0, MOMSN=5165, MT Status=0, MTMSN=0 2019-11-14T22:45:56.435Z,1573771556.435 [NAL9602](INFO): No messages in MT queue 2019-11-14T22:46:10.481Z,1573771570.481 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191114T182338/Express0136.lzma 2019-11-14T22:46:12.487Z,1573771572.487 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0136.lzma.bak 2019-11-14T22:46:12.487Z,1573771572.487 [DataOverHttps](INFO): SBD MOMSN=12064896 2019-11-14T22:46:13.845Z,1573771573.845 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:46:13.846Z,1573771573.846 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:46:13.846Z,1573771573.846 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:46:27.142Z,1573771587.142 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:47:33.834Z,1573771653.834 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T22:47:33.834Z,1573771653.834 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111422483729,35.0, -0.1, 0.0,10 2019-11-14T22:51:12.795Z,1573771872.795 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T22:51:12.795Z,1573771872.795 [RDI_Pathfinder](ERROR): Failed to parse: :TS,191114225.0, -0.1, 0.0,1448.9, 0 2019-11-14T22:51:14.416Z,1573771874.416 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:51:14.416Z,1573771874.416 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:51:14.417Z,1573771874.417 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:51:14.418Z,1573771874.418 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:51:14.841Z,1573771874.841 [Default:CheckIn:D] Stopped 2019-11-14T22:51:14.842Z,1573771874.842 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 287.368132 min 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn:E] Stopped 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn] Stopped 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn](INFO): Running loop #49 2019-11-14T22:51:15.244Z,1573771875.244 [Default:CheckIn] Running Loop=49 2019-11-14T22:51:15.245Z,1573771875.245 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:51:15.245Z,1573771875.245 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:51:17.227Z,1573771877.227 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225119.00,A,3648.17107,N,12147.28935,W,0.797,47.19,141119,,,A*42 2019-11-14T22:51:17.230Z,1573771877.230 [NAL9602](INFO): GPS fix at 20191114T225119: (36.802851, -121.788156) 2019-11-14T22:51:17.269Z,1573771877.269 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:51:17.269Z,1573771877.269 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:51:25.309Z,1573771885.309 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191114T182338/Courier0138.lzma 2019-11-14T22:51:27.315Z,1573771887.315 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0138.lzma.bak 2019-11-14T22:51:27.315Z,1573771887.315 [DataOverHttps](INFO): SBD MOMSN=12064910 2019-11-14T22:51:44.764Z,1573771904.764 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191114T182338/Express0139.lzma 2019-11-14T22:51:46.775Z,1573771906.775 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0139.lzma.bak 2019-11-14T22:51:46.776Z,1573771906.776 [DataOverHttps](INFO): SBD MOMSN=12064914 2019-11-14T22:51:47.970Z,1573771907.970 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:51:47.970Z,1573771907.970 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:51:47.970Z,1573771907.970 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:56:19.440Z,1573772179.440 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-14T22:56:48.568Z,1573772208.568 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T22:56:48.568Z,1573772208.568 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:56:48.568Z,1573772208.568 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:56:48.568Z,1573772208.568 [Default:CheckIn:D] Running Loop=1 2019-11-14T22:56:48.942Z,1573772208.942 [Default:CheckIn:D] Stopped 2019-11-14T22:56:48.942Z,1573772208.942 [Default:CheckIn:E] Running Loop=1 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 292.936491 min 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn:E] Stopped 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn] Stopped 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn](INFO): Running loop #50 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn] Running Loop=50 2019-11-14T22:56:49.351Z,1573772209.351 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T22:56:49.352Z,1573772209.352 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T22:56:51.344Z,1573772211.344 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,225653.00,A,3648.16774,N,12147.28723,W,0.933,24.36,141119,,,A*49 2019-11-14T22:56:51.346Z,1573772211.346 [NAL9602](INFO): GPS fix at 20191114T225653: (36.802796, -121.788121) 2019-11-14T22:56:51.427Z,1573772211.427 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T22:56:51.427Z,1573772211.427 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T22:56:59.469Z,1573772219.469 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191114T182338/Courier0141.lzma 2019-11-14T22:57:01.475Z,1573772221.475 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Courier0141.lzma.bak 2019-11-14T22:57:01.475Z,1573772221.475 [DataOverHttps](INFO): SBD MOMSN=12064953 2019-11-14T22:57:18.809Z,1573772238.809 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20191114T182338/Express0142.lzma 2019-11-14T22:57:20.823Z,1573772240.823 [DataOverHttps](INFO): Moved sent file to Logs/20191114T182338/Express0142.lzma.bak 2019-11-14T22:57:20.823Z,1573772240.823 [DataOverHttps](INFO): SBD MOMSN=12064956 2019-11-14T22:57:22.081Z,1573772242.081 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T22:57:22.081Z,1573772242.081 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T22:57:22.081Z,1573772242.081 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T22:57:23.656Z,1573772243.656 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T22:59:28.923Z,1573772368.923 [CommandLine](IMPORTANT): got command failComponent 2019-11-14T22:59:28.923Z,1573772368.923 [CommandLine](IMPORTANT): Failed components: 2019-11-14T22:59:28.923Z,1573772368.923 [CommandLine](IMPORTANT): No failed Components. 2019-11-14T22:59:32.086Z,1573772372.086 [CommandLine](IMPORTANT): got command quit 2019-11-14T22:59:33.090Z,1573772373.090 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:33.090Z,1573772373.090 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.091Z,1573772373.091 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-11-14T22:59:33.091Z,1573772373.091 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.092Z,1573772373.092 [CommandLine](INFO): Join timeout helper Thread ID is 3539 2019-11-14T22:59:33.101Z,1573772373.101 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-11-14T22:59:33.101Z,1573772373.101 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.101Z,1573772373.101 [NavChartDb](INFO): Join timeout helper Thread ID is 3540 2019-11-14T22:59:33.321Z,1573772373.321 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:33.321Z,1573772373.321 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.329Z,1573772373.329 [ComponentRegistry](INFO): Shutting down WetLabsUBAT ThreadHandler 2019-11-14T22:59:33.329Z,1573772373.329 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.329Z,1573772373.329 [WetLabsUBAT](INFO): Join timeout helper Thread ID is 3541 2019-11-14T22:59:33.549Z,1573772373.549 [WetLabsUBAT ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:33.549Z,1573772373.549 [WetLabsUBAT](INFO): Powering down 2019-11-14T22:59:33.550Z,1573772373.550 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.569Z,1573772373.569 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-11-14T22:59:33.569Z,1573772373.569 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.569Z,1573772373.569 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3542 2019-11-14T22:59:33.785Z,1573772373.785 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:33.786Z,1573772373.786 [WetLabsBB2FL](INFO): Powering down 2019-11-14T22:59:33.786Z,1573772373.786 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.789Z,1573772373.789 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-11-14T22:59:33.789Z,1573772373.789 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.789Z,1573772373.789 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3543 2019-11-14T22:59:33.821Z,1573772373.821 [CTD_Seabird](INFO): Powering down 2019-11-14T22:59:33.833Z,1573772373.833 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:33.833Z,1573772373.833 [CTD_Seabird](INFO): Powering down 2019-11-14T22:59:33.853Z,1573772373.853 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.874Z,1573772373.874 [ComponentRegistry](INFO): Shutting down BackSeatDriver ThreadHandler 2019-11-14T22:59:33.874Z,1573772373.874 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:33.874Z,1573772373.874 [BackSeatDriver](INFO): Join timeout helper Thread ID is 3544 2019-11-14T22:59:34.029Z,1573772374.029 [BackSeatDriver ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:34.030Z,1573772374.030 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:34.046Z,1573772374.046 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-11-14T22:59:34.046Z,1573772374.046 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:34.046Z,1573772374.046 [Radio_Surface](INFO): Join timeout helper Thread ID is 3545 2019-11-14T22:59:34.365Z,1573772374.365 [Radio_Surface](INFO): Powering down 2019-11-14T22:59:34.366Z,1573772374.366 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:34.367Z,1573772374.367 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:34.382Z,1573772374.382 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-11-14T22:59:34.382Z,1573772374.382 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:34.382Z,1573772374.382 [DataOverHttps](INFO): Join timeout helper Thread ID is 3546 2019-11-14T22:59:35.037Z,1573772375.037 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:35.037Z,1573772375.037 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.046Z,1573772375.046 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-11-14T22:59:35.046Z,1573772375.046 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.047Z,1573772375.047 [logger](INFO): Join timeout helper Thread ID is 3547 2019-11-14T22:59:35.081Z,1573772375.081 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:35.082Z,1573772375.082 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.094Z,1573772375.094 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-11-14T22:59:35.094Z,1573772375.094 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.094Z,1573772375.094 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-11-14T22:59:35.094Z,1573772375.094 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.094Z,1573772375.094 [controlThread](INFO): Join timeout helper Thread ID is 3548 2019-11-14T22:59:35.353Z,1573772375.353 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-14T22:59:35.353Z,1573772375.353 [controlThread](DEBUG): Uninitializing ControlThread 2019-11-14T22:59:35.353Z,1573772375.353 [AHRS_M2](INFO): Powering down 2019-11-14T22:59:35.426Z,1573772375.426 [NAL9602](INFO): Powering down 2019-11-14T22:59:35.497Z,1573772375.497 [RDI_Pathfinder](INFO): Powering down 2019-11-14T22:59:35.498Z,1573772375.498 [DAT](INFO): Powering down 2019-11-14T22:59:35.618Z,1573772375.618 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-11-14T22:59:35.619Z,1573772375.619 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-11-14T22:59:35.619Z,1573772375.619 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-11-14T22:59:35.619Z,1573772375.619 [MissionManager](INFO): Uninitializing Mission Default 2019-11-14T22:59:35.620Z,1573772375.620 [Default] Stopped 2019-11-14T22:59:35.620Z,1573772375.620 [Default](DEBUG): Aggregate::uninitialize Default 2019-11-14T22:59:35.620Z,1573772375.620 [Default:B.GoToSurface] Stopped 2019-11-14T22:59:35.620Z,1573772375.620 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-11-14T22:59:35.620Z,1573772375.620 [Default:CheckIn] Stopped 2019-11-14T22:59:35.620Z,1573772375.620 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T22:59:35.620Z,1573772375.620 [Default:CheckIn:C.Wait] Stopped 2019-11-14T22:59:35.620Z,1573772375.620 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T22:59:35.623Z,1573772375.623 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-11-14T22:59:35.623Z,1573772375.623 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-11-14T22:59:35.623Z,1573772375.623 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-11-14T22:59:35.623Z,1573772375.623 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-11-14T22:59:35.624Z,1573772375.624 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-11-14T22:59:35.624Z,1573772375.624 [BuoyancyServo](INFO): Powering down 2019-11-14T22:59:35.637Z,1573772375.637 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-11-14T22:59:35.637Z,1573772375.637 [ElevatorServo](INFO): Powering down 2019-11-14T22:59:35.638Z,1573772375.638 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-11-14T22:59:35.638Z,1573772375.638 [MassServo](INFO): Powering down 2019-11-14T22:59:35.639Z,1573772375.639 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-11-14T22:59:35.639Z,1573772375.639 [RudderServo](INFO): Powering down 2019-11-14T22:59:35.640Z,1573772375.640 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-11-14T22:59:35.640Z,1573772375.640 [ThrusterServo](INFO): Powering down 2019-11-14T22:59:35.641Z,1573772375.641 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-11-14T22:59:35.641Z,1573772375.641 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-11-14T22:59:35.641Z,1573772375.641 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-11-14T22:59:35.641Z,1573772375.641 [CBIT](DEBUG): Powering off loads. 2019-11-14T22:59:35.653Z,1573772375.653 [CBIT](DEBUG): Disabling WDT. 2019-11-14T22:59:35.665Z,1573772375.665 [CBIT](DEBUG): Opening all GF detection circuits. 2019-11-14T22:59:35.666Z,1573772375.666 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.847Z,1573772375.847 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.863Z,1573772375.863 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.965Z,1573772375.965 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.978Z,1573772375.978 [WetLabsUBAT](INFO): WetLabs destructor: dataLog is open - close it 2019-11-14T22:59:35.978Z,1573772375.978 [WetLabsUBAT](INFO): WetLabs destructor: done 2019-11-14T22:59:35.981Z,1573772375.981 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.984Z,1573772375.984 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:35.987Z,1573772375.987 [BackSeatDriver ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:36.005Z,1573772376.005 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-14T22:59:36.152Z,1573772376.152 [logger ThreadHandler](INFO): Thread cancelled.