2019-09-12T21:22:09.161Z,1568323329.161 [CommandLine](IMPORTANT): got command restart logs 2019-09-12T21:22:14.800Z,1568323334.800 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T204858/Courier0018.lzma 2019-09-12T21:22:16.806Z,1568323336.806 [DataOverHttps](INFO): Moved sent file to Logs/20190912T204858/Courier0018.lzma.bak 2019-09-12T21:22:16.806Z,1568323336.806 [DataOverHttps](INFO): SBD MOMSN=11777467 2019-09-12T21:22:39.750Z,1568323359.750 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:23:16.993Z,1568323396.993 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.187653 2019-09-12T21:23:29.232Z,1568323409.232 [NAL9602](INFO): SBD MO Status=1, MOMSN=1303, MT Status=0, MTMSN=0 2019-09-12T21:23:29.289Z,1568323409.289 [NAL9602](INFO): Sent 25 bytes from file Logs/20190912T204858/Courier0021.lzma 2019-09-12T21:23:29.289Z,1568323409.289 [NAL9602](INFO): Packets left to send: 0 2019-09-12T21:23:36.620Z,1568323416.620 [NAL9602](INFO): SBD MO Status=1, MOMSN=1304, MT Status=0, MTMSN=0 2019-09-12T21:23:36.677Z,1568323416.677 [NAL9602](INFO): Sent 131 bytes from file Logs/20190912T204858/Express0019.lzma 2019-09-12T21:23:36.677Z,1568323416.677 [NAL9602](INFO): Packets left to send: 0 2019-09-12T21:23:48.142Z,1568323428.142 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T21:23:52.448Z,1568323432.448 [NAL9602](INFO): SBD MO Status=1, MOMSN=1305, MT Status=0, MTMSN=0 2019-09-12T21:23:52.509Z,1568323432.509 [NAL9602](INFO): Sent 134 bytes from file Logs/20190912T204858/Express0022.lzma 2019-09-12T21:23:52.509Z,1568323432.509 [NAL9602](INFO): Packets left to send: 0 2019-09-12T21:24:00.538Z,1568323440.538 [NAL9602](INFO): SBD MO Status=0, MOMSN=1306, MT Status=0, MTMSN=0 2019-09-12T21:24:00.625Z,1568323440.625 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:24:00.626Z,1568323440.626 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:24:00.626Z,1568323440.626 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:24:23.281Z,1568323463.281 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T21:24:31.243Z,1568323471.243 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:24:58.421Z,1568323498.421 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T21:25:33.561Z,1568323533.561 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T21:25:52.037Z,1568323552.037 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003047 2019-09-12T21:25:57.703Z,1568323557.703 [DVL_micro](ERROR): Failed to parse: :SA,+04.47,-05.98,059.4 2019-09-12T21:26:20.725Z,1568323580.725 [DVL_micro](ERROR): Failed to parse:137,+00295,+00709,+00000,I 2019-09-12T21:26:38.491Z,1568323598.491 [DVL_micro](ERROR): Failed to parse: :WI,+00082,+00328,-00333,+00000,A 2019-09-12T21:27:03.943Z,1568323623.943 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:27:03.943Z,1568323623.943 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+17.3,00000,000 2019-09-12T21:27:29.400Z,1568323649.400 [DVL_micro](ERROR): only read 2 of 4 data items 2019-09-12T21:27:29.400Z,1568323649.400 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999..99,+9999.99 2019-09-12T21:27:57.275Z,1568323677.275 [DVL_micro](ERROR): Failed to parse: :WI,00360,-00246,+00000,A 2019-09-12T21:28:22.730Z,1568323702.730 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 36 2019-09-12T21:28:22.734Z,1568323702.734 [DVL_micro](ERROR): Failed to parse: :BD,+000,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T21:29:01.127Z,1568323741.127 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:29:01.127Z,1568323741.127 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:29:01.127Z,1568323741.127 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:29:01.127Z,1568323741.127 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:29:01.541Z,1568323741.541 [Default:CheckIn:D] Stopped 2019-09-12T21:29:01.541Z,1568323741.541 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.935921 min 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn:E] Stopped 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn] Stopped 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn](INFO): Running loop #9 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn] Running Loop=9 2019-09-12T21:29:01.945Z,1568323741.945 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:29:01.946Z,1568323741.946 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:29:03.526Z,1568323743.526 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:29:03.527Z,1568323743.527 [DVL_micro](ERROR): Failed to parse: :TS0000000,35.0,00.0,1489.0,000 2019-09-12T21:29:03.549Z,1568323743.549 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:29:03.936Z,1568323743.936 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212904.00,A,3648.47365,N,12147.26124,W,7.464,51.96,120919,,,D*45 2019-09-12T21:29:03.938Z,1568323743.938 [NAL9602](INFO): GPS fix at 20190912T212904: (36.807894, -121.787687) 2019-09-12T21:29:03.979Z,1568323743.979 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:29:03.979Z,1568323743.979 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:29:05.558Z,1568323745.558 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:29:12.477Z,1568323752.477 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190912T212209/Courier0000.lzma 2019-09-12T21:29:14.482Z,1568323754.482 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0000.lzma.bak 2019-09-12T21:29:14.482Z,1568323754.482 [DataOverHttps](INFO): SBD MOMSN=11777524 2019-09-12T21:29:28.988Z,1568323768.988 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:29:28.989Z,1568323768.989 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.999,+9999.99 2019-09-12T21:29:33.525Z,1568323773.525 [DataOverHttps](INFO): Sending 343 bytes from file Logs/20190912T212209/Express0001.lzma 2019-09-12T21:29:35.530Z,1568323775.530 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0001.lzma.bak 2019-09-12T21:29:35.530Z,1568323775.530 [DataOverHttps](INFO): SBD MOMSN=11777528 2019-09-12T21:29:37.060Z,1568323777.060 [NAL9602](INFO): SBD MO Status=2, MOMSN=1307, MT Status=2, MTMSN=0 2019-09-12T21:29:37.060Z,1568323777.060 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:29:39.146Z,1568323779.146 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:29:39.146Z,1568323779.146 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:29:39.146Z,1568323779.146 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:29:48.785Z,1568323788.785 [NAL9602](INFO): SBD MO Status=0, MOMSN=1307, MT Status=0, MTMSN=0 2019-09-12T21:29:48.785Z,1568323788.785 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:30:12.216Z,1568323812.216 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:30:12.216Z,1568323812.216 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-09-12T21:30:19.496Z,1568323819.496 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:31:23.326Z,1568323883.326 [DVL_micro](ERROR): Failed to parse: 66,+00069,-00159,+00000,I 2019-09-12T21:31:38.677Z,1568323898.677 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:31:38.677Z,1568323898.677 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-09-12T21:32:04.126Z,1568323924.126 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:32:04.126Z,1568323924.126 [DVL_micro](ERROR): Failed to parse: :TS0000000,36,0000.0,1489.0,000 2019-09-12T21:32:47.351Z,1568323967.351 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:32:47.351Z,1568323967.351 [DVL_micro](ERROR): Failed to parse: :BI,+00124,+00262,-00077,+00000+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T21:33:58.468Z,1568324038.468 [DVL_micro](ERROR): Failed to parse: :SA,-00.58,-03.59,204.6 2019-09-12T21:34:39.696Z,1568324079.696 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:34:39.696Z,1568324079.696 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:34:39.696Z,1568324079.696 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:34:39.717Z,1568324079.717 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:34:40.129Z,1568324080.129 [Default:CheckIn:D] Stopped 2019-09-12T21:34:40.129Z,1568324080.129 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:34:40.495Z,1568324080.495 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.579057 min 2019-09-12T21:34:40.495Z,1568324080.495 [Default:CheckIn:E] Stopped 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn] Stopped 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn](INFO): Running loop #10 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn] Running Loop=10 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:34:40.496Z,1568324080.496 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:34:42.093Z,1568324082.093 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:34:42.488Z,1568324082.488 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213443.00,A,3648.15838,N,12147.21336,W,3.149,210.06,120919,,,D*78 2019-09-12T21:34:42.490Z,1568324082.490 [NAL9602](INFO): GPS fix at 20190912T213443: (36.802640, -121.786889) 2019-09-12T21:34:42.535Z,1568324082.535 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:34:42.535Z,1568324082.535 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:34:51.384Z,1568324091.384 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0003.lzma 2019-09-12T21:34:53.390Z,1568324093.390 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0003.lzma.bak 2019-09-12T21:34:53.390Z,1568324093.390 [DataOverHttps](INFO): SBD MOMSN=11777541 2019-09-12T21:35:04.709Z,1568324104.709 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 88 2019-09-12T21:35:04.711Z,1568324104.711 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T21:35:12.924Z,1568324112.924 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20190912T212209/Express0004.lzma 2019-09-12T21:35:14.930Z,1568324114.930 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0004.lzma.bak 2019-09-12T21:35:14.930Z,1568324114.930 [DataOverHttps](INFO): SBD MOMSN=11777544 2019-09-12T21:35:18.477Z,1568324118.477 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:35:18.478Z,1568324118.478 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:35:18.478Z,1568324118.478 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:35:24.096Z,1568324124.096 [NAL9602](INFO): SBD MO Status=0, MOMSN=1308, MT Status=0, MTMSN=0 2019-09-12T21:35:24.101Z,1568324124.101 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:35:47.935Z,1568324147.935 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:35:47.935Z,1568324147.935 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-09-12T21:35:54.802Z,1568324154.802 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:37:14.392Z,1568324234.392 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:37:14.392Z,1568324234.392 [DVL_micro](ERROR): Failed to parse: :TS,000000000000+18.0,000.0,000 2019-09-12T21:38:17.823Z,1568324297.823 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,0RD,+99999.99,+9999.99,+9999.99 2019-09-12T21:40:02.064Z,1568324402.064 [DVL_micro](ERROR): Failed to parse: :SA,-00.41,-04.85,191.1 2019-09-12T21:40:19.077Z,1568324419.077 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:40:19.077Z,1568324419.077 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:40:19.077Z,1568324419.077 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:40:19.078Z,1568324419.078 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:40:19.501Z,1568324419.501 [Default:CheckIn:D] Stopped 2019-09-12T21:40:19.501Z,1568324419.501 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.235250 min 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn:E] Stopped 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn] Stopped 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn](INFO): Running loop #11 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn] Running Loop=11 2019-09-12T21:40:19.909Z,1568324419.909 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:40:19.910Z,1568324419.910 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:40:21.457Z,1568324421.457 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:40:21.852Z,1568324421.852 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214022.00,A,3648.14947,N,12147.22203,W,0.544,235.20,120919,,,D*79 2019-09-12T21:40:21.854Z,1568324421.854 [NAL9602](INFO): GPS fix at 20190912T214022: (36.802491, -121.787034) 2019-09-12T21:40:21.899Z,1568324421.899 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:40:21.899Z,1568324421.899 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:40:31.973Z,1568324431.973 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212209/Courier0006.lzma 2019-09-12T21:40:33.979Z,1568324433.979 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0006.lzma.bak 2019-09-12T21:40:33.979Z,1568324433.979 [DataOverHttps](INFO): SBD MOMSN=11777564 2019-09-12T21:40:53.020Z,1568324453.020 [NAL9602](INFO): SBD MO Status=0, MOMSN=1309, MT Status=0, MTMSN=0 2019-09-12T21:40:53.020Z,1568324453.020 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:40:53.100Z,1568324453.100 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T212209/Express0007.lzma 2019-09-12T21:40:55.106Z,1568324455.106 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0007.lzma.bak 2019-09-12T21:40:55.106Z,1568324455.106 [DataOverHttps](INFO): SBD MOMSN=11777567 2019-09-12T21:40:58.307Z,1568324458.307 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:40:58.307Z,1568324458.307 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:40:58.307Z,1568324458.307 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:41:03.072Z,1568324463.072 [DVL_micro](ERROR): Failed to parse: :SA,-02.02,+04.07,026.2 2019-09-12T21:41:17.627Z,1568324477.627 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:41:23.665Z,1568324483.665 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:41:29.340Z,1568324489.340 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:41:41.063Z,1568324501.063 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:41:52.357Z,1568324512.357 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:42:03.263Z,1568324523.263 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:42:14.585Z,1568324534.585 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:42:26.299Z,1568324546.299 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:42:27.102Z,1568324547.102 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:42:27.102Z,1568324547.102 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.999,+9999.99 2019-09-12T21:42:37.610Z,1568324557.610 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:42:49.325Z,1568324569.325 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:43:00.637Z,1568324580.637 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:43:12.793Z,1568324592.793 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:43:24.066Z,1568324604.066 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:43:35.418Z,1568324615.418 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:44:36.787Z,1568324676.787 [DVL_micro](ERROR): Failed to parse: :W,+00080,+00064,+00000,A 2019-09-12T21:45:20.003Z,1568324720.003 [DVL_micro](ERROR): Failed to parse: :6,+00269,00000,I 2019-09-12T21:45:58.838Z,1568324758.838 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:45:58.838Z,1568324758.838 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:45:58.838Z,1568324758.838 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:45:58.838Z,1568324758.838 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:45:59.246Z,1568324759.246 [Default:CheckIn:D] Stopped 2019-09-12T21:45:59.246Z,1568324759.246 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.897664 min 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn:E] Stopped 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn] Stopped 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn](INFO): Running loop #12 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn] Running Loop=12 2019-09-12T21:45:59.653Z,1568324759.653 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:45:59.654Z,1568324759.654 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:46:01.225Z,1568324761.225 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:46:01.634Z,1568324761.634 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214602.00,A,3648.15049,N,12147.22326,W,0.078,263.53,120919,,,D*70 2019-09-12T21:46:01.639Z,1568324761.639 [NAL9602](INFO): GPS fix at 20190912T214602: (36.802508, -121.787054) 2019-09-12T21:46:01.679Z,1568324761.679 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:46:01.679Z,1568324761.679 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:46:05.666Z,1568324765.666 [DVL_micro](ERROR): Failed to parse: :SA,-01.88,+05.40,192.8 2019-09-12T21:46:10.652Z,1568324770.652 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212209/Courier0009.lzma 2019-09-12T21:46:10.911Z,1568324770.911 [NAL9602](INFO): SBD MO Status=0, MOMSN=1310, MT Status=0, MTMSN=0 2019-09-12T21:46:10.912Z,1568324770.912 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:46:12.658Z,1568324772.658 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0009.lzma.bak 2019-09-12T21:46:12.658Z,1568324772.658 [DataOverHttps](INFO): SBD MOMSN=11777577 2019-09-12T21:46:31.116Z,1568324791.116 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:46:31.116Z,1568324791.116 [DVL_micro](ERROR): Failed to parse: :TS,000000005.0,+18.8,0000.0,1489.0,000 2019-09-12T21:46:33.712Z,1568324793.712 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190912T212209/Express0010.lzma 2019-09-12T21:46:35.718Z,1568324795.718 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0010.lzma.bak 2019-09-12T21:46:35.718Z,1568324795.718 [DataOverHttps](INFO): SBD MOMSN=11777581 2019-09-12T21:46:38.858Z,1568324798.858 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:46:38.858Z,1568324798.858 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:46:38.858Z,1568324798.858 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:46:41.618Z,1568324801.618 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:47:39.804Z,1568324859.804 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:47:39.804Z,1568324859.804 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.999 2019-09-12T21:47:57.581Z,1568324877.581 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:47:57.581Z,1568324877.581 [DVL_micro](ERROR): Failed to parse: :BI,+00266,-0134,+00000,I 2019-09-12T21:49:54.333Z,1568324994.333 [DVL_micro](ERROR): Failed to parse: 26,-01373,+00536,+00000,I 2019-09-12T21:50:09.685Z,1568325009.685 [DVL_micro](ERROR): Failed to parse: :BI,-01328,-00303,+00535,+00000,I 2019-09-12T21:50:44.509Z,1568325044.509 [BPC1](ERROR): BPC1B failed to parse battery data due to unrecognized msg size. 2019-09-12T21:51:00.632Z,1568325060.632 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:51:11.917Z,1568325071.917 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:51:23.244Z,1568325083.244 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:51:34.954Z,1568325094.954 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:51:39.417Z,1568325099.417 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:51:39.417Z,1568325099.417 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:51:39.417Z,1568325099.417 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:51:39.417Z,1568325099.417 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:51:39.827Z,1568325099.827 [Default:CheckIn:D] Stopped 2019-09-12T21:51:39.827Z,1568325099.827 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:51:40.228Z,1568325100.228 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.574023 min 2019-09-12T21:51:40.228Z,1568325100.228 [Default:CheckIn:E] Stopped 2019-09-12T21:51:40.228Z,1568325100.228 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:51:40.228Z,1568325100.228 [Default:CheckIn] Stopped 2019-09-12T21:51:40.228Z,1568325100.228 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:51:40.229Z,1568325100.229 [Default:CheckIn](INFO): Running loop #13 2019-09-12T21:51:40.229Z,1568325100.229 [Default:CheckIn] Running Loop=13 2019-09-12T21:51:40.229Z,1568325100.229 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:51:40.229Z,1568325100.229 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:51:41.809Z,1568325101.809 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:51:42.204Z,1568325102.204 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215142.00,A,3648.14171,N,12147.23076,W,0.019,200.17,120919,,,D*7C 2019-09-12T21:51:42.206Z,1568325102.206 [NAL9602](INFO): GPS fix at 20190912T215142: (36.802362, -121.787179) 2019-09-12T21:51:42.230Z,1568325102.230 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:51:42.231Z,1568325102.231 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:51:43.427Z,1568325103.427 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:51:46.263Z,1568325106.263 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:51:50.816Z,1568325110.816 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0012.lzma 2019-09-12T21:51:52.823Z,1568325112.823 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0012.lzma.bak 2019-09-12T21:51:52.823Z,1568325112.823 [DataOverHttps](INFO): SBD MOMSN=11777601 2019-09-12T21:51:57.167Z,1568325117.167 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:52:08.904Z,1568325128.904 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:52:12.148Z,1568325132.148 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T212209/Express0013.lzma 2019-09-12T21:52:12.498Z,1568325132.498 [NAL9602](INFO): SBD MO Status=0, MOMSN=1311, MT Status=0, MTMSN=0 2019-09-12T21:52:12.498Z,1568325132.498 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:52:14.154Z,1568325134.154 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0013.lzma.bak 2019-09-12T21:52:14.154Z,1568325134.154 [DataOverHttps](INFO): SBD MOMSN=11777604 2019-09-12T21:52:17.412Z,1568325137.412 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:52:17.417Z,1568325137.417 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:52:17.417Z,1568325137.417 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:52:20.229Z,1568325140.229 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:52:24.247Z,1568325144.247 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T21:52:31.126Z,1568325151.126 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:52:43.226Z,1568325163.226 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:52:44.049Z,1568325164.049 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:52:56.995Z,1568325176.995 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:53:09.920Z,1568325189.920 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T21:53:53.120Z,1568325233.120 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:53:53.121Z,1568325233.121 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+20.0,00000,000 2019-09-12T21:54:10.902Z,1568325250.902 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:54:10.902Z,1568325250.902 [DVL_micro](ERROR): Failed to parse: :BI,+00080,+00129,+00417, 2019-09-12T21:54:31.106Z,1568325271.106 [DVL_micro](ERROR): Failed to parse:00000000000,35.0,+0.0,1489.0,000 2019-09-12T21:56:50.886Z,1568325410.886 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:56:50.887Z,1568325410.887 [DVL_micro](ERROR): Failed to parse: :BI,+00134,+02300,+0000,I 2019-09-12T21:57:11.092Z,1568325431.092 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T21:57:11.092Z,1568325431.092 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+2.0,1489.WI,-01905,-00085,+00582,+00000,A 2019-09-12T21:57:18.002Z,1568325438.002 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:57:18.002Z,1568325438.002 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:57:18.002Z,1568325438.002 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:57:18.002Z,1568325438.002 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:57:18.405Z,1568325438.405 [Default:CheckIn:D] Stopped 2019-09-12T21:57:18.405Z,1568325438.405 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:57:18.822Z,1568325438.822 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.216984 min 2019-09-12T21:57:18.822Z,1568325438.822 [Default:CheckIn:E] Stopped 2019-09-12T21:57:18.822Z,1568325438.822 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:57:18.822Z,1568325438.822 [Default:CheckIn] Stopped 2019-09-12T21:57:18.822Z,1568325438.822 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:57:18.823Z,1568325438.823 [Default:CheckIn](INFO): Running loop #14 2019-09-12T21:57:18.823Z,1568325438.823 [Default:CheckIn] Running Loop=14 2019-09-12T21:57:18.823Z,1568325438.823 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:57:18.823Z,1568325438.823 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:57:20.389Z,1568325440.389 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:57:20.774Z,1568325440.774 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215721.00,A,3648.17092,N,12147.28090,W,0.117,259.72,120919,,,D*73 2019-09-12T21:57:20.776Z,1568325440.776 [NAL9602](INFO): GPS fix at 20190912T215721: (36.802849, -121.788015) 2019-09-12T21:57:20.821Z,1568325440.821 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:57:20.822Z,1568325440.822 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:57:26.433Z,1568325446.433 [DVL_micro](ERROR): Failed to parse: :WI,-00600,-00025,+00575,+00000,A 2019-09-12T21:57:30.424Z,1568325450.424 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0015.lzma 2019-09-12T21:57:32.430Z,1568325452.430 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0015.lzma.bak 2019-09-12T21:57:32.430Z,1568325452.430 [DataOverHttps](INFO): SBD MOMSN=11777615 2019-09-12T21:57:44.223Z,1568325464.223 [DVL_micro](ERROR): only read 2 of 4 data items 2019-09-12T21:57:44.223Z,1568325464.223 [DVL_micro](ERROR): Failed to parse: :RD,+99999.99,+9999.99, 2019-09-12T21:57:52.025Z,1568325472.025 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T212209/Express0016.lzma 2019-09-12T21:57:54.030Z,1568325474.030 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0016.lzma.bak 2019-09-12T21:57:54.030Z,1568325474.030 [DataOverHttps](INFO): SBD MOMSN=11777618 2019-09-12T21:57:55.116Z,1568325475.116 [NAL9602](INFO): SBD MO Status=2, MOMSN=1312, MT Status=2, MTMSN=0 2019-09-12T21:57:55.116Z,1568325475.116 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:57:57.168Z,1568325477.168 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:57:57.189Z,1568325477.189 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:57:57.189Z,1568325477.189 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:59:07.856Z,1568325547.856 [NAL9602](INFO): SBD MO Status=2, MOMSN=1312, MT Status=2, MTMSN=0 2019-09-12T21:59:07.856Z,1568325547.856 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:59:23.192Z,1568325563.192 [DVL_micro](ERROR): only read 0 of 4 data items 2019-09-12T21:59:23.193Z,1568325563.193 [DVL_micro](ERROR): Failed to parse: :RD,++9999.99,+9999.99,+9999.99 2019-09-12T21:59:40.972Z,1568325580.972 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T21:59:40.972Z,1568325580.972 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-09-12T21:59:53.084Z,1568325593.084 [NAL9602](INFO): SBD MO Status=0, MOMSN=1312, MT Status=0, MTMSN=0 2019-09-12T21:59:53.084Z,1568325593.084 [NAL9602](INFO): No messages in MT queue 2019-09-12T22:00:23.806Z,1568325623.806 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:00:34.311Z,1568325634.311 [DVL_micro](ERROR): Failed to parse: :7,+01242,+00041,+00000,I 2019-09-12T22:00:40.365Z,1568325640.365 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:00:51.698Z,1568325651.698 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:01:03.397Z,1568325663.397 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:01:14.299Z,1568325674.299 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:01:26.021Z,1568325686.021 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:01:37.746Z,1568325697.746 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:01:49.459Z,1568325709.459 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:00.765Z,1568325720.765 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:12.484Z,1568325732.484 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:20.948Z,1568325740.948 [DVL_micro](ERROR): Failed to parse: :WI,+2506,+01101,+00000,A 2019-09-12T22:02:23.801Z,1568325743.801 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:35.105Z,1568325755.105 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:41.154Z,1568325761.154 [DVL_micro](ERROR): Failed to parse: 39,+0256,+00000,A1239,+0254,+00000,I 2019-09-12T22:02:46.827Z,1568325766.827 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:57.816Z,1568325777.816 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:02:57.816Z,1568325777.816 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:02:57.816Z,1568325777.816 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:02:57.821Z,1568325777.821 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:02:58.129Z,1568325778.129 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T22:02:58.204Z,1568325778.204 [Default:CheckIn:D] Stopped 2019-09-12T22:02:58.204Z,1568325778.204 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.880298 min 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn:E] Stopped 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn] Stopped 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn](INFO): Running loop #15 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn] Running Loop=15 2019-09-12T22:02:58.574Z,1568325778.574 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:02:58.575Z,1568325778.575 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:03:00.149Z,1568325780.149 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:03:00.544Z,1568325780.544 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220301.00,A,3648.16815,N,12147.28044,W,0.214,212.31,120919,,,A*71 2019-09-12T22:03:00.546Z,1568325780.546 [NAL9602](INFO): GPS fix at 20190912T220301: (36.802802, -121.788007) 2019-09-12T22:03:00.571Z,1568325780.571 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:03:00.571Z,1568325780.571 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:03:02.566Z,1568325782.566 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T22:03:09.864Z,1568325789.864 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212209/Courier0018.lzma 2019-09-12T22:03:11.870Z,1568325791.870 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0018.lzma.bak 2019-09-12T22:03:11.871Z,1568325791.871 [DataOverHttps](INFO): SBD MOMSN=11777638 2019-09-12T22:03:31.208Z,1568325811.208 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190912T212209/Express0019.lzma 2019-09-12T22:03:33.214Z,1568325813.214 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0019.lzma.bak 2019-09-12T22:03:33.214Z,1568325813.214 [DataOverHttps](INFO): SBD MOMSN=11777641 2019-09-12T22:03:36.544Z,1568325816.544 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:03:36.569Z,1568325816.569 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:03:36.569Z,1568325816.569 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:04:35.501Z,1568325875.501 [DVL_micro](ERROR): Failed to parse: :WI,+02750,-01255,+00189,+00000,A 2019-09-12T22:04:50.468Z,1568325890.468 [BPC1](INFO): Calculating totals. Valid battery stick count: 54. Valid reserve battery stick count: 6. 2019-09-12T22:04:50.470Z,1568325890.470 [BPC1](ERROR): Failed to receive data from all sticks prior to timeout. Will not retry this scan cycle. 2019-09-12T22:04:53.280Z,1568325893.280 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:04:53.280Z,1568325893.280 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+99999.99 2019-09-12T22:07:17.907Z,1568326037.907 [DVL_micro](ERROR): Failed to parse: :WI,-00069,+00407,+00587,+00000,A 2019-09-12T22:08:03.154Z,1568326083.154 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:08:33.881Z,1568326113.881 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:08:37.124Z,1568326117.124 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:08:37.124Z,1568326117.124 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:08:37.124Z,1568326117.124 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:08:37.145Z,1568326117.145 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:08:37.559Z,1568326117.559 [Default:CheckIn:D] Stopped 2019-09-12T22:08:37.559Z,1568326117.559 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.536214 min 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn:E] Stopped 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn] Stopped 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:08:37.974Z,1568326117.974 [Default:CheckIn](INFO): Running loop #16 2019-09-12T22:08:37.975Z,1568326117.975 [Default:CheckIn] Running Loop=16 2019-09-12T22:08:37.975Z,1568326117.975 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:08:37.975Z,1568326117.975 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:08:39.525Z,1568326119.525 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:08:39.920Z,1568326119.920 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,220840.00,A,3648.16756,N,12147.28075,W,0.156,130.36,120919,,,A*74 2019-09-12T22:08:39.922Z,1568326119.922 [NAL9602](INFO): GPS fix at 20190912T220840: (36.802793, -121.788012) 2019-09-12T22:08:39.970Z,1568326119.970 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:08:39.970Z,1568326119.970 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:08:49.576Z,1568326129.576 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20190912T212209/Courier0021.lzma 2019-09-12T22:08:51.582Z,1568326131.582 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0021.lzma.bak 2019-09-12T22:08:51.582Z,1568326131.582 [DataOverHttps](INFO): SBD MOMSN=11777651 2019-09-12T22:09:10.667Z,1568326150.667 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:09:10.709Z,1568326150.709 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20190912T212209/Express0022.lzma 2019-09-12T22:09:10.745Z,1568326150.745 [NAL9602](FAULT): received: +CSQ:1 OK12, 0, 0, 0, 0 OK 2019-09-12T22:09:10.745Z,1568326150.745 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:09:10.745Z,1568326150.745 [NAL9602](ERROR): Data Fault 2019-09-12T22:09:10.783Z,1568326150.783 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:09:11.070Z,1568326151.070 [NAL9602](INFO): Powering down 2019-09-12T22:09:11.922Z,1568326151.922 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:09:11.922Z,1568326151.922 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:09:12.714Z,1568326152.714 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0022.lzma.bak 2019-09-12T22:09:12.715Z,1568326152.715 [DataOverHttps](INFO): SBD MOMSN=11777654 2019-09-12T22:09:15.564Z,1568326155.564 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:09:15.569Z,1568326155.569 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:09:15.569Z,1568326155.569 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:09:19.960Z,1568326159.960 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:09:19.960Z,1568326159.960 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+2346,+00197,+00000,I 2019-09-12T22:09:41.374Z,1568326181.374 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:09:52.282Z,1568326192.282 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:09:55.510Z,1568326195.510 [DVL_micro](ERROR): Failed to parse: :000000000,35.0,+20.8,0000.0,1489.0,000 2019-09-12T22:10:23.395Z,1568326223.395 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:11:06.615Z,1568326266.615 [DVL_micro](ERROR): Failed to parse: :WI,-01844,-01316,+01196,+00000,A 2019-09-12T22:12:17.752Z,1568326337.752 [DVL_micro](ERROR): Failed to parse: 00000000+20.9,0000.0,1489.0,000 2019-09-12T22:13:28.881Z,1568326408.881 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:13:28.881Z,1568326408.881 [DVL_micro](ERROR): Failed to parse: :BI,-00134,-00806,+00797,+000D,+0000000000000.00,+00000000.00,9999.99,000.00 2019-09-12T22:13:46.649Z,1568326426.649 [DVL_micro](ERROR): Failed to parse: :WI,-01605,-01514,+01314,+00000,A 2019-09-12T22:14:16.193Z,1568326456.193 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:14:16.193Z,1568326456.193 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:14:16.193Z,1568326456.193 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:14:16.194Z,1568326456.194 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:14:16.577Z,1568326456.577 [Default:CheckIn:D] Stopped 2019-09-12T22:14:16.577Z,1568326456.577 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.186523 min 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn:E] Stopped 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn] Stopped 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn](INFO): Running loop #17 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn] Running Loop=17 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:14:16.982Z,1568326456.982 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:14:18.569Z,1568326458.569 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:14:18.968Z,1568326458.968 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221418.00,A,3648.16898,N,12147.27645,W,0.330,0.00,120919,,,A*76 2019-09-12T22:14:18.970Z,1568326458.970 [NAL9602](INFO): GPS fix at 20190912T221418: (36.802816, -121.787941) 2019-09-12T22:14:19.011Z,1568326459.011 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:14:19.011Z,1568326459.011 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:14:20.578Z,1568326460.578 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:14:22.200Z,1568326462.200 [DVL_micro](ERROR): Failed to parse: :T00000000,39,0000.0000 2019-09-12T22:14:27.728Z,1568326467.728 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0024.lzma 2019-09-12T22:14:29.734Z,1568326469.734 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0024.lzma.bak 2019-09-12T22:14:29.735Z,1568326469.735 [DataOverHttps](INFO): SBD MOMSN=11777674 2019-09-12T22:14:49.380Z,1568326489.380 [DataOverHttps](INFO): Sending 159 bytes from file Logs/20190912T212209/Express0025.lzma 2019-09-12T22:14:51.280Z,1568326491.280 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:14:51.386Z,1568326491.386 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0025.lzma.bak 2019-09-12T22:14:51.386Z,1568326491.386 [DataOverHttps](INFO): SBD MOMSN=11777677 2019-09-12T22:14:55.004Z,1568326495.004 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:14:55.024Z,1568326495.024 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:14:55.024Z,1568326495.024 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:15:17.956Z,1568326517.956 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:15:17.957Z,1568326517.957 [DVL_micro](ERROR): Failed to parse::TS,000000,35.0,+0.0,1489.0,000 2019-09-12T22:15:51.081Z,1568326551.081 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:15:51.081Z,1568326551.081 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,+0.0,1489:WI,-00792,+00224,+00879,+00000,A 2019-09-12T22:16:08.858Z,1568326568.858 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:16:08.858Z,1568326568.858 [DVL_micro](ERROR): Failed to parse: :BI,-01034,+0648,+00000,I 2019-09-12T22:18:20.984Z,1568326700.984 [DVL_micro](ERROR): Failed to parse:710,-0010,+00000,00710,-0060,+00000,I 2019-09-12T22:18:38.753Z,1568326718.753 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:18:38.753Z,1568326718.753 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.0,000.0,000 2019-09-12T22:18:56.541Z,1568326736.541 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:18:56.541Z,1568326736.541 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,+21.01489.0,000 2019-09-12T22:19:14.306Z,1568326754.306 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:19:14.306Z,1568326754.306 [DVL_micro](ERROR): Failed to parse: :TS,000000000.0,+21.0,489.0,0001378,-00136,+00348,+00000,A 2019-09-12T22:19:32.093Z,1568326772.093 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:19:32.093Z,1568326772.093 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,+21.1,0000.0,148 2019-09-12T22:19:52.289Z,1568326792.289 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:19:52.290Z,1568326792.290 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.1,089.0,000 2019-09-12T22:19:55.569Z,1568326795.569 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:19:55.569Z,1568326795.569 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:19:55.569Z,1568326795.569 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:19:55.570Z,1568326795.570 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:19:55.977Z,1568326795.977 [Default:CheckIn:D] Stopped 2019-09-12T22:19:55.977Z,1568326795.977 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:19:56.388Z,1568326796.388 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.843188 min 2019-09-12T22:19:56.388Z,1568326796.388 [Default:CheckIn:E] Stopped 2019-09-12T22:19:56.388Z,1568326796.388 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:19:56.388Z,1568326796.388 [Default:CheckIn] Stopped 2019-09-12T22:19:56.388Z,1568326796.388 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:19:56.389Z,1568326796.389 [Default:CheckIn](INFO): Running loop #18 2019-09-12T22:19:56.389Z,1568326796.389 [Default:CheckIn] Running Loop=18 2019-09-12T22:19:56.389Z,1568326796.389 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:19:56.389Z,1568326796.389 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:19:57.961Z,1568326797.961 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:19:58.342Z,1568326798.342 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,221959.00,A,3648.16847,N,12147.27923,W,0.156,94.29,120919,,,A*47 2019-09-12T22:19:58.344Z,1568326798.344 [NAL9602](INFO): GPS fix at 20190912T221959: (36.802808, -121.787987) 2019-09-12T22:19:58.387Z,1568326798.387 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:19:58.387Z,1568326798.387 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:20:07.216Z,1568326807.216 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T212209/Courier0027.lzma 2019-09-12T22:20:09.222Z,1568326809.222 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0027.lzma.bak 2019-09-12T22:20:09.222Z,1568326809.222 [DataOverHttps](INFO): SBD MOMSN=11777691 2019-09-12T22:20:30.197Z,1568326830.197 [DataOverHttps](INFO): Sending 198 bytes from file Logs/20190912T212209/Express0028.lzma 2019-09-12T22:20:32.202Z,1568326832.202 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0028.lzma.bak 2019-09-12T22:20:32.202Z,1568326832.202 [DataOverHttps](INFO): SBD MOMSN=11777694 2019-09-12T22:20:35.608Z,1568326835.608 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:20:35.617Z,1568326835.617 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:20:35.617Z,1568326835.617 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:21:00.996Z,1568326860.996 [DVL_micro](ERROR): only read 2 of 4 data items 2019-09-12T22:21:00.996Z,1568326860.996 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,++9999.99 2019-09-12T22:21:18.768Z,1568326878.768 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:21:18.769Z,1568326878.769 [DVL_micro](ERROR): Failed to parse: :TS,000000,31,0000.0,1489.0,,+00014,+0600,+00000,A 2019-09-12T22:22:11.288Z,1568326931.288 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:22:11.288Z,1568326931.288 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:22:12.102Z,1568326932.102 [DVL_micro](ERROR): Failed to parse::WI,-00639,+0503,+00000,A 2019-09-12T22:22:32.301Z,1568326952.301 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:22:32.301Z,1568326952.301 [DVL_micro](ERROR): Failed to parse: :BI,+00084,00628,+00000,I 2019-09-12T22:25:00.963Z,1568327100.963 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:25:31.670Z,1568327131.670 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:25:36.149Z,1568327136.149 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:25:36.149Z,1568327136.149 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:25:36.149Z,1568327136.149 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:25:36.150Z,1568327136.150 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:25:36.563Z,1568327136.563 [Default:CheckIn:D] Stopped 2019-09-12T22:25:36.563Z,1568327136.563 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 109.519604 min 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn:E] Stopped 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn] Stopped 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn](INFO): Running loop #19 2019-09-12T22:25:36.983Z,1568327136.983 [Default:CheckIn] Running Loop=19 2019-09-12T22:25:36.984Z,1568327136.984 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:25:36.984Z,1568327136.984 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:25:38.553Z,1568327138.553 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:25:38.944Z,1568327138.944 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,222539.00,A,3648.16741,N,12147.28038,W,0.097,94.29,120919,,,A*47 2019-09-12T22:25:38.946Z,1568327138.946 [NAL9602](INFO): GPS fix at 20190912T222539: (36.802790, -121.788006) 2019-09-12T22:25:38.975Z,1568327138.975 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:25:38.975Z,1568327138.975 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:25:47.908Z,1568327147.908 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0030.lzma 2019-09-12T22:25:49.926Z,1568327149.926 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0030.lzma.bak 2019-09-12T22:25:49.926Z,1568327149.926 [DataOverHttps](INFO): SBD MOMSN=11777712 2019-09-12T22:26:09.157Z,1568327169.157 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20190912T212209/Express0031.lzma 2019-09-12T22:26:09.646Z,1568327169.646 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:26:09.729Z,1568327169.729 [NAL9602](FAULT): received: +CSQ:0 OK13, 2, 0, 0, 0 OK 2019-09-12T22:26:09.729Z,1568327169.729 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:26:09.729Z,1568327169.729 [NAL9602](ERROR): Data Fault 2019-09-12T22:26:09.812Z,1568327169.812 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:26:10.050Z,1568327170.050 [NAL9602](INFO): Powering down 2019-09-12T22:26:10.472Z,1568327170.472 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2019-09-12T22:26:10.472Z,1568327170.472 [NAL9602] Hardware Fault, FailCount= 1 2019-09-12T22:26:10.472Z,1568327170.472 [NAL9602](ERROR): Hardware Fault 2019-09-12T22:26:10.895Z,1568327170.895 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:26:10.895Z,1568327170.895 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:26:11.162Z,1568327171.162 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0031.lzma.bak 2019-09-12T22:26:11.162Z,1568327171.162 [DataOverHttps](INFO): SBD MOMSN=11777715 2019-09-12T22:26:14.550Z,1568327174.550 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:26:14.551Z,1568327174.551 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:26:14.551Z,1568327174.551 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:26:40.356Z,1568327200.356 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:26:51.280Z,1568327211.280 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:27:14.294Z,1568327234.294 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:27:14.294Z,1568327234.294 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0000.0,1489.0,000 2019-09-12T22:27:22.378Z,1568327242.378 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:27:32.072Z,1568327252.072 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:27:32.072Z,1568327252.072 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,00.0,1489.0,000 2019-09-12T22:28:10.049Z,1568327290.049 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:28:10.049Z,1568327290.049 [DVL_micro](ERROR): Failed to parse: :TS0000000,35.0,+21.2,0000.0,10 2019-09-12T22:28:25.404Z,1568327305.404 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:28:25.404Z,1568327305.404 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,.2,0000.0,1489.0,000 2019-09-12T22:28:43.184Z,1568327323.184 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:28:43.185Z,1568327323.185 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+99999.99,+9999.99 2019-09-12T22:29:46.617Z,1568327386.617 [DVL_micro](ERROR): Failed to parse: 9.99,+9999.99,+9999.99,+9999.99 2019-09-12T22:31:15.133Z,1568327475.133 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:31:15.133Z,1568327475.133 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:31:15.133Z,1568327475.133 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:31:15.133Z,1568327475.133 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:31:15.541Z,1568327475.541 [Default:CheckIn:D] Stopped 2019-09-12T22:31:15.541Z,1568327475.541 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 115.169255 min 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn:E] Stopped 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn] Stopped 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:31:15.954Z,1568327475.954 [Default:CheckIn](INFO): Running loop #20 2019-09-12T22:31:15.955Z,1568327475.955 [Default:CheckIn] Running Loop=20 2019-09-12T22:31:15.955Z,1568327475.955 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:31:15.955Z,1568327475.955 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:31:17.513Z,1568327477.513 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:31:17.917Z,1568327477.917 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223118.00,A,3648.16618,N,12147.27790,W,0.194,55.93,120919,,,A*48 2019-09-12T22:31:17.919Z,1568327477.919 [NAL9602](INFO): GPS fix at 20190912T223118: (36.802770, -121.787965) 2019-09-12T22:31:17.973Z,1568327477.973 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:31:17.973Z,1568327477.973 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:31:19.523Z,1568327479.523 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:31:27.340Z,1568327487.340 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0033.lzma 2019-09-12T22:31:29.347Z,1568327489.347 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0033.lzma.bak 2019-09-12T22:31:29.347Z,1568327489.347 [DataOverHttps](INFO): SBD MOMSN=11777735 2019-09-12T22:31:48.341Z,1568327508.341 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190912T212209/Express0034.lzma 2019-09-12T22:31:50.230Z,1568327510.230 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:31:50.346Z,1568327510.346 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0034.lzma.bak 2019-09-12T22:31:50.346Z,1568327510.346 [DataOverHttps](INFO): SBD MOMSN=11777738 2019-09-12T22:31:53.924Z,1568327513.924 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:31:53.924Z,1568327513.924 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:31:53.924Z,1568327513.924 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:32:11.242Z,1568327531.242 [DVL_micro](ERROR): Failed to parse: 9.99,+99999.99,+9999.99 2019-09-12T22:32:56.487Z,1568327576.487 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2019-09-12T22:32:56.487Z,1568327576.487 [DropWeight] Hardware Fault, FailCount= 1 2019-09-12T22:32:56.487Z,1568327576.487 [DropWeight](ERROR): Hardware Fault 2019-09-12T22:32:56.539Z,1568327576.539 [CommandLine](FAULT): Scheduling is paused 2019-09-12T22:32:56.539Z,1568327576.539 [CBIT](INFO): Critical error at 20190912T223256 2019-09-12T22:32:56.546Z,1568327576.546 [CBIT](ERROR): Hardware Fault in component: DropWeight 2019-09-12T22:32:56.546Z,1568327576.546 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2019-09-12T22:32:56.978Z,1568327576.978 [CBIT](INFO): Critical error at 20190912T223256 2019-09-12T22:33:30.039Z,1568327610.039 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:33:30.039Z,1568327610.039 [DVL_micro](ERROR): Failed to parse::TS,000000035.0,+21.21489.0,,-01194,+00062,+01001,+00000,A 2019-09-12T22:34:05.574Z,1568327645.574 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:34:05.574Z,1568327645.574 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.31489.0,000 2019-09-12T22:34:25.777Z,1568327665.777 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:34:25.778Z,1568327665.778 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,00.0,1489.0,000 2019-09-12T22:34:43.557Z,1568327683.557 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:34:43.557Z,1568327683.557 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.2,000.0,000 2019-09-12T22:35:44.556Z,1568327744.556 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:35:44.557Z,1568327744.557 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.3,000.0,000 2019-09-12T22:36:02.331Z,1568327762.331 [DVL_micro](ERROR): Failed to parse: :000000000,35.0,+21.3,0000.0,1489.0,000 2019-09-12T22:36:22.538Z,1568327782.538 [DVL_micro](ERROR): Failed to parse: :BI,+02389,+00684,+00233,+00000,I 2019-09-12T22:36:54.485Z,1568327814.485 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:36:54.485Z,1568327814.485 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:36:54.485Z,1568327814.485 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:36:54.485Z,1568327814.485 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:36:54.882Z,1568327814.882 [Default:CheckIn:D] Stopped 2019-09-12T22:36:54.882Z,1568327814.882 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:36:55.324Z,1568327815.324 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 120.824943 min 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn:E] Stopped 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn] Stopped 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn](INFO): Running loop #21 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn] Running Loop=21 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:36:55.325Z,1568327815.325 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:36:56.885Z,1568327816.885 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:36:57.280Z,1568327817.280 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,223657.00,A,3648.16749,N,12147.28202,W,0.136,55.93,120919,,,A*48 2019-09-12T22:36:57.282Z,1568327817.282 [NAL9602](INFO): GPS fix at 20190912T223657: (36.802791, -121.788034) 2019-09-12T22:36:57.327Z,1568327817.327 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:36:57.327Z,1568327817.327 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:37:05.788Z,1568327825.788 [DataOverHttps](INFO): Sending 171 bytes from file Logs/20190912T212209/Courier0036.lzma 2019-09-12T22:37:07.794Z,1568327827.794 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0036.lzma.bak 2019-09-12T22:37:07.794Z,1568327827.794 [DataOverHttps](INFO): SBD MOMSN=11777750 2019-09-12T22:37:26.913Z,1568327846.913 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190912T212209/Express0037.lzma 2019-09-12T22:37:28.918Z,1568327848.918 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0037.lzma.bak 2019-09-12T22:37:28.918Z,1568327848.918 [DataOverHttps](INFO): SBD MOMSN=11777755 2019-09-12T22:37:32.534Z,1568327852.534 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:37:32.534Z,1568327852.534 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:37:32.534Z,1568327852.534 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:38:54.490Z,1568327934.490 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:38:54.491Z,1568327934.491 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:40:27.412Z,1568328027.412 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:40:27.412Z,1568328027.412 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:40:52.864Z,1568328052.864 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:40:52.864Z,1568328052.864 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:41:50.237Z,1568328110.237 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:41:50.237Z,1568328110.237 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.31489.0,0-02834,+00282,+01219,+00000,A 2019-09-12T22:41:59.930Z,1568328119.930 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:42:30.689Z,1568328150.689 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:42:33.139Z,1568328153.139 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:42:33.139Z,1568328153.139 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:42:33.139Z,1568328153.139 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:42:33.139Z,1568328153.139 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:42:33.521Z,1568328153.521 [Default:CheckIn:D] Stopped 2019-09-12T22:42:33.521Z,1568328153.521 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 126.468921 min 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn:E] Stopped 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn] Stopped 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn](INFO): Running loop #22 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn] Running Loop=22 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:42:33.931Z,1568328153.931 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:42:35.493Z,1568328155.493 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:42:35.893Z,1568328155.893 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224236.00,A,3648.16865,N,12147.28037,W,0.156,55.93,120919,,,A*4F 2019-09-12T22:42:35.895Z,1568328155.895 [NAL9602](INFO): GPS fix at 20190912T224236: (36.802811, -121.788006) 2019-09-12T22:42:35.925Z,1568328155.925 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:42:35.925Z,1568328155.925 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:42:44.908Z,1568328164.908 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T212209/Courier0039.lzma 2019-09-12T22:42:46.914Z,1568328166.914 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0039.lzma.bak 2019-09-12T22:42:46.914Z,1568328166.914 [DataOverHttps](INFO): SBD MOMSN=11777776 2019-09-12T22:43:01.334Z,1568328181.334 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:43:01.334Z,1568328181.334 [DVL_micro](ERROR): Failed to parse: :TS,000000000000001.3,0000.0,1489.0,000 2019-09-12T22:43:06.112Z,1568328186.112 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190912T212209/Express0040.lzma 2019-09-12T22:43:06.586Z,1568328186.586 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-09-12T22:43:06.669Z,1568328186.669 [NAL9602](FAULT): received: +CSQ:0 OK13, 2, 0, 0, 0 OK 2019-09-12T22:43:06.669Z,1568328186.669 [NAL9602] Data Fault, FailCount= 1 2019-09-12T22:43:06.669Z,1568328186.669 [NAL9602](ERROR): Data Fault 2019-09-12T22:43:06.710Z,1568328186.710 [CBIT](ERROR): Data Fault in component: NAL9602 2019-09-12T22:43:06.990Z,1568328186.990 [NAL9602](INFO): Powering down 2019-09-12T22:43:07.850Z,1568328187.850 [CBIT](INFO): Clearing failed state for component NAL9602 2019-09-12T22:43:07.850Z,1568328187.850 [NAL9602] No Fault, FailCount= 1 2019-09-12T22:43:08.118Z,1568328188.118 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0040.lzma.bak 2019-09-12T22:43:08.118Z,1568328188.118 [DataOverHttps](INFO): SBD MOMSN=11777779 2019-09-12T22:43:11.513Z,1568328191.513 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:43:11.513Z,1568328191.513 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:43:11.514Z,1568328191.514 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:43:37.294Z,1568328217.294 [NAL9602](INFO): Powering up NAL9602 2019-09-12T22:43:39.318Z,1568328219.318 [DVL_micro](ERROR): Failed to parse: :WI,-00396,-00252,+00720,+00000,A 2019-09-12T22:43:48.199Z,1568328228.199 [NAL9602](INFO): NAL9602 initialized 2019-09-12T22:44:12.438Z,1568328252.438 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:44:12.438Z,1568328252.438 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.4,0000.0,148 2019-09-12T22:44:19.303Z,1568328259.303 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:44:30.289Z,1568328270.289 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-09-12T22:44:30.289Z,1568328270.289 [DVL_micro] Communications Fault, FailCount= 1 2019-09-12T22:44:30.289Z,1568328270.289 [DVL_micro](ERROR): Communications Fault 2019-09-12T22:44:30.289Z,1568328270.289 [DVL_micro](ERROR): Failed to parse: 2019-09-12T22:44:30.321Z,1568328270.321 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-09-12T22:44:30.685Z,1568328270.685 [DVL_micro](INFO): Powering down 2019-09-12T22:44:31.465Z,1568328271.465 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-09-12T22:44:31.465Z,1568328271.465 [DVL_micro] No Fault, FailCount= 1 2019-09-12T22:44:37.561Z,1568328277.561 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-09-12T22:44:37.561Z,1568328277.561 [DVL_micro] Communications Fault, FailCount= 1 2019-09-12T22:44:37.561Z,1568328277.561 [DVL_micro](ERROR): Communications Fault 2019-09-12T22:44:37.561Z,1568328277.561 [DVL_micro](ERROR): Failed to parse: 2019-09-12T22:44:37.666Z,1568328277.666 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-09-12T22:44:37.961Z,1568328277.961 [DVL_micro](INFO): Powering down 2019-09-12T22:44:38.769Z,1568328278.769 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-09-12T22:44:38.770Z,1568328278.770 [DVL_micro] No Fault, FailCount= 1 2019-09-12T22:45:20.316Z,1568328320.316 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T22:45:20.316Z,1568328320.316 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.999 2019-09-12T22:47:56.707Z,1568328476.707 [CBIT](INFO): Clearing failed state for component DropWeight 2019-09-12T22:47:56.707Z,1568328476.707 [DropWeight] No Fault, FailCount= 1 2019-09-12T22:48:12.057Z,1568328492.057 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:48:12.057Z,1568328492.057 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:48:12.057Z,1568328492.057 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:48:12.058Z,1568328492.058 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:48:12.449Z,1568328492.449 [Default:CheckIn:D] Stopped 2019-09-12T22:48:12.449Z,1568328492.449 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:48:12.861Z,1568328492.861 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 132.117725 min 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn:E] Stopped 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn] Stopped 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn](INFO): Running loop #23 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn] Running Loop=23 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:48:12.862Z,1568328492.862 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:48:14.449Z,1568328494.449 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:48:14.844Z,1568328494.844 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,224814.00,A,3648.17135,N,12147.27793,W,0.272,0.00,120919,,,A*71 2019-09-12T22:48:14.846Z,1568328494.846 [NAL9602](INFO): GPS fix at 20190912T224814: (36.802856, -121.787965) 2019-09-12T22:48:14.886Z,1568328494.886 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:48:14.886Z,1568328494.886 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:48:16.863Z,1568328496.863 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:48:23.857Z,1568328503.857 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T212209/Courier0042.lzma 2019-09-12T22:48:25.862Z,1568328505.862 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0042.lzma.bak 2019-09-12T22:48:25.863Z,1568328505.863 [DataOverHttps](INFO): SBD MOMSN=11777790 2019-09-12T22:48:45.180Z,1568328525.180 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20190912T212209/Express0043.lzma 2019-09-12T22:48:47.186Z,1568328527.186 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0043.lzma.bak 2019-09-12T22:48:47.186Z,1568328527.186 [DataOverHttps](INFO): SBD MOMSN=11777793 2019-09-12T22:48:47.562Z,1568328527.562 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:48:50.433Z,1568328530.433 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:48:50.434Z,1568328530.434 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:48:50.434Z,1568328530.434 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T22:49:03.724Z,1568328543.724 [DVL_micro](ERROR): Failed to parse: 0000000000,35.0,+21.2,0000.0,1489.0,000 2019-09-12T22:49:21.500Z,1568328561.500 [DVL_micro](ERROR): Failed to parse: :WI+00013,+0000,A 2019-09-12T22:50:14.831Z,1568328614.831 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.99,+9999.99 2019-09-12T22:51:08.241Z,1568328668.241 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-09-12T22:51:08.241Z,1568328668.241 [DVL_micro] Communications Fault, FailCount= 1 2019-09-12T22:51:08.241Z,1568328668.241 [DVL_micro](ERROR): Communications Fault 2019-09-12T22:51:08.241Z,1568328668.241 [DVL_micro](ERROR): Failed to parse: 2019-09-12T22:51:08.300Z,1568328668.300 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-09-12T22:51:08.633Z,1568328668.633 [DVL_micro](INFO): Powering down 2019-09-12T22:51:09.398Z,1568328669.398 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-09-12T22:51:09.398Z,1568328669.398 [DVL_micro] No Fault, FailCount= 1 2019-09-12T22:51:15.427Z,1568328675.427 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:51:15.427Z,1568328675.427 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,00.0,1489:WI,+01436,+01043,+00027,+00000,A 2019-09-12T22:53:51.017Z,1568328831.017 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T22:53:51.017Z,1568328831.017 [Default:CheckIn:C.Wait] Stopped 2019-09-12T22:53:51.017Z,1568328831.017 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T22:53:51.018Z,1568328831.018 [Default:CheckIn:D] Running Loop=1 2019-09-12T22:53:51.418Z,1568328831.418 [Default:CheckIn:D] Stopped 2019-09-12T22:53:51.418Z,1568328831.418 [Default:CheckIn:E] Running Loop=1 2019-09-12T22:53:51.811Z,1568328831.811 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.767204 min 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn:E] Stopped 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn] Stopped 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn](INFO): Running loop #24 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn] Running Loop=24 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T22:53:51.812Z,1568328831.812 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T22:53:53.413Z,1568328833.413 [NAL9602](DEBUG): Fix Requested 2019-09-12T22:54:16.369Z,1568328856.369 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T22:54:19.382Z,1568328859.382 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.240078 2019-09-12T22:54:28.953Z,1568328868.953 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T22:54:28.953Z,1568328868.953 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+20.3,0000.0,1489.0,,+00197,-01322,+01498,+00000,A 2019-09-12T22:54:51.509Z,1568328891.509 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T22:55:26.657Z,1568328926.657 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T22:56:01.797Z,1568328961.797 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-09-12T22:56:15.457Z,1568328975.457 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002980 2019-09-12T22:56:45.941Z,1568329005.941 [DVL_micro](ERROR): Failed to parse: :SA,+01.92,+05.29,067.9 2019-09-12T22:57:03.276Z,1568329023.276 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:57:03.276Z,1568329023.276 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:57:33.176Z,1568329053.176 [NAL9602](INFO): SBD MO Status=2, MOMSN=1313, MT Status=2, MTMSN=0 2019-09-12T22:57:33.176Z,1568329053.176 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T22:58:52.000Z,1568329132.000 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-09-12T22:53:51.8Z 2019-09-12T22:58:52.001Z,1568329132.001 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T22:58:52.001Z,1568329132.001 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T22:58:55.990Z,1568329135.990 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T22:59:00.752Z,1568329140.752 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T212209/Courier0045.lzma 2019-09-12T22:59:02.759Z,1568329142.759 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Courier0045.lzma.bak 2019-09-12T22:59:02.759Z,1568329142.759 [DataOverHttps](INFO): SBD MOMSN=11777822 2019-09-12T22:59:21.956Z,1568329161.956 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190912T212209/Express0046.lzma 2019-09-12T22:59:23.962Z,1568329163.962 [DataOverHttps](INFO): Moved sent file to Logs/20190912T212209/Express0046.lzma.bak 2019-09-12T22:59:23.962Z,1568329163.962 [DataOverHttps](INFO): SBD MOMSN=11777824 2019-09-12T22:59:26.694Z,1568329166.694 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T22:59:27.189Z,1568329167.189 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T22:59:27.190Z,1568329167.190 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T22:59:27.190Z,1568329167.190 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T23:04:26.471Z,1568329466.471 [CommandLine](IMPORTANT): got command quit 2019-09-12T23:04:27.477Z,1568329467.477 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:27.477Z,1568329467.477 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:27.501Z,1568329467.501 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-09-12T23:04:27.501Z,1568329467.501 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:27.502Z,1568329467.502 [CommandLine](INFO): Join timeout helper Thread ID is 6660 2019-09-12T23:04:27.509Z,1568329467.509 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-09-12T23:04:27.509Z,1568329467.509 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:27.509Z,1568329467.509 [NavChartDb](INFO): Join timeout helper Thread ID is 6661 2019-09-12T23:04:27.525Z,1568329467.525 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:27.525Z,1568329467.525 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:27.537Z,1568329467.537 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-09-12T23:04:27.537Z,1568329467.537 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:27.537Z,1568329467.537 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 6662 2019-09-12T23:04:27.734Z,1568329467.734 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T23:04:27.734Z,1568329467.734 [Default:CheckIn:C.Wait] Stopped 2019-09-12T23:04:27.734Z,1568329467.734 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T23:04:27.735Z,1568329467.735 [Default:CheckIn:D] Running Loop=1 2019-09-12T23:04:28.001Z,1568329468.001 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:28.001Z,1568329468.001 [WetLabsBB2FL](INFO): Powering down 2019-09-12T23:04:28.002Z,1568329468.002 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.021Z,1568329468.021 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-09-12T23:04:28.021Z,1568329468.021 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.021Z,1568329468.021 [CTD_Seabird](INFO): Join timeout helper Thread ID is 6663 2019-09-12T23:04:28.149Z,1568329468.149 [CTD_Seabird](INFO): Powering down 2019-09-12T23:04:28.158Z,1568329468.158 [Default:CheckIn:D] Stopped 2019-09-12T23:04:28.158Z,1568329468.158 [Default:CheckIn:E] Running Loop=1 2019-09-12T23:04:28.161Z,1568329468.161 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:28.161Z,1568329468.161 [CTD_Seabird](INFO): Powering down 2019-09-12T23:04:28.173Z,1568329468.173 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.189Z,1568329468.189 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-09-12T23:04:28.189Z,1568329468.189 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.189Z,1568329468.189 [Radio_Surface](INFO): Join timeout helper Thread ID is 6664 2019-09-12T23:04:28.257Z,1568329468.257 [Radio_Surface](INFO): Powering down 2019-09-12T23:04:28.258Z,1568329468.258 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:28.258Z,1568329468.258 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.278Z,1568329468.278 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-09-12T23:04:28.278Z,1568329468.278 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:28.278Z,1568329468.278 [DataOverHttps](INFO): Join timeout helper Thread ID is 6665 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 148.379541 min 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn:E] Stopped 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn] Stopped 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn](INFO): Running loop #25 2019-09-12T23:04:28.517Z,1568329468.517 [Default:CheckIn] Running Loop=25 2019-09-12T23:04:28.518Z,1568329468.518 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T23:04:28.518Z,1568329468.518 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T23:04:29.157Z,1568329469.157 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:29.160Z,1568329469.160 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.173Z,1568329469.173 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-09-12T23:04:29.174Z,1568329469.174 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.174Z,1568329469.174 [logger](INFO): Join timeout helper Thread ID is 6666 2019-09-12T23:04:29.221Z,1568329469.221 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:29.221Z,1568329469.221 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.233Z,1568329469.233 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-09-12T23:04:29.233Z,1568329469.233 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.234Z,1568329469.234 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-09-12T23:04:29.234Z,1568329469.234 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.234Z,1568329469.234 [controlThread](INFO): Join timeout helper Thread ID is 6667 2019-09-12T23:04:29.273Z,1568329469.273 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T23:04:29.273Z,1568329469.273 [controlThread](DEBUG): Uninitializing ControlThread 2019-09-12T23:04:29.273Z,1568329469.273 [AHRS_M2](INFO): Powering down 2019-09-12T23:04:29.417Z,1568329469.417 [DVL_micro](INFO): Powering down 2019-09-12T23:04:29.418Z,1568329469.418 [NAL9602](INFO): Powering down 2019-09-12T23:04:29.419Z,1568329469.419 [DAT](INFO): Powering down 2019-09-12T23:04:29.538Z,1568329469.538 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-09-12T23:04:29.539Z,1568329469.539 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-09-12T23:04:29.539Z,1568329469.539 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-09-12T23:04:29.540Z,1568329469.540 [MissionManager](INFO): Uninitializing Mission Default 2019-09-12T23:04:29.540Z,1568329469.540 [Default] Stopped 2019-09-12T23:04:29.540Z,1568329469.540 [Default](DEBUG): Aggregate::uninitialize Default 2019-09-12T23:04:29.540Z,1568329469.540 [Default:B.GoToSurface] Stopped 2019-09-12T23:04:29.540Z,1568329469.540 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-09-12T23:04:29.540Z,1568329469.540 [Default:CheckIn] Stopped 2019-09-12T23:04:29.540Z,1568329469.540 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T23:04:29.540Z,1568329469.540 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T23:04:29.543Z,1568329469.543 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-09-12T23:04:29.543Z,1568329469.543 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-09-12T23:04:29.543Z,1568329469.543 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-09-12T23:04:29.543Z,1568329469.543 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-09-12T23:04:29.544Z,1568329469.544 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-09-12T23:04:29.544Z,1568329469.544 [BuoyancyServo](INFO): Powering down 2019-09-12T23:04:29.557Z,1568329469.557 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-09-12T23:04:29.557Z,1568329469.557 [ElevatorServo](INFO): Powering down 2019-09-12T23:04:29.558Z,1568329469.558 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-09-12T23:04:29.558Z,1568329469.558 [MassServo](INFO): Powering down 2019-09-12T23:04:29.559Z,1568329469.559 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-09-12T23:04:29.559Z,1568329469.559 [RudderServo](INFO): Powering down 2019-09-12T23:04:29.559Z,1568329469.559 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-09-12T23:04:29.559Z,1568329469.559 [ThrusterServo](INFO): Powering down 2019-09-12T23:04:29.560Z,1568329469.560 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-09-12T23:04:29.561Z,1568329469.561 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-09-12T23:04:29.561Z,1568329469.561 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-09-12T23:04:29.561Z,1568329469.561 [CBIT](DEBUG): Powering off loads. 2019-09-12T23:04:29.573Z,1568329469.573 [CBIT](DEBUG): Disabling WDT. 2019-09-12T23:04:29.585Z,1568329469.585 [CBIT](DEBUG): Opening all GF detection circuits. 2019-09-12T23:04:29.585Z,1568329469.585 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.665Z,1568329469.665 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.672Z,1568329469.672 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.708Z,1568329469.708 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.711Z,1568329469.711 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.744Z,1568329469.744 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T23:04:29.822Z,1568329469.822 [logger ThreadHandler](INFO): Thread cancelled.