2021-05-18T15:07:00.172Z,1621350420.172 [CommandLine](IMPORTANT): got command restart logs 2021-05-18T15:08:06.058Z,1621350486.058 [DAT](INFO): DAT read: user:18>Lowpower 2021-05-18T15:08:06.058Z,1621350486.058 [DAT](DEBUG): Re-entering command mode due to deviceResponse_: user:18>Lowpower 2021-05-18T15:08:38.380Z,1621350518.380 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T15:08:38.380Z,1621350518.380 [NAL9602] Data Fault, FailCount= 1 2021-05-18T15:08:38.380Z,1621350518.380 [NAL9602](ERROR): Data Fault 2021-05-18T15:08:38.399Z,1621350518.399 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T15:08:38.789Z,1621350518.789 [NAL9602](INFO): Powering down 2021-05-18T15:08:39.610Z,1621350519.610 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T15:08:39.610Z,1621350519.610 [NAL9602] No Fault, FailCount= 1 2021-05-18T15:09:09.080Z,1621350549.080 [NAL9602](INFO): Powering up NAL9602 2021-05-18T15:09:19.992Z,1621350559.992 [NAL9602](INFO): NAL9602 initialized 2021-05-18T15:09:59.000Z,1621350600.000 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4 2021-05-18T15:09:59.000Z,1621350600.000 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:10:00.014Z,1621350600.014 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:10:00.459Z,1621350600.459 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:10:00.459Z,1621350600.459 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4 2021-05-18T15:10:23.442Z,1621350623.442 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-05-18T15:05:23.3Z 2021-05-18T15:10:23.442Z,1621350623.442 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:10:23.443Z,1621350623.443 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-05-18T15:10:23.853Z,1621350623.853 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-05-18T15:10:33.863Z,1621350633.863 [DataOverHttps](INFO): Sending 227 bytes from file Logs/20210518T145747/Courier0004.lzma 2021-05-18T15:10:34.865Z,1621350634.865 [DataOverHttps](INFO): Moved sent file to Logs/20210518T145747/Courier0004.lzma.bak 2021-05-18T15:10:34.865Z,1621350634.865 [DataOverHttps](INFO): SBD MOMSN=15648662 2021-05-18T15:10:54.942Z,1621350654.942 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210518T150700/Courier0000.lzma 2021-05-18T15:10:55.945Z,1621350655.945 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Courier0000.lzma.bak 2021-05-18T15:10:55.945Z,1621350655.945 [DataOverHttps](INFO): SBD MOMSN=15648665 2021-05-18T15:11:13.068Z,1621350673.068 [DataOverHttps](INFO): Sending 753 bytes from file Logs/20210518T145747/Express0005.lzma 2021-05-18T15:11:14.069Z,1621350674.069 [DataOverHttps](INFO): Moved sent file to Logs/20210518T145747/Express0005.lzma.bak 2021-05-18T15:11:14.069Z,1621350674.069 [DataOverHttps](INFO): SBD MOMSN=15648668 2021-05-18T15:11:30.891Z,1621350690.891 [DataOverHttps](INFO): Sending 296 bytes from file Logs/20210518T150700/Express0001.lzma 2021-05-18T15:11:31.893Z,1621350691.893 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Express0001.lzma.bak 2021-05-18T15:11:31.893Z,1621350691.893 [DataOverHttps](INFO): SBD MOMSN=15648688 2021-05-18T15:11:34.433Z,1621350694.433 [Default:CheckIn:Read_Iridium] Stopped 2021-05-18T15:11:34.434Z,1621350694.434 [Default:CheckIn:C.Wait] Running Loop=1 2021-05-18T15:11:34.434Z,1621350694.434 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:13:00.876Z,1621350780.876 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5 2021-05-18T15:13:00.877Z,1621350780.877 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:13:00.887Z,1621350780.887 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:13:01.289Z,1621350781.289 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:13:01.289Z,1621350781.289 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5 2021-05-18T15:16:01.888Z,1621350961.888 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6 2021-05-18T15:16:01.888Z,1621350961.888 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:16:01.899Z,1621350961.899 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:16:02.306Z,1621350962.306 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:16:02.306Z,1621350962.306 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6 2021-05-18T15:16:35.001Z,1621350995.001 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-05-18T15:16:35.001Z,1621350995.001 [Default:CheckIn:C.Wait] Stopped 2021-05-18T15:16:35.001Z,1621350995.001 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:16:35.001Z,1621350995.001 [Default:CheckIn:D] Running Loop=1 2021-05-18T15:16:35.421Z,1621350995.421 [Default:CheckIn:D] Stopped 2021-05-18T15:16:35.422Z,1621350995.422 [Default:CheckIn:E] Running Loop=1 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.430680 min 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn:E] Stopped 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn] Stopped 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn](INFO): Running loop #2 2021-05-18T15:16:35.833Z,1621350995.833 [Default:CheckIn] Running Loop=2 2021-05-18T15:16:35.834Z,1621350995.834 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T15:16:35.834Z,1621350995.834 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T15:19:02.880Z,1621351142.880 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7 2021-05-18T15:19:02.880Z,1621351142.880 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:19:02.911Z,1621351142.911 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:19:03.294Z,1621351143.294 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:19:03.294Z,1621351143.294 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7 2021-05-18T15:19:21.028Z,1621351161.028 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T15:19:21.028Z,1621351161.028 [NAL9602] Data Fault, FailCount= 2 2021-05-18T15:19:21.028Z,1621351161.028 [NAL9602](ERROR): Data Fault 2021-05-18T15:19:21.090Z,1621351161.090 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T15:19:21.436Z,1621351161.436 [NAL9602](INFO): Powering down 2021-05-18T15:19:22.293Z,1621351162.293 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T15:19:22.293Z,1621351162.293 [NAL9602] No Fault, FailCount= 2 2021-05-18T15:19:51.732Z,1621351191.732 [NAL9602](INFO): Powering up NAL9602 2021-05-18T15:20:02.640Z,1621351202.640 [NAL9602](INFO): NAL9602 initialized 2021-05-18T15:21:35.987Z,1621351295.987 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-05-18T15:16:35.8Z 2021-05-18T15:21:35.987Z,1621351295.987 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:21:35.987Z,1621351295.987 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-05-18T15:21:43.158Z,1621351303.158 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210518T150700/Courier0003.lzma 2021-05-18T15:21:44.161Z,1621351304.161 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Courier0003.lzma.bak 2021-05-18T15:21:44.161Z,1621351304.161 [DataOverHttps](INFO): SBD MOMSN=15648692 2021-05-18T15:21:59.963Z,1621351319.963 [DataOverHttps](INFO): Sending 181 bytes from file Logs/20210518T150700/Express0004.lzma 2021-05-18T15:22:00.965Z,1621351320.965 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Express0004.lzma.bak 2021-05-18T15:22:00.965Z,1621351320.965 [DataOverHttps](INFO): SBD MOMSN=15648694 2021-05-18T15:22:03.871Z,1621351323.871 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8 2021-05-18T15:22:03.872Z,1621351323.872 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:22:03.882Z,1621351323.882 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:22:04.284Z,1621351324.284 [Default:CheckIn:Read_Iridium] Stopped 2021-05-18T15:22:04.284Z,1621351324.284 [Default:CheckIn:C.Wait] Running Loop=1 2021-05-18T15:22:04.284Z,1621351324.284 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:22:04.302Z,1621351324.302 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:22:04.302Z,1621351324.302 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8 2021-05-18T15:25:04.858Z,1621351504.858 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9 2021-05-18T15:25:04.858Z,1621351504.858 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:25:04.868Z,1621351504.868 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:25:05.258Z,1621351505.258 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:25:05.258Z,1621351505.258 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9 2021-05-18T15:27:04.846Z,1621351624.846 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-05-18T15:27:04.846Z,1621351624.846 [Default:CheckIn:C.Wait] Stopped 2021-05-18T15:27:04.846Z,1621351624.846 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:27:04.846Z,1621351624.846 [Default:CheckIn:D] Running Loop=1 2021-05-18T15:27:05.238Z,1621351625.238 [Default:CheckIn:D] Stopped 2021-05-18T15:27:05.238Z,1621351625.238 [Default:CheckIn:E] Running Loop=1 2021-05-18T15:27:05.646Z,1621351625.646 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 21.927616 min 2021-05-18T15:27:05.646Z,1621351625.646 [Default:CheckIn:E] Stopped 2021-05-18T15:27:05.646Z,1621351625.646 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-05-18T15:27:05.646Z,1621351625.646 [Default:CheckIn] Stopped 2021-05-18T15:27:05.646Z,1621351625.646 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T15:27:05.647Z,1621351625.647 [Default:CheckIn](INFO): Running loop #3 2021-05-18T15:27:05.647Z,1621351625.647 [Default:CheckIn] Running Loop=3 2021-05-18T15:27:05.647Z,1621351625.647 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T15:27:05.647Z,1621351625.647 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T15:28:05.840Z,1621351685.840 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10 2021-05-18T15:28:05.840Z,1621351685.840 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:28:05.850Z,1621351685.850 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:28:06.257Z,1621351686.257 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:28:06.257Z,1621351686.257 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10 2021-05-18T15:30:05.017Z,1621351805.017 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T15:30:05.017Z,1621351805.017 [NAL9602] Data Fault, FailCount= 3 2021-05-18T15:30:05.017Z,1621351805.017 [NAL9602](ERROR): Data Fault 2021-05-18T15:30:05.054Z,1621351805.054 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T15:30:05.416Z,1621351805.416 [NAL9602](INFO): Powering down 2021-05-18T15:30:06.249Z,1621351806.249 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T15:30:06.249Z,1621351806.249 [NAL9602] No Fault, FailCount= 3 2021-05-18T15:30:35.768Z,1621351835.768 [NAL9602](INFO): Powering up NAL9602 2021-05-18T15:30:46.676Z,1621351846.676 [NAL9602](INFO): NAL9602 initialized 2021-05-18T15:31:06.900Z,1621351866.900 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11 2021-05-18T15:31:06.901Z,1621351866.901 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:31:06.935Z,1621351866.935 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:31:07.300Z,1621351867.300 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:31:07.300Z,1621351867.300 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11 2021-05-18T15:32:05.886Z,1621351925.886 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-05-18T15:27:05.6Z 2021-05-18T15:32:05.886Z,1621351925.886 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:32:05.886Z,1621351925.886 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-05-18T15:32:13.986Z,1621351933.986 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210518T150700/Courier0006.lzma 2021-05-18T15:32:14.989Z,1621351934.989 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Courier0006.lzma.bak 2021-05-18T15:32:14.989Z,1621351934.989 [DataOverHttps](INFO): SBD MOMSN=15648698 2021-05-18T15:32:31.790Z,1621351951.790 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20210518T150700/Express0007.lzma 2021-05-18T15:32:32.793Z,1621351952.793 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Express0007.lzma.bak 2021-05-18T15:32:32.793Z,1621351952.793 [DataOverHttps](INFO): SBD MOMSN=15648700 2021-05-18T15:32:35.384Z,1621351955.384 [Default:CheckIn:Read_Iridium] Stopped 2021-05-18T15:32:35.385Z,1621351955.385 [Default:CheckIn:C.Wait] Running Loop=1 2021-05-18T15:32:35.385Z,1621351955.385 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:34:07.876Z,1621352047.876 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12 2021-05-18T15:34:07.876Z,1621352047.876 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:34:07.887Z,1621352047.887 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:34:08.292Z,1621352048.292 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:34:08.293Z,1621352048.293 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12 2021-05-18T15:37:08.922Z,1621352228.922 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13 2021-05-18T15:37:08.922Z,1621352228.922 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:37:08.933Z,1621352228.933 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:37:09.306Z,1621352229.306 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:37:09.306Z,1621352229.306 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13 2021-05-18T15:37:35.979Z,1621352255.979 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-05-18T15:37:35.979Z,1621352255.979 [Default:CheckIn:C.Wait] Stopped 2021-05-18T15:37:35.979Z,1621352255.979 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:37:35.979Z,1621352255.979 [Default:CheckIn:D] Running Loop=1 2021-05-18T15:37:36.357Z,1621352256.357 [Default:CheckIn:D] Stopped 2021-05-18T15:37:36.357Z,1621352256.357 [Default:CheckIn:E] Running Loop=1 2021-05-18T15:37:36.765Z,1621352256.765 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 32.446275 min 2021-05-18T15:37:36.765Z,1621352256.765 [Default:CheckIn:E] Stopped 2021-05-18T15:37:36.765Z,1621352256.765 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-05-18T15:37:36.765Z,1621352256.765 [Default:CheckIn] Stopped 2021-05-18T15:37:36.766Z,1621352256.766 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T15:37:36.766Z,1621352256.766 [Default:CheckIn](INFO): Running loop #4 2021-05-18T15:37:36.766Z,1621352256.766 [Default:CheckIn] Running Loop=4 2021-05-18T15:37:36.766Z,1621352256.766 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T15:37:36.766Z,1621352256.766 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T15:40:09.904Z,1621352409.904 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14 2021-05-18T15:40:09.904Z,1621352409.904 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:40:09.916Z,1621352409.916 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:40:10.306Z,1621352410.306 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:40:10.306Z,1621352410.306 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14 2021-05-18T15:40:49.108Z,1621352449.108 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T15:40:49.108Z,1621352449.108 [NAL9602] Data Fault, FailCount= 4 2021-05-18T15:40:49.108Z,1621352449.108 [NAL9602](ERROR): Data Fault 2021-05-18T15:40:49.126Z,1621352449.126 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T15:40:49.484Z,1621352449.484 [NAL9602](INFO): Powering down 2021-05-18T15:40:50.325Z,1621352450.325 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T15:40:50.325Z,1621352450.325 [NAL9602] No Fault, FailCount= 4 2021-05-18T15:41:19.784Z,1621352479.784 [NAL9602](INFO): Powering up NAL9602 2021-05-18T15:41:30.692Z,1621352490.692 [NAL9602](INFO): NAL9602 initialized 2021-05-18T15:42:36.965Z,1621352556.965 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-05-18T15:37:36.8Z 2021-05-18T15:42:36.965Z,1621352556.965 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:42:36.965Z,1621352556.965 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-05-18T15:42:42.703Z,1621352562.703 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210518T150700/Courier0009.lzma 2021-05-18T15:42:43.689Z,1621352563.689 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Courier0009.lzma.bak 2021-05-18T15:42:43.689Z,1621352563.689 [DataOverHttps](INFO): SBD MOMSN=15648704 2021-05-18T15:43:00.558Z,1621352580.558 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20210518T150700/Express0010.lzma 2021-05-18T15:43:01.561Z,1621352581.561 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Express0010.lzma.bak 2021-05-18T15:43:01.561Z,1621352581.561 [DataOverHttps](INFO): SBD MOMSN=15648706 2021-05-18T15:43:04.074Z,1621352584.074 [Default:CheckIn:Read_Iridium] Stopped 2021-05-18T15:43:04.074Z,1621352584.074 [Default:CheckIn:C.Wait] Running Loop=1 2021-05-18T15:43:04.074Z,1621352584.074 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:43:10.935Z,1621352590.935 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 15 2021-05-18T15:43:10.936Z,1621352590.936 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:43:10.946Z,1621352590.946 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:43:11.326Z,1621352591.326 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:43:11.326Z,1621352591.326 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 15 2021-05-18T15:46:11.924Z,1621352771.924 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 16 2021-05-18T15:46:11.924Z,1621352771.924 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:46:11.935Z,1621352771.935 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:46:12.338Z,1621352772.338 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:46:12.338Z,1621352772.338 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 16 2021-05-18T15:48:04.637Z,1621352884.637 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-05-18T15:48:04.637Z,1621352884.637 [Default:CheckIn:C.Wait] Stopped 2021-05-18T15:48:04.638Z,1621352884.638 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:48:04.638Z,1621352884.638 [Default:CheckIn:D] Running Loop=1 2021-05-18T15:48:05.045Z,1621352885.045 [Default:CheckIn:D] Stopped 2021-05-18T15:48:05.045Z,1621352885.045 [Default:CheckIn:E] Running Loop=1 2021-05-18T15:48:05.442Z,1621352885.442 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.924410 min 2021-05-18T15:48:05.442Z,1621352885.442 [Default:CheckIn:E] Stopped 2021-05-18T15:48:05.442Z,1621352885.442 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-05-18T15:48:05.442Z,1621352885.442 [Default:CheckIn] Stopped 2021-05-18T15:48:05.442Z,1621352885.442 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T15:48:05.443Z,1621352885.443 [Default:CheckIn](INFO): Running loop #5 2021-05-18T15:48:05.444Z,1621352885.444 [Default:CheckIn] Running Loop=5 2021-05-18T15:48:05.444Z,1621352885.444 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T15:48:05.444Z,1621352885.444 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T15:49:12.903Z,1621352952.903 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 17 2021-05-18T15:49:12.903Z,1621352952.903 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:49:12.913Z,1621352952.913 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:49:13.326Z,1621352953.326 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:49:13.326Z,1621352953.326 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 17 2021-05-18T15:49:37.963Z,1621352977.963 [CommandLine](IMPORTANT): got command run ./Missions/lab_range_test.xml 2021-05-18T15:49:37.964Z,1621352977.964 [MissionManager](INFO): Loading Mission: ./Missions/lab_range_test.xml 2021-05-18T15:49:38.024Z,1621352978.024 [MissionManager](INFO): DefineArg lab_range_test.MissionTimeout = 2.000000 min 2021-05-18T15:49:38.026Z,1621352978.026 [MissionManager](INFO): DefineArg lab_range_test.ContactLabel = 50.000000 count 2021-05-18T15:49:38.029Z,1621352978.029 [MissionManager](INFO): DefineArg lab_range_test.TrackingUpdatePeriod = 3.000000 s 2021-05-18T15:49:38.031Z,1621352978.031 [MissionManager](INFO): DefineArg lab_range_test.NumberOfPings = 5.000000 count 2021-05-18T15:49:38.033Z,1621352978.033 [MissionManager](INFO): DefineArg lab_range_test.ContactDepth = nan m 2021-05-18T15:49:38.089Z,1621352978.089 [lab_range_test:B.Wait](DEBUG): Construct Wait. 2021-05-18T15:49:38.106Z,1621352978.106 [MissionManager](DEBUG): LAB TEST MISSION - ping remote xponder Maximum duration of mission 2 The acoustic address of the asset to be tracked 50 How long to wait between acoustic queries 3 Number of return pings to request with each acoustic query (more than 1 will activate oneway mode) 5 The acoustic address of the asset to be tracked NaN 2021-05-18T15:49:38.108Z,1621352978.108 [CommandLine](IMPORTANT): Running ./Missions/lab_range_test.xml 2021-05-18T15:49:38.366Z,1621352978.366 [Default] Stopped 2021-05-18T15:49:38.367Z,1621352978.367 [Default](DEBUG): Aggregate::uninitialize Default 2021-05-18T15:49:38.367Z,1621352978.367 [Default:B.GoToSurface] Stopped 2021-05-18T15:49:38.367Z,1621352978.367 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-05-18T15:49:38.367Z,1621352978.367 [Default:CheckIn] Stopped 2021-05-18T15:49:38.367Z,1621352978.367 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T15:49:38.367Z,1621352978.367 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:49:38.367Z,1621352978.367 [MissionManager](IMPORTANT): Started mission lab_range_test 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test] Running Loop=1 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test](DEBUG): Aggregate::initialize lab_range_test 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test:A.] Running Loop=1 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test:A.](INFO): Initializing Tracking. 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test:B.Wait] Running Loop=1 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test:B.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:49:38.368Z,1621352978.368 [lab_range_test:A.] Running Loop=1 2021-05-18T15:49:38.369Z,1621352978.369 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:38.369Z,1621352978.369 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:38.370Z,1621352978.370 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.118404 forward, 0.992965 starboard, 0.000000 keelward ] 2021-05-18T15:49:38.370Z,1621352978.370 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T15:49:38.372Z,1621352978.372 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.998830,-0.048290,-0.002768;0.048344,0.998522,0.024821;0.001565,-0.024926,0.999688 ] 2021-05-18T15:49:38.373Z,1621352978.373 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T15:49:38.374Z,1621352978.374 [lab_range_test:A.](INFO): direction in world frame: [ 0.166269 north, 0.985780 east, 0.024319 down ] 2021-05-18T15:49:38.374Z,1621352978.374 [lab_range_test:A.](INFO): relPosInFSK: [ 0.035521 forward, 0.297890 starboard, 0.000000 keelward ] 2021-05-18T15:49:38.375Z,1621352978.375 [lab_range_test:A.](INFO): relPosInNED: [ 0.049881 north, 0.295734 east, 0.007296 down ] 2021-05-18T15:49:38.376Z,1621352978.376 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T15:49:38.376Z,1621352978.376 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T15:49:38.760Z,1621352978.760 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:38.761Z,1621352978.761 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:39.174Z,1621352979.174 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:39.174Z,1621352979.174 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:39.609Z,1621352979.609 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:39.610Z,1621352979.610 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:39.986Z,1621352979.986 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:39.986Z,1621352979.986 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:40.369Z,1621352980.369 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:40.370Z,1621352980.370 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:40.777Z,1621352980.777 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:40.778Z,1621352980.778 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:41.181Z,1621352981.181 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:41.181Z,1621352981.181 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:41.592Z,1621352981.592 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:41.593Z,1621352981.593 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:41.986Z,1621352981.986 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:41.986Z,1621352981.986 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:42.405Z,1621352982.405 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:42.406Z,1621352982.406 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:42.813Z,1621352982.813 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:42.814Z,1621352982.814 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:43.221Z,1621352983.221 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:43.221Z,1621352983.221 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:43.601Z,1621352983.601 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:43.602Z,1621352983.602 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:43.602Z,1621352983.602 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T15:49:43.602Z,1621352983.602 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T15:49:43.994Z,1621352983.994 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:43.994Z,1621352983.994 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:43.995Z,1621352983.995 [DAT](INFO): entering command mode 2021-05-18T15:49:44.009Z,1621352984.009 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:44.010Z,1621352984.010 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:44.399Z,1621352984.399 [DAT](INFO): DAT read: UART Wakeup 2021-05-18T15:49:44.400Z,1621352984.400 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2021-05-18T15:49:44.401Z,1621352984.401 [DAT](INFO): commRate: 800 2021-05-18T15:49:44.401Z,1621352984.401 [DAT](INFO): DAT read: 2021-05-18T15:49:44.402Z,1621352984.402 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:44.402Z,1621352984.402 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:44.446Z,1621352984.446 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:44.447Z,1621352984.447 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:44.818Z,1621352984.818 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:44.818Z,1621352984.818 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:44.826Z,1621352984.826 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:44.826Z,1621352984.826 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:45.220Z,1621352985.220 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:45.221Z,1621352985.221 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:45.234Z,1621352985.234 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:45.234Z,1621352985.234 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:45.625Z,1621352985.625 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:45.625Z,1621352985.625 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:45.665Z,1621352985.665 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:45.665Z,1621352985.665 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:46.029Z,1621352986.029 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:46.029Z,1621352986.029 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:46.069Z,1621352986.069 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:46.069Z,1621352986.069 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:46.418Z,1621352986.418 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:46.418Z,1621352986.418 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:46.418Z,1621352986.418 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:46.430Z,1621352986.430 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:46.431Z,1621352986.431 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:46.823Z,1621352986.823 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:46.823Z,1621352986.823 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:46.823Z,1621352986.823 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:46.854Z,1621352986.854 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:46.854Z,1621352986.854 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:47.226Z,1621352987.226 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:47.226Z,1621352987.226 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:47.226Z,1621352987.226 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:47.276Z,1621352987.276 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:47.277Z,1621352987.277 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:47.635Z,1621352987.635 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:47.635Z,1621352987.635 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:47.635Z,1621352987.635 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:47.643Z,1621352987.643 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:47.643Z,1621352987.643 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:48.043Z,1621352988.043 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:48.043Z,1621352988.043 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:48.047Z,1621352988.047 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:48.066Z,1621352988.066 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:48.079Z,1621352988.079 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:48.458Z,1621352988.458 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:48.458Z,1621352988.458 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:48.458Z,1621352988.458 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:48.496Z,1621352988.496 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:48.497Z,1621352988.497 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:48.856Z,1621352988.856 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:48.856Z,1621352988.856 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:48.857Z,1621352988.857 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:48.901Z,1621352988.901 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:48.901Z,1621352988.901 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:48.901Z,1621352988.901 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T15:49:48.902Z,1621352988.902 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T15:49:49.257Z,1621352989.257 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:49.257Z,1621352989.257 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:49.257Z,1621352989.257 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:49.273Z,1621352989.273 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:49.273Z,1621352989.273 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:49.662Z,1621352989.662 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:49.663Z,1621352989.663 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:49.663Z,1621352989.663 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:49.681Z,1621352989.681 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:49.682Z,1621352989.682 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:50.062Z,1621352990.062 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:50.062Z,1621352990.062 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:50.062Z,1621352990.062 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:50.108Z,1621352990.108 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:50.109Z,1621352990.109 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:50.464Z,1621352990.464 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:50.464Z,1621352990.464 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:50.464Z,1621352990.464 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:50.518Z,1621352990.518 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:50.518Z,1621352990.518 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:50.862Z,1621352990.862 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:50.862Z,1621352990.862 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:50.862Z,1621352990.862 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:50.876Z,1621352990.876 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:50.877Z,1621352990.877 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:51.276Z,1621352991.276 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:51.276Z,1621352991.276 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:51.276Z,1621352991.276 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:51.320Z,1621352991.320 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:51.321Z,1621352991.321 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:51.685Z,1621352991.685 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:51.685Z,1621352991.685 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:51.685Z,1621352991.685 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:51.770Z,1621352991.770 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:51.775Z,1621352991.775 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:52.085Z,1621352992.085 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:52.085Z,1621352992.085 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:52.085Z,1621352992.085 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:52.097Z,1621352992.097 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:52.097Z,1621352992.097 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:52.478Z,1621352992.478 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:52.478Z,1621352992.478 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:52.478Z,1621352992.478 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:52.526Z,1621352992.526 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:52.526Z,1621352992.526 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:52.882Z,1621352992.882 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:52.882Z,1621352992.882 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:52.883Z,1621352992.883 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:52.901Z,1621352992.901 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:52.901Z,1621352992.901 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:53.287Z,1621352993.287 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:53.290Z,1621352993.290 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:53.290Z,1621352993.290 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:53.302Z,1621352993.302 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:53.302Z,1621352993.302 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:53.698Z,1621352993.698 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:53.698Z,1621352993.698 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:53.698Z,1621352993.698 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:53.734Z,1621352993.734 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:53.734Z,1621352993.734 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:54.105Z,1621352994.105 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:54.105Z,1621352994.105 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:54.105Z,1621352994.105 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:54.150Z,1621352994.150 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:54.151Z,1621352994.151 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:54.151Z,1621352994.151 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T15:49:54.151Z,1621352994.151 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T15:49:54.513Z,1621352994.513 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:54.513Z,1621352994.513 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:54.513Z,1621352994.513 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:54.550Z,1621352994.550 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:54.560Z,1621352994.560 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:54.932Z,1621352994.932 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:54.932Z,1621352994.932 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:54.933Z,1621352994.933 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:54.945Z,1621352994.945 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:54.946Z,1621352994.946 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:55.169Z,1621352995.169 [CommandLine](IMPORTANT): got command stop 2021-05-18T15:49:55.169Z,1621352995.169 [CommandLine](IMPORTANT): Scheduling is paused 2021-05-18T15:49:55.169Z,1621352995.169 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2021-05-18T15:49:55.306Z,1621352995.306 [DAT](INFO): ****** received valid address query ****** 2021-05-18T15:49:55.306Z,1621352995.306 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T15:49:55.307Z,1621352995.307 [DAT](DEBUG): checking for command mode acknowledgment 2021-05-18T15:49:55.319Z,1621352995.319 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T15:49:55.323Z,1621352995.323 [lab_range_test:A.](INFO): Received request for short update period 3.000000 seconds, increasing to 5 seconds. Consider requesting multiple pings instead. 2021-05-18T15:49:55.324Z,1621352995.324 [MissionManager](INFO): MissionManager is completed. 2021-05-18T15:49:55.324Z,1621352995.324 [MissionManager](INFO): Uninitializing Mission lab_range_test 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test] Stopped 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test](DEBUG): Aggregate::uninitialize lab_range_test 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test:A.] Stopped 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test:A.](DEBUG): Uninitializing Tracking. 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test:B.Wait] Stopped 2021-05-18T15:49:55.324Z,1621352995.324 [lab_range_test:B.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:49:55.733Z,1621352995.733 [MissionManager](IMPORTANT): Started mission Default 2021-05-18T15:49:55.733Z,1621352995.733 [Default] Running Loop=1 2021-05-18T15:49:55.734Z,1621352995.734 [Default](DEBUG): Aggregate::initialize Default 2021-05-18T15:49:55.734Z,1621352995.734 [Default:B.GoToSurface] Running Loop=1 2021-05-18T15:49:55.734Z,1621352995.734 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-05-18T15:49:55.734Z,1621352995.734 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-05-18T15:49:55.734Z,1621352995.734 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-05-18T15:49:55.735Z,1621352995.735 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-05-18T15:49:55.739Z,1621352995.739 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-05-18T15:49:55.740Z,1621352995.740 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-05-18T15:49:55.740Z,1621352995.740 [Default:A.Wait] Running Loop=1 2021-05-18T15:49:55.740Z,1621352995.740 [Default:A.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:50:09.074Z,1621353009.074 [Default:A.Wait](INFO): Done Waiting. 2021-05-18T15:50:09.074Z,1621353009.074 [Default:A.Wait] Stopped 2021-05-18T15:50:09.074Z,1621353009.074 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T15:50:09.482Z,1621353009.482 [Default:CheckIn] Running Loop=1 2021-05-18T15:50:09.482Z,1621353009.482 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T15:50:09.482Z,1621353009.482 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T15:51:33.152Z,1621353093.152 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T15:51:33.153Z,1621353093.153 [NAL9602] Data Fault, FailCount= 5 2021-05-18T15:51:33.153Z,1621353093.153 [NAL9602](ERROR): Data Fault 2021-05-18T15:51:33.195Z,1621353093.195 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T15:51:33.196Z,1621353093.196 [CBIT](CRITICAL): Data Fault in component: NAL9602 2021-05-18T15:51:33.552Z,1621353093.552 [NAL9602](INFO): Powering down 2021-05-18T15:51:33.591Z,1621353093.591 [CommandLine](FAULT): Scheduling is paused 2021-05-18T15:51:33.592Z,1621353093.592 [CBIT](INFO): Critical error at 20210518T155133 2021-05-18T15:52:13.971Z,1621353133.971 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 18 2021-05-18T15:52:13.971Z,1621353133.971 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:52:13.982Z,1621353133.982 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:52:14.389Z,1621353134.389 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:52:14.389Z,1621353134.389 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 18 2021-05-18T15:52:44.257Z,1621353164.257 [DAT](INFO): DAT read: user:18>Lowpower 2021-05-18T15:53:33.158Z,1621353213.158 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T15:53:33.158Z,1621353213.158 [NAL9602] No Fault, FailCount= 5 2021-05-18T15:53:33.546Z,1621353213.546 [NAL9602](INFO): Powering up NAL9602 2021-05-18T15:53:44.453Z,1621353224.453 [NAL9602](INFO): NAL9602 initialized 2021-05-18T15:55:09.706Z,1621353309.706 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-05-18T15:50:09.5Z 2021-05-18T15:55:09.706Z,1621353309.706 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T15:55:09.706Z,1621353309.706 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-05-18T15:55:14.965Z,1621353314.965 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 19 2021-05-18T15:55:14.965Z,1621353314.965 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:55:15.007Z,1621353315.007 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:55:15.429Z,1621353315.429 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T15:55:15.429Z,1621353315.429 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 19 2021-05-18T15:55:17.094Z,1621353317.094 [DataOverHttps](INFO): Sending 104 bytes from file Logs/20210518T150700/Courier0012.lzma 2021-05-18T15:55:18.097Z,1621353318.097 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Courier0012.lzma.bak 2021-05-18T15:55:18.097Z,1621353318.097 [DataOverHttps](INFO): SBD MOMSN=15648710 2021-05-18T15:55:34.851Z,1621353334.851 [DataOverHttps](INFO): Sending 490 bytes from file Logs/20210518T150700/Express0013.lzma 2021-05-18T15:55:35.853Z,1621353335.853 [DataOverHttps](INFO): Moved sent file to Logs/20210518T150700/Express0013.lzma.bak 2021-05-18T15:55:35.853Z,1621353335.853 [DataOverHttps](INFO): SBD MOMSN=15648713 2021-05-18T15:55:38.431Z,1621353338.431 [Default:CheckIn:Read_Iridium] Stopped 2021-05-18T15:55:38.431Z,1621353338.431 [Default:CheckIn:C.Wait] Running Loop=1 2021-05-18T15:55:38.431Z,1621353338.431 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-05-18T15:58:15.982Z,1621353495.982 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 20 2021-05-18T15:58:15.982Z,1621353495.982 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T15:58:15.993Z,1621353495.993 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T15:58:15.993Z,1621353495.993 [CBIT](FAULT): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T16:00:39.059Z,1621353639.059 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-05-18T16:00:39.059Z,1621353639.059 [Default:CheckIn:C.Wait] Stopped 2021-05-18T16:00:39.059Z,1621353639.059 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T16:00:39.060Z,1621353639.060 [Default:CheckIn:D] Running Loop=1 2021-05-18T16:00:39.494Z,1621353639.494 [Default:CheckIn:D] Stopped 2021-05-18T16:00:39.503Z,1621353639.503 [Default:CheckIn:E] Running Loop=1 2021-05-18T16:00:39.859Z,1621353639.859 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.729348 min 2021-05-18T16:00:39.859Z,1621353639.859 [Default:CheckIn:E] Stopped 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn] Stopped 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn](INFO): Running loop #2 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn] Running Loop=2 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T16:00:39.860Z,1621353639.860 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T16:03:45.280Z,1621353825.280 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-05-18T16:03:45.280Z,1621353825.280 [NAL9602] Data Fault, FailCount= 1 2021-05-18T16:03:45.280Z,1621353825.280 [NAL9602](ERROR): Data Fault 2021-05-18T16:03:45.317Z,1621353825.317 [CBIT](ERROR): Data Fault in component: NAL9602 2021-05-18T16:03:45.644Z,1621353825.644 [NAL9602](INFO): Powering down 2021-05-18T16:03:46.478Z,1621353826.478 [CBIT](INFO): Clearing failed state for component NAL9602 2021-05-18T16:03:46.479Z,1621353826.479 [NAL9602] No Fault, FailCount= 1 2021-05-18T16:04:15.944Z,1621353855.944 [NAL9602](INFO): Powering up NAL9602