2019-07-18T17:26:13.000Z,1563470774.000 [DataOverHttps](INFO): Received command:restart logs 2019-07-18T17:26:14.009Z,1563470774.009 [CommandLine](IMPORTANT): got command restart logs 2019-07-18T17:26:16.163Z,1563470776.163 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:26:16.163Z,1563470776.163 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:26:16.163Z,1563470776.163 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:26:16.163Z,1563470776.163 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:26:16.563Z,1563470776.563 [Default:CheckIn:D] Stopped 2019-07-18T17:26:16.563Z,1563470776.563 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:26:16.979Z,1563470776.979 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.693064 min 2019-07-18T17:26:16.979Z,1563470776.979 [Default:CheckIn:E] Stopped 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn] Stopped 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn](INFO): Running loop #4 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn] Running Loop=4 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:26:16.984Z,1563470776.984 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:26:18.572Z,1563470778.572 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:26:18.964Z,1563470778.964 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172618.00,A,3648.52035,N,12149.41172,W,0.369,127.14,180719,,,D*7F 2019-07-18T17:26:18.966Z,1563470778.966 [NAL9602](INFO): GPS fix at 20190718T172618: (36.808673, -121.823529) 2019-07-18T17:26:18.991Z,1563470778.991 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:26:18.991Z,1563470778.991 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:26:28.700Z,1563470788.700 [DataOverHttps](INFO): Sending 177 bytes from file Logs/20190718T151446/Express0052.lzma 2019-07-18T17:26:29.505Z,1563470789.505 [DataOverHttps](INFO): Moved sent file to Logs/20190718T151446/Express0052.lzma.bak 2019-07-18T17:26:29.505Z,1563470789.505 [DataOverHttps](INFO): SBD MOMSN=11453971 2019-07-18T17:26:30.465Z,1563470790.465 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:26:30.465Z,1563470790.465 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:26:30.465Z,1563470790.465 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:26:51.817Z,1563470811.817 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:28:04.577Z,1563470884.577 [RDI_Pathfinder](ERROR): Failed to parse: 68,-32768,-32768,V 2019-07-18T17:31:31.005Z,1563471091.005 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:31:31.005Z,1563471091.005 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:31:31.005Z,1563471091.005 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:31:31.006Z,1563471091.006 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:31:31.435Z,1563471091.435 [Default:CheckIn:D] Stopped 2019-07-18T17:31:31.435Z,1563471091.435 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:31:31.809Z,1563471091.809 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.940926 min 2019-07-18T17:31:31.809Z,1563471091.809 [Default:CheckIn:E] Stopped 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn] Stopped 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn](INFO): Running loop #5 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn] Running Loop=5 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:31:31.810Z,1563471091.810 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:31:33.412Z,1563471093.412 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:31:33.807Z,1563471093.807 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173132.00,A,3648.32308,N,12149.87345,W,18.719,233.65,180719,,,D*4C 2019-07-18T17:31:33.810Z,1563471093.810 [NAL9602](INFO): GPS fix at 20190718T173132: (36.805385, -121.831224) 2019-07-18T17:31:33.844Z,1563471093.844 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:31:33.844Z,1563471093.844 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:31:39.764Z,1563471099.764 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190718T172614/Courier0005.lzma 2019-07-18T17:31:40.569Z,1563471100.569 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0005.lzma.bak 2019-07-18T17:31:40.569Z,1563471100.569 [DataOverHttps](INFO): SBD MOMSN=11453976 2019-07-18T17:31:55.562Z,1563471115.562 [DataOverHttps](INFO): Sending 352 bytes from file Logs/20190718T172614/Express0007.lzma 2019-07-18T17:31:56.357Z,1563471116.357 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0007.lzma.bak 2019-07-18T17:31:56.357Z,1563471116.357 [DataOverHttps](INFO): SBD MOMSN=11453980 2019-07-18T17:31:57.279Z,1563471117.279 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:31:57.279Z,1563471117.279 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:31:57.279Z,1563471117.279 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:32:04.510Z,1563471124.510 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-18T17:32:04.588Z,1563471124.588 [NAL9602](FAULT): received: +CSQ:0 OK86, 2, 0, 0, 0 OK 2019-07-18T17:32:04.588Z,1563471124.588 [NAL9602] Data Fault, FailCount= 1 2019-07-18T17:32:04.588Z,1563471124.588 [NAL9602](ERROR): Data Fault 2019-07-18T17:32:04.723Z,1563471124.723 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-18T17:32:04.914Z,1563471124.914 [NAL9602](INFO): Powering down 2019-07-18T17:32:05.882Z,1563471125.882 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-18T17:32:05.882Z,1563471125.882 [NAL9602] No Fault, FailCount= 1 2019-07-18T17:32:35.218Z,1563471155.218 [NAL9602](INFO): Powering up NAL9602 2019-07-18T17:32:46.126Z,1563471166.126 [NAL9602](INFO): NAL9602 initialized 2019-07-18T17:33:17.229Z,1563471197.229 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:36:57.867Z,1563471417.867 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:36:57.867Z,1563471417.867 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:36:57.867Z,1563471417.867 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:36:57.867Z,1563471417.867 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:36:58.258Z,1563471418.258 [Default:CheckIn:D] Stopped 2019-07-18T17:36:58.259Z,1563471418.259 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:36:58.664Z,1563471418.664 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.387988 min 2019-07-18T17:36:58.664Z,1563471418.664 [Default:CheckIn:E] Stopped 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn] Stopped 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn](INFO): Running loop #6 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn] Running Loop=6 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:36:58.665Z,1563471418.665 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:37:00.256Z,1563471420.256 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:37:00.645Z,1563471420.645 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173658.00,A,3647.85438,N,12150.73794,W,0.253,88.29,180719,,,A*46 2019-07-18T17:37:00.648Z,1563471420.648 [NAL9602](INFO): GPS fix at 20190718T173658: (36.797573, -121.845632) 2019-07-18T17:37:00.683Z,1563471420.683 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:37:00.683Z,1563471420.683 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:37:02.334Z,1563471422.334 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-18T17:37:06.535Z,1563471426.535 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190718T172614/Courier0009.lzma 2019-07-18T17:37:07.341Z,1563471427.341 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0009.lzma.bak 2019-07-18T17:37:07.342Z,1563471427.342 [DataOverHttps](INFO): SBD MOMSN=11453998 2019-07-18T17:37:19.048Z,1563471439.048 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20190718T172614/Express0010.lzma 2019-07-18T17:37:19.853Z,1563471439.853 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0010.lzma.bak 2019-07-18T17:37:19.854Z,1563471439.854 [DataOverHttps](INFO): SBD MOMSN=11454004 2019-07-18T17:37:20.571Z,1563471440.571 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:37:20.571Z,1563471440.571 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:37:20.571Z,1563471440.571 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:37:33.041Z,1563471453.041 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:39:01.020Z,1563471541.020 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:39:05.060Z,1563471545.060 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.195599 2019-07-18T17:39:36.168Z,1563471576.168 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:40:11.316Z,1563471611.316 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:40:46.464Z,1563471646.464 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:41:21.612Z,1563471681.612 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:41:40.204Z,1563471700.204 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003686 2019-07-18T17:42:21.129Z,1563471741.129 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:42:21.129Z,1563471741.129 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:42:21.129Z,1563471741.129 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:42:21.129Z,1563471741.129 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:42:21.543Z,1563471741.543 [Default:CheckIn:D] Stopped 2019-07-18T17:42:21.543Z,1563471741.543 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:42:21.929Z,1563471741.929 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 38.776066 min 2019-07-18T17:42:21.929Z,1563471741.929 [Default:CheckIn:E] Stopped 2019-07-18T17:42:21.929Z,1563471741.929 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:42:21.929Z,1563471741.929 [Default:CheckIn] Stopped 2019-07-18T17:42:21.930Z,1563471741.930 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:42:21.930Z,1563471741.930 [Default:CheckIn](INFO): Running loop #7 2019-07-18T17:42:21.930Z,1563471741.930 [Default:CheckIn] Running Loop=7 2019-07-18T17:42:21.930Z,1563471741.930 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:42:21.930Z,1563471741.930 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:42:23.536Z,1563471743.536 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:42:23.927Z,1563471743.927 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174223.00,A,3647.87174,N,12149.71757,W,28.419,79.58,180719,,,D*7C 2019-07-18T17:42:23.929Z,1563471743.929 [NAL9602](INFO): GPS fix at 20190718T174223: (36.797862, -121.828626) 2019-07-18T17:42:23.954Z,1563471743.954 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:42:23.954Z,1563471743.954 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:42:29.555Z,1563471749.555 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190718T172614/Courier0012.lzma 2019-07-18T17:42:30.366Z,1563471750.366 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0012.lzma.bak 2019-07-18T17:42:30.367Z,1563471750.367 [DataOverHttps](INFO): SBD MOMSN=11454033 2019-07-18T17:42:41.944Z,1563471761.944 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20190718T172614/Express0013.lzma 2019-07-18T17:42:42.749Z,1563471762.749 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0013.lzma.bak 2019-07-18T17:42:42.749Z,1563471762.749 [DataOverHttps](INFO): SBD MOMSN=11454036 2019-07-18T17:42:43.343Z,1563471763.343 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:42:43.343Z,1563471763.343 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:42:43.343Z,1563471763.343 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:42:43.723Z,1563471763.723 [NAL9602](INFO): SBD MO Status=0, MOMSN=8286, MT Status=0, MTMSN=0 2019-07-18T17:42:43.723Z,1563471763.723 [NAL9602](INFO): No messages in MT queue 2019-07-18T17:43:14.422Z,1563471794.422 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:43:48.402Z,1563471828.402 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-18T17:43:48.402Z,1563471828.402 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768, 2019-07-18T17:43:48.944Z,1563471828.944 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:43:49.752Z,1563471829.752 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.211559 2019-07-18T17:44:04.944Z,1563471844.944 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T17:44:04.944Z,1563471844.944 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071810541634,35.0, -0.1, 0.0,14 2019-07-18T17:44:24.092Z,1563471864.092 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:44:45.641Z,1563471885.641 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003710 2019-07-18T17:46:09.524Z,1563471969.524 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2019-07-18T17:46:15.180Z,1563471975.180 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.135696 2019-07-18T17:46:44.943Z,1563472004.943 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T17:46:44.943Z,1563472004.943 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071810565634,35.0, -0.1, 0.0 0 2019-07-18T17:47:19.832Z,1563472039.832 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-07-18T17:47:30.378Z,1563472050.378 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.011457 2019-07-18T17:47:43.929Z,1563472063.929 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:47:43.929Z,1563472063.929 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:47:43.929Z,1563472063.929 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:47:43.929Z,1563472063.929 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:47:44.333Z,1563472064.333 [Default:CheckIn:D] Stopped 2019-07-18T17:47:44.333Z,1563472064.333 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.155900 min 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn:E] Stopped 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn] Stopped 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:47:44.763Z,1563472064.763 [Default:CheckIn](INFO): Running loop #8 2019-07-18T17:47:44.768Z,1563472064.768 [Default:CheckIn] Running Loop=8 2019-07-18T17:47:44.769Z,1563472064.769 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:47:44.769Z,1563472064.769 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:47:46.340Z,1563472066.340 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:47:46.755Z,1563472066.755 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174745.00,A,3648.47388,N,12147.11680,W,7.581,168.67,180719,,,D*78 2019-07-18T17:47:46.757Z,1563472066.757 [NAL9602](INFO): GPS fix at 20190718T174745: (36.807898, -121.785280) 2019-07-18T17:47:46.849Z,1563472066.849 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:47:46.849Z,1563472066.849 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:47:53.179Z,1563472073.179 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0015.lzma 2019-07-18T17:47:53.985Z,1563472073.985 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0015.lzma.bak 2019-07-18T17:47:53.985Z,1563472073.985 [DataOverHttps](INFO): SBD MOMSN=11454060 2019-07-18T17:48:00.161Z,1563472080.161 [NAL9602](INFO): SBD MO Status=0, MOMSN=8287, MT Status=0, MTMSN=0 2019-07-18T17:48:00.161Z,1563472080.161 [NAL9602](INFO): No messages in MT queue 2019-07-18T17:48:05.916Z,1563472085.916 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190718T172614/Express0016.lzma 2019-07-18T17:48:06.725Z,1563472086.725 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0016.lzma.bak 2019-07-18T17:48:06.725Z,1563472086.725 [DataOverHttps](INFO): SBD MOMSN=11454063 2019-07-18T17:48:07.473Z,1563472087.473 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:48:07.473Z,1563472087.473 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:48:07.473Z,1563472087.473 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:48:30.876Z,1563472110.876 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:53:08.038Z,1563472388.038 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:53:08.038Z,1563472388.038 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:53:08.038Z,1563472388.038 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:53:08.039Z,1563472388.039 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:53:08.459Z,1563472388.459 [Default:CheckIn:D] Stopped 2019-07-18T17:53:08.459Z,1563472388.459 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:53:08.848Z,1563472388.848 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.557992 min 2019-07-18T17:53:08.848Z,1563472388.848 [Default:CheckIn:E] Stopped 2019-07-18T17:53:08.848Z,1563472388.848 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:53:08.848Z,1563472388.848 [Default:CheckIn] Stopped 2019-07-18T17:53:08.849Z,1563472388.849 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:53:08.849Z,1563472388.849 [Default:CheckIn](INFO): Running loop #9 2019-07-18T17:53:08.849Z,1563472388.849 [Default:CheckIn] Running Loop=9 2019-07-18T17:53:08.849Z,1563472388.849 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:53:08.849Z,1563472388.849 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:53:10.462Z,1563472390.462 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:53:10.853Z,1563472390.853 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175309.00,A,3648.13456,N,12147.20565,W,0.428,329.42,180719,,,D*7F 2019-07-18T17:53:10.855Z,1563472390.855 [NAL9602](INFO): GPS fix at 20190718T175309: (36.802243, -121.786761) 2019-07-18T17:53:10.897Z,1563472390.897 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:53:10.897Z,1563472390.897 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:53:16.767Z,1563472396.767 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0018.lzma 2019-07-18T17:53:17.573Z,1563472397.573 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0018.lzma.bak 2019-07-18T17:53:17.573Z,1563472397.573 [DataOverHttps](INFO): SBD MOMSN=11454075 2019-07-18T17:53:25.795Z,1563472405.795 [NAL9602](INFO): SBD MO Status=0, MOMSN=8288, MT Status=0, MTMSN=0 2019-07-18T17:53:25.796Z,1563472405.796 [NAL9602](INFO): No messages in MT queue 2019-07-18T17:53:29.244Z,1563472409.244 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20190718T172614/Express0019.lzma 2019-07-18T17:53:30.049Z,1563472410.049 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0019.lzma.bak 2019-07-18T17:53:30.049Z,1563472410.049 [DataOverHttps](INFO): SBD MOMSN=11454078 2019-07-18T17:53:30.683Z,1563472410.683 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:53:30.683Z,1563472410.683 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:53:30.684Z,1563472410.684 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:53:56.498Z,1563472436.498 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T17:55:05.194Z,1563472505.194 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2019-07-18T17:55:59.737Z,1563472559.737 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-07-18T17:56:38.621Z,1563472598.621 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-07-18T17:56:38.624Z,1563472598.624 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2019-07-18T17:56:57.102Z,1563472617.102 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T17:58:31.249Z,1563472711.249 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T17:58:31.249Z,1563472711.249 [Default:CheckIn:C.Wait] Stopped 2019-07-18T17:58:31.249Z,1563472711.249 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T17:58:31.249Z,1563472711.249 [Default:CheckIn:D] Running Loop=1 2019-07-18T17:58:31.661Z,1563472711.661 [Default:CheckIn:D] Stopped 2019-07-18T17:58:31.662Z,1563472711.662 [Default:CheckIn:E] Running Loop=1 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.944706 min 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn:E] Stopped 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn] Stopped 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn](INFO): Running loop #10 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn] Running Loop=10 2019-07-18T17:58:32.061Z,1563472712.061 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T17:58:32.062Z,1563472712.062 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T17:58:33.660Z,1563472713.660 [NAL9602](DEBUG): Fix Requested 2019-07-18T17:58:34.048Z,1563472714.048 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175833.00,A,3648.13754,N,12147.20777,W,0.078,329.42,180719,,,D*7C 2019-07-18T17:58:34.050Z,1563472714.050 [NAL9602](INFO): GPS fix at 20190718T175833: (36.802292, -121.786796) 2019-07-18T17:58:34.079Z,1563472714.079 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T17:58:34.079Z,1563472714.079 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T17:58:39.828Z,1563472719.828 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190718T172614/Courier0021.lzma 2019-07-18T17:58:40.633Z,1563472720.633 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0021.lzma.bak 2019-07-18T17:58:40.633Z,1563472720.633 [DataOverHttps](INFO): SBD MOMSN=11454093 2019-07-18T17:58:53.171Z,1563472733.171 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190718T172614/Express0022.lzma 2019-07-18T17:58:53.977Z,1563472733.977 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0022.lzma.bak 2019-07-18T17:58:53.977Z,1563472733.977 [DataOverHttps](INFO): SBD MOMSN=11454097 2019-07-18T17:58:54.705Z,1563472734.705 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T17:58:54.705Z,1563472734.705 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T17:58:54.706Z,1563472734.706 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T17:59:23.739Z,1563472763.739 [NAL9602](INFO): SBD MO Status=0, MOMSN=8289, MT Status=0, MTMSN=0 2019-07-18T17:59:23.740Z,1563472763.740 [NAL9602](INFO): No messages in MT queue 2019-07-18T17:59:54.445Z,1563472794.445 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:03:55.255Z,1563473035.255 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:03:55.255Z,1563473035.255 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:03:55.255Z,1563473035.255 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:03:55.255Z,1563473035.255 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:03:55.663Z,1563473035.663 [Default:CheckIn:D] Stopped 2019-07-18T18:03:55.663Z,1563473035.663 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:03:56.080Z,1563473036.080 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.344727 min 2019-07-18T18:03:56.080Z,1563473036.080 [Default:CheckIn:E] Stopped 2019-07-18T18:03:56.080Z,1563473036.080 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn] Stopped 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn](INFO): Running loop #11 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn] Running Loop=11 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:03:56.081Z,1563473036.081 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:03:57.660Z,1563473037.660 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:03:58.059Z,1563473038.059 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180357.00,A,3648.13181,N,12147.21224,W,0.039,214.48,180719,,,D*73 2019-07-18T18:03:58.062Z,1563473038.062 [NAL9602](INFO): GPS fix at 20190718T180357: (36.802197, -121.786871) 2019-07-18T18:03:58.085Z,1563473038.085 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:03:58.085Z,1563473038.085 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:04:03.911Z,1563473043.911 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0024.lzma 2019-07-18T18:04:04.717Z,1563473044.717 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0024.lzma.bak 2019-07-18T18:04:04.717Z,1563473044.717 [DataOverHttps](INFO): SBD MOMSN=11454108 2019-07-18T18:04:16.276Z,1563473056.276 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0025.lzma 2019-07-18T18:04:17.081Z,1563473057.081 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0025.lzma.bak 2019-07-18T18:04:17.082Z,1563473057.082 [DataOverHttps](INFO): SBD MOMSN=11454111 2019-07-18T18:04:17.879Z,1563473057.879 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:04:17.879Z,1563473057.879 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:04:17.879Z,1563473057.879 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:04:18.659Z,1563473058.659 [NAL9602](INFO): SBD MO Status=2, MOMSN=8290, MT Status=2, MTMSN=0 2019-07-18T18:04:18.659Z,1563473058.659 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:04:34.824Z,1563473074.824 [NAL9602](INFO): SBD MO Status=2, MOMSN=8290, MT Status=2, MTMSN=0 2019-07-18T18:04:34.824Z,1563473074.824 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:04:53.414Z,1563473093.414 [NAL9602](INFO): SBD MO Status=2, MOMSN=8290, MT Status=2, MTMSN=0 2019-07-18T18:04:53.415Z,1563473093.415 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:05:10.390Z,1563473110.390 [NAL9602](INFO): SBD MO Status=2, MOMSN=8290, MT Status=2, MTMSN=0 2019-07-18T18:05:10.390Z,1563473110.390 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:06:06.940Z,1563473166.940 [NAL9602](INFO): SBD MO Status=0, MOMSN=8290, MT Status=0, MTMSN=0 2019-07-18T18:06:06.940Z,1563473166.940 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:06:37.631Z,1563473197.631 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:09:18.473Z,1563473358.473 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:09:18.473Z,1563473358.473 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:09:18.473Z,1563473358.473 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:09:18.473Z,1563473358.473 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:09:18.876Z,1563473358.876 [Default:CheckIn:D] Stopped 2019-07-18T18:09:18.876Z,1563473358.876 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:09:19.259Z,1563473359.259 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.731604 min 2019-07-18T18:09:19.259Z,1563473359.259 [Default:CheckIn:E] Stopped 2019-07-18T18:09:19.259Z,1563473359.259 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:09:19.259Z,1563473359.259 [Default:CheckIn] Stopped 2019-07-18T18:09:19.260Z,1563473359.260 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:09:19.260Z,1563473359.260 [Default:CheckIn](INFO): Running loop #12 2019-07-18T18:09:19.260Z,1563473359.260 [Default:CheckIn] Running Loop=12 2019-07-18T18:09:19.260Z,1563473359.260 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:09:19.260Z,1563473359.260 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:09:20.872Z,1563473360.872 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:09:21.267Z,1563473361.267 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180920.00,A,3648.16557,N,12147.25463,W,2.333,296.62,180719,,,D*7B 2019-07-18T18:09:21.269Z,1563473361.269 [NAL9602](INFO): GPS fix at 20190718T180920: (36.802760, -121.787577) 2019-07-18T18:09:21.293Z,1563473361.293 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:09:21.293Z,1563473361.293 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:09:27.123Z,1563473367.123 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0027.lzma 2019-07-18T18:09:27.929Z,1563473367.929 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0027.lzma.bak 2019-07-18T18:09:27.929Z,1563473367.929 [DataOverHttps](INFO): SBD MOMSN=11454125 2019-07-18T18:09:37.011Z,1563473377.011 [NAL9602](INFO): SBD MO Status=0, MOMSN=8291, MT Status=0, MTMSN=0 2019-07-18T18:09:37.011Z,1563473377.011 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:09:39.663Z,1563473379.663 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0028.lzma 2019-07-18T18:09:40.469Z,1563473380.469 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0028.lzma.bak 2019-07-18T18:09:40.469Z,1563473380.469 [DataOverHttps](INFO): SBD MOMSN=11454130 2019-07-18T18:09:41.083Z,1563473381.083 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:09:41.084Z,1563473381.084 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:09:41.084Z,1563473381.084 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:10:07.734Z,1563473407.734 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:12:05.746Z,1563473525.746 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-18T18:12:05.746Z,1563473525.746 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3278,V 2019-07-18T18:12:09.762Z,1563473529.762 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T18:12:09.762Z,1563473529.762 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:14:32.407Z,1563473672.407 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T18:14:32.407Z,1563473672.407 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:14:41.692Z,1563473681.692 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:14:41.692Z,1563473681.692 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:14:41.692Z,1563473681.692 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:14:41.692Z,1563473681.692 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:14:42.092Z,1563473682.092 [Default:CheckIn:D] Stopped 2019-07-18T18:14:42.092Z,1563473682.092 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:14:42.486Z,1563473682.486 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.118555 min 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn:E] Stopped 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn] Stopped 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn](INFO): Running loop #13 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn] Running Loop=13 2019-07-18T18:14:42.487Z,1563473682.487 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:14:42.488Z,1563473682.488 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:14:44.096Z,1563473684.096 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:14:44.484Z,1563473684.484 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181443.00,A,3648.17474,N,12147.28115,W,0.136,274.37,180719,,,D*73 2019-07-18T18:14:44.486Z,1563473684.486 [NAL9602](INFO): GPS fix at 20190718T181443: (36.802912, -121.788019) 2019-07-18T18:14:44.533Z,1563473684.533 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:14:44.533Z,1563473684.533 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:14:50.099Z,1563473690.099 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0030.lzma 2019-07-18T18:14:50.905Z,1563473690.905 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0030.lzma.bak 2019-07-18T18:14:50.905Z,1563473690.905 [DataOverHttps](INFO): SBD MOMSN=11454141 2019-07-18T18:15:02.439Z,1563473702.439 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190718T172614/Express0031.lzma 2019-07-18T18:15:03.252Z,1563473703.252 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0031.lzma.bak 2019-07-18T18:15:03.252Z,1563473703.252 [DataOverHttps](INFO): SBD MOMSN=11454144 2019-07-18T18:15:03.887Z,1563473703.887 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:15:03.887Z,1563473703.887 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:15:03.887Z,1563473703.887 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:15:06.824Z,1563473706.824 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-07-18T18:15:06.824Z,1563473706.824 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-07-18T18:15:06.824Z,1563473706.824 [RDI_Pathfinder](ERROR): Communications Fault 2019-07-18T18:15:06.824Z,1563473706.824 [RDI_Pathfinder](ERROR): Failed to parse: 2019-07-18T18:15:06.881Z,1563473706.881 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-07-18T18:15:07.192Z,1563473707.192 [RDI_Pathfinder](INFO): Powering down 2019-07-18T18:15:07.948Z,1563473707.948 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-07-18T18:15:07.948Z,1563473707.948 [RDI_Pathfinder] No Fault, FailCount= 1 2019-07-18T18:15:21.266Z,1563473721.266 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-07-18T18:16:29.949Z,1563473789.949 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:17:36.600Z,1563473856.600 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:18:33.135Z,1563473913.135 [NAL9602](INFO): SBD MO Status=2, MOMSN=8292, MT Status=2, MTMSN=0 2019-07-18T18:18:33.135Z,1563473913.135 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:19:55.567Z,1563473995.567 [NAL9602](INFO): SBD MO Status=2, MOMSN=8292, MT Status=2, MTMSN=0 2019-07-18T18:19:55.567Z,1563473995.567 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:19:55.958Z,1563473995.958 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-18T18:20:04.479Z,1563474004.479 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:20:04.479Z,1563474004.479 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:20:04.479Z,1563474004.479 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:20:04.479Z,1563474004.479 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:20:04.875Z,1563474004.875 [Default:CheckIn:D] Stopped 2019-07-18T18:20:04.876Z,1563474004.876 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:20:05.290Z,1563474005.290 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.498275 min 2019-07-18T18:20:05.290Z,1563474005.290 [Default:CheckIn:E] Stopped 2019-07-18T18:20:05.290Z,1563474005.290 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:20:05.290Z,1563474005.290 [Default:CheckIn] Stopped 2019-07-18T18:20:05.290Z,1563474005.290 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:20:05.291Z,1563474005.291 [Default:CheckIn](INFO): Running loop #14 2019-07-18T18:20:05.291Z,1563474005.291 [Default:CheckIn] Running Loop=14 2019-07-18T18:20:05.291Z,1563474005.291 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:20:05.291Z,1563474005.291 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:20:06.880Z,1563474006.880 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:20:07.291Z,1563474007.291 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182006.00,A,3648.18068,N,12147.28049,W,0.525,274.37,180719,,,A*78 2019-07-18T18:20:07.293Z,1563474007.293 [NAL9602](INFO): GPS fix at 20190718T182006: (36.803011, -121.788008) 2019-07-18T18:20:07.328Z,1563474007.328 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:20:07.328Z,1563474007.328 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:20:13.251Z,1563474013.251 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190718T172614/Courier0033.lzma 2019-07-18T18:20:14.057Z,1563474014.057 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0033.lzma.bak 2019-07-18T18:20:14.058Z,1563474014.058 [DataOverHttps](INFO): SBD MOMSN=11454185 2019-07-18T18:20:29.068Z,1563474029.068 [DataOverHttps](INFO): Sending 193 bytes from file Logs/20190718T172614/Express0034.lzma 2019-07-18T18:20:29.873Z,1563474029.873 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0034.lzma.bak 2019-07-18T18:20:29.874Z,1563474029.874 [DataOverHttps](INFO): SBD MOMSN=11454188 2019-07-18T18:20:30.765Z,1563474030.765 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:20:30.765Z,1563474030.765 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:20:30.765Z,1563474030.765 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:20:39.598Z,1563474039.598 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:24:41.631Z,1563474281.631 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-07-18T18:24:41.632Z,1563474281.632 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, 0.00,559.99 2019-07-18T18:25:18.396Z,1563474318.396 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-18T18:25:31.333Z,1563474331.333 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:25:31.333Z,1563474331.333 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:25:31.334Z,1563474331.334 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:25:31.334Z,1563474331.334 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:25:31.709Z,1563474331.709 [Default:CheckIn:D] Stopped 2019-07-18T18:25:31.709Z,1563474331.709 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:25:32.119Z,1563474332.119 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.945508 min 2019-07-18T18:25:32.119Z,1563474332.119 [Default:CheckIn:E] Stopped 2019-07-18T18:25:32.119Z,1563474332.119 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:25:32.119Z,1563474332.119 [Default:CheckIn] Stopped 2019-07-18T18:25:32.120Z,1563474332.120 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:25:32.120Z,1563474332.120 [Default:CheckIn](INFO): Running loop #15 2019-07-18T18:25:32.120Z,1563474332.120 [Default:CheckIn] Running Loop=15 2019-07-18T18:25:32.120Z,1563474332.120 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:25:32.120Z,1563474332.120 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:25:33.720Z,1563474333.720 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:25:34.116Z,1563474334.116 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182533.00,A,3648.17665,N,12147.28087,W,0.233,0.00,180719,,,A*78 2019-07-18T18:25:34.118Z,1563474334.118 [NAL9602](INFO): GPS fix at 20190718T182533: (36.802944, -121.788015) 2019-07-18T18:25:34.171Z,1563474334.171 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:25:34.171Z,1563474334.171 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:25:39.923Z,1563474339.923 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0036.lzma 2019-07-18T18:25:40.729Z,1563474340.729 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0036.lzma.bak 2019-07-18T18:25:40.730Z,1563474340.730 [DataOverHttps](INFO): SBD MOMSN=11454201 2019-07-18T18:25:54.067Z,1563474354.067 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190718T172614/Express0037.lzma 2019-07-18T18:25:54.873Z,1563474354.873 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0037.lzma.bak 2019-07-18T18:25:54.874Z,1563474354.874 [DataOverHttps](INFO): SBD MOMSN=11454204 2019-07-18T18:25:55.599Z,1563474355.599 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:25:55.599Z,1563474355.599 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:25:55.599Z,1563474355.599 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:27:07.047Z,1563474427.047 [NAL9602](INFO): SBD MO Status=0, MOMSN=8292, MT Status=0, MTMSN=0 2019-07-18T18:27:07.047Z,1563474427.047 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:27:37.750Z,1563474457.750 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:30:56.150Z,1563474656.150 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:30:56.150Z,1563474656.150 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:30:56.150Z,1563474656.150 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:30:56.151Z,1563474656.151 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:30:56.563Z,1563474656.563 [Default:CheckIn:D] Stopped 2019-07-18T18:30:56.563Z,1563474656.563 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:30:56.963Z,1563474656.963 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.359733 min 2019-07-18T18:30:56.963Z,1563474656.963 [Default:CheckIn:E] Stopped 2019-07-18T18:30:56.963Z,1563474656.963 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:30:56.963Z,1563474656.963 [Default:CheckIn] Stopped 2019-07-18T18:30:56.964Z,1563474656.964 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:30:56.964Z,1563474656.964 [Default:CheckIn](INFO): Running loop #16 2019-07-18T18:30:56.964Z,1563474656.964 [Default:CheckIn] Running Loop=16 2019-07-18T18:30:56.964Z,1563474656.964 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:30:56.964Z,1563474656.964 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:30:58.560Z,1563474658.560 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:30:58.960Z,1563474658.960 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183058.00,A,3648.17354,N,12147.27768,W,0.117,0.00,180719,,,D*7F 2019-07-18T18:30:58.962Z,1563474658.962 [NAL9602](INFO): GPS fix at 20190718T183058: (36.802892, -121.787961) 2019-07-18T18:30:58.986Z,1563474658.986 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:30:58.986Z,1563474658.986 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:31:04.703Z,1563474664.703 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0039.lzma 2019-07-18T18:31:05.509Z,1563474665.509 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0039.lzma.bak 2019-07-18T18:31:05.509Z,1563474665.509 [DataOverHttps](INFO): SBD MOMSN=11454218 2019-07-18T18:31:16.887Z,1563474676.887 [DataOverHttps](INFO): Sending 122 bytes from file Logs/20190718T172614/Express0040.lzma 2019-07-18T18:31:17.693Z,1563474677.693 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0040.lzma.bak 2019-07-18T18:31:17.694Z,1563474677.694 [DataOverHttps](INFO): SBD MOMSN=11454221 2019-07-18T18:31:18.417Z,1563474678.417 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:31:18.418Z,1563474678.418 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:31:18.418Z,1563474678.418 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:31:29.260Z,1563474689.260 [NAL9602](INFO): SBD MO Status=2, MOMSN=8293, MT Status=2, MTMSN=0 2019-07-18T18:31:29.260Z,1563474689.260 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:34:47.657Z,1563474887.657 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-18T18:35:23.991Z,1563474923.991 [NAL9602](INFO): SBD MO Status=2, MOMSN=8293, MT Status=2, MTMSN=0 2019-07-18T18:35:23.991Z,1563474923.991 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:35:32.880Z,1563474932.880 [NAL9602](INFO): SBD MO Status=0, MOMSN=8293, MT Status=0, MTMSN=0 2019-07-18T18:35:32.880Z,1563474932.880 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:35:42.587Z,1563474942.587 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T18:35:42.587Z,1563474942.587 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:36:03.578Z,1563474963.578 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:36:18.953Z,1563474978.953 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:36:18.953Z,1563474978.953 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:36:18.953Z,1563474978.953 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:36:18.954Z,1563474978.954 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:36:19.358Z,1563474979.358 [Default:CheckIn:D] Stopped 2019-07-18T18:36:19.358Z,1563474979.358 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:36:19.771Z,1563474979.771 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.739640 min 2019-07-18T18:36:19.771Z,1563474979.771 [Default:CheckIn:E] Stopped 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn] Stopped 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn](INFO): Running loop #17 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn] Running Loop=17 2019-07-18T18:36:19.772Z,1563474979.772 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:36:19.773Z,1563474979.773 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:36:21.368Z,1563474981.368 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:36:21.758Z,1563474981.758 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183620.00,A,3648.17390,N,12147.27819,W,0.039,0.00,180719,,,D*7A 2019-07-18T18:36:21.760Z,1563474981.760 [NAL9602](INFO): GPS fix at 20190718T183620: (36.802898, -121.787970) 2019-07-18T18:36:21.784Z,1563474981.784 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:36:21.784Z,1563474981.784 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:36:27.591Z,1563474987.591 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0042.lzma 2019-07-18T18:36:28.397Z,1563474988.397 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0042.lzma.bak 2019-07-18T18:36:28.398Z,1563474988.398 [DataOverHttps](INFO): SBD MOMSN=11454231 2019-07-18T18:36:33.880Z,1563474993.880 [NAL9602](INFO): SBD MO Status=0, MOMSN=8294, MT Status=0, MTMSN=0 2019-07-18T18:36:33.880Z,1563474993.880 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:36:39.871Z,1563474999.871 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190718T172614/Express0043.lzma 2019-07-18T18:36:40.677Z,1563475000.677 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0043.lzma.bak 2019-07-18T18:36:40.678Z,1563475000.678 [DataOverHttps](INFO): SBD MOMSN=11454234 2019-07-18T18:36:41.611Z,1563475001.611 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:36:41.611Z,1563475001.611 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:36:41.611Z,1563475001.611 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:37:04.597Z,1563475024.597 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:41:42.163Z,1563475302.163 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:41:42.163Z,1563475302.163 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:41:42.163Z,1563475302.163 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:41:42.163Z,1563475302.163 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:41:42.575Z,1563475302.575 [Default:CheckIn:D] Stopped 2019-07-18T18:41:42.576Z,1563475302.576 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:41:42.971Z,1563475302.971 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.126603 min 2019-07-18T18:41:42.971Z,1563475302.971 [Default:CheckIn:E] Stopped 2019-07-18T18:41:42.971Z,1563475302.971 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:41:42.971Z,1563475302.971 [Default:CheckIn] Stopped 2019-07-18T18:41:42.972Z,1563475302.972 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:41:42.972Z,1563475302.972 [Default:CheckIn](INFO): Running loop #18 2019-07-18T18:41:42.972Z,1563475302.972 [Default:CheckIn] Running Loop=18 2019-07-18T18:41:42.972Z,1563475302.972 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:41:42.972Z,1563475302.972 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:41:44.572Z,1563475304.572 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:41:44.976Z,1563475304.976 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184144.00,A,3648.17251,N,12147.27759,W,0.175,0.00,180719,,,D*76 2019-07-18T18:41:44.978Z,1563475304.978 [NAL9602](INFO): GPS fix at 20190718T184144: (36.802875, -121.787960) 2019-07-18T18:41:45.037Z,1563475305.037 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:41:45.037Z,1563475305.037 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:41:50.931Z,1563475310.931 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0045.lzma 2019-07-18T18:41:51.737Z,1563475311.737 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0045.lzma.bak 2019-07-18T18:41:51.738Z,1563475311.738 [DataOverHttps](INFO): SBD MOMSN=11454251 2019-07-18T18:42:03.159Z,1563475323.159 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190718T172614/Express0046.lzma 2019-07-18T18:42:03.965Z,1563475323.965 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0046.lzma.bak 2019-07-18T18:42:03.966Z,1563475323.966 [DataOverHttps](INFO): SBD MOMSN=11454254 2019-07-18T18:42:04.891Z,1563475324.891 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:42:04.891Z,1563475324.891 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:42:04.891Z,1563475324.891 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:42:14.567Z,1563475334.567 [NAL9602](INFO): SBD MO Status=2, MOMSN=8295, MT Status=2, MTMSN=0 2019-07-18T18:42:14.567Z,1563475334.567 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:44:07.286Z,1563475447.286 [NAL9602](INFO): SBD MO Status=2, MOMSN=8295, MT Status=2, MTMSN=0 2019-07-18T18:44:07.286Z,1563475447.286 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:44:16.591Z,1563475456.591 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T18:44:16.591Z,1563475456.591 [RDI_Pathfinder](ERROR): Failed to parse: :TS1542818,35.0, -0.1, 0.0,1448.9, 0 2019-07-18T18:44:24.251Z,1563475464.251 [NAL9602](INFO): SBD MO Status=2, MOMSN=8295, MT Status=2, MTMSN=0 2019-07-18T18:44:24.252Z,1563475464.252 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T18:44:33.559Z,1563475473.559 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T18:44:38.392Z,1563475478.392 [NAL9602](INFO): SBD MO Status=0, MOMSN=8295, MT Status=0, MTMSN=0 2019-07-18T18:44:38.392Z,1563475478.392 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:45:09.090Z,1563475509.090 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:46:10.559Z,1563475570.559 [RDI_Pathfinder](ERROR): Failed to parse: 2768,V 2019-07-18T18:47:05.487Z,1563475625.487 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:47:05.487Z,1563475625.487 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:47:05.487Z,1563475625.487 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:47:05.487Z,1563475625.487 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:47:05.875Z,1563475625.875 [Default:CheckIn:D] Stopped 2019-07-18T18:47:05.875Z,1563475625.875 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:47:06.291Z,1563475626.291 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.514925 min 2019-07-18T18:47:06.291Z,1563475626.291 [Default:CheckIn:E] Stopped 2019-07-18T18:47:06.291Z,1563475626.291 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:47:06.291Z,1563475626.291 [Default:CheckIn] Stopped 2019-07-18T18:47:06.292Z,1563475626.292 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:47:06.292Z,1563475626.292 [Default:CheckIn](INFO): Running loop #19 2019-07-18T18:47:06.292Z,1563475626.292 [Default:CheckIn] Running Loop=19 2019-07-18T18:47:06.292Z,1563475626.292 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:47:06.292Z,1563475626.292 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:47:07.884Z,1563475627.884 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:47:08.284Z,1563475628.284 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184707.00,A,3648.17527,N,12147.27377,W,0.039,121.77,180719,,,D*72 2019-07-18T18:47:08.286Z,1563475628.286 [NAL9602](INFO): GPS fix at 20190718T184707: (36.802921, -121.787896) 2019-07-18T18:47:08.310Z,1563475628.310 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:47:08.310Z,1563475628.310 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:47:14.007Z,1563475634.007 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0048.lzma 2019-07-18T18:47:14.813Z,1563475634.813 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0048.lzma.bak 2019-07-18T18:47:14.814Z,1563475634.814 [DataOverHttps](INFO): SBD MOMSN=11454267 2019-07-18T18:47:23.220Z,1563475643.220 [NAL9602](INFO): SBD MO Status=0, MOMSN=8296, MT Status=0, MTMSN=0 2019-07-18T18:47:23.220Z,1563475643.220 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:47:26.275Z,1563475646.275 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20190718T172614/Express0049.lzma 2019-07-18T18:47:27.081Z,1563475647.081 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0049.lzma.bak 2019-07-18T18:47:27.082Z,1563475647.082 [DataOverHttps](INFO): SBD MOMSN=11454270 2019-07-18T18:47:27.685Z,1563475647.685 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:47:27.685Z,1563475647.685 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:47:27.685Z,1563475647.685 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:47:53.925Z,1563475673.925 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:52:28.270Z,1563475948.270 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:52:28.270Z,1563475948.270 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:52:28.270Z,1563475948.270 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:52:28.271Z,1563475948.271 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:52:28.691Z,1563475948.691 [Default:CheckIn:D] Stopped 2019-07-18T18:52:28.691Z,1563475948.691 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:52:29.073Z,1563475949.073 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.895199 min 2019-07-18T18:52:29.073Z,1563475949.073 [Default:CheckIn:E] Stopped 2019-07-18T18:52:29.073Z,1563475949.073 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn] Stopped 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn](INFO): Running loop #20 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn] Running Loop=20 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:52:29.074Z,1563475949.074 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:52:30.680Z,1563475950.680 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:52:31.072Z,1563475951.072 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185230.00,A,3648.17351,N,12147.27651,W,0.078,100.79,180719,,,D*7C 2019-07-18T18:52:31.074Z,1563475951.074 [NAL9602](INFO): GPS fix at 20190718T185230: (36.802892, -121.787942) 2019-07-18T18:52:31.097Z,1563475951.097 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:52:31.097Z,1563475951.097 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:52:36.679Z,1563475956.679 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190718T172614/Courier0051.lzma 2019-07-18T18:52:37.485Z,1563475957.485 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0051.lzma.bak 2019-07-18T18:52:37.485Z,1563475957.485 [DataOverHttps](INFO): SBD MOMSN=11454281 2019-07-18T18:52:41.595Z,1563475961.595 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T18:52:41.596Z,1563475961.596 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071812025318,35.0, -0.1,448.9, 0 2019-07-18T18:52:48.447Z,1563475968.447 [NAL9602](INFO): SBD MO Status=0, MOMSN=8297, MT Status=0, MTMSN=0 2019-07-18T18:52:48.448Z,1563475968.448 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:52:48.939Z,1563475968.939 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0052.lzma 2019-07-18T18:52:49.745Z,1563475969.745 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0052.lzma.bak 2019-07-18T18:52:49.746Z,1563475969.746 [DataOverHttps](INFO): SBD MOMSN=11454284 2019-07-18T18:52:50.897Z,1563475970.897 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:52:50.897Z,1563475970.897 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:52:50.898Z,1563475970.898 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:53:19.146Z,1563475999.146 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:56:35.925Z,1563476195.925 [CBIT](IMPORTANT): Beginning ground fault scan 2019-07-18T18:56:46.851Z,1563476206.851 [CBIT](IMPORTANT): Low side ground fault detected mA: CHAN A0 (Batt): 0.546635 CHAN A1 (24V): 0.673303 CHAN A2 (12V): 0.295316 CHAN A3 (5V): 0.074664 CHAN B0 (3.3V): 0.046418 CHAN B1 (3.15aV): 0.050334 CHAN B2 (3.15bV): 0.052209 CHAN B3 (GND): -0.030246 OPEN: 0.018380 Full Scale Calc: 4.765 mA, -1.589 mA 2019-07-18T18:57:51.473Z,1563476271.473 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T18:57:51.473Z,1563476271.473 [Default:CheckIn:C.Wait] Stopped 2019-07-18T18:57:51.473Z,1563476271.473 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T18:57:51.474Z,1563476271.474 [Default:CheckIn:D] Running Loop=1 2019-07-18T18:57:51.871Z,1563476271.871 [Default:CheckIn:D] Stopped 2019-07-18T18:57:51.871Z,1563476271.871 [Default:CheckIn:E] Running Loop=1 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 114.281527 min 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn:E] Stopped 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn] Stopped 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn](INFO): Running loop #21 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn] Running Loop=21 2019-07-18T18:57:52.285Z,1563476272.285 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T18:57:52.286Z,1563476272.286 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T18:57:53.880Z,1563476273.880 [NAL9602](DEBUG): Fix Requested 2019-07-18T18:57:54.272Z,1563476274.272 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185753.00,A,3648.16907,N,12147.26812,W,0.175,100.79,180719,,,D*70 2019-07-18T18:57:54.274Z,1563476274.274 [NAL9602](INFO): GPS fix at 20190718T185753: (36.802818, -121.787802) 2019-07-18T18:57:54.308Z,1563476274.308 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T18:57:54.308Z,1563476274.308 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T18:57:59.939Z,1563476279.939 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0054.lzma 2019-07-18T18:58:00.746Z,1563476280.746 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0054.lzma.bak 2019-07-18T18:58:00.746Z,1563476280.746 [DataOverHttps](INFO): SBD MOMSN=11454299 2019-07-18T18:58:12.264Z,1563476292.264 [DataOverHttps](INFO): Sending 341 bytes from file Logs/20190718T172614/Express0055.lzma 2019-07-18T18:58:13.069Z,1563476293.069 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0055.lzma.bak 2019-07-18T18:58:13.070Z,1563476293.070 [DataOverHttps](INFO): SBD MOMSN=11454302 2019-07-18T18:58:13.759Z,1563476293.759 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T18:58:13.760Z,1563476293.760 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T18:58:13.760Z,1563476293.760 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T18:58:16.488Z,1563476296.488 [NAL9602](INFO): SBD MO Status=0, MOMSN=8298, MT Status=0, MTMSN=0 2019-07-18T18:58:16.488Z,1563476296.488 [NAL9602](INFO): No messages in MT queue 2019-07-18T18:58:47.194Z,1563476327.194 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T18:59:20.764Z,1563476360.764 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00,2637.69 2019-07-18T19:03:14.280Z,1563476594.280 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:03:14.280Z,1563476594.280 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:03:14.280Z,1563476594.280 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:03:14.281Z,1563476594.281 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:03:14.684Z,1563476594.684 [Default:CheckIn:D] Stopped 2019-07-18T19:03:14.684Z,1563476594.684 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.661743 min 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn:E] Stopped 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn] Stopped 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn](INFO): Running loop #22 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn] Running Loop=22 2019-07-18T19:03:15.066Z,1563476595.066 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:03:15.067Z,1563476595.067 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:03:16.676Z,1563476596.676 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:03:17.064Z,1563476597.064 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190316.00,A,3648.17237,N,12147.27762,W,0.039,100.79,180719,,,D*78 2019-07-18T19:03:17.066Z,1563476597.066 [NAL9602](INFO): GPS fix at 20190718T190316: (36.802873, -121.787960) 2019-07-18T19:03:17.107Z,1563476597.107 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:03:17.107Z,1563476597.107 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:03:22.959Z,1563476602.959 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0057.lzma 2019-07-18T19:03:23.765Z,1563476603.765 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0057.lzma.bak 2019-07-18T19:03:23.766Z,1563476603.766 [DataOverHttps](INFO): SBD MOMSN=11454318 2019-07-18T19:03:35.247Z,1563476615.247 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0058.lzma 2019-07-18T19:03:36.053Z,1563476616.053 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0058.lzma.bak 2019-07-18T19:03:36.054Z,1563476616.054 [DataOverHttps](INFO): SBD MOMSN=11454321 2019-07-18T19:03:36.943Z,1563476616.943 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:03:36.943Z,1563476616.943 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:03:36.943Z,1563476616.943 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:03:37.288Z,1563476617.288 [NAL9602](INFO): SBD MO Status=0, MOMSN=8299, MT Status=0, MTMSN=0 2019-07-18T19:03:37.288Z,1563476617.288 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:04:02.762Z,1563476642.762 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-07-18T19:04:02.764Z,1563476642.764 [BPC1](INFO): Received data from all battery sticks. 2019-07-18T19:04:07.990Z,1563476647.990 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:05:19.930Z,1563476719.930 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T19:05:19.930Z,1563476719.930 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-18T19:07:06.583Z,1563476826.583 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T19:07:06.584Z,1563476826.584 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071812171818,31, 0.0,1448.9, 0 2019-07-18T19:07:40.923Z,1563476860.923 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T19:07:40.923Z,1563476860.923 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071812175218,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T19:08:37.522Z,1563476917.522 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:08:37.522Z,1563476917.522 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:08:37.522Z,1563476917.522 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:08:37.523Z,1563476917.523 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:08:37.895Z,1563476917.895 [Default:CheckIn:D] Stopped 2019-07-18T19:08:37.895Z,1563476917.895 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:08:38.303Z,1563476918.303 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 125.048592 min 2019-07-18T19:08:38.303Z,1563476918.303 [Default:CheckIn:E] Stopped 2019-07-18T19:08:38.303Z,1563476918.303 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:08:38.303Z,1563476918.303 [Default:CheckIn] Stopped 2019-07-18T19:08:38.304Z,1563476918.304 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:08:38.305Z,1563476918.305 [Default:CheckIn](INFO): Running loop #23 2019-07-18T19:08:38.305Z,1563476918.305 [Default:CheckIn] Running Loop=23 2019-07-18T19:08:38.305Z,1563476918.305 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:08:38.306Z,1563476918.306 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:08:39.904Z,1563476919.904 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:08:40.292Z,1563476920.292 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190839.00,A,3648.17374,N,12147.27089,W,0.078,100.79,180719,,,D*7F 2019-07-18T19:08:40.294Z,1563476920.294 [NAL9602](INFO): GPS fix at 20190718T190839: (36.802896, -121.787848) 2019-07-18T19:08:40.327Z,1563476920.327 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:08:40.327Z,1563476920.327 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:08:45.933Z,1563476925.933 [DataOverHttps](INFO): Sending 80 bytes from file Logs/20190718T172614/Courier0060.lzma 2019-07-18T19:08:46.733Z,1563476926.733 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0060.lzma.bak 2019-07-18T19:08:46.734Z,1563476926.734 [DataOverHttps](INFO): SBD MOMSN=11454334 2019-07-18T19:08:55.239Z,1563476935.239 [NAL9602](INFO): SBD MO Status=0, MOMSN=8300, MT Status=0, MTMSN=0 2019-07-18T19:08:55.240Z,1563476935.240 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:08:58.267Z,1563476938.267 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0061.lzma 2019-07-18T19:08:59.073Z,1563476939.073 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0061.lzma.bak 2019-07-18T19:08:59.074Z,1563476939.074 [DataOverHttps](INFO): SBD MOMSN=11454338 2019-07-18T19:08:59.715Z,1563476939.715 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:08:59.715Z,1563476939.715 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:08:59.715Z,1563476939.715 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:09:25.942Z,1563476965.942 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:09:46.581Z,1563476986.581 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T19:09:46.581Z,1563476986.581 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-07-18T19:10:26.607Z,1563477026.607 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-18T19:14:00.322Z,1563477240.322 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:14:00.322Z,1563477240.322 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:14:00.322Z,1563477240.322 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:14:00.322Z,1563477240.322 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:14:00.729Z,1563477240.729 [Default:CheckIn:D] Stopped 2019-07-18T19:14:00.729Z,1563477240.729 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:14:01.113Z,1563477241.113 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.429159 min 2019-07-18T19:14:01.113Z,1563477241.113 [Default:CheckIn:E] Stopped 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn] Stopped 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn](INFO): Running loop #24 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn] Running Loop=24 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:14:01.114Z,1563477241.114 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:14:02.728Z,1563477242.728 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:14:03.106Z,1563477243.106 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191402.00,A,3648.17190,N,12147.27589,W,0.156,0.00,180719,,,D*75 2019-07-18T19:14:03.108Z,1563477243.108 [NAL9602](INFO): GPS fix at 20190718T191402: (36.802865, -121.787931) 2019-07-18T19:14:03.172Z,1563477243.172 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:14:03.173Z,1563477243.173 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:14:08.691Z,1563477248.691 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0063.lzma 2019-07-18T19:14:09.497Z,1563477249.497 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0063.lzma.bak 2019-07-18T19:14:09.498Z,1563477249.498 [DataOverHttps](INFO): SBD MOMSN=11454605 2019-07-18T19:14:20.923Z,1563477260.923 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0064.lzma 2019-07-18T19:14:21.729Z,1563477261.729 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0064.lzma.bak 2019-07-18T19:14:21.730Z,1563477261.730 [DataOverHttps](INFO): SBD MOMSN=11454608 2019-07-18T19:14:22.535Z,1563477262.535 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:14:22.535Z,1563477262.535 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:14:22.538Z,1563477262.538 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:14:24.919Z,1563477264.919 [NAL9602](INFO): SBD MO Status=0, MOMSN=8301, MT Status=0, MTMSN=0 2019-07-18T19:14:24.919Z,1563477264.919 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:14:55.619Z,1563477295.619 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:19:23.097Z,1563477563.097 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:19:23.097Z,1563477563.097 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:19:23.097Z,1563477563.097 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:19:23.098Z,1563477563.098 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:19:23.516Z,1563477563.516 [Default:CheckIn:D] Stopped 2019-07-18T19:19:23.516Z,1563477563.516 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 135.808952 min 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn:E] Stopped 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn] Stopped 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn](INFO): Running loop #25 2019-07-18T19:19:23.913Z,1563477563.913 [Default:CheckIn] Running Loop=25 2019-07-18T19:19:23.914Z,1563477563.914 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:19:23.914Z,1563477563.914 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:19:25.508Z,1563477565.508 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:19:25.903Z,1563477565.903 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191924.00,A,3648.16930,N,12147.27935,W,0.000,0.00,180719,,,D*76 2019-07-18T19:19:25.906Z,1563477565.906 [NAL9602](INFO): GPS fix at 20190718T191924: (36.802822, -121.787989) 2019-07-18T19:19:25.930Z,1563477565.930 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:19:25.930Z,1563477565.930 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:19:31.667Z,1563477571.667 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0066.lzma 2019-07-18T19:19:32.473Z,1563477572.473 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0066.lzma.bak 2019-07-18T19:19:32.474Z,1563477572.474 [DataOverHttps](INFO): SBD MOMSN=11454651 2019-07-18T19:19:37.260Z,1563477577.260 [NAL9602](INFO): SBD MO Status=0, MOMSN=8302, MT Status=0, MTMSN=0 2019-07-18T19:19:37.260Z,1563477577.260 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:19:43.923Z,1563477583.923 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190718T172614/Express0067.lzma 2019-07-18T19:19:44.729Z,1563477584.729 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0067.lzma.bak 2019-07-18T19:19:44.730Z,1563477584.730 [DataOverHttps](INFO): SBD MOMSN=11454654 2019-07-18T19:19:45.323Z,1563477585.323 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:19:45.323Z,1563477585.323 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:19:45.324Z,1563477585.324 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:20:07.918Z,1563477607.918 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:24:45.899Z,1563477885.899 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:24:45.899Z,1563477885.899 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:24:45.899Z,1563477885.899 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:24:45.899Z,1563477885.899 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:24:46.312Z,1563477886.312 [Default:CheckIn:D] Stopped 2019-07-18T19:24:46.312Z,1563477886.312 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.188883 min 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn:E] Stopped 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn] Stopped 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:24:46.713Z,1563477886.713 [Default:CheckIn](INFO): Running loop #26 2019-07-18T19:24:46.714Z,1563477886.714 [Default:CheckIn] Running Loop=26 2019-07-18T19:24:46.714Z,1563477886.714 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:24:46.714Z,1563477886.714 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:24:48.308Z,1563477888.308 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:24:48.700Z,1563477888.700 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192447.00,A,3648.17086,N,12147.28124,W,0.078,0.00,180719,,,D*70 2019-07-18T19:24:48.702Z,1563477888.702 [NAL9602](INFO): GPS fix at 20190718T192447: (36.802848, -121.788021) 2019-07-18T19:24:48.735Z,1563477888.735 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:24:48.735Z,1563477888.735 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:24:54.419Z,1563477894.419 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0069.lzma 2019-07-18T19:24:55.225Z,1563477895.225 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0069.lzma.bak 2019-07-18T19:24:55.226Z,1563477895.226 [DataOverHttps](INFO): SBD MOMSN=11454697 2019-07-18T19:25:03.247Z,1563477903.247 [NAL9602](INFO): SBD MO Status=0, MOMSN=8303, MT Status=0, MTMSN=0 2019-07-18T19:25:03.247Z,1563477903.247 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:25:06.655Z,1563477906.655 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190718T172614/Express0070.lzma 2019-07-18T19:25:07.461Z,1563477907.461 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0070.lzma.bak 2019-07-18T19:25:07.462Z,1563477907.462 [DataOverHttps](INFO): SBD MOMSN=11454700 2019-07-18T19:25:08.127Z,1563477908.127 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:25:08.127Z,1563477908.127 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:25:08.127Z,1563477908.127 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:25:12.186Z,1563477912.186 [RDI_Pathfinder](ERROR): Failed to parse: :8,-32768,-32768,V 2019-07-18T19:25:33.954Z,1563477933.954 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:29:56.590Z,1563478196.590 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-07-18T19:29:56.591Z,1563478196.591 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-07-18T19:30:08.703Z,1563478208.703 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:30:08.703Z,1563478208.703 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:30:08.703Z,1563478208.703 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:30:08.704Z,1563478208.704 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:30:09.108Z,1563478209.108 [Default:CheckIn:D] Stopped 2019-07-18T19:30:09.108Z,1563478209.108 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:30:09.540Z,1563478209.540 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 146.568815 min 2019-07-18T19:30:09.540Z,1563478209.540 [Default:CheckIn:E] Stopped 2019-07-18T19:30:09.540Z,1563478209.540 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn] Stopped 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn](INFO): Running loop #27 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn] Running Loop=27 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:30:09.541Z,1563478209.541 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:30:11.108Z,1563478211.108 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:30:11.500Z,1563478211.500 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193010.00,A,3648.17422,N,12147.27277,W,0.039,0.00,180719,,,D*72 2019-07-18T19:30:11.502Z,1563478211.502 [NAL9602](INFO): GPS fix at 20190718T193010: (36.802904, -121.787880) 2019-07-18T19:30:11.536Z,1563478211.536 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:30:11.536Z,1563478211.536 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:30:17.279Z,1563478217.279 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0072.lzma 2019-07-18T19:30:18.085Z,1563478218.085 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0072.lzma.bak 2019-07-18T19:30:18.086Z,1563478218.086 [DataOverHttps](INFO): SBD MOMSN=11454713 2019-07-18T19:30:23.216Z,1563478223.216 [NAL9602](INFO): SBD MO Status=0, MOMSN=8304, MT Status=0, MTMSN=0 2019-07-18T19:30:23.216Z,1563478223.216 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:30:29.451Z,1563478229.451 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0073.lzma 2019-07-18T19:30:30.516Z,1563478230.516 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0073.lzma.bak 2019-07-18T19:30:30.517Z,1563478230.517 [DataOverHttps](INFO): SBD MOMSN=11454716 2019-07-18T19:30:30.923Z,1563478230.923 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:30:30.923Z,1563478230.923 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:30:30.923Z,1563478230.923 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:30:53.916Z,1563478253.916 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:35:31.503Z,1563478531.503 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:35:31.503Z,1563478531.503 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:35:31.504Z,1563478531.504 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:35:31.504Z,1563478531.504 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:35:31.903Z,1563478531.903 [Default:CheckIn:D] Stopped 2019-07-18T19:35:31.903Z,1563478531.903 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 151.948730 min 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn:E] Stopped 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn] Stopped 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn](INFO): Running loop #28 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn] Running Loop=28 2019-07-18T19:35:32.308Z,1563478532.308 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:35:32.309Z,1563478532.309 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:35:33.908Z,1563478533.908 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:35:34.300Z,1563478534.300 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193533.00,A,3648.18821,N,12147.27431,W,0.156,174.44,180719,,,D*78 2019-07-18T19:35:34.302Z,1563478534.302 [NAL9602](INFO): GPS fix at 20190718T193533: (36.803137, -121.787905) 2019-07-18T19:35:34.355Z,1563478534.355 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:35:34.355Z,1563478534.355 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:35:40.159Z,1563478540.159 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0075.lzma 2019-07-18T19:35:40.965Z,1563478540.965 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0075.lzma.bak 2019-07-18T19:35:40.966Z,1563478540.966 [DataOverHttps](INFO): SBD MOMSN=11454748 2019-07-18T19:35:51.692Z,1563478551.692 [NAL9602](INFO): SBD MO Status=0, MOMSN=8305, MT Status=0, MTMSN=0 2019-07-18T19:35:51.692Z,1563478551.692 [NAL9602](INFO): No messages in MT queue 2019-07-18T19:35:54.371Z,1563478554.371 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0076.lzma 2019-07-18T19:35:55.177Z,1563478555.177 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0076.lzma.bak 2019-07-18T19:35:55.178Z,1563478555.178 [DataOverHttps](INFO): SBD MOMSN=11454751 2019-07-18T19:35:55.779Z,1563478555.779 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:35:55.779Z,1563478555.779 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:35:55.779Z,1563478555.779 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:36:22.394Z,1563478582.394 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:36:30.890Z,1563478590.890 [RDI_Pathfinder](ERROR): only read 0 of 4 data items 2019-07-18T19:36:30.890Z,1563478590.890 [RDI_Pathfinder](ERROR): Failed to parse: :RA68,-32768,-32768,V 2019-07-18T19:37:29.880Z,1563478649.880 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T19:37:35.557Z,1563478655.557 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-07-18T19:40:56.340Z,1563478856.340 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:40:56.340Z,1563478856.340 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:40:56.340Z,1563478856.340 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:40:56.340Z,1563478856.340 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:40:56.731Z,1563478856.731 [Default:CheckIn:D] Stopped 2019-07-18T19:40:56.731Z,1563478856.731 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 157.362533 min 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn:E] Stopped 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn] Stopped 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:40:57.140Z,1563478857.140 [Default:CheckIn](INFO): Running loop #29 2019-07-18T19:40:57.141Z,1563478857.141 [Default:CheckIn] Running Loop=29 2019-07-18T19:40:57.141Z,1563478857.141 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:40:57.141Z,1563478857.141 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:40:58.744Z,1563478858.744 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:40:59.136Z,1563478859.136 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194058.00,A,3648.16750,N,12147.27986,W,0.117,55.92,180719,,,D*4D 2019-07-18T19:40:59.138Z,1563478859.138 [NAL9602](INFO): GPS fix at 20190718T194058: (36.802792, -121.787998) 2019-07-18T19:40:59.162Z,1563478859.162 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:40:59.162Z,1563478859.162 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:41:05.019Z,1563478865.019 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190718T172614/Courier0078.lzma 2019-07-18T19:41:05.825Z,1563478865.825 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0078.lzma.bak 2019-07-18T19:41:05.826Z,1563478865.826 [DataOverHttps](INFO): SBD MOMSN=11454762 2019-07-18T19:41:17.980Z,1563478877.980 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190718T172614/Express0079.lzma 2019-07-18T19:41:18.786Z,1563478878.786 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0079.lzma.bak 2019-07-18T19:41:18.786Z,1563478878.786 [DataOverHttps](INFO): SBD MOMSN=11454765 2019-07-18T19:41:19.359Z,1563478879.359 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:41:19.359Z,1563478879.359 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:41:19.359Z,1563478879.359 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:45:47.587Z,1563479147.587 [NAL9602](INFO): SBD MO Status=2, MOMSN=8306, MT Status=2, MTMSN=0 2019-07-18T19:45:47.588Z,1563479147.588 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-07-18T19:46:01.323Z,1563479161.323 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-18T19:46:19.939Z,1563479179.939 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:46:19.939Z,1563479179.939 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:46:19.939Z,1563479179.939 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:46:19.939Z,1563479179.939 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:46:20.337Z,1563479180.337 [Default:CheckIn:D] Stopped 2019-07-18T19:46:20.337Z,1563479180.337 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 162.755973 min 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn:E] Stopped 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn] Stopped 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn](INFO): Running loop #30 2019-07-18T19:46:20.748Z,1563479180.748 [Default:CheckIn] Running Loop=30 2019-07-18T19:46:20.749Z,1563479180.749 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:46:20.749Z,1563479180.749 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:46:22.348Z,1563479182.348 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:46:22.739Z,1563479182.739 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194621.00,A,3648.16595,N,12147.28074,W,0.039,55.92,180719,,,A*4D 2019-07-18T19:46:22.742Z,1563479182.742 [NAL9602](INFO): GPS fix at 20190718T194621: (36.802766, -121.788012) 2019-07-18T19:46:22.766Z,1563479182.766 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:46:22.766Z,1563479182.766 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:46:28.467Z,1563479188.467 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190718T172614/Courier0081.lzma 2019-07-18T19:46:29.273Z,1563479189.273 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0081.lzma.bak 2019-07-18T19:46:29.274Z,1563479189.274 [DataOverHttps](INFO): SBD MOMSN=11454786 2019-07-18T19:46:40.700Z,1563479200.700 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190718T172614/Express0082.lzma 2019-07-18T19:46:41.505Z,1563479201.505 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0082.lzma.bak 2019-07-18T19:46:41.506Z,1563479201.506 [DataOverHttps](INFO): SBD MOMSN=11454789 2019-07-18T19:46:42.187Z,1563479202.187 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:46:42.187Z,1563479202.187 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:46:42.187Z,1563479202.187 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:46:43.378Z,1563479203.378 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00,5479.66 2019-07-18T19:46:54.650Z,1563479214.650 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:47:38.724Z,1563479258.724 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-07-18T19:47:38.724Z,1563479258.724 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19071812570 0.0,1448.9, 0 2019-07-18T19:51:42.722Z,1563479502.722 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:51:42.722Z,1563479502.722 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:51:42.723Z,1563479502.723 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:51:42.723Z,1563479502.723 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:51:43.159Z,1563479503.159 [Default:CheckIn:D] Stopped 2019-07-18T19:51:43.159Z,1563479503.159 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 168.136312 min 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn:E] Stopped 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn] Stopped 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn](INFO): Running loop #31 2019-07-18T19:51:43.544Z,1563479503.544 [Default:CheckIn] Running Loop=31 2019-07-18T19:51:43.545Z,1563479503.545 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:51:43.545Z,1563479503.545 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:51:45.172Z,1563479505.172 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:51:45.532Z,1563479505.532 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195144.00,A,3648.16818,N,12147.27911,W,0.292,55.92,180719,,,A*46 2019-07-18T19:51:45.534Z,1563479505.534 [NAL9602](INFO): GPS fix at 20190718T195144: (36.802803, -121.787985) 2019-07-18T19:51:45.566Z,1563479505.566 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T19:51:45.566Z,1563479505.566 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T19:51:51.707Z,1563479511.707 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190718T172614/Courier0084.lzma 2019-07-18T19:51:52.513Z,1563479512.513 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0084.lzma.bak 2019-07-18T19:51:52.514Z,1563479512.514 [DataOverHttps](INFO): SBD MOMSN=11454799 2019-07-18T19:52:05.787Z,1563479525.787 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190718T172614/Express0085.lzma 2019-07-18T19:52:06.594Z,1563479526.594 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0085.lzma.bak 2019-07-18T19:52:06.594Z,1563479526.594 [DataOverHttps](INFO): SBD MOMSN=11454802 2019-07-18T19:52:07.471Z,1563479527.471 [Default:CheckIn:Read_Iridium] Stopped 2019-07-18T19:52:07.471Z,1563479527.471 [Default:CheckIn:C.Wait] Running Loop=1 2019-07-18T19:52:07.471Z,1563479527.471 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-07-18T19:52:15.543Z,1563479535.543 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-07-18T19:52:16.330Z,1563479536.330 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-07-18T19:52:16.404Z,1563479536.404 [NAL9602](FAULT): received: +CSQ:1 OK06, 2, 0, 0, 0 OK 2019-07-18T19:52:16.404Z,1563479536.404 [NAL9602] Data Fault, FailCount= 1 2019-07-18T19:52:16.404Z,1563479536.404 [NAL9602](ERROR): Data Fault 2019-07-18T19:52:16.499Z,1563479536.499 [CBIT](ERROR): Data Fault in component: NAL9602 2019-07-18T19:52:16.726Z,1563479536.726 [NAL9602](INFO): Powering down 2019-07-18T19:52:17.142Z,1563479537.142 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2019-07-18T19:52:17.142Z,1563479537.142 [NAL9602] Hardware Fault, FailCount= 1 2019-07-18T19:52:17.142Z,1563479537.142 [NAL9602](ERROR): Hardware Fault 2019-07-18T19:52:17.625Z,1563479537.625 [CBIT](INFO): Clearing failed state for component NAL9602 2019-07-18T19:52:17.625Z,1563479537.625 [NAL9602] No Fault, FailCount= 1 2019-07-18T19:52:47.026Z,1563479567.026 [NAL9602](INFO): Powering up NAL9602 2019-07-18T19:52:57.934Z,1563479577.934 [NAL9602](INFO): NAL9602 initialized 2019-07-18T19:53:29.038Z,1563479609.038 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T19:56:17.104Z,1563479777.104 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2019-07-18T19:56:17.104Z,1563479777.104 [DropWeight] Hardware Fault, FailCount= 1 2019-07-18T19:56:17.105Z,1563479777.105 [DropWeight](ERROR): Hardware Fault 2019-07-18T19:56:17.136Z,1563479777.136 [CommandLine](FAULT): Scheduling is paused 2019-07-18T19:56:17.136Z,1563479777.136 [CBIT](INFO): Critical error at 20190718T195617 2019-07-18T19:56:17.136Z,1563479777.136 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2019-07-18T19:56:17.139Z,1563479777.139 [CBIT](ERROR): Hardware Fault in component: DropWeight 2019-07-18T19:56:17.139Z,1563479777.139 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2019-07-18T19:56:17.546Z,1563479777.546 [CBIT](INFO): Critical error at 20190718T195617 2019-07-18T19:57:08.032Z,1563479828.032 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-07-18T19:57:08.032Z,1563479828.032 [Default:CheckIn:C.Wait] Stopped 2019-07-18T19:57:08.033Z,1563479828.033 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-07-18T19:57:08.033Z,1563479828.033 [Default:CheckIn:D] Running Loop=1 2019-07-18T19:57:08.448Z,1563479828.448 [Default:CheckIn:D] Stopped 2019-07-18T19:57:08.448Z,1563479828.448 [Default:CheckIn:E] Running Loop=1 2019-07-18T19:57:08.839Z,1563479828.839 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 173.557813 min 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn:E] Stopped 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn] Stopped 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn](INFO): Running loop #32 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn] Running Loop=32 2019-07-18T19:57:08.840Z,1563479828.840 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-07-18T19:57:08.841Z,1563479828.841 [Default:CheckIn:Read_GPS] Running Loop=1 2019-07-18T19:57:10.444Z,1563479830.444 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:13.258Z,1563479833.258 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-07-18T19:57:14.088Z,1563479834.088 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:16.504Z,1563479836.504 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:19.740Z,1563479839.740 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:22.564Z,1563479842.564 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:25.796Z,1563479845.796 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:28.628Z,1563479848.628 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:31.856Z,1563479851.856 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:34.684Z,1563479854.684 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:37.520Z,1563479857.520 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:40.340Z,1563479860.340 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:42.364Z,1563479862.364 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:45.592Z,1563479865.592 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:48.420Z,1563479868.420 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:51.656Z,1563479871.656 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:54.484Z,1563479874.484 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:57:57.716Z,1563479877.716 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:00.544Z,1563479880.544 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:03.372Z,1563479883.372 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:06.604Z,1563479886.604 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:09.428Z,1563479889.428 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:12.664Z,1563479892.664 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:15.492Z,1563479895.492 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:18.724Z,1563479898.724 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:21.548Z,1563479901.548 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:24.376Z,1563479904.376 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:27.612Z,1563479907.612 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:30.436Z,1563479910.436 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:33.672Z,1563479913.672 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:36.496Z,1563479916.496 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:39.732Z,1563479919.732 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:42.556Z,1563479922.556 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:45.388Z,1563479925.388 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:48.624Z,1563479928.624 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:51.448Z,1563479931.448 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:54.676Z,1563479934.676 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:58:57.508Z,1563479937.508 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:00.328Z,1563479940.328 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:02.356Z,1563479942.356 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:05.584Z,1563479945.584 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:08.408Z,1563479948.408 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:11.644Z,1563479951.644 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:14.472Z,1563479954.472 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:17.704Z,1563479957.704 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:20.540Z,1563479960.540 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:23.360Z,1563479963.360 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:25.788Z,1563479965.788 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:28.612Z,1563479968.612 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:31.848Z,1563479971.848 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:34.676Z,1563479974.676 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:37.504Z,1563479977.504 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:40.732Z,1563479980.732 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:43.564Z,1563479983.564 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:46.392Z,1563479986.392 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:49.624Z,1563479989.624 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:52.452Z,1563479992.452 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:55.680Z,1563479995.680 [NAL9602](DEBUG): Fix Requested 2019-07-18T19:59:58.535Z,1563479998.535 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:01.744Z,1563480001.744 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:04.575Z,1563480004.575 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:07.802Z,1563480007.802 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:10.624Z,1563480010.624 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:13.864Z,1563480013.864 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:16.692Z,1563480016.692 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:19.536Z,1563480019.536 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:22.348Z,1563480022.348 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:24.368Z,1563480024.368 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:27.596Z,1563480027.596 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:30.428Z,1563480030.428 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:33.668Z,1563480033.668 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:36.484Z,1563480036.484 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:39.720Z,1563480039.720 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:42.548Z,1563480042.548 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:45.368Z,1563480045.368 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:48.604Z,1563480048.604 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:51.436Z,1563480051.436 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:54.668Z,1563480054.668 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:00:57.496Z,1563480057.496 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:00.724Z,1563480060.724 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:03.560Z,1563480063.560 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:06.388Z,1563480066.388 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:09.616Z,1563480069.616 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:12.444Z,1563480072.444 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:15.676Z,1563480075.676 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:18.504Z,1563480078.504 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:21.732Z,1563480081.732 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:24.564Z,1563480084.564 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:27.392Z,1563480087.392 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:30.616Z,1563480090.616 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:33.448Z,1563480093.448 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:36.680Z,1563480096.680 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:38.714Z,1563480098.714 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-07-18T20:01:38.714Z,1563480098.714 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3768,-32768,V 2019-07-18T20:01:39.544Z,1563480099.544 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:42.744Z,1563480102.744 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:45.576Z,1563480105.576 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:48.400Z,1563480108.400 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:51.628Z,1563480111.628 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:54.460Z,1563480114.460 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:01:57.692Z,1563480117.692 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:02:00.536Z,1563480120.536 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:02:03.344Z,1563480123.344 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:02:06.576Z,1563480126.576 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:02:09.011Z,1563480129.011 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-07-18T19:57:08.8Z 2019-07-18T20:02:09.011Z,1563480129.011 [Default:CheckIn:Read_GPS] Stopped 2019-07-18T20:02:09.012Z,1563480129.012 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-07-18T20:02:09.404Z,1563480129.404 [NAL9602](DEBUG): Fix Requested 2019-07-18T20:02:20.940Z,1563480140.940 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190718T172614/Courier0087.lzma 2019-07-18T20:02:21.746Z,1563480141.746 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Courier0087.lzma.bak 2019-07-18T20:02:21.746Z,1563480141.746 [DataOverHttps](INFO): SBD MOMSN=11454827 2019-07-18T20:02:25.506Z,1563480145.506 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-07-18T20:02:42.434Z,1563480162.434 [NAL9602](INFO): Not Powering down - fast GPS 2019-07-18T20:02:45.565Z,1563480165.565 [DataOverHttps](INFO): Sending 293 bytes from file Logs/20190718T172614/Express0088.lzma 2019-07-18T20:02:46.378Z,1563480166.378 [DataOverHttps](INFO): Moved sent file to Logs/20190718T172614/Express0088.lzma.bak 2019-07-18T20:02:46.378Z,1563480166.378 [DataOverHttps](INFO): SBD MOMSN=11454831 2019-07-18T20:02:47.347