2019-09-25T17:32:33.617Z,1569432753.617 [DataOverHttps](INFO): Received command:restart logs 2019-09-25T17:32:33.634Z,1569432753.634 [CommandLine](IMPORTANT): got command restart logs 2019-09-25T17:32:46.188Z,1569432766.188 [DataOverHttps](INFO): Sending 136 bytes from file Logs/20190925T160428/Express0022.lzma 2019-09-25T17:32:48.194Z,1569432768.194 [DataOverHttps](INFO): Moved sent file to Logs/20190925T160428/Express0022.lzma.bak 2019-09-25T17:32:48.195Z,1569432768.195 [DataOverHttps](INFO): SBD MOMSN=11815401 2019-09-25T17:33:03.175Z,1569432783.175 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T17:33:20.322Z,1569432800.322 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-25T17:33:37.684Z,1569432817.684 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T160428/Courier0024.lzma 2019-09-25T17:33:39.690Z,1569432819.690 [DataOverHttps](INFO): Moved sent file to Logs/20190925T160428/Courier0024.lzma.bak 2019-09-25T17:33:39.691Z,1569432819.691 [DataOverHttps](INFO): SBD MOMSN=11815407 2019-09-25T17:34:06.856Z,1569432846.856 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0000.lzma 2019-09-25T17:34:10.870Z,1569432850.870 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0000.lzma.bak 2019-09-25T17:34:10.871Z,1569432850.871 [DataOverHttps](INFO): SBD MOMSN=11815416 2019-09-25T17:34:28.517Z,1569432868.517 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20190925T160428/Express0025.lzma 2019-09-25T17:34:30.522Z,1569432870.522 [DataOverHttps](INFO): Moved sent file to Logs/20190925T160428/Express0025.lzma.bak 2019-09-25T17:34:30.523Z,1569432870.523 [DataOverHttps](INFO): SBD MOMSN=11815419 2019-09-25T17:35:08.096Z,1569432908.096 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Express0001.lzma 2019-09-25T17:35:10.102Z,1569432910.102 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0001.lzma.bak 2019-09-25T17:35:10.103Z,1569432910.103 [DataOverHttps](INFO): SBD MOMSN=11815423 2019-09-25T17:35:11.684Z,1569432911.684 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T17:35:11.684Z,1569432911.684 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T17:35:11.684Z,1569432911.684 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T17:39:42.344Z,1569433182.344 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-09-25T17:40:12.266Z,1569433212.266 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T17:40:12.266Z,1569433212.266 [Default:CheckIn:C.Wait] Stopped 2019-09-25T17:40:12.266Z,1569433212.266 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T17:40:12.267Z,1569433212.267 [Default:CheckIn:D] Running Loop=1 2019-09-25T17:40:12.659Z,1569433212.659 [Default:CheckIn:D] Stopped 2019-09-25T17:40:12.659Z,1569433212.659 [Default:CheckIn:E] Running Loop=1 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.723322 min 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn:E] Stopped 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn] Stopped 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn](INFO): Running loop #5 2019-09-25T17:40:13.079Z,1569433213.079 [Default:CheckIn] Running Loop=5 2019-09-25T17:40:13.080Z,1569433213.080 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T17:40:13.080Z,1569433213.080 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T17:40:14.661Z,1569433214.661 [NAL9602](DEBUG): Fix Requested 2019-09-25T17:40:15.060Z,1569433215.060 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174016.00,A,3647.97133,N,12149.15312,W,17.281,75.90,250919,,,D*7E 2019-09-25T17:40:15.062Z,1569433215.062 [NAL9602](INFO): GPS fix at 20190925T174016: (36.799522, -121.819219) 2019-09-25T17:40:15.124Z,1569433215.124 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T17:40:15.124Z,1569433215.124 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T17:40:23.490Z,1569433223.490 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190925T173233/Courier0003.lzma 2019-09-25T17:40:25.490Z,1569433225.490 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0003.lzma.bak 2019-09-25T17:40:25.491Z,1569433225.491 [DataOverHttps](INFO): SBD MOMSN=11815450 2019-09-25T17:40:42.881Z,1569433242.881 [DataOverHttps](INFO): Sending 343 bytes from file Logs/20190925T173233/Express0004.lzma 2019-09-25T17:40:44.886Z,1569433244.886 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0004.lzma.bak 2019-09-25T17:40:44.886Z,1569433244.886 [DataOverHttps](INFO): SBD MOMSN=11815457 2019-09-25T17:40:46.163Z,1569433246.163 [NAL9602](INFO): SBD MO Status=0, MOMSN=1876, MT Status=0, MTMSN=0 2019-09-25T17:40:46.163Z,1569433246.163 [NAL9602](INFO): No messages in MT queue 2019-09-25T17:40:46.600Z,1569433246.600 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T17:40:46.600Z,1569433246.600 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T17:40:46.600Z,1569433246.600 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T17:41:16.870Z,1569433276.870 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T17:45:47.236Z,1569433547.236 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T17:45:47.237Z,1569433547.237 [Default:CheckIn:C.Wait] Stopped 2019-09-25T17:45:47.237Z,1569433547.237 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T17:45:47.237Z,1569433547.237 [Default:CheckIn:D] Running Loop=1 2019-09-25T17:45:47.607Z,1569433547.607 [Default:CheckIn:D] Stopped 2019-09-25T17:45:47.607Z,1569433547.607 [Default:CheckIn:E] Running Loop=1 2019-09-25T17:45:48.008Z,1569433548.008 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.305780 min 2019-09-25T17:45:48.008Z,1569433548.008 [Default:CheckIn:E] Stopped 2019-09-25T17:45:48.008Z,1569433548.008 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T17:45:48.008Z,1569433548.008 [Default:CheckIn] Stopped 2019-09-25T17:45:48.008Z,1569433548.008 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T17:45:48.009Z,1569433548.009 [Default:CheckIn](INFO): Running loop #6 2019-09-25T17:45:48.009Z,1569433548.009 [Default:CheckIn] Running Loop=6 2019-09-25T17:45:48.009Z,1569433548.009 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T17:45:48.009Z,1569433548.009 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T17:45:49.597Z,1569433549.597 [NAL9602](DEBUG): Fix Requested 2019-09-25T17:45:50.000Z,1569433550.000 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174551.00,A,3648.06123,N,12148.46924,W,17.670,72.01,250919,,,D*73 2019-09-25T17:45:50.008Z,1569433550.008 [NAL9602](INFO): GPS fix at 20190925T174551: (36.801020, -121.807821) 2019-09-25T17:45:50.066Z,1569433550.066 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T17:45:50.066Z,1569433550.066 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T17:45:57.360Z,1569433557.360 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0006.lzma 2019-09-25T17:45:59.366Z,1569433559.366 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0006.lzma.bak 2019-09-25T17:45:59.367Z,1569433559.367 [DataOverHttps](INFO): SBD MOMSN=11815520 2019-09-25T17:46:16.728Z,1569433576.728 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190925T173233/Express0007.lzma 2019-09-25T17:46:17.459Z,1569433577.459 [NAL9602](INFO): SBD MO Status=0, MOMSN=1877, MT Status=0, MTMSN=0 2019-09-25T17:46:17.460Z,1569433577.460 [NAL9602](INFO): No messages in MT queue 2019-09-25T17:46:18.734Z,1569433578.734 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0007.lzma.bak 2019-09-25T17:46:18.734Z,1569433578.734 [DataOverHttps](INFO): SBD MOMSN=11815523 2019-09-25T17:46:20.355Z,1569433580.355 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T17:46:20.356Z,1569433580.356 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T17:46:20.356Z,1569433580.356 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T17:46:48.166Z,1569433608.166 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T17:51:20.888Z,1569433880.888 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T17:51:20.888Z,1569433880.888 [Default:CheckIn:C.Wait] Stopped 2019-09-25T17:51:20.888Z,1569433880.888 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T17:51:20.892Z,1569433880.892 [Default:CheckIn:D] Running Loop=1 2019-09-25T17:51:21.316Z,1569433881.316 [Default:CheckIn:D] Stopped 2019-09-25T17:51:21.316Z,1569433881.316 [Default:CheckIn:E] Running Loop=1 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 37.867594 min 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn:E] Stopped 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn] Stopped 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn](INFO): Running loop #7 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn] Running Loop=7 2019-09-25T17:51:21.704Z,1569433881.704 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T17:51:21.705Z,1569433881.705 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T17:51:23.301Z,1569433883.301 [NAL9602](DEBUG): Fix Requested 2019-09-25T17:51:23.692Z,1569433883.692 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175125.00,A,3648.50918,N,12147.16959,W,5.734,83.13,250919,,,D*49 2019-09-25T17:51:23.694Z,1569433883.694 [NAL9602](INFO): GPS fix at 20190925T175125: (36.808486, -121.786160) 2019-09-25T17:51:23.718Z,1569433883.718 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T17:51:23.718Z,1569433883.718 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T17:51:31.752Z,1569433891.752 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0009.lzma 2019-09-25T17:51:33.758Z,1569433893.758 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0009.lzma.bak 2019-09-25T17:51:33.759Z,1569433893.759 [DataOverHttps](INFO): SBD MOMSN=11815569 2019-09-25T17:51:34.619Z,1569433894.619 [NAL9602](INFO): SBD MO Status=0, MOMSN=1878, MT Status=0, MTMSN=0 2019-09-25T17:51:34.619Z,1569433894.619 [NAL9602](INFO): No messages in MT queue 2019-09-25T17:51:51.065Z,1569433911.065 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20190925T173233/Express0010.lzma 2019-09-25T17:51:53.071Z,1569433913.071 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0010.lzma.bak 2019-09-25T17:51:53.071Z,1569433913.071 [DataOverHttps](INFO): SBD MOMSN=11815572 2019-09-25T17:51:54.438Z,1569433914.438 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T17:51:54.438Z,1569433914.438 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T17:51:54.438Z,1569433914.438 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T17:52:05.306Z,1569433925.306 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T17:55:12.016Z,1569434112.016 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-25T17:55:12.016Z,1569434112.016 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, +0.00, 0.00,1409.91 2019-09-25T17:56:55.053Z,1569434215.053 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T17:56:55.053Z,1569434215.053 [Default:CheckIn:C.Wait] Stopped 2019-09-25T17:56:55.053Z,1569434215.053 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T17:56:55.053Z,1569434215.053 [Default:CheckIn:D] Running Loop=1 2019-09-25T17:56:55.428Z,1569434215.428 [Default:CheckIn:D] Stopped 2019-09-25T17:56:55.428Z,1569434215.428 [Default:CheckIn:E] Running Loop=1 2019-09-25T17:56:55.827Z,1569434215.827 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.436125 min 2019-09-25T17:56:55.827Z,1569434215.827 [Default:CheckIn:E] Stopped 2019-09-25T17:56:55.827Z,1569434215.827 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T17:56:55.827Z,1569434215.827 [Default:CheckIn] Stopped 2019-09-25T17:56:55.828Z,1569434215.828 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T17:56:55.828Z,1569434215.828 [Default:CheckIn](INFO): Running loop #8 2019-09-25T17:56:55.828Z,1569434215.828 [Default:CheckIn] Running Loop=8 2019-09-25T17:56:55.828Z,1569434215.828 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T17:56:55.828Z,1569434215.828 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T17:56:57.429Z,1569434217.429 [NAL9602](DEBUG): Fix Requested 2019-09-25T17:56:57.824Z,1569434217.824 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175659.00,A,3648.15424,N,12147.21937,W,0.253,214.82,250919,,,A*7A 2019-09-25T17:56:57.826Z,1569434217.826 [NAL9602](INFO): GPS fix at 20190925T175659: (36.802571, -121.786990) 2019-09-25T17:56:57.868Z,1569434217.868 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T17:56:57.868Z,1569434217.868 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T17:57:05.796Z,1569434225.796 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0012.lzma 2019-09-25T17:57:07.803Z,1569434227.803 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0012.lzma.bak 2019-09-25T17:57:07.803Z,1569434227.803 [DataOverHttps](INFO): SBD MOMSN=11815590 2019-09-25T17:57:11.155Z,1569434231.155 [NAL9602](INFO): SBD MO Status=0, MOMSN=1879, MT Status=0, MTMSN=0 2019-09-25T17:57:11.155Z,1569434231.155 [NAL9602](INFO): No messages in MT queue 2019-09-25T17:57:25.113Z,1569434245.113 [DataOverHttps](INFO): Sending 141 bytes from file Logs/20190925T173233/Express0013.lzma 2019-09-25T17:57:27.121Z,1569434247.121 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0013.lzma.bak 2019-09-25T17:57:27.122Z,1569434247.122 [DataOverHttps](INFO): SBD MOMSN=11815595 2019-09-25T17:57:28.555Z,1569434248.555 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T17:57:28.555Z,1569434248.555 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T17:57:28.555Z,1569434248.555 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T17:57:41.858Z,1569434261.858 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:01:08.359Z,1569434468.359 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-09-25T18:02:29.132Z,1569434549.132 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:02:29.132Z,1569434549.132 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:02:29.132Z,1569434549.132 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:02:29.133Z,1569434549.133 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:02:29.552Z,1569434549.552 [Default:CheckIn:D] Stopped 2019-09-25T18:02:29.552Z,1569434549.552 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:02:29.952Z,1569434549.952 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.004858 min 2019-09-25T18:02:29.952Z,1569434549.952 [Default:CheckIn:E] Stopped 2019-09-25T18:02:29.952Z,1569434549.952 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:02:29.952Z,1569434549.952 [Default:CheckIn] Stopped 2019-09-25T18:02:29.953Z,1569434549.953 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:02:29.953Z,1569434549.953 [Default:CheckIn](INFO): Running loop #9 2019-09-25T18:02:29.953Z,1569434549.953 [Default:CheckIn] Running Loop=9 2019-09-25T18:02:29.953Z,1569434549.953 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:02:29.953Z,1569434549.953 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:02:31.548Z,1569434551.548 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:02:31.944Z,1569434551.944 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180233.00,A,3648.15505,N,12147.21970,W,0.019,214.82,250919,,,D*70 2019-09-25T18:02:31.947Z,1569434551.947 [NAL9602](INFO): GPS fix at 20190925T180233: (36.802584, -121.786995) 2019-09-25T18:02:32.014Z,1569434552.014 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:02:32.015Z,1569434552.015 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:02:32.391Z,1569434552.391 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-25T18:02:32.392Z,1569434552.392 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-09-25T18:02:40.076Z,1569434560.076 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0015.lzma 2019-09-25T18:02:42.082Z,1569434562.082 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0015.lzma.bak 2019-09-25T18:02:42.083Z,1569434562.083 [DataOverHttps](INFO): SBD MOMSN=11815621 2019-09-25T18:02:47.703Z,1569434567.703 [NAL9602](INFO): SBD MO Status=0, MOMSN=1880, MT Status=0, MTMSN=0 2019-09-25T18:02:47.703Z,1569434567.703 [NAL9602](INFO): No messages in MT queue 2019-09-25T18:02:59.413Z,1569434579.413 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190925T173233/Express0016.lzma 2019-09-25T18:03:01.681Z,1569434581.681 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0016.lzma.bak 2019-09-25T18:03:01.681Z,1569434581.681 [DataOverHttps](INFO): SBD MOMSN=11815624 2019-09-25T18:03:03.123Z,1569434583.123 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:03:03.124Z,1569434583.124 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:03:03.124Z,1569434583.124 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:03:08.736Z,1569434588.736 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-25T18:03:08.736Z,1569434588.736 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,32768,V 2019-09-25T18:03:18.402Z,1569434598.402 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:03:35.393Z,1569434615.393 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T18:03:35.393Z,1569434615.393 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092518044121,35.0, -0.1, 0.0, 0 2019-09-25T18:08:03.681Z,1569434883.681 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:08:03.681Z,1569434883.681 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:08:03.681Z,1569434883.681 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:08:03.681Z,1569434883.681 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:08:04.100Z,1569434884.100 [Default:CheckIn:D] Stopped 2019-09-25T18:08:04.100Z,1569434884.100 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.580664 min 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn:E] Stopped 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn] Stopped 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn](INFO): Running loop #10 2019-09-25T18:08:04.487Z,1569434884.487 [Default:CheckIn] Running Loop=10 2019-09-25T18:08:04.488Z,1569434884.488 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:08:04.488Z,1569434884.488 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:08:06.089Z,1569434886.089 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:08:06.484Z,1569434886.484 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180808.00,A,3648.14135,N,12147.22836,W,0.019,230.57,250919,,,D*7A 2019-09-25T18:08:06.495Z,1569434886.495 [NAL9602](INFO): GPS fix at 20190925T180808: (36.802356, -121.787139) 2019-09-25T18:08:06.524Z,1569434886.524 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:08:06.524Z,1569434886.524 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:08:13.852Z,1569434893.852 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0018.lzma 2019-09-25T18:08:15.858Z,1569434895.858 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0018.lzma.bak 2019-09-25T18:08:15.859Z,1569434895.859 [DataOverHttps](INFO): SBD MOMSN=11815662 2019-09-25T18:08:17.015Z,1569434897.015 [NAL9602](INFO): SBD MO Status=0, MOMSN=1881, MT Status=0, MTMSN=0 2019-09-25T18:08:17.015Z,1569434897.015 [NAL9602](INFO): No messages in MT queue 2019-09-25T18:08:35.528Z,1569434915.528 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190925T173233/Express0019.lzma 2019-09-25T18:08:37.534Z,1569434917.534 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0019.lzma.bak 2019-09-25T18:08:37.535Z,1569434917.535 [DataOverHttps](INFO): SBD MOMSN=11815665 2019-09-25T18:08:38.883Z,1569434918.883 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:08:38.883Z,1569434918.883 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:08:38.883Z,1569434918.883 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:08:47.742Z,1569434927.742 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:13:39.498Z,1569435219.498 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:13:39.498Z,1569435219.498 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:13:39.498Z,1569435219.498 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:13:39.498Z,1569435219.498 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:13:39.888Z,1569435219.888 [Default:CheckIn:D] Stopped 2019-09-25T18:13:39.888Z,1569435219.888 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.177140 min 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn:E] Stopped 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn] Stopped 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:13:40.303Z,1569435220.303 [Default:CheckIn](INFO): Running loop #11 2019-09-25T18:13:40.304Z,1569435220.304 [Default:CheckIn] Running Loop=11 2019-09-25T18:13:40.304Z,1569435220.304 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:13:40.304Z,1569435220.304 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:13:41.901Z,1569435221.901 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:13:42.286Z,1569435222.286 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181344.00,A,3648.17185,N,12147.26924,W,2.955,295.19,250919,,,D*70 2019-09-25T18:13:42.288Z,1569435222.288 [NAL9602](INFO): GPS fix at 20190925T181344: (36.802864, -121.787821) 2019-09-25T18:13:42.338Z,1569435222.338 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:13:42.338Z,1569435222.338 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:13:50.100Z,1569435230.100 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0021.lzma 2019-09-25T18:13:52.107Z,1569435232.107 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0021.lzma.bak 2019-09-25T18:13:52.107Z,1569435232.107 [DataOverHttps](INFO): SBD MOMSN=11815677 2019-09-25T18:14:02.495Z,1569435242.495 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:14:02.495Z,1569435242.495 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:14:09.748Z,1569435249.748 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190925T173233/Express0022.lzma 2019-09-25T18:14:11.754Z,1569435251.754 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0022.lzma.bak 2019-09-25T18:14:11.755Z,1569435251.755 [DataOverHttps](INFO): SBD MOMSN=11815680 2019-09-25T18:14:13.428Z,1569435253.428 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:14:13.428Z,1569435253.428 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:14:13.428Z,1569435253.428 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:14:41.679Z,1569435281.679 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:14:41.680Z,1569435281.680 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:15:09.147Z,1569435309.147 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:15:09.148Z,1569435309.148 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:17:17.247Z,1569435437.247 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T18:17:17.247Z,1569435437.247 [RDI_Pathfinder](ERROR): Failed to parse: :TS8182221,35.0, -0.1, 0.0,1448.9, 0 2019-09-25T18:18:44.886Z,1569435524.886 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T18:19:12.061Z,1569435552.061 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-09-25T18:19:12.061Z,1569435552.061 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-09-25T18:19:12.061Z,1569435552.061 [RDI_Pathfinder](ERROR): Communications Fault 2019-09-25T18:19:12.061Z,1569435552.061 [RDI_Pathfinder](ERROR): Failed to parse: 2019-09-25T18:19:12.105Z,1569435552.105 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-09-25T18:19:12.441Z,1569435552.441 [RDI_Pathfinder](INFO): Powering down 2019-09-25T18:19:13.204Z,1569435553.204 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-09-25T18:19:13.204Z,1569435553.204 [RDI_Pathfinder] No Fault, FailCount= 1 2019-09-25T18:19:13.000Z,1569435554.000 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:19:13.000Z,1569435554.000 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:19:13.000Z,1569435554.000 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:19:14.000Z,1569435554.000 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:19:14.408Z,1569435554.408 [Default:CheckIn:D] Stopped 2019-09-25T18:19:14.408Z,1569435554.408 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.752462 min 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn:E] Stopped 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn] Stopped 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn](INFO): Running loop #12 2019-09-25T18:19:14.813Z,1569435554.813 [Default:CheckIn] Running Loop=12 2019-09-25T18:19:14.814Z,1569435554.814 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:19:14.814Z,1569435554.814 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:19:16.405Z,1569435556.405 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:19:16.804Z,1569435556.804 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181918.00,A,3648.18229,N,12147.27515,W,0.194,304.17,250919,,,D*76 2019-09-25T18:19:16.806Z,1569435556.806 [NAL9602](INFO): GPS fix at 20190925T181918: (36.803038, -121.787919) 2019-09-25T18:19:16.854Z,1569435556.854 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:19:16.854Z,1569435556.854 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:19:23.828Z,1569435563.828 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0024.lzma 2019-09-25T18:19:25.834Z,1569435565.834 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0024.lzma.bak 2019-09-25T18:19:25.835Z,1569435565.835 [DataOverHttps](INFO): SBD MOMSN=11815710 2019-09-25T18:19:26.926Z,1569435566.926 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-09-25T18:19:43.225Z,1569435583.225 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190925T173233/Express0025.lzma 2019-09-25T18:19:45.230Z,1569435585.230 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0025.lzma.bak 2019-09-25T18:19:45.231Z,1569435585.231 [DataOverHttps](INFO): SBD MOMSN=11815713 2019-09-25T18:19:46.762Z,1569435586.762 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:19:46.762Z,1569435586.762 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:19:46.762Z,1569435586.762 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:19:48.737Z,1569435588.737 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:24:47.331Z,1569435887.331 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:24:47.331Z,1569435887.331 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:24:47.332Z,1569435887.332 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:24:47.332Z,1569435887.332 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:24:47.769Z,1569435887.769 [Default:CheckIn:D] Stopped 2019-09-25T18:24:47.769Z,1569435887.769 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.308488 min 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn:E] Stopped 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn] Stopped 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:24:48.138Z,1569435888.138 [Default:CheckIn](INFO): Running loop #13 2019-09-25T18:24:48.139Z,1569435888.139 [Default:CheckIn] Running Loop=13 2019-09-25T18:24:48.139Z,1569435888.139 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:24:48.139Z,1569435888.139 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:24:49.757Z,1569435889.757 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:24:50.137Z,1569435890.137 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182452.00,A,3648.16842,N,12147.28142,W,0.194,214.17,250919,,,A*73 2019-09-25T18:24:50.139Z,1569435890.139 [NAL9602](INFO): GPS fix at 20190925T182452: (36.802807, -121.788024) 2019-09-25T18:24:50.168Z,1569435890.168 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:24:50.168Z,1569435890.168 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:24:52.154Z,1569435892.154 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-25T18:24:58.144Z,1569435898.144 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0027.lzma 2019-09-25T18:25:00.150Z,1569435900.150 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0027.lzma.bak 2019-09-25T18:25:00.151Z,1569435900.151 [DataOverHttps](INFO): SBD MOMSN=11815726 2019-09-25T18:25:17.508Z,1569435917.508 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190925T173233/Express0028.lzma 2019-09-25T18:25:19.514Z,1569435919.514 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0028.lzma.bak 2019-09-25T18:25:19.515Z,1569435919.515 [DataOverHttps](INFO): SBD MOMSN=11815729 2019-09-25T18:25:20.830Z,1569435920.830 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-25T18:25:20.913Z,1569435920.913 [NAL9602](FAULT): received: K CSQ:0 OK82, 2, 0, 0, 0 OK 2019-09-25T18:25:20.913Z,1569435920.913 [NAL9602] Data Fault, FailCount= 1 2019-09-25T18:25:20.913Z,1569435920.913 [NAL9602](ERROR): Data Fault 2019-09-25T18:25:20.975Z,1569435920.975 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:25:20.975Z,1569435920.975 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:25:20.975Z,1569435920.975 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:25:20.992Z,1569435920.992 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T18:25:21.238Z,1569435921.238 [NAL9602](INFO): Powering down 2019-09-25T18:25:22.107Z,1569435922.107 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T18:25:22.107Z,1569435922.107 [NAL9602] No Fault, FailCount= 1 2019-09-25T18:25:51.534Z,1569435951.534 [NAL9602](INFO): Powering up NAL9602 2019-09-25T18:26:02.448Z,1569435962.448 [NAL9602](INFO): NAL9602 initialized 2019-09-25T18:26:33.578Z,1569435993.578 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:27:07.143Z,1569436027.143 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-25T18:27:07.143Z,1569436027.143 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-25T18:30:21.456Z,1569436221.456 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:30:21.456Z,1569436221.456 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:30:21.456Z,1569436221.456 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:30:21.456Z,1569436221.456 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:30:21.871Z,1569436221.871 [Default:CheckIn:D] Stopped 2019-09-25T18:30:21.871Z,1569436221.871 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 76.876847 min 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn:E] Stopped 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn] Stopped 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn](INFO): Running loop #14 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn] Running Loop=14 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:30:22.271Z,1569436222.271 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:30:23.869Z,1569436223.869 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:30:24.260Z,1569436224.260 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183025.00,A,3648.16820,N,12147.28185,W,0.078,0.00,250919,,,A*7B 2019-09-25T18:30:24.262Z,1569436224.262 [NAL9602](INFO): GPS fix at 20190925T183025: (36.802803, -121.788031) 2019-09-25T18:30:24.286Z,1569436224.286 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:30:24.286Z,1569436224.286 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:30:26.682Z,1569436226.682 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T18:30:32.264Z,1569436232.264 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0030.lzma 2019-09-25T18:30:34.271Z,1569436234.271 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0030.lzma.bak 2019-09-25T18:30:34.271Z,1569436234.271 [DataOverHttps](INFO): SBD MOMSN=11815753 2019-09-25T18:30:51.829Z,1569436251.829 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20190925T173233/Express0031.lzma 2019-09-25T18:30:53.834Z,1569436253.834 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0031.lzma.bak 2019-09-25T18:30:53.835Z,1569436253.835 [DataOverHttps](INFO): SBD MOMSN=11815756 2019-09-25T18:30:55.414Z,1569436255.414 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:30:55.414Z,1569436255.414 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:30:55.414Z,1569436255.414 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:30:57.382Z,1569436257.382 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:32:48.106Z,1569436368.106 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T18:35:10.742Z,1569436510.742 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-25T18:35:55.965Z,1569436555.965 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:35:55.965Z,1569436555.965 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:35:55.965Z,1569436555.965 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:35:55.965Z,1569436555.965 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:35:56.378Z,1569436556.378 [Default:CheckIn:D] Stopped 2019-09-25T18:35:56.378Z,1569436556.378 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:35:56.798Z,1569436556.798 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 82.451969 min 2019-09-25T18:35:56.798Z,1569436556.798 [Default:CheckIn:E] Stopped 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn] Stopped 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn](INFO): Running loop #15 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn] Running Loop=15 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:35:56.799Z,1569436556.799 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:35:58.375Z,1569436558.375 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:35:58.772Z,1569436558.772 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183600.00,A,3648.16877,N,12147.28128,W,0.292,288.04,250919,,,A*7F 2019-09-25T18:35:58.774Z,1569436558.774 [NAL9602](INFO): GPS fix at 20190925T183600: (36.802813, -121.788021) 2019-09-25T18:35:58.824Z,1569436558.824 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:35:58.824Z,1569436558.824 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:36:06.600Z,1569436566.600 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0033.lzma 2019-09-25T18:36:08.606Z,1569436568.606 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0033.lzma.bak 2019-09-25T18:36:08.607Z,1569436568.607 [DataOverHttps](INFO): SBD MOMSN=11815777 2019-09-25T18:36:26.097Z,1569436586.097 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190925T173233/Express0034.lzma 2019-09-25T18:36:28.102Z,1569436588.102 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0034.lzma.bak 2019-09-25T18:36:28.103Z,1569436588.103 [DataOverHttps](INFO): SBD MOMSN=11815786 2019-09-25T18:36:29.626Z,1569436589.626 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:36:29.626Z,1569436589.626 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:36:29.626Z,1569436589.626 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:36:35.935Z,1569436595.935 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:36:35.936Z,1569436595.936 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:36:50.134Z,1569436610.134 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-09-25T18:36:50.136Z,1569436610.136 [BPC1](INFO): Received data from all battery sticks. 2019-09-25T18:37:01.799Z,1569436621.799 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:37:01.799Z,1569436621.799 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:37:10.736Z,1569436630.736 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-25T18:38:15.319Z,1569436695.319 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:38:15.320Z,1569436695.320 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:39:00.163Z,1569436740.163 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:39:00.164Z,1569436740.164 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:39:18.751Z,1569436758.751 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:39:18.751Z,1569436758.751 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:39:36.523Z,1569436776.523 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:39:36.524Z,1569436776.524 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:41:00.558Z,1569436860.558 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T18:41:30.086Z,1569436890.086 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:41:30.087Z,1569436890.087 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:41:30.087Z,1569436890.087 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:41:30.087Z,1569436890.087 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:41:30.484Z,1569436890.484 [Default:CheckIn:D] Stopped 2019-09-25T18:41:30.485Z,1569436890.485 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:41:30.894Z,1569436890.894 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 88.020410 min 2019-09-25T18:41:30.894Z,1569436890.894 [Default:CheckIn:E] Stopped 2019-09-25T18:41:30.894Z,1569436890.894 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:41:30.894Z,1569436890.894 [Default:CheckIn] Stopped 2019-09-25T18:41:30.894Z,1569436890.894 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:41:30.895Z,1569436890.895 [Default:CheckIn](INFO): Running loop #16 2019-09-25T18:41:30.895Z,1569436890.895 [Default:CheckIn] Running Loop=16 2019-09-25T18:41:30.895Z,1569436890.895 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:41:30.895Z,1569436890.895 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:41:31.262Z,1569436891.262 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:41:32.485Z,1569436892.485 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:41:32.880Z,1569436892.880 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184134.00,A,3648.17122,N,12147.28156,W,0.194,203.71,250919,,,A*7D 2019-09-25T18:41:32.882Z,1569436892.882 [NAL9602](INFO): GPS fix at 20190925T184134: (36.802854, -121.788026) 2019-09-25T18:41:32.934Z,1569436892.934 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:41:32.934Z,1569436892.934 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:41:42.217Z,1569436902.217 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190925T173233/Courier0036.lzma 2019-09-25T18:41:44.222Z,1569436904.222 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0036.lzma.bak 2019-09-25T18:41:44.223Z,1569436904.223 [DataOverHttps](INFO): SBD MOMSN=11815801 2019-09-25T18:42:03.582Z,1569436923.582 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-25T18:42:03.657Z,1569436923.657 [NAL9602](FAULT): received: +CSQ:0 OK82, 2, 0, 0, 0 OK 2019-09-25T18:42:03.657Z,1569436923.657 [NAL9602] Data Fault, FailCount= 1 2019-09-25T18:42:03.657Z,1569436923.657 [NAL9602](ERROR): Data Fault 2019-09-25T18:42:03.734Z,1569436923.734 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T18:42:03.986Z,1569436923.986 [NAL9602](INFO): Powering down 2019-09-25T18:42:04.851Z,1569436924.851 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T18:42:04.851Z,1569436924.851 [NAL9602] No Fault, FailCount= 1 2019-09-25T18:42:09.157Z,1569436929.157 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190925T173233/Express0037.lzma 2019-09-25T18:42:11.162Z,1569436931.162 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0037.lzma.bak 2019-09-25T18:42:11.163Z,1569436931.163 [DataOverHttps](INFO): SBD MOMSN=11815805 2019-09-25T18:42:12.512Z,1569436932.512 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:42:12.512Z,1569436932.512 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:42:12.512Z,1569436932.512 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:42:34.286Z,1569436954.286 [NAL9602](INFO): Powering up NAL9602 2019-09-25T18:42:45.188Z,1569436965.188 [NAL9602](INFO): NAL9602 initialized 2019-09-25T18:43:16.302Z,1569436996.302 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:44:36.761Z,1569437076.761 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-25T18:44:36.761Z,1569437076.761 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-3:BE,-32768,-32768,-32768,V 2019-09-25T18:47:13.075Z,1569437233.075 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:47:13.075Z,1569437233.075 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:47:13.075Z,1569437233.075 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:47:13.076Z,1569437233.076 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:47:13.480Z,1569437233.480 [Default:CheckIn:D] Stopped 2019-09-25T18:47:13.480Z,1569437233.480 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:47:13.933Z,1569437233.933 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 93.736995 min 2019-09-25T18:47:13.933Z,1569437233.933 [Default:CheckIn:E] Stopped 2019-09-25T18:47:13.933Z,1569437233.933 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:47:13.933Z,1569437233.933 [Default:CheckIn] Stopped 2019-09-25T18:47:13.934Z,1569437233.934 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:47:13.934Z,1569437233.934 [Default:CheckIn](INFO): Running loop #17 2019-09-25T18:47:13.934Z,1569437233.934 [Default:CheckIn] Running Loop=17 2019-09-25T18:47:13.934Z,1569437233.934 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:47:13.934Z,1569437233.934 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:47:15.481Z,1569437235.481 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:47:15.876Z,1569437235.876 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184717.00,A,3648.16818,N,12147.27983,W,0.292,341.22,250919,,,A*70 2019-09-25T18:47:15.878Z,1569437235.878 [NAL9602](INFO): GPS fix at 20190925T184717: (36.802803, -121.787997) 2019-09-25T18:47:15.921Z,1569437235.921 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:47:15.921Z,1569437235.921 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:47:17.486Z,1569437237.486 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T18:47:23.984Z,1569437243.984 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0039.lzma 2019-09-25T18:47:35.028Z,1569437255.028 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0039.lzma.bak 2019-09-25T18:47:35.028Z,1569437255.028 [DataOverHttps](INFO): SBD MOMSN=11815817 2019-09-25T18:47:48.190Z,1569437268.190 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T18:47:52.677Z,1569437272.677 [DataOverHttps](INFO): Sending 161 bytes from file Logs/20190925T173233/Express0040.lzma 2019-09-25T18:47:54.683Z,1569437274.683 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0040.lzma.bak 2019-09-25T18:47:54.683Z,1569437274.683 [DataOverHttps](INFO): SBD MOMSN=11815820 2019-09-25T18:47:56.323Z,1569437276.323 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:47:56.324Z,1569437276.324 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:47:56.324Z,1569437276.324 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:52:56.891Z,1569437576.891 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:52:56.891Z,1569437576.891 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:52:56.891Z,1569437576.891 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:52:56.891Z,1569437576.891 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:52:57.277Z,1569437577.277 [Default:CheckIn:D] Stopped 2019-09-25T18:52:57.277Z,1569437577.277 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:52:57.683Z,1569437577.683 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 99.466951 min 2019-09-25T18:52:57.683Z,1569437577.683 [Default:CheckIn:E] Stopped 2019-09-25T18:52:57.683Z,1569437577.683 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:52:57.683Z,1569437577.683 [Default:CheckIn] Stopped 2019-09-25T18:52:57.683Z,1569437577.683 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:52:57.684Z,1569437577.684 [Default:CheckIn](INFO): Running loop #18 2019-09-25T18:52:57.684Z,1569437577.684 [Default:CheckIn] Running Loop=18 2019-09-25T18:52:57.684Z,1569437577.684 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:52:57.684Z,1569437577.684 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:52:59.289Z,1569437579.289 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:52:59.702Z,1569437579.702 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185301.00,A,3648.16711,N,12147.27590,W,0.175,341.22,250919,,,A*70 2019-09-25T18:52:59.709Z,1569437579.709 [NAL9602](INFO): GPS fix at 20190925T185301: (36.802785, -121.787932) 2019-09-25T18:52:59.762Z,1569437579.762 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:52:59.762Z,1569437579.762 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:53:06.892Z,1569437586.892 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0042.lzma 2019-09-25T18:53:08.898Z,1569437588.898 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0042.lzma.bak 2019-09-25T18:53:08.899Z,1569437588.899 [DataOverHttps](INFO): SBD MOMSN=11815842 2019-09-25T18:53:26.582Z,1569437606.582 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190925T173233/Express0043.lzma 2019-09-25T18:53:28.470Z,1569437608.470 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0043.lzma.bak 2019-09-25T18:53:28.471Z,1569437608.471 [DataOverHttps](INFO): SBD MOMSN=11815845 2019-09-25T18:53:30.009Z,1569437610.009 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:53:30.009Z,1569437610.009 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:53:30.009Z,1569437610.009 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:53:40.097Z,1569437620.097 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T18:53:40.097Z,1569437620.097 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092518544597,35.0, -0.,1448.9, 0 2019-09-25T18:58:15.200Z,1569437895.200 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T18:58:15.200Z,1569437895.200 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T18:58:15.602Z,1569437895.602 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T18:58:30.620Z,1569437910.620 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T18:58:30.620Z,1569437910.620 [Default:CheckIn:C.Wait] Stopped 2019-09-25T18:58:30.620Z,1569437910.620 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T18:58:30.621Z,1569437910.621 [Default:CheckIn:D] Running Loop=1 2019-09-25T18:58:31.048Z,1569437911.048 [Default:CheckIn:D] Stopped 2019-09-25T18:58:31.048Z,1569437911.048 [Default:CheckIn:E] Running Loop=1 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 105.029801 min 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn:E] Stopped 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn] Stopped 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn](INFO): Running loop #19 2019-09-25T18:58:31.428Z,1569437911.428 [Default:CheckIn] Running Loop=19 2019-09-25T18:58:31.429Z,1569437911.429 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T18:58:31.429Z,1569437911.429 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T18:58:33.025Z,1569437913.025 [NAL9602](DEBUG): Fix Requested 2019-09-25T18:58:33.420Z,1569437913.420 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185835.00,A,3648.16378,N,12147.27783,W,0.136,206.24,250919,,,A*74 2019-09-25T18:58:33.431Z,1569437913.431 [NAL9602](INFO): GPS fix at 20190925T185835: (36.802730, -121.787964) 2019-09-25T18:58:33.455Z,1569437913.455 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T18:58:33.455Z,1569437913.455 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T18:58:41.176Z,1569437921.176 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0045.lzma 2019-09-25T18:58:43.182Z,1569437923.182 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0045.lzma.bak 2019-09-25T18:58:43.183Z,1569437923.183 [DataOverHttps](INFO): SBD MOMSN=11815857 2019-09-25T18:59:00.533Z,1569437940.533 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190925T173233/Express0046.lzma 2019-09-25T18:59:02.539Z,1569437942.539 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0046.lzma.bak 2019-09-25T18:59:02.539Z,1569437942.539 [DataOverHttps](INFO): SBD MOMSN=11815860 2019-09-25T18:59:04.186Z,1569437944.186 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T18:59:04.186Z,1569437944.186 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T18:59:04.186Z,1569437944.186 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T18:59:05.734Z,1569437945.734 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:04:04.765Z,1569438244.765 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:04:04.765Z,1569438244.765 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:04:04.765Z,1569438244.765 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:04:04.766Z,1569438244.766 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:04:05.183Z,1569438245.183 [Default:CheckIn:D] Stopped 2019-09-25T19:04:05.183Z,1569438245.183 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:04:05.561Z,1569438245.561 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 110.598722 min 2019-09-25T19:04:05.561Z,1569438245.561 [Default:CheckIn:E] Stopped 2019-09-25T19:04:05.561Z,1569438245.561 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:04:05.561Z,1569438245.561 [Default:CheckIn] Stopped 2019-09-25T19:04:05.561Z,1569438245.561 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:04:05.562Z,1569438245.562 [Default:CheckIn](INFO): Running loop #20 2019-09-25T19:04:05.562Z,1569438245.562 [Default:CheckIn] Running Loop=20 2019-09-25T19:04:05.562Z,1569438245.562 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:04:05.562Z,1569438245.562 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:04:07.169Z,1569438247.169 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:04:07.554Z,1569438247.554 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190409.00,A,3648.17117,N,12147.28391,W,0.117,206.24,250919,,,A*72 2019-09-25T19:04:07.556Z,1569438247.556 [NAL9602](INFO): GPS fix at 20190925T190409: (36.802853, -121.788065) 2019-09-25T19:04:07.596Z,1569438247.596 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:04:07.596Z,1569438247.596 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:04:14.948Z,1569438254.948 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190925T173233/Courier0048.lzma 2019-09-25T19:04:16.954Z,1569438256.954 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0048.lzma.bak 2019-09-25T19:04:16.955Z,1569438256.955 [DataOverHttps](INFO): SBD MOMSN=11815880 2019-09-25T19:04:35.444Z,1569438275.444 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190925T173233/Express0049.lzma 2019-09-25T19:04:37.450Z,1569438277.450 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0049.lzma.bak 2019-09-25T19:04:37.451Z,1569438277.451 [DataOverHttps](INFO): SBD MOMSN=11815883 2019-09-25T19:04:39.120Z,1569438279.120 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:04:39.121Z,1569438279.121 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:04:39.121Z,1569438279.121 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:04:57.732Z,1569438297.732 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-25T19:04:57.732Z,1569438297.732 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3278,V 2019-09-25T19:08:02.328Z,1569438482.328 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T19:08:02.329Z,1569438482.329 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T19:08:37.862Z,1569438517.862 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T19:08:37.863Z,1569438517.863 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T19:09:25.535Z,1569438565.535 [NAL9602](INFO): SBD MO Status=2, MOMSN=1882, MT Status=2, MTMSN=0 2019-09-25T19:09:25.536Z,1569438565.536 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-25T19:09:25.942Z,1569438565.942 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T19:09:39.740Z,1569438579.740 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:09:39.741Z,1569438579.741 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:09:39.741Z,1569438579.741 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:09:39.741Z,1569438579.741 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:09:40.101Z,1569438580.101 [Default:CheckIn:D] Stopped 2019-09-25T19:09:40.101Z,1569438580.101 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:09:40.508Z,1569438580.508 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 116.180672 min 2019-09-25T19:09:40.508Z,1569438580.508 [Default:CheckIn:E] Stopped 2019-09-25T19:09:40.508Z,1569438580.508 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:09:40.508Z,1569438580.508 [Default:CheckIn] Stopped 2019-09-25T19:09:40.509Z,1569438580.509 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:09:40.509Z,1569438580.509 [Default:CheckIn](INFO): Running loop #21 2019-09-25T19:09:40.509Z,1569438580.509 [Default:CheckIn] Running Loop=21 2019-09-25T19:09:40.509Z,1569438580.509 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:09:40.509Z,1569438580.509 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:09:42.113Z,1569438582.113 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:09:42.502Z,1569438582.502 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190944.00,A,3648.16835,N,12147.28025,W,0.156,0.00,250919,,,A*75 2019-09-25T19:09:42.504Z,1569438582.504 [NAL9602](INFO): GPS fix at 20190925T190944: (36.802806, -121.788004) 2019-09-25T19:09:42.546Z,1569438582.546 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:09:42.547Z,1569438582.547 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:09:50.096Z,1569438590.096 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0051.lzma 2019-09-25T19:09:52.102Z,1569438592.102 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0051.lzma.bak 2019-09-25T19:09:52.103Z,1569438592.103 [DataOverHttps](INFO): SBD MOMSN=11815890 2019-09-25T19:10:09.501Z,1569438609.501 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190925T173233/Express0052.lzma 2019-09-25T19:10:11.507Z,1569438611.507 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0052.lzma.bak 2019-09-25T19:10:11.507Z,1569438611.507 [DataOverHttps](INFO): SBD MOMSN=11815893 2019-09-25T19:10:13.238Z,1569438613.238 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:10:13.238Z,1569438613.238 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:10:13.238Z,1569438613.238 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:10:14.826Z,1569438614.826 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:15:13.829Z,1569438913.829 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:15:13.829Z,1569438913.829 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:15:13.829Z,1569438913.829 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:15:13.829Z,1569438913.829 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:15:14.241Z,1569438914.241 [Default:CheckIn:D] Stopped 2019-09-25T19:15:14.241Z,1569438914.241 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:15:14.627Z,1569438914.627 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 121.749691 min 2019-09-25T19:15:14.627Z,1569438914.627 [Default:CheckIn:E] Stopped 2019-09-25T19:15:14.627Z,1569438914.627 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn] Stopped 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn](INFO): Running loop #22 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn] Running Loop=22 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:15:14.628Z,1569438914.628 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:15:16.233Z,1569438916.233 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:15:16.640Z,1569438916.640 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191518.00,A,3648.16669,N,12147.28791,W,1.400,0.00,250919,,,A*79 2019-09-25T19:15:16.643Z,1569438916.643 [NAL9602](INFO): GPS fix at 20190925T191518: (36.802778, -121.788132) 2019-09-25T19:15:16.670Z,1569438916.670 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:15:16.670Z,1569438916.670 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:15:24.068Z,1569438924.068 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0054.lzma 2019-09-25T19:15:26.074Z,1569438926.074 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0054.lzma.bak 2019-09-25T19:15:26.075Z,1569438926.075 [DataOverHttps](INFO): SBD MOMSN=11815913 2019-09-25T19:15:43.536Z,1569438943.536 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190925T173233/Express0055.lzma 2019-09-25T19:15:45.543Z,1569438945.543 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0055.lzma.bak 2019-09-25T19:15:45.543Z,1569438945.543 [DataOverHttps](INFO): SBD MOMSN=11815916 2019-09-25T19:15:46.966Z,1569438946.966 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:15:46.967Z,1569438946.967 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:15:46.967Z,1569438946.967 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:20:18.902Z,1569439218.902 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T19:20:47.620Z,1569439247.620 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:20:47.620Z,1569439247.620 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:20:47.620Z,1569439247.620 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:20:47.620Z,1569439247.620 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:20:48.066Z,1569439248.066 [Default:CheckIn:D] Stopped 2019-09-25T19:20:48.066Z,1569439248.066 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:20:48.428Z,1569439248.428 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 127.313436 min 2019-09-25T19:20:48.428Z,1569439248.428 [Default:CheckIn:E] Stopped 2019-09-25T19:20:48.428Z,1569439248.428 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:20:48.428Z,1569439248.428 [Default:CheckIn] Stopped 2019-09-25T19:20:48.428Z,1569439248.428 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:20:48.429Z,1569439248.429 [Default:CheckIn](INFO): Running loop #23 2019-09-25T19:20:48.429Z,1569439248.429 [Default:CheckIn] Running Loop=23 2019-09-25T19:20:48.429Z,1569439248.429 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:20:48.429Z,1569439248.429 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:20:50.033Z,1569439250.033 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:20:50.416Z,1569439250.416 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192052.00,A,3648.17636,N,12147.28820,W,0.758,0.00,250919,,,A*70 2019-09-25T19:20:50.418Z,1569439250.418 [NAL9602](INFO): GPS fix at 20190925T192052: (36.802939, -121.788137) 2019-09-25T19:20:50.460Z,1569439250.460 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:20:50.460Z,1569439250.460 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:21:03.389Z,1569439263.389 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190925T173233/Courier0057.lzma 2019-09-25T19:21:05.395Z,1569439265.395 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0057.lzma.bak 2019-09-25T19:21:05.395Z,1569439265.395 [DataOverHttps](INFO): SBD MOMSN=11815957 2019-09-25T19:21:22.870Z,1569439282.870 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:21:33.469Z,1569439293.469 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190925T173233/Express0058.lzma 2019-09-25T19:21:35.475Z,1569439295.475 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0058.lzma.bak 2019-09-25T19:21:35.475Z,1569439295.475 [DataOverHttps](INFO): SBD MOMSN=11815960 2019-09-25T19:21:37.456Z,1569439297.456 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:21:37.456Z,1569439297.456 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:21:37.457Z,1569439297.457 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:26:38.065Z,1569439598.065 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:26:38.065Z,1569439598.065 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:26:38.065Z,1569439598.065 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:26:38.065Z,1569439598.065 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:26:38.443Z,1569439598.443 [Default:CheckIn:D] Stopped 2019-09-25T19:26:38.443Z,1569439598.443 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:26:38.877Z,1569439598.877 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 133.153044 min 2019-09-25T19:26:38.877Z,1569439598.877 [Default:CheckIn:E] Stopped 2019-09-25T19:26:38.877Z,1569439598.877 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:26:38.877Z,1569439598.877 [Default:CheckIn] Stopped 2019-09-25T19:26:38.878Z,1569439598.878 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:26:38.878Z,1569439598.878 [Default:CheckIn](INFO): Running loop #24 2019-09-25T19:26:38.878Z,1569439598.878 [Default:CheckIn] Running Loop=24 2019-09-25T19:26:38.878Z,1569439598.878 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:26:38.878Z,1569439598.878 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:26:40.436Z,1569439600.436 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:26:40.824Z,1569439600.824 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192642.00,A,3648.16975,N,12147.27919,W,0.875,165.82,250919,,,A*72 2019-09-25T19:26:40.826Z,1569439600.826 [NAL9602](INFO): GPS fix at 20190925T192642: (36.802829, -121.787987) 2019-09-25T19:26:40.916Z,1569439600.916 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:26:40.916Z,1569439600.916 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:26:53.413Z,1569439613.413 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190925T173233/Courier0060.lzma 2019-09-25T19:26:55.419Z,1569439615.419 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0060.lzma.bak 2019-09-25T19:26:55.419Z,1569439615.419 [DataOverHttps](INFO): SBD MOMSN=11815965 2019-09-25T19:27:01.073Z,1569439621.073 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T19:27:01.073Z,1569439621.073 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092519280697,35.0, -0.,1448.9, 0 2019-09-25T19:27:11.546Z,1569439631.546 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-25T19:27:11.629Z,1569439631.629 [NAL9602](FAULT): received: +CSQ:0 OK82, 2, 0, 0, 0 OK 2019-09-25T19:27:11.629Z,1569439631.629 [NAL9602] Data Fault, FailCount= 1 2019-09-25T19:27:11.629Z,1569439631.629 [NAL9602](ERROR): Data Fault 2019-09-25T19:27:11.768Z,1569439631.768 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T19:27:11.958Z,1569439631.958 [NAL9602](INFO): Powering down 2019-09-25T19:27:12.354Z,1569439632.354 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2019-09-25T19:27:12.354Z,1569439632.354 [NAL9602] Hardware Fault, FailCount= 1 2019-09-25T19:27:12.354Z,1569439632.354 [NAL9602](ERROR): Hardware Fault 2019-09-25T19:27:12.914Z,1569439632.914 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T19:27:12.914Z,1569439632.914 [NAL9602] No Fault, FailCount= 1 2019-09-25T19:27:23.797Z,1569439643.797 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190925T173233/Express0061.lzma 2019-09-25T19:27:25.803Z,1569439645.803 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0061.lzma.bak 2019-09-25T19:27:25.803Z,1569439645.803 [DataOverHttps](INFO): SBD MOMSN=11815968 2019-09-25T19:27:27.785Z,1569439647.785 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:27:27.786Z,1569439647.786 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:27:27.786Z,1569439647.786 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:27:42.250Z,1569439662.250 [NAL9602](INFO): Powering up NAL9602 2019-09-25T19:27:53.162Z,1569439673.162 [NAL9602](INFO): NAL9602 initialized 2019-09-25T19:28:24.271Z,1569439704.271 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:29:41.225Z,1569439781.225 [CommandLine](IMPORTANT): got command show variable acoustic 2019-09-25T19:29:41.316Z,1569439781.316 [CommandLine](IMPORTANT): acoustic_receive_time (epoch_second) 2019-09-25T19:29:41.316Z,1569439781.316 [CommandLine](IMPORTANT): acoustic_transmit_time (epoch_second) 2019-09-25T19:29:41.316Z,1569439781.316 [CommandLine](IMPORTANT): acoustic_contact_direction_vehicle_frame (unknown) 2019-09-25T19:29:41.317Z,1569439781.317 [CommandLine](IMPORTANT): acoustic_contact_address (unknown) 2019-09-25T19:29:41.317Z,1569439781.317 [CommandLine](IMPORTANT): acoustic_contact_range (unknown) 2019-09-25T19:29:41.340Z,1569439781.340 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool) 2019-09-25T19:29:41.341Z,1569439781.341 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.simulateHardware (bool) 2019-09-25T19:29:41.341Z,1569439781.341 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count) 2019-09-25T19:29:41.342Z,1569439781.342 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.verbosity (count) 2019-09-25T19:29:41.350Z,1569439781.350 [CommandLine](IMPORTANT): Rowe_600.acousticBlankingDistance (meter) 2019-09-25T19:29:41.527Z,1569439781.527 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadControl (none) 2019-09-25T19:29:41.527Z,1569439781.527 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.uart (none) 2019-09-25T19:29:41.528Z,1569439781.528 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.baud (bit_per_second) 2019-09-25T19:29:41.651Z,1569439781.651 [CommandLine](IMPORTANT): DAT.acoustic_receive_time (epoch_second) 2019-09-25T19:29:41.652Z,1569439781.652 [CommandLine](IMPORTANT): DAT.acoustic_transmit_time (epoch_second) 2019-09-25T19:29:41.676Z,1569439781.676 [CommandLine](IMPORTANT): DAT.acoustic_wakeup (count) 2019-09-25T19:32:28.336Z,1569439948.336 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:32:28.336Z,1569439948.336 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:32:28.336Z,1569439948.336 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:32:28.336Z,1569439948.336 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:32:28.757Z,1569439948.757 [Default:CheckIn:D] Stopped 2019-09-25T19:32:28.757Z,1569439948.757 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:32:29.153Z,1569439949.153 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 138.991618 min 2019-09-25T19:32:29.153Z,1569439949.153 [Default:CheckIn:E] Stopped 2019-09-25T19:32:29.153Z,1569439949.153 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:32:29.153Z,1569439949.153 [Default:CheckIn] Stopped 2019-09-25T19:32:29.153Z,1569439949.153 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:32:29.154Z,1569439949.154 [Default:CheckIn](INFO): Running loop #25 2019-09-25T19:32:29.154Z,1569439949.154 [Default:CheckIn] Running Loop=25 2019-09-25T19:32:29.154Z,1569439949.154 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:32:29.154Z,1569439949.154 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:32:30.753Z,1569439950.753 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:33.554Z,1569439953.554 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T19:32:34.373Z,1569439954.373 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:36.809Z,1569439956.809 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:40.032Z,1569439960.032 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:42.861Z,1569439962.861 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:45.689Z,1569439965.689 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:47.725Z,1569439967.725 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:50.937Z,1569439970.937 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:53.765Z,1569439973.765 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:56.997Z,1569439976.997 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:32:59.829Z,1569439979.829 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:02.653Z,1569439982.653 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:04.697Z,1569439984.697 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:06.713Z,1569439986.713 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:09.929Z,1569439989.929 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:12.777Z,1569439992.777 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:15.989Z,1569439995.989 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:18.825Z,1569439998.825 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:22.045Z,1569440002.045 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:24.873Z,1569440004.873 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:27.723Z,1569440007.723 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:30.937Z,1569440010.937 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:33.761Z,1569440013.761 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:36.997Z,1569440016.997 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:39.821Z,1569440019.821 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:42.661Z,1569440022.661 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:44.673Z,1569440024.673 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:46.718Z,1569440026.718 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:49.921Z,1569440029.921 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:52.777Z,1569440032.777 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:55.985Z,1569440035.985 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:33:56.424Z,1569440036.424 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T19:33:56.424Z,1569440036.424 [RDI_Pathfinder](ERROR): Failed to parse: :TS,190925193501 -0.1, 0.0,1448.9, 0 2019-09-25T19:33:58.813Z,1569440038.813 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:02.043Z,1569440042.043 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:04.873Z,1569440044.873 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:07.719Z,1569440047.719 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:10.937Z,1569440050.937 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:13.761Z,1569440053.761 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:16.993Z,1569440056.993 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:19.829Z,1569440059.829 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:22.645Z,1569440062.645 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:24.669Z,1569440064.669 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:26.712Z,1569440066.712 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:29.921Z,1569440069.921 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:32.777Z,1569440072.777 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:35.989Z,1569440075.989 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:38.805Z,1569440078.805 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:42.041Z,1569440082.041 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:44.865Z,1569440084.865 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:47.717Z,1569440087.717 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:50.925Z,1569440090.925 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:53.757Z,1569440093.757 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:56.988Z,1569440096.988 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:34:59.817Z,1569440099.817 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:02.645Z,1569440102.645 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:04.669Z,1569440104.669 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:06.709Z,1569440106.709 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:09.925Z,1569440109.925 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:12.765Z,1569440112.765 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:15.977Z,1569440115.977 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:18.805Z,1569440118.805 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:22.037Z,1569440122.037 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:24.865Z,1569440124.865 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:27.717Z,1569440127.717 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:30.925Z,1569440130.925 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:33.749Z,1569440133.749 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:36.985Z,1569440136.985 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:39.813Z,1569440139.813 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:43.044Z,1569440143.044 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:45.873Z,1569440145.873 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:48.724Z,1569440148.724 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:51.933Z,1569440151.933 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:54.761Z,1569440154.761 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:35:57.989Z,1569440157.989 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:00.821Z,1569440160.821 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:03.645Z,1569440163.645 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:05.669Z,1569440165.669 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:07.713Z,1569440167.713 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:10.917Z,1569440170.917 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:13.753Z,1569440173.753 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:16.985Z,1569440176.985 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:19.813Z,1569440179.813 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:23.061Z,1569440183.061 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:25.869Z,1569440185.869 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:28.721Z,1569440188.721 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:31.928Z,1569440191.928 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:34.761Z,1569440194.761 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:37.985Z,1569440197.985 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:40.817Z,1569440200.817 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:43.645Z,1569440203.645 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:45.665Z,1569440205.665 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:47.713Z,1569440207.713 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:49.713Z,1569440209.713 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:52.933Z,1569440212.933 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:55.761Z,1569440215.761 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:36:58.999Z,1569440218.999 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:01.821Z,1569440221.821 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:04.653Z,1569440224.653 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:06.685Z,1569440226.685 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:08.713Z,1569440228.713 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:11.925Z,1569440231.925 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:14.749Z,1569440234.749 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:17.981Z,1569440237.981 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:20.813Z,1569440240.813 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:24.045Z,1569440244.045 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:26.873Z,1569440246.873 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:29.324Z,1569440249.324 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T19:32:29.2Z 2019-09-25T19:37:29.324Z,1569440249.324 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:37:29.324Z,1569440249.324 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:37:29.712Z,1569440249.712 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:37:45.356Z,1569440265.356 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0063.lzma 2019-09-25T19:37:47.362Z,1569440267.362 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0063.lzma.bak 2019-09-25T19:37:47.363Z,1569440267.363 [DataOverHttps](INFO): SBD MOMSN=11815975 2019-09-25T19:38:02.814Z,1569440282.814 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:38:04.933Z,1569440284.933 [DataOverHttps](INFO): Sending 578 bytes from file Logs/20190925T173233/Express0064.lzma 2019-09-25T19:38:06.939Z,1569440286.939 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0064.lzma.bak 2019-09-25T19:38:06.939Z,1569440286.939 [DataOverHttps](INFO): SBD MOMSN=11815977 2019-09-25T19:38:08.504Z,1569440288.504 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:38:08.504Z,1569440288.504 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:38:08.504Z,1569440288.504 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:41:08.702Z,1569440468.702 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-25T19:41:08.702Z,1569440468.702 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3268,-32768,V 2019-09-25T19:42:24.230Z,1569440544.230 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-09-25T19:43:09.072Z,1569440589.072 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:43:09.072Z,1569440589.072 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:43:09.073Z,1569440589.073 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:43:09.073Z,1569440589.073 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:43:09.477Z,1569440589.477 [Default:CheckIn:D] Stopped 2019-09-25T19:43:09.477Z,1569440589.477 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:43:09.898Z,1569440589.898 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 149.670280 min 2019-09-25T19:43:09.898Z,1569440589.898 [Default:CheckIn:E] Stopped 2019-09-25T19:43:09.898Z,1569440589.898 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:43:09.898Z,1569440589.898 [Default:CheckIn] Stopped 2019-09-25T19:43:09.898Z,1569440589.898 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:43:09.899Z,1569440589.899 [Default:CheckIn](INFO): Running loop #26 2019-09-25T19:43:09.899Z,1569440589.899 [Default:CheckIn] Running Loop=26 2019-09-25T19:43:09.899Z,1569440589.899 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:43:09.899Z,1569440589.899 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:43:11.474Z,1569440591.474 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T19:43:11.474Z,1569440591.474 [NAL9602] Data Fault, FailCount= 1 2019-09-25T19:43:11.474Z,1569440591.474 [NAL9602](ERROR): Data Fault 2019-09-25T19:43:11.533Z,1569440591.533 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T19:43:11.872Z,1569440591.872 [NAL9602](INFO): Powering down 2019-09-25T19:43:12.757Z,1569440592.757 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T19:43:12.757Z,1569440592.757 [NAL9602] No Fault, FailCount= 1 2019-09-25T19:43:42.178Z,1569440622.178 [NAL9602](INFO): Powering up NAL9602 2019-09-25T19:43:49.085Z,1569440629.085 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-09-25T19:43:53.086Z,1569440633.086 [NAL9602](INFO): NAL9602 initialized 2019-09-25T19:43:53.905Z,1569440633.905 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:44:25.084Z,1569440665.084 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-09-25T19:44:25.087Z,1569440665.087 [BPC1](INFO): Received data from all battery sticks. 2019-09-25T19:45:49.061Z,1569440749.061 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-25T19:45:49.061Z,1569440749.061 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-09-25T19:48:10.064Z,1569440890.064 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T19:43:09.9Z 2019-09-25T19:48:10.064Z,1569440890.064 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:48:10.064Z,1569440890.064 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:48:31.062Z,1569440911.062 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-09-25T19:48:31.063Z,1569440911.063 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 2019-09-25T19:48:42.533Z,1569440922.533 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-25T19:48:49.545Z,1569440929.545 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=61.247681 2019-09-25T19:48:56.490Z,1569440936.490 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T19:48:58.205Z,1569440938.205 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003377 2019-09-25T19:49:05.929Z,1569440945.929 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20190925T173233/Courier0066.lzma 2019-09-25T19:49:07.935Z,1569440947.935 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0066.lzma.bak 2019-09-25T19:49:07.935Z,1569440947.935 [DataOverHttps](INFO): SBD MOMSN=11816019 2019-09-25T19:49:25.476Z,1569440965.476 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190925T173233/Express0067.lzma 2019-09-25T19:49:27.483Z,1569440967.483 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0067.lzma.bak 2019-09-25T19:49:27.483Z,1569440967.483 [DataOverHttps](INFO): SBD MOMSN=11816023 2019-09-25T19:49:28.847Z,1569440968.847 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T19:49:28.847Z,1569440968.847 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T19:49:28.847Z,1569440968.847 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T19:49:31.634Z,1569440971.634 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T19:54:29.437Z,1569441269.437 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T19:54:29.437Z,1569441269.437 [Default:CheckIn:C.Wait] Stopped 2019-09-25T19:54:29.437Z,1569441269.437 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T19:54:29.438Z,1569441269.438 [Default:CheckIn:D] Running Loop=1 2019-09-25T19:54:29.859Z,1569441269.859 [Default:CheckIn:D] Stopped 2019-09-25T19:54:29.859Z,1569441269.859 [Default:CheckIn:E] Running Loop=1 2019-09-25T19:54:30.259Z,1569441270.259 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 161.009977 min 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn:E] Stopped 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn] Stopped 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn](INFO): Running loop #27 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn] Running Loop=27 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T19:54:30.260Z,1569441270.260 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T19:54:31.838Z,1569441271.838 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T19:54:31.838Z,1569441271.838 [NAL9602] Data Fault, FailCount= 2 2019-09-25T19:54:31.838Z,1569441271.838 [NAL9602](ERROR): Data Fault 2019-09-25T19:54:31.906Z,1569441271.906 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T19:54:32.242Z,1569441272.242 [NAL9602](INFO): Powering down 2019-09-25T19:54:33.103Z,1569441273.103 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T19:54:33.103Z,1569441273.103 [NAL9602] No Fault, FailCount= 2 2019-09-25T19:55:02.551Z,1569441302.551 [NAL9602](INFO): Powering up NAL9602 2019-09-25T19:55:13.454Z,1569441313.454 [NAL9602](INFO): NAL9602 initialized 2019-09-25T19:55:14.269Z,1569441314.269 [NAL9602](DEBUG): Fix Requested 2019-09-25T19:59:30.433Z,1569441570.433 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T19:54:30.3Z 2019-09-25T19:59:30.434Z,1569441570.434 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T19:59:30.434Z,1569441570.434 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T19:59:38.097Z,1569441578.097 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0069.lzma 2019-09-25T19:59:40.102Z,1569441580.102 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0069.lzma.bak 2019-09-25T19:59:40.103Z,1569441580.103 [DataOverHttps](INFO): SBD MOMSN=11816074 2019-09-25T19:59:57.622Z,1569441597.622 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20190925T173233/Express0070.lzma 2019-09-25T19:59:59.627Z,1569441599.627 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0070.lzma.bak 2019-09-25T19:59:59.627Z,1569441599.627 [DataOverHttps](INFO): SBD MOMSN=11816080 2019-09-25T20:00:01.144Z,1569441601.144 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:00:01.144Z,1569441601.144 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:00:01.144Z,1569441601.144 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:00:16.870Z,1569441616.870 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:00:47.567Z,1569441647.567 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:05:01.760Z,1569441901.760 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:05:01.760Z,1569441901.760 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:05:01.760Z,1569441901.760 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:05:01.761Z,1569441901.761 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:05:02.124Z,1569441902.124 [Default:CheckIn:D] Stopped 2019-09-25T20:05:02.124Z,1569441902.124 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:05:02.529Z,1569441902.529 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 171.547738 min 2019-09-25T20:05:02.529Z,1569441902.529 [Default:CheckIn:E] Stopped 2019-09-25T20:05:02.529Z,1569441902.529 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:05:02.529Z,1569441902.529 [Default:CheckIn] Stopped 2019-09-25T20:05:02.530Z,1569441902.530 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:05:02.530Z,1569441902.530 [Default:CheckIn](INFO): Running loop #28 2019-09-25T20:05:02.530Z,1569441902.530 [Default:CheckIn] Running Loop=28 2019-09-25T20:05:02.530Z,1569441902.530 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:05:02.530Z,1569441902.530 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:05:04.121Z,1569441904.121 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:05:35.218Z,1569441935.218 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-25T20:05:35.293Z,1569441935.293 [NAL9602](FAULT): received: +CSQ:0 OK82, 2, 0, 0, 0 OK 2019-09-25T20:05:35.293Z,1569441935.293 [NAL9602] Data Fault, FailCount= 3 2019-09-25T20:05:35.293Z,1569441935.293 [NAL9602](ERROR): Data Fault 2019-09-25T20:05:35.370Z,1569441935.370 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:05:35.627Z,1569441935.627 [NAL9602](INFO): Powering down 2019-09-25T20:05:36.482Z,1569441936.482 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:05:36.482Z,1569441936.482 [NAL9602] No Fault, FailCount= 3 2019-09-25T20:06:05.926Z,1569441965.926 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:06:16.828Z,1569441976.828 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:06:17.647Z,1569441977.647 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T20:06:17.647Z,1569441977.647 [NAL9602] Data Fault, FailCount= 4 2019-09-25T20:06:17.647Z,1569441977.647 [NAL9602](ERROR): Data Fault 2019-09-25T20:06:17.765Z,1569441977.765 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:06:18.042Z,1569441978.042 [NAL9602](INFO): Powering down 2019-09-25T20:06:18.941Z,1569441978.941 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:06:18.941Z,1569441978.941 [NAL9602] No Fault, FailCount= 4 2019-09-25T20:06:48.342Z,1569442008.342 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:06:59.254Z,1569442019.254 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:07:00.093Z,1569442020.093 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:10:02.737Z,1569442202.737 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:05:02.5Z 2019-09-25T20:10:02.737Z,1569442202.737 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T20:10:02.738Z,1569442202.738 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T20:10:06.306Z,1569442206.306 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:10:10.376Z,1569442210.376 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0072.lzma 2019-09-25T20:10:12.383Z,1569442212.383 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0072.lzma.bak 2019-09-25T20:10:12.383Z,1569442212.383 [DataOverHttps](INFO): SBD MOMSN=11816207 2019-09-25T20:10:30.185Z,1569442230.185 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20190925T173233/Express0073.lzma 2019-09-25T20:10:32.191Z,1569442232.191 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0073.lzma.bak 2019-09-25T20:10:32.191Z,1569442232.191 [DataOverHttps](INFO): SBD MOMSN=11816214 2019-09-25T20:10:33.833Z,1569442233.833 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:10:33.833Z,1569442233.833 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:10:33.833Z,1569442233.833 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:10:37.010Z,1569442237.010 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:14:00.675Z,1569442440.675 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-25T20:14:00.675Z,1569442440.675 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-3268,V 2019-09-25T20:15:34.390Z,1569442534.390 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:15:34.390Z,1569442534.390 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:15:34.390Z,1569442534.390 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:15:34.390Z,1569442534.390 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:15:34.784Z,1569442534.784 [Default:CheckIn:D] Stopped 2019-09-25T20:15:34.784Z,1569442534.784 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:15:35.200Z,1569442535.200 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 182.092074 min 2019-09-25T20:15:35.200Z,1569442535.200 [Default:CheckIn:E] Stopped 2019-09-25T20:15:35.200Z,1569442535.200 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:15:35.200Z,1569442535.200 [Default:CheckIn] Stopped 2019-09-25T20:15:35.200Z,1569442535.200 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:15:35.201Z,1569442535.201 [Default:CheckIn](INFO): Running loop #29 2019-09-25T20:15:35.201Z,1569442535.201 [Default:CheckIn] Running Loop=29 2019-09-25T20:15:35.201Z,1569442535.201 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:15:35.201Z,1569442535.201 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:15:36.797Z,1569442536.797 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:20:35.368Z,1569442835.368 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:15:35.2Z 2019-09-25T20:20:35.368Z,1569442835.368 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T20:20:35.368Z,1569442835.368 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T20:20:39.778Z,1569442839.778 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:20:42.764Z,1569442842.764 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0075.lzma 2019-09-25T20:20:44.771Z,1569442844.771 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0075.lzma.bak 2019-09-25T20:20:44.771Z,1569442844.771 [DataOverHttps](INFO): SBD MOMSN=11816235 2019-09-25T20:21:01.269Z,1569442861.269 [DataOverHttps](INFO): Sending 199 bytes from file Logs/20190925T173233/Express0076.lzma 2019-09-25T20:21:03.267Z,1569442863.267 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0076.lzma.bak 2019-09-25T20:21:03.267Z,1569442863.267 [DataOverHttps](INFO): SBD MOMSN=11816265 2019-09-25T20:21:04.860Z,1569442864.860 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:21:04.860Z,1569442864.860 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:21:04.860Z,1569442864.860 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:21:10.479Z,1569442870.479 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:26:05.453Z,1569443165.453 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:26:05.453Z,1569443165.453 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:26:05.453Z,1569443165.453 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:26:05.454Z,1569443165.454 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:26:05.844Z,1569443165.844 [Default:CheckIn:D] Stopped 2019-09-25T20:26:05.844Z,1569443165.844 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 192.609733 min 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn:E] Stopped 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn] Stopped 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn](INFO): Running loop #30 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn] Running Loop=30 2019-09-25T20:26:06.264Z,1569443166.264 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:26:06.265Z,1569443166.265 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:26:07.841Z,1569443167.841 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T20:26:07.842Z,1569443167.842 [NAL9602] Data Fault, FailCount= 5 2019-09-25T20:26:07.842Z,1569443167.842 [NAL9602](ERROR): Data Fault 2019-09-25T20:26:07.888Z,1569443167.888 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:26:07.909Z,1569443167.909 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-09-25T20:26:08.246Z,1569443168.246 [NAL9602](INFO): Powering down 2019-09-25T20:26:08.294Z,1569443168.294 [CommandLine](FAULT): Scheduling is paused 2019-09-25T20:26:08.294Z,1569443168.294 [CBIT](INFO): Critical error at 20190925T202607 2019-09-25T20:28:07.911Z,1569443287.911 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:28:07.911Z,1569443287.911 [NAL9602] No Fault, FailCount= 5 2019-09-25T20:28:08.262Z,1569443288.262 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:28:19.178Z,1569443299.178 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:28:19.989Z,1569443299.989 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:29:21.015Z,1569443361.015 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T20:29:21.016Z,1569443361.016 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092520302697,35.0, -0.1, 0.0,1448.9A, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T20:31:06.460Z,1569443466.460 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:26:06.3Z 2019-09-25T20:31:06.460Z,1569443466.460 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T20:31:06.460Z,1569443466.460 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T20:31:14.125Z,1569443474.125 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20190925T173233/Courier0078.lzma 2019-09-25T20:31:16.131Z,1569443476.131 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0078.lzma.bak 2019-09-25T20:31:16.131Z,1569443476.131 [DataOverHttps](INFO): SBD MOMSN=11816315 2019-09-25T20:31:37.558Z,1569443497.558 [DataOverHttps](INFO): Sending 238 bytes from file Logs/20190925T173233/Express0079.lzma 2019-09-25T20:31:39.563Z,1569443499.563 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0079.lzma.bak 2019-09-25T20:31:39.563Z,1569443499.563 [DataOverHttps](INFO): SBD MOMSN=11816321 2019-09-25T20:31:41.216Z,1569443501.216 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:31:41.216Z,1569443501.216 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:31:41.216Z,1569443501.216 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:32:12.732Z,1569443532.732 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-09-25T20:32:12.732Z,1569443532.732 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-2768,-32768,V 2019-09-25T20:33:22.578Z,1569443602.578 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:33:53.278Z,1569443633.278 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:36:41.790Z,1569443801.790 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:36:41.790Z,1569443801.790 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:36:41.791Z,1569443801.791 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:36:41.791Z,1569443801.791 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:36:42.203Z,1569443802.203 [Default:CheckIn:D] Stopped 2019-09-25T20:36:42.204Z,1569443802.204 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:36:42.577Z,1569443802.577 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 203.215723 min 2019-09-25T20:36:42.577Z,1569443802.577 [Default:CheckIn:E] Stopped 2019-09-25T20:36:42.577Z,1569443802.577 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:36:42.577Z,1569443802.577 [Default:CheckIn] Stopped 2019-09-25T20:36:42.578Z,1569443802.578 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:36:42.578Z,1569443802.578 [Default:CheckIn](INFO): Running loop #31 2019-09-25T20:36:42.578Z,1569443802.578 [Default:CheckIn] Running Loop=31 2019-09-25T20:36:42.578Z,1569443802.578 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:36:42.578Z,1569443802.578 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:36:44.185Z,1569443804.185 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:37:07.663Z,1569443827.663 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-25T20:37:07.663Z,1569443827.663 [RDI_Pathfinder](ERROR): Failed to parse: :BD, , +0.00, 0.00,8258.27 2019-09-25T20:38:47.818Z,1569443927.818 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T20:39:27.810Z,1569443967.810 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-09-25T20:39:48.013Z,1569443988.013 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T20:41:42.782Z,1569444102.782 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:36:42.6Z 2019-09-25T20:41:42.783Z,1569444102.783 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T20:41:42.783Z,1569444102.783 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T20:41:46.374Z,1569444106.374 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:41:50.892Z,1569444110.892 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0081.lzma 2019-09-25T20:41:52.915Z,1569444112.915 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0081.lzma.bak 2019-09-25T20:41:52.915Z,1569444112.915 [DataOverHttps](INFO): SBD MOMSN=11816381 2019-09-25T20:42:10.649Z,1569444130.649 [DataOverHttps](INFO): Sending 201 bytes from file Logs/20190925T173233/Express0082.lzma 2019-09-25T20:42:12.635Z,1569444132.635 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0082.lzma.bak 2019-09-25T20:42:12.635Z,1569444132.635 [DataOverHttps](INFO): SBD MOMSN=11816383 2019-09-25T20:42:14.268Z,1569444134.268 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:42:14.268Z,1569444134.268 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:42:14.268Z,1569444134.268 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:42:17.066Z,1569444137.066 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:47:14.841Z,1569444434.841 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:47:14.841Z,1569444434.841 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:47:14.841Z,1569444434.841 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:47:14.841Z,1569444434.841 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:47:15.258Z,1569444435.258 [Default:CheckIn:D] Stopped 2019-09-25T20:47:15.258Z,1569444435.258 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:47:15.656Z,1569444435.656 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 213.766634 min 2019-09-25T20:47:15.656Z,1569444435.656 [Default:CheckIn:E] Stopped 2019-09-25T20:47:15.656Z,1569444435.656 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:47:15.656Z,1569444435.656 [Default:CheckIn] Stopped 2019-09-25T20:47:15.656Z,1569444435.656 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:47:15.657Z,1569444435.657 [Default:CheckIn](INFO): Running loop #32 2019-09-25T20:47:15.657Z,1569444435.657 [Default:CheckIn] Running Loop=32 2019-09-25T20:47:15.657Z,1569444435.657 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:47:15.657Z,1569444435.657 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:47:17.242Z,1569444437.242 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T20:47:17.242Z,1569444437.242 [NAL9602] Data Fault, FailCount= 1 2019-09-25T20:47:17.242Z,1569444437.242 [NAL9602](ERROR): Data Fault 2019-09-25T20:47:17.304Z,1569444437.304 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:47:17.656Z,1569444437.656 [NAL9602](INFO): Powering down 2019-09-25T20:47:18.491Z,1569444438.491 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:47:18.492Z,1569444438.492 [NAL9602] No Fault, FailCount= 1 2019-09-25T20:47:47.940Z,1569444467.940 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:47:58.848Z,1569444478.848 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:47:59.673Z,1569444479.673 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:49:36.678Z,1569444576.678 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-25T20:49:36.678Z,1569444576.678 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, + +0.00, 0.00,9006.54 2019-09-25T20:50:03.706Z,1569444603.706 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file). 2019-09-25T20:51:03.613Z,1569444663.613 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-25T20:51:07.630Z,1569444667.630 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.244167 2019-09-25T20:51:17.705Z,1569444677.705 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003317 2019-09-25T20:51:54.808Z,1569444714.808 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-09-25T20:51:54.837Z,1569444714.837 [BPC1](INFO): Received data from all battery sticks. 2019-09-25T20:52:15.834Z,1569444735.834 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:47:15.7Z 2019-09-25T20:52:15.835Z,1569444735.835 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T20:52:15.835Z,1569444735.835 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T20:52:23.440Z,1569444743.440 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20190925T173233/Courier0084.lzma 2019-09-25T20:52:25.447Z,1569444745.447 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0084.lzma.bak 2019-09-25T20:52:25.447Z,1569444745.447 [DataOverHttps](INFO): SBD MOMSN=11816435 2019-09-25T20:52:43.005Z,1569444763.005 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20190925T173233/Express0085.lzma 2019-09-25T20:52:45.011Z,1569444765.011 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0085.lzma.bak 2019-09-25T20:52:45.011Z,1569444765.011 [DataOverHttps](INFO): SBD MOMSN=11816437 2019-09-25T20:52:46.532Z,1569444766.532 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T20:52:46.532Z,1569444766.532 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T20:52:46.532Z,1569444766.532 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T20:53:02.258Z,1569444782.258 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T20:53:32.962Z,1569444812.962 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T20:57:47.100Z,1569445067.100 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T20:57:47.100Z,1569445067.100 [Default:CheckIn:C.Wait] Stopped 2019-09-25T20:57:47.100Z,1569445067.100 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T20:57:47.101Z,1569445067.101 [Default:CheckIn:D] Running Loop=1 2019-09-25T20:57:47.508Z,1569445067.508 [Default:CheckIn:D] Stopped 2019-09-25T20:57:47.508Z,1569445067.508 [Default:CheckIn:E] Running Loop=1 2019-09-25T20:57:47.920Z,1569445067.920 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 224.304134 min 2019-09-25T20:57:47.920Z,1569445067.920 [Default:CheckIn:E] Stopped 2019-09-25T20:57:47.920Z,1569445067.920 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T20:57:47.920Z,1569445067.920 [Default:CheckIn] Stopped 2019-09-25T20:57:47.921Z,1569445067.921 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T20:57:47.921Z,1569445067.921 [Default:CheckIn](INFO): Running loop #33 2019-09-25T20:57:47.921Z,1569445067.921 [Default:CheckIn] Running Loop=33 2019-09-25T20:57:47.921Z,1569445067.921 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T20:57:47.921Z,1569445067.921 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T20:57:49.516Z,1569445069.516 [NAL9602](DEBUG): Fix Requested 2019-09-25T20:58:20.636Z,1569445100.636 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-25T20:58:20.709Z,1569445100.709 [NAL9602](FAULT): received: +CSQ:0 OK82, 2, 0, 0, 0 OK 2019-09-25T20:58:20.709Z,1569445100.709 [NAL9602] Data Fault, FailCount= 2 2019-09-25T20:58:20.709Z,1569445100.709 [NAL9602](ERROR): Data Fault 2019-09-25T20:58:20.799Z,1569445100.799 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:58:21.012Z,1569445101.012 [NAL9602](INFO): Powering down 2019-09-25T20:58:21.859Z,1569445101.859 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:58:21.859Z,1569445101.859 [NAL9602] No Fault, FailCount= 2 2019-09-25T20:58:41.667Z,1569445121.667 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-09-25T20:58:41.667Z,1569445121.667 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.00, , +0.00, 0.00,9551.00 2019-09-25T20:58:51.314Z,1569445131.314 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:59:02.218Z,1569445142.217 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:59:03.030Z,1569445143.030 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T20:59:03.030Z,1569445143.030 [NAL9602] Data Fault, FailCount= 3 2019-09-25T20:59:03.030Z,1569445143.030 [NAL9602](ERROR): Data Fault 2019-09-25T20:59:03.093Z,1569445143.093 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T20:59:03.434Z,1569445143.434 [NAL9602](INFO): Powering down 2019-09-25T20:59:04.278Z,1569445144.278 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T20:59:04.278Z,1569445144.278 [NAL9602] No Fault, FailCount= 3 2019-09-25T20:59:33.739Z,1569445173.739 [NAL9602](INFO): Powering up NAL9602 2019-09-25T20:59:44.638Z,1569445184.638 [NAL9602](INFO): NAL9602 initialized 2019-09-25T20:59:45.457Z,1569445185.457 [NAL9602](DEBUG): Fix Requested 2019-09-25T21:00:54.994Z,1569445254.994 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T21:00:54.994Z,1569445254.994 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092521020097,35.0, -0.1, 0.0,1448:RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T21:01:39.010Z,1569445299.010 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T21:01:39.010Z,1569445299.010 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092521024497,.1, 0.0,1448.9, 0 2019-09-25T21:02:19.805Z,1569445339.805 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-09-25T21:02:19.805Z,1569445339.805 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19092521032497.79 2019-09-25T21:02:48.089Z,1569445368.089 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T20:57:47.9Z 2019-09-25T21:02:48.089Z,1569445368.089 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T21:02:48.089Z,1569445368.089 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T21:02:52.498Z,1569445372.498 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T21:02:55.736Z,1569445375.736 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0087.lzma 2019-09-25T21:02:57.743Z,1569445377.743 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0087.lzma.bak 2019-09-25T21:02:57.743Z,1569445377.743 [DataOverHttps](INFO): SBD MOMSN=11816474 2019-09-25T21:03:15.285Z,1569445395.285 [DataOverHttps](INFO): Sending 252 bytes from file Logs/20190925T173233/Express0088.lzma 2019-09-25T21:03:17.291Z,1569445397.291 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0088.lzma.bak 2019-09-25T21:03:17.291Z,1569445397.291 [DataOverHttps](INFO): SBD MOMSN=11816476 2019-09-25T21:03:18.803Z,1569445398.803 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T21:03:18.803Z,1569445398.803 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T21:03:18.803Z,1569445398.803 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T21:03:23.202Z,1569445403.202 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T21:08:19.368Z,1569445699.368 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T21:08:19.368Z,1569445699.368 [Default:CheckIn:C.Wait] Stopped 2019-09-25T21:08:19.368Z,1569445699.368 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T21:08:19.369Z,1569445699.369 [Default:CheckIn:D] Running Loop=1 2019-09-25T21:08:19.782Z,1569445699.782 [Default:CheckIn:D] Stopped 2019-09-25T21:08:19.782Z,1569445699.782 [Default:CheckIn:E] Running Loop=1 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 234.842041 min 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn:E] Stopped 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn] Stopped 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn](INFO): Running loop #34 2019-09-25T21:08:20.172Z,1569445700.172 [Default:CheckIn] Running Loop=34 2019-09-25T21:08:20.201Z,1569445700.201 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T21:08:20.201Z,1569445700.201 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T21:08:21.773Z,1569445701.773 [NAL9602](DEBUG): Fix Requested 2019-09-25T21:10:46.538Z,1569445846.538 [CommandLine](IMPORTANT): got command show variable acoustic 2019-09-25T21:10:46.539Z,1569445846.539 [CommandLine](IMPORTANT): acoustic_receive_time (epoch_second) 2019-09-25T21:10:46.540Z,1569445846.540 [CommandLine](IMPORTANT): acoustic_transmit_time (epoch_second) 2019-09-25T21:10:46.540Z,1569445846.540 [CommandLine](IMPORTANT): acoustic_contact_direction_vehicle_frame (unknown) 2019-09-25T21:10:46.540Z,1569445846.540 [CommandLine](IMPORTANT): acoustic_contact_address (unknown) 2019-09-25T21:10:46.541Z,1569445846.541 [CommandLine](IMPORTANT): acoustic_contact_range (unknown) 2019-09-25T21:10:46.556Z,1569445846.556 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool) 2019-09-25T21:10:46.556Z,1569445846.556 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.simulateHardware (bool) 2019-09-25T21:10:46.557Z,1569445846.557 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count) 2019-09-25T21:10:46.557Z,1569445846.557 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.verbosity (count) 2019-09-25T21:10:46.566Z,1569445846.566 [CommandLine](IMPORTANT): Rowe_600.acousticBlankingDistance (meter) 2019-09-25T21:10:46.700Z,1569445846.700 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadControl (none) 2019-09-25T21:10:46.700Z,1569445846.700 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.uart (none) 2019-09-25T21:10:46.701Z,1569445846.701 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.baud (bit_per_second) 2019-09-25T21:10:46.926Z,1569445846.926 [CommandLine](IMPORTANT): DAT.acoustic_receive_time (epoch_second) 2019-09-25T21:10:46.926Z,1569445846.926 [CommandLine](IMPORTANT): DAT.acoustic_transmit_time (epoch_second) 2019-09-25T21:10:46.928Z,1569445846.928 [CommandLine](IMPORTANT): DAT.acoustic_wakeup (count) 2019-09-25T21:11:36.864Z,1569445896.864 [CommandLine](IMPORTANT): got command show variable tracking 2019-09-25T21:11:47.269Z,1569445907.269 [CommandLine](IMPORTANT): got command load ./Missions/Engineering/portuguese_ledge.xml 2019-09-25T21:11:47.270Z,1569445907.270 [MissionManager](INFO): Loading Mission: ./Missions/Engineering/portuguese_ledge.xml 2019-09-25T21:11:47.495Z,1569445907.495 [MissionManager](INFO): DefineArg portuguese_ledge.MissionTimeout = 4.000000 h 2019-09-25T21:11:47.501Z,1569445907.501 [MissionManager](INFO): DefineArg portuguese_ledge.NeedCommsTime = 120.000000 min 2019-09-25T21:11:47.504Z,1569445907.504 [MissionManager](INFO): DefineArg portuguese_ledge.AcousticContactTimeout = 15.000000 min 2019-09-25T21:11:47.510Z,1569445907.510 [MissionManager](INFO): DefineArg portuguese_ledge.Depth = 50.000000 m 2019-09-25T21:11:47.512Z,1569445907.512 [MissionManager](INFO): DefineArg portuguese_ledge.Speed = 1.000000 m/s 2019-09-25T21:11:47.518Z,1569445907.518 [MissionManager](INFO): DefineArg portuguese_ledge.MaxDepth = 60.000000 m 2019-09-25T21:11:47.520Z,1569445907.520 [MissionManager](INFO): DefineArg portuguese_ledge.MinOffshore = 4.000000 km 2019-09-25T21:11:47.527Z,1569445907.527 [MissionManager](INFO): DefineArg portuguese_ledge.MinAltitude = 5.000000 m 2019-09-25T21:11:47.533Z,1569445907.533 [MissionManager](INFO): DefineArg portuguese_ledge.MassHold = 1 bool 2019-09-25T21:11:47.535Z,1569445907.535 [MissionManager](INFO): DefineArg portuguese_ledge.BuoyancyHold = 1 bool 2019-09-25T21:11:47.541Z,1569445907.541 [MissionManager](INFO): DefineArg portuguese_ledge.Repeat = 4.000000 count 2019-09-25T21:11:47.543Z,1569445907.543 [MissionManager](INFO): DefineArg portuguese_ledge.Lat1 = 36.695944 arcdeg 2019-09-25T21:11:47.550Z,1569445907.550 [MissionManager](INFO): DefineArg portuguese_ledge.Lon1 = -121.945120 arcdeg 2019-09-25T21:11:47.552Z,1569445907.552 [MissionManager](INFO): DefineArg portuguese_ledge.Lat2 = 36.696536 arcdeg 2019-09-25T21:11:47.576Z,1569445907.576 [MissionManager](INFO): DefineArg portuguese_ledge.Lon2 = -121.937544 arcdeg 2019-09-25T21:11:47.583Z,1569445907.583 [MissionManager](INFO): DefineArg portuguese_ledge.Lat3 = 36.693760 arcdeg 2019-09-25T21:11:47.590Z,1569445907.590 [MissionManager](INFO): DefineArg portuguese_ledge.Lon3 = -121.938647 arcdeg 2019-09-25T21:11:47.611Z,1569445907.611 [MissionManager](INFO): DefineArg portuguese_ledge.Lat4 = 36.698094 arcdeg 2019-09-25T21:11:47.633Z,1569445907.633 [MissionManager](INFO): DefineArg portuguese_ledge.Lon4 = -121.940450 arcdeg 2019-09-25T21:11:47.635Z,1569445907.635 [MissionManager](INFO): DefineArg portuguese_ledge.Lat5 = 36.695944 arcdeg 2019-09-25T21:11:47.641Z,1569445907.641 [MissionManager](INFO): DefineArg portuguese_ledge.Lon5 = -121.945120 arcdeg 2019-09-25T21:11:47.644Z,1569445907.644 [MissionManager](INFO): DefineArg portuguese_ledge.ContactLabel = 0.000000 count 2019-09-25T21:11:47.654Z,1569445907.654 [MissionManager](INFO): DefineArg portuguese_ledge.ContactDepth = nan m 2019-09-25T21:11:47.665Z,1569445907.665 [MissionManager](INFO): DefineArg portuguese_ledge.TrackingUpdatePeriod = 60.000000 s 2019-09-25T21:11:47.679Z,1569445907.679 [MissionManager](INFO): DefineArg portuguese_ledge.NumberOfPings = 1.000000 count 2019-09-25T21:11:47.680Z,1569445907.680 [MissionManager](INFO): Inserting Stack: Missions/Insert/AbortDrift.xml 2019-09-25T21:11:47.724Z,1569445907.724 [MissionManager](INFO): DefineArg portuguese_ledge:AbortDrift.AcousticTimeout = 96.000000 h 2019-09-25T21:11:47.734Z,1569445907.734 [portuguese_ledge:AbortDrift:B.AbortDrift](DEBUG): Construct AbortDrift. 2019-09-25T21:11:47.736Z,1569445907.736 [portuguese_ledge:AbortDrift:C.Execute](DEBUG): Construct Execute. 2019-09-25T21:11:47.743Z,1569445907.743 [MissionManager](INFO): RedefineArg portuguese_ledge:AbortDrift.AcousticTimeout = reader:portuguese_ledge.AcousticContactTimeout 2019-09-25T21:11:47.784Z,1569445907.784 [MissionManager](INFO): Inserting Stack: Missions/Insert/Science.xml 2019-09-25T21:11:48.355Z,1569445908.355 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUS = 0 bool 2019-09-25T21:11:48.358Z,1569445908.358 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUSmaxPitch = 60.000000 arcdeg 2019-09-25T21:11:48.360Z,1569445908.360 [MissionManager](INFO): DefineArg portuguese_ledge:Science.SampleISUSminPitch = -60.000000 arcdeg 2019-09-25T21:11:48.362Z,1569445908.362 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectChlActive = 0 bool 2019-09-25T21:11:48.364Z,1569445908.364 [MissionManager](INFO): DefineArg portuguese_ledge:Science.TimeWindowPeakReport = nan min 2019-09-25T21:11:48.366Z,1569445908.366 [MissionManager](INFO): DefineArg portuguese_ledge:Science.HighestChlPeakReportActive = 0 bool 2019-09-25T21:11:48.368Z,1569445908.368 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PatchTracking = 0 bool 2019-09-25T21:11:48.370Z,1569445908.370 [MissionManager](INFO): DefineArg portuguese_ledge:Science.FilterWidthHorizontal = 3.000000 count 2019-09-25T21:11:48.372Z,1569445908.372 [MissionManager](INFO): DefineArg portuguese_ledge:Science.NumProfilesSlidingwindow = 100.000000 count 2019-09-25T21:11:48.409Z,1569445908.409 [MissionManager](INFO): DefineArg portuguese_ledge:Science.OffPeakFractionHorizontal = 80.000000 % 2019-09-25T21:11:48.411Z,1569445908.411 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectNO3Active = 0 bool 2019-09-25T21:11:48.431Z,1569445908.431 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectOilActive = 0 bool 2019-09-25T21:11:48.432Z,1569445908.432 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDetectFDOMActive = 0 bool 2019-09-25T21:11:48.434Z,1569445908.434 [MissionManager](INFO): DefineArg portuguese_ledge:Science.UpwardDerivativeOfTemperatureActive = 0 bool 2019-09-25T21:11:48.437Z,1569445908.437 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledAanderaaO2 = 0.000000 bool 2019-09-25T21:11:48.439Z,1569445908.439 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledNeilBrown = 0.000000 bool 2019-09-25T21:11:48.462Z,1569445908.462 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledSeabird = 1.000000 bool 2019-09-25T21:11:48.471Z,1569445908.471 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledTurbulence_NPS = 0.000000 bool 2019-09-25T21:11:48.474Z,1569445908.474 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsBB2FL = 1.000000 bool 2019-09-25T21:11:48.476Z,1569445908.476 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsSeaOWL_UV_A = 0.000000 bool 2019-09-25T21:11:48.478Z,1569445908.478 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledWetLabsUBAT = 1.000000 bool 2019-09-25T21:11:48.492Z,1569445908.492 [MissionManager](INFO): DefineArg portuguese_ledge:Science.EnabledISUS = 0.000000 bool 2019-09-25T21:11:48.495Z,1569445908.495 [MissionManager](INFO): DefineArg portuguese_ledge:Science.LowPassWindowLength = 20.000000 count 2019-09-25T21:11:48.497Z,1569445908.497 [MissionManager](INFO): DefineArg portuguese_ledge:Science.MedianFilterLen = 5.000000 count 2019-09-25T21:11:48.499Z,1569445908.499 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakChlShallowBound = nan m 2019-09-25T21:11:48.500Z,1569445908.500 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakChlDeepBound = nan m 2019-09-25T21:11:48.539Z,1569445908.539 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakShallowBound = nan m 2019-09-25T21:11:48.541Z,1569445908.541 [MissionManager](INFO): DefineArg portuguese_ledge:Science.PeakDeepBound = nan m 2019-09-25T21:11:48.543Z,1569445908.543 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChl = 0.000000 ug/l 2019-09-25T21:11:48.545Z,1569445908.545 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlDepth = 0.000000 m 2019-09-25T21:11:48.547Z,1569445908.547 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlTemperature = 0.000000 degC 2019-09-25T21:11:48.574Z,1569445908.574 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlLatitude = nan arcdeg 2019-09-25T21:11:48.576Z,1569445908.576 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakChlLongitude = nan arcdeg 2019-09-25T21:11:48.592Z,1569445908.592 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3 = 0.000000 umol/l 2019-09-25T21:11:48.655Z,1569445908.655 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Depth = 0.000000 m 2019-09-25T21:11:48.658Z,1569445908.658 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Latitude = nan arcdeg 2019-09-25T21:11:48.660Z,1569445908.660 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakNO3Longitude = nan arcdeg 2019-09-25T21:11:48.663Z,1569445908.663 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChl = 0.000000 m 2019-09-25T21:11:48.706Z,1569445908.706 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlDepth = 0.000000 m 2019-09-25T21:11:48.708Z,1569445908.708 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlLatitude = nan arcdeg 2019-09-25T21:11:48.723Z,1569445908.723 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlLongitude = nan arcdeg 2019-09-25T21:11:48.727Z,1569445908.727 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchChlDistance = nan m 2019-09-25T21:11:48.733Z,1569445908.733 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOil = 0.000000 kg/m3 2019-09-25T21:11:48.736Z,1569445908.736 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilDepth = 0.000000 m 2019-09-25T21:11:48.738Z,1569445908.738 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilLatitude = nan arcdeg 2019-09-25T21:11:48.740Z,1569445908.740 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakOilLongitude = nan arcdeg 2019-09-25T21:11:48.767Z,1569445908.767 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOM = 0.000000 ppb 2019-09-25T21:11:48.790Z,1569445908.790 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMDepth = 0.000000 m 2019-09-25T21:11:48.792Z,1569445908.792 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMLatitude = nan arcdeg 2019-09-25T21:11:48.809Z,1569445908.809 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PeakFDOMLongitude = nan arcdeg 2019-09-25T21:11:48.811Z,1569445908.811 [MissionManager](INFO): DefineOutput portuguese_ledge:Science.PatchFDOMDistance = nan m 2019-09-25T21:11:48.869Z,1569445908.869 [portuguese_ledge:Science:PeakDetectChl:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth. 2019-09-25T21:11:48.924Z,1569445908.924 [portuguese_ledge:Science:HighestChlPeakReport:A.PeakDetectHorizontal](DEBUG): Construct PeakDetectHorizontal. 2019-09-25T21:11:48.979Z,1569445908.979 [portuguese_ledge:Science:PeakDetectNO3:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth. 2019-09-25T21:11:49.000Z,1569445909.000 [portuguese_ledge:Science:PeakDetectOil:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth. 2019-09-25T21:11:49.090Z,1569445909.090 [portuguese_ledge:Science:PeakDetectFDOM:A.PeakDetectVsDepth](DEBUG): Construct PeakDetectVsDepth. 2019-09-25T21:11:49.119Z,1569445909.119 [MissionManager](INFO): RedefineArg portuguese_ledge:Science.SampleISUS = value:1 bool 2019-09-25T21:11:49.121Z,1569445909.121 [MissionManager](INFO): RedefineArg portuguese_ledge:Science.PeakDetectChlActive = value:1 bool 2019-09-25T21:11:49.125Z,1569445909.125 [MissionManager](INFO): Inserting Stack: Missions/Insert/NeedComms.xml 2019-09-25T21:11:49.251Z,1569445909.251 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.DiveInterval = 3.000000 h 2019-09-25T21:11:49.261Z,1569445909.261 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.WaitForPitchUp = 10.000000 min 2019-09-25T21:11:49.263Z,1569445909.263 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfacePitch = 20.000000 arcdeg 2019-09-25T21:11:49.269Z,1569445909.269 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfaceDepthRate = nan m/s 2019-09-25T21:11:49.271Z,1569445909.271 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.SurfaceSpeed = 1.000000 m/s 2019-09-25T21:11:49.286Z,1569445909.286 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.GPSTimeout = 7.000000 min 2019-09-25T21:11:49.288Z,1569445909.288 [MissionManager](INFO): DefineArg portuguese_ledge:NeedComms.CommsTimeout = 30.000000 min 2019-09-25T21:11:49.314Z,1569445909.314 [portuguese_ledge:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-09-25T21:11:49.349Z,1569445909.349 [MissionManager](INFO): Inserting Stack: Missions/Insert/StandardEnvelopes.xml 2019-09-25T21:11:49.384Z,1569445909.384 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MinAltitude = 5.000000 m 2019-09-25T21:11:49.394Z,1569445909.394 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MaxDepth = 200.000000 m 2019-09-25T21:11:49.397Z,1569445909.397 [MissionManager](INFO): DefineArg portuguese_ledge:StandardEnvelopes.MinOffshore = 2000.000000 m 2019-09-25T21:11:49.410Z,1569445909.410 [portuguese_ledge:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2019-09-25T21:11:49.486Z,1569445909.486 [portuguese_ledge:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2019-09-25T21:11:49.508Z,1569445909.508 [portuguese_ledge:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2019-09-25T21:11:49.546Z,1569445909.546 [portuguese_ledge:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy. 2019-09-25T21:11:49.560Z,1569445909.560 [portuguese_ledge:MassHold.Pitch](DEBUG): Construct. 2019-09-25T21:11:49.571Z,1569445909.571 [portuguese_ledge:Transit:A.Pitch](DEBUG): Construct. 2019-09-25T21:11:49.598Z,1569445909.598 [portuguese_ledge:Transit:B.SetSpeed](DEBUG): Construct. 2019-09-25T21:11:49.627Z,1569445909.627 [portuguese_ledge:Transit:Lap:Wpt1:A.Waypoint](DEBUG): Construct Waypoint. 2019-09-25T21:11:49.661Z,1569445909.661 [portuguese_ledge:Transit:Lap:Wpt2:A.Waypoint](DEBUG): Construct Waypoint. 2019-09-25T21:11:49.666Z,1569445909.666 [portuguese_ledge:Transit:Lap:Wpt3:A.Waypoint](DEBUG): Construct Waypoint. 2019-09-25T21:11:49.690Z,1569445909.690 [portuguese_ledge:Transit:Lap:Wpt4:A.Waypoint](DEBUG): Construct Waypoint. 2019-09-25T21:11:49.695Z,1569445909.695 [portuguese_ledge:Transit:Lap:Wpt5:A.Waypoint](DEBUG): Construct Waypoint. 2019-09-25T21:11:49.748Z,1569445909.748 [MissionManager](DEBUG): O ve좵lo nada uma vez ao redor do percurso e depois vem �uperf좩e. Maximum duration of mission 4 How often to surface for commumications 120 If the vehicle does not receive an acoustic signal for more than this length of time, it will surface for communications with shore. 15 Depth of flat and level flight during the mission. 50 Speed of vehicle (relative to water) during the mission. 1 Maximum depth for the entire mission. 60 Minimum distance offshore for the entire mission. 4 Minimum height above the sea floor for the entire mission. 5 Set to True in order to hold mass at default position, False to allow mass to run on its own. Set to True in order to hold buoyancy at neutral position, False to allow buoyancy to run on its own. Number of times the vehicle should try to cycle through waypoints.. 4 Latitude of waypoint 1. If nan, waypoint is skipped. 36.695944 Longitude of waypoint 1. If nan, waypoint is skipped. -121.945120 Latitude of waypoint 2. If nan, waypoint is skipped. 36.696536 Longitude of waypoint 2. If nan, waypoint is skipped. -121.937544 Latitude of waypoint 3. If nan, waypoint is skipped. 36.693760 Longitude of waypoint 3. If nan, waypoint is skipped. -121.938647 Latitude of waypoint 4. If nan, waypoint is skipped. 36.698094 Longitude of waypoint 4. If nan, waypoint is skipped. -121.940450 Latitude of waypoint 5. If nan, waypoint is skipped. 36.695944 Longitude of waypoint 5. If nan, waypoint is skipped. -121.945120 The acoustic address of the asset to be tracked 0 The acoustic address of the asset to be tracked NaN How long to wait between acoustic queries 60 Number of return pings to request with each acoustic query (more than 1 will activate oneway mode) 1 Most missions will run the science sensors. If you don't place this aggregate above NeedComms, science instruments get turned off on the last upcast and while floating on the surface. 2019-09-25T21:11:49.748Z,1569445909.748 [CommandLine](IMPORTANT): Loaded ./Missions/Engineering/portuguese_ledge.xml 2019-09-25T21:11:52.743Z,1569445912.743 [CommandLine](IMPORTANT): got command show variable tracking 2019-09-25T21:11:52.955Z,1569445912.955 [CommandLine](IMPORTANT): portuguese_ledge.TrackingUpdatePeriod (second) 2019-09-25T21:11:52.956Z,1569445912.956 [CommandLine](IMPORTANT): Tracking.contact_label (enum) 2019-09-25T21:11:52.956Z,1569445912.956 [CommandLine](IMPORTANT): Tracking.contact_latitude (degree) 2019-09-25T21:11:52.959Z,1569445912.959 [CommandLine](IMPORTANT): Tracking.contact_latitude_lowpass (degree) 2019-09-25T21:11:52.959Z,1569445912.959 [CommandLine](IMPORTANT): Tracking.contact_longitude (degree) 2019-09-25T21:11:52.960Z,1569445912.960 [CommandLine](IMPORTANT): Tracking.contact_longitude_lowpass (degree) 2019-09-25T21:11:52.960Z,1569445912.960 [CommandLine](IMPORTANT): Tracking.eastings_to_contact (meter) 2019-09-25T21:11:52.960Z,1569445912.960 [CommandLine](IMPORTANT): Tracking.northings_to_contact (meter) 2019-09-25T21:11:52.961Z,1569445912.961 [CommandLine](IMPORTANT): Tracking.contact_depth (meter) 2019-09-25T21:11:52.961Z,1569445912.961 [CommandLine](IMPORTANT): Tracking.contact_depth_lowpass (meter) 2019-09-25T21:11:52.962Z,1569445912.962 [CommandLine](IMPORTANT): Tracking.range_to_contact (meter) 2019-09-25T21:11:52.962Z,1569445912.962 [CommandLine](IMPORTANT): Tracking.azimuth_to_contact_vehicleFrame (radian) 2019-09-25T21:11:52.962Z,1569445912.962 [CommandLine](IMPORTANT): Tracking.elevation_to_contact_vehicleFrame (radian) 2019-09-25T21:11:52.963Z,1569445912.963 [CommandLine](IMPORTANT): Tracking.heading_to_contact (radian) 2019-09-25T21:11:52.963Z,1569445912.963 [CommandLine](IMPORTANT): Tracking.direction_vehicleFrame (none) 2019-09-25T21:11:52.963Z,1569445912.963 [CommandLine](IMPORTANT): Tracking.direction_navigationFrame (none) 2019-09-25T21:11:52.964Z,1569445912.964 [CommandLine](IMPORTANT): Tracking.relativePosition_vehicleFrame (meter) 2019-09-25T21:11:52.964Z,1569445912.964 [CommandLine](IMPORTANT): Tracking.relativePosition_navigationFrame (meter) 2019-09-25T21:11:52.966Z,1569445912.966 [CommandLine](IMPORTANT): portuguese_ledge:Science.PatchTracking (bool) 2019-09-25T21:13:20.373Z,1569446000.373 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T21:08:20.2Z 2019-09-25T21:13:20.373Z,1569446000.373 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T21:13:20.373Z,1569446000.373 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T21:13:24.014Z,1569446004.014 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T21:13:27.636Z,1569446007.636 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0090.lzma 2019-09-25T21:13:29.643Z,1569446009.643 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0090.lzma.bak 2019-09-25T21:13:29.643Z,1569446009.643 [DataOverHttps](INFO): SBD MOMSN=11816517 2019-09-25T21:13:46.974Z,1569446026.974 [DataOverHttps](INFO): Sending 822 bytes from file Logs/20190925T173233/Express0091.lzma 2019-09-25T21:13:48.979Z,1569446028.979 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0091.lzma.bak 2019-09-25T21:13:48.979Z,1569446028.979 [DataOverHttps](INFO): SBD MOMSN=11816519 2019-09-25T21:13:50.288Z,1569446030.288 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T21:13:50.288Z,1569446030.288 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T21:13:50.288Z,1569446030.288 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T21:13:54.710Z,1569446034.710 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T21:15:07.541Z,1569446107.541 [CommandLine](IMPORTANT): got command show variable DAT. 2019-09-25T21:15:07.547Z,1569446107.547 [CommandLine](IMPORTANT): AHRS_3DMGX3.loadAtStartup (bool) 2019-09-25T21:15:07.548Z,1569446107.548 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup (bool) 2019-09-25T21:15:07.548Z,1569446107.548 [CommandLine](IMPORTANT): AHRS_sp3003D.loadAtStartup (bool) 2019-09-25T21:15:07.549Z,1569446107.549 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool) 2019-09-25T21:15:07.550Z,1569446107.550 [CommandLine](IMPORTANT): Batt_Ocean_Server.loadAtStartup (bool) 2019-09-25T21:15:07.550Z,1569446107.550 [CommandLine](IMPORTANT): BPC1.loadAtStartup (bool) 2019-09-25T21:15:07.551Z,1569446107.551 [CommandLine](IMPORTANT): DataOverHttps.loadAtStartup (bool) 2019-09-25T21:15:07.551Z,1569446107.551 [CommandLine](IMPORTANT): DataOverHttps.connectionTimeout (second) 2019-09-25T21:15:07.552Z,1569446107.552 [CommandLine](IMPORTANT): DataOverHttps.period (second) 2019-09-25T21:15:07.552Z,1569446107.552 [CommandLine](IMPORTANT): DataOverHttps.power (watt) 2019-09-25T21:15:07.552Z,1569446107.552 [CommandLine](IMPORTANT): DataOverHttps.timeout (minute) 2019-09-25T21:15:07.554Z,1569446107.554 [CommandLine](IMPORTANT): DataOverHttps.verbosity (count) 2019-09-25T21:15:07.555Z,1569446107.555 [CommandLine](IMPORTANT): DAT.loadAtStartup (bool) 2019-09-25T21:15:07.555Z,1569446107.555 [CommandLine](IMPORTANT): DAT.simulateHardware (bool) 2019-09-25T21:15:07.556Z,1569446107.556 [CommandLine](IMPORTANT): DAT.convertPhaseDataToDirection (bool) 2019-09-25T21:15:07.556Z,1569446107.556 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle (bool) 2019-09-25T21:15:07.557Z,1569446107.557 [CommandLine](IMPORTANT): DAT.localAddress (count) 2019-09-25T21:15:07.557Z,1569446107.557 [CommandLine](IMPORTANT): DAT.powerLoadControl (none) 2019-09-25T21:15:07.557Z,1569446107.557 [CommandLine](IMPORTANT): DAT.verbosity (count) 2019-09-25T21:15:07.558Z,1569446107.558 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool) 2019-09-25T21:15:07.559Z,1569446107.559 [CommandLine](IMPORTANT): Depth_Keller.loadAtStartup (bool) 2019-09-25T21:15:07.560Z,1569446107.560 [CommandLine](IMPORTANT): DropWeight.loadAtStartup (bool) 2019-09-25T21:15:07.561Z,1569446107.561 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup (bool) 2019-09-25T21:15:07.561Z,1569446107.561 [CommandLine](IMPORTANT): GobyModem.loadAtStartup (bool) 2019-09-25T21:15:07.562Z,1569446107.562 [CommandLine](IMPORTANT): LineCaptureServo.loadAtStartup (bool) 2019-09-25T21:15:07.563Z,1569446107.563 [CommandLine](IMPORTANT): Micromodem.loadAtStartup (bool) 2019-09-25T21:15:07.563Z,1569446107.563 [CommandLine](IMPORTANT): Micromodem.dataRate (enum) 2019-09-25T21:15:07.564Z,1569446107.564 [CommandLine](IMPORTANT): NAL9602.loadAtStartup (bool) 2019-09-25T21:15:07.565Z,1569446107.565 [CommandLine](IMPORTANT): Onboard.loadAtStartup (bool) 2019-09-25T21:15:07.565Z,1569446107.565 [CommandLine](IMPORTANT): PowerOnly.loadAtStartup (bool) 2019-09-25T21:15:07.566Z,1569446107.566 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup (bool) 2019-09-25T21:15:07.567Z,1569446107.567 [CommandLine](IMPORTANT): Radio_Surface.loadAtStartup (bool) 2019-09-25T21:15:07.567Z,1569446107.567 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup (bool) 2019-09-25T21:15:07.568Z,1569446107.568 [CommandLine](IMPORTANT): RDI_PathfinderUp.loadAtStartup (bool) 2019-09-25T21:15:07.568Z,1569446107.568 [CommandLine](IMPORTANT): Rowe_600.loadAtStartup (bool) 2019-09-25T21:15:07.572Z,1569446107.572 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup (bool) 2019-09-25T21:15:07.574Z,1569446107.574 [CommandLine](IMPORTANT): SCPI.loadAtStartup (bool) 2019-09-25T21:15:07.575Z,1569446107.575 [CommandLine](IMPORTANT): BR_Ping1D.loadAtStartup (bool) 2019-09-25T21:15:07.576Z,1569446107.576 [CommandLine](IMPORTANT): AsyncPiEstimator.loadAtStartup (bool) 2019-09-25T21:15:07.576Z,1569446107.576 [CommandLine](IMPORTANT): LcmPublisher.loadAtStartup (bool) 2019-09-25T21:15:07.577Z,1569446107.577 [CommandLine](IMPORTANT): LcmListener.loadAtStartup (bool) 2019-09-25T21:15:07.606Z,1569446107.606 [CommandLine](IMPORTANT): HFRadarModelCalc.loadAtStartup (bool) 2019-09-25T21:15:07.608Z,1569446107.608 [CommandLine](IMPORTANT): HFRadarCompactModelForecaster.loadAtStartup (bool) 2019-09-25T21:15:07.631Z,1569446107.631 [CommandLine](IMPORTANT): HFRCMSpaceInterpolator.loadAtStartup (bool) 2019-09-25T21:15:07.631Z,1569446107.631 [CommandLine](IMPORTANT): HFRCMTimeInterpolator.loadAtStartup (bool) 2019-09-25T21:15:07.632Z,1569446107.632 [CommandLine](IMPORTANT): HFRCMReconstructedInterpolator.loadAtStartup (bool) 2019-09-25T21:15:07.633Z,1569446107.633 [CommandLine](IMPORTANT): HFRCMSurfaceCurrentAtVehicleLocation.loadAtStartup (bool) 2019-09-25T21:15:07.633Z,1569446107.633 [CommandLine](IMPORTANT): HFRCMVirtualSurfaceDrifter.loadAtStartup (bool) 2019-09-25T21:15:07.634Z,1569446107.634 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup (bool) 2019-09-25T21:15:07.634Z,1569446107.634 [CommandLine](IMPORTANT): DepAvgTempFrontDetector.loadAtStartup (bool) 2019-09-25T21:15:07.635Z,1569446107.635 [CommandLine](IMPORTANT): BuoyancyServo.loadAtStartup (bool) 2019-09-25T21:15:07.636Z,1569446107.636 [CommandLine](IMPORTANT): ElevatorServo.loadAtStartup (bool) 2019-09-25T21:15:07.651Z,1569446107.651 [CommandLine](IMPORTANT): MassServo.loadAtStartup (bool) 2019-09-25T21:15:07.651Z,1569446107.651 [CommandLine](IMPORTANT): RudderServo.loadAtStartup (bool) 2019-09-25T21:15:07.663Z,1569446107.663 [CommandLine](IMPORTANT): ThrusterServo.loadAtStartup (bool) 2019-09-25T21:15:07.664Z,1569446107.664 [CommandLine](IMPORTANT): ExternalSim.loadAtStartup (bool) 2019-09-25T21:15:07.665Z,1569446107.665 [CommandLine](IMPORTANT): InternalSim.loadAtStartup (bool) 2019-09-25T21:15:07.665Z,1569446107.665 [CommandLine](IMPORTANT): NavigationSim.loadAtStartup (bool) 2019-09-25T21:15:07.680Z,1569446107.680 [CommandLine](IMPORTANT): Config/Simulator.oceanModelData (none) 2019-09-25T21:15:07.702Z,1569446107.702 [CommandLine](IMPORTANT): DepthRateCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.702Z,1569446107.702 [CommandLine](IMPORTANT): TempGradientCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.703Z,1569446107.703 [CommandLine](IMPORTANT): PitchRateCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.704Z,1569446107.704 [CommandLine](IMPORTANT): SpeedCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.704Z,1569446107.704 [CommandLine](IMPORTANT): VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.709Z,1569446107.709 [CommandLine](IMPORTANT): YawRateCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.710Z,1569446107.710 [CommandLine](IMPORTANT): ElevatorOffsetCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.711Z,1569446107.711 [CommandLine](IMPORTANT): Vehicle.sendDataToShore (bool) 2019-09-25T21:15:07.726Z,1569446107.726 [CommandLine](IMPORTANT): DAT.loadControl (none) 2019-09-25T21:15:07.726Z,1569446107.726 [CommandLine](IMPORTANT): DAT.uart (none) 2019-09-25T21:15:07.727Z,1569446107.727 [CommandLine](IMPORTANT): DAT.baud (bit_per_second) 2019-09-25T21:15:07.740Z,1569446107.740 [CommandLine](IMPORTANT): DeadReckonUsingMultipleVelocitySources.loadAtStartup (bool) 2019-09-25T21:15:07.753Z,1569446107.753 [CommandLine](IMPORTANT): DeadReckonUsingSpeedCalculator.loadAtStartup (bool) 2019-09-25T21:15:07.754Z,1569446107.754 [CommandLine](IMPORTANT): DeadReckonWithRespectToWater.loadAtStartup (bool) 2019-09-25T21:15:07.755Z,1569446107.755 [CommandLine](IMPORTANT): DeadReckonWithRespectToSeafloor.loadAtStartup (bool) 2019-09-25T21:15:07.755Z,1569446107.755 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.loadAtStartup (bool) 2019-09-25T21:15:07.756Z,1569446107.756 [CommandLine](IMPORTANT): DeadReckonUsingCompactModelForecast.loadAtStartup (bool) 2019-09-25T21:15:07.771Z,1569446107.771 [CommandLine](IMPORTANT): NavChart.loadAtStartup (bool) 2019-09-25T21:15:07.772Z,1569446107.772 [CommandLine](IMPORTANT): UniversalFixResidualReporter.loadAtStartup (bool) 2019-09-25T21:15:07.772Z,1569446107.772 [CommandLine](IMPORTANT): CBIT.loadAtStartup (bool) 2019-09-25T21:15:07.774Z,1569446107.774 [CommandLine](IMPORTANT): SBIT.loadAtStartup (bool) 2019-09-25T21:15:07.774Z,1569446107.774 [CommandLine](IMPORTANT): IBIT.loadAtStartup (bool) 2019-09-25T21:15:07.775Z,1569446107.775 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup (bool) 2019-09-25T21:15:07.776Z,1569446107.776 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup (bool) 2019-09-25T21:15:07.776Z,1569446107.776 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup (bool) 2019-09-25T21:15:07.787Z,1569446107.787 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup (bool) 2019-09-25T21:15:07.799Z,1569446107.799 [CommandLine](IMPORTANT): CTD_SeabirdLCM.loadAtStartup (bool) 2019-09-25T21:15:07.800Z,1569446107.800 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup (bool) 2019-09-25T21:15:07.802Z,1569446107.802 [CommandLine](IMPORTANT): ISUS.loadAtStartup (bool) 2019-09-25T21:15:07.803Z,1569446107.803 [CommandLine](IMPORTANT): PAR_Licor.loadAtStartup (bool) 2019-09-25T21:15:07.803Z,1569446107.803 [CommandLine](IMPORTANT): Turner_Cyclops_rhodamine.loadAtStartup (bool) 2019-09-25T21:15:07.804Z,1569446107.804 [CommandLine](IMPORTANT): Turbulence_NPS.loadAtStartup (bool) 2019-09-25T21:15:07.805Z,1569446107.805 [CommandLine](IMPORTANT): VemcoVR2C.loadAtStartup (bool) 2019-09-25T21:15:07.805Z,1569446107.805 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup (bool) 2019-09-25T21:15:07.806Z,1569446107.806 [CommandLine](IMPORTANT): WetLabsSeaOWL_UV_A.loadAtStartup (bool) 2019-09-25T21:15:07.807Z,1569446107.807 [CommandLine](IMPORTANT): WetLabsUBAT.loadAtStartup (bool) 2019-09-25T21:15:07.808Z,1569446107.808 [CommandLine](IMPORTANT): BackSeatDriver.loadAtStartup (bool) 2019-09-25T21:15:07.808Z,1569446107.808 [CommandLine](IMPORTANT): HorizontalControl.loadAtStartup (bool) 2019-09-25T21:15:07.877Z,1569446107.877 [CommandLine](IMPORTANT): LoopControl.loadAtStartup (bool) 2019-09-25T21:15:07.878Z,1569446107.878 [CommandLine](IMPORTANT): SpeedControl.loadAtStartup (bool) 2019-09-25T21:15:07.878Z,1569446107.878 [CommandLine](IMPORTANT): VerticalControl.loadAtStartup (bool) 2019-09-25T21:15:07.920Z,1569446107.920 [CommandLine](IMPORTANT): DataOverHttps.platform_communications (bool) 2019-09-25T21:15:07.932Z,1569446107.932 [CommandLine](IMPORTANT): DAT.queryAddressRequested (count) 2019-09-25T21:15:07.932Z,1569446107.932 [CommandLine](IMPORTANT): DAT.numberOfPingsRequested (count) 2019-09-25T21:15:07.937Z,1569446107.937 [CommandLine](IMPORTANT): DAT.acoustic_receive_time (epoch_second) 2019-09-25T21:15:07.938Z,1569446107.938 [CommandLine](IMPORTANT): DAT.acoustic_transmit_time (epoch_second) 2019-09-25T21:15:07.938Z,1569446107.938 [CommandLine](IMPORTANT): DAT.LVL1 (count) 2019-09-25T21:15:07.938Z,1569446107.938 [CommandLine](IMPORTANT): DAT.LVL2 (count) 2019-09-25T21:15:07.939Z,1569446107.939 [CommandLine](IMPORTANT): DAT.LVL3 (count) 2019-09-25T21:15:07.939Z,1569446107.939 [CommandLine](IMPORTANT): DAT.LVL4 (count) 2019-09-25T21:15:07.939Z,1569446107.939 [CommandLine](IMPORTANT): DAT.AGC (count) 2019-09-25T21:15:07.940Z,1569446107.940 [CommandLine](IMPORTANT): DAT.phaseA (radian) 2019-09-25T21:15:07.940Z,1569446107.940 [CommandLine](IMPORTANT): DAT.phaseB (radian) 2019-09-25T21:15:07.941Z,1569446107.941 [CommandLine](IMPORTANT): DAT.phaseC (radian) 2019-09-25T21:15:07.953Z,1569446107.953 [CommandLine](IMPORTANT): DAT.rawAzimuth (degree) 2019-09-25T21:15:07.954Z,1569446107.954 [CommandLine](IMPORTANT): DAT.rawElevation (degree) 2019-09-25T21:15:07.954Z,1569446107.954 [CommandLine](IMPORTANT): DAT.calibratedAzimuth (degree) 2019-09-25T21:15:07.954Z,1569446107.954 [CommandLine](IMPORTANT): DAT.calibratedElevation (degree) 2019-09-25T21:15:07.955Z,1569446107.955 [CommandLine](IMPORTANT): DAT.rotatedAzimuth (degree) 2019-09-25T21:15:07.955Z,1569446107.955 [CommandLine](IMPORTANT): DAT.rotatedElevation (degree) 2019-09-25T21:15:07.956Z,1569446107.956 [CommandLine](IMPORTANT): DAT.acoustic_wakeup (count) 2019-09-25T21:15:07.956Z,1569446107.956 [CommandLine](IMPORTANT): DAT.range_request (count) 2019-09-25T21:15:07.956Z,1569446107.956 [CommandLine](IMPORTANT): DAT.remoteAddress (enum) 2019-09-25T21:15:07.958Z,1569446107.958 [CommandLine](IMPORTANT): DAT.localAddressReading (enum) 2019-09-25T21:15:07.958Z,1569446107.958 [CommandLine](IMPORTANT): DAT.range (meter) 2019-09-25T21:15:07.958Z,1569446107.958 [CommandLine](IMPORTANT): DAT.azimuth_instrumentFrame (radian) 2019-09-25T21:15:07.959Z,1569446107.959 [CommandLine](IMPORTANT): DAT.elevation_instrumentFrame (radian) 2019-09-25T21:15:07.959Z,1569446107.959 [CommandLine](IMPORTANT): DAT.azimuth_vehicleFrame (radian) 2019-09-25T21:15:07.959Z,1569446107.959 [CommandLine](IMPORTANT): DAT.elevation_vehicleFrame (radian) 2019-09-25T21:15:07.960Z,1569446107.960 [CommandLine](IMPORTANT): DAT.direction_instrumentFrame (none) 2019-09-25T21:15:07.960Z,1569446107.960 [CommandLine](IMPORTANT): DAT.direction_vehicleFrame (none) 2019-09-25T21:15:08.022Z,1569446108.022 [CommandLine](IMPORTANT): DAT.component_voltage (volt) 2019-09-25T21:15:08.023Z,1569446108.023 [CommandLine](IMPORTANT): DAT.component_avgVoltage (volt) 2019-09-25T21:15:08.023Z,1569446108.023 [CommandLine](IMPORTANT): DAT.component_current (milliampere) 2019-09-25T21:15:08.023Z,1569446108.023 [CommandLine](IMPORTANT): DAT.component_avgCurrent (milliampere) 2019-09-25T21:15:08.034Z,1569446108.034 [CommandLine](IMPORTANT): portuguese_ledge.TrackingUpdatePeriod (second) 2019-09-25T21:15:15.270Z,1569446115.270 [CommandLine](IMPORTANT): got command show variable acoustic 2019-09-25T21:15:15.272Z,1569446115.272 [CommandLine](IMPORTANT): acoustic_receive_time (epoch_second) 2019-09-25T21:15:15.272Z,1569446115.272 [CommandLine](IMPORTANT): acoustic_transmit_time (epoch_second) 2019-09-25T21:15:15.274Z,1569446115.274 [CommandLine](IMPORTANT): acoustic_contact_direction_vehicle_frame (unknown) 2019-09-25T21:15:15.275Z,1569446115.275 [CommandLine](IMPORTANT): acoustic_contact_address (unknown) 2019-09-25T21:15:15.275Z,1569446115.275 [CommandLine](IMPORTANT): acoustic_contact_range (unknown) 2019-09-25T21:15:15.290Z,1569446115.290 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool) 2019-09-25T21:15:15.291Z,1569446115.291 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.simulateHardware (bool) 2019-09-25T21:15:15.291Z,1569446115.291 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.localAddress (count) 2019-09-25T21:15:15.291Z,1569446115.291 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.verbosity (count) 2019-09-25T21:15:15.300Z,1569446115.300 [CommandLine](IMPORTANT): Rowe_600.acousticBlankingDistance (meter) 2019-09-25T21:15:15.418Z,1569446115.418 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadControl (none) 2019-09-25T21:15:15.419Z,1569446115.419 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.uart (none) 2019-09-25T21:15:15.419Z,1569446115.419 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.baud (bit_per_second) 2019-09-25T21:15:15.639Z,1569446115.639 [CommandLine](IMPORTANT): DAT.acoustic_receive_time (epoch_second) 2019-09-25T21:15:15.639Z,1569446115.639 [CommandLine](IMPORTANT): DAT.acoustic_transmit_time (epoch_second) 2019-09-25T21:15:15.641Z,1569446115.641 [CommandLine](IMPORTANT): DAT.acoustic_wakeup (count) 2019-09-25T21:15:15.714Z,1569446115.714 [CommandLine](IMPORTANT): portuguese_ledge.AcousticContactTimeout (minute) 2019-09-25T21:15:15.715Z,1569446115.715 [CommandLine](IMPORTANT): portuguese_ledge:AbortDrift.AcousticTimeout (hour) 2019-09-25T21:18:19.622Z,1569446299.622 [CommandLine](IMPORTANT): got command show variable DVL 2019-09-25T21:18:19.635Z,1569446299.635 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup (bool) 2019-09-25T21:18:19.636Z,1569446299.636 [CommandLine](IMPORTANT): DVL_micro.simulateHardware (bool) 2019-09-25T21:18:19.636Z,1569446299.636 [CommandLine](IMPORTANT): DVL_micro.magDeviation (degree) 2019-09-25T21:18:19.636Z,1569446299.636 [CommandLine](IMPORTANT): DVL_micro.pitchOffset (degree) 2019-09-25T21:18:19.637Z,1569446299.637 [CommandLine](IMPORTANT): DVL_micro.power (watt) 2019-09-25T21:18:19.637Z,1569446299.637 [CommandLine](IMPORTANT): DVL_micro.rollOffset (degree) 2019-09-25T21:18:19.703Z,1569446299.703 [CommandLine](IMPORTANT): DVL_micro.loadControl (none) 2019-09-25T21:18:19.704Z,1569446299.704 [CommandLine](IMPORTANT): DVL_micro.uart (none) 2019-09-25T21:18:19.704Z,1569446299.704 [CommandLine](IMPORTANT): DVL_micro.baud (bit_per_second) 2019-09-25T21:18:19.755Z,1569446299.755 [CommandLine](IMPORTANT): Rowe_600LCM.lcmChannelDVL (none) 2019-09-25T21:18:19.774Z,1569446299.774 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.loadAtStartup (bool) 2019-09-25T21:18:19.775Z,1569446299.775 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.accuracyPremultiplier (none) 2019-09-25T21:18:19.775Z,1569446299.775 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.allowableFailures (count) 2019-09-25T21:18:19.775Z,1569446299.775 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.orientationStaleAfter (minute) 2019-09-25T21:18:19.776Z,1569446299.776 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.velocityStaleAfter (second) 2019-09-25T21:18:19.776Z,1569446299.776 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.verbosity (count) 2019-09-25T21:18:33.492Z,1569446313.492 [CommandLine](IMPORTANT): got command get DVL_micro.loadAtStartup 2019-09-25T21:18:33.492Z,1569446313.492 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup 0 bool 2019-09-25T21:18:36.467Z,1569446316.467 [CommandLine](IMPORTANT): got command show variable RDI 2019-09-25T21:18:36.475Z,1569446316.475 [CommandLine](IMPORTANT): projection_x_coordinate (unknown) 2019-09-25T21:18:36.475Z,1569446316.475 [CommandLine](IMPORTANT): projection_y_coordinate (unknown) 2019-09-25T21:18:36.488Z,1569446316.488 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup (bool) 2019-09-25T21:18:36.488Z,1569446316.488 [CommandLine](IMPORTANT): RDI_Pathfinder.simulateHardware (bool) 2019-09-25T21:18:36.488Z,1569446316.488 [CommandLine](IMPORTANT): RDI_PathfinderUp.loadAtStartup (bool) 2019-09-25T21:18:36.489Z,1569446316.489 [CommandLine](IMPORTANT): RDI_PathfinderUp.simulateHardware (bool) 2019-09-25T21:18:36.563Z,1569446316.563 [CommandLine](IMPORTANT): RDI_Pathfinder.loadControl (none) 2019-09-25T21:18:36.563Z,1569446316.563 [CommandLine](IMPORTANT): RDI_Pathfinder.uart (none) 2019-09-25T21:18:36.563Z,1569446316.563 [CommandLine](IMPORTANT): RDI_Pathfinder.baud (bit_per_second) 2019-09-25T21:18:36.676Z,1569446316.676 [CommandLine](IMPORTANT): RDI_Pathfinder.height_above_sea_floor (meter) 2019-09-25T21:18:36.681Z,1569446316.681 [CommandLine](IMPORTANT): RDI_Pathfinder.platform_velocity_wrt_ground (meter_per_second) 2019-09-25T21:18:36.681Z,1569446316.681 [CommandLine](IMPORTANT): RDI_Pathfinder.platform_x_velocity_wrt_ground (meter_per_second) 2019-09-25T21:18:36.682Z,1569446316.682 [CommandLine](IMPORTANT): RDI_Pathfinder.platform_y_velocity_wrt_ground (meter_per_second) 2019-09-25T21:18:36.682Z,1569446316.682 [CommandLine](IMPORTANT): RDI_Pathfinder.platform_z_velocity_wrt_ground (meter_per_second) 2019-09-25T21:18:36.682Z,1569446316.682 [CommandLine](IMPORTANT): RDI_Pathfinder.BottomVelocityFlag (count) 2019-09-25T21:18:36.683Z,1569446316.683 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam1Range (meter) 2019-09-25T21:18:36.683Z,1569446316.683 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam2Range (meter) 2019-09-25T21:18:36.684Z,1569446316.684 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam3Range (meter) 2019-09-25T21:18:36.684Z,1569446316.684 [CommandLine](IMPORTANT): RDI_Pathfinder.Beam4Range (meter) 2019-09-25T21:18:36.780Z,1569446316.780 [CommandLine](IMPORTANT): RDI_Pathfinder.component_voltage (volt) 2019-09-25T21:18:36.788Z,1569446316.788 [CommandLine](IMPORTANT): RDI_Pathfinder.component_avgVoltage (volt) 2019-09-25T21:18:36.788Z,1569446316.788 [CommandLine](IMPORTANT): RDI_Pathfinder.component_current (milliampere) 2019-09-25T21:18:36.788Z,1569446316.788 [CommandLine](IMPORTANT): RDI_Pathfinder.component_avgCurrent (milliampere) 2019-09-25T21:18:45.913Z,1569446325.913 [CommandLine](IMPORTANT): got command get RDI_Pathfinder.loadAtStartup 2019-09-25T21:18:45.914Z,1569446325.914 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup 1 bool 2019-09-25T21:18:50.899Z,1569446330.899 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T21:18:50.899Z,1569446330.899 [Default:CheckIn:C.Wait] Stopped 2019-09-25T21:18:50.899Z,1569446330.899 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T21:18:50.899Z,1569446330.899 [Default:CheckIn:D] Running Loop=1 2019-09-25T21:18:51.284Z,1569446331.284 [Default:CheckIn:D] Stopped 2019-09-25T21:18:51.284Z,1569446331.284 [Default:CheckIn:E] Running Loop=1 2019-09-25T21:18:51.697Z,1569446331.697 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 245.367057 min 2019-09-25T21:18:51.697Z,1569446331.697 [Default:CheckIn:E] Stopped 2019-09-25T21:18:51.697Z,1569446331.697 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T21:18:51.697Z,1569446331.697 [Default:CheckIn] Stopped 2019-09-25T21:18:51.698Z,1569446331.698 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T21:18:51.698Z,1569446331.698 [Default:CheckIn](INFO): Running loop #35 2019-09-25T21:18:51.698Z,1569446331.698 [Default:CheckIn] Running Loop=35 2019-09-25T21:18:51.698Z,1569446331.698 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T21:18:51.698Z,1569446331.698 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T21:18:53.271Z,1569446333.271 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T21:18:53.271Z,1569446333.271 [NAL9602] Data Fault, FailCount= 4 2019-09-25T21:18:53.271Z,1569446333.271 [NAL9602](ERROR): Data Fault 2019-09-25T21:18:53.338Z,1569446333.338 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T21:18:53.669Z,1569446333.669 [NAL9602](INFO): Powering down 2019-09-25T21:18:54.528Z,1569446334.528 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T21:18:54.528Z,1569446334.528 [NAL9602] No Fault, FailCount= 4 2019-09-25T21:19:23.990Z,1569446363.990 [NAL9602](INFO): Powering up NAL9602 2019-09-25T21:19:34.894Z,1569446374.894 [NAL9602](INFO): NAL9602 initialized 2019-09-25T21:19:35.728Z,1569446375.728 [NAL9602](DEBUG): Fix Requested 2019-09-25T21:23:51.872Z,1569446631.872 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T21:18:51.7Z 2019-09-25T21:23:51.872Z,1569446631.872 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T21:23:51.872Z,1569446631.872 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T21:23:59.933Z,1569446639.933 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0093.lzma 2019-09-25T21:24:01.939Z,1569446641.939 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0093.lzma.bak 2019-09-25T21:24:01.939Z,1569446641.939 [DataOverHttps](INFO): SBD MOMSN=11816581 2019-09-25T21:24:20.063Z,1569446660.063 [DataOverHttps](INFO): Sending 2506 bytes from file Logs/20190925T173233/Express0094.lzma 2019-09-25T21:24:22.063Z,1569446662.063 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0094.lzma.bak 2019-09-25T21:24:22.063Z,1569446662.063 [DataOverHttps](INFO): SBD MOMSN=11816583 2019-09-25T21:24:23.819Z,1569446663.819 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T21:24:23.819Z,1569446663.819 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T21:24:23.819Z,1569446663.819 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T21:24:38.298Z,1569446678.298 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T21:25:09.006Z,1569446709.006 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T21:29:24.363Z,1569446964.363 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T21:29:24.363Z,1569446964.363 [Default:CheckIn:C.Wait] Stopped 2019-09-25T21:29:24.363Z,1569446964.363 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T21:29:24.364Z,1569446964.364 [Default:CheckIn:D] Running Loop=1 2019-09-25T21:29:24.761Z,1569446964.761 [Default:CheckIn:D] Stopped 2019-09-25T21:29:24.761Z,1569446964.761 [Default:CheckIn:E] Running Loop=1 2019-09-25T21:29:25.175Z,1569446965.175 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 255.925016 min 2019-09-25T21:29:25.175Z,1569446965.175 [Default:CheckIn:E] Stopped 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn] Stopped 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn](INFO): Running loop #36 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn] Running Loop=36 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T21:29:25.176Z,1569446965.176 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T21:29:26.769Z,1569446966.769 [NAL9602](DEBUG): Fix Requested 2019-09-25T21:30:29.822Z,1569447029.822 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-09-25T21:34:25.343Z,1569447265.343 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T21:29:25.2Z 2019-09-25T21:34:25.343Z,1569447265.343 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T21:34:25.343Z,1569447265.343 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T21:34:29.362Z,1569447269.362 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-25T21:34:33.052Z,1569447273.052 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190925T173233/Courier0096.lzma 2019-09-25T21:34:35.059Z,1569447275.059 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0096.lzma.bak 2019-09-25T21:34:35.059Z,1569447275.059 [DataOverHttps](INFO): SBD MOMSN=11817045 2019-09-25T21:34:52.381Z,1569447292.381 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20190925T173233/Express0097.lzma 2019-09-25T21:34:54.387Z,1569447294.387 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Express0097.lzma.bak 2019-09-25T21:34:54.387Z,1569447294.387 [DataOverHttps](INFO): SBD MOMSN=11817065 2019-09-25T21:34:56.075Z,1569447296.075 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T21:34:56.075Z,1569447296.075 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-25T21:34:56.075Z,1569447296.075 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-25T21:35:00.063Z,1569447300.063 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-25T21:37:45.332Z,1569447465.332 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-09-25T21:39:56.665Z,1569447596.665 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-25T21:39:56.665Z,1569447596.665 [Default:CheckIn:C.Wait] Stopped 2019-09-25T21:39:56.665Z,1569447596.665 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-25T21:39:56.665Z,1569447596.665 [Default:CheckIn:D] Running Loop=1 2019-09-25T21:39:57.051Z,1569447597.051 [Default:CheckIn:D] Stopped 2019-09-25T21:39:57.051Z,1569447597.051 [Default:CheckIn:E] Running Loop=1 2019-09-25T21:39:57.449Z,1569447597.449 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 266.463184 min 2019-09-25T21:39:57.449Z,1569447597.449 [Default:CheckIn:E] Stopped 2019-09-25T21:39:57.449Z,1569447597.449 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-25T21:39:57.449Z,1569447597.449 [Default:CheckIn] Stopped 2019-09-25T21:39:57.450Z,1569447597.450 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T21:39:57.450Z,1569447597.450 [Default:CheckIn](INFO): Running loop #37 2019-09-25T21:39:57.450Z,1569447597.450 [Default:CheckIn] Running Loop=37 2019-09-25T21:39:57.450Z,1569447597.450 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-25T21:39:57.450Z,1569447597.450 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-25T21:39:59.042Z,1569447599.042 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-09-25T21:39:59.042Z,1569447599.042 [NAL9602] Data Fault, FailCount= 5 2019-09-25T21:39:59.042Z,1569447599.042 [NAL9602](ERROR): Data Fault 2019-09-25T21:39:59.110Z,1569447599.110 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-25T21:39:59.111Z,1569447599.111 [CBIT](CRITICAL): Data Fault in component: NAL9602 2019-09-25T21:39:59.446Z,1569447599.446 [NAL9602](INFO): Powering down 2019-09-25T21:39:59.482Z,1569447599.482 [CBIT](INFO): Critical error at 20190925T213959 2019-09-25T21:39:59.482Z,1569447599.482 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2019-09-25T21:41:59.163Z,1569447719.163 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-25T21:41:59.163Z,1569447719.163 [NAL9602] No Fault, FailCount= 5 2019-09-25T21:41:59.446Z,1569447719.446 [NAL9602](INFO): Powering up NAL9602 2019-09-25T21:42:10.338Z,1569447730.338 [NAL9602](INFO): NAL9602 initialized 2019-09-25T21:42:11.161Z,1569447731.161 [NAL9602](DEBUG): Fix Requested 2019-09-25T21:44:57.656Z,1569447897.656 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-25T21:39:57.4Z 2019-09-25T21:44:57.656Z,1569447897.656 [Default:CheckIn:Read_GPS] Stopped 2019-09-25T21:44:57.656Z,1569447897.656 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-25T21:45:05.580Z,1569447905.580 [DataOverHttps](INFO): Sending 69 bytes from file Logs/20190925T173233/Courier0099.lzma 2019-09-25T21:45:07.590Z,1569447907.590 [DataOverHttps](INFO): Moved sent file to Logs/20190925T173233/Courier0099.lzma.bak 2019-09-25T21:45:07.591Z,1569447907.591 [DataOverHttps](INFO): SBD MOMSN=11817090 2019-09-25T21:45:08.611Z,1569447908.611 [CommandLine](IMPORTANT): got command restart system 2019-09-25T21:45:10.673Z,1569447910.673 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:10.673Z,1569447910.673 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:10.853Z,1569447910.853 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-09-25T21:45:10.853Z,1569447910.853 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:10.854Z,1569447910.854 [CommandLine](INFO): Join timeout helper Thread ID is 8947 2019-09-25T21:45:10.855Z,1569447910.855 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-09-25T21:45:10.855Z,1569447910.855 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:10.855Z,1569447910.855 [NavChartDb](INFO): Join timeout helper Thread ID is 8948 2019-09-25T21:45:11.201Z,1569447911.201 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:11.201Z,1569447911.201 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.213Z,1569447911.213 [ComponentRegistry](INFO): Shutting down WetLabsUBAT ThreadHandler 2019-09-25T21:45:11.213Z,1569447911.213 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.213Z,1569447911.213 [WetLabsUBAT](INFO): Join timeout helper Thread ID is 8949 2019-09-25T21:45:11.517Z,1569447911.517 [WetLabsUBAT ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:11.517Z,1569447911.517 [WetLabsUBAT](INFO): Powering down 2019-09-25T21:45:11.518Z,1569447911.518 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.521Z,1569447911.521 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-09-25T21:45:11.521Z,1569447911.521 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.521Z,1569447911.521 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 8950 2019-09-25T21:45:11.805Z,1569447911.805 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:11.806Z,1569447911.806 [WetLabsBB2FL](INFO): Powering down 2019-09-25T21:45:11.806Z,1569447911.806 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.825Z,1569447911.825 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-09-25T21:45:11.825Z,1569447911.825 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:11.825Z,1569447911.825 [CTD_Seabird](INFO): Join timeout helper Thread ID is 8951 2019-09-25T21:45:12.137Z,1569447912.137 [CTD_Seabird](INFO): Powering down 2019-09-25T21:45:12.149Z,1569447912.149 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:12.149Z,1569447912.149 [CTD_Seabird](INFO): Powering down 2019-09-25T21:45:12.162Z,1569447912.162 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:12.163Z,1569447912.163 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-09-25T21:45:12.163Z,1569447912.163 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:12.164Z,1569447912.164 [Radio_Surface](INFO): Join timeout helper Thread ID is 8952 2019-09-25T21:45:12.313Z,1569447912.313 [Radio_Surface](INFO): Powering down 2019-09-25T21:45:12.314Z,1569447912.314 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:12.314Z,1569447912.314 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:12.322Z,1569447912.322 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-09-25T21:45:12.322Z,1569447912.322 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:12.322Z,1569447912.322 [DataOverHttps](INFO): Join timeout helper Thread ID is 8953 2019-09-25T21:45:14.542Z,1569447914.542 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:14.548Z,1569447914.548 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:14.558Z,1569447914.558 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-09-25T21:45:14.558Z,1569447914.558 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:14.558Z,1569447914.558 [logger](INFO): Join timeout helper Thread ID is 8954 2019-09-25T21:45:14.597Z,1569447914.597 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:14.597Z,1569447914.597 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:14.606Z,1569447914.606 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-09-25T21:45:14.606Z,1569447914.606 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:14.606Z,1569447914.606 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-09-25T21:45:14.606Z,1569447914.606 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:14.606Z,1569447914.606 [controlThread](INFO): Join timeout helper Thread ID is 8955 2019-09-25T21:45:14.954Z,1569447914.954 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-25T21:45:14.954Z,1569447914.954 [controlThread](DEBUG): Uninitializing ControlThread 2019-09-25T21:45:14.956Z,1569447914.956 [AHRS_M2](INFO): Powering down 2019-09-25T21:45:15.029Z,1569447915.029 [NAL9602](INFO): Powering down 2019-09-25T21:45:15.101Z,1569447915.101 [RDI_Pathfinder](INFO): Powering down 2019-09-25T21:45:15.102Z,1569447915.102 [DAT](INFO): Powering down 2019-09-25T21:45:15.222Z,1569447915.222 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-09-25T21:45:15.223Z,1569447915.223 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-09-25T21:45:15.223Z,1569447915.223 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-09-25T21:45:15.224Z,1569447915.224 [MissionManager](INFO): Uninitializing Mission Default 2019-09-25T21:45:15.224Z,1569447915.224 [Default] Stopped 2019-09-25T21:45:15.224Z,1569447915.224 [Default](DEBUG): Aggregate::uninitialize Default 2019-09-25T21:45:15.224Z,1569447915.224 [Default:B.GoToSurface] Stopped 2019-09-25T21:45:15.224Z,1569447915.224 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-09-25T21:45:15.224Z,1569447915.224 [Default:CheckIn] Stopped 2019-09-25T21:45:15.224Z,1569447915.224 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-25T21:45:15.224Z,1569447915.224 [Default:CheckIn:Read_Iridium] Stopped 2019-09-25T21:45:15.226Z,1569447915.226 [MissionManager](INFO): Uninitializing Mission portuguese_ledge 2019-09-25T21:45:15.262Z,1569447915.262 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-09-25T21:45:15.262Z,1569447915.262 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-09-25T21:45:15.263Z,1569447915.263 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-09-25T21:45:15.263Z,1569447915.263 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-09-25T21:45:15.263Z,1569447915.263 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-09-25T21:45:15.263Z,1569447915.263 [BuoyancyServo](INFO): Powering down 2019-09-25T21:45:15.277Z,1569447915.277 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-09-25T21:45:15.277Z,1569447915.277 [ElevatorServo](INFO): Powering down 2019-09-25T21:45:15.278Z,1569447915.278 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-09-25T21:45:15.278Z,1569447915.278 [MassServo](INFO): Powering down 2019-09-25T21:45:15.279Z,1569447915.279 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-09-25T21:45:15.279Z,1569447915.279 [RudderServo](INFO): Powering down 2019-09-25T21:45:15.280Z,1569447915.280 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-09-25T21:45:15.280Z,1569447915.280 [ThrusterServo](INFO): Powering down 2019-09-25T21:45:15.281Z,1569447915.281 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-09-25T21:45:15.281Z,1569447915.281 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-09-25T21:45:15.281Z,1569447915.281 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-09-25T21:45:15.281Z,1569447915.281 [CBIT](DEBUG): Powering off loads. 2019-09-25T21:45:15.293Z,1569447915.293 [CBIT](DEBUG): Disabling WDT. 2019-09-25T21:45:15.305Z,1569447915.305 [CBIT](DEBUG): Opening all GF detection circuits. 2019-09-25T21:45:15.306Z,1569447915.306 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.403Z,1569447915.403 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.411Z,1569447915.411 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.475Z,1569447915.475 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.476Z,1569447915.476 [WetLabsUBAT](INFO): WetLabs destructor: dataLog is open - close it 2019-09-25T21:45:15.480Z,1569447915.480 [WetLabsUBAT](INFO): WetLabs destructor: done 2019-09-25T21:45:15.532Z,1569447915.532 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.534Z,1569447915.534 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.549Z,1569447915.549 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-25T21:45:15.638Z,1569447915.638 [logger ThreadHandler](INFO): Thread cancelled.