2019-06-19T16:09:35.813Z,1560960575.813 [CommandLine](IMPORTANT): got command restart logs 2019-06-19T16:13:15.289Z,1560960795.289 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:13:15.289Z,1560960795.289 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:13:15.289Z,1560960795.289 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:13:15.289Z,1560960795.289 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:13:15.698Z,1560960795.698 [Default:CheckIn:D] Stopped 2019-06-19T16:13:15.698Z,1560960795.698 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.341125 min 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn:E] Stopped 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn] Stopped 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn](INFO): Running loop #5 2019-06-19T16:13:16.104Z,1560960796.104 [Default:CheckIn] Running Loop=5 2019-06-19T16:13:16.105Z,1560960796.105 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:13:16.105Z,1560960796.105 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:13:17.705Z,1560960797.705 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:13:18.093Z,1560960798.093 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,161309.00,A,3648.35204,N,12147.43757,W,25.736,55.88,190619,,,D*7C 2019-06-19T16:13:18.095Z,1560960798.095 [NAL9602](INFO): GPS fix at 20190619T161309: (36.805867, -121.790626) 2019-06-19T16:13:18.120Z,1560960798.120 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:13:18.120Z,1560960798.120 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:13:23.496Z,1560960803.496 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T032301/Courier0142.lzma 2019-06-19T16:13:24.303Z,1560960804.303 [DataOverHttps](INFO): Moved sent file to Logs/20190619T032301/Courier0142.lzma.bak 2019-06-19T16:13:24.303Z,1560960804.303 [DataOverHttps](INFO): SBD MOMSN=11390834 2019-06-19T16:13:35.130Z,1560960815.130 [NAL9602](INFO): SBD MO Status=0, MOMSN=3807, MT Status=0, MTMSN=0 2019-06-19T16:13:35.130Z,1560960815.130 [NAL9602](INFO): No messages in MT queue 2019-06-19T16:13:35.337Z,1560960815.337 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190619T160935/Courier0000.lzma 2019-06-19T16:13:36.142Z,1560960816.142 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0000.lzma.bak 2019-06-19T16:13:36.142Z,1560960816.142 [DataOverHttps](INFO): SBD MOMSN=11390836 2019-06-19T16:13:47.164Z,1560960827.164 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190619T160935/Courier0003.lzma 2019-06-19T16:13:47.970Z,1560960827.970 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0003.lzma.bak 2019-06-19T16:13:47.970Z,1560960827.970 [DataOverHttps](INFO): SBD MOMSN=11390840 2019-06-19T16:13:59.304Z,1560960839.304 [DataOverHttps](INFO): Sending 97 bytes from file Logs/20190619T032301/Express0143.lzma 2019-06-19T16:14:00.185Z,1560960840.185 [DataOverHttps](INFO): Moved sent file to Logs/20190619T032301/Express0143.lzma.bak 2019-06-19T16:14:00.185Z,1560960840.185 [DataOverHttps](INFO): SBD MOMSN=11390842 2019-06-19T16:14:05.842Z,1560960845.842 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:14:11.278Z,1560960851.278 [DataOverHttps](INFO): Sending 349 bytes from file Logs/20190619T160935/Express0001.lzma 2019-06-19T16:14:12.082Z,1560960852.082 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0001.lzma.bak 2019-06-19T16:14:12.082Z,1560960852.082 [DataOverHttps](INFO): SBD MOMSN=11390845 2019-06-19T16:14:23.076Z,1560960863.076 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Express0005.lzma 2019-06-19T16:14:23.882Z,1560960863.882 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0005.lzma.bak 2019-06-19T16:14:23.882Z,1560960863.882 [DataOverHttps](INFO): SBD MOMSN=11390849 2019-06-19T16:14:24.850Z,1560960864.850 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:14:24.850Z,1560960864.850 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:14:24.850Z,1560960864.850 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:19:25.418Z,1560961165.418 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:19:25.418Z,1560961165.418 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:19:25.418Z,1560961165.418 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:19:25.418Z,1560961165.418 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:19:25.822Z,1560961165.822 [Default:CheckIn:D] Stopped 2019-06-19T16:19:25.822Z,1560961165.822 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.509851 min 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn:E] Stopped 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn] Stopped 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn](INFO): Running loop #6 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn] Running Loop=6 2019-06-19T16:19:26.220Z,1560961166.220 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:19:26.221Z,1560961166.221 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:19:27.829Z,1560961167.829 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:19:28.224Z,1560961168.224 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,161919.00,A,3648.18370,N,12147.17955,W,3.091,205.51,190619,,,D*7A 2019-06-19T16:19:28.226Z,1560961168.226 [NAL9602](INFO): GPS fix at 20190619T161919: (36.803062, -121.786326) 2019-06-19T16:19:28.250Z,1560961168.250 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:19:28.250Z,1560961168.250 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:19:33.640Z,1560961173.640 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0004.lzma 2019-06-19T16:19:34.449Z,1560961174.449 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0004.lzma.bak 2019-06-19T16:19:34.449Z,1560961174.449 [DataOverHttps](INFO): SBD MOMSN=11390852 2019-06-19T16:19:45.460Z,1560961185.460 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190619T160935/Express0007.lzma 2019-06-19T16:19:46.266Z,1560961186.266 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0007.lzma.bak 2019-06-19T16:19:46.267Z,1560961186.267 [DataOverHttps](INFO): SBD MOMSN=11390854 2019-06-19T16:19:47.246Z,1560961187.246 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:19:47.246Z,1560961187.246 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:19:47.246Z,1560961187.246 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:19:49.227Z,1560961189.227 [NAL9602](INFO): SBD MO Status=0, MOMSN=3808, MT Status=0, MTMSN=0 2019-06-19T16:19:49.228Z,1560961189.228 [NAL9602](INFO): No messages in MT queue 2019-06-19T16:20:19.930Z,1560961219.930 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:24:47.810Z,1560961487.810 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:24:47.810Z,1560961487.810 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:24:47.810Z,1560961487.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:24:47.811Z,1560961487.811 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:24:48.213Z,1560961488.213 [Default:CheckIn:D] Stopped 2019-06-19T16:24:48.214Z,1560961488.214 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:24:48.614Z,1560961488.614 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.883053 min 2019-06-19T16:24:48.614Z,1560961488.614 [Default:CheckIn:E] Stopped 2019-06-19T16:24:48.614Z,1560961488.614 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:24:48.614Z,1560961488.614 [Default:CheckIn] Stopped 2019-06-19T16:24:48.614Z,1560961488.614 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:24:48.615Z,1560961488.615 [Default:CheckIn](INFO): Running loop #7 2019-06-19T16:24:48.615Z,1560961488.615 [Default:CheckIn] Running Loop=7 2019-06-19T16:24:48.615Z,1560961488.615 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:24:48.615Z,1560961488.615 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:24:50.221Z,1560961490.221 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:24:50.616Z,1560961490.616 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162441.00,A,3648.16541,N,12147.21689,W,0.039,261.78,190619,,,D*70 2019-06-19T16:24:50.618Z,1560961490.618 [NAL9602](INFO): GPS fix at 20190619T162441: (36.802757, -121.786948) 2019-06-19T16:24:50.642Z,1560961490.642 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:24:50.643Z,1560961490.643 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:24:56.104Z,1560961496.104 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190619T160935/Courier0009.lzma 2019-06-19T16:24:56.910Z,1560961496.910 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0009.lzma.bak 2019-06-19T16:24:56.910Z,1560961496.910 [DataOverHttps](INFO): SBD MOMSN=11390858 2019-06-19T16:25:07.904Z,1560961507.904 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190619T160935/Express0010.lzma 2019-06-19T16:25:08.710Z,1560961508.710 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0010.lzma.bak 2019-06-19T16:25:08.711Z,1560961508.711 [DataOverHttps](INFO): SBD MOMSN=11390861 2019-06-19T16:25:09.634Z,1560961509.634 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:25:09.634Z,1560961509.634 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:25:09.634Z,1560961509.634 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:25:15.253Z,1560961515.253 [NAL9602](INFO): SBD MO Status=0, MOMSN=3809, MT Status=0, MTMSN=0 2019-06-19T16:25:15.253Z,1560961515.253 [NAL9602](INFO): No messages in MT queue 2019-06-19T16:25:45.958Z,1560961545.958 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:30:10.206Z,1560961810.206 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:30:10.206Z,1560961810.206 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:30:10.206Z,1560961810.206 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:30:10.207Z,1560961810.207 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:30:10.611Z,1560961810.611 [Default:CheckIn:D] Stopped 2019-06-19T16:30:10.611Z,1560961810.611 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:30:11.019Z,1560961811.019 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 41.256344 min 2019-06-19T16:30:11.019Z,1560961811.019 [Default:CheckIn:E] Stopped 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn] Stopped 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn](INFO): Running loop #8 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn] Running Loop=8 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:30:11.020Z,1560961811.020 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:30:12.613Z,1560961812.613 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:30:13.008Z,1560961813.008 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163004.00,A,3648.17346,N,12147.27968,W,0.311,203.40,190619,,,D*74 2019-06-19T16:30:13.010Z,1560961813.010 [NAL9602](INFO): GPS fix at 20190619T163004: (36.802891, -121.787995) 2019-06-19T16:30:13.034Z,1560961813.034 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:30:13.035Z,1560961813.035 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:30:18.576Z,1560961818.576 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190619T160935/Courier0012.lzma 2019-06-19T16:30:19.382Z,1560961819.382 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0012.lzma.bak 2019-06-19T16:30:19.382Z,1560961819.382 [DataOverHttps](INFO): SBD MOMSN=11390865 2019-06-19T16:30:30.473Z,1560961830.473 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190619T160935/Express0013.lzma 2019-06-19T16:30:31.281Z,1560961831.281 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0013.lzma.bak 2019-06-19T16:30:31.281Z,1560961831.281 [DataOverHttps](INFO): SBD MOMSN=11390868 2019-06-19T16:30:32.022Z,1560961832.022 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:30:32.022Z,1560961832.022 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:30:32.022Z,1560961832.022 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:35:15.598Z,1560962115.598 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T16:35:32.594Z,1560962132.594 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:35:32.594Z,1560962132.594 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:35:32.594Z,1560962132.594 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:35:32.595Z,1560962132.595 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:35:32.997Z,1560962132.997 [Default:CheckIn:D] Stopped 2019-06-19T16:35:32.998Z,1560962132.998 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:35:33.395Z,1560962133.395 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.629451 min 2019-06-19T16:35:33.395Z,1560962133.395 [Default:CheckIn:E] Stopped 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn] Stopped 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn](INFO): Running loop #9 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn] Running Loop=9 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:35:33.396Z,1560962133.396 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:35:35.005Z,1560962135.005 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:35:35.400Z,1560962135.400 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163526.00,A,3648.16817,N,12147.28092,W,0.097,281.74,190619,,,A*79 2019-06-19T16:35:35.402Z,1560962135.402 [NAL9602](INFO): GPS fix at 20190619T163526: (36.802803, -121.788015) 2019-06-19T16:35:35.426Z,1560962135.426 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:35:35.426Z,1560962135.426 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:35:40.868Z,1560962140.868 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190619T160935/Courier0015.lzma 2019-06-19T16:35:41.674Z,1560962141.674 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0015.lzma.bak 2019-06-19T16:35:41.674Z,1560962141.674 [DataOverHttps](INFO): SBD MOMSN=11390871 2019-06-19T16:35:52.602Z,1560962152.602 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190619T160935/Express0016.lzma 2019-06-19T16:35:53.406Z,1560962153.406 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0016.lzma.bak 2019-06-19T16:35:53.407Z,1560962153.407 [DataOverHttps](INFO): SBD MOMSN=11390874 2019-06-19T16:35:54.011Z,1560962154.011 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:35:54.011Z,1560962154.011 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:35:54.011Z,1560962154.011 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:36:07.718Z,1560962167.718 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:40:54.586Z,1560962454.586 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:40:54.586Z,1560962454.586 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:40:54.587Z,1560962454.587 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:40:54.587Z,1560962454.587 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:40:55.002Z,1560962455.002 [Default:CheckIn:D] Stopped 2019-06-19T16:40:55.002Z,1560962455.002 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:40:55.389Z,1560962455.389 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.996200 min 2019-06-19T16:40:55.389Z,1560962455.389 [Default:CheckIn:E] Stopped 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn] Stopped 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn](INFO): Running loop #10 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn] Running Loop=10 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:40:55.390Z,1560962455.390 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:40:56.989Z,1560962456.989 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:40:57.388Z,1560962457.388 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164048.00,A,3648.16988,N,12147.28224,W,0.330,281.74,190619,,,A*75 2019-06-19T16:40:57.390Z,1560962457.390 [NAL9602](INFO): GPS fix at 20190619T164048: (36.802831, -121.788037) 2019-06-19T16:40:57.415Z,1560962457.415 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:40:57.415Z,1560962457.415 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:41:02.924Z,1560962462.924 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190619T160935/Courier0018.lzma 2019-06-19T16:41:03.730Z,1560962463.730 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0018.lzma.bak 2019-06-19T16:41:03.730Z,1560962463.730 [DataOverHttps](INFO): SBD MOMSN=11390878 2019-06-19T16:41:14.696Z,1560962474.696 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20190619T160935/Express0019.lzma 2019-06-19T16:41:15.503Z,1560962475.503 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0019.lzma.bak 2019-06-19T16:41:15.503Z,1560962475.503 [DataOverHttps](INFO): SBD MOMSN=11390881 2019-06-19T16:41:16.410Z,1560962476.410 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:41:16.410Z,1560962476.410 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:41:16.410Z,1560962476.410 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:41:28.086Z,1560962488.086 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-06-19T16:41:28.165Z,1560962488.165 [NAL9602](FAULT): received: +CSQ:0 OK09, 0, 0, 0, 0 OK 2019-06-19T16:41:28.165Z,1560962488.165 [NAL9602] Data Fault, FailCount= 1 2019-06-19T16:41:28.165Z,1560962488.165 [NAL9602](ERROR): Data Fault 2019-06-19T16:41:28.203Z,1560962488.203 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T16:41:28.490Z,1560962488.490 [NAL9602](INFO): Powering down 2019-06-19T16:41:29.343Z,1560962489.343 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T16:41:29.343Z,1560962489.343 [NAL9602] No Fault, FailCount= 1 2019-06-19T16:41:58.802Z,1560962518.802 [NAL9602](INFO): Powering up NAL9602 2019-06-19T16:42:09.698Z,1560962529.698 [NAL9602](INFO): NAL9602 initialized 2019-06-19T16:42:40.806Z,1560962560.806 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:46:16.975Z,1560962776.975 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:46:16.975Z,1560962776.975 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:46:16.975Z,1560962776.975 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:46:16.976Z,1560962776.976 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:46:17.394Z,1560962777.394 [Default:CheckIn:D] Stopped 2019-06-19T16:46:17.394Z,1560962777.394 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:46:17.792Z,1560962777.792 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.369393 min 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn:E] Stopped 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn] Stopped 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn](INFO): Running loop #11 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn] Running Loop=11 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:46:17.793Z,1560962777.793 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:46:19.381Z,1560962779.381 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:21.394Z,1560962781.394 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T16:46:22.209Z,1560962782.209 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:24.637Z,1560962784.637 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:27.465Z,1560962787.465 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:30.293Z,1560962790.293 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:33.525Z,1560962793.525 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:36.349Z,1560962796.349 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:39.581Z,1560962799.581 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:42.409Z,1560962802.409 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:45.641Z,1560962805.641 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:48.469Z,1560962808.469 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:51.705Z,1560962811.705 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:54.529Z,1560962814.529 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:46:57.765Z,1560962817.765 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:00.589Z,1560962820.589 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:03.421Z,1560962823.421 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:06.649Z,1560962826.649 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:09.481Z,1560962829.481 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:12.309Z,1560962832.309 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:15.537Z,1560962835.537 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:18.365Z,1560962838.365 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:21.601Z,1560962841.601 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:24.425Z,1560962844.425 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:27.661Z,1560962847.661 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:30.485Z,1560962850.485 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:33.717Z,1560962853.717 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:36.545Z,1560962856.545 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:39.785Z,1560962859.785 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:42.609Z,1560962862.609 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:45.433Z,1560962865.433 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:48.261Z,1560962868.261 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:50.281Z,1560962870.281 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:52.301Z,1560962872.301 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:55.537Z,1560962875.537 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:47:58.361Z,1560962878.361 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:01.597Z,1560962881.597 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:04.421Z,1560962884.421 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:07.257Z,1560962887.257 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:09.673Z,1560962889.673 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:12.505Z,1560962892.505 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:15.733Z,1560962895.733 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:18.565Z,1560962898.565 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:21.793Z,1560962901.793 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:24.625Z,1560962904.625 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:27.449Z,1560962907.449 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:30.277Z,1560962910.277 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:32.297Z,1560962912.297 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:35.529Z,1560962915.529 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:38.357Z,1560962918.357 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:41.593Z,1560962921.593 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:44.421Z,1560962924.421 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:47.653Z,1560962927.653 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:50.481Z,1560962930.481 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:53.305Z,1560962933.305 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:56.537Z,1560962936.537 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:48:59.369Z,1560962939.369 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:02.597Z,1560962942.597 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:05.429Z,1560962945.429 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:08.257Z,1560962948.257 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:10.273Z,1560962950.273 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:12.301Z,1560962952.301 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:15.529Z,1560962955.529 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:18.353Z,1560962958.353 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:21.589Z,1560962961.589 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:24.413Z,1560962964.413 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:27.649Z,1560962967.649 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:30.477Z,1560962970.477 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:33.721Z,1560962973.721 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:36.533Z,1560962976.533 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:39.765Z,1560962979.765 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:42.597Z,1560962982.597 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:45.829Z,1560962985.829 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:48.653Z,1560962988.653 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:51.485Z,1560962991.485 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:54.313Z,1560962994.313 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:56.333Z,1560962996.333 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:49:59.565Z,1560962999.565 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:02.393Z,1560963002.393 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:05.625Z,1560963005.625 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:08.453Z,1560963008.453 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:11.685Z,1560963011.685 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:14.525Z,1560963014.525 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:17.341Z,1560963017.341 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:20.569Z,1560963020.569 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:23.401Z,1560963023.401 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:26.629Z,1560963026.629 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:29.461Z,1560963029.461 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:32.689Z,1560963032.689 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:35.521Z,1560963035.521 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:38.349Z,1560963038.349 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:41.581Z,1560963041.581 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:44.405Z,1560963044.405 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:47.637Z,1560963047.637 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:50.469Z,1560963050.469 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:53.701Z,1560963053.701 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:56.533Z,1560963056.533 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:50:59.357Z,1560963059.357 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:02.585Z,1560963062.585 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:05.413Z,1560963065.413 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:08.645Z,1560963068.645 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:11.473Z,1560963071.473 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:14.705Z,1560963074.705 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:17.533Z,1560963077.533 [NAL9602](DEBUG): Fix Requested 2019-06-19T16:51:17.966Z,1560963077.966 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T16:46:17.8Z 2019-06-19T16:51:17.966Z,1560963077.966 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T16:51:17.966Z,1560963077.966 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T16:51:23.544Z,1560963083.544 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0021.lzma 2019-06-19T16:51:24.350Z,1560963084.350 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0021.lzma.bak 2019-06-19T16:51:24.350Z,1560963084.350 [DataOverHttps](INFO): SBD MOMSN=11390884 2019-06-19T16:51:35.521Z,1560963095.521 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20190619T160935/Express0022.lzma 2019-06-19T16:51:36.326Z,1560963096.326 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0022.lzma.bak 2019-06-19T16:51:36.327Z,1560963096.327 [DataOverHttps](INFO): SBD MOMSN=11390886 2019-06-19T16:51:36.937Z,1560963096.937 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T16:51:36.937Z,1560963096.937 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T16:51:36.937Z,1560963096.937 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T16:51:50.246Z,1560963110.246 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T16:56:37.531Z,1560963397.531 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T16:56:37.531Z,1560963397.531 [Default:CheckIn:C.Wait] Stopped 2019-06-19T16:56:37.531Z,1560963397.531 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T16:56:37.531Z,1560963397.531 [Default:CheckIn:D] Running Loop=1 2019-06-19T16:56:37.936Z,1560963397.936 [Default:CheckIn:D] Stopped 2019-06-19T16:56:37.936Z,1560963397.936 [Default:CheckIn:E] Running Loop=1 2019-06-19T16:56:38.351Z,1560963398.351 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 67.711759 min 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn:E] Stopped 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn] Stopped 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn](INFO): Running loop #12 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn] Running Loop=12 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T16:56:38.352Z,1560963398.352 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T16:56:39.920Z,1560963399.920 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-06-19T16:56:39.920Z,1560963399.920 [NAL9602] Data Fault, FailCount= 1 2019-06-19T16:56:39.920Z,1560963399.920 [NAL9602](ERROR): Data Fault 2019-06-19T16:56:39.956Z,1560963399.956 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T16:56:40.338Z,1560963400.338 [NAL9602](INFO): Powering down 2019-06-19T16:56:41.195Z,1560963401.195 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T16:56:41.195Z,1560963401.195 [NAL9602] No Fault, FailCount= 1 2019-06-19T16:57:10.616Z,1560963430.616 [NAL9602](INFO): Powering up NAL9602 2019-06-19T16:57:21.530Z,1560963441.530 [NAL9602](INFO): NAL9602 initialized 2019-06-19T16:57:22.349Z,1560963442.349 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:00:54.472Z,1560963654.472 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-06-19T17:00:54.475Z,1560963654.475 [BPC1](INFO): Received data from all battery sticks. 2019-06-19T17:01:38.506Z,1560963698.506 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T16:56:38.4Z 2019-06-19T17:01:38.506Z,1560963698.506 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:01:38.507Z,1560963698.507 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:01:39.881Z,1560963699.881 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190619T160935/Courier0024.lzma 2019-06-19T17:01:40.686Z,1560963700.686 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0024.lzma.bak 2019-06-19T17:01:40.686Z,1560963700.686 [DataOverHttps](INFO): SBD MOMSN=11390891 2019-06-19T17:01:51.721Z,1560963711.721 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190619T160935/Express0025.lzma 2019-06-19T17:01:52.526Z,1560963712.526 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0025.lzma.bak 2019-06-19T17:01:52.527Z,1560963712.527 [DataOverHttps](INFO): SBD MOMSN=11390893 2019-06-19T17:01:53.106Z,1560963713.106 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:01:53.106Z,1560963713.106 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:01:53.106Z,1560963713.106 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:02:24.982Z,1560963744.982 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:02:55.683Z,1560963775.683 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:06:53.678Z,1560964013.678 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:06:53.678Z,1560964013.678 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:06:53.678Z,1560964013.678 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:06:53.678Z,1560964013.678 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:06:54.085Z,1560964014.085 [Default:CheckIn:D] Stopped 2019-06-19T17:06:54.086Z,1560964014.086 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:06:54.483Z,1560964014.483 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.980916 min 2019-06-19T17:06:54.483Z,1560964014.483 [Default:CheckIn:E] Stopped 2019-06-19T17:06:54.483Z,1560964014.483 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn] Stopped 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn](INFO): Running loop #13 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn] Running Loop=13 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:06:54.484Z,1560964014.484 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:06:56.081Z,1560964016.081 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:11:54.669Z,1560964314.669 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:06:54.5Z 2019-06-19T17:11:54.669Z,1560964314.669 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:11:54.669Z,1560964314.669 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:11:56.207Z,1560964316.207 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0027.lzma 2019-06-19T17:11:56.902Z,1560964316.902 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0027.lzma.bak 2019-06-19T17:11:56.903Z,1560964316.903 [DataOverHttps](INFO): SBD MOMSN=11390897 2019-06-19T17:11:58.318Z,1560964318.318 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:12:08.377Z,1560964328.377 [DataOverHttps](INFO): Sending 200 bytes from file Logs/20190619T160935/Express0028.lzma 2019-06-19T17:12:09.182Z,1560964329.182 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0028.lzma.bak 2019-06-19T17:12:09.183Z,1560964329.183 [DataOverHttps](INFO): SBD MOMSN=11390899 2019-06-19T17:12:10.082Z,1560964330.082 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:12:10.082Z,1560964330.082 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:12:10.082Z,1560964330.082 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:12:29.019Z,1560964349.019 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:17:10.652Z,1560964630.652 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:17:10.652Z,1560964630.652 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:17:10.652Z,1560964630.652 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:17:10.652Z,1560964630.652 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:17:11.041Z,1560964631.041 [Default:CheckIn:D] Stopped 2019-06-19T17:17:11.042Z,1560964631.042 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:17:11.441Z,1560964631.441 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 88.263517 min 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn:E] Stopped 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn] Stopped 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn](INFO): Running loop #14 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn] Running Loop=14 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:17:11.442Z,1560964631.442 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:17:13.034Z,1560964633.034 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-06-19T17:17:13.034Z,1560964633.034 [NAL9602] Data Fault, FailCount= 2 2019-06-19T17:17:13.034Z,1560964633.034 [NAL9602](ERROR): Data Fault 2019-06-19T17:17:13.069Z,1560964633.069 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T17:17:13.438Z,1560964633.438 [NAL9602](INFO): Powering down 2019-06-19T17:17:14.294Z,1560964634.294 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T17:17:14.294Z,1560964634.294 [NAL9602] No Fault, FailCount= 2 2019-06-19T17:17:43.738Z,1560964663.738 [NAL9602](INFO): Powering up NAL9602 2019-06-19T17:17:54.654Z,1560964674.654 [NAL9602](INFO): NAL9602 initialized 2019-06-19T17:17:55.465Z,1560964675.465 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:22:11.630Z,1560964931.630 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:17:11.4Z 2019-06-19T17:22:11.630Z,1560964931.630 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:22:11.631Z,1560964931.631 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:22:16.820Z,1560964936.820 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0030.lzma 2019-06-19T17:22:17.626Z,1560964937.626 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0030.lzma.bak 2019-06-19T17:22:17.627Z,1560964937.627 [DataOverHttps](INFO): SBD MOMSN=11390903 2019-06-19T17:22:28.757Z,1560964948.757 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20190619T160935/Express0031.lzma 2019-06-19T17:22:29.562Z,1560964949.562 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0031.lzma.bak 2019-06-19T17:22:29.563Z,1560964949.563 [DataOverHttps](INFO): SBD MOMSN=11390905 2019-06-19T17:22:30.208Z,1560964950.208 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:22:30.208Z,1560964950.208 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:22:30.208Z,1560964950.208 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:22:58.050Z,1560964978.050 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:23:28.758Z,1560965008.758 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:27:30.777Z,1560965250.777 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:27:30.777Z,1560965250.777 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:27:30.777Z,1560965250.777 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:27:30.778Z,1560965250.778 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:27:31.182Z,1560965251.182 [Default:CheckIn:D] Stopped 2019-06-19T17:27:31.182Z,1560965251.182 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:27:31.586Z,1560965251.586 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.599186 min 2019-06-19T17:27:31.586Z,1560965251.586 [Default:CheckIn:E] Stopped 2019-06-19T17:27:31.586Z,1560965251.586 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:27:31.586Z,1560965251.586 [Default:CheckIn] Stopped 2019-06-19T17:27:31.586Z,1560965251.586 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:27:31.587Z,1560965251.587 [Default:CheckIn](INFO): Running loop #15 2019-06-19T17:27:31.587Z,1560965251.587 [Default:CheckIn] Running Loop=15 2019-06-19T17:27:31.587Z,1560965251.587 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:27:31.587Z,1560965251.587 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:27:33.185Z,1560965253.185 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:28:04.288Z,1560965284.288 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-06-19T17:28:04.361Z,1560965284.361 [NAL9602](FAULT): received: +CSQ:0 OK09, 0, 0, 0, 0 OK 2019-06-19T17:28:04.361Z,1560965284.361 [NAL9602] Data Fault, FailCount= 3 2019-06-19T17:28:04.361Z,1560965284.361 [NAL9602](ERROR): Data Fault 2019-06-19T17:28:04.437Z,1560965284.437 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T17:28:04.686Z,1560965284.686 [NAL9602](INFO): Powering down 2019-06-19T17:28:05.565Z,1560965285.565 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T17:28:05.565Z,1560965285.565 [NAL9602] No Fault, FailCount= 3 2019-06-19T17:28:34.986Z,1560965314.986 [NAL9602](INFO): Powering up NAL9602 2019-06-19T17:28:45.894Z,1560965325.894 [NAL9602](INFO): NAL9602 initialized 2019-06-19T17:28:46.708Z,1560965326.708 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-06-19T17:28:46.708Z,1560965326.708 [NAL9602] Data Fault, FailCount= 4 2019-06-19T17:28:46.708Z,1560965326.708 [NAL9602](ERROR): Data Fault 2019-06-19T17:28:46.751Z,1560965326.751 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T17:28:47.110Z,1560965327.110 [NAL9602](INFO): Powering down 2019-06-19T17:28:47.983Z,1560965327.983 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T17:28:47.983Z,1560965327.983 [NAL9602] No Fault, FailCount= 4 2019-06-19T17:29:17.404Z,1560965357.404 [NAL9602](INFO): Powering up NAL9602 2019-06-19T17:29:28.312Z,1560965368.312 [NAL9602](INFO): NAL9602 initialized 2019-06-19T17:29:29.133Z,1560965369.133 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:32:31.776Z,1560965551.776 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:27:31.6Z 2019-06-19T17:32:31.781Z,1560965551.781 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:32:31.781Z,1560965551.781 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:32:34.048Z,1560965554.048 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0033.lzma 2019-06-19T17:32:34.854Z,1560965554.854 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0033.lzma.bak 2019-06-19T17:32:34.855Z,1560965554.855 [DataOverHttps](INFO): SBD MOMSN=11390911 2019-06-19T17:32:35.426Z,1560965555.426 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:32:45.865Z,1560965565.865 [DataOverHttps](INFO): Sending 251 bytes from file Logs/20190619T160935/Express0034.lzma 2019-06-19T17:32:46.670Z,1560965566.670 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0034.lzma.bak 2019-06-19T17:32:46.671Z,1560965566.671 [DataOverHttps](INFO): SBD MOMSN=11390913 2019-06-19T17:32:47.578Z,1560965567.578 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:32:47.578Z,1560965567.578 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:32:47.578Z,1560965567.578 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:33:06.126Z,1560965586.126 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:37:48.162Z,1560965868.162 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:37:48.162Z,1560965868.162 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:37:48.162Z,1560965868.162 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:37:48.163Z,1560965868.163 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:37:48.553Z,1560965868.553 [Default:CheckIn:D] Stopped 2019-06-19T17:37:48.554Z,1560965868.554 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.888721 min 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn:E] Stopped 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn] Stopped 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn](INFO): Running loop #16 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn] Running Loop=16 2019-06-19T17:37:48.958Z,1560965868.958 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:37:48.959Z,1560965868.959 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:37:50.557Z,1560965870.557 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:42:49.138Z,1560966169.138 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:37:48.0Z 2019-06-19T17:42:49.138Z,1560966169.138 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:42:49.138Z,1560966169.138 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:42:53.138Z,1560966173.138 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:42:54.576Z,1560966174.576 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0036.lzma 2019-06-19T17:42:55.382Z,1560966175.382 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0036.lzma.bak 2019-06-19T17:42:55.382Z,1560966175.382 [DataOverHttps](INFO): SBD MOMSN=11390919 2019-06-19T17:43:06.265Z,1560966186.265 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20190619T160935/Express0037.lzma 2019-06-19T17:43:07.070Z,1560966187.070 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0037.lzma.bak 2019-06-19T17:43:07.071Z,1560966187.071 [DataOverHttps](INFO): SBD MOMSN=11390921 2019-06-19T17:43:07.705Z,1560966187.705 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:43:07.705Z,1560966187.705 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:43:07.705Z,1560966187.705 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:43:23.846Z,1560966203.846 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:48:08.278Z,1560966488.278 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:48:08.278Z,1560966488.278 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:48:08.278Z,1560966488.278 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:48:08.279Z,1560966488.279 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:48:08.690Z,1560966488.690 [Default:CheckIn:D] Stopped 2019-06-19T17:48:08.690Z,1560966488.690 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.224325 min 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn:E] Stopped 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn] Stopped 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn](INFO): Running loop #17 2019-06-19T17:48:09.102Z,1560966489.102 [Default:CheckIn] Running Loop=17 2019-06-19T17:48:09.103Z,1560966489.103 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:48:09.103Z,1560966489.103 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:48:10.680Z,1560966490.680 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-06-19T17:48:10.680Z,1560966490.680 [NAL9602] Data Fault, FailCount= 5 2019-06-19T17:48:10.680Z,1560966490.680 [NAL9602](ERROR): Data Fault 2019-06-19T17:48:10.720Z,1560966490.720 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T17:48:10.720Z,1560966490.720 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-06-19T17:48:11.086Z,1560966491.086 [NAL9602](INFO): Powering down 2019-06-19T17:48:11.125Z,1560966491.125 [CommandLine](FAULT): Scheduling is paused 2019-06-19T17:48:11.126Z,1560966491.126 [CBIT](INFO): Critical error at 20190619T174810 2019-06-19T17:50:10.704Z,1560966610.704 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T17:50:10.704Z,1560966610.704 [NAL9602] No Fault, FailCount= 5 2019-06-19T17:50:11.078Z,1560966611.078 [NAL9602](INFO): Powering up NAL9602 2019-06-19T17:50:21.986Z,1560966621.986 [NAL9602](INFO): NAL9602 initialized 2019-06-19T17:50:22.801Z,1560966622.801 [NAL9602](DEBUG): Fix Requested 2019-06-19T17:53:09.274Z,1560966789.274 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:48:09.1Z 2019-06-19T17:53:09.274Z,1560966789.274 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T17:53:09.275Z,1560966789.275 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T17:53:11.792Z,1560966791.792 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20190619T160935/Courier0039.lzma 2019-06-19T17:53:12.598Z,1560966792.598 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0039.lzma.bak 2019-06-19T17:53:12.599Z,1560966792.599 [DataOverHttps](INFO): SBD MOMSN=11390925 2019-06-19T17:53:23.741Z,1560966803.741 [DataOverHttps](INFO): Sending 240 bytes from file Logs/20190619T160935/Express0040.lzma 2019-06-19T17:53:24.546Z,1560966804.546 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0040.lzma.bak 2019-06-19T17:53:24.547Z,1560966804.547 [DataOverHttps](INFO): SBD MOMSN=11390928 2019-06-19T17:53:25.497Z,1560966805.497 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T17:53:25.497Z,1560966805.497 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T17:53:25.497Z,1560966805.497 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T17:55:25.430Z,1560966925.430 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T17:55:56.134Z,1560966956.134 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T17:58:26.054Z,1560967106.054 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T17:58:26.055Z,1560967106.055 [Default:CheckIn:C.Wait] Stopped 2019-06-19T17:58:26.055Z,1560967106.055 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T17:58:26.055Z,1560967106.055 [Default:CheckIn:D] Running Loop=1 2019-06-19T17:58:26.442Z,1560967106.442 [Default:CheckIn:D] Stopped 2019-06-19T17:58:26.443Z,1560967106.443 [Default:CheckIn:E] Running Loop=1 2019-06-19T17:58:26.854Z,1560967106.854 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 129.520199 min 2019-06-19T17:58:26.854Z,1560967106.854 [Default:CheckIn:E] Stopped 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn] Stopped 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn](INFO): Running loop #18 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn] Running Loop=18 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T17:58:26.855Z,1560967106.855 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T17:58:28.457Z,1560967108.457 [NAL9602](DEBUG): Fix Requested 2019-06-19T18:02:57.091Z,1560967377.091 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2019-06-19T18:03:23.650Z,1560967403.650 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2019-06-19T18:03:27.166Z,1560967407.166 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T17:58:26.9Z 2019-06-19T18:03:27.166Z,1560967407.166 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T18:03:27.166Z,1560967407.166 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T18:03:30.882Z,1560967410.882 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T18:03:37.277Z,1560967417.277 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190619T160935/Courier0042.lzma 2019-06-19T18:03:38.083Z,1560967418.083 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0042.lzma.bak 2019-06-19T18:03:38.083Z,1560967418.083 [DataOverHttps](INFO): SBD MOMSN=11390934 2019-06-19T18:03:58.504Z,1560967438.504 [DataOverHttps](INFO): Sending 200 bytes from file Logs/20190619T160935/Express0043.lzma 2019-06-19T18:03:59.310Z,1560967439.310 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0043.lzma.bak 2019-06-19T18:03:59.311Z,1560967439.311 [DataOverHttps](INFO): SBD MOMSN=11390936 2019-06-19T18:04:00.006Z,1560967440.006 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T18:04:00.006Z,1560967440.006 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T18:04:00.006Z,1560967440.006 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T18:04:01.586Z,1560967441.586 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T18:04:45.804Z,1560967485.804 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2019-06-19T18:06:14.222Z,1560967574.222 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2019-06-19T18:06:21.125Z,1560967581.125 [BPC1](ERROR): BPC1A failed to parse battery data due to unrecognized msg size. 2019-06-19T18:08:00.800Z,1560967680.800 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-06-19T18:08:00.803Z,1560967680.803 [BPC1](INFO): Received data from all battery sticks. 2019-06-19T18:09:00.598Z,1560967740.598 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-06-19T18:09:00.598Z,1560967740.598 [Default:CheckIn:C.Wait] Stopped 2019-06-19T18:09:00.598Z,1560967740.598 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T18:09:00.598Z,1560967740.598 [Default:CheckIn:D] Running Loop=1 2019-06-19T18:09:01.009Z,1560967741.009 [Default:CheckIn:D] Stopped 2019-06-19T18:09:01.010Z,1560967741.010 [Default:CheckIn:E] Running Loop=1 2019-06-19T18:09:01.412Z,1560967741.412 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 140.096322 min 2019-06-19T18:09:01.412Z,1560967741.412 [Default:CheckIn:E] Stopped 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn] Stopped 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn](INFO): Running loop #19 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn] Running Loop=19 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-06-19T18:09:01.413Z,1560967741.413 [Default:CheckIn:Read_GPS] Running Loop=1 2019-06-19T18:09:02.998Z,1560967742.998 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-06-19T18:09:02.998Z,1560967742.998 [NAL9602] Data Fault, FailCount= 1 2019-06-19T18:09:02.998Z,1560967742.998 [NAL9602](ERROR): Data Fault 2019-06-19T18:09:03.033Z,1560967743.033 [CBIT](ERROR): Data Fault in component: NAL9602 2019-06-19T18:09:03.398Z,1560967743.398 [NAL9602](INFO): Powering down 2019-06-19T18:09:04.243Z,1560967744.243 [CBIT](INFO): Clearing failed state for component NAL9602 2019-06-19T18:09:04.244Z,1560967744.244 [NAL9602] No Fault, FailCount= 1 2019-06-19T18:09:33.702Z,1560967773.702 [NAL9602](INFO): Powering up NAL9602 2019-06-19T18:09:44.606Z,1560967784.606 [NAL9602](INFO): NAL9602 initialized 2019-06-19T18:09:45.425Z,1560967785.425 [NAL9602](DEBUG): Fix Requested 2019-06-19T18:14:01.642Z,1560968041.642 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-06-19T18:09:01.4Z 2019-06-19T18:14:01.642Z,1560968041.642 [Default:CheckIn:Read_GPS] Stopped 2019-06-19T18:14:01.644Z,1560968041.644 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-06-19T18:14:06.507Z,1560968046.507 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20190619T160935/Courier0045.lzma 2019-06-19T18:14:07.095Z,1560968047.095 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Courier0045.lzma.bak 2019-06-19T18:14:07.095Z,1560968047.095 [DataOverHttps](INFO): SBD MOMSN=11390940 2019-06-19T18:14:18.901Z,1560968058.901 [DataOverHttps](INFO): Sending 217 bytes from file Logs/20190619T160935/Express0046.lzma 2019-06-19T18:14:19.707Z,1560968059.707 [DataOverHttps](INFO): Moved sent file to Logs/20190619T160935/Express0046.lzma.bak 2019-06-19T18:14:19.707Z,1560968059.707 [DataOverHttps](INFO): SBD MOMSN=11390942 2019-06-19T18:14:20.550Z,1560968060.550 [Default:CheckIn:Read_Iridium] Stopped 2019-06-19T18:14:20.550Z,1560968060.550 [Default:CheckIn:C.Wait] Running Loop=1 2019-06-19T18:14:20.550Z,1560968060.550 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-06-19T18:14:47.970Z,1560968087.970 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-06-19T18:15:18.667Z,1560968118.667 [NAL9602](INFO): Not Powering down - fast GPS 2019-06-19T18:19:17.318Z,1560968357.318 [CommandLine](IMPORTANT): got command quit 2019-06-19T18:19:18.325Z,1560968358.325 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:18.325Z,1560968358.325 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.421Z,1560968358.421 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-06-19T18:19:18.421Z,1560968358.421 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.422Z,1560968358.422 [CommandLine](INFO): Join timeout helper Thread ID is 7087 2019-06-19T18:19:18.422Z,1560968358.422 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-06-19T18:19:18.423Z,1560968358.423 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.423Z,1560968358.423 [NavChartDb](INFO): Join timeout helper Thread ID is 7088 2019-06-19T18:19:18.529Z,1560968358.529 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:18.529Z,1560968358.529 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.541Z,1560968358.541 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-06-19T18:19:18.541Z,1560968358.541 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.541Z,1560968358.541 [Radio_Surface](INFO): Join timeout helper Thread ID is 7089 2019-06-19T18:19:18.717Z,1560968358.717 [Radio_Surface](INFO): Powering down 2019-06-19T18:19:18.718Z,1560968358.718 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:18.718Z,1560968358.718 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.725Z,1560968358.725 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-06-19T18:19:18.725Z,1560968358.725 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.725Z,1560968358.725 [DataOverHttps](INFO): Join timeout helper Thread ID is 7090 2019-06-19T18:19:18.770Z,1560968358.770 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:18.770Z,1560968358.770 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.777Z,1560968358.777 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-06-19T18:19:18.777Z,1560968358.777 [logger ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.777Z,1560968358.777 [logger](INFO): Join timeout helper Thread ID is 7091 2019-06-19T18:19:18.812Z,1560968358.812 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:18.812Z,1560968358.812 [logger ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.830Z,1560968358.830 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-06-19T18:19:18.830Z,1560968358.830 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.830Z,1560968358.830 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-06-19T18:19:18.830Z,1560968358.830 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:18.831Z,1560968358.831 [controlThread](INFO): Join timeout helper Thread ID is 7092 2019-06-19T18:19:19.033Z,1560968359.033 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-06-19T18:19:19.033Z,1560968359.033 [controlThread](DEBUG): Uninitializing ControlThread 2019-06-19T18:19:19.034Z,1560968359.034 [AHRS_M2](INFO): Powering down 2019-06-19T18:19:19.105Z,1560968359.105 [NAL9602](INFO): Powering down 2019-06-19T18:19:19.107Z,1560968359.107 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-06-19T18:19:19.108Z,1560968359.108 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-06-19T18:19:19.109Z,1560968359.109 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-06-19T18:19:19.109Z,1560968359.109 [MissionManager](INFO): Uninitializing Mission Default 2019-06-19T18:19:19.110Z,1560968359.110 [Default] Stopped 2019-06-19T18:19:19.110Z,1560968359.110 [Default](DEBUG): Aggregate::uninitialize Default 2019-06-19T18:19:19.110Z,1560968359.110 [Default:B.GoToSurface] Stopped 2019-06-19T18:19:19.110Z,1560968359.110 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-06-19T18:19:19.110Z,1560968359.110 [Default:CheckIn] Stopped 2019-06-19T18:19:19.110Z,1560968359.110 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-06-19T18:19:19.110Z,1560968359.110 [Default:CheckIn:C.Wait] Stopped 2019-06-19T18:19:19.110Z,1560968359.110 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-06-19T18:19:19.112Z,1560968359.112 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-06-19T18:19:19.113Z,1560968359.113 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-06-19T18:19:19.113Z,1560968359.113 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-06-19T18:19:19.113Z,1560968359.113 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-06-19T18:19:19.114Z,1560968359.114 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-06-19T18:19:19.114Z,1560968359.114 [BuoyancyServo](INFO): Powering down 2019-06-19T18:19:19.125Z,1560968359.125 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-06-19T18:19:19.125Z,1560968359.125 [ElevatorServo](INFO): Powering down 2019-06-19T18:19:19.126Z,1560968359.126 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-06-19T18:19:19.126Z,1560968359.126 [MassServo](INFO): Powering down 2019-06-19T18:19:19.127Z,1560968359.127 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-06-19T18:19:19.127Z,1560968359.127 [RudderServo](INFO): Powering down 2019-06-19T18:19:19.128Z,1560968359.128 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-06-19T18:19:19.128Z,1560968359.128 [ThrusterServo](INFO): Powering down 2019-06-19T18:19:19.128Z,1560968359.128 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-06-19T18:19:19.129Z,1560968359.129 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-06-19T18:19:19.129Z,1560968359.129 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-06-19T18:19:19.129Z,1560968359.129 [CBIT](DEBUG): Powering off loads. 2019-06-19T18:19:19.141Z,1560968359.141 [CBIT](DEBUG): Disabling WDT. 2019-06-19T18:19:19.153Z,1560968359.153 [CBIT](DEBUG): Opening all GF detection circuits. 2019-06-19T18:19:19.154Z,1560968359.154 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:19.272Z,1560968359.272 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:19.278Z,1560968359.278 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:19.318Z,1560968359.318 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-06-19T18:19:19.388Z,1560968359.388 [logger ThreadHandler](INFO): Thread cancelled.