2022-04-13T22:15:33.659Z,1649888133.659 [Supervisor](DEBUG): Initializing supervisor. 2022-04-13T22:15:33.664Z,1649888133.664 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2022-04-13T22:15:33.664Z,1649888133.664 [SyncHandler](INFO): Protected caller Thread ID is 5238 2022-04-13T22:15:33.665Z,1649888133.665 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2022-04-13T22:15:33.666Z,1649888133.666 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2022-04-13T22:15:33.666Z,1649888133.666 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5239 2022-04-13T22:15:33.670Z,1649888133.670 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2022-04-13T22:15:33.691Z,1649888133.691 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2022-04-13T22:15:33.692Z,1649888133.692 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2022-04-13T22:15:33.692Z,1649888133.692 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 5240 2022-04-13T22:15:33.696Z,1649888133.696 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2022-04-13T22:15:33.697Z,1649888133.697 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2022-04-13T22:15:33.698Z,1649888133.698 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5241 2022-04-13T22:15:33.700Z,1649888133.700 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2022-04-13T22:15:33.701Z,1649888133.701 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2022-04-13T22:15:33.701Z,1649888133.701 [logger ThreadHandler](INFO): Protected caller Thread ID is 5242 2022-04-13T22:15:33.705Z,1649888133.705 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2022-04-13T22:15:33.706Z,1649888133.706 [Supervisor](INFO): Looking for Config files in directory: Config/ 2022-04-13T22:15:33.707Z,1649888133.707 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2022-04-13T22:15:33.871Z,1649888133.871 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2022-04-13T22:15:33.871Z,1649888133.871 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2022-04-13T22:15:34.626Z,1649888134.626 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2022-04-13T22:15:34.627Z,1649888134.627 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2022-04-13T22:15:34.857Z,1649888134.857 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2022-04-13T22:15:34.859Z,1649888134.859 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2022-04-13T22:15:34.939Z,1649888134.939 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2022-04-13T22:15:35.065Z,1649888135.065 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2022-04-13T22:15:35.067Z,1649888135.067 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2022-04-13T22:15:35.150Z,1649888135.150 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2022-04-13T22:15:35.260Z,1649888135.260 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2022-04-13T22:15:35.261Z,1649888135.261 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2022-04-13T22:15:35.650Z,1649888135.650 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2022-04-13T22:15:35.652Z,1649888135.652 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2022-04-13T22:15:36.251Z,1649888136.251 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2022-04-13T22:15:36.251Z,1649888136.251 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2022-04-13T22:15:36.478Z,1649888136.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2022-04-13T22:15:36.479Z,1649888136.479 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2022-04-13T22:15:36.685Z,1649888136.685 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2022-04-13T22:15:36.686Z,1649888136.686 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2022-04-13T22:15:37.177Z,1649888137.177 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2022-04-13T22:15:37.179Z,1649888137.179 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2022-04-13T22:15:37.517Z,1649888137.517 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2022-04-13T22:15:37.847Z,1649888137.847 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2022-04-13T22:15:38.283Z,1649888138.283 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2022-04-13T22:15:38.314Z,1649888138.314 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2022-04-13T22:15:38.697Z,1649888138.697 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2022-04-13T22:15:38.699Z,1649888138.699 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2022-04-13T22:15:39.078Z,1649888139.078 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2022-04-13T22:15:39.080Z,1649888139.080 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/ 2022-04-13T22:15:39.081Z,1649888139.081 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg 2022-04-13T22:15:39.165Z,1649888139.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg 2022-04-13T22:15:39.329Z,1649888139.329 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg 2022-04-13T22:15:39.442Z,1649888139.442 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg 2022-04-13T22:15:39.529Z,1649888139.529 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg 2022-04-13T22:15:39.625Z,1649888139.625 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg 2022-04-13T22:15:39.821Z,1649888139.821 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg 2022-04-13T22:15:40.094Z,1649888140.094 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2022-04-13T22:15:40.095Z,1649888140.095 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg 2022-04-13T22:15:40.190Z,1649888140.190 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg 2022-04-13T22:15:40.290Z,1649888140.290 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg 2022-04-13T22:15:40.436Z,1649888140.436 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg 2022-04-13T22:15:40.538Z,1649888140.538 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/ 2022-04-13T22:15:40.539Z,1649888140.539 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2022-04-13T22:15:40.554Z,1649888140.554 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2022-04-13T22:15:40.682Z,1649888140.682 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2022-04-13T22:15:40.683Z,1649888140.683 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2022-04-13T22:15:40.754Z,1649888140.754 [VerticalControl](DEBUG): Construct VerticalControl. 2022-04-13T22:15:40.816Z,1649888140.816 [VerticalControl] Loaded 2022-04-13T22:15:40.816Z,1649888140.816 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2022-04-13T22:15:40.819Z,1649888140.819 [HorizontalControl](DEBUG): Construct HorizontalControl. 2022-04-13T22:15:40.859Z,1649888140.859 [HorizontalControl] Loaded 2022-04-13T22:15:40.860Z,1649888140.860 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2022-04-13T22:15:40.862Z,1649888140.862 [SpeedControl](DEBUG): Construct SpeedControl. 2022-04-13T22:15:40.865Z,1649888140.865 [SpeedControl] Loaded 2022-04-13T22:15:40.866Z,1649888140.866 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2022-04-13T22:15:40.868Z,1649888140.868 [LoopControl](DEBUG): Construct LoopControl. 2022-04-13T22:15:40.869Z,1649888140.869 [LoopControl] Loaded 2022-04-13T22:15:40.869Z,1649888140.869 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2022-04-13T22:15:40.870Z,1649888140.870 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2022-04-13T22:15:40.870Z,1649888140.870 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2022-04-13T22:15:40.946Z,1649888140.946 [DepthRateCalculator] Loaded 2022-04-13T22:15:40.946Z,1649888140.946 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2022-04-13T22:15:40.951Z,1649888140.951 [PitchRateCalculator] Loaded 2022-04-13T22:15:40.951Z,1649888140.951 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2022-04-13T22:15:40.962Z,1649888140.962 [SpeedCalculator] Loaded 2022-04-13T22:15:40.962Z,1649888140.962 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2022-04-13T22:15:40.967Z,1649888140.967 [YawRateCalculator] Loaded 2022-04-13T22:15:40.967Z,1649888140.967 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2022-04-13T22:15:40.985Z,1649888140.985 [ElevatorOffsetCalculator] Loaded 2022-04-13T22:15:40.985Z,1649888140.985 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2022-04-13T22:15:40.986Z,1649888140.986 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2022-04-13T22:15:40.987Z,1649888140.987 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2022-04-13T22:15:41.031Z,1649888141.031 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2022-04-13T22:15:41.031Z,1649888141.031 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2022-04-13T22:15:41.123Z,1649888141.123 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2022-04-13T22:15:41.124Z,1649888141.124 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2022-04-13T22:15:41.505Z,1649888141.505 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2022-04-13T22:15:41.506Z,1649888141.506 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2022-04-13T22:15:41.653Z,1649888141.653 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2022-04-13T22:15:41.654Z,1649888141.654 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2022-04-13T22:15:42.342Z,1649888142.342 [AHRS_M2] Loaded 2022-04-13T22:15:42.343Z,1649888142.343 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2022-04-13T22:15:42.612Z,1649888142.612 [BackseatComponent] Loaded 2022-04-13T22:15:42.613Z,1649888142.613 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2022-04-13T22:15:42.614Z,1649888142.614 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 4096B4E0 2022-04-13T22:15:42.614Z,1649888142.614 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 5325 2022-04-13T22:15:42.617Z,1649888142.617 [LcmUniversalReporter] Loaded 2022-04-13T22:15:42.617Z,1649888142.617 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2022-04-13T22:15:44.065Z,1649888144.065 [BPC1] Loaded 2022-04-13T22:15:44.066Z,1649888144.066 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2022-04-13T22:15:44.162Z,1649888144.162 [DataOverHttps] Loaded 2022-04-13T22:15:44.162Z,1649888144.162 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2022-04-13T22:15:44.163Z,1649888144.163 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4099B4E0 2022-04-13T22:15:44.163Z,1649888144.163 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5326 2022-04-13T22:15:44.184Z,1649888144.184 [Depth_Keller] Loaded 2022-04-13T22:15:44.184Z,1649888144.184 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2022-04-13T22:15:44.189Z,1649888144.189 [DropWeight] Loaded 2022-04-13T22:15:44.190Z,1649888144.190 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2022-04-13T22:15:44.253Z,1649888144.253 [NAL9602] Loaded 2022-04-13T22:15:44.253Z,1649888144.253 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2022-04-13T22:15:44.283Z,1649888144.283 [Onboard] Loaded 2022-04-13T22:15:44.283Z,1649888144.283 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2022-04-13T22:15:44.286Z,1649888144.286 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409CB4E0 2022-04-13T22:15:44.287Z,1649888144.287 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 5327 2022-04-13T22:15:44.299Z,1649888144.299 [Power24vConverter] Loaded 2022-04-13T22:15:44.300Z,1649888144.300 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2022-04-13T22:15:44.313Z,1649888144.313 [Radio_Surface] Loaded 2022-04-13T22:15:44.313Z,1649888144.313 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2022-04-13T22:15:44.314Z,1649888144.314 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409FB4E0 2022-04-13T22:15:44.314Z,1649888144.314 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5328 2022-04-13T22:15:44.359Z,1649888144.359 [RDI_Pathfinder] Loaded 2022-04-13T22:15:44.360Z,1649888144.360 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread. 2022-04-13T22:15:44.448Z,1649888144.448 [DAT] Loaded 2022-04-13T22:15:44.448Z,1649888144.448 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2022-04-13T22:15:44.449Z,1649888144.449 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40A2B4E0 2022-04-13T22:15:44.450Z,1649888144.450 [DAT ThreadHandler](INFO): Protected caller Thread ID is 5329 2022-04-13T22:15:44.450Z,1649888144.450 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2022-04-13T22:15:44.451Z,1649888144.451 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2022-04-13T22:15:44.593Z,1649888144.593 [DeadReckonUsingMultipleVelocitySources] Loaded 2022-04-13T22:15:44.593Z,1649888144.593 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2022-04-13T22:15:44.607Z,1649888144.607 [NavChart] Loaded 2022-04-13T22:15:44.607Z,1649888144.607 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2022-04-13T22:15:44.613Z,1649888144.613 [UniversalFixResidualReporter] Loaded 2022-04-13T22:15:44.613Z,1649888144.613 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2022-04-13T22:15:44.614Z,1649888144.614 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2022-04-13T22:15:44.615Z,1649888144.615 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2022-04-13T22:15:44.792Z,1649888144.792 [SBIT](DEBUG): Construct Startup Built In Test. 2022-04-13T22:15:44.802Z,1649888144.802 [SBIT] Loaded 2022-04-13T22:15:44.802Z,1649888144.802 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2022-04-13T22:15:44.805Z,1649888144.805 [IBIT](DEBUG): Construct Initiated Built In Test. 2022-04-13T22:15:44.819Z,1649888144.819 [IBIT] Loaded 2022-04-13T22:15:44.819Z,1649888144.819 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2022-04-13T22:15:44.825Z,1649888144.825 [CBIT](DEBUG): Construct Continuous Built In Test. 2022-04-13T22:15:44.933Z,1649888144.933 [CBIT] Loaded 2022-04-13T22:15:44.933Z,1649888144.933 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2022-04-13T22:15:44.934Z,1649888144.934 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2022-04-13T22:15:44.934Z,1649888144.934 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2022-04-13T22:15:45.094Z,1649888145.094 [BuoyancyServo] Loaded 2022-04-13T22:15:45.095Z,1649888145.095 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2022-04-13T22:15:45.115Z,1649888145.115 [ElevatorServo] Loaded 2022-04-13T22:15:45.116Z,1649888145.116 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2022-04-13T22:15:45.136Z,1649888145.136 [MassServo] Loaded 2022-04-13T22:15:45.137Z,1649888145.137 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2022-04-13T22:15:45.155Z,1649888145.155 [RudderServo] Loaded 2022-04-13T22:15:45.156Z,1649888145.156 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2022-04-13T22:15:45.174Z,1649888145.174 [ThrusterServo] Loaded 2022-04-13T22:15:45.175Z,1649888145.175 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2022-04-13T22:15:45.175Z,1649888145.175 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2022-04-13T22:15:45.176Z,1649888145.176 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2022-04-13T22:15:45.194Z,1649888145.194 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2022-04-13T22:15:45.195Z,1649888145.195 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2022-04-13T22:15:45.425Z,1649888145.425 [CTD_Seabird] Loaded 2022-04-13T22:15:45.425Z,1649888145.425 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2022-04-13T22:15:45.426Z,1649888145.426 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B754E0 2022-04-13T22:15:45.427Z,1649888145.427 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 5330 2022-04-13T22:15:45.447Z,1649888145.447 [PAR_Licor] Loaded 2022-04-13T22:15:45.447Z,1649888145.447 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2022-04-13T22:15:45.480Z,1649888145.480 [WetLabsBB2FL] Loaded 2022-04-13T22:15:45.480Z,1649888145.480 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2022-04-13T22:15:45.481Z,1649888145.481 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40BA54E0 2022-04-13T22:15:45.482Z,1649888145.482 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5331 2022-04-13T22:15:45.503Z,1649888145.503 [WetLabsUBAT] Loaded 2022-04-13T22:15:45.503Z,1649888145.503 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread. 2022-04-13T22:15:45.505Z,1649888145.505 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40BD54E0 2022-04-13T22:15:45.505Z,1649888145.505 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 5332 2022-04-13T22:15:45.505Z,1649888145.505 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2022-04-13T22:15:45.512Z,1649888145.512 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2022-04-13T22:15:45.515Z,1649888145.515 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2022-04-13T22:15:45.526Z,1649888145.526 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2022-04-13T22:15:45.527Z,1649888145.527 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C054E0 2022-04-13T22:15:45.527Z,1649888145.527 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5333 2022-04-13T22:15:45.532Z,1649888145.532 [Supervisor](INFO): Main Thread ID is 5237 2022-04-13T22:15:45.532Z,1649888145.532 [Supervisor](DEBUG): Running supervisor. 2022-04-13T22:15:45.533Z,1649888145.533 [CommandExec ThreadHandler](INFO): Handler Thread ID is 5334 2022-04-13T22:15:45.533Z,1649888145.533 [CommandExec](INFO): Initializing the command executive. 2022-04-13T22:15:45.537Z,1649888145.537 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5335 2022-04-13T22:15:45.539Z,1649888145.539 [controlThread ThreadHandler](INFO): Handler Thread ID is 5336 2022-04-13T22:15:45.540Z,1649888145.540 [controlThread](DEBUG): Initializing ControlThread 2022-04-13T22:15:45.541Z,1649888145.541 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2022-04-13T22:15:45.542Z,1649888145.542 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2022-04-13T22:15:45.543Z,1649888145.543 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2022-04-13T22:15:45.543Z,1649888145.543 [LoopControl](DEBUG): Initialize LoopControlComponent. 2022-04-13T22:15:45.544Z,1649888145.544 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2022-04-13T22:15:45.545Z,1649888145.545 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2022-04-13T22:15:45.545Z,1649888145.545 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2022-04-13T22:15:45.545Z,1649888145.545 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2022-04-13T22:15:45.546Z,1649888145.546 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2022-04-13T22:15:45.550Z,1649888145.550 [NavChart](DEBUG): Initialize NavChart Navigation. 2022-04-13T22:15:45.551Z,1649888145.551 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2022-04-13T22:15:45.551Z,1649888145.551 [SBIT](INFO): Initialize SBIT Component. 2022-04-13T22:15:45.551Z,1649888145.551 [SBIT](IMPORTANT): git: 2022-03-28 2022-04-13T22:15:45.552Z,1649888145.552 [SBIT](INFO): git hash: 0e7e0e7b40c8d568e57eb54527c6c47c298abae2 2022-04-13T22:15:45.552Z,1649888145.552 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2022-04-13T22:15:45.553Z,1649888145.553 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021 2022-04-13T22:15:45.554Z,1649888145.554 [SBIT](INFO): Beginning SBIT in 42.000000 seconds. 2022-04-13T22:15:45.555Z,1649888145.555 [IBIT](INFO): Initialize IBIT Component. 2022-04-13T22:15:45.556Z,1649888145.556 [CBIT](DEBUG): Initialize CBIT Component. 2022-04-13T22:15:45.557Z,1649888145.557 [logger ThreadHandler](INFO): Handler Thread ID is 5337 2022-04-13T22:15:45.568Z,1649888145.568 [CBIT](DEBUG): Initialized mux pins. 2022-04-13T22:15:45.568Z,1649888145.568 [CBIT](DEBUG): Initializing the watchdog timer. 2022-04-13T22:15:45.576Z,1649888145.576 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 5338 2022-04-13T22:15:45.588Z,1649888145.588 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5339 2022-04-13T22:15:45.589Z,1649888145.589 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2022-04-13T22:15:45.592Z,1649888145.592 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2022-04-13T22:15:45.593Z,1649888145.593 [CBIT](DEBUG): Initializing heartbeat. 2022-04-13T22:15:45.600Z,1649888145.600 [Onboard ThreadHandler](INFO): Handler Thread ID is 5340 2022-04-13T22:15:45.617Z,1649888145.617 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5341 2022-04-13T22:15:45.636Z,1649888145.636 [DAT ThreadHandler](INFO): Handler Thread ID is 5342 2022-04-13T22:15:45.637Z,1649888145.637 [DAT](INFO): Powering up 2022-04-13T22:15:45.637Z,1649888145.637 [DAT](DEBUG): Initializing DAT. 2022-04-13T22:15:45.642Z,1649888145.642 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 5344 2022-04-13T22:15:45.642Z,1649888145.642 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2022-04-13T22:15:45.649Z,1649888145.649 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5346 2022-04-13T22:15:45.653Z,1649888145.653 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 5348 2022-04-13T22:15:45.654Z,1649888145.654 [WetLabsBB2FL](INFO): Powering up 2022-04-13T22:15:45.656Z,1649888145.656 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5350 2022-04-13T22:15:45.658Z,1649888145.658 [WetLabsUBAT](INFO): Powering up 2022-04-13T22:15:45.664Z,1649888145.664 [CBIT](DEBUG): Deactivating GF circuits. 2022-04-13T22:15:45.664Z,1649888145.664 [CBIT](DEBUG): Deactivating emergency mode. 2022-04-13T22:15:45.666Z,1649888145.667 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2022-04-13T22:15:45.667Z,1649888145.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2022-04-13T22:15:45.667Z,1649888145.667 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2022-04-13T22:15:45.667Z,1649888145.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2022-04-13T22:15:45.667Z,1649888145.667 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2022-04-13T22:15:45.667Z,1649888145.667 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2022-04-13T22:15:45.668Z,1649888145.668 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2022-04-13T22:15:45.668Z,1649888145.668 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2022-04-13T22:15:45.668Z,1649888145.668 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2022-04-13T22:15:45.668Z,1649888145.668 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2022-04-13T22:15:45.669Z,1649888145.669 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2022-04-13T22:15:45.700Z,1649888145.700 [CBIT](DEBUG): Backplane powered. 2022-04-13T22:15:45.705Z,1649888145.705 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml 2022-04-13T22:15:45.749Z,1649888145.749 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2022-04-13T22:15:45.776Z,1649888145.776 [MissionManager](DEBUG): 2022-04-13T22:15:45.777Z,1649888145.777 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml 2022-04-13T22:15:45.843Z,1649888145.843 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2022-04-13T22:15:45.864Z,1649888145.864 [Default:A.Wait](DEBUG): Construct Wait. 2022-04-13T22:15:45.866Z,1649888145.866 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2022-04-13T22:15:45.886Z,1649888145.886 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2022-04-13T22:15:45.901Z,1649888145.901 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2022-04-13T22:15:45.933Z,1649888145.933 [Default:E.Execute](DEBUG): Construct Execute. 2022-04-13T22:15:45.937Z,1649888145.937 [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-04-13T22:15:45.941Z,1649888145.941 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,RDI_Pathfinder,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-04-13T22:15:45.960Z,1649888145.960 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2022-04-13T22:15:46.024Z,1649888146.024 [Radio_Surface](INFO): Powering up 2022-04-13T22:15:46.027Z,1649888146.027 [Power24vConverter](INFO): Powering up. 2022-04-13T22:15:46.114Z,1649888146.114 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:46.124Z,1649888146.124 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2022-04-13T22:15:46.125Z,1649888146.125 [ElevatorServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:46.132Z,1649888146.132 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2022-04-13T22:15:46.134Z,1649888146.134 [MassServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:46.141Z,1649888146.141 [MassServo](DEBUG): Initializing MassServo. 2022-04-13T22:15:46.142Z,1649888146.142 [RudderServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:46.148Z,1649888146.148 [RudderServo](DEBUG): Initializing RudderServo. 2022-04-13T22:15:46.149Z,1649888146.149 [ThrusterServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:46.156Z,1649888146.156 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2022-04-13T22:15:46.373Z,1649888146.373 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2022-04-13T22:15:46.373Z,1649888146.373 [DropWeight] Hardware Fault, FailCount= 1 2022-04-13T22:15:46.373Z,1649888146.373 [DropWeight](ERROR): Hardware Fault 2022-04-13T22:15:46.398Z,1649888146.398 [CommandExec](FAULT): Scheduling is paused 2022-04-13T22:15:46.399Z,1649888146.399 [CBIT](INFO): Critical error at 20220413T221546 2022-04-13T22:15:46.399Z,1649888146.399 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2022-04-13T22:15:46.409Z,1649888146.409 [CBIT](ERROR): Hardware Fault in component: DropWeight 2022-04-13T22:15:46.410Z,1649888146.410 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2022-04-13T22:15:47.092Z,1649888147.092 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2022-04-13T22:15:47.092Z,1649888147.092 [RudderServo](FAULT): Rudder failed to initialize 2022-04-13T22:15:47.092Z,1649888147.092 [RudderServo] Communications Fault, FailCount= 1 2022-04-13T22:15:47.092Z,1649888147.092 [RudderServo](ERROR): Communications Fault 2022-04-13T22:15:47.190Z,1649888147.190 [CBIT](INFO): Critical error at 20220413T221546 2022-04-13T22:15:47.193Z,1649888147.193 [CBIT](ERROR): Communications Fault in component: RudderServo 2022-04-13T22:15:47.410Z,1649888147.410 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2022-04-13T22:15:47.411Z,1649888147.411 [RudderServo](INFO): Powering down 2022-04-13T22:15:48.054Z,1649888148.054 [RudderServo](DEBUG): Initializing EZServoServo. 2022-04-13T22:15:48.173Z,1649888148.173 [RudderServo](DEBUG): Initializing RudderServo. 2022-04-13T22:15:48.177Z,1649888148.177 [CBIT](INFO): Clearing failed state for component RudderServo 2022-04-13T22:15:48.177Z,1649888148.177 [RudderServo] No Fault, FailCount= 1 2022-04-13T22:15:48.264Z,1649888148.264 [WetLabsBB2FL](INFO): Powering down 2022-04-13T22:15:54.920Z,1649888154.920 [WetLabsUBAT](INFO): Powering down 2022-04-13T22:15:58.546Z,1649888158.546 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004735 2022-04-13T22:16:14.273Z,1649888174.273 [NAL9602](INFO): Powering up NAL9602 2022-04-13T22:16:25.177Z,1649888185.177 [NAL9602](INFO): NAL9602 initialized 2022-04-13T22:16:28.077Z,1649888188.077 [SBIT](IMPORTANT): Beginning Startup BIT 2022-04-13T22:16:28.089Z,1649888188.089 [CBIT](IMPORTANT): Beginning ground fault scan 2022-04-13T22:16:39.008Z,1649888199.008 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.000469 CHAN A1 (24V): -0.000240 CHAN A2 (12V): -0.006699 CHAN A3 (5V): -0.001806 CHAN B0 (3.3V): 0.000193 CHAN B1 (3.15aV): -0.000016 CHAN B2 (3.15bV): -0.000107 CHAN B3 (GND): 0.001941 OPEN: 0.004950 Full Scale: +/- 1 mA 2022-04-13T22:16:45.893Z,1649888205.893 [DAT](FAULT): failed to initialize, no bytes available on serial interface 2022-04-13T22:16:45.893Z,1649888205.893 [DAT] Communications Fault, FailCount= 1 2022-04-13T22:16:45.893Z,1649888205.893 [DAT](ERROR): Communications Fault 2022-04-13T22:16:45.922Z,1649888205.922 [CBIT](ERROR): Communications Fault in component: DAT 2022-04-13T22:16:46.296Z,1649888206.296 [DAT](INFO): Powering down 2022-04-13T22:16:47.516Z,1649888207.516 [CBIT](INFO): Clearing failed state for component DAT 2022-04-13T22:16:47.517Z,1649888207.517 [DAT] No Fault, FailCount= 1 2022-04-13T22:16:49.340Z,1649888209.340 [DAT](INFO): Powering up 2022-04-13T22:16:49.340Z,1649888209.340 [DAT](DEBUG): Initializing DAT. 2022-04-13T22:17:03.959Z,1649888223.959 [DAT](INFO): commRate: 800 2022-04-13T22:17:06.024Z,1649888226.024 [DAT](INFO): entering command mode 2022-04-13T22:17:06.225Z,1649888226.225 [DAT](INFO): setting verbose to 3 2022-04-13T22:17:06.477Z,1649888226.477 [DAT](INFO): set verbose to 3 2022-04-13T22:17:06.478Z,1649888226.478 [DAT](INFO): setting DatVerbose to 27440 2022-04-13T22:17:06.729Z,1649888226.729 [DAT](INFO): set DatVerbose to 27440 2022-04-13T22:17:06.730Z,1649888226.730 [DAT](INFO): setting transmit power to 8 2022-04-13T22:17:06.981Z,1649888226.981 [DAT](INFO): set transmit power to 8 2022-04-13T22:17:06.982Z,1649888226.982 [DAT](INFO): setting local address to 9 2022-04-13T22:17:07.233Z,1649888227.233 [DAT](INFO): set local address to 9 2022-04-13T22:17:07.234Z,1649888227.234 [DAT](INFO): Setting time to: 22:17:7 And date to:4/13/2022 2022-04-13T22:17:07.485Z,1649888227.485 [DAT](INFO): Local DAT time set to Wed Apr 13, 2022 22:17:07 2022-04-13T22:17:21.785Z,1649888241.785 [SBIT](IMPORTANT): SBIT PASSED 2022-04-13T22:17:21.785Z,1649888241.785 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=2 count; 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): CBIT.gf24Offset=143 microampere; 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): DAT.baud=115200 bit_per_second; 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool; 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): Express linearApproximation WetLabsUBAT.flow_rate 0.300000 liter_per_second; 2022-04-13T22:17:21.786Z,1649888241.786 [SBIT](IMPORTANT): IBIT.batteryCapacityThreshold=24 ampere_hour; 2022-04-13T22:17:21.787Z,1649888241.787 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=13 volt; 2022-04-13T22:17:21.787Z,1649888241.787 [SBIT](IMPORTANT): Power24vConverter.simulateHardware=0 bool; 2022-04-13T22:17:21.787Z,1649888241.787 [SBIT](IMPORTANT): RDI_Pathfinder.loadAtStartup=1 bool; 2022-04-13T22:17:21.787Z,1649888241.787 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=300.651033 cubic_centimeter; 2022-04-13T22:17:21.787Z,1649888241.787 [SBIT](IMPORTANT): VerticalControl.massDefault=5.530755 millimeter; 2022-04-13T22:17:22.162Z,1649888242.162 [MissionManager](IMPORTANT): Started mission Startup 2022-04-13T22:17:22.163Z,1649888242.163 [Startup] Running Loop=1 2022-04-13T22:17:22.163Z,1649888242.163 [Startup](DEBUG): Aggregate::initialize Startup 2022-04-13T22:17:22.163Z,1649888242.163 [Startup:A.GoToSurface] Running Loop=1 2022-04-13T22:17:22.163Z,1649888242.163 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-04-13T22:17:22.180Z,1649888242.180 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-04-13T22:17:22.181Z,1649888242.181 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-04-13T22:17:22.181Z,1649888242.181 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-04-13T22:17:22.181Z,1649888242.181 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-04-13T22:17:22.182Z,1649888242.182 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-04-13T22:17:22.183Z,1649888242.183 [Startup:StartupSatComms] Running Loop=1 2022-04-13T22:17:22.183Z,1649888242.183 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2022-04-13T22:17:22.183Z,1649888242.183 [Startup:StartupSatComms:A] Running Loop=1 2022-04-13T22:17:22.562Z,1649888242.562 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2022-04-13T22:18:22.354Z,1649888302.354 [Startup:StartupSatComms:A](INFO): Timed out from 2022-04-13T22:17:22.2Z 2022-04-13T22:18:22.354Z,1649888302.354 [Startup:StartupSatComms:A] Stopped 2022-04-13T22:18:22.354Z,1649888302.354 [Startup:StartupSatComms:B] Running Loop=1 2022-04-13T22:18:22.757Z,1649888302.757 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-04-13T22:18:30.048Z,1649888310.048 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20220402T011830/Courier0018.lzma 2022-04-13T22:18:31.050Z,1649888311.050 [DataOverHttps](INFO): Moved sent file to Logs/20220402T011830/Courier0018.lzma.bak 2022-04-13T22:18:31.050Z,1649888311.050 [DataOverHttps](INFO): SBD MOMSN=16644659 2022-04-13T22:18:45.831Z,1649888325.831 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2022-04-13T22:18:45.831Z,1649888325.831 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-04-13T22:18:45.871Z,1649888325.871 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-04-13T22:18:46.203Z,1649888326.203 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-04-13T22:18:46.203Z,1649888326.203 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2022-04-13T22:18:46.947Z,1649888326.947 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220402T011830/Courier0021.lzma 2022-04-13T22:18:47.950Z,1649888327.950 [DataOverHttps](INFO): Moved sent file to Logs/20220402T011830/Courier0021.lzma.bak 2022-04-13T22:18:47.950Z,1649888327.950 [DataOverHttps](INFO): SBD MOMSN=16644662 2022-04-13T22:19:03.995Z,1649888343.995 [DataOverHttps](INFO): Sending 244 bytes from file Logs/20220413T221533/Courier0000.lzma 2022-04-13T22:19:04.994Z,1649888344.994 [DataOverHttps](INFO): Moved sent file to Logs/20220413T221533/Courier0000.lzma.bak 2022-04-13T22:19:04.994Z,1649888344.994 [DataOverHttps](INFO): SBD MOMSN=16644664 2022-04-13T22:19:20.939Z,1649888360.939 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20220402T011830/Express0019.lzma 2022-04-13T22:19:21.942Z,1649888361.942 [DataOverHttps](INFO): Moved sent file to Logs/20220402T011830/Express0019.lzma.bak 2022-04-13T22:19:21.942Z,1649888361.942 [DataOverHttps](INFO): SBD MOMSN=16644669 2022-04-13T22:19:22.554Z,1649888362.554 [Startup:StartupSatComms:B](INFO): Timed out from 2022-04-13T22:18:22.4Z 2022-04-13T22:19:22.554Z,1649888362.554 [Startup:StartupSatComms:B] Stopped 2022-04-13T22:19:22.554Z,1649888362.554 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2022-04-13T22:19:22.554Z,1649888362.554 [Startup:StartupSatComms] Stopped 2022-04-13T22:19:22.554Z,1649888362.554 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2022-04-13T22:19:22.555Z,1649888362.555 [Startup](INFO): Completed Startup 2022-04-13T22:19:22.555Z,1649888362.555 [MissionManager](INFO): Startup is completed. 2022-04-13T22:19:22.556Z,1649888362.556 [MissionManager](INFO): Uninitializing Mission Startup 2022-04-13T22:19:22.556Z,1649888362.556 [Startup] Stopped 2022-04-13T22:19:22.556Z,1649888362.556 [Startup](DEBUG): Aggregate::uninitialize Startup 2022-04-13T22:19:22.556Z,1649888362.556 [Startup:A.GoToSurface] Stopped 2022-04-13T22:19:22.556Z,1649888362.556 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-04-13T22:19:23.016Z,1649888363.016 [MissionManager](IMPORTANT): Started mission Default 2022-04-13T22:19:23.016Z,1649888363.016 [Default] Running Loop=1 2022-04-13T22:19:23.017Z,1649888363.017 [Default](DEBUG): Aggregate::initialize Default 2022-04-13T22:19:23.017Z,1649888363.017 [Default:B.GoToSurface] Running Loop=1 2022-04-13T22:19:23.017Z,1649888363.017 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-04-13T22:19:23.017Z,1649888363.017 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-04-13T22:19:23.017Z,1649888363.017 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-04-13T22:19:23.018Z,1649888363.018 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-04-13T22:19:23.018Z,1649888363.018 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-04-13T22:19:23.018Z,1649888363.018 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-04-13T22:19:23.018Z,1649888363.018 [Default:A.Wait] Running Loop=1 2022-04-13T22:19:23.019Z,1649888363.019 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-04-13T22:19:36.314Z,1649888376.314 [Default:A.Wait](INFO): Done Waiting. 2022-04-13T22:19:36.314Z,1649888376.314 [Default:A.Wait] Stopped 2022-04-13T22:19:36.314Z,1649888376.314 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-04-13T22:19:36.770Z,1649888376.770 [Default:CheckIn] Running Loop=1 2022-04-13T22:19:36.771Z,1649888376.771 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-04-13T22:19:36.771Z,1649888376.771 [Default:CheckIn:Read_GPS] Running Loop=1 2022-04-13T22:19:37.164Z,1649888377.164 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-04-13T22:20:57.703Z,1649888457.703 [CommandExec](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:20:57.703Z,1649888457.703 [MissionManager](INFO): Loading Mission from file: ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:20:57.738Z,1649888457.738 [MissionManager](DEBUG): 2022-04-13T22:20:57.740Z,1649888457.740 [CommandExec](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:20:57.935Z,1649888457.935 [Default] Stopped 2022-04-13T22:20:57.935Z,1649888457.935 [Default](DEBUG): Aggregate::uninitialize Default 2022-04-13T22:20:57.935Z,1649888457.935 [Default:B.GoToSurface] Stopped 2022-04-13T22:20:57.935Z,1649888457.935 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-04-13T22:20:57.944Z,1649888457.944 [Default:CheckIn] Stopped 2022-04-13T22:20:57.944Z,1649888457.944 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-04-13T22:20:57.944Z,1649888457.944 [Default:CheckIn:Read_GPS] Stopped 2022-04-13T22:20:57.944Z,1649888457.944 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2022-04-13T22:20:57.944Z,1649888457.944 [senddata_direct_test] Running Loop=1 2022-04-13T22:20:57.945Z,1649888457.945 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2022-04-13T22:20:57.945Z,1649888457.945 [senddata_direct_test:A] Running Loop=1 2022-04-13T22:20:57.945Z,1649888457.945 [senddata_direct_test:A](INFO): Queuing up send data for Onboard.Pressure with destination: modem:1:_.pressure 2022-04-13T22:20:57.946Z,1649888457.946 [senddata_direct_test:A] Stopped 2022-04-13T22:20:57.946Z,1649888457.946 [senddata_direct_test:B] Running Loop=1 2022-04-13T22:20:58.295Z,1649888458.295 [senddata_direct_test:B](INFO): Queuing up send data for Onboard.Temperature with destination: modem:1:_.temperature 2022-04-13T22:20:58.295Z,1649888458.295 [senddata_direct_test:B] Stopped 2022-04-13T22:20:58.295Z,1649888458.295 [senddata_direct_test:C] Running Loop=1 2022-04-13T22:20:58.725Z,1649888458.725 [senddata_direct_test:C](INFO): Queuing up send data for Onboard.Humidity with destination: modem:1:_.humidity 2022-04-13T22:20:58.725Z,1649888458.725 [senddata_direct_test:C] Stopped 2022-04-13T22:20:58.725Z,1649888458.725 [senddata_direct_test](INFO): Completed senddata_direct_test 2022-04-13T22:20:58.725Z,1649888458.725 [MissionManager](INFO): senddata_direct_test is completed. 2022-04-13T22:20:58.725Z,1649888458.725 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2022-04-13T22:20:58.726Z,1649888458.726 [senddata_direct_test] Stopped 2022-04-13T22:20:58.726Z,1649888458.726 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2022-04-13T22:20:59.134Z,1649888459.134 [MissionManager](IMPORTANT): Started mission Default 2022-04-13T22:20:59.134Z,1649888459.134 [Default] Running Loop=1 2022-04-13T22:20:59.134Z,1649888459.134 [Default](DEBUG): Aggregate::initialize Default 2022-04-13T22:20:59.135Z,1649888459.135 [Default:B.GoToSurface] Running Loop=1 2022-04-13T22:20:59.135Z,1649888459.135 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-04-13T22:20:59.135Z,1649888459.135 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-04-13T22:20:59.135Z,1649888459.135 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-04-13T22:20:59.136Z,1649888459.136 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-04-13T22:20:59.136Z,1649888459.136 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-04-13T22:20:59.137Z,1649888459.137 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-04-13T22:20:59.137Z,1649888459.137 [Default:A.Wait] Running Loop=1 2022-04-13T22:20:59.137Z,1649888459.137 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-04-13T22:21:09.786Z,1649888469.786 [CommandExec](IMPORTANT): got command get DAT.loadAtStartup 2022-04-13T22:21:09.787Z,1649888469.787 [CommandExec](IMPORTANT): DAT.loadAtStartup 1 bool 2022-04-13T22:21:12.462Z,1649888472.462 [Default:A.Wait](INFO): Done Waiting. 2022-04-13T22:21:12.462Z,1649888472.462 [Default:A.Wait] Stopped 2022-04-13T22:21:12.462Z,1649888472.462 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-04-13T22:21:12.854Z,1649888472.854 [Default:CheckIn] Running Loop=1 2022-04-13T22:21:12.854Z,1649888472.854 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-04-13T22:21:12.854Z,1649888472.854 [Default:CheckIn:Read_GPS] Running Loop=1 2022-04-13T22:21:25.270Z,1649888485.270 [CommandExec](IMPORTANT): got command get DAT.simulateHardware 2022-04-13T22:21:25.270Z,1649888485.270 [CommandExec](IMPORTANT): DAT.simulateHardware 0 bool 2022-04-13T22:21:28.189Z,1649888488.189 [CommandExec](IMPORTANT): got command fileExec 2022-04-13T22:21:28.189Z,1649888488.189 [CommandExec](FAULT): Incomplete syntax. Try: help fileExec 2022-04-13T22:21:28.191Z,1649888488.191 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-04-13T22:21:30.164Z,1649888490.164 [CommandExec](IMPORTANT): got command failComponent 2022-04-13T22:21:30.165Z,1649888490.165 [CommandExec](IMPORTANT): Failed components: 2022-04-13T22:21:30.165Z,1649888490.165 [CommandExec](IMPORTANT): DropWeight: Hardware Fault 2022-04-13T22:21:46.773Z,1649888506.773 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2022-04-13T22:21:46.773Z,1649888506.773 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-04-13T22:21:46.801Z,1649888506.801 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-04-13T22:21:47.190Z,1649888507.190 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-04-13T22:21:47.190Z,1649888507.190 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2022-04-13T22:21:49.128Z,1649888509.128 [CommandExec](IMPORTANT): got command configSet DAT.surfaceThreshold 0 meter persist 2022-04-13T22:21:53.930Z,1649888513.930 [CommandExec](IMPORTANT): got command failComponent hardware DAT 2022-04-13T22:21:53.930Z,1649888513.930 [DAT] Hardware Fault, FailCount= 2 2022-04-13T22:21:53.930Z,1649888513.930 [DAT](ERROR): Hardware Fault 2022-04-13T22:21:53.930Z,1649888513.930 [CommandExec](IMPORTANT): DAT failureMode is Hardware Fault 2022-04-13T22:21:54.094Z,1649888514.094 [CBIT](ERROR): Hardware Fault in component: DAT 2022-04-13T22:21:54.176Z,1649888514.176 [DAT](INFO): Powering down 2022-04-13T22:21:55.269Z,1649888515.269 [CBIT](INFO): Clearing failed state for component DAT 2022-04-13T22:21:55.269Z,1649888515.269 [DAT] No Fault, FailCount= 2 2022-04-13T22:21:57.232Z,1649888517.232 [DAT](INFO): Powering up 2022-04-13T22:21:57.232Z,1649888517.232 [DAT](DEBUG): Initializing DAT. 2022-04-13T22:22:04.634Z,1649888524.634 [CommandExec](IMPORTANT): got command get DAT.surfaceThreshold 2022-04-13T22:22:04.635Z,1649888524.635 [CommandExec](IMPORTANT): DAT.surfaceThreshold 0.000000 m 2022-04-13T22:22:07.244Z,1649888527.244 [CommandExec](IMPORTANT): got command get depth 2022-04-13T22:22:07.245Z,1649888527.245 [CommandExec](IMPORTANT): depth -0.146160 m 2022-04-13T22:22:11.850Z,1649888531.850 [DAT](INFO): commRate: 800 2022-04-13T22:22:13.916Z,1649888533.916 [DAT](INFO): entering command mode 2022-04-13T22:22:14.117Z,1649888534.117 [DAT](INFO): setting verbose to 3 2022-04-13T22:22:14.369Z,1649888534.369 [DAT](INFO): set verbose to 3 2022-04-13T22:22:14.370Z,1649888534.370 [DAT](INFO): setting DatVerbose to 27440 2022-04-13T22:22:14.621Z,1649888534.621 [DAT](INFO): set DatVerbose to 27440 2022-04-13T22:22:14.621Z,1649888534.621 [DAT](INFO): setting transmit power to 8 2022-04-13T22:22:14.873Z,1649888534.873 [DAT](INFO): set transmit power to 8 2022-04-13T22:22:14.874Z,1649888534.874 [DAT](INFO): setting local address to 9 2022-04-13T22:22:15.125Z,1649888535.125 [DAT](INFO): set local address to 9 2022-04-13T22:22:15.125Z,1649888535.125 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:15.376Z,1649888535.376 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:15.628Z,1649888535.628 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:15.747Z,1649888535.747 [CommandExec](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.1 meter 2022-04-13T22:22:15.751Z,1649888535.751 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread. 2022-04-13T22:22:15.880Z,1649888535.880 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:15.946Z,1649888535.946 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,RDI_Pathfinder,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-04-13T22:22:16.132Z,1649888536.132 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:16.384Z,1649888536.384 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:16.636Z,1649888536.636 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:16.888Z,1649888536.888 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:17.140Z,1649888537.140 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:17.392Z,1649888537.392 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:17.644Z,1649888537.644 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:17.896Z,1649888537.896 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:18.148Z,1649888538.148 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:18.400Z,1649888538.400 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:18.652Z,1649888538.652 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:18.904Z,1649888538.904 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:19.156Z,1649888539.156 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:19.408Z,1649888539.408 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:19.660Z,1649888539.660 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:19.912Z,1649888539.912 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:20.164Z,1649888540.164 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:20.416Z,1649888540.416 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:20.668Z,1649888540.668 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:20.920Z,1649888540.920 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:21.172Z,1649888541.172 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:21.424Z,1649888541.424 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:21.676Z,1649888541.676 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:21.928Z,1649888541.928 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:22.182Z,1649888542.182 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:22.432Z,1649888542.432 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:22.684Z,1649888542.684 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:22.936Z,1649888542.936 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:23.192Z,1649888543.192 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:23.444Z,1649888543.444 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:23.699Z,1649888543.699 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:23.952Z,1649888543.952 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:24.204Z,1649888544.204 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:24.456Z,1649888544.456 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:24.709Z,1649888544.709 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:24.960Z,1649888544.960 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:25.212Z,1649888545.212 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:25.464Z,1649888545.464 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:25.716Z,1649888545.716 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:25.968Z,1649888545.968 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:26.220Z,1649888546.220 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:26.472Z,1649888546.472 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:26.724Z,1649888546.724 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:26.976Z,1649888546.976 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:27.228Z,1649888547.228 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:27.480Z,1649888547.480 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:27.752Z,1649888547.752 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:28.004Z,1649888548.004 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:28.256Z,1649888548.256 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:28.508Z,1649888548.508 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:28.761Z,1649888548.761 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:29.012Z,1649888549.012 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:29.264Z,1649888549.264 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:29.346Z,1649888549.346 [CommandExec](IMPORTANT): got command run ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:22:29.346Z,1649888549.346 [MissionManager](INFO): Loading Mission from file: ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:22:29.360Z,1649888549.360 [MissionManager](DEBUG): 2022-04-13T22:22:29.362Z,1649888549.362 [CommandExec](IMPORTANT): Running ./Missions/Demo/senddata_direct_test.xml 2022-04-13T22:22:29.516Z,1649888549.516 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:29.655Z,1649888549.655 [Default] Stopped 2022-04-13T22:22:29.655Z,1649888549.655 [Default](DEBUG): Aggregate::uninitialize Default 2022-04-13T22:22:29.655Z,1649888549.655 [Default:B.GoToSurface] Stopped 2022-04-13T22:22:29.655Z,1649888549.655 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-04-13T22:22:29.655Z,1649888549.655 [Default:CheckIn] Stopped 2022-04-13T22:22:29.655Z,1649888549.655 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-04-13T22:22:29.668Z,1649888549.668 [Default:CheckIn:Read_GPS] Stopped 2022-04-13T22:22:29.668Z,1649888549.668 [MissionManager](IMPORTANT): Started mission senddata_direct_test 2022-04-13T22:22:29.668Z,1649888549.668 [senddata_direct_test] Running Loop=1 2022-04-13T22:22:29.668Z,1649888549.668 [senddata_direct_test](DEBUG): Aggregate::initialize senddata_direct_test 2022-04-13T22:22:29.669Z,1649888549.669 [senddata_direct_test:A] Running Loop=1 2022-04-13T22:22:29.669Z,1649888549.669 [senddata_direct_test:A](INFO): Queuing up send data for Onboard.Pressure with destination: modem:1:_.pressure 2022-04-13T22:22:29.670Z,1649888549.670 [senddata_direct_test:A] Stopped 2022-04-13T22:22:29.670Z,1649888549.670 [senddata_direct_test:B] Running Loop=1 2022-04-13T22:22:29.768Z,1649888549.768 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:30.010Z,1649888550.010 [senddata_direct_test:B](INFO): Queuing up send data for Onboard.Temperature with destination: modem:1:_.temperature 2022-04-13T22:22:30.010Z,1649888550.010 [senddata_direct_test:B] Stopped 2022-04-13T22:22:30.010Z,1649888550.010 [senddata_direct_test:C] Running Loop=1 2022-04-13T22:22:30.028Z,1649888550.028 [DAT](DEBUG): checking for time setting acknowledgment 2022-04-13T22:22:30.028Z,1649888550.028 [DAT](FAULT): failed to set time 2022-04-13T22:22:30.281Z,1649888550.281 [DAT](INFO): Setting time to: 22:22:30 And date to:4/13/2022 2022-04-13T22:22:30.431Z,1649888550.431 [senddata_direct_test:C](INFO): Queuing up send data for Onboard.Humidity with destination: modem:1:_.humidity 2022-04-13T22:22:30.431Z,1649888550.431 [senddata_direct_test:C] Stopped 2022-04-13T22:22:30.431Z,1649888550.431 [senddata_direct_test](INFO): Completed senddata_direct_test 2022-04-13T22:22:30.431Z,1649888550.431 [MissionManager](INFO): senddata_direct_test is completed. 2022-04-13T22:22:30.431Z,1649888550.431 [MissionManager](INFO): Uninitializing Mission senddata_direct_test 2022-04-13T22:22:30.431Z,1649888550.431 [senddata_direct_test] Stopped 2022-04-13T22:22:30.431Z,1649888550.431 [senddata_direct_test](DEBUG): Aggregate::uninitialize senddata_direct_test 2022-04-13T22:22:30.533Z,1649888550.533 [DAT](INFO): Local DAT time set to Wed Apr 13, 2022 22:22:30 2022-04-13T22:22:30.535Z,1649888550.535 [DAT](INFO): modem://1: set _.pressure 0.521850 atmosphere 2022-04-13T22:22:30.535Z,1649888550.535 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:22:30.785Z,1649888550.785 [DAT](INFO): setting remote address to 1 2022-04-13T22:22:30.848Z,1649888550.848 [MissionManager](IMPORTANT): Started mission Default 2022-04-13T22:22:30.848Z,1649888550.848 [Default] Running Loop=1 2022-04-13T22:22:30.848Z,1649888550.848 [Default](DEBUG): Aggregate::initialize Default 2022-04-13T22:22:30.848Z,1649888550.848 [Default:B.GoToSurface] Running Loop=1 2022-04-13T22:22:30.848Z,1649888550.848 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-04-13T22:22:30.849Z,1649888550.849 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-04-13T22:22:30.849Z,1649888550.849 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-04-13T22:22:30.849Z,1649888550.849 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-04-13T22:22:30.850Z,1649888550.850 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-04-13T22:22:30.850Z,1649888550.850 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-04-13T22:22:30.850Z,1649888550.850 [Default:A.Wait] Running Loop=1 2022-04-13T22:22:30.851Z,1649888550.851 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-04-13T22:22:31.037Z,1649888551.037 [DAT](INFO): set remote address to 1 2022-04-13T22:22:31.038Z,1649888551.038 [DAT](INFO): entering online mode 2022-04-13T22:22:31.290Z,1649888551.290 [DAT](INFO): commRate: 800 2022-04-13T22:22:31.290Z,1649888551.290 [DAT](INFO): online mode acknowledged 2022-04-13T22:22:31.290Z,1649888551.290 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:22:34.565Z,1649888554.565 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:22:44.155Z,1649888564.155 [Default:A.Wait](INFO): Done Waiting. 2022-04-13T22:22:44.156Z,1649888564.156 [Default:A.Wait] Stopped 2022-04-13T22:22:44.156Z,1649888564.156 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-04-13T22:22:44.574Z,1649888564.574 [Default:CheckIn] Running Loop=1 2022-04-13T22:22:44.574Z,1649888564.574 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-04-13T22:22:44.574Z,1649888564.574 [Default:CheckIn:Read_GPS] Running Loop=1 2022-04-13T22:22:44.656Z,1649888564.656 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:22:44.656Z,1649888564.656 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:22:44.909Z,1649888564.909 [DAT](INFO): modem://1: set _.temperature 23.494074 celsius 2022-04-13T22:22:44.909Z,1649888564.909 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:22:45.160Z,1649888565.160 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:22:48.437Z,1649888568.437 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:22:58.524Z,1649888578.524 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:22:58.524Z,1649888578.524 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:22:58.777Z,1649888578.777 [DAT](INFO): modem://1: set _.humidity 22.268343 percent 2022-04-13T22:22:58.777Z,1649888578.777 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:22:59.028Z,1649888579.028 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:23:02.305Z,1649888582.305 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:23:12.408Z,1649888592.408 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:23:12.408Z,1649888592.408 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:23:12.653Z,1649888592.653 [DAT](INFO): modem://1: set _.pressure 0.523271 atmosphere 2022-04-13T22:23:12.653Z,1649888592.653 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:23:12.907Z,1649888592.907 [DAT](INFO): unknown deviceResponse_: WARNING: Modem reset during xmit; lowering xmit power level by 3 dB. 2022-04-13T22:23:12.909Z,1649888592.909 [DAT](INFO): unknown deviceResponse_: WARNING: Reduced xmit power level to 7 due to weak battery. 2022-04-13T22:23:12.910Z,1649888592.910 [DAT](INFO): commRate: 800 2022-04-13T22:23:12.911Z,1649888592.911 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:23:13.637Z,1649888593.637 [BPC1](INFO): Calculating totals. Valid battery stick count: 54. Valid reserve battery stick count: 6. 2022-04-13T22:23:13.640Z,1649888593.640 [BPC1](INFO): Received data from all battery sticks. 2022-04-13T22:23:16.193Z,1649888596.193 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:23:26.284Z,1649888606.284 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:23:26.284Z,1649888606.284 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:23:26.538Z,1649888606.538 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:23:26.789Z,1649888606.789 [DAT](INFO): modem://1: set _.temperature 23.494074 celsius 2022-04-13T22:23:26.789Z,1649888606.789 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:23:27.041Z,1649888607.041 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:23:30.317Z,1649888610.317 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:23:40.396Z,1649888620.396 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:23:40.397Z,1649888620.397 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:23:40.648Z,1649888620.648 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:23:40.901Z,1649888620.901 [DAT](INFO): modem://1: set _.humidity 22.292761 percent 2022-04-13T22:23:40.901Z,1649888620.901 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:23:41.152Z,1649888621.152 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:23:44.429Z,1649888624.429 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:23:54.528Z,1649888634.528 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:23:54.528Z,1649888634.528 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:23:54.780Z,1649888634.780 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:23:55.032Z,1649888635.032 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:23:55.284Z,1649888635.284 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:23:58.569Z,1649888638.569 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:24:08.672Z,1649888648.672 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:24:08.672Z,1649888648.672 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:24:08.925Z,1649888648.925 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:24:09.178Z,1649888649.178 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:24:09.428Z,1649888649.428 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:24:12.705Z,1649888652.705 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:24:22.812Z,1649888662.812 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:24:22.813Z,1649888662.813 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:24:23.065Z,1649888663.065 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:24:23.316Z,1649888663.316 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2022-04-13T22:24:23.570Z,1649888663.570 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2022-04-13T22:24:26.845Z,1649888666.845 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2022-04-13T22:24:36.948Z,1649888676.948 [DAT](FAULT): Ack receipt timeout failure. 2022-04-13T22:24:36.948Z,1649888676.948 [DAT](DEBUG): In sendingAckWaiting, hit max timeouts so set commsState_ = SENDING_VERIFIED 2022-04-13T22:24:37.200Z,1649888677.200 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER 2022-04-13T22:24:47.854Z,1649888687.854 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2022-04-13T22:24:47.854Z,1649888687.854 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-04-13T22:24:47.905Z,1649888687.905 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-04-13T22:24:48.229Z,1649888688.229 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-04-13T22:24:48.230Z,1649888688.230 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2022-04-13T22:24:58.889Z,1649888698.889 [CommandExec](IMPORTANT): got command get DAT.verbosity 2022-04-13T22:24:58.890Z,1649888698.890 [CommandExec](IMPORTANT): DAT.verbosity 0 count 2022-04-13T22:25:06.580Z,1649888706.580 [CommandExec](IMPORTANT): got command configSet DAT.verbosity 2 count persist 2022-04-13T22:25:10.961Z,1649888710.961 [CommandExec](IMPORTANT): got command show stack 2022-04-13T22:25:10.961Z,1649888710.961 [CommandExec](IMPORTANT): Behavior Stack: 2022-04-13T22:25:10.962Z,1649888710.962 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface 2022-04-13T22:25:10.962Z,1649888710.962 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS