2022-05-17T17:18:01.696Z,1652807881.696 [Supervisor](DEBUG): Initializing supervisor. 2022-05-17T17:18:01.700Z,1652807881.700 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2022-05-17T17:18:01.701Z,1652807881.701 [SyncHandler](INFO): Protected caller Thread ID is 828 2022-05-17T17:18:01.701Z,1652807881.701 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2022-05-17T17:18:01.702Z,1652807881.702 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2022-05-17T17:18:01.703Z,1652807881.703 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 829 2022-05-17T17:18:01.707Z,1652807881.707 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2022-05-17T17:18:01.725Z,1652807881.725 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2022-05-17T17:18:01.726Z,1652807881.726 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2022-05-17T17:18:01.727Z,1652807881.727 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 830 2022-05-17T17:18:01.731Z,1652807881.731 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2022-05-17T17:18:01.732Z,1652807881.732 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2022-05-17T17:18:01.732Z,1652807881.732 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 831 2022-05-17T17:18:01.734Z,1652807881.734 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2022-05-17T17:18:01.735Z,1652807881.735 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2022-05-17T17:18:01.736Z,1652807881.736 [logger ThreadHandler](INFO): Protected caller Thread ID is 832 2022-05-17T17:18:01.739Z,1652807881.739 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2022-05-17T17:18:01.740Z,1652807881.740 [Supervisor](INFO): Looking for Config files in directory: Config/ 2022-05-17T17:18:01.745Z,1652807881.745 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2022-05-17T17:18:01.843Z,1652807881.843 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2022-05-17T17:18:01.844Z,1652807881.844 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2022-05-17T17:18:02.076Z,1652807882.076 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2022-05-17T17:18:02.077Z,1652807882.077 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2022-05-17T17:18:02.357Z,1652807882.357 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2022-05-17T17:18:02.358Z,1652807882.358 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2022-05-17T17:18:02.469Z,1652807882.469 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2022-05-17T17:18:02.471Z,1652807882.471 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2022-05-17T17:18:03.196Z,1652807883.196 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2022-05-17T17:18:03.197Z,1652807883.197 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2022-05-17T17:18:03.705Z,1652807883.705 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2022-05-17T17:18:03.706Z,1652807883.706 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2022-05-17T17:18:04.315Z,1652807884.315 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2022-05-17T17:18:04.316Z,1652807884.316 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2022-05-17T17:18:04.732Z,1652807884.732 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2022-05-17T17:18:04.733Z,1652807884.733 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2022-05-17T17:18:05.299Z,1652807885.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2022-05-17T17:18:05.300Z,1652807885.300 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2022-05-17T17:18:06.203Z,1652807886.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2022-05-17T17:18:06.204Z,1652807886.204 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2022-05-17T17:18:06.440Z,1652807886.440 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2022-05-17T17:18:06.440Z,1652807886.440 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2022-05-17T17:18:06.576Z,1652807886.576 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2022-05-17T17:18:06.577Z,1652807886.577 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2022-05-17T17:18:06.659Z,1652807886.659 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2022-05-17T17:18:06.739Z,1652807886.739 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2022-05-17T17:18:06.942Z,1652807886.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2022-05-17T17:18:06.942Z,1652807886.942 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2022-05-17T17:18:07.174Z,1652807887.174 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2022-05-17T17:18:07.176Z,1652807887.176 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/ 2022-05-17T17:18:07.180Z,1652807887.180 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg 2022-05-17T17:18:07.264Z,1652807887.264 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg 2022-05-17T17:18:07.538Z,1652807887.538 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2022-05-17T17:18:07.539Z,1652807887.539 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg 2022-05-17T17:18:07.643Z,1652807887.643 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg 2022-05-17T17:18:07.820Z,1652807887.820 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg 2022-05-17T17:18:08.018Z,1652807888.018 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg 2022-05-17T17:18:08.106Z,1652807888.106 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg 2022-05-17T17:18:08.218Z,1652807888.218 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg 2022-05-17T17:18:08.329Z,1652807888.329 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg 2022-05-17T17:18:08.500Z,1652807888.500 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg 2022-05-17T17:18:08.608Z,1652807888.608 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg 2022-05-17T17:18:08.711Z,1652807888.711 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2022-05-17T17:18:08.714Z,1652807888.714 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2022-05-17T17:18:08.867Z,1652807888.867 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2022-05-17T17:18:08.868Z,1652807888.868 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2022-05-17T17:18:09.054Z,1652807889.054 [BuoyancyServo] Loaded 2022-05-17T17:18:09.054Z,1652807889.054 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2022-05-17T17:18:09.075Z,1652807889.075 [ElevatorServo] Loaded 2022-05-17T17:18:09.076Z,1652807889.076 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2022-05-17T17:18:09.096Z,1652807889.096 [MassServo] Loaded 2022-05-17T17:18:09.097Z,1652807889.097 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2022-05-17T17:18:09.117Z,1652807889.117 [RudderServo] Loaded 2022-05-17T17:18:09.117Z,1652807889.117 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2022-05-17T17:18:09.134Z,1652807889.134 [ThrusterHE] Loaded 2022-05-17T17:18:09.134Z,1652807889.134 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread. 2022-05-17T17:18:09.135Z,1652807889.135 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2022-05-17T17:18:09.136Z,1652807889.136 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2022-05-17T17:18:09.314Z,1652807889.314 [SBIT](DEBUG): Construct Startup Built In Test. 2022-05-17T17:18:09.329Z,1652807889.329 [SBIT] Loaded 2022-05-17T17:18:09.329Z,1652807889.329 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2022-05-17T17:18:09.332Z,1652807889.332 [IBIT](DEBUG): Construct Initiated Built In Test. 2022-05-17T17:18:09.354Z,1652807889.354 [IBIT] Loaded 2022-05-17T17:18:09.354Z,1652807889.354 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2022-05-17T17:18:09.360Z,1652807889.360 [CBIT](DEBUG): Construct Continuous Built In Test. 2022-05-17T17:18:09.583Z,1652807889.583 [CBIT] Loaded 2022-05-17T17:18:09.584Z,1652807889.584 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2022-05-17T17:18:09.584Z,1652807889.584 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2022-05-17T17:18:09.585Z,1652807889.585 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2022-05-17T17:18:09.809Z,1652807889.809 [CTD_Seabird] Loaded 2022-05-17T17:18:09.809Z,1652807889.809 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2022-05-17T17:18:09.811Z,1652807889.811 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406614E0 2022-05-17T17:18:09.811Z,1652807889.811 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 914 2022-05-17T17:18:09.843Z,1652807889.843 [ESPComponent] Loaded 2022-05-17T17:18:09.843Z,1652807889.843 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2022-05-17T17:18:09.864Z,1652807889.864 [PAR_Licor] Loaded 2022-05-17T17:18:09.864Z,1652807889.864 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2022-05-17T17:18:09.896Z,1652807889.896 [WetLabsBB2FL] Loaded 2022-05-17T17:18:09.896Z,1652807889.896 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2022-05-17T17:18:09.897Z,1652807889.897 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406914E0 2022-05-17T17:18:09.898Z,1652807889.898 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 915 2022-05-17T17:18:09.899Z,1652807889.899 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2022-05-17T17:18:09.900Z,1652807889.900 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2022-05-17T17:18:09.973Z,1652807889.973 [DepthRateCalculator] Loaded 2022-05-17T17:18:09.973Z,1652807889.973 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2022-05-17T17:18:09.979Z,1652807889.979 [PitchRateCalculator] Loaded 2022-05-17T17:18:09.979Z,1652807889.979 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2022-05-17T17:18:09.990Z,1652807889.990 [SpeedCalculator] Loaded 2022-05-17T17:18:09.990Z,1652807889.990 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2022-05-17T17:18:09.995Z,1652807889.995 [YawRateCalculator] Loaded 2022-05-17T17:18:09.995Z,1652807889.995 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2022-05-17T17:18:10.015Z,1652807890.015 [ElevatorOffsetCalculator] Loaded 2022-05-17T17:18:10.015Z,1652807890.015 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2022-05-17T17:18:10.015Z,1652807890.015 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2022-05-17T17:18:10.016Z,1652807890.016 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2022-05-17T17:18:10.142Z,1652807890.142 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2022-05-17T17:18:10.142Z,1652807890.142 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2022-05-17T17:18:10.188Z,1652807890.188 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2022-05-17T17:18:10.189Z,1652807890.189 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2022-05-17T17:18:10.328Z,1652807890.328 [DeadReckonUsingMultipleVelocitySources] Loaded 2022-05-17T17:18:10.328Z,1652807890.328 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2022-05-17T17:18:10.342Z,1652807890.342 [NavChart] Loaded 2022-05-17T17:18:10.342Z,1652807890.342 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2022-05-17T17:18:10.348Z,1652807890.348 [UniversalFixResidualReporter] Loaded 2022-05-17T17:18:10.349Z,1652807890.349 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2022-05-17T17:18:10.349Z,1652807890.349 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2022-05-17T17:18:10.350Z,1652807890.350 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2022-05-17T17:18:11.921Z,1652807891.921 [AHRS_M2] Loaded 2022-05-17T17:18:11.921Z,1652807891.921 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2022-05-17T17:18:12.171Z,1652807892.171 [BackseatComponent] Loaded 2022-05-17T17:18:12.171Z,1652807892.171 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2022-05-17T17:18:12.172Z,1652807892.172 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A0D4E0 2022-05-17T17:18:12.173Z,1652807892.173 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 917 2022-05-17T17:18:12.175Z,1652807892.175 [LcmUniversalReporter] Loaded 2022-05-17T17:18:12.176Z,1652807892.176 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2022-05-17T17:18:12.319Z,1652807892.319 [DataOverHttps] Loaded 2022-05-17T17:18:12.319Z,1652807892.319 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2022-05-17T17:18:12.320Z,1652807892.320 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A3D4E0 2022-05-17T17:18:12.320Z,1652807892.320 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 918 2022-05-17T17:18:12.341Z,1652807892.341 [Depth_Keller] Loaded 2022-05-17T17:18:12.341Z,1652807892.341 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2022-05-17T17:18:12.346Z,1652807892.346 [DropWeight] Loaded 2022-05-17T17:18:12.346Z,1652807892.346 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2022-05-17T17:18:12.384Z,1652807892.384 [DVL_micro] Loaded 2022-05-17T17:18:12.385Z,1652807892.385 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2022-05-17T17:18:12.445Z,1652807892.445 [NAL9602] Loaded 2022-05-17T17:18:12.445Z,1652807892.445 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2022-05-17T17:18:12.472Z,1652807892.472 [Onboard] Loaded 2022-05-17T17:18:12.472Z,1652807892.472 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2022-05-17T17:18:12.473Z,1652807892.473 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A6D4E0 2022-05-17T17:18:12.473Z,1652807892.473 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 919 2022-05-17T17:18:12.486Z,1652807892.486 [Power24vConverter] Loaded 2022-05-17T17:18:12.486Z,1652807892.486 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2022-05-17T17:18:12.499Z,1652807892.499 [Radio_Surface] Loaded 2022-05-17T17:18:12.500Z,1652807892.500 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2022-05-17T17:18:12.501Z,1652807892.501 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40A9D4E0 2022-05-17T17:18:12.501Z,1652807892.501 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 920 2022-05-17T17:18:12.502Z,1652807892.502 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2022-05-17T17:18:12.503Z,1652807892.503 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2022-05-17T17:18:12.590Z,1652807892.590 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2022-05-17T17:18:12.592Z,1652807892.592 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2022-05-17T17:18:12.662Z,1652807892.662 [VerticalControl](DEBUG): Construct VerticalControl. 2022-05-17T17:18:12.715Z,1652807892.715 [VerticalControl] Loaded 2022-05-17T17:18:12.716Z,1652807892.716 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2022-05-17T17:18:12.719Z,1652807892.719 [HorizontalControl](DEBUG): Construct HorizontalControl. 2022-05-17T17:18:12.756Z,1652807892.756 [HorizontalControl] Loaded 2022-05-17T17:18:12.756Z,1652807892.756 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2022-05-17T17:18:12.759Z,1652807892.759 [SpeedControl](DEBUG): Construct SpeedControl. 2022-05-17T17:18:12.761Z,1652807892.761 [SpeedControl] Loaded 2022-05-17T17:18:12.761Z,1652807892.761 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2022-05-17T17:18:12.764Z,1652807892.764 [LoopControl](DEBUG): Construct LoopControl. 2022-05-17T17:18:12.764Z,1652807892.764 [LoopControl] Loaded 2022-05-17T17:18:12.764Z,1652807892.764 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2022-05-17T17:18:12.765Z,1652807892.765 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2022-05-17T17:18:12.766Z,1652807892.766 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2022-05-17T17:18:12.782Z,1652807892.782 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2022-05-17T17:18:12.782Z,1652807892.782 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2022-05-17T17:18:13.166Z,1652807893.166 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2022-05-17T17:18:13.172Z,1652807893.172 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2022-05-17T17:18:13.175Z,1652807893.175 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2022-05-17T17:18:13.185Z,1652807893.185 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2022-05-17T17:18:13.187Z,1652807893.187 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BA74E0 2022-05-17T17:18:13.187Z,1652807893.187 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 921 2022-05-17T17:18:13.191Z,1652807893.191 [Supervisor](INFO): Main Thread ID is 823 2022-05-17T17:18:13.191Z,1652807893.191 [Supervisor](DEBUG): Running supervisor. 2022-05-17T17:18:13.192Z,1652807893.192 [CommandExec ThreadHandler](INFO): Handler Thread ID is 922 2022-05-17T17:18:13.193Z,1652807893.193 [CommandExec](INFO): Initializing the command executive. 2022-05-17T17:18:13.194Z,1652807893.194 [CommandLine ThreadHandler](INFO): Handler Thread ID is 923 2022-05-17T17:18:13.196Z,1652807893.196 [controlThread ThreadHandler](INFO): Handler Thread ID is 924 2022-05-17T17:18:13.197Z,1652807893.197 [controlThread](DEBUG): Initializing ControlThread 2022-05-17T17:18:13.198Z,1652807893.198 [SBIT](INFO): Initialize SBIT Component. 2022-05-17T17:18:13.199Z,1652807893.199 [SBIT](IMPORTANT): git: 2022-05-16 2022-05-17T17:18:13.199Z,1652807893.199 [SBIT](INFO): git hash: 22dd8ec1d68d2d3458ffb0a0481759ba9019d0f5 2022-05-17T17:18:13.199Z,1652807893.199 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2022-05-17T17:18:13.201Z,1652807893.201 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021 2022-05-17T17:18:13.202Z,1652807893.202 [SBIT](INFO): Beginning SBIT in 59.000000 seconds. 2022-05-17T17:18:13.202Z,1652807893.202 [IBIT](INFO): Initialize IBIT Component. 2022-05-17T17:18:13.203Z,1652807893.203 [CBIT](DEBUG): Initialize CBIT Component. 2022-05-17T17:18:13.204Z,1652807893.204 [logger ThreadHandler](INFO): Handler Thread ID is 925 2022-05-17T17:18:13.216Z,1652807893.216 [CBIT](DEBUG): Initialized mux pins. 2022-05-17T17:18:13.216Z,1652807893.216 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2022-05-17T17:18:13.216Z,1652807893.216 [CBIT](DEBUG): Initializing the watchdog timer. 2022-05-17T17:18:13.224Z,1652807893.224 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 926 2022-05-17T17:18:13.225Z,1652807893.225 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2022-05-17T17:18:13.229Z,1652807893.229 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 928 2022-05-17T17:18:13.232Z,1652807893.232 [WetLabsBB2FL](INFO): Powering up 2022-05-17T17:18:13.234Z,1652807893.234 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 930 2022-05-17T17:18:13.240Z,1652807893.240 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2022-05-17T17:18:13.240Z,1652807893.240 [CBIT](DEBUG): Initializing heartbeat. 2022-05-17T17:18:13.241Z,1652807893.241 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 931 2022-05-17T17:18:13.242Z,1652807893.242 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2022-05-17T17:18:13.248Z,1652807893.248 [Onboard ThreadHandler](INFO): Handler Thread ID is 932 2022-05-17T17:18:13.265Z,1652807893.265 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 933 2022-05-17T17:18:13.288Z,1652807893.288 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 934 2022-05-17T17:18:13.297Z,1652807893.297 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2022-05-17T17:18:13.297Z,1652807893.297 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2022-05-17T17:18:13.298Z,1652807893.298 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000 2022-05-17T17:18:13.299Z,1652807893.299 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000 2022-05-17T17:18:13.312Z,1652807893.312 [CBIT](DEBUG): Deactivating GF circuits. 2022-05-17T17:18:13.312Z,1652807893.312 [CBIT](DEBUG): Deactivating emergency mode. 2022-05-17T17:18:13.348Z,1652807893.348 [CBIT](DEBUG): Backplane powered. 2022-05-17T17:18:13.352Z,1652807893.352 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2022-05-17T17:18:13.353Z,1652807893.353 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2022-05-17T17:18:13.353Z,1652807893.353 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2022-05-17T17:18:13.353Z,1652807893.353 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2022-05-17T17:18:13.354Z,1652807893.354 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2022-05-17T17:18:13.355Z,1652807893.355 [NavChart](DEBUG): Initialize NavChart Navigation. 2022-05-17T17:18:13.355Z,1652807893.355 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2022-05-17T17:18:13.362Z,1652807893.362 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2022-05-17T17:18:13.364Z,1652807893.364 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2022-05-17T17:18:13.365Z,1652807893.365 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2022-05-17T17:18:13.365Z,1652807893.365 [LoopControl](DEBUG): Initialize LoopControlComponent. 2022-05-17T17:18:13.366Z,1652807893.366 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml 2022-05-17T17:18:13.411Z,1652807893.411 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2022-05-17T17:18:13.451Z,1652807893.451 [MissionManager](DEBUG): 2022-05-17T17:18:13.468Z,1652807893.468 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml 2022-05-17T17:18:13.542Z,1652807893.542 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2022-05-17T17:18:13.543Z,1652807893.543 [Default:A.Wait](DEBUG): Construct Wait. 2022-05-17T17:18:13.545Z,1652807893.545 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2022-05-17T17:18:13.601Z,1652807893.601 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2022-05-17T17:18:13.603Z,1652807893.603 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2022-05-17T17:18:13.619Z,1652807893.619 [Default:E.Execute](DEBUG): Construct Execute. 2022-05-17T17:18:13.623Z,1652807893.623 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2022-05-17T17:18:13.652Z,1652807893.652 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-05-17T17:18:13.680Z,1652807893.680 [Radio_Surface](INFO): Powering up 2022-05-17T17:18:13.685Z,1652807893.685 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2022-05-17T17:18:13.797Z,1652807893.797 [Depth_Keller](ERROR): Pressure reading out of range: 1895.834351 decibar 2022-05-17T17:18:13.805Z,1652807893.805 [Power24vConverter](INFO): Powering up. 2022-05-17T17:18:13.825Z,1652807893.825 [DepthRateCalculator](ERROR): Depth measurement is not active 2022-05-17T17:18:13.886Z,1652807893.886 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:13.892Z,1652807893.892 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2022-05-17T17:18:13.893Z,1652807893.893 [ElevatorServo](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:13.900Z,1652807893.900 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2022-05-17T17:18:13.901Z,1652807893.901 [MassServo](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:13.908Z,1652807893.908 [MassServo](DEBUG): Initializing MassServo. 2022-05-17T17:18:13.909Z,1652807893.909 [RudderServo](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:13.916Z,1652807893.916 [RudderServo](DEBUG): Initializing RudderServo. 2022-05-17T17:18:13.917Z,1652807893.917 [ThrusterHE](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:13.924Z,1652807893.924 [ThrusterHE](DEBUG): Initializing ThrusterHE. 2022-05-17T17:18:14.098Z,1652807894.098 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2022-05-17T17:18:14.098Z,1652807894.098 [DropWeight] Hardware Fault, FailCount= 1 2022-05-17T17:18:14.098Z,1652807894.098 [DropWeight](ERROR): Hardware Fault 2022-05-17T17:18:14.121Z,1652807894.121 [CommandExec](FAULT): Scheduling is paused 2022-05-17T17:18:14.121Z,1652807894.121 [CBIT](INFO): Critical error at 20220517T171814 2022-05-17T17:18:14.122Z,1652807894.122 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2022-05-17T17:18:14.132Z,1652807894.132 [CBIT](ERROR): Hardware Fault in component: DropWeight 2022-05-17T17:18:14.133Z,1652807894.133 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2022-05-17T17:18:14.816Z,1652807894.816 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2022-05-17T17:18:14.816Z,1652807894.816 [RudderServo](FAULT): Rudder failed to initialize 2022-05-17T17:18:14.816Z,1652807894.816 [RudderServo] Communications Fault, FailCount= 1 2022-05-17T17:18:14.816Z,1652807894.816 [RudderServo](ERROR): Communications Fault 2022-05-17T17:18:14.818Z,1652807894.818 [CBIT](INFO): Critical error at 20220517T171814 2022-05-17T17:18:14.820Z,1652807894.820 [CBIT](ERROR): Communications Fault in component: RudderServo 2022-05-17T17:18:15.013Z,1652807895.013 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2022-05-17T17:18:15.013Z,1652807895.013 [RudderServo](INFO): Powering down 2022-05-17T17:18:15.340Z,1652807895.340 [WetLabsBB2FL](INFO): Powering down 2022-05-17T17:18:15.701Z,1652807895.701 [RudderServo](DEBUG): Initializing EZServoServo. 2022-05-17T17:18:15.821Z,1652807895.821 [RudderServo](DEBUG): Initializing RudderServo. 2022-05-17T17:18:15.825Z,1652807895.825 [CBIT](INFO): Clearing failed state for component RudderServo 2022-05-17T17:18:15.825Z,1652807895.825 [RudderServo] No Fault, FailCount= 1 2022-05-17T17:18:19.573Z,1652807899.573 [ThrusterHE](ERROR): Zero Speed Commanded. 2022-05-17T17:18:42.758Z,1652807922.758 [NAL9602](INFO): Powering up NAL9602 2022-05-17T17:18:53.666Z,1652807933.666 [NAL9602](INFO): NAL9602 initialized 2022-05-17T17:19:12.679Z,1652807952.679 [SBIT](IMPORTANT): Beginning Startup BIT 2022-05-17T17:19:12.683Z,1652807952.683 [CBIT](IMPORTANT): Beginning ground fault scan 2022-05-17T17:19:23.613Z,1652807963.613 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.002778 CHAN A1 (24V): -0.000253 CHAN A2 (12V): -0.005576 CHAN A3 (5V): -0.002655 CHAN B0 (3.3V): -0.001702 CHAN B1 (3.15aV): -0.001197 CHAN B2 (3.15bV): -0.000964 CHAN B3 (GND): -0.000151 OPEN: 0.004985 Full Scale: +/- 1 mA 2022-05-17T17:20:06.401Z,1652808006.401 [SBIT](IMPORTANT): SBIT PASSED 2022-05-17T17:20:06.401Z,1652808006.401 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2022-05-17T17:20:06.805Z,1652808006.805 [MissionManager](IMPORTANT): Started mission Startup 2022-05-17T17:20:06.806Z,1652808006.806 [Startup] Running Loop=1 2022-05-17T17:20:06.806Z,1652808006.806 [Startup](DEBUG): Aggregate::initialize Startup 2022-05-17T17:20:06.806Z,1652808006.806 [Startup:A.GoToSurface] Running Loop=1 2022-05-17T17:20:06.806Z,1652808006.806 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-05-17T17:20:06.806Z,1652808006.806 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-05-17T17:20:06.807Z,1652808006.807 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-05-17T17:20:06.807Z,1652808006.807 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-05-17T17:20:06.808Z,1652808006.808 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-05-17T17:20:06.809Z,1652808006.809 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-05-17T17:20:06.810Z,1652808006.810 [Startup:StartupSatComms] Running Loop=1 2022-05-17T17:20:06.810Z,1652808006.810 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2022-05-17T17:20:06.810Z,1652808006.810 [Startup:StartupSatComms:A] Running Loop=1 2022-05-17T17:20:07.206Z,1652808007.206 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2022-05-17T17:21:06.995Z,1652808066.995 [Startup:StartupSatComms:A](INFO): Timed out from 2022-05-17T17:20:06.8Z 2022-05-17T17:21:06.995Z,1652808066.995 [Startup:StartupSatComms:A] Stopped 2022-05-17T17:21:06.995Z,1652808066.995 [Startup:StartupSatComms:B] Running Loop=1 2022-05-17T17:21:07.405Z,1652808067.405 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-05-17T17:21:13.496Z,1652808073.496 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2022-05-17T17:21:13.496Z,1652808073.496 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-05-17T17:21:13.531Z,1652808073.531 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-05-17T17:21:13.884Z,1652808073.884 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-05-17T17:21:13.884Z,1652808073.884 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2022-05-17T17:21:45.771Z,1652808105.771 [NAL9602](INFO): SBD MO Status=2, MOMSN=46983, MT Status=2, MTMSN=0 2022-05-17T17:21:45.772Z,1652808105.772 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-17T17:21:53.390Z,1652808113.390 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004607 2022-05-17T17:22:00.612Z,1652808120.612 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220516T230620/Courier0031.lzma 2022-05-17T17:22:01.614Z,1652808121.614 [DataOverHttps](INFO): Moved sent file to Logs/20220516T230620/Courier0031.lzma.bak 2022-05-17T17:22:01.614Z,1652808121.614 [DataOverHttps](INFO): SBD MOMSN=16797989 2022-05-17T17:22:07.267Z,1652808127.267 [Startup:StartupSatComms:B](INFO): Timed out from 2022-05-17T17:21:06.0Z 2022-05-17T17:22:07.267Z,1652808127.267 [Startup:StartupSatComms:B] Stopped 2022-05-17T17:22:07.267Z,1652808127.267 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2022-05-17T17:22:07.267Z,1652808127.267 [Startup:StartupSatComms] Stopped 2022-05-17T17:22:07.267Z,1652808127.267 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2022-05-17T17:22:07.272Z,1652808127.272 [Startup](INFO): Completed Startup 2022-05-17T17:22:07.272Z,1652808127.272 [MissionManager](INFO): Startup is completed. 2022-05-17T17:22:07.272Z,1652808127.272 [MissionManager](INFO): Uninitializing Mission Startup 2022-05-17T17:22:07.272Z,1652808127.272 [Startup] Stopped 2022-05-17T17:22:07.272Z,1652808127.272 [Startup](DEBUG): Aggregate::uninitialize Startup 2022-05-17T17:22:07.273Z,1652808127.273 [Startup:A.GoToSurface] Stopped 2022-05-17T17:22:07.273Z,1652808127.273 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-05-17T17:22:07.676Z,1652808127.676 [MissionManager](IMPORTANT): Started mission Default 2022-05-17T17:22:07.677Z,1652808127.677 [Default] Running Loop=1 2022-05-17T17:22:07.677Z,1652808127.677 [Default](DEBUG): Aggregate::initialize Default 2022-05-17T17:22:07.677Z,1652808127.677 [Default:B.GoToSurface] Running Loop=1 2022-05-17T17:22:07.677Z,1652808127.677 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-05-17T17:22:07.677Z,1652808127.677 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-05-17T17:22:07.677Z,1652808127.677 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-05-17T17:22:07.678Z,1652808127.678 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-05-17T17:22:07.678Z,1652808127.678 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-05-17T17:22:07.678Z,1652808127.678 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-05-17T17:22:07.679Z,1652808127.679 [Default:A.Wait] Running Loop=1 2022-05-17T17:22:07.679Z,1652808127.679 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:22:21.014Z,1652808141.014 [Default:A.Wait](INFO): Done Waiting. 2022-05-17T17:22:21.014Z,1652808141.014 [Default:A.Wait] Stopped 2022-05-17T17:22:21.014Z,1652808141.014 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:22:21.421Z,1652808141.421 [Default:CheckIn] Running Loop=1 2022-05-17T17:22:21.421Z,1652808141.421 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:22:21.421Z,1652808141.421 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:22:21.888Z,1652808141.888 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-05-17T17:22:22.637Z,1652808142.637 [DataOverHttps](INFO): Sending 268 bytes from file Logs/20220517T171230/Courier0000.lzma 2022-05-17T17:22:23.637Z,1652808143.637 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171230/Courier0000.lzma.bak 2022-05-17T17:22:23.638Z,1652808143.638 [DataOverHttps](INFO): SBD MOMSN=16797992 2022-05-17T17:23:33.277Z,1652808213.277 [CommandExec](IMPORTANT): got command maintain control HorizontalControl.rudderAngleAction 10 degree 2022-05-17T17:23:33.289Z,1652808213.289 [ComponentRegistry](DEBUG): SyncComponent "Maintain_HorizontalControl.rudderAngleAction" handled in the control thread. 2022-05-17T17:23:33.398Z,1652808213.398 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_HorizontalControl.rudderAngleAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-05-17T17:23:43.271Z,1652808223.271 [CommandExec](IMPORTANT): got command maintain control HorizontalControl.rudderAngleAction 13 degree 2022-05-17T17:23:56.342Z,1652808236.342 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-17T17:23:56.436Z,1652808236.436 [CommandExec](IMPORTANT): got command maintain control HorizontalControl.rudderAngleAction -13 degree 2022-05-17T17:24:07.253Z,1652808247.253 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172406.00,A,3426.97602,N,11943.36154,W,0.019,189.60,170522,,,D*70 2022-05-17T17:24:07.257Z,1652808247.257 [NAL9602](INFO): GPS fix at 20220517T172406: (34.449600, -119.722692) 2022-05-17T17:24:07.266Z,1652808247.266 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:24:07.266Z,1652808247.266 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:24:07.703Z,1652808247.703 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-05-17T17:24:15.751Z,1652808255.751 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220517T171230/Courier0004.lzma 2022-05-17T17:24:16.754Z,1652808256.754 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171230/Courier0004.lzma.bak 2022-05-17T17:24:16.754Z,1652808256.754 [DataOverHttps](INFO): SBD MOMSN=16797998 2022-05-17T17:24:17.791Z,1652808257.791 [CommandExec](IMPORTANT): got command maintain control HorizontalControl.rudderAngleAction -15 degree 2022-05-17T17:24:27.298Z,1652808267.298 [CommandExec](IMPORTANT): got command maintain clear 2022-05-17T17:24:27.606Z,1652808267.606 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-05-17T17:24:32.900Z,1652808272.900 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20220517T171801/Courier0000.lzma 2022-05-17T17:24:33.904Z,1652808273.904 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0000.lzma.bak 2022-05-17T17:24:33.904Z,1652808273.904 [DataOverHttps](INFO): SBD MOMSN=16798000 2022-05-17T17:24:39.751Z,1652808279.751 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-17T17:24:49.566Z,1652808289.566 [CommandExec](IMPORTANT): got command show variable RudderServo.offset 2022-05-17T17:24:49.723Z,1652808289.723 [CommandExec](IMPORTANT): RudderServo.offsetAngle (degree) 2022-05-17T17:24:53.344Z,1652808293.344 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20220517T171801/Courier0004.lzma 2022-05-17T17:24:54.346Z,1652808294.346 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0004.lzma.bak 2022-05-17T17:24:54.346Z,1652808294.346 [DataOverHttps](INFO): SBD MOMSN=16798008 2022-05-17T17:24:57.335Z,1652808297.335 [CommandExec](IMPORTANT): got command get RudderServo.offsetAngle degree 2022-05-17T17:24:57.336Z,1652808297.336 [CommandExec](IMPORTANT): RudderServo.offsetAngle 1.500000 arcdeg 2022-05-17T17:25:08.837Z,1652808308.837 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2022-05-17T17:25:08.837Z,1652808308.837 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+19.3,0000.0,1489.0I,+00062,00885,+00BI,+00062,+00411,-00885,+00000,I 2022-05-17T17:25:10.891Z,1652808310.891 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220516T230620/Express0032.lzma 2022-05-17T17:25:11.894Z,1652808311.894 [DataOverHttps](INFO): Moved sent file to Logs/20220516T230620/Express0032.lzma.bak 2022-05-17T17:25:11.894Z,1652808311.894 [DataOverHttps](INFO): SBD MOMSN=16798015 2022-05-17T17:25:24.186Z,1652808324.186 [DVL_micro](ERROR): only read 3 of 4 data items 2022-05-17T17:25:24.186Z,1652808324.186 [DVL_micro](ERROR): Failed to parse: :BI,+00004,+0007,+00000,I 2022-05-17T17:25:27.782Z,1652808327.782 [DataOverHttps](INFO): Sending 898 bytes from file Logs/20220517T171230/Express0001.lzma 2022-05-17T17:25:28.782Z,1652808328.782 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171230/Express0001.lzma.bak 2022-05-17T17:25:28.782Z,1652808328.782 [DataOverHttps](INFO): SBD MOMSN=16798017 2022-05-17T17:25:48.887Z,1652808348.887 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220517T171230/Express0005.lzma 2022-05-17T17:25:49.890Z,1652808349.890 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171230/Express0005.lzma.bak 2022-05-17T17:25:49.890Z,1652808349.890 [DataOverHttps](INFO): SBD MOMSN=16798044 2022-05-17T17:26:05.813Z,1652808365.813 [DataOverHttps](INFO): Sending 680 bytes from file Logs/20220517T171801/Express0001.lzma 2022-05-17T17:26:06.814Z,1652808366.814 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0001.lzma.bak 2022-05-17T17:26:06.814Z,1652808366.814 [DataOverHttps](INFO): SBD MOMSN=16798046 2022-05-17T17:26:11.941Z,1652808371.941 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2022-05-17T17:26:11.941Z,1652808371.941 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35,0000.0,1489.0,000 2022-05-17T17:26:23.520Z,1652808383.520 [DataOverHttps](INFO): Sending 398 bytes from file Logs/20220517T171801/Express0005.lzma 2022-05-17T17:26:24.522Z,1652808384.522 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0005.lzma.bak 2022-05-17T17:26:24.522Z,1652808384.522 [DataOverHttps](INFO): SBD MOMSN=16798060 2022-05-17T17:26:26.071Z,1652808386.071 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:26:26.071Z,1652808386.071 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:26:26.071Z,1652808386.071 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:31:26.682Z,1652808686.682 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:31:26.682Z,1652808686.682 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:31:26.682Z,1652808686.682 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:31:26.682Z,1652808686.682 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:31:27.087Z,1652808687.087 [Default:CheckIn:D] Stopped 2022-05-17T17:31:27.087Z,1652808687.087 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.323499 min 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn:E] Stopped 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn] Stopped 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn](INFO): Running loop #2 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn] Running Loop=2 2022-05-17T17:31:27.498Z,1652808687.498 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:31:27.499Z,1652808687.499 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:31:29.507Z,1652808689.507 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173128.00,A,3426.96978,N,11943.35817,W,0.058,189.60,170522,,,D*73 2022-05-17T17:31:29.509Z,1652808689.509 [NAL9602](INFO): GPS fix at 20220517T173128: (34.449496, -119.722636) 2022-05-17T17:31:29.541Z,1652808689.541 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:31:29.541Z,1652808689.541 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:31:39.015Z,1652808699.015 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220517T171801/Courier0007.lzma 2022-05-17T17:31:40.018Z,1652808700.018 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0007.lzma.bak 2022-05-17T17:31:40.018Z,1652808700.018 [DataOverHttps](INFO): SBD MOMSN=16798074 2022-05-17T17:31:57.184Z,1652808717.184 [DataOverHttps](INFO): Sending 320 bytes from file Logs/20220517T171801/Express0008.lzma 2022-05-17T17:31:58.186Z,1652808718.186 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0008.lzma.bak 2022-05-17T17:31:58.186Z,1652808718.186 [DataOverHttps](INFO): SBD MOMSN=16798077 2022-05-17T17:31:59.945Z,1652808719.945 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-17T17:32:00.024Z,1652808720.024 [NAL9602](ERROR): received: +CSQ:0 OK983, 2, 0, 0, 0 OK 2022-05-17T17:32:00.074Z,1652808720.074 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:32:00.074Z,1652808720.074 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:32:00.075Z,1652808720.075 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:32:29.132Z,1652808749.132 [DVL_micro](ERROR): DVL uart error: serial timeout 2022-05-17T17:32:29.132Z,1652808749.132 [DVL_micro] Communications Fault, FailCount= 1 2022-05-17T17:32:29.132Z,1652808749.132 [DVL_micro](ERROR): Communications Fault 2022-05-17T17:32:29.132Z,1652808749.132 [DVL_micro](ERROR): Failed to parse: 2022-05-17T17:32:29.218Z,1652808749.218 [CBIT](ERROR): Communications Fault in component: DVL_micro 2022-05-17T17:32:29.504Z,1652808749.504 [DVL_micro](INFO): Powering down 2022-05-17T17:32:30.274Z,1652808750.274 [CBIT](INFO): Clearing failed state for component DVL_micro 2022-05-17T17:32:30.274Z,1652808750.274 [DVL_micro] No Fault, FailCount= 1 2022-05-17T17:33:14.357Z,1652808794.357 [CBIT](INFO): Clearing failed state for component DropWeight 2022-05-17T17:33:14.357Z,1652808794.357 [DropWeight] No Fault, FailCount= 1 2022-05-17T17:33:26.442Z,1652808806.442 [DVL_micro](ERROR): only read 3 of 4 data items 2022-05-17T17:33:26.443Z,1652808806.443 [DVL_micro](ERROR): Failed to parse: :BI,-00040,+0783,+00000,I 2022-05-17T17:34:39.730Z,1652808879.730 [DVL_micro](ERROR): only read 3 of 4 data items 2022-05-17T17:34:39.730Z,1652808879.730 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999..99 2022-05-17T17:36:31.248Z,1652808991.248 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-17T17:37:00.404Z,1652809020.404 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:37:00.404Z,1652809020.404 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:37:00.404Z,1652809020.404 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:37:00.405Z,1652809020.405 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:37:00.802Z,1652809020.802 [Default:CheckIn:D] Stopped 2022-05-17T17:37:00.802Z,1652809020.802 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 14.885423 min 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn:E] Stopped 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn] Stopped 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:37:01.236Z,1652809021.236 [Default:CheckIn](INFO): Running loop #3 2022-05-17T17:37:01.237Z,1652809021.237 [Default:CheckIn] Running Loop=3 2022-05-17T17:37:01.237Z,1652809021.237 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:37:01.237Z,1652809021.237 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:37:03.226Z,1652809023.226 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173702.00,A,3426.96559,N,11943.35181,W,0.544,189.60,170522,,,D*7C 2022-05-17T17:37:03.228Z,1652809023.228 [NAL9602](INFO): GPS fix at 20220517T173702: (34.449427, -119.722530) 2022-05-17T17:37:03.262Z,1652809023.262 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:37:03.262Z,1652809023.262 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:37:10.571Z,1652809030.571 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220517T171801/Courier0010.lzma 2022-05-17T17:37:11.573Z,1652809031.573 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0010.lzma.bak 2022-05-17T17:37:11.574Z,1652809031.574 [DataOverHttps](INFO): SBD MOMSN=16798093 2022-05-17T17:37:27.620Z,1652809047.620 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220517T171801/Express0011.lzma 2022-05-17T17:37:28.622Z,1652809048.622 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0011.lzma.bak 2022-05-17T17:37:28.622Z,1652809048.622 [DataOverHttps](INFO): SBD MOMSN=16798096 2022-05-17T17:37:30.306Z,1652809050.306 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:37:30.306Z,1652809050.306 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:37:30.306Z,1652809050.306 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:37:35.991Z,1652809055.991 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-17T17:41:32.096Z,1652809292.096 [DVL_micro](ERROR): Failed to parse: :000000000,35.0,+19.8,0000.0,10 2022-05-17T17:42:30.739Z,1652809350.739 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:42:30.739Z,1652809350.739 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:42:30.739Z,1652809350.739 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:42:30.739Z,1652809350.739 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:42:31.152Z,1652809351.152 [Default:CheckIn:D] Stopped 2022-05-17T17:42:31.152Z,1652809351.152 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:42:31.540Z,1652809351.540 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.391258 min 2022-05-17T17:42:31.540Z,1652809351.540 [Default:CheckIn:E] Stopped 2022-05-17T17:42:31.540Z,1652809351.540 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn] Stopped 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn](INFO): Running loop #4 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn] Running Loop=4 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:42:31.541Z,1652809351.541 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:42:33.555Z,1652809353.555 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174232.00,A,3426.97201,N,11943.36083,W,0.253,189.60,170522,,,D*77 2022-05-17T17:42:33.566Z,1652809353.566 [NAL9602](INFO): GPS fix at 20220517T174232: (34.449534, -119.722680) 2022-05-17T17:42:33.575Z,1652809353.575 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:42:33.576Z,1652809353.576 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:42:43.859Z,1652809363.859 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20220517T171801/Courier0013.lzma 2022-05-17T17:42:44.862Z,1652809364.862 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0013.lzma.bak 2022-05-17T17:42:44.862Z,1652809364.862 [DataOverHttps](INFO): SBD MOMSN=16798108 2022-05-17T17:43:00.783Z,1652809380.783 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220517T171801/Express0014.lzma 2022-05-17T17:43:01.786Z,1652809381.786 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0014.lzma.bak 2022-05-17T17:43:01.786Z,1652809381.786 [DataOverHttps](INFO): SBD MOMSN=16798111 2022-05-17T17:43:03.953Z,1652809383.953 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:43:03.953Z,1652809383.953 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:43:03.953Z,1652809383.953 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:43:04.327Z,1652809384.327 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-17T17:43:04.408Z,1652809384.408 [NAL9602](ERROR): received: +CSQ:0 OK983, 2, 0, 0, 0 OK 2022-05-17T17:47:35.815Z,1652809655.815 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-17T17:48:04.520Z,1652809684.520 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:48:04.520Z,1652809684.520 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:48:04.520Z,1652809684.520 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:48:04.520Z,1652809684.520 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:48:04.914Z,1652809684.914 [Default:CheckIn:D] Stopped 2022-05-17T17:48:04.914Z,1652809684.914 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:48:05.310Z,1652809685.310 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 25.953949 min 2022-05-17T17:48:05.310Z,1652809685.310 [Default:CheckIn:E] Stopped 2022-05-17T17:48:05.310Z,1652809685.310 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:48:05.310Z,1652809685.310 [Default:CheckIn] Stopped 2022-05-17T17:48:05.310Z,1652809685.310 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:48:05.311Z,1652809685.311 [Default:CheckIn](INFO): Running loop #5 2022-05-17T17:48:05.311Z,1652809685.311 [Default:CheckIn] Running Loop=5 2022-05-17T17:48:05.311Z,1652809685.311 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:48:05.311Z,1652809685.311 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:48:07.331Z,1652809687.331 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174806.00,A,3426.97029,N,11943.35496,W,0.117,127.56,170522,,,D*73 2022-05-17T17:48:07.333Z,1652809687.333 [NAL9602](INFO): GPS fix at 20220517T174806: (34.449505, -119.722583) 2022-05-17T17:48:07.343Z,1652809687.343 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:48:07.343Z,1652809687.343 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:48:14.567Z,1652809694.567 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220517T171801/Courier0016.lzma 2022-05-17T17:48:15.570Z,1652809695.570 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0016.lzma.bak 2022-05-17T17:48:15.570Z,1652809695.570 [DataOverHttps](INFO): SBD MOMSN=16798121 2022-05-17T17:48:31.480Z,1652809711.480 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220517T171801/Express0017.lzma 2022-05-17T17:48:32.486Z,1652809712.486 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0017.lzma.bak 2022-05-17T17:48:32.486Z,1652809712.486 [DataOverHttps](INFO): SBD MOMSN=16798124 2022-05-17T17:48:34.416Z,1652809714.416 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:48:34.416Z,1652809714.416 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:48:34.416Z,1652809714.416 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:48:39.718Z,1652809719.718 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-17T17:53:35.148Z,1652810015.148 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:53:35.148Z,1652810015.148 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:53:35.148Z,1652810015.148 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:53:35.148Z,1652810015.148 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:53:35.564Z,1652810015.564 [Default:CheckIn:D] Stopped 2022-05-17T17:53:35.564Z,1652810015.564 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:53:35.989Z,1652810015.989 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.464732 min 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn:E] Stopped 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn] Stopped 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn](INFO): Running loop #6 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn] Running Loop=6 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:53:35.990Z,1652810015.990 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:53:37.962Z,1652810017.962 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175336.00,A,3426.97058,N,11943.35830,W,0.078,127.56,170522,,,D*74 2022-05-17T17:53:37.964Z,1652810017.964 [NAL9602](INFO): GPS fix at 20220517T175336: (34.449510, -119.722638) 2022-05-17T17:53:37.973Z,1652810017.973 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:53:37.973Z,1652810017.973 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:53:45.795Z,1652810025.795 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220517T171801/Courier0019.lzma 2022-05-17T17:53:46.798Z,1652810026.798 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0019.lzma.bak 2022-05-17T17:53:46.798Z,1652810026.798 [DataOverHttps](INFO): SBD MOMSN=16798148 2022-05-17T17:54:02.959Z,1652810042.959 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220517T171801/Express0020.lzma 2022-05-17T17:54:03.962Z,1652810043.962 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0020.lzma.bak 2022-05-17T17:54:03.962Z,1652810043.962 [DataOverHttps](INFO): SBD MOMSN=16798151 2022-05-17T17:54:05.577Z,1652810045.577 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:54:05.577Z,1652810045.577 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:54:05.577Z,1652810045.577 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:54:08.397Z,1652810048.397 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-17T17:54:08.472Z,1652810048.472 [NAL9602](ERROR): received: +CSQ:0 OK983, 2, 0, 0, 0 OK 2022-05-17T17:56:08.060Z,1652810168.060 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+20.2,0000.0,1489.0,000 2022-05-17T17:58:40.764Z,1652810320.764 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-17T17:59:06.244Z,1652810346.244 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T17:59:06.244Z,1652810346.244 [Default:CheckIn:C.Wait] Stopped 2022-05-17T17:59:06.244Z,1652810346.244 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T17:59:06.244Z,1652810346.244 [Default:CheckIn:D] Running Loop=1 2022-05-17T17:59:06.629Z,1652810346.629 [Default:CheckIn:D] Stopped 2022-05-17T17:59:06.629Z,1652810346.629 [Default:CheckIn:E] Running Loop=1 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.982532 min 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn:E] Stopped 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn] Stopped 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn](INFO): Running loop #7 2022-05-17T17:59:07.038Z,1652810347.038 [Default:CheckIn] Running Loop=7 2022-05-17T17:59:07.039Z,1652810347.039 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T17:59:07.039Z,1652810347.039 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T17:59:09.051Z,1652810349.051 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175908.00,A,3426.97083,N,11943.35857,W,0.019,127.56,170522,,,D*73 2022-05-17T17:59:09.054Z,1652810349.054 [NAL9602](INFO): GPS fix at 20220517T175908: (34.449514, -119.722643) 2022-05-17T17:59:09.067Z,1652810349.067 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T17:59:09.067Z,1652810349.067 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T17:59:15.791Z,1652810355.791 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20220517T171801/Courier0022.lzma 2022-05-17T17:59:16.794Z,1652810356.794 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0022.lzma.bak 2022-05-17T17:59:16.794Z,1652810356.794 [DataOverHttps](INFO): SBD MOMSN=16798228 2022-05-17T17:59:32.900Z,1652810372.900 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220517T171801/Express0023.lzma 2022-05-17T17:59:33.902Z,1652810373.902 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0023.lzma.bak 2022-05-17T17:59:33.902Z,1652810373.902 [DataOverHttps](INFO): SBD MOMSN=16798231 2022-05-17T17:59:35.747Z,1652810375.747 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T17:59:35.747Z,1652810375.747 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T17:59:35.747Z,1652810375.747 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T17:59:41.767Z,1652810381.767 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-17T17:59:43.402Z,1652810383.402 [DVL_micro](ERROR): Failed to parse: 9.99,+9999.99,+9999.99,+9999.99 2022-05-17T18:03:02.987Z,1652810582.987 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2022-05-17T18:03:02.987Z,1652810582.987 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+20.3,0000.0,1489.0,,+00142,-00285,-00621,+00000,A 2022-05-17T18:03:15.887Z,1652810595.887 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2022-05-17T18:03:15.887Z,1652810595.887 [DropWeight] Hardware Fault, FailCount= 1 2022-05-17T18:03:15.887Z,1652810595.887 [DropWeight](ERROR): Hardware Fault 2022-05-17T18:03:15.968Z,1652810595.968 [CBIT](INFO): Critical error at 20220517T180315 2022-05-17T18:03:15.970Z,1652810595.970 [CBIT](ERROR): Hardware Fault in component: DropWeight 2022-05-17T18:03:15.971Z,1652810595.971 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2022-05-17T18:03:16.314Z,1652810596.314 [CBIT](INFO): Critical error at 20220517T180315 2022-05-17T18:04:36.315Z,1652810676.315 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T18:04:36.315Z,1652810676.315 [Default:CheckIn:C.Wait] Stopped 2022-05-17T18:04:36.315Z,1652810676.315 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T18:04:36.315Z,1652810676.315 [Default:CheckIn:D] Running Loop=1 2022-05-17T18:04:36.735Z,1652810676.735 [Default:CheckIn:D] Stopped 2022-05-17T18:04:36.735Z,1652810676.735 [Default:CheckIn:E] Running Loop=1 2022-05-17T18:04:37.117Z,1652810677.117 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.484306 min 2022-05-17T18:04:37.117Z,1652810677.117 [Default:CheckIn:E] Stopped 2022-05-17T18:04:37.117Z,1652810677.117 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T18:04:37.117Z,1652810677.117 [Default:CheckIn] Stopped 2022-05-17T18:04:37.117Z,1652810677.117 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T18:04:37.118Z,1652810677.118 [Default:CheckIn](INFO): Running loop #8 2022-05-17T18:04:37.118Z,1652810677.118 [Default:CheckIn] Running Loop=8 2022-05-17T18:04:37.118Z,1652810677.118 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T18:04:37.118Z,1652810677.118 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T18:04:39.137Z,1652810679.137 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180438.00,A,3426.97248,N,11943.35817,W,0.078,127.56,170522,,,D*71 2022-05-17T18:04:39.139Z,1652810679.139 [NAL9602](INFO): GPS fix at 20220517T180438: (34.449541, -119.722636) 2022-05-17T18:04:39.148Z,1652810679.148 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T18:04:39.148Z,1652810679.148 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T18:04:46.069Z,1652810686.069 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20220517T171801/Courier0025.lzma 2022-05-17T18:04:47.070Z,1652810687.070 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0025.lzma.bak 2022-05-17T18:04:47.070Z,1652810687.070 [DataOverHttps](INFO): SBD MOMSN=16798258 2022-05-17T18:05:05.983Z,1652810705.983 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20220517T171801/Express0026.lzma 2022-05-17T18:05:06.986Z,1652810706.986 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0026.lzma.bak 2022-05-17T18:05:06.986Z,1652810706.986 [DataOverHttps](INFO): SBD MOMSN=16798263 2022-05-17T18:05:09.538Z,1652810709.538 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T18:05:09.538Z,1652810709.538 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T18:05:09.539Z,1652810709.539 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T18:05:09.934Z,1652810709.934 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-17T18:05:10.012Z,1652810710.012 [NAL9602](ERROR): received: +CSQ:0 OK983, 2, 0, 0, 0 OK 2022-05-17T18:06:56.191Z,1652810816.191 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2022-05-17T18:06:56.191Z,1652810816.191 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,34,0000.0,1489.0,000 2022-05-17T18:09:41.858Z,1652810981.858 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-17T18:10:10.144Z,1652811010.144 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T18:10:10.144Z,1652811010.144 [Default:CheckIn:C.Wait] Stopped 2022-05-17T18:10:10.144Z,1652811010.144 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T18:10:10.144Z,1652811010.144 [Default:CheckIn:D] Running Loop=1 2022-05-17T18:10:10.545Z,1652811010.545 [Default:CheckIn:D] Stopped 2022-05-17T18:10:10.545Z,1652811010.545 [Default:CheckIn:E] Running Loop=1 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.047803 min 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn:E] Stopped 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn] Stopped 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn](INFO): Running loop #9 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn] Running Loop=9 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-17T18:10:10.965Z,1652811010.965 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-17T18:10:12.965Z,1652811012.965 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181012.00,A,3426.97400,N,11943.36073,W,0.369,127.56,170522,,,D*7C 2022-05-17T18:10:12.967Z,1652811012.967 [NAL9602](INFO): GPS fix at 20220517T181012: (34.449567, -119.722679) 2022-05-17T18:10:13.001Z,1652811013.001 [Default:CheckIn:Read_GPS] Stopped 2022-05-17T18:10:13.001Z,1652811013.001 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-17T18:10:20.715Z,1652811020.715 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220517T171801/Courier0028.lzma 2022-05-17T18:10:21.718Z,1652811021.718 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Courier0028.lzma.bak 2022-05-17T18:10:21.718Z,1652811021.718 [DataOverHttps](INFO): SBD MOMSN=16798310 2022-05-17T18:10:40.979Z,1652811040.979 [DataOverHttps](INFO): Sending 203 bytes from file Logs/20220517T171801/Express0029.lzma 2022-05-17T18:10:41.982Z,1652811041.982 [DataOverHttps](INFO): Moved sent file to Logs/20220517T171801/Express0029.lzma.bak 2022-05-17T18:10:41.982Z,1652811041.982 [DataOverHttps](INFO): SBD MOMSN=16798321 2022-05-17T18:10:44.212Z,1652811044.212 [Default:CheckIn:Read_Iridium] Stopped 2022-05-17T18:10:44.212Z,1652811044.212 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-17T18:10:44.212Z,1652811044.212 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-17T18:10:45.393Z,1652811045.393 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-17T18:15:36.977Z,1652811336.977 [CommandExec](IMPORTANT): got command strobe off 2022-05-17T18:15:36.978Z,1652811336.978 [CommandExec](IMPORTANT): Deactivating strobe 2022-05-17T18:15:44.763Z,1652811344.763 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-17T18:15:44.764Z,1652811344.764 [Default:CheckIn:C.Wait] Stopped 2022-05-17T18:15:44.764Z,1652811344.764 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-17T18:15:44.764Z,1652811344.764 [Default:CheckIn:D] Running Loop=1 2022-05-17T18:15:45.166Z,1652811345.166 [Default:CheckIn:D] Stopped 2022-05-17T18:15:45.166Z,1652811345.166 [Default:CheckIn:E]