2019-10-10T16:58:36.742Z,1570726716.742 [DataOverHttps](INFO): Received command:restart logs 2019-10-10T16:58:36.747Z,1570726716.747 [CommandLine](IMPORTANT): got command restart logs 2019-10-10T16:59:08.731Z,1570726748.731 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T16:59:08.731Z,1570726748.731 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+0.0,1489.WI,+00659,02373,+00000,A 2019-10-10T16:59:23.926Z,1570726763.926 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T16:59:38.987Z,1570726778.987 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239803 2019-10-10T17:00:25.170Z,1570726825.170 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T17:00:56.303Z,1570726856.303 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T17:01:27.434Z,1570726887.434 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T17:01:33.364Z,1570726893.364 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+14.2,0000.0,1489.0,000 2019-10-10T17:01:58.570Z,1570726918.570 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T17:02:29.711Z,1570726949.711 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-10-10T17:02:42.242Z,1570726962.242 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003260 2019-10-10T17:02:58.638Z,1570726978.638 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:02:58.638Z,1570726978.638 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:02:58.638Z,1570726978.638 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:02:58.666Z,1570726978.666 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:02:59.039Z,1570726979.039 [Default:CheckIn:D] Stopped 2019-10-10T17:02:59.039Z,1570726979.039 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:02:59.455Z,1570726979.455 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.745046 min 2019-10-10T17:02:59.455Z,1570726979.455 [Default:CheckIn:E] Stopped 2019-10-10T17:02:59.455Z,1570726979.455 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn] Stopped 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn](INFO): Running loop #4 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn] Running Loop=4 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:02:59.456Z,1570726979.456 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:03:01.041Z,1570726981.041 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:03:01.432Z,1570726981.432 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164714.00,A,3648.32480,N,12149.72433,W,15.279,65.77,101019,,,D*71 2019-10-10T17:03:01.435Z,1570726981.435 [NAL9602](INFO): GPS fix at 20191010T164714: (36.805413, -121.828739) 2019-10-10T17:03:01.474Z,1570726981.474 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:03:01.474Z,1570726981.474 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:03:07.107Z,1570726987.107 [DVL_micro](ERROR): Failed to parse: :SA,+01.26,-08.14,339.7 2019-10-10T17:03:08.026Z,1570726988.026 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191010T134700/Courier0049.lzma 2019-10-10T17:03:10.032Z,1570726990.032 [DataOverHttps](INFO): Moved sent file to Logs/20191010T134700/Courier0049.lzma.bak 2019-10-10T17:03:10.032Z,1570726990.032 [DataOverHttps](INFO): SBD MOMSN=11871834 2019-10-10T17:03:24.905Z,1570727004.905 [DVL_micro](ERROR): Failed to parse:99.99,+99999.99,+9999.99 2019-10-10T17:03:27.214Z,1570727007.214 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191010T165820/Courier0000.lzma 2019-10-10T17:03:28.981Z,1570727008.981 [NAL9602](INFO): SBD MO Status=0, MOMSN=36167, MT Status=0, MTMSN=0 2019-10-10T17:03:28.981Z,1570727008.981 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:03:29.448Z,1570727009.448 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165820/Courier0000.lzma.bak 2019-10-10T17:03:29.448Z,1570727009.448 [DataOverHttps](INFO): SBD MOMSN=11871836 2019-10-10T17:03:46.315Z,1570727026.315 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20191010T165836/Courier0000.lzma 2019-10-10T17:03:48.320Z,1570727028.320 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0000.lzma.bak 2019-10-10T17:03:48.320Z,1570727028.320 [DataOverHttps](INFO): SBD MOMSN=11871839 2019-10-10T17:03:59.606Z,1570727039.606 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:04:06.190Z,1570727046.190 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191010T165836/Courier0003.lzma 2019-10-10T17:04:08.196Z,1570727048.196 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0003.lzma.bak 2019-10-10T17:04:08.196Z,1570727048.196 [DataOverHttps](INFO): SBD MOMSN=11871843 2019-10-10T17:04:25.354Z,1570727065.354 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20191010T134700/Express0050.lzma 2019-10-10T17:04:27.360Z,1570727067.360 [DataOverHttps](INFO): Moved sent file to Logs/20191010T134700/Express0050.lzma.bak 2019-10-10T17:04:27.360Z,1570727067.360 [DataOverHttps](INFO): SBD MOMSN=11871847 2019-10-10T17:04:46.347Z,1570727086.347 [DataOverHttps](INFO): Sending 296 bytes from file Logs/20191010T165820/Express0001.lzma 2019-10-10T17:04:48.352Z,1570727088.352 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165820/Express0001.lzma.bak 2019-10-10T17:04:48.352Z,1570727088.352 [DataOverHttps](INFO): SBD MOMSN=11871850 2019-10-10T17:05:06.290Z,1570727106.290 [DVL_micro](ERROR): Failed to parse: :R99,+9999.99,+9999.99,+9999.99 2019-10-10T17:05:37.743Z,1570727137.743 [DataOverHttps](INFO): Sending 335 bytes from file Logs/20191010T165836/Express0001.lzma 2019-10-10T17:05:39.748Z,1570727139.748 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0001.lzma.bak 2019-10-10T17:05:39.748Z,1570727139.748 [DataOverHttps](INFO): SBD MOMSN=11871857 2019-10-10T17:06:12.222Z,1570727172.222 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Express0004.lzma 2019-10-10T17:06:14.228Z,1570727174.228 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0004.lzma.bak 2019-10-10T17:06:14.228Z,1570727174.228 [DataOverHttps](INFO): SBD MOMSN=11871868 2019-10-10T17:06:15.796Z,1570727175.796 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:06:15.796Z,1570727175.796 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:06:15.796Z,1570727175.796 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:06:45.271Z,1570727205.271 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:06:45.271Z,1570727205.271 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+14.3,009.0,000 2019-10-10T17:07:51.186Z,1570727271.186 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-10-10T17:07:51.186Z,1570727271.186 [DVL_micro] Communications Fault, FailCount= 1 2019-10-10T17:07:51.186Z,1570727271.186 [DVL_micro](ERROR): Communications Fault 2019-10-10T17:07:51.187Z,1570727271.187 [DVL_micro](ERROR): Failed to parse: 2019-10-10T17:07:51.267Z,1570727271.267 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-10-10T17:07:51.602Z,1570727271.602 [DVL_micro](INFO): Powering down 2019-10-10T17:07:52.374Z,1570727272.374 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-10-10T17:07:52.374Z,1570727272.374 [DVL_micro] No Fault, FailCount= 1 2019-10-10T17:08:54.154Z,1570727334.154 [DVL_micro](ERROR): Failed to parse::RD,+9999.99,+9999.99,+9999.99,+9999.99 2019-10-10T17:09:22.036Z,1570727362.036 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:09:22.036Z,1570727362.036 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99, 2019-10-10T17:11:03.428Z,1570727463.428 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:11:03.428Z,1570727463.428 [DVL_micro](ERROR): Failed to parse: :BI,-01170,+02579,-00764,+0:BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-10-10T17:11:16.376Z,1570727476.376 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:11:16.377Z,1570727476.377 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:11:16.377Z,1570727476.377 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:11:16.378Z,1570727476.378 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:11:16.791Z,1570727476.791 [Default:CheckIn:D] Stopped 2019-10-10T17:11:16.791Z,1570727476.791 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.040922 min 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn:E] Stopped 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn] Stopped 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn](INFO): Running loop #5 2019-10-10T17:11:17.176Z,1570727477.176 [Default:CheckIn] Running Loop=5 2019-10-10T17:11:17.177Z,1570727477.177 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:11:17.177Z,1570727477.177 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:11:18.786Z,1570727478.786 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:11:19.179Z,1570727479.179 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165531.00,A,3648.44469,N,12149.11020,W,20.994,100.10,101019,,,D*4D 2019-10-10T17:11:19.181Z,1570727479.181 [NAL9602](INFO): GPS fix at 20191010T165531: (36.807412, -121.818503) 2019-10-10T17:11:19.210Z,1570727479.210 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:11:19.210Z,1570727479.210 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:11:27.038Z,1570727487.038 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0006.lzma 2019-10-10T17:11:29.044Z,1570727489.044 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0006.lzma.bak 2019-10-10T17:11:29.044Z,1570727489.044 [DataOverHttps](INFO): SBD MOMSN=11871882 2019-10-10T17:11:32.157Z,1570727492.157 [NAL9602](INFO): SBD MO Status=0, MOMSN=36168, MT Status=0, MTMSN=0 2019-10-10T17:11:32.157Z,1570727492.157 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:11:49.406Z,1570727509.406 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20191010T165836/Express0007.lzma 2019-10-10T17:11:51.180Z,1570727511.180 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0007.lzma.bak 2019-10-10T17:11:51.180Z,1570727511.180 [DataOverHttps](INFO): SBD MOMSN=11871889 2019-10-10T17:11:52.819Z,1570727512.819 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:11:52.819Z,1570727512.819 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:11:52.820Z,1570727512.820 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:12:02.852Z,1570727522.852 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:13:12.762Z,1570727592.762 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:13:12.762Z,1570727592.762 [DVL_micro](ERROR): Failed to parse: :TS,000000000000004.4,0000.0,1489.0,000 2019-10-10T17:15:16.892Z,1570727716.892 [DVL_micro](ERROR): Failed to parse: :B,+03436,-0258,I 2019-10-10T17:15:42.343Z,1570727742.343 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:15:42.343Z,1570727742.343 [DVL_micro](ERROR): Failed to parse: :TS,000000,35,0000.0,1489.0,000 2019-10-10T17:16:10.218Z,1570727770.218 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:16:10.219Z,1570727770.219 [DVL_micro](ERROR): Failed to parse: :TS,000000035.0,+14.4,000.0,000 2019-10-10T17:16:53.566Z,1570727813.566 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:16:53.566Z,1570727813.566 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:16:53.566Z,1570727813.566 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:16:53.566Z,1570727813.566 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:16:53.972Z,1570727813.972 [Default:CheckIn:D] Stopped 2019-10-10T17:16:53.972Z,1570727813.972 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 34.660592 min 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn:E] Stopped 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn] Stopped 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn](INFO): Running loop #6 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn] Running Loop=6 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:16:54.381Z,1570727814.381 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:16:55.998Z,1570727815.998 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:16:56.377Z,1570727816.377 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170108.00,A,3648.50941,N,12147.15846,W,6.531,119.37,101019,,,D*7D 2019-10-10T17:16:56.379Z,1570727816.379 [NAL9602](INFO): GPS fix at 20191010T170108: (36.808490, -121.785974) 2019-10-10T17:16:56.430Z,1570727816.430 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:16:56.431Z,1570727816.431 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:17:04.498Z,1570727824.498 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191010T165836/Courier0009.lzma 2019-10-10T17:17:06.504Z,1570727826.504 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0009.lzma.bak 2019-10-10T17:17:06.504Z,1570727826.504 [DataOverHttps](INFO): SBD MOMSN=11871910 2019-10-10T17:17:11.733Z,1570727831.733 [NAL9602](INFO): SBD MO Status=0, MOMSN=36169, MT Status=0, MTMSN=0 2019-10-10T17:17:11.733Z,1570727831.733 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:17:23.810Z,1570727843.810 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20191010T165836/Express0010.lzma 2019-10-10T17:17:25.816Z,1570727845.816 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0010.lzma.bak 2019-10-10T17:17:25.816Z,1570727845.816 [DataOverHttps](INFO): SBD MOMSN=11871917 2019-10-10T17:17:27.126Z,1570727847.126 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:17:27.127Z,1570727847.127 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:17:27.127Z,1570727847.127 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:17:42.426Z,1570727862.426 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:18:26.489Z,1570727906.489 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-10-10T17:18:26.489Z,1570727906.489 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-10-10T17:18:26.490Z,1570727906.490 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5. 2019-10-10T17:18:26.492Z,1570727906.492 [BPC1](INFO): Received data from all battery sticks. 2019-10-10T17:18:42.241Z,1570727922.241 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-10-10T17:19:10.111Z,1570727950.111 [DVL_micro](ERROR): Failed to parse: :WI,+01134,+00281,-02149,+00000,A 2019-10-10T17:21:31.925Z,1570728091.925 [DVL_micro](ERROR): Failed to parse: :WI,+00268,+01548,-02715,+00000,A 2019-10-10T17:22:27.700Z,1570728147.700 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:22:27.701Z,1570728147.701 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:22:27.701Z,1570728147.701 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:22:27.701Z,1570728147.701 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:22:28.098Z,1570728148.098 [Default:CheckIn:D] Stopped 2019-10-10T17:22:28.099Z,1570728148.099 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:22:28.511Z,1570728148.511 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.229374 min 2019-10-10T17:22:28.511Z,1570728148.511 [Default:CheckIn:E] Stopped 2019-10-10T17:22:28.511Z,1570728148.511 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:22:28.511Z,1570728148.511 [Default:CheckIn] Stopped 2019-10-10T17:22:28.511Z,1570728148.511 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:22:28.512Z,1570728148.512 [Default:CheckIn](INFO): Running loop #7 2019-10-10T17:22:28.512Z,1570728148.512 [Default:CheckIn] Running Loop=7 2019-10-10T17:22:28.512Z,1570728148.512 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:22:28.512Z,1570728148.512 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:22:30.134Z,1570728150.134 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:22:30.510Z,1570728150.510 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170642.00,A,3648.16353,N,12147.21671,W,0.097,227.08,101019,,,A*7A 2019-10-10T17:22:30.512Z,1570728150.512 [NAL9602](INFO): GPS fix at 20191010T170642: (36.802726, -121.786945) 2019-10-10T17:22:30.592Z,1570728150.592 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:22:30.592Z,1570728150.592 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:22:35.348Z,1570728155.348 [DVL_micro](ERROR): Failed to parse: :B,+00090,-02818,+00000,I 2019-10-10T17:22:39.742Z,1570728159.742 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20191010T165836/Courier0012.lzma 2019-10-10T17:22:41.748Z,1570728161.748 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0012.lzma.bak 2019-10-10T17:22:41.748Z,1570728161.748 [DataOverHttps](INFO): SBD MOMSN=11871932 2019-10-10T17:22:55.137Z,1570728175.137 [NAL9602](INFO): SBD MO Status=0, MOMSN=36170, MT Status=0, MTMSN=0 2019-10-10T17:22:55.137Z,1570728175.137 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:23:03.286Z,1570728183.286 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-10-10T17:23:03.286Z,1570728183.286 [DVL_micro] Communications Fault, FailCount= 1 2019-10-10T17:23:03.286Z,1570728183.286 [DVL_micro](ERROR): Communications Fault 2019-10-10T17:23:03.287Z,1570728183.287 [DVL_micro](ERROR): Failed to parse: 2019-10-10T17:23:03.330Z,1570728183.330 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-10-10T17:23:03.694Z,1570728183.694 [DVL_micro](INFO): Powering down 2019-10-10T17:23:04.504Z,1570728184.504 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-10-10T17:23:04.504Z,1570728184.504 [DVL_micro] No Fault, FailCount= 1 2019-10-10T17:23:16.591Z,1570728196.591 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20191010T165836/Express0013.lzma 2019-10-10T17:23:18.596Z,1570728198.596 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0013.lzma.bak 2019-10-10T17:23:18.596Z,1570728198.596 [DataOverHttps](INFO): SBD MOMSN=11871939 2019-10-10T17:23:20.205Z,1570728200.205 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:23:20.206Z,1570728200.206 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:23:20.206Z,1570728200.206 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:23:25.840Z,1570728205.840 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:24:16.381Z,1570728256.381 [DVL_micro](ERROR): Failed to parse: :WI,-00699,-00768,-01877,+00000,A 2019-10-10T17:25:12.092Z,1570728312.092 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:25:12.093Z,1570728312.093 [DVL_micro](ERROR): Failed to parse: :TS,000000005.0,+14.9,0000.0,1489.0,000 2019-10-10T17:25:57.760Z,1570728357.760 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:25:57.760Z,1570728357.760 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+99999.99,+9999.99 2019-10-10T17:26:25.619Z,1570728385.619 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:26:25.619Z,1570728385.619 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+14.9,0000.0,1489.0I,+02331,-03801,+00046,+00000,A 2019-10-10T17:26:53.506Z,1570728413.506 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:26:53.506Z,1570728413.506 [DVL_micro](ERROR): Failed to parse: :TS,000000000000015.0,0000.,000 2019-10-10T17:27:21.385Z,1570728441.385 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:27:21.385Z,1570728441.385 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0000.0,1489:WI,-06889,-07987,+00444,+00000,A 2019-10-10T17:28:20.800Z,1570728500.800 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:28:20.801Z,1570728500.801 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:28:20.801Z,1570728500.801 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:28:20.802Z,1570728500.802 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:28:21.192Z,1570728501.192 [Default:CheckIn:D] Stopped 2019-10-10T17:28:21.192Z,1570728501.192 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:28:21.601Z,1570728501.601 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.114274 min 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn:E] Stopped 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn] Stopped 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn](INFO): Running loop #8 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn] Running Loop=8 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:28:21.602Z,1570728501.602 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:28:23.202Z,1570728503.202 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:28:23.596Z,1570728503.596 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171234.00,A,3648.15922,N,12147.21713,W,0.136,205.23,101019,,,A*77 2019-10-10T17:28:23.610Z,1570728503.610 [NAL9602](INFO): GPS fix at 20191010T171234: (36.802654, -121.786952) 2019-10-10T17:28:23.633Z,1570728503.633 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:28:23.633Z,1570728503.633 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:28:33.410Z,1570728513.410 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191010T165836/Courier0015.lzma 2019-10-10T17:28:35.416Z,1570728515.416 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0015.lzma.bak 2019-10-10T17:28:35.416Z,1570728515.416 [DataOverHttps](INFO): SBD MOMSN=11871964 2019-10-10T17:28:41.005Z,1570728521.005 [NAL9602](INFO): SBD MO Status=0, MOMSN=36171, MT Status=0, MTMSN=0 2019-10-10T17:28:41.005Z,1570728521.005 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:28:52.650Z,1570728532.650 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191010T165836/Express0016.lzma 2019-10-10T17:28:54.656Z,1570728534.656 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0016.lzma.bak 2019-10-10T17:28:54.656Z,1570728534.656 [DataOverHttps](INFO): SBD MOMSN=11871969 2019-10-10T17:28:55.966Z,1570728535.967 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:28:55.967Z,1570728535.967 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:28:55.967Z,1570728535.967 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:29:11.687Z,1570728551.687 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:32:17.963Z,1570728737.963 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:32:17.963Z,1570728737.963 [DVL_micro](ERROR): Failed to parse: :BI,-00014,+2151,+00000,I 2019-10-10T17:33:56.575Z,1570728836.575 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:33:56.576Z,1570728836.576 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:33:56.576Z,1570728836.576 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:33:56.576Z,1570728836.576 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:33:56.977Z,1570728836.977 [Default:CheckIn:D] Stopped 2019-10-10T17:33:56.977Z,1570728836.977 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.710685 min 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn:E] Stopped 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn] Stopped 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn](INFO): Running loop #9 2019-10-10T17:33:57.364Z,1570728837.364 [Default:CheckIn] Running Loop=9 2019-10-10T17:33:57.365Z,1570728837.365 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:33:57.365Z,1570728837.365 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:33:58.978Z,1570728838.978 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:33:59.365Z,1570728839.365 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171809.00,A,3648.17853,N,12147.28202,W,0.117,303.89,101019,,,A*7E 2019-10-10T17:33:59.367Z,1570728839.367 [NAL9602](INFO): GPS fix at 20191010T171809: (36.802976, -121.788034) 2019-10-10T17:33:59.390Z,1570728839.390 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:33:59.390Z,1570728839.390 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:34:07.470Z,1570728847.470 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191010T165836/Courier0018.lzma 2019-10-10T17:34:09.476Z,1570728849.476 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0018.lzma.bak 2019-10-10T17:34:09.476Z,1570728849.476 [DataOverHttps](INFO): SBD MOMSN=11871982 2019-10-10T17:34:26.511Z,1570728866.511 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191010T165836/Express0019.lzma 2019-10-10T17:34:28.516Z,1570728868.516 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0019.lzma.bak 2019-10-10T17:34:28.516Z,1570728868.516 [DataOverHttps](INFO): SBD MOMSN=11871985 2019-10-10T17:34:30.099Z,1570728870.099 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:34:30.099Z,1570728870.099 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:34:30.099Z,1570728870.099 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:34:32.988Z,1570728872.988 [NAL9602](INFO): SBD MO Status=0, MOMSN=36172, MT Status=0, MTMSN=0 2019-10-10T17:34:32.988Z,1570728872.988 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:35:03.644Z,1570728903.644 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:35:33.149Z,1570728933.149 [DVL_micro](ERROR): Failed to parse: :B,+01197,-02023,+00000,I 2019-10-10T17:36:21.215Z,1570728981.215 [DVL_micro](ERROR): Failed to parse: :W,-00886,-01692,+00000,A 2019-10-10T17:37:27.068Z,1570729047.068 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:37:27.069Z,1570729047.069 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+150,1489.0,,-01420,-02180,-01614,+00000,A 2019-10-10T17:39:30.715Z,1570729170.715 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:39:30.715Z,1570729170.715 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:39:30.716Z,1570729170.716 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:39:30.716Z,1570729170.716 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:39:31.142Z,1570729171.142 [Default:CheckIn:D] Stopped 2019-10-10T17:39:31.142Z,1570729171.142 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:39:31.522Z,1570729171.522 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 57.280094 min 2019-10-10T17:39:31.522Z,1570729171.522 [Default:CheckIn:E] Stopped 2019-10-10T17:39:31.522Z,1570729171.523 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn] Stopped 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn](INFO): Running loop #10 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn] Running Loop=10 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:39:31.523Z,1570729171.523 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:39:33.126Z,1570729173.126 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:39:33.537Z,1570729173.537 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172343.00,A,3648.17057,N,12147.27930,W,0.253,224.02,101019,,,A*75 2019-10-10T17:39:33.539Z,1570729173.539 [NAL9602](INFO): GPS fix at 20191010T172343: (36.802843, -121.787988) 2019-10-10T17:39:33.561Z,1570729173.561 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:39:33.561Z,1570729173.561 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:39:41.726Z,1570729181.726 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0021.lzma 2019-10-10T17:39:43.732Z,1570729183.732 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0021.lzma.bak 2019-10-10T17:39:43.732Z,1570729183.732 [DataOverHttps](INFO): SBD MOMSN=11872009 2019-10-10T17:40:00.726Z,1570729200.726 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191010T165836/Express0022.lzma 2019-10-10T17:40:02.732Z,1570729202.732 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0022.lzma.bak 2019-10-10T17:40:02.732Z,1570729202.732 [DataOverHttps](INFO): SBD MOMSN=11872012 2019-10-10T17:40:04.258Z,1570729204.258 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:40:04.258Z,1570729204.258 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:40:04.258Z,1570729204.258 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:41:32.704Z,1570729292.704 [DVL_micro](ERROR): Failed to parse: :0000000005.8,0000.0,1489.0,000 2019-10-10T17:41:42.842Z,1570729302.842 [DVL_micro](ERROR): Failed to parse: :WI,+00714,-03853,-01236,+00000,A 2019-10-10T17:42:06.265Z,1570729326.265 [NAL9602](INFO): SBD MO Status=0, MOMSN=36173, MT Status=0, MTMSN=0 2019-10-10T17:42:06.265Z,1570729326.265 [NAL9602](INFO): No messages in MT queue 2019-10-10T17:42:23.242Z,1570729343.242 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:42:23.242Z,1570729343.242 [DVL_micro](ERROR): Failed to parse: :BI,-01797,-0803,+00000+0000000000000.00,+00000000.00,9999.99,000.00 2019-10-10T17:42:36.977Z,1570729356.977 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:44:45.074Z,1570729485.074 [DVL_micro](ERROR): Failed to parse: 9.99,+9999.99,+9999.99,+9999.99 2019-10-10T17:45:04.858Z,1570729504.858 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:45:04.858Z,1570729504.858 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:45:04.859Z,1570729504.859 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:45:04.859Z,1570729504.859 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:45:05.277Z,1570729505.277 [Default:CheckIn:D] Stopped 2019-10-10T17:45:05.277Z,1570729505.277 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 62.849007 min 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn:E] Stopped 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn] Stopped 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn](INFO): Running loop #11 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn] Running Loop=11 2019-10-10T17:45:05.670Z,1570729505.670 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:45:05.671Z,1570729505.671 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:45:07.273Z,1570729507.273 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:45:07.694Z,1570729507.694 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172917.00,A,3648.16824,N,12147.28358,W,0.214,224.02,101019,,,A*7B 2019-10-10T17:45:07.696Z,1570729507.696 [NAL9602](INFO): GPS fix at 20191010T172917: (36.802804, -121.788060) 2019-10-10T17:45:07.729Z,1570729507.729 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:45:07.729Z,1570729507.729 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:45:15.354Z,1570729515.354 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0024.lzma 2019-10-10T17:45:17.360Z,1570729517.360 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0024.lzma.bak 2019-10-10T17:45:17.360Z,1570729517.360 [DataOverHttps](INFO): SBD MOMSN=11872028 2019-10-10T17:45:20.604Z,1570729520.604 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:45:20.604Z,1570729520.604 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+150,1489.0,000 2019-10-10T17:45:34.482Z,1570729534.482 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191010T165836/Express0025.lzma 2019-10-10T17:45:36.488Z,1570729536.488 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0025.lzma.bak 2019-10-10T17:45:36.488Z,1570729536.488 [DataOverHttps](INFO): SBD MOMSN=11872031 2019-10-10T17:45:38.010Z,1570729538.010 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:45:38.010Z,1570729538.010 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:45:38.010Z,1570729538.010 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:46:46.668Z,1570729606.668 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:46:46.668Z,1570729606.668 [DVL_micro](ERROR): Failed to parse: :BI,-01517,+1624,+00000,I 2019-10-10T17:50:10.287Z,1570729810.287 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-10T17:50:38.591Z,1570729838.591 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:50:38.591Z,1570729838.591 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:50:38.591Z,1570729838.591 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:50:38.591Z,1570729838.591 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:50:38.999Z,1570729838.999 [Default:CheckIn:D] Stopped 2019-10-10T17:50:38.999Z,1570729838.999 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 68.411043 min 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn:E] Stopped 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn] Stopped 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn](INFO): Running loop #12 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn] Running Loop=12 2019-10-10T17:50:39.427Z,1570729839.427 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:50:39.428Z,1570729839.428 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:50:41.002Z,1570729841.002 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:50:41.394Z,1570729841.394 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173450.00,A,3648.16969,N,12147.28577,W,0.292,224.02,101019,,,A*79 2019-10-10T17:50:41.396Z,1570729841.396 [NAL9602](INFO): GPS fix at 20191010T173450: (36.802828, -121.788096) 2019-10-10T17:50:41.419Z,1570729841.419 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:50:41.419Z,1570729841.419 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:50:49.490Z,1570729849.490 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0027.lzma 2019-10-10T17:50:51.496Z,1570729851.496 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0027.lzma.bak 2019-10-10T17:50:51.496Z,1570729851.496 [DataOverHttps](INFO): SBD MOMSN=11872047 2019-10-10T17:51:08.469Z,1570729868.469 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20191010T165836/Express0028.lzma 2019-10-10T17:51:10.472Z,1570729870.472 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0028.lzma.bak 2019-10-10T17:51:10.472Z,1570729870.472 [DataOverHttps](INFO): SBD MOMSN=11872050 2019-10-10T17:51:12.157Z,1570729872.157 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:51:12.157Z,1570729872.157 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:51:12.157Z,1570729872.157 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:51:13.713Z,1570729873.713 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:51:14.927Z,1570729874.927 [DVL_micro](ERROR): Failed to parse: :WI,+0040,-01828A 2019-10-10T17:52:10.681Z,1570729930.681 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:52:10.681Z,1570729930.681 [DVL_micro](ERROR): Failed to parse: :TS,000000005.0,+16.31489.0,000 2019-10-10T17:52:58.764Z,1570729978.764 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:52:58.765Z,1570729978.765 [DVL_micro](ERROR): Failed to parse: :TS,000000005.0,+16.31489.0,0-01322,-0371,+000I,-01322,-01354,-01371,+00000,I 2019-10-10T17:55:43.177Z,1570730143.177 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T17:55:43.177Z,1570730143.177 [DVL_micro](ERROR): Failed to parse: :TS,00000000000,+16.4,0000.0,1489.0,000 2019-10-10T17:56:12.705Z,1570730172.705 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T17:56:12.705Z,1570730172.705 [Default:CheckIn:C.Wait] Stopped 2019-10-10T17:56:12.705Z,1570730172.705 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T17:56:12.706Z,1570730172.706 [Default:CheckIn:D] Running Loop=1 2019-10-10T17:56:13.099Z,1570730173.099 [Default:CheckIn:D] Stopped 2019-10-10T17:56:13.100Z,1570730173.100 [Default:CheckIn:E] Running Loop=1 2019-10-10T17:56:13.515Z,1570730173.515 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.979386 min 2019-10-10T17:56:13.515Z,1570730173.515 [Default:CheckIn:E] Stopped 2019-10-10T17:56:13.515Z,1570730173.515 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T17:56:13.515Z,1570730173.515 [Default:CheckIn] Stopped 2019-10-10T17:56:13.515Z,1570730173.515 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T17:56:13.516Z,1570730173.516 [Default:CheckIn](INFO): Running loop #13 2019-10-10T17:56:13.516Z,1570730173.516 [Default:CheckIn] Running Loop=13 2019-10-10T17:56:13.516Z,1570730173.516 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T17:56:13.516Z,1570730173.516 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T17:56:15.114Z,1570730175.114 [NAL9602](DEBUG): Fix Requested 2019-10-10T17:56:15.511Z,1570730175.511 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174024.00,A,3648.16904,N,12147.28219,W,0.194,0.00,101019,,,A*7E 2019-10-10T17:56:15.513Z,1570730175.513 [NAL9602](INFO): GPS fix at 20191010T174024: (36.802817, -121.788037) 2019-10-10T17:56:15.536Z,1570730175.536 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T17:56:15.536Z,1570730175.536 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T17:56:23.025Z,1570730183.025 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191010T165836/Courier0030.lzma 2019-10-10T17:56:25.028Z,1570730185.028 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0030.lzma.bak 2019-10-10T17:56:25.028Z,1570730185.028 [DataOverHttps](INFO): SBD MOMSN=11872062 2019-10-10T17:56:42.218Z,1570730202.218 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191010T165836/Express0031.lzma 2019-10-10T17:56:44.224Z,1570730204.224 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0031.lzma.bak 2019-10-10T17:56:44.224Z,1570730204.224 [DataOverHttps](INFO): SBD MOMSN=11872065 2019-10-10T17:56:45.832Z,1570730205.832 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T17:56:45.833Z,1570730205.833 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T17:56:45.833Z,1570730205.833 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T17:56:46.218Z,1570730206.218 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-10-10T17:56:46.294Z,1570730206.294 [NAL9602](FAULT): received: +CSQ:0 OK173, 0, 0, 0, 0 OK 2019-10-10T17:56:46.294Z,1570730206.294 [NAL9602] Data Fault, FailCount= 1 2019-10-10T17:56:46.294Z,1570730206.294 [NAL9602](ERROR): Data Fault 2019-10-10T17:56:46.353Z,1570730206.353 [CBIT](ERROR): Data Fault in component: NAL9602 2019-10-10T17:56:46.607Z,1570730206.607 [NAL9602](INFO): Powering down 2019-10-10T17:56:47.500Z,1570730207.500 [CBIT](INFO): Clearing failed state for component NAL9602 2019-10-10T17:56:47.500Z,1570730207.500 [NAL9602] No Fault, FailCount= 1 2019-10-10T17:56:51.459Z,1570730211.459 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99,+9999.99 2019-10-10T17:57:16.924Z,1570730236.924 [NAL9602](INFO): Powering up NAL9602 2019-10-10T17:57:27.880Z,1570730247.880 [NAL9602](INFO): NAL9602 initialized 2019-10-10T17:57:58.924Z,1570730278.924 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T17:59:08.034Z,1570730348.034 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:59:08.034Z,1570730348.034 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99, 2019-10-10T17:59:18.142Z,1570730358.142 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T17:59:18.142Z,1570730358.142 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.999,+9999.99 2019-10-10T18:00:26.417Z,1570730426.417 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:00:26.417Z,1570730426.417 [DVL_micro](ERROR): Failed to parse: :BI,-0047,-02110,+00000,I 2019-10-10T18:00:36.524Z,1570730436.524 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+16.6,0000.0,1489.0,000 2019-10-10T18:01:46.433Z,1570730506.433 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:01:46.434Z,1570730506.434 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:01:46.434Z,1570730506.434 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:01:46.434Z,1570730506.434 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:01:46.827Z,1570730506.827 [Default:CheckIn:D] Stopped 2019-10-10T18:01:46.827Z,1570730506.827 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:01:47.242Z,1570730507.242 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 79.541520 min 2019-10-10T18:01:47.242Z,1570730507.242 [Default:CheckIn:E] Stopped 2019-10-10T18:01:47.242Z,1570730507.242 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:01:47.242Z,1570730507.242 [Default:CheckIn] Stopped 2019-10-10T18:01:47.242Z,1570730507.242 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:01:47.243Z,1570730507.243 [Default:CheckIn](INFO): Running loop #14 2019-10-10T18:01:47.243Z,1570730507.243 [Default:CheckIn] Running Loop=14 2019-10-10T18:01:47.243Z,1570730507.243 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:01:47.243Z,1570730507.243 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:01:48.842Z,1570730508.842 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:01:51.252Z,1570730511.252 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-10T18:01:52.082Z,1570730512.082 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:01:54.503Z,1570730514.503 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:01:56.522Z,1570730516.522 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:01:58.938Z,1570730518.938 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:01.766Z,1570730521.766 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:05.010Z,1570730525.010 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:07.822Z,1570730527.822 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:10.650Z,1570730530.650 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:13.886Z,1570730533.886 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:16.714Z,1570730536.714 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:19.542Z,1570730539.542 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:22.765Z,1570730542.765 [DVL_micro](ERROR): Failed to parse: :BI,-01103,-02080,-01213,+00000,I 2019-10-10T18:02:22.778Z,1570730542.778 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:25.603Z,1570730545.603 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:28.842Z,1570730548.842 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:31.670Z,1570730551.670 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:32.864Z,1570730552.864 [DVL_micro](ERROR): Failed to parse: :T00000000,35.0,+16.7,0000.0,1489.0,000 2019-10-10T18:02:34.894Z,1570730554.894 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:37.754Z,1570730557.754 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:40.950Z,1570730560.950 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:43.790Z,1570730563.790 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:47.018Z,1570730567.018 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:49.838Z,1570730569.838 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:53.082Z,1570730573.082 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:55.902Z,1570730575.902 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:02:58.726Z,1570730578.726 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:01.966Z,1570730581.966 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:04.795Z,1570730584.795 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:07.614Z,1570730587.614 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:10.850Z,1570730590.850 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:13.678Z,1570730593.678 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:16.914Z,1570730596.914 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:19.741Z,1570730599.741 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:22.966Z,1570730602.966 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:25.806Z,1570730605.806 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:29.042Z,1570730609.042 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:31.858Z,1570730611.858 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:35.090Z,1570730615.090 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:37.921Z,1570730617.921 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:41.166Z,1570730621.166 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:43.978Z,1570730623.978 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:46.806Z,1570730626.806 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:50.038Z,1570730630.038 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:52.866Z,1570730632.866 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:55.698Z,1570730635.698 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:03:58.922Z,1570730638.922 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:01.362Z,1570730641.362 [DVL_micro](ERROR): Failed to parse::WI,-00029,+01929,-01996,+00000,A 2019-10-10T18:04:01.758Z,1570730641.758 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:04.982Z,1570730644.982 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:07.822Z,1570730647.822 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:11.050Z,1570730651.050 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:13.887Z,1570730653.887 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:17.106Z,1570730657.106 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:19.934Z,1570730659.934 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:23.174Z,1570730663.174 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:25.994Z,1570730665.994 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:29.234Z,1570730669.234 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:32.054Z,1570730672.054 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:35.282Z,1570730675.282 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:38.122Z,1570730678.122 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:40.942Z,1570730680.942 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:43.766Z,1570730683.766 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:47.002Z,1570730687.002 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:49.831Z,1570730689.831 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:53.062Z,1570730693.062 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:55.891Z,1570730695.891 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:04:59.146Z,1570730699.146 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:01.990Z,1570730701.990 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:05.182Z,1570730705.182 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:08.006Z,1570730708.006 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:11.241Z,1570730711.241 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:14.074Z,1570730714.074 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:17.306Z,1570730717.306 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:20.130Z,1570730720.130 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:23.358Z,1570730723.358 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:26.194Z,1570730726.194 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:29.432Z,1570730729.432 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:32.274Z,1570730732.274 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:35.482Z,1570730735.482 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:38.310Z,1570730738.310 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:39.918Z,1570730739.918 [DVL_micro](ERROR): Failed to parse:923,-00483,-00958,+00000,I 2019-10-10T18:05:41.138Z,1570730741.138 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:43.966Z,1570730743.966 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:47.210Z,1570730747.210 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:50.018Z,1570730750.018 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:05:50.018Z,1570730750.018 [DVL_micro](ERROR): Failed to parse: :BI,-0618,-01109,+00000,I 2019-10-10T18:05:50.030Z,1570730750.030 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:53.258Z,1570730753.258 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:56.089Z,1570730756.089 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:05:59.319Z,1570730759.319 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:02.146Z,1570730762.146 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:05.379Z,1570730765.379 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:08.210Z,1570730768.210 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:10.212Z,1570730770.212 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T18:06:10.213Z,1570730770.213 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,00.0,1489.0,000 2019-10-10T18:06:11.030Z,1570730771.030 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:14.266Z,1570730774.266 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:17.090Z,1570730777.090 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:06:17.495Z,1570730777.495 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175024.00,A,3648.16558,N,12147.27894,W,0.350,307.83,101019,,,A*7F 2019-10-10T18:06:17.497Z,1570730777.497 [NAL9602](INFO): GPS fix at 20191010T175024: (36.802760, -121.787982) 2019-10-10T18:06:17.554Z,1570730777.554 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:06:17.554Z,1570730777.554 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:06:25.218Z,1570730785.218 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20191010T165836/Courier0033.lzma 2019-10-10T18:06:27.224Z,1570730787.224 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0033.lzma.bak 2019-10-10T18:06:27.224Z,1570730787.224 [DataOverHttps](INFO): SBD MOMSN=11872088 2019-10-10T18:06:44.351Z,1570730804.351 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20191010T165836/Express0034.lzma 2019-10-10T18:06:46.356Z,1570730806.356 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0034.lzma.bak 2019-10-10T18:06:46.356Z,1570730806.356 [DataOverHttps](INFO): SBD MOMSN=11872092 2019-10-10T18:06:47.839Z,1570730807.839 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:06:47.839Z,1570730807.839 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:06:47.839Z,1570730807.839 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:06:50.223Z,1570730810.223 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T18:11:48.417Z,1570731108.417 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:11:48.417Z,1570731108.417 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:11:48.417Z,1570731108.417 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:11:48.417Z,1570731108.417 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:11:48.796Z,1570731108.796 [Default:CheckIn:D] Stopped 2019-10-10T18:11:48.796Z,1570731108.796 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:11:49.196Z,1570731109.196 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.574333 min 2019-10-10T18:11:49.196Z,1570731109.196 [Default:CheckIn:E] Stopped 2019-10-10T18:11:49.196Z,1570731109.196 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn] Stopped 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn](INFO): Running loop #15 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn] Running Loop=15 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:11:49.197Z,1570731109.197 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:11:50.818Z,1570731110.818 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:11:51.192Z,1570731111.192 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175558.00,A,3648.16766,N,12147.26913,W,0.194,0.00,101019,,,A*74 2019-10-10T18:11:51.195Z,1570731111.195 [NAL9602](INFO): GPS fix at 20191010T175558: (36.802794, -121.787819) 2019-10-10T18:11:51.256Z,1570731111.256 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:11:51.256Z,1570731111.256 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:12:01.282Z,1570731121.282 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0036.lzma 2019-10-10T18:12:03.296Z,1570731123.296 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0036.lzma.bak 2019-10-10T18:12:03.296Z,1570731123.296 [DataOverHttps](INFO): SBD MOMSN=11872132 2019-10-10T18:12:09.775Z,1570731129.775 [NAL9602](INFO): SBD MO Status=2, MOMSN=36174, MT Status=2, MTMSN=0 2019-10-10T18:12:09.776Z,1570731129.776 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-10T18:12:13.817Z,1570731133.817 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:12:13.817Z,1570731133.817 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+99999.99,+9999.99 2019-10-10T18:12:20.606Z,1570731140.606 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191010T165836/Express0037.lzma 2019-10-10T18:12:22.612Z,1570731142.612 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0037.lzma.bak 2019-10-10T18:12:22.612Z,1570731142.612 [DataOverHttps](INFO): SBD MOMSN=11872137 2019-10-10T18:12:23.954Z,1570731143.954 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:12:23.955Z,1570731143.955 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:12:23.955Z,1570731143.955 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:15:12.788Z,1570731312.788 [DVL_micro](ERROR): Failed to parse: :WI,-00708,-00915,-01522,+00000,A 2019-10-10T18:16:33.592Z,1570731393.592 [DVL_micro](ERROR): Failed to parse: :WI,-00678,+00894,-01582,+00000,A 2019-10-10T18:16:53.421Z,1570731413.421 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-10T18:17:24.118Z,1570731444.118 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T18:17:24.545Z,1570731444.545 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:17:24.545Z,1570731444.545 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:17:24.545Z,1570731444.545 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:17:24.545Z,1570731444.545 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:17:24.961Z,1570731444.961 [Default:CheckIn:D] Stopped 2019-10-10T18:17:24.962Z,1570731444.962 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:17:25.354Z,1570731445.354 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 95.177091 min 2019-10-10T18:17:25.354Z,1570731445.354 [Default:CheckIn:E] Stopped 2019-10-10T18:17:25.354Z,1570731445.354 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn] Stopped 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn](INFO): Running loop #16 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn] Running Loop=16 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:17:25.355Z,1570731445.355 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:17:26.950Z,1570731446.950 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:17:27.347Z,1570731447.347 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180133.00,A,3648.16859,N,12147.27793,W,0.350,0.00,101019,,,A*79 2019-10-10T18:17:27.349Z,1570731447.349 [NAL9602](INFO): GPS fix at 20191010T180133: (36.802810, -121.787965) 2019-10-10T18:17:27.372Z,1570731447.372 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:17:27.372Z,1570731447.372 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:17:34.710Z,1570731454.710 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0039.lzma 2019-10-10T18:17:36.724Z,1570731456.724 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0039.lzma.bak 2019-10-10T18:17:36.724Z,1570731456.724 [DataOverHttps](INFO): SBD MOMSN=11872166 2019-10-10T18:17:39.073Z,1570731459.073 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T18:17:39.074Z,1570731459.074 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+1.0,1489.0I,-00795,-03120,-00781,+00000,A 2019-10-10T18:17:53.904Z,1570731473.904 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20191010T165836/Express0040.lzma 2019-10-10T18:17:55.896Z,1570731475.896 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0040.lzma.bak 2019-10-10T18:17:55.896Z,1570731475.896 [DataOverHttps](INFO): SBD MOMSN=11872169 2019-10-10T18:17:57.279Z,1570731477.279 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:17:57.279Z,1570731477.279 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:17:57.279Z,1570731477.279 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:17:58.051Z,1570731478.051 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-10-10T18:17:58.126Z,1570731478.126 [NAL9602](FAULT): received: +CSQ:0 OK174, 2, 0, 0, 0 OK 2019-10-10T18:17:58.126Z,1570731478.126 [NAL9602] Data Fault, FailCount= 1 2019-10-10T18:17:58.126Z,1570731478.126 [NAL9602](ERROR): Data Fault 2019-10-10T18:17:58.191Z,1570731478.191 [CBIT](ERROR): Data Fault in component: NAL9602 2019-10-10T18:17:58.450Z,1570731478.450 [NAL9602](INFO): Powering down 2019-10-10T18:17:59.383Z,1570731479.383 [CBIT](INFO): Clearing failed state for component NAL9602 2019-10-10T18:17:59.383Z,1570731479.383 [NAL9602] No Fault, FailCount= 1 2019-10-10T18:18:28.757Z,1570731508.757 [NAL9602](INFO): Powering up NAL9602 2019-10-10T18:18:39.672Z,1570731519.672 [NAL9602](INFO): NAL9602 initialized 2019-10-10T18:19:10.769Z,1570731550.769 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T18:19:35.024Z,1570731575.024 [DVL_micro](ERROR): Failed to parse:99.99,+9999.99,+9999.99,+9999.99 2019-10-10T18:19:42.688Z,1570731582.688 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:19:42.689Z,1570731582.689 [DVL_micro](ERROR): Failed to parse: :BI,-00241,+1309,+00000,I 2019-10-10T18:20:48.139Z,1570731648.139 [DVL_micro](ERROR): Failed to parse: :WI,-00994,-00242,-01349,+00000,A 2019-10-10T18:21:05.946Z,1570731665.946 [DVL_micro](ERROR): only read 0 of 4 data items 2019-10-10T18:21:05.950Z,1570731665.950 [DVL_micro](ERROR): Failed to parse: :RD,,+9999.999,+9999.99 2019-10-10T18:22:57.882Z,1570731777.882 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:22:57.882Z,1570731777.882 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:22:57.882Z,1570731777.882 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:22:57.882Z,1570731777.882 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:22:58.299Z,1570731778.299 [Default:CheckIn:D] Stopped 2019-10-10T18:22:58.299Z,1570731778.299 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:22:58.706Z,1570731778.706 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 100.732707 min 2019-10-10T18:22:58.706Z,1570731778.706 [Default:CheckIn:E] Stopped 2019-10-10T18:22:58.706Z,1570731778.706 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn] Stopped 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn](INFO): Running loop #17 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn] Running Loop=17 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:22:58.707Z,1570731778.707 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:23:00.282Z,1570731780.282 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:23:00.682Z,1570731780.682 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180706.00,A,3648.16626,N,12147.27657,W,0.661,150.59,101019,,,A*79 2019-10-10T18:23:00.684Z,1570731780.684 [NAL9602](INFO): GPS fix at 20191010T180706: (36.802771, -121.787943) 2019-10-10T18:23:00.707Z,1570731780.707 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:23:00.707Z,1570731780.707 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:23:02.296Z,1570731782.296 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-10-10T18:23:08.770Z,1570731788.770 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191010T165836/Courier0042.lzma 2019-10-10T18:23:10.776Z,1570731790.776 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0042.lzma.bak 2019-10-10T18:23:10.776Z,1570731790.776 [DataOverHttps](INFO): SBD MOMSN=11872199 2019-10-10T18:23:22.104Z,1570731802.104 [DVL_micro](ERROR): only read 2 of 4 data items 2019-10-10T18:23:22.104Z,1570731802.104 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,++9999.99 2019-10-10T18:23:28.082Z,1570731808.082 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20191010T165836/Express0043.lzma 2019-10-10T18:23:30.090Z,1570731810.090 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0043.lzma.bak 2019-10-10T18:23:30.090Z,1570731810.090 [DataOverHttps](INFO): SBD MOMSN=11872202 2019-10-10T18:23:31.418Z,1570731811.418 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:23:31.418Z,1570731811.418 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:23:31.418Z,1570731811.418 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:23:32.997Z,1570731812.997 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T18:24:15.019Z,1570731855.019 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:24:15.019Z,1570731855.019 [DVL_micro](ERROR): Failed to parse: :BI,+00126,+1235,+00000,I 2019-10-10T18:24:37.705Z,1570731877.705 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99,+9999.99 2019-10-10T18:26:07.542Z,1570731967.542 [BPC1](ERROR): Battery stick #38 (s/n: 0139) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-10-10T18:26:07.543Z,1570731967.543 [BPC1](ERROR): Battery stick #39 (s/n: 00F0) reported TERMINATE_DISCHARGE_ALARM. Status code: 0x48C0. 2019-10-10T18:26:07.544Z,1570731967.544 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5. 2019-10-10T18:26:07.546Z,1570731967.546 [BPC1](INFO): Received data from all battery sticks. 2019-10-10T18:27:54.149Z,1570732074.149 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T18:27:54.149Z,1570732074.149 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,+1.0,1489.0,000 2019-10-10T18:28:32.155Z,1570732112.155 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:28:32.155Z,1570732112.155 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:28:32.155Z,1570732112.155 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:28:32.155Z,1570732112.155 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:28:32.564Z,1570732112.564 [Default:CheckIn:D] Stopped 2019-10-10T18:28:32.564Z,1570732112.564 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:28:32.958Z,1570732112.958 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 106.303792 min 2019-10-10T18:28:32.958Z,1570732112.958 [Default:CheckIn:E] Stopped 2019-10-10T18:28:32.958Z,1570732112.958 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:28:32.958Z,1570732112.958 [Default:CheckIn] Stopped 2019-10-10T18:28:32.974Z,1570732112.974 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:28:32.974Z,1570732112.974 [Default:CheckIn](INFO): Running loop #18 2019-10-10T18:28:32.974Z,1570732112.974 [Default:CheckIn] Running Loop=18 2019-10-10T18:28:32.975Z,1570732112.975 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:28:32.975Z,1570732112.975 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:28:34.566Z,1570732114.566 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:28:34.968Z,1570732114.968 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181240.00,A,3648.16937,N,12147.28309,W,0.019,150.59,101019,,,A*78 2019-10-10T18:28:34.970Z,1570732114.970 [NAL9602](INFO): GPS fix at 20191010T181240: (36.802823, -121.788051) 2019-10-10T18:28:34.992Z,1570732114.992 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:28:34.992Z,1570732114.992 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:28:44.778Z,1570732124.778 [DataOverHttps](INFO): Sending 79 bytes from file Logs/20191010T165836/Courier0045.lzma 2019-10-10T18:28:46.784Z,1570732126.784 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0045.lzma.bak 2019-10-10T18:28:46.784Z,1570732126.784 [DataOverHttps](INFO): SBD MOMSN=11872221 2019-10-10T18:28:57.708Z,1570732137.708 [NAL9602](INFO): SBD MO Status=2, MOMSN=36174, MT Status=2, MTMSN=0 2019-10-10T18:28:57.708Z,1570732137.708 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-10-10T18:29:03.798Z,1570732143.798 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20191010T165836/Express0046.lzma 2019-10-10T18:29:05.805Z,1570732145.805 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0046.lzma.bak 2019-10-10T18:29:05.805Z,1570732145.805 [DataOverHttps](INFO): SBD MOMSN=11872224 2019-10-10T18:29:07.442Z,1570732147.442 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:29:07.443Z,1570732147.443 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:29:07.443Z,1570732147.443 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:29:12.265Z,1570732152.265 [DVL_micro](ERROR): Failed to parse: :T00000000,35.0,+17.0,0000.0,14 2019-10-10T18:29:13.476Z,1570732153.476 [NAL9602](INFO): SBD MO Status=0, MOMSN=36174, MT Status=0, MTMSN=0 2019-10-10T18:29:13.476Z,1570732153.476 [NAL9602](INFO): No messages in MT queue 2019-10-10T18:29:22.355Z,1570732162.355 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 66 2019-10-10T18:29:22.357Z,1570732162.357 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-10-10T18:29:44.166Z,1570732184.166 [NAL9602](INFO): Not Powering down - fast GPS 2019-10-10T18:30:05.200Z,1570732205.200 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T18:30:05.200Z,1570732205.200 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+16.9,0000.0,00 2019-10-10T18:31:51.038Z,1570732311.038 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:31:51.039Z,1570732311.039 [DVL_micro](ERROR): Failed to parse: :BI,+00636,+0090,+00000,I 2019-10-10T18:33:06.580Z,1570732386.580 [DVL_micro](ERROR): Failed to parse: :SA,-03.42,+01.80,338.7 2019-10-10T18:33:14.266Z,1570732394.266 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:33:14.266Z,1570732394.266 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-10-10T18:34:08.008Z,1570732448.008 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-10-10T18:34:08.008Z,1570732448.008 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:34:08.008Z,1570732448.008 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:34:08.009Z,1570732448.009 [Default:CheckIn:D] Running Loop=1 2019-10-10T18:34:08.422Z,1570732448.422 [Default:CheckIn:D] Stopped 2019-10-10T18:34:08.422Z,1570732448.422 [Default:CheckIn:E] Running Loop=1 2019-10-10T18:34:08.825Z,1570732448.825 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 111.901424 min 2019-10-10T18:34:08.825Z,1570732448.825 [Default:CheckIn:E] Stopped 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn] Stopped 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn](INFO): Running loop #19 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn] Running Loop=19 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-10-10T18:34:08.826Z,1570732448.826 [Default:CheckIn:Read_GPS] Running Loop=1 2019-10-10T18:34:10.418Z,1570732450.418 [NAL9602](DEBUG): Fix Requested 2019-10-10T18:34:10.812Z,1570732450.812 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181815.00,A,3648.15304,N,12147.25901,W,11.002,46.82,101019,,,A*7E 2019-10-10T18:34:10.815Z,1570732450.815 [NAL9602](INFO): GPS fix at 20191010T181815: (36.802551, -121.787650) 2019-10-10T18:34:10.858Z,1570732450.858 [Default:CheckIn:Read_GPS] Stopped 2019-10-10T18:34:10.858Z,1570732450.858 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-10-10T18:34:17.278Z,1570732457.278 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-10-10T18:34:17.279Z,1570732457.279 [DVL_micro](ERROR): Failed to parse::TS,00000000000000,35.0,+16.8,0000.0,1489.WI,-0306,-00703,+00000,A 2019-10-10T18:34:18.358Z,1570732458.358 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191010T165836/Courier0048.lzma 2019-10-10T18:34:20.364Z,1570732460.364 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Courier0048.lzma.bak 2019-10-10T18:34:20.364Z,1570732460.364 [DataOverHttps](INFO): SBD MOMSN=11872242 2019-10-10T18:34:29.810Z,1570732469.810 [DVL_micro](ERROR): Failed to parse: :.99,+9999.99,+9999.99,+9999.99 2019-10-10T18:34:37.954Z,1570732477.954 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191010T165836/Express0049.lzma 2019-10-10T18:34:39.976Z,1570732479.976 [DataOverHttps](INFO): Moved sent file to Logs/20191010T165836/Express0049.lzma.bak 2019-10-10T18:34:39.976Z,1570732479.976 [DataOverHttps](INFO): SBD MOMSN=11872245 2019-10-10T18:34:41.563Z,1570732481.563 [Default:CheckIn:Read_Iridium] Stopped 2019-10-10T18:34:41.563Z,1570732481.563 [Default:CheckIn:C.Wait] Running Loop=1 2019-10-10T18:34:41.563Z,1570732481.563 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-10-10T18:36:00.709Z,1570732560.709 [DVL_micro](ERROR): Failed to parse: 34,+02977,-02445,+00000,I 2019-10-10T18:36:43.534Z,1570732603.534 [DVL_micro](ERROR): Failed to parse: :WI,+00688,-01098,-01284,+00000,A 2019-10-10T18:36:56.067Z,1570732616.067 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:36:56.067Z,1570732616.067 [DVL_micro](ERROR): Failed to parse: :BI,-2881,-02342,+0:BD,+00000000.00,+00000000.00,+00000000.00,999900 2019-10-10T18:37:03.775Z,1570732623.775 [DVL_micro](ERROR): only read 3 of 4 data items 2019-10-10T18:37:03.776Z,1570732623.776 [DVL_micro](ERROR): Failed to parse::BI,-0192,-01758,+00000,I 2019-10-10T18:38:37.150Z,1570732717.150 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-10-10T18:38:37.150Z,1570732717.150 [DVL_micro] Communications Fault, FailCount= 1 2019-10-10T18:38:37.150Z,1570732717.150 [DVL_micro](ERROR): Communications Fault 2019-10-10T18:38:37.151Z,1570732717.151 [DVL_micro](ERROR): Failed to parse: 2019-10-10T18:38:37.215Z,1570732717.215 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-10-10T18:38:37.519Z,1570732717.519 [DVL_micro](INFO): Powering down 2019-10-10T18:38:38.306Z,1570732718.306 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-10-10T18:38:38.306Z,1570732718.306 [DVL_micro] No Fault, FailCount= 1 2019-10-10T18:38:53.396Z,1570732733.396 [CBIT](CRITICAL): run-time exception #7 2019-10-10T18:38:53.397Z,1570732733.397 [CBIT](CRITICAL): Bad address: 0x4041E008 2019-10-10T18:38:53.397Z,1570732733.397 [CBIT](CRITICAL): Backtrace: ./bin/LRAUV(_ZN7PCaller20DefaultSignalHandlerEiP7siginfoPv+0x20) [0x17a510] ./bin/LRAUV(_ZN7PCaller10PThreadRunEPv+0xbc) [0x17a0ac] 2019-10-10T18:38:53.397Z,1570732733.397 [CBIT] Software Fault, FailCount= 1 2019-10-10T18:38:53.397Z,1570732733.397 [CBIT](ERROR): Software Fault 2019-10-10T18:38:53.410Z,1570732733.410 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-10-10T18:38:53.411Z,1570732733.411 [SyncHandler](INFO): Protected caller Thread ID is 9669 2019-10-10T18:38:53.684Z,1570732733.684 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-10-10T18:38:53.684Z,1570732733.684 [CBIT](DEBUG): Powering off loads. 2019-10-10T18:38:53.698Z,1570732733.698 [CBIT](DEBUG): Disabling WDT. 2019-10-10T18:38:53.722Z,1570732733.722 [CBIT](DEBUG): Opening all GF detection circuits. 2019-10-10T18:38:57.604Z,1570732737.604 [CommandLine](IMPORTANT): got command quit 2019-10-10T18:38:58.610Z,1570732738.610 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:38:58.611Z,1570732738.611 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:58.746Z,1570732738.746 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-10-10T18:38:58.746Z,1570732738.746 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:58.747Z,1570732738.747 [CommandLine](INFO): Join timeout helper Thread ID is 9701 2019-10-10T18:38:58.748Z,1570732738.748 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-10-10T18:38:58.748Z,1570732738.748 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:58.748Z,1570732738.748 [NavChartDb](INFO): Join timeout helper Thread ID is 9702 2019-10-10T18:38:58.974Z,1570732738.974 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:38:58.975Z,1570732738.975 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:58.990Z,1570732738.990 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-10-10T18:38:58.990Z,1570732738.990 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:58.991Z,1570732738.991 [Radio_Surface](INFO): Join timeout helper Thread ID is 9703 2019-10-10T18:38:59.038Z,1570732739.038 [Radio_Surface](INFO): Powering down 2019-10-10T18:38:59.039Z,1570732739.039 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:38:59.040Z,1570732739.040 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:59.046Z,1570732739.046 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-10-10T18:38:59.046Z,1570732739.046 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:59.047Z,1570732739.047 [DataOverHttps](INFO): Join timeout helper Thread ID is 9705 2019-10-10T18:38:59.795Z,1570732739.795 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:38:59.798Z,1570732739.798 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:59.818Z,1570732739.818 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-10-10T18:38:59.818Z,1570732739.818 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:38:59.819Z,1570732739.819 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 9711 2019-10-10T18:39:00.091Z,1570732740.091 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:39:00.091Z,1570732740.091 [WetLabsBB2FL](INFO): Powering down 2019-10-10T18:39:00.091Z,1570732740.091 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.099Z,1570732740.099 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-10-10T18:39:00.099Z,1570732740.099 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.100Z,1570732740.100 [CTD_Seabird](INFO): Join timeout helper Thread ID is 9712 2019-10-10T18:39:00.338Z,1570732740.338 [CTD_Seabird](INFO): Powering down 2019-10-10T18:39:00.350Z,1570732740.350 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:39:00.350Z,1570732740.350 [CTD_Seabird](INFO): Powering down 2019-10-10T18:39:00.362Z,1570732740.362 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.363Z,1570732740.363 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-10-10T18:39:00.364Z,1570732740.364 [logger ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.364Z,1570732740.364 [logger](INFO): Join timeout helper Thread ID is 9715 2019-10-10T18:39:00.394Z,1570732740.394 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:39:00.395Z,1570732740.395 [logger ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.403Z,1570732740.403 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-10-10T18:39:00.403Z,1570732740.403 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.403Z,1570732740.403 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-10-10T18:39:00.403Z,1570732740.403 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.404Z,1570732740.404 [controlThread](INFO): Join timeout helper Thread ID is 9716 2019-10-10T18:39:00.487Z,1570732740.487 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-10-10T18:39:00.487Z,1570732740.487 [controlThread](DEBUG): Uninitializing ControlThread 2019-10-10T18:39:00.487Z,1570732740.487 [Aanderaa_O2](INFO): Powering down 2019-10-10T18:39:00.488Z,1570732740.488 [AHRS_M2](INFO): Powering down 2019-10-10T18:39:00.630Z,1570732740.630 [DVL_micro](INFO): Powering down 2019-10-10T18:39:00.631Z,1570732740.631 [NAL9602](INFO): Powering down 2019-10-10T18:39:00.633Z,1570732740.633 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-10-10T18:39:00.634Z,1570732740.634 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-10-10T18:39:00.634Z,1570732740.634 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-10-10T18:39:00.635Z,1570732740.635 [MissionManager](INFO): Uninitializing Mission Default 2019-10-10T18:39:00.635Z,1570732740.635 [Default] Stopped 2019-10-10T18:39:00.635Z,1570732740.635 [Default](DEBUG): Aggregate::uninitialize Default 2019-10-10T18:39:00.635Z,1570732740.635 [Default:B.GoToSurface] Stopped 2019-10-10T18:39:00.635Z,1570732740.635 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-10-10T18:39:00.635Z,1570732740.635 [Default:CheckIn] Stopped 2019-10-10T18:39:00.635Z,1570732740.635 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-10-10T18:39:00.636Z,1570732740.636 [Default:CheckIn:C.Wait] Stopped 2019-10-10T18:39:00.636Z,1570732740.636 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-10-10T18:39:00.638Z,1570732740.638 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-10-10T18:39:00.638Z,1570732740.638 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-10-10T18:39:00.639Z,1570732740.639 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-10-10T18:39:00.639Z,1570732740.639 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-10-10T18:39:00.639Z,1570732740.639 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-10-10T18:39:00.639Z,1570732740.639 [BuoyancyServo](INFO): Powering down 2019-10-10T18:39:00.650Z,1570732740.650 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-10-10T18:39:00.650Z,1570732740.650 [ElevatorServo](INFO): Powering down 2019-10-10T18:39:00.651Z,1570732740.651 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-10-10T18:39:00.651Z,1570732740.651 [MassServo](INFO): Powering down 2019-10-10T18:39:00.652Z,1570732740.652 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-10-10T18:39:00.652Z,1570732740.652 [RudderServo](INFO): Powering down 2019-10-10T18:39:00.653Z,1570732740.653 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-10-10T18:39:00.653Z,1570732740.653 [ThrusterServo](INFO): Powering down 2019-10-10T18:39:00.654Z,1570732740.654 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-10-10T18:39:00.654Z,1570732740.654 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-10-10T18:39:00.655Z,1570732740.655 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-10-10T18:39:00.655Z,1570732740.655 [CBIT](DEBUG): Powering off loads. 2019-10-10T18:39:00.666Z,1570732740.666 [CBIT](DEBUG): Disabling WDT. 2019-10-10T18:39:00.678Z,1570732740.678 [CBIT](DEBUG): Opening all GF detection circuits. 2019-10-10T18:39:00.679Z,1570732740.679 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.726Z,1570732740.726 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.732Z,1570732740.732 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.790Z,1570732740.790 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.797Z,1570732740.797 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.880Z,1570732740.880 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-10-10T18:39:00.952Z,1570732740.952 [logger ThreadHandler](INFO): Thread cancelled.