2019-05-24T16:43:14.378Z,1558716194.378 [DataOverHttps](INFO): Received command:restart logs 2019-05-24T16:43:14.420Z,1558716194.420 [CommandLine](IMPORTANT): got command restart logs 2019-05-24T16:43:28.441Z,1558716208.441 [DVL_micro](ERROR): only read 43 of 46 data items 2019-05-24T16:43:28.441Z,1558716208.441 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 -1716 -326 1162 415 2 2 2 2 -3841.1 -989.0 -125.4 2 -250.2 -125.4 2 -3841 -989 -125 2 -2535 3050 -125 2 -14.94 3.74 295.3 -3.0 14.8 0.005 35.0 1489 94 2019-05-24T16:43:44.612Z,1558716224.612 [DVL_micro](ERROR): checksum mismatch: reported89 , calculated:95 2019-05-24T16:43:44.612Z,1558716224.612 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 1270 2661 -2369 -2025 2 2 2 2 454.1 -124.9 2 7744.3 -1651.0 -124.9 2 4856 6254 -124 2 7744 -1651 -124 2 -13.18 5.61 295.8 -3.0 14.8 0.005 35.0 1489 89 2019-05-24T16:44:00.765Z,1558716240.765 [DVL_micro](ERROR): only read 45 of 46 data items 2019-05-24T16:44:00.765Z,1558716240.765 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -1615 451 -3298 -329 2 2 2 2 2246.2 1041.0 -1291.8 2 2176.9 -1178.8 -1291.8 2 2246 1041 -1291 2 2176 -1178 -1291 2 -7.55 7.28 306.7 -3.0 14 35.0 1489 66 2019-05-24T16:44:04.003Z,1558716244.003 [DVL_micro](ERROR): only read 45 of 46 data items 2019-05-24T16:44:04.004Z,1558716244.004 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -2258 1937 -2561 1765 2 2 2 2 404.4 229.6 -301.2 2 388.2 -256.1 -301.2 2 404 229 -8 -256 -301 2 -9.46 3.70 297.0 -3.0 14.8 0.005 35.0 1489 105 2019-05-24T16:44:06.816Z,1558716246.816 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:44:06.816Z,1558716246.816 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:44:06.816Z,1558716246.816 [DVL_micro](ERROR): Data Fault 2019-05-24T16:44:06.865Z,1558716246.865 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:44:07.291Z,1558716247.291 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:44:08.097Z,1558716248.097 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:44:08.097Z,1558716248.097 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:44:08.438Z,1558716248.438 [DVL_micro](INFO): Initializing 2019-05-24T16:44:14.910Z,1558716254.910 [DVL_micro](ERROR): only read 43 of 46 data items 2019-05-24T16:44:14.910Z,1558716254.910 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 -1519 2035 -2100 23 2 2 2 2 775.4 2685.3 -420.9 2 2762.9 422.4 -420.9 2 775 2685 -420 2 2762 422 -420 2 -12.57 3.18 294.8 -3.0 14.8 0.005 35.0 1489 83 2019-05-24T16:44:18.137Z,1558716258.137 [DVL_micro](ERROR): only read 43 of 46 data items 2019-05-24T16:44:18.138Z,1558716258.138 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 -1545 1589 -2645 2984 2 2 2 2 1468.1 -1861.8 103.3 2 -1048.4 -2126.6 103.3 2 1468 -1861 103 2 -1048 -2126 103 2 -13.73 5.27 295.5 -3.0 14.8 0.005 35.0 1489 91 2019-05-24T16:47:12.653Z,1558716432.653 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:47:12.653Z,1558716432.653 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:47:12.653Z,1558716432.653 [DVL_micro](ERROR): Data Fault 2019-05-24T16:47:12.687Z,1558716432.687 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:47:13.131Z,1558716433.131 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:47:13.912Z,1558716433.912 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:47:13.912Z,1558716433.912 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:47:14.282Z,1558716434.282 [DVL_micro](INFO): Initializing 2019-05-24T16:48:10.048Z,1558716490.048 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T16:48:10.048Z,1558716490.048 [Default:CheckIn:C.Wait] Stopped 2019-05-24T16:48:10.048Z,1558716490.048 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T16:48:10.048Z,1558716490.048 [Default:CheckIn:D] Running Loop=1 2019-05-24T16:48:10.463Z,1558716490.463 [Default:CheckIn:D] Stopped 2019-05-24T16:48:10.463Z,1558716490.463 [Default:CheckIn:E] Running Loop=1 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 14.414118 min 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn:E] Stopped 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn] Stopped 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn](INFO): Running loop #3 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn] Running Loop=3 2019-05-24T16:48:10.921Z,1558716490.921 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T16:48:10.922Z,1558716490.922 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T16:48:12.487Z,1558716492.487 [NAL9602](DEBUG): Fix Requested 2019-05-24T16:48:12.856Z,1558716492.856 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164403.00,A,3648.47935,N,12147.25021,W,8.222,54.46,240519,,,D*4F 2019-05-24T16:48:12.859Z,1558716492.859 [NAL9602](INFO): GPS fix at 20190524T164403: (36.807989, -121.787503) 2019-05-24T16:48:12.885Z,1558716492.885 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T16:48:12.886Z,1558716492.885 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T16:48:14.937Z,1558716494.937 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T16:48:19.032Z,1558716499.032 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T010101/Courier0090.lzma 2019-05-24T16:48:19.837Z,1558716499.837 [DataOverHttps](INFO): Moved sent file to Logs/20190524T010101/Courier0090.lzma.bak 2019-05-24T16:48:19.837Z,1558716499.837 [DataOverHttps](INFO): SBD MOMSN=11179592 2019-05-24T16:48:31.231Z,1558716511.231 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20190524T164314/Courier0000.lzma 2019-05-24T16:48:32.036Z,1558716512.036 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0000.lzma.bak 2019-05-24T16:48:32.036Z,1558716512.036 [DataOverHttps](INFO): SBD MOMSN=11179594 2019-05-24T16:48:38.407Z,1558716518.407 [NAL9602](INFO): SBD MO Status=2, MOMSN=12966, MT Status=2, MTMSN=0 2019-05-24T16:48:38.411Z,1558716518.411 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-24T16:48:43.362Z,1558716523.362 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T164314/Courier0003.lzma 2019-05-24T16:48:44.168Z,1558716524.168 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0003.lzma.bak 2019-05-24T16:48:44.168Z,1558716524.168 [DataOverHttps](INFO): SBD MOMSN=11179598 2019-05-24T16:48:55.596Z,1558716535.596 [DataOverHttps](INFO): Sending 117 bytes from file Logs/20190524T010101/Express0091.lzma 2019-05-24T16:48:56.401Z,1558716536.401 [DataOverHttps](INFO): Moved sent file to Logs/20190524T010101/Express0091.lzma.bak 2019-05-24T16:48:56.401Z,1558716536.401 [DataOverHttps](INFO): SBD MOMSN=11179600 2019-05-24T16:48:57.354Z,1558716537.354 [NAL9602](INFO): SBD MO Status=0, MOMSN=12966, MT Status=0, MTMSN=0 2019-05-24T16:48:57.354Z,1558716537.354 [NAL9602](INFO): No messages in MT queue 2019-05-24T16:49:08.203Z,1558716548.203 [DataOverHttps](INFO): Sending 404 bytes from file Logs/20190524T164314/Express0001.lzma 2019-05-24T16:49:09.008Z,1558716549.008 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0001.lzma.bak 2019-05-24T16:49:09.008Z,1558716549.008 [DataOverHttps](INFO): SBD MOMSN=11179603 2019-05-24T16:49:20.606Z,1558716560.606 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190524T164314/Express0002.lzma 2019-05-24T16:49:21.412Z,1558716561.412 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0002.lzma.bak 2019-05-24T16:49:21.412Z,1558716561.412 [DataOverHttps](INFO): SBD MOMSN=11179609 2019-05-24T16:49:28.056Z,1558716568.056 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T16:49:32.634Z,1558716572.634 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T164314/Express0004.lzma 2019-05-24T16:49:33.440Z,1558716573.440 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0004.lzma.bak 2019-05-24T16:49:33.440Z,1558716573.440 [DataOverHttps](INFO): SBD MOMSN=11179612 2019-05-24T16:49:34.584Z,1558716574.584 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T16:49:34.585Z,1558716574.585 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T16:49:34.585Z,1558716574.585 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T16:50:18.554Z,1558716618.554 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:50:18.554Z,1558716618.554 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:50:18.554Z,1558716618.554 [DVL_micro](ERROR): Data Fault 2019-05-24T16:50:18.588Z,1558716618.588 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:50:19.035Z,1558716619.035 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:50:19.801Z,1558716619.801 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:50:19.801Z,1558716619.801 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:50:20.178Z,1558716620.178 [DVL_micro](INFO): Initializing 2019-05-24T16:53:14.705Z,1558716794.705 [DVL_micro](ERROR): checksum mismatch: reported68 , calculated:86 2019-05-24T16:53:14.705Z,1558716794.705 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 205 -173 -1591 -1558 2 2 2 2 2397.0 1848.5 -840.5 2 -2961. -840.5 2 2397 1848 -840 2 -2961 -626 -840 2 -4.77 2.90 154.3 -3.0 15.2 0.005 35.0 1489 68 2019-05-24T16:53:24.413Z,1558716804.413 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:53:24.413Z,1558716804.413 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:53:24.413Z,1558716804.413 [DVL_micro](ERROR): Data Fault 2019-05-24T16:53:24.447Z,1558716804.447 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:53:24.899Z,1558716804.899 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:53:25.640Z,1558716805.640 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:53:25.640Z,1558716805.640 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:53:26.022Z,1558716806.022 [DVL_micro](INFO): Initializing 2019-05-24T16:54:35.124Z,1558716875.124 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T16:54:35.124Z,1558716875.124 [Default:CheckIn:C.Wait] Stopped 2019-05-24T16:54:35.124Z,1558716875.124 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T16:54:35.124Z,1558716875.124 [Default:CheckIn:D] Running Loop=1 2019-05-24T16:54:35.528Z,1558716875.528 [Default:CheckIn:D] Stopped 2019-05-24T16:54:35.528Z,1558716875.528 [Default:CheckIn:E] Running Loop=1 2019-05-24T16:54:35.931Z,1558716875.931 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.831871 min 2019-05-24T16:54:35.931Z,1558716875.931 [Default:CheckIn:E] Stopped 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn] Stopped 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn](INFO): Running loop #4 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn] Running Loop=4 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T16:54:35.932Z,1558716875.932 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T16:54:37.535Z,1558716877.535 [NAL9602](DEBUG): Fix Requested 2019-05-24T16:54:37.931Z,1558716877.931 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165027.00,A,3648.14398,N,12147.19794,W,2.916,188.45,240519,,,D*74 2019-05-24T16:54:37.933Z,1558716877.933 [NAL9602](INFO): GPS fix at 20190524T165027: (36.802400, -121.786632) 2019-05-24T16:54:37.981Z,1558716877.981 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T16:54:37.981Z,1558716877.981 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T16:54:39.568Z,1558716879.568 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T16:54:49.354Z,1558716889.354 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190524T164314/Courier0005.lzma 2019-05-24T16:54:50.160Z,1558716890.160 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0005.lzma.bak 2019-05-24T16:54:50.160Z,1558716890.160 [DataOverHttps](INFO): SBD MOMSN=11179646 2019-05-24T16:55:01.363Z,1558716901.363 [NAL9602](INFO): SBD MO Status=0, MOMSN=12967, MT Status=0, MTMSN=0 2019-05-24T16:55:01.363Z,1558716901.363 [NAL9602](INFO): No messages in MT queue 2019-05-24T16:55:01.879Z,1558716901.879 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190524T164314/Express0007.lzma 2019-05-24T16:55:02.684Z,1558716902.684 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0007.lzma.bak 2019-05-24T16:55:02.684Z,1558716902.684 [DataOverHttps](INFO): SBD MOMSN=11179649 2019-05-24T16:55:03.826Z,1558716903.826 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T16:55:03.826Z,1558716903.826 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T16:55:03.826Z,1558716903.826 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T16:55:32.089Z,1558716932.089 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T16:56:30.236Z,1558716990.236 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:56:30.237Z,1558716990.237 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:56:30.237Z,1558716990.237 [DVL_micro](ERROR): Data Fault 2019-05-24T16:56:30.270Z,1558716990.270 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:56:30.715Z,1558716990.715 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:56:31.493Z,1558716991.493 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:56:31.493Z,1558716991.493 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:56:31.856Z,1558716991.856 [DVL_micro](INFO): Initializing 2019-05-24T16:59:36.080Z,1558717176.080 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T16:59:36.080Z,1558717176.080 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T16:59:36.080Z,1558717176.080 [DVL_micro](ERROR): Data Fault 2019-05-24T16:59:36.115Z,1558717176.115 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T16:59:36.555Z,1558717176.555 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T16:59:37.339Z,1558717177.339 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T16:59:37.339Z,1558717177.339 [DVL_micro] No Fault, FailCount= 1 2019-05-24T16:59:37.706Z,1558717177.706 [DVL_micro](INFO): Initializing 2019-05-24T17:00:04.384Z,1558717204.384 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:00:04.384Z,1558717204.384 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:00:04.384Z,1558717204.384 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:00:04.384Z,1558717204.384 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:00:04.791Z,1558717204.791 [Default:CheckIn:D] Stopped 2019-05-24T17:00:04.791Z,1558717204.791 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 26.319586 min 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn:E] Stopped 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn] Stopped 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn](INFO): Running loop #5 2019-05-24T17:00:05.220Z,1558717205.220 [Default:CheckIn] Running Loop=5 2019-05-24T17:00:05.221Z,1558717205.221 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:00:05.221Z,1558717205.221 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:00:06.851Z,1558717206.851 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:00:07.196Z,1558717207.196 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165556.00,A,3648.13773,N,12147.20571,W,0.292,246.21,240519,,,D*74 2019-05-24T17:00:07.199Z,1558717207.199 [NAL9602](INFO): GPS fix at 20190524T165556: (36.802295, -121.786762) 2019-05-24T17:00:07.246Z,1558717207.246 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:00:07.246Z,1558717207.246 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:00:09.220Z,1558717209.220 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T17:00:12.634Z,1558717212.634 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190524T164314/Courier0009.lzma 2019-05-24T17:00:13.440Z,1558717213.440 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0009.lzma.bak 2019-05-24T17:00:13.440Z,1558717213.440 [DataOverHttps](INFO): SBD MOMSN=11179663 2019-05-24T17:00:25.023Z,1558717225.023 [DataOverHttps](INFO): Sending 174 bytes from file Logs/20190524T164314/Express0010.lzma 2019-05-24T17:00:25.828Z,1558717225.828 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0010.lzma.bak 2019-05-24T17:00:25.828Z,1558717225.828 [DataOverHttps](INFO): SBD MOMSN=11179666 2019-05-24T17:00:27.015Z,1558717227.015 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:00:27.015Z,1558717227.015 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:00:27.015Z,1558717227.015 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:01:03.750Z,1558717263.750 [NAL9602](INFO): SBD MO Status=2, MOMSN=12968, MT Status=2, MTMSN=0 2019-05-24T17:01:03.750Z,1558717263.750 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-05-24T17:01:56.282Z,1558717316.282 [NAL9602](INFO): SBD MO Status=0, MOMSN=12968, MT Status=0, MTMSN=0 2019-05-24T17:01:56.282Z,1558717316.282 [NAL9602](INFO): No messages in MT queue 2019-05-24T17:02:26.980Z,1558717346.980 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:02:41.932Z,1558717361.932 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:02:41.932Z,1558717361.932 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:02:41.933Z,1558717361.933 [DVL_micro](ERROR): Data Fault 2019-05-24T17:02:41.975Z,1558717361.975 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:02:42.407Z,1558717362.407 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:02:43.190Z,1558717363.190 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:02:43.190Z,1558717363.190 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:02:43.551Z,1558717363.551 [DVL_micro](INFO): Initializing 2019-05-24T17:05:27.601Z,1558717527.601 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:05:27.601Z,1558717527.601 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:05:27.601Z,1558717527.601 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:05:27.601Z,1558717527.601 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:05:28.007Z,1558717528.007 [Default:CheckIn:D] Stopped 2019-05-24T17:05:28.007Z,1558717528.007 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:05:28.432Z,1558717528.432 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.706510 min 2019-05-24T17:05:28.432Z,1558717528.432 [Default:CheckIn:E] Stopped 2019-05-24T17:05:28.432Z,1558717528.432 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn] Stopped 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn](INFO): Running loop #6 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn] Running Loop=6 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:05:28.433Z,1558717528.433 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:05:30.011Z,1558717530.011 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:05:30.400Z,1558717530.400 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170118.00,A,3648.14350,N,12147.20949,W,0.292,356.98,240519,,,D*79 2019-05-24T17:05:30.402Z,1558717530.402 [NAL9602](INFO): GPS fix at 20190524T170118: (36.802392, -121.786825) 2019-05-24T17:05:30.427Z,1558717530.427 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:05:30.427Z,1558717530.427 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:05:32.455Z,1558717532.455 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T17:05:35.906Z,1558717535.906 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190524T164314/Courier0012.lzma 2019-05-24T17:05:36.712Z,1558717536.712 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0012.lzma.bak 2019-05-24T17:05:36.712Z,1558717536.712 [DataOverHttps](INFO): SBD MOMSN=11179697 2019-05-24T17:05:47.772Z,1558717547.772 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:05:47.772Z,1558717547.772 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:05:47.772Z,1558717547.772 [DVL_micro](ERROR): Data Fault 2019-05-24T17:05:47.823Z,1558717547.823 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:05:47.935Z,1558717547.935 [DataOverHttps](INFO): Sending 167 bytes from file Logs/20190524T164314/Express0013.lzma 2019-05-24T17:05:48.251Z,1558717548.251 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:05:48.740Z,1558717548.740 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0013.lzma.bak 2019-05-24T17:05:48.740Z,1558717548.740 [DataOverHttps](INFO): SBD MOMSN=11179700 2019-05-24T17:05:49.020Z,1558717549.020 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:05:49.020Z,1558717549.020 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:05:49.394Z,1558717549.394 [DVL_micro](INFO): Initializing 2019-05-24T17:05:49.832Z,1558717549.832 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:05:49.833Z,1558717549.833 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:05:49.833Z,1558717549.833 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:05:52.218Z,1558717552.218 [NAL9602](INFO): SBD MO Status=0, MOMSN=12969, MT Status=0, MTMSN=0 2019-05-24T17:05:52.218Z,1558717552.218 [NAL9602](INFO): No messages in MT queue 2019-05-24T17:06:22.920Z,1558717582.920 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:06:34.658Z,1558717594.658 [DVL_micro](ERROR): only read 45 of 46 data items 2019-05-24T17:06:34.658Z,1558717594.658 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -2260 -1462 -18462 2 2 -552.5 -739.4 -1746.2 2 -801.2 458.3 -1746.2 2 -552 -739 -1746 2 -801 458 -1746 2 -7.49 0.67 277.0 -3.0 15.8 0.005 35.0 1489 90 2019-05-24T17:08:53.609Z,1558717733.609 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:08:53.609Z,1558717733.609 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:08:53.609Z,1558717733.609 [DVL_micro](ERROR): Data Fault 2019-05-24T17:08:53.651Z,1558717733.651 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:08:54.087Z,1558717734.087 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:08:54.862Z,1558717734.862 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:08:54.863Z,1558717734.863 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:08:55.241Z,1558717735.241 [DVL_micro](INFO): Initializing 2019-05-24T17:10:50.406Z,1558717850.406 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:10:50.406Z,1558717850.406 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:10:50.406Z,1558717850.406 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:10:50.408Z,1558717850.408 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:10:50.796Z,1558717850.796 [Default:CheckIn:D] Stopped 2019-05-24T17:10:50.796Z,1558717850.796 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:10:51.201Z,1558717851.201 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 37.086332 min 2019-05-24T17:10:51.201Z,1558717851.201 [Default:CheckIn:E] Stopped 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn] Stopped 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn](INFO): Running loop #7 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn] Running Loop=7 2019-05-24T17:10:51.202Z,1558717851.202 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:10:51.203Z,1558717851.203 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:10:52.811Z,1558717852.811 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:10:53.202Z,1558717853.202 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170641.00,A,3648.16473,N,12147.28258,W,0.194,358.41,240519,,,A*7F 2019-05-24T17:10:53.204Z,1558717853.204 [NAL9602](INFO): GPS fix at 20190524T170641: (36.802746, -121.788043) 2019-05-24T17:10:53.229Z,1558717853.229 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:10:53.229Z,1558717853.229 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:10:54.888Z,1558717854.888 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T17:10:58.742Z,1558717858.742 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190524T164314/Courier0015.lzma 2019-05-24T17:10:59.548Z,1558717859.548 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0015.lzma.bak 2019-05-24T17:10:59.548Z,1558717859.548 [DataOverHttps](INFO): SBD MOMSN=11179712 2019-05-24T17:11:10.735Z,1558717870.735 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190524T164314/Express0016.lzma 2019-05-24T17:11:11.540Z,1558717871.540 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0016.lzma.bak 2019-05-24T17:11:11.540Z,1558717871.540 [DataOverHttps](INFO): SBD MOMSN=11179716 2019-05-24T17:11:12.659Z,1558717872.659 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:11:12.659Z,1558717872.659 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:11:12.659Z,1558717872.659 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:11:59.472Z,1558717919.472 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:11:59.472Z,1558717919.472 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:11:59.472Z,1558717919.472 [DVL_micro](ERROR): Data Fault 2019-05-24T17:11:59.532Z,1558717919.532 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:11:59.947Z,1558717919.947 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:12:00.718Z,1558717920.718 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:12:00.718Z,1558717920.718 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:12:01.094Z,1558717921.094 [DVL_micro](INFO): Initializing 2019-05-24T17:15:05.318Z,1558718105.318 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:15:05.318Z,1558718105.318 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:15:05.318Z,1558718105.318 [DVL_micro](ERROR): Data Fault 2019-05-24T17:15:05.352Z,1558718105.352 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:15:05.783Z,1558718105.783 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:15:06.584Z,1558718106.584 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:15:06.585Z,1558718106.585 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:15:06.938Z,1558718106.938 [DVL_micro](INFO): Initializing 2019-05-24T17:15:52.188Z,1558718152.188 [DVL_micro](ERROR): only read 45 of 46 data items 2019-05-24T17:15:52.189Z,1558718152.189 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 062 -1121 712 -1408 2 2 2 2 -2768.0 383.0 -857.2 2 2757.4 452.5 -857.2 2 -2768 383 -857 2 2757 452 -857 2 -6.52 -2.16 197.2 -3.0 16.8 0.005 35.0 1489 89 2019-05-24T17:15:55.434Z,1558718155.434 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-24T17:16:13.212Z,1558718173.212 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:16:13.212Z,1558718173.212 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:16:13.212Z,1558718173.212 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:16:13.212Z,1558718173.212 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:16:13.620Z,1558718173.620 [Default:CheckIn:D] Stopped 2019-05-24T17:16:13.620Z,1558718173.620 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:16:14.027Z,1558718174.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.466740 min 2019-05-24T17:16:14.027Z,1558718174.027 [Default:CheckIn:E] Stopped 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn] Stopped 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn](INFO): Running loop #8 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn] Running Loop=8 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:16:14.028Z,1558718174.028 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:16:15.627Z,1558718175.627 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:16:16.018Z,1558718176.018 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171203.00,A,3648.26936,N,12147.24201,W,8.397,16.04,240519,,,A*42 2019-05-24T17:16:16.020Z,1558718176.020 [NAL9602](INFO): GPS fix at 20190524T171203: (36.804489, -121.787367) 2019-05-24T17:16:16.045Z,1558718176.045 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:16:16.045Z,1558718176.045 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:16:21.634Z,1558718181.634 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190524T164314/Courier0018.lzma 2019-05-24T17:16:22.440Z,1558718182.440 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0018.lzma.bak 2019-05-24T17:16:22.440Z,1558718182.440 [DataOverHttps](INFO): SBD MOMSN=11179747 2019-05-24T17:16:33.611Z,1558718193.611 [DataOverHttps](INFO): Sending 272 bytes from file Logs/20190524T164314/Express0019.lzma 2019-05-24T17:16:34.416Z,1558718194.416 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0019.lzma.bak 2019-05-24T17:16:34.417Z,1558718194.417 [DataOverHttps](INFO): SBD MOMSN=11179750 2019-05-24T17:16:35.878Z,1558718195.878 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:16:35.878Z,1558718195.878 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:16:35.883Z,1558718195.883 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:16:48.332Z,1558718208.332 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:18:11.152Z,1558718291.152 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:18:11.152Z,1558718291.152 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:18:11.152Z,1558718291.152 [DVL_micro](ERROR): Data Fault 2019-05-24T17:18:11.203Z,1558718291.203 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:18:11.627Z,1558718291.627 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:18:12.402Z,1558718292.402 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:18:12.403Z,1558718292.403 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:18:12.774Z,1558718292.774 [DVL_micro](INFO): Initializing 2019-05-24T17:21:17.028Z,1558718477.028 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:21:17.028Z,1558718477.028 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:21:17.028Z,1558718477.028 [DVL_micro](ERROR): Data Fault 2019-05-24T17:21:17.075Z,1558718477.075 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:21:17.487Z,1558718477.487 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:21:18.282Z,1558718478.282 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:21:18.282Z,1558718478.282 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:21:18.638Z,1558718478.638 [DVL_micro](INFO): Initializing 2019-05-24T17:21:36.435Z,1558718496.435 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:21:36.436Z,1558718496.436 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:21:36.436Z,1558718496.436 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:21:36.436Z,1558718496.436 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:21:36.844Z,1558718496.844 [Default:CheckIn:D] Stopped 2019-05-24T17:21:36.844Z,1558718496.844 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 47.853796 min 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn:E] Stopped 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn] Stopped 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:21:37.248Z,1558718497.248 [Default:CheckIn](INFO): Running loop #9 2019-05-24T17:21:37.249Z,1558718497.249 [Default:CheckIn] Running Loop=9 2019-05-24T17:21:37.249Z,1558718497.249 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:21:37.249Z,1558718497.249 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:21:38.843Z,1558718498.843 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:21:39.234Z,1558718499.234 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171726.00,A,3648.16183,N,12147.28392,W,0.447,212.41,240519,,,A*77 2019-05-24T17:21:39.236Z,1558718499.236 [NAL9602](INFO): GPS fix at 20190524T171726: (36.802697, -121.788065) 2019-05-24T17:21:39.267Z,1558718499.267 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:21:39.267Z,1558718499.267 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:21:40.880Z,1558718500.880 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-05-24T17:21:44.908Z,1558718504.908 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190524T164314/Courier0021.lzma 2019-05-24T17:21:45.713Z,1558718505.713 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0021.lzma.bak 2019-05-24T17:21:45.713Z,1558718505.713 [DataOverHttps](INFO): SBD MOMSN=11179765 2019-05-24T17:21:56.958Z,1558718516.958 [DataOverHttps](INFO): Sending 190 bytes from file Logs/20190524T164314/Express0022.lzma 2019-05-24T17:21:57.764Z,1558718517.764 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0022.lzma.bak 2019-05-24T17:21:57.764Z,1558718517.764 [DataOverHttps](INFO): SBD MOMSN=11179768 2019-05-24T17:21:58.659Z,1558718518.659 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:21:58.659Z,1558718518.659 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:21:58.659Z,1558718518.659 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:22:09.940Z,1558718529.940 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-05-24T17:22:10.463Z,1558718530.463 [NAL9602](FAULT): received: 2019-05-24T17:22:10.463Z,1558718530.463 [NAL9602] Data Fault, FailCount= 1 2019-05-24T17:22:10.463Z,1558718530.463 [NAL9602](ERROR): Data Fault 2019-05-24T17:22:10.508Z,1558718530.508 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-24T17:22:10.629Z,1558718530.629 [NAL9602](INFO): Powering down 2019-05-24T17:22:10.928Z,1558718530.928 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2019-05-24T17:22:10.928Z,1558718530.928 [NAL9602] Hardware Fault, FailCount= 1 2019-05-24T17:22:10.928Z,1558718530.928 [NAL9602](ERROR): Hardware Fault 2019-05-24T17:22:11.400Z,1558718531.400 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-24T17:22:11.400Z,1558718531.400 [NAL9602] No Fault, FailCount= 1 2019-05-24T17:22:40.828Z,1558718560.828 [NAL9602](INFO): Powering up NAL9602 2019-05-24T17:22:51.733Z,1558718571.733 [NAL9602](INFO): NAL9602 initialized 2019-05-24T17:23:22.840Z,1558718602.840 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:24:23.040Z,1558718663.040 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:24:23.040Z,1558718663.040 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:24:23.040Z,1558718663.040 [DVL_micro](ERROR): Data Fault 2019-05-24T17:24:23.100Z,1558718663.100 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:24:23.511Z,1558718663.511 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:24:24.279Z,1558718664.279 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:24:24.279Z,1558718664.279 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:24:24.658Z,1558718664.658 [DVL_micro](INFO): Initializing 2019-05-24T17:26:59.414Z,1558718819.414 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:26:59.414Z,1558718819.414 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:26:59.414Z,1558718819.414 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:26:59.414Z,1558718819.414 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:26:59.878Z,1558718819.878 [Default:CheckIn:D] Stopped 2019-05-24T17:26:59.878Z,1558718819.878 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:27:00.223Z,1558718820.223 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.237703 min 2019-05-24T17:27:00.223Z,1558718820.223 [Default:CheckIn:E] Stopped 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn] Stopped 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn](INFO): Running loop #10 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn] Running Loop=10 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:27:00.224Z,1558718820.224 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:27:01.831Z,1558718821.831 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:04.236Z,1558718824.236 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-24T17:27:05.059Z,1558718825.059 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:07.879Z,1558718827.879 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:10.711Z,1558718830.711 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:13.543Z,1558718833.543 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:16.771Z,1558718836.771 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:19.611Z,1558718839.611 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:22.839Z,1558718842.839 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:25.687Z,1558718845.687 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:28.876Z,1558718848.876 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:27:28.876Z,1558718848.876 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:27:28.877Z,1558718848.877 [DVL_micro](ERROR): Data Fault 2019-05-24T17:27:28.891Z,1558718848.891 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:28.932Z,1558718848.932 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:27:29.351Z,1558718849.351 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:27:30.146Z,1558718850.146 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:27:30.146Z,1558718850.146 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:27:30.498Z,1558718850.498 [DVL_micro](INFO): Initializing 2019-05-24T17:27:31.715Z,1558718851.715 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:34.547Z,1558718854.547 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:36.571Z,1558718856.571 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:39.799Z,1558718859.799 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:42.627Z,1558718862.627 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:45.863Z,1558718865.863 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:48.687Z,1558718868.687 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:51.923Z,1558718871.923 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:54.747Z,1558718874.747 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:57.571Z,1558718877.571 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:27:59.635Z,1558718879.635 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:01.615Z,1558718881.615 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:04.843Z,1558718884.843 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:07.679Z,1558718887.679 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:10.907Z,1558718890.907 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:13.746Z,1558718893.746 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:16.963Z,1558718896.963 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:19.799Z,1558718899.799 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:22.631Z,1558718902.631 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:24.639Z,1558718904.639 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:27.875Z,1558718907.875 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:30.699Z,1558718910.699 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:33.935Z,1558718913.935 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:36.759Z,1558718916.759 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:39.995Z,1558718919.995 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:42.831Z,1558718922.831 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:45.655Z,1558718925.655 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:47.675Z,1558718927.675 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:49.687Z,1558718929.687 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:52.928Z,1558718932.928 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:55.751Z,1558718935.751 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:28:58.983Z,1558718938.983 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:01.815Z,1558718941.815 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:05.051Z,1558718945.051 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:07.907Z,1558718947.907 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:10.731Z,1558718950.731 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:12.719Z,1558718952.719 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:15.956Z,1558718955.956 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:18.779Z,1558718958.779 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:22.019Z,1558718962.019 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:24.839Z,1558718964.839 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:28.075Z,1558718968.075 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:30.899Z,1558718970.899 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:33.727Z,1558718973.727 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:35.754Z,1558718975.754 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:38.984Z,1558718978.984 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:41.803Z,1558718981.803 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:45.039Z,1558718985.039 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:47.867Z,1558718987.867 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:51.103Z,1558718991.103 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:53.927Z,1558718993.927 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:56.759Z,1558718996.759 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:29:58.775Z,1558718998.775 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:00.795Z,1558719000.795 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:02.815Z,1558719002.815 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:06.043Z,1558719006.043 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:08.911Z,1558719008.911 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:12.143Z,1558719012.143 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:14.939Z,1558719014.939 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:17.779Z,1558719017.779 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:19.787Z,1558719019.787 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:21.823Z,1558719021.823 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:23.827Z,1558719023.827 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:27.059Z,1558719027.059 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:29.887Z,1558719029.887 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:33.111Z,1558719033.111 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:34.716Z,1558719034.716 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:30:34.716Z,1558719034.716 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:30:34.716Z,1558719034.716 [DVL_micro](ERROR): Data Fault 2019-05-24T17:30:34.752Z,1558719034.752 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:30:35.195Z,1558719035.195 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:30:35.943Z,1558719035.943 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:35.990Z,1558719035.990 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:30:35.990Z,1558719035.990 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:30:36.338Z,1558719036.338 [DVL_micro](INFO): Initializing 2019-05-24T17:30:39.175Z,1558719039.175 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:42.007Z,1558719042.007 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:44.835Z,1558719044.835 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:46.851Z,1558719046.851 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:48.875Z,1558719048.875 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:52.119Z,1558719052.119 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:54.931Z,1558719054.931 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:30:58.167Z,1558719058.167 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:00.991Z,1558719060.991 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:04.223Z,1558719064.223 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:07.047Z,1558719067.047 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:09.879Z,1558719069.879 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:11.959Z,1558719071.959 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:13.923Z,1558719073.923 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:17.155Z,1558719077.155 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:19.983Z,1558719079.983 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:23.211Z,1558719083.211 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:24.703Z,1558719084.703 [CommandLine](IMPORTANT): got command failComponent 2019-05-24T17:31:24.706Z,1558719084.706 [CommandLine](IMPORTANT): Failed components: 2019-05-24T17:31:24.707Z,1558719084.707 [CommandLine](IMPORTANT): No failed Components. 2019-05-24T17:31:26.035Z,1558719086.035 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:28.871Z,1558719088.871 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:31.335Z,1558719091.335 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:34.123Z,1558719094.123 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:36.951Z,1558719096.951 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:40.191Z,1558719100.191 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:43.007Z,1558719103.007 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:46.239Z,1558719106.239 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:49.067Z,1558719109.067 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:52.299Z,1558719112.299 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:55.131Z,1558719115.131 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:57.955Z,1558719117.955 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:31:59.975Z,1558719119.975 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:32:00.447Z,1558719120.447 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T17:27:00.2Z 2019-05-24T17:32:00.447Z,1558719120.447 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:32:00.448Z,1558719120.448 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:32:03.614Z,1558719123.614 [DVL_micro](ERROR): checksum mismatch: reported124 , calculated:110 2019-05-24T17:32:03.614Z,1558719123.614 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -1110 -416 -1805 -1164 2 2 6 998.3 -1212.0 2 -590.9 -1227.9 -1212.0 2 927 998 -1212 2 -590 -1227 -1212 2 -6.42 -2.37 197.2 -3.0 17.7 0.005 35.0 1489 124 2019-05-24T17:32:05.910Z,1558719125.910 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T164314/Courier0024.lzma 2019-05-24T17:32:06.716Z,1558719126.716 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0024.lzma.bak 2019-05-24T17:32:06.716Z,1558719126.716 [DataOverHttps](INFO): SBD MOMSN=11179948 2019-05-24T17:32:18.035Z,1558719138.035 [DataOverHttps](INFO): Sending 332 bytes from file Logs/20190524T164314/Express0025.lzma 2019-05-24T17:32:18.840Z,1558719138.840 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0025.lzma.bak 2019-05-24T17:32:18.840Z,1558719138.840 [DataOverHttps](INFO): SBD MOMSN=11179951 2019-05-24T17:32:19.840Z,1558719139.840 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:32:19.840Z,1558719139.840 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:32:19.840Z,1558719139.840 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:32:31.876Z,1558719151.876 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:33:40.562Z,1558719220.562 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:33:40.562Z,1558719220.562 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:33:40.562Z,1558719220.562 [DVL_micro](ERROR): Data Fault 2019-05-24T17:33:40.596Z,1558719220.596 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:33:41.031Z,1558719221.031 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:33:41.821Z,1558719221.821 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:33:41.821Z,1558719221.821 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:33:42.182Z,1558719222.182 [DVL_micro](INFO): Initializing 2019-05-24T17:36:46.402Z,1558719406.402 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:36:46.402Z,1558719406.402 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:36:46.402Z,1558719406.402 [DVL_micro](ERROR): Data Fault 2019-05-24T17:36:46.436Z,1558719406.436 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:36:46.867Z,1558719406.867 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:36:47.671Z,1558719407.671 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:36:47.671Z,1558719407.671 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:36:48.022Z,1558719408.022 [DVL_micro](INFO): Initializing 2019-05-24T17:37:20.376Z,1558719440.376 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:37:20.376Z,1558719440.376 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:37:20.376Z,1558719440.376 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:37:20.377Z,1558719440.377 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:37:20.767Z,1558719440.767 [Default:CheckIn:D] Stopped 2019-05-24T17:37:20.767Z,1558719440.767 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.585856 min 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn:E] Stopped 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn] Stopped 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn](INFO): Running loop #11 2019-05-24T17:37:21.169Z,1558719441.169 [Default:CheckIn] Running Loop=11 2019-05-24T17:37:21.170Z,1558719441.170 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:37:21.170Z,1558719441.170 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:37:22.768Z,1558719442.768 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-05-24T17:37:22.768Z,1558719442.768 [NAL9602] Data Fault, FailCount= 1 2019-05-24T17:37:22.769Z,1558719442.769 [NAL9602](ERROR): Data Fault 2019-05-24T17:37:22.841Z,1558719442.841 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-24T17:37:23.164Z,1558719443.164 [NAL9602](INFO): Powering down 2019-05-24T17:37:24.011Z,1558719444.011 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-24T17:37:24.011Z,1558719444.011 [NAL9602] No Fault, FailCount= 1 2019-05-24T17:37:53.475Z,1558719473.475 [NAL9602](INFO): Powering up NAL9602 2019-05-24T17:38:04.373Z,1558719484.373 [NAL9602](INFO): NAL9602 initialized 2019-05-24T17:38:05.195Z,1558719485.195 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:39:52.240Z,1558719592.240 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:39:52.240Z,1558719592.240 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:39:52.240Z,1558719592.240 [DVL_micro](ERROR): Data Fault 2019-05-24T17:39:52.314Z,1558719592.314 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:39:52.711Z,1558719592.711 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:39:53.495Z,1558719593.495 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:39:53.496Z,1558719593.496 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:39:53.862Z,1558719593.862 [DVL_micro](INFO): Initializing 2019-05-24T17:42:21.340Z,1558719741.340 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T17:37:21.2Z 2019-05-24T17:42:21.340Z,1558719741.340 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:42:21.340Z,1558719741.340 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:42:26.894Z,1558719746.894 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T164314/Courier0027.lzma 2019-05-24T17:42:27.700Z,1558719747.700 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0027.lzma.bak 2019-05-24T17:42:27.700Z,1558719747.700 [DataOverHttps](INFO): SBD MOMSN=11180050 2019-05-24T17:42:39.263Z,1558719759.263 [DataOverHttps](INFO): Sending 193 bytes from file Logs/20190524T164314/Express0028.lzma 2019-05-24T17:42:40.068Z,1558719760.068 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0028.lzma.bak 2019-05-24T17:42:40.068Z,1558719760.068 [DataOverHttps](INFO): SBD MOMSN=11180052 2019-05-24T17:42:41.174Z,1558719761.174 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:42:41.174Z,1558719761.174 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:42:41.174Z,1558719761.174 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:42:58.073Z,1558719778.073 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:42:58.073Z,1558719778.073 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:42:58.074Z,1558719778.074 [DVL_micro](ERROR): Data Fault 2019-05-24T17:42:58.108Z,1558719778.108 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:42:58.559Z,1558719778.559 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:42:59.335Z,1558719779.335 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:42:59.336Z,1558719779.336 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:42:59.706Z,1558719779.706 [DVL_micro](INFO): Initializing 2019-05-24T17:43:07.770Z,1558719787.770 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-24T17:43:38.502Z,1558719818.502 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:46:03.920Z,1558719963.920 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:46:03.920Z,1558719963.920 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:46:03.920Z,1558719963.920 [DVL_micro](ERROR): Data Fault 2019-05-24T17:46:03.973Z,1558719963.973 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:46:04.395Z,1558719964.395 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:46:05.160Z,1558719965.160 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:46:05.160Z,1558719965.160 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:46:05.542Z,1558719965.542 [DVL_micro](INFO): Initializing 2019-05-24T17:47:41.719Z,1558720061.719 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:47:41.719Z,1558720061.719 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:47:41.719Z,1558720061.719 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:47:41.720Z,1558720061.720 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:47:42.132Z,1558720062.132 [Default:CheckIn:D] Stopped 2019-05-24T17:47:42.132Z,1558720062.132 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:47:42.559Z,1558720062.559 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.941935 min 2019-05-24T17:47:42.560Z,1558720062.560 [Default:CheckIn:E] Stopped 2019-05-24T17:47:42.560Z,1558720062.560 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:47:42.561Z,1558720062.561 [Default:CheckIn] Stopped 2019-05-24T17:47:42.561Z,1558720062.561 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:47:42.562Z,1558720062.562 [Default:CheckIn](INFO): Running loop #12 2019-05-24T17:47:42.562Z,1558720062.562 [Default:CheckIn] Running Loop=12 2019-05-24T17:47:42.567Z,1558720062.567 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:47:42.567Z,1558720062.567 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:47:44.123Z,1558720064.123 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:49:09.760Z,1558720149.760 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:49:09.760Z,1558720149.760 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:49:09.760Z,1558720149.760 [DVL_micro](ERROR): Data Fault 2019-05-24T17:49:09.796Z,1558720149.796 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:49:10.239Z,1558720150.239 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:49:11.024Z,1558720151.024 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:49:11.024Z,1558720151.024 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:49:11.388Z,1558720151.388 [DVL_micro](INFO): Initializing 2019-05-24T17:52:15.600Z,1558720335.600 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:52:15.600Z,1558720335.600 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:52:15.600Z,1558720335.600 [DVL_micro](ERROR): Data Fault 2019-05-24T17:52:15.635Z,1558720335.635 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:52:16.071Z,1558720336.071 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:52:16.865Z,1558720336.865 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:52:16.865Z,1558720336.865 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:52:17.222Z,1558720337.222 [DVL_micro](INFO): Initializing 2019-05-24T17:52:42.694Z,1558720362.694 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T17:47:42.6Z 2019-05-24T17:52:42.695Z,1558720362.695 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T17:52:42.696Z,1558720362.696 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T17:52:46.767Z,1558720366.767 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-24T17:52:54.286Z,1558720374.286 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190524T164314/Courier0030.lzma 2019-05-24T17:52:55.092Z,1558720375.092 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0030.lzma.bak 2019-05-24T17:52:55.092Z,1558720375.092 [DataOverHttps](INFO): SBD MOMSN=11180101 2019-05-24T17:53:06.783Z,1558720386.783 [DataOverHttps](INFO): Sending 241 bytes from file Logs/20190524T164314/Express0031.lzma 2019-05-24T17:53:07.589Z,1558720387.589 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0031.lzma.bak 2019-05-24T17:53:07.589Z,1558720387.589 [DataOverHttps](INFO): SBD MOMSN=11180105 2019-05-24T17:53:08.622Z,1558720388.622 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T17:53:08.622Z,1558720388.622 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T17:53:08.622Z,1558720388.622 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T17:53:17.464Z,1558720397.464 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T17:55:21.496Z,1558720521.496 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:55:21.496Z,1558720521.496 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:55:21.496Z,1558720521.496 [DVL_micro](ERROR): Data Fault 2019-05-24T17:55:21.551Z,1558720521.551 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:55:21.967Z,1558720521.967 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:55:22.783Z,1558720522.783 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:55:22.784Z,1558720522.784 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:55:23.111Z,1558720523.111 [DVL_micro](INFO): Initializing 2019-05-24T17:58:09.187Z,1558720689.187 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T17:58:09.187Z,1558720689.187 [Default:CheckIn:C.Wait] Stopped 2019-05-24T17:58:09.187Z,1558720689.187 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T17:58:09.187Z,1558720689.187 [Default:CheckIn:D] Running Loop=1 2019-05-24T17:58:09.590Z,1558720689.590 [Default:CheckIn:D] Stopped 2019-05-24T17:58:09.590Z,1558720689.590 [Default:CheckIn:E] Running Loop=1 2019-05-24T17:58:10.003Z,1558720690.003 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 84.399569 min 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn:E] Stopped 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn] Stopped 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn](INFO): Running loop #13 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn] Running Loop=13 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T17:58:10.004Z,1558720690.004 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T17:58:11.583Z,1558720691.583 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-05-24T17:58:11.583Z,1558720691.583 [NAL9602] Data Fault, FailCount= 2 2019-05-24T17:58:11.583Z,1558720691.583 [NAL9602](ERROR): Data Fault 2019-05-24T17:58:11.622Z,1558720691.622 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-24T17:58:11.984Z,1558720691.984 [NAL9602](INFO): Powering down 2019-05-24T17:58:12.832Z,1558720692.832 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-24T17:58:12.833Z,1558720692.833 [NAL9602] No Fault, FailCount= 2 2019-05-24T17:58:27.330Z,1558720707.330 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T17:58:27.330Z,1558720707.330 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T17:58:27.330Z,1558720707.330 [DVL_micro](ERROR): Data Fault 2019-05-24T17:58:27.381Z,1558720707.381 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T17:58:27.811Z,1558720707.811 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T17:58:28.580Z,1558720708.580 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T17:58:28.580Z,1558720708.580 [DVL_micro] No Fault, FailCount= 1 2019-05-24T17:58:28.958Z,1558720708.958 [DVL_micro](INFO): Initializing 2019-05-24T17:58:42.283Z,1558720722.283 [NAL9602](INFO): Powering up NAL9602 2019-05-24T17:58:53.192Z,1558720733.192 [NAL9602](INFO): NAL9602 initialized 2019-05-24T17:58:54.019Z,1558720734.019 [NAL9602](DEBUG): Fix Requested 2019-05-24T17:59:09.773Z,1558720749.773 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-05-24T17:59:09.775Z,1558720749.775 [BPC1](INFO): Received data from all battery sticks. 2019-05-24T18:01:33.177Z,1558720893.177 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T18:01:33.178Z,1558720893.178 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T18:01:33.178Z,1558720893.178 [DVL_micro](ERROR): Data Fault 2019-05-24T18:01:33.216Z,1558720893.216 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T18:01:33.651Z,1558720893.651 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T18:01:34.451Z,1558720894.451 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T18:01:34.451Z,1558720894.451 [DVL_micro] No Fault, FailCount= 1 2019-05-24T18:01:34.798Z,1558720894.798 [DVL_micro](INFO): Initializing 2019-05-24T18:03:10.171Z,1558720990.171 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-05-24T17:58:10.0Z 2019-05-24T18:03:10.171Z,1558720990.171 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T18:03:10.171Z,1558720990.171 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T18:03:15.714Z,1558720995.714 [DataOverHttps](INFO): Sending 186 bytes from file Logs/20190524T164314/Courier0033.lzma 2019-05-24T18:03:16.520Z,1558720996.520 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0033.lzma.bak 2019-05-24T18:03:16.520Z,1558720996.520 [DataOverHttps](INFO): SBD MOMSN=11180152 2019-05-24T18:03:24.684Z,1558721004.684 [DVL_micro](ERROR): checksum mismatch: reported71 , calculated:80 2019-05-24T18:03:24.685Z,1558721004.685 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -746 -1640 -546 -1066 2 2 2 2 -266.9 -766.1 -1078.0 2 29 -1078.0 2 -266 -766 -1078 2 29 810 -1078 2 -6.48 -2.44 197.1 -3.0 19.0 0.005 35.0 1489 71 2019-05-24T18:03:33.839Z,1558721013.839 [DataOverHttps](INFO): Sending 252 bytes from file Logs/20190524T164314/Express0034.lzma 2019-05-24T18:03:34.644Z,1558721014.644 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0034.lzma.bak 2019-05-24T18:03:34.644Z,1558721014.644 [DataOverHttps](INFO): SBD MOMSN=11180157 2019-05-24T18:03:35.619Z,1558721015.619 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T18:03:35.619Z,1558721015.619 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T18:03:35.619Z,1558721015.619 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T18:03:56.596Z,1558721036.596 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-24T18:04:27.300Z,1558721067.300 [NAL9602](INFO): Not Powering down - fast GPS 2019-05-24T18:04:39.016Z,1558721079.016 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T18:04:39.016Z,1558721079.016 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T18:04:39.016Z,1558721079.016 [DVL_micro](ERROR): Data Fault 2019-05-24T18:04:39.054Z,1558721079.054 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T18:04:39.495Z,1558721079.495 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T18:04:40.276Z,1558721080.276 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T18:04:40.276Z,1558721080.276 [DVL_micro] No Fault, FailCount= 1 2019-05-24T18:04:40.641Z,1558721080.641 [DVL_micro](INFO): Initializing 2019-05-24T18:07:16.698Z,1558721236.698 [CommandLine](IMPORTANT): got command gfscan 2019-05-24T18:07:17.108Z,1558721237.108 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-24T18:07:27.996Z,1558721247.996 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.180055 CHAN A1 (24V): 0.049816 CHAN A2 (12V): -0.001586 CHAN A3 (5V): -0.013683 CHAN B0 (3.3V): -0.010837 CHAN B1 (3.15aV): -0.007088 CHAN B2 (3.15bV): -0.005496 CHAN B3 (GND): -0.023481 OPEN: 0.006656 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-24T18:07:44.916Z,1558721264.916 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T18:07:44.916Z,1558721264.916 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T18:07:44.916Z,1558721264.916 [DVL_micro](ERROR): Data Fault 2019-05-24T18:07:44.995Z,1558721264.995 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T18:07:45.387Z,1558721265.387 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T18:07:46.215Z,1558721266.215 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T18:07:46.215Z,1558721266.215 [DVL_micro] No Fault, FailCount= 1 2019-05-24T18:07:46.538Z,1558721266.538 [DVL_micro](INFO): Initializing 2019-05-24T18:08:35.028Z,1558721315.028 [DVL_micro](ERROR): checksum mismatch: reported81 , calculated:78 2019-05-24T18:08:35.028Z,1558721315.028 [DVL_micro](ERROR): Failed to parse:$#NQ.RES 0X0000 0 0 0 0 0 0 0 0 0 0 0 0 -696 311 -1514 -845 2 2 2 2 1091.7 139.9 2 -589.9 -1795.6 -739.9 2 1091 1542 -739 2 -589 -1795 -739 2 -6.37 -2.41 197.1 -3.0 19.2 0.005 35.0 1489 81 2019-05-24T18:08:36.287Z,1558721316.287 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-05-24T18:08:36.287Z,1558721316.287 [Default:CheckIn:C.Wait] Stopped 2019-05-24T18:08:36.287Z,1558721316.287 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T18:08:36.288Z,1558721316.288 [Default:CheckIn:D] Running Loop=1 2019-05-24T18:08:36.662Z,1558721316.662 [Default:CheckIn:D] Stopped 2019-05-24T18:08:36.667Z,1558721316.667 [Default:CheckIn:E] Running Loop=1 2019-05-24T18:08:37.071Z,1558721317.071 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 94.850773 min 2019-05-24T18:08:37.071Z,1558721317.071 [Default:CheckIn:E] Stopped 2019-05-24T18:08:37.071Z,1558721317.071 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-05-24T18:08:37.071Z,1558721317.071 [Default:CheckIn] Stopped 2019-05-24T18:08:37.071Z,1558721317.071 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T18:08:37.072Z,1558721317.072 [Default:CheckIn](INFO): Running loop #14 2019-05-24T18:08:37.072Z,1558721317.072 [Default:CheckIn] Running Loop=14 2019-05-24T18:08:37.072Z,1558721317.072 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-24T18:08:37.072Z,1558721317.072 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-24T18:08:38.663Z,1558721318.663 [NAL9602](DEBUG): Fix Requested 2019-05-24T18:09:09.760Z,1558721349.760 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-05-24T18:09:09.835Z,1558721349.835 [NAL9602](FAULT): received: +CSQ:0 OK969, 0, 0, 0, 0 OK 2019-05-24T18:09:09.835Z,1558721349.835 [NAL9602] Data Fault, FailCount= 3 2019-05-24T18:09:09.835Z,1558721349.835 [NAL9602](ERROR): Data Fault 2019-05-24T18:09:09.876Z,1558721349.876 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-24T18:09:10.162Z,1558721350.162 [NAL9602](INFO): Powering down 2019-05-24T18:09:11.008Z,1558721351.008 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-24T18:09:11.008Z,1558721351.008 [NAL9602] No Fault, FailCount= 3 2019-05-24T18:09:40.465Z,1558721380.465 [NAL9602](INFO): Powering up NAL9602 2019-05-24T18:09:51.373Z,1558721391.373 [NAL9602](INFO): NAL9602 initialized 2019-05-24T18:09:52.181Z,1558721392.181 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-05-24T18:09:52.181Z,1558721392.181 [NAL9602] Data Fault, FailCount= 4 2019-05-24T18:09:52.181Z,1558721392.181 [NAL9602](ERROR): Data Fault 2019-05-24T18:09:52.220Z,1558721392.220 [CBIT](ERROR): Data Fault in component: NAL9602 2019-05-24T18:09:52.611Z,1558721392.611 [NAL9602](INFO): Powering down 2019-05-24T18:09:53.425Z,1558721393.425 [CBIT](INFO): Clearing failed state for component NAL9602 2019-05-24T18:09:53.425Z,1558721393.425 [NAL9602] No Fault, FailCount= 4 2019-05-24T18:10:02.396Z,1558721402.396 [CommandLine](IMPORTANT): got command failComponent 2019-05-24T18:10:02.396Z,1558721402.396 [CommandLine](IMPORTANT): Failed components: 2019-05-24T18:10:02.397Z,1558721402.397 [CommandLine](IMPORTANT): No failed Components. 2019-05-24T18:10:22.885Z,1558721422.885 [NAL9602](INFO): Powering up NAL9602 2019-05-24T18:10:32.789Z,1558721432.789 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree 2019-05-24T18:10:32.800Z,1558721432.800 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread. 2019-05-24T18:10:32.800Z,1558721432.800 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree 2019-05-24T18:10:32.802Z,1558721432.802 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread. 2019-05-24T18:10:33.030Z,1558721433.030 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-05-24T18:10:33.793Z,1558721433.793 [NAL9602](INFO): NAL9602 initialized 2019-05-24T18:10:34.635Z,1558721434.635 [NAL9602](DEBUG): Fix Requested 2019-05-24T18:10:50.760Z,1558721450.760 [DVL_micro](FAULT): DVL failed to acquire valid data within timeout. 2019-05-24T18:10:50.760Z,1558721450.760 [DVL_micro] Data Fault, FailCount= 1 2019-05-24T18:10:50.761Z,1558721450.761 [DVL_micro](ERROR): Data Fault 2019-05-24T18:10:50.801Z,1558721450.801 [CBIT](ERROR): Data Fault in component: DVL_micro 2019-05-24T18:10:51.235Z,1558721451.235 [DVL_micro](INFO): uninitialize:Powering down 2019-05-24T18:10:51.296Z,1558721451.296 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1558721408.000000 second 2019-05-24T18:10:51.593Z,1558721451.593 [Default:CheckIn:Read_GPS] Stopped 2019-05-24T18:10:51.593Z,1558721451.593 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-05-24T18:10:52.013Z,1558721452.013 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-05-24T18:10:52.013Z,1558721452.013 [DVL_micro] No Fault, FailCount= 1 2019-05-24T18:10:52.409Z,1558721452.409 [DVL_micro](INFO): Initializing 2019-05-24T18:10:56.934Z,1558721456.934 [DataOverHttps](INFO): Sending 43 bytes from file Logs/20190524T164314/Courier0036.lzma 2019-05-24T18:10:57.647Z,1558721457.647 [CommandLine](IMPORTANT): got command failComponent 2019-05-24T18:10:57.647Z,1558721457.647 [CommandLine](IMPORTANT): Failed components: 2019-05-24T18:10:57.648Z,1558721457.648 [CommandLine](IMPORTANT): No failed Components. 2019-05-24T18:10:57.740Z,1558721457.740 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Courier0036.lzma.bak 2019-05-24T18:10:57.741Z,1558721457.741 [DataOverHttps](INFO): SBD MOMSN=11180210 2019-05-24T18:11:09.195Z,1558721469.195 [DataOverHttps](INFO): Sending 660 bytes from file Logs/20190524T164314/Express0037.lzma 2019-05-24T18:11:10.000Z,1558721470.000 [DataOverHttps](INFO): Moved sent file to Logs/20190524T164314/Express0037.lzma.bak 2019-05-24T18:11:10.000Z,1558721470.000 [DataOverHttps](INFO): SBD MOMSN=11180213 2019-05-24T18:11:11.015Z,1558721471.015 [Default:CheckIn:Read_Iridium] Stopped 2019-05-24T18:11:11.015Z,1558721471.015 [Default:CheckIn:C.Wait] Running Loop=1 2019-05-24T18:11:11.015Z,1558721471.015 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T18:11:52.488Z,1558721512.488 [DataOverHttps](IMPORTANT): SBD MTMSN=20190524T180734 2019-05-24T18:11:57.807Z,1558721517.807 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 3 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 3 meter;run 2019-05-24T18:11:57.849Z,1558721517.849 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml 2019-05-24T18:11:57.850Z,1558721517.850 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml 2019-05-24T18:11:57.917Z,1558721517.917 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min 2019-05-24T18:11:57.940Z,1558721517.940 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m 2019-05-24T18:11:57.949Z,1558721517.949 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count 2019-05-24T18:11:57.953Z,1558721517.953 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min 2019-05-24T18:11:57.954Z,1558721517.954 [sample:A.AbortSample](DEBUG): Construct. 2019-05-24T18:11:57.964Z,1558721517.964 [sample:B.Pitch](DEBUG): Construct. 2019-05-24T18:11:57.980Z,1558721517.980 [sample:C.SetSpeed](DEBUG): Construct. 2019-05-24T18:11:57.988Z,1558721517.988 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml 2019-05-24T18:11:58.127Z,1558721518.127 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m 2019-05-24T18:11:58.130Z,1558721518.130 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s 2019-05-24T18:11:58.137Z,1558721518.137 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h 2019-05-24T18:11:58.142Z,1558721518.142 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool 2019-05-24T18:11:58.161Z,1558721518.161 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool 2019-05-24T18:11:58.173Z,1558721518.173 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool 2019-05-24T18:11:58.177Z,1558721518.177 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min 2019-05-24T18:11:58.195Z,1558721518.195 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min 2019-05-24T18:11:58.207Z,1558721518.207 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 315.000012 cc 2019-05-24T18:11:58.215Z,1558721518.215 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct. 2019-05-24T18:11:58.283Z,1558721518.283 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute. 2019-05-24T18:11:58.286Z,1558721518.286 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct. 2019-05-24T18:11:58.325Z,1558721518.325 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait. 2019-05-24T18:11:58.356Z,1558721518.356 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute. 2019-05-24T18:11:58.373Z,1558721518.373 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute. 2019-05-24T18:11:58.432Z,1558721518.432 [MissionManager](DEBUG): This mission is designed to be run in the test tank only and samples whichever sampler is installed once the vehicle reaches the target depth. How long to let the mission run. 90 Depth to sample at. 7 Number of samples to take. 1 How long to wait between samples. This starts *before* the first sample to exercise the SettleTime setting in the insert aggregate. 3 0 2019-05-24T18:11:58.433Z,1558721518.433 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml 2019-05-24T18:12:07.918Z,1558721527.918 [CommandLine](IMPORTANT): got command set sample.Depth 3.000000 meter 2019-05-24T18:12:07.937Z,1558721527.937 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second 2019-05-24T18:12:07.941Z,1558721527.941 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 3.000000 meter 2019-05-24T18:12:07.942Z,1558721527.942 [CommandLine](IMPORTANT): got command run 2019-05-24T18:12:08.007Z,1558721528.007 [CommandLine](IMPORTANT): Running 2019-05-24T18:12:08.015Z,1558721528.015 [Default] Stopped 2019-05-24T18:12:08.016Z,1558721528.016 [Default](DEBUG): Aggregate::uninitialize Default 2019-05-24T18:12:08.016Z,1558721528.016 [Default:B.GoToSurface] Stopped 2019-05-24T18:12:08.016Z,1558721528.016 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-24T18:12:08.016Z,1558721528.016 [Default:CheckIn] Stopped 2019-05-24T18:12:08.016Z,1558721528.016 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-05-24T18:12:08.016Z,1558721528.016 [Default:CheckIn:C.Wait] Stopped 2019-05-24T18:12:08.016Z,1558721528.016 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T18:12:08.016Z,1558721528.016 [MissionManager](IMPORTANT): Started mission sample 2019-05-24T18:12:08.016Z,1558721528.016 [sample] Running Loop=1 2019-05-24T18:12:08.017Z,1558721528.017 [sample](DEBUG): Aggregate::initialize sample 2019-05-24T18:12:08.017Z,1558721528.017 [sample:A.AbortSample] Running Loop=1 2019-05-24T18:12:08.017Z,1558721528.017 [sample:A.AbortSample](INFO): Initializing AbortSample. 2019-05-24T18:12:08.017Z,1558721528.017 [sample:B.Pitch] Running Loop=1 2019-05-24T18:12:08.017Z,1558721528.017 [sample:B.Pitch](DEBUG): Initialize. 2019-05-24T18:12:08.017Z,1558721528.017 [sample:C.SetSpeed] Running Loop=1 2019-05-24T18:12:08.017Z,1558721528.017 [sample:C.SetSpeed](DEBUG): Initialize. 2019-05-24T18:12:08.017Z,1558721528.017 [sample:E] Running Loop=1 2019-05-24T18:12:08.018Z,1558721528.018 [sample:E] Stopped 2019-05-24T18:12:08.018Z,1558721528.018 [sample:F] Running Loop=1 2019-05-24T18:12:08.018Z,1558721528.018 [sample:C.SetSpeed] Running Loop=1 2019-05-24T18:12:08.018Z,1558721528.018 [sample:B.Pitch] Running Loop=1 2019-05-24T18:12:08.023Z,1558721528.023 [sample:A.AbortSample] Running Loop=1 2019-05-24T18:12:08.392Z,1558721528.392 [sample:F] Stopped 2019-05-24T18:12:08.392Z,1558721528.392 [sample:SampleRepeater] Running Loop=1 2019-05-24T18:12:08.393Z,1558721528.393 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater 2019-05-24T18:12:08.393Z,1558721528.393 [sample:SampleRepeater:Sample] Running Loop=1 2019-05-24T18:12:08.393Z,1558721528.393 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample 2019-05-24T18:12:08.777Z,1558721528.777 [sample:SampleAtDepth] Running Loop=1 2019-05-24T18:12:08.777Z,1558721528.777 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth 2019-05-24T18:12:08.777Z,1558721528.777 [sample:SampleAtDepth:ApproachDepth] Running Loop=1 2019-05-24T18:12:08.778Z,1558721528.778 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth 2019-05-24T18:12:08.778Z,1558721528.778 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1 2019-05-24T18:12:08.795Z,1558721528.795 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 3.000000 m 2019-05-24T18:12:08.795Z,1558721528.795 [sample:SampleAtDepth:ApproachDepth:A] Stopped 2019-05-24T18:12:08.795Z,1558721528.795 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1 2019-05-24T18:12:08.795Z,1558721528.795 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize. 2019-05-24T18:12:17.004Z,1558721537.004 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter 2019-05-24T18:12:17.005Z,1558721537.005 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread. 2019-05-24T18:12:17.353Z,1558721537.353 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-05-24T18:12:17.674Z,1558721537.674 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped 2019-05-24T18:12:17.674Z,1558721537.674 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth 2019-05-24T18:12:17.674Z,1558721537.674 [sample:SampleAtDepth:ApproachDepth] Stopped 2019-05-24T18:12:17.674Z,1558721537.674 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth 2019-05-24T18:12:17.674Z,1558721537.674 [sample:SampleAtDepth:SampleWrapper] Running Loop=1 2019-05-24T18:12:17.675Z,1558721537.675 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper 2019-05-24T18:12:17.675Z,1558721537.675 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1 2019-05-24T18:12:17.675Z,1558721537.675 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize. 2019-05-24T18:12:17.675Z,1558721537.675 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1 2019-05-24T18:12:18.073Z,1558721538.073 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 3.000000 m , settling for 0.050000 min 2019-05-24T18:12:18.074Z,1558721538.074 [sample:SampleAtDepth:SampleWrapper:B] Stopped 2019-05-24T18:12:18.074Z,1558721538.074 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1 2019-05-24T18:12:18.074Z,1558721538.074 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component. 2019-05-24T18:12:18.074Z,1558721538.074 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting. 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component. 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1 2019-05-24T18:12:21.733Z,1558721541.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1 2019-05-24T18:12:22.141Z,1558721542.141 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP 2019-05-24T18:12:22.142Z,1558721542.142 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1 2019-05-24T18:12:22.525Z,1558721542.525 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2019-05-24T18:12:23.800Z,1558721543.800 [ESPComponent](INFO): powering up ESP 2019-05-24T18:12:23.800Z,1558721543.800 [ESPComponent](INFO): powering up ESP secondary power supply 2019-05-24T18:12:23.819Z,1558721543.819 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2019-05-24T18:12:24.054Z,1558721544.054 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2019-05-24T18:12:24.331Z,1558721544.331 [ESPComponent](INFO): console: 2019-05-24T18:12:25.061Z,1558721545.061 [ESPComponent](INFO): console: 2019-05-24T18:12:25.468Z,1558721545.468 [ESPComponent](INFO): console:NAND: 256 MiB 2019-05-24T18:12:25.926Z,1558721545.926 [ESPComponent](INFO): console: BOOTMODE: SPI 2019-05-24T18:12:26.339Z,1558721546.339 [ESPComponent](INFO): console: reading SPI NOR.. 2019-05-24T18:12:27.499Z,1558721547.499 [ESPComponent](INFO): console:Done 2019-05-24T18:12:27.909Z,1558721547.909 [ESPComponent](INFO): console: 2019-05-24T18:12:28.305Z,1558721548.305 [ESPComponent](INFO): console: 2019-05-24T18:12:28.716Z,1558721548.716 [ESPComponent](INFO): console: U-Boot 2009.11-mbariC (Apr 02 2019 - 13:08:14) 2019-05-24T18:12:29.137Z,1558721549.137 [ESPComponent](INFO): console: 2019-05-24T18:12:29.520Z,1558721549.520 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2019-05-24T18:12:29.915Z,1558721549.915 [ESPComponent](INFO): console: flash params are already written into flash 2019-05-24T18:12:30.310Z,1558721550.310 [ESPComponent](INFO): console: DRAM: 64 MB 2019-05-24T18:12:30.722Z,1558721550.722 [ESPComponent](INFO): console: In: serial 2019-05-24T18:12:31.140Z,1558721551.140 [ESPComponent](INFO): console: Out: serial 2019-05-24T18:12:31.547Z,1558721551.547 [ESPComponent](INFO): console: Err: serial 2019-05-24T18:12:31.953Z,1558721551.953 [ESPComponent](INFO): console: Net: ks8851_mll 2019-05-24T18:12:32.416Z,1558721552.416 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2019-05-24T18:12:32.759Z,1558721552.759 [ESPComponent](INFO): console: mmc1 is available 2019-05-24T18:12:33.152Z,1558721553.152 [ESPComponent](INFO): console: reading uImage 2019-05-24T18:12:33.554Z,1558721553.554 [ESPComponent](INFO): console: 2019-05-24T18:12:33.961Z,1558721553.961 [ESPComponent](INFO): console: 1681452 bytes read 2019-05-24T18:12:34.368Z,1558721554.368 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2019-05-24T18:12:34.760Z,1558721554.760 [ESPComponent](INFO): console: Image Name: Linux-2.6.33-ea3131-mbari6 2019-05-24T18:12:35.160Z,1558721555.160 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2019-05-24T18:12:35.593Z,1558721555.593 [ESPComponent](INFO): console: Data Size: 1681388 Bytes = 1.6 MB 2019-05-24T18:12:35.976Z,1558721555.976 [ESPComponent](INFO): console: Load Address: 30008000 2019-05-24T18:12:36.378Z,1558721556.378 [ESPComponent](INFO): console: Entry Point: 30008000 2019-05-24T18:12:36.776Z,1558721556.776 [ESPComponent](INFO): console: Verifying Checksum ... OK 2019-05-24T18:12:37.200Z,1558721557.200 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2019-05-24T18:12:37.606Z,1558721557.606 [ESPComponent](INFO): console: OK 2019-05-24T18:12:38.015Z,1558721558.015 [ESPComponent](INFO): console: 2019-05-24T18:12:38.407Z,1558721558.407 [ESPComponent](INFO): console: Starting kernel ... 2019-05-24T18:12:38.824Z,1558721558.824 [ESPComponent](INFO): console: 2019-05-24T18:12:39.208Z,1558721559.208 [ESPComponent](INFO): console: Uncompressing Linux... done, booting the kernel. 2019-05-24T18:12:39.611Z,1558721559.611 [ESPComponent](INFO): console: [ 0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177 2019-05-24T18:12:40.016Z,1558721560.016 [ESPComponent](INFO): console: [ 0.00] CPU: VIVT data cache, VIVT instruction cache 2019-05-24T18:12:40.425Z,1558721560.425 [ESPComponent](INFO): console: [ 0.00] Machine: NXP EA313X 2019-05-24T18:12:40.818Z,1558721560.818 [ESPComponent](INFO): console: [ 0.00] Memory policy: ECC disabled, Data cache writeback 2019-05-24T18:12:41.227Z,1558721561.227 [ESPComponent](INFO): console: [ 0.00] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 16256 2019-05-24T18:12:41.629Z,1558721561.629 [ESPComponent](INFO): console: [ 0.24] Mount-cache hash table entries: 512 2019-05-24T18:12:42.058Z,1558721562.058 [ESPComponent](INFO): console: [ 0.30] MBARI ESP 3G 2019-05-24T18:12:42.447Z,1558721562.447 [ESPComponent](INFO): console: [ 0.40] bio: create slab