2021-11-17T22:36:19.173Z,1637188579.173 [Supervisor](DEBUG): Initializing supervisor. 2021-11-17T22:36:19.178Z,1637188579.178 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2021-11-17T22:36:19.178Z,1637188579.178 [SyncHandler](INFO): Protected caller Thread ID is 834 2021-11-17T22:36:19.179Z,1637188579.179 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2021-11-17T22:36:19.180Z,1637188579.180 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2021-11-17T22:36:19.180Z,1637188579.180 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 835 2021-11-17T22:36:19.184Z,1637188579.184 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2021-11-17T22:36:19.202Z,1637188579.202 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2021-11-17T22:36:19.203Z,1637188579.203 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2021-11-17T22:36:19.204Z,1637188579.204 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 836 2021-11-17T22:36:19.208Z,1637188579.208 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2021-11-17T22:36:19.209Z,1637188579.209 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2021-11-17T22:36:19.209Z,1637188579.209 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 837 2021-11-17T22:36:19.211Z,1637188579.211 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2021-11-17T22:36:19.212Z,1637188579.212 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2021-11-17T22:36:19.213Z,1637188579.213 [logger ThreadHandler](INFO): Protected caller Thread ID is 838 2021-11-17T22:36:19.217Z,1637188579.217 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2021-11-17T22:36:19.217Z,1637188579.217 [Supervisor](INFO): Looking for Config files in directory: Config/ 2021-11-17T22:36:19.221Z,1637188579.221 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2021-11-17T22:36:19.446Z,1637188579.446 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2021-11-17T22:36:19.448Z,1637188579.448 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2021-11-17T22:36:19.530Z,1637188579.530 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2021-11-17T22:36:20.029Z,1637188580.029 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2021-11-17T22:36:20.031Z,1637188580.031 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2021-11-17T22:36:20.349Z,1637188580.349 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2021-11-17T22:36:20.351Z,1637188580.351 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2021-11-17T22:36:20.447Z,1637188580.447 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2021-11-17T22:36:20.447Z,1637188580.447 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2021-11-17T22:36:20.803Z,1637188580.803 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2021-11-17T22:36:20.805Z,1637188580.805 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2021-11-17T22:36:21.012Z,1637188581.012 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2021-11-17T22:36:21.014Z,1637188581.014 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2021-11-17T22:36:21.460Z,1637188581.460 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2021-11-17T22:36:21.460Z,1637188581.460 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2021-11-17T22:36:21.587Z,1637188581.587 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2021-11-17T22:36:21.588Z,1637188581.588 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2021-11-17T22:36:21.666Z,1637188581.666 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2021-11-17T22:36:22.318Z,1637188582.318 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2021-11-17T22:36:22.319Z,1637188582.319 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2021-11-17T22:36:22.682Z,1637188582.682 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2021-11-17T22:36:22.682Z,1637188582.682 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2021-11-17T22:36:23.814Z,1637188583.814 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2021-11-17T22:36:23.845Z,1637188583.845 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2021-11-17T22:36:23.996Z,1637188583.996 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2021-11-17T22:36:23.997Z,1637188583.997 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2021-11-17T22:36:24.146Z,1637188584.146 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2021-11-17T22:36:24.148Z,1637188584.148 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2021-11-17T22:36:24.370Z,1637188584.370 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2021-11-17T22:36:24.371Z,1637188584.371 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2021-11-17T22:36:24.374Z,1637188584.374 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2021-11-17T22:36:24.464Z,1637188584.464 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2021-11-17T22:36:24.549Z,1637188584.549 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2021-11-17T22:36:24.648Z,1637188584.648 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2021-11-17T22:36:24.731Z,1637188584.731 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2021-11-17T22:36:24.825Z,1637188584.825 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2021-11-17T22:36:24.925Z,1637188584.925 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2021-11-17T22:36:25.108Z,1637188585.108 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2021-11-17T22:36:25.185Z,1637188585.185 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2021-11-17T22:36:25.331Z,1637188585.331 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2021-11-17T22:36:25.465Z,1637188585.465 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2021-11-17T22:36:25.579Z,1637188585.579 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2021-11-17T22:36:25.837Z,1637188585.837 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2021-11-17T22:36:25.837Z,1637188585.837 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2021-11-17T22:36:26.015Z,1637188586.015 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2021-11-17T22:36:26.234Z,1637188586.234 [VerticalControl](DEBUG): Construct VerticalControl. 2021-11-17T22:36:26.299Z,1637188586.299 [VerticalControl] Loaded 2021-11-17T22:36:26.299Z,1637188586.299 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2021-11-17T22:36:26.302Z,1637188586.302 [HorizontalControl](DEBUG): Construct HorizontalControl. 2021-11-17T22:36:26.340Z,1637188586.340 [HorizontalControl] Loaded 2021-11-17T22:36:26.340Z,1637188586.340 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2021-11-17T22:36:26.342Z,1637188586.342 [SpeedControl](DEBUG): Construct SpeedControl. 2021-11-17T22:36:26.346Z,1637188586.346 [SpeedControl] Loaded 2021-11-17T22:36:26.346Z,1637188586.346 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2021-11-17T22:36:26.348Z,1637188586.348 [LoopControl](DEBUG): Construct LoopControl. 2021-11-17T22:36:26.349Z,1637188586.349 [LoopControl] Loaded 2021-11-17T22:36:26.349Z,1637188586.349 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2021-11-17T22:36:26.350Z,1637188586.350 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2021-11-17T22:36:26.350Z,1637188586.350 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2021-11-17T22:36:26.366Z,1637188586.366 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2021-11-17T22:36:26.368Z,1637188586.368 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2021-11-17T22:36:26.500Z,1637188586.500 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2021-11-17T22:36:26.501Z,1637188586.501 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2021-11-17T22:36:26.680Z,1637188586.680 [BuoyancyServo] Loaded 2021-11-17T22:36:26.681Z,1637188586.681 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2021-11-17T22:36:26.700Z,1637188586.700 [ElevatorServo] Loaded 2021-11-17T22:36:26.700Z,1637188586.700 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2021-11-17T22:36:26.718Z,1637188586.718 [MassServo] Loaded 2021-11-17T22:36:26.718Z,1637188586.718 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2021-11-17T22:36:26.736Z,1637188586.736 [RudderServo] Loaded 2021-11-17T22:36:26.736Z,1637188586.736 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2021-11-17T22:36:26.754Z,1637188586.754 [ThrusterServo] Loaded 2021-11-17T22:36:26.754Z,1637188586.754 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2021-11-17T22:36:26.755Z,1637188586.755 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2021-11-17T22:36:26.755Z,1637188586.755 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2021-11-17T22:36:26.855Z,1637188586.855 [DeadReckonUsingMultipleVelocitySources] Loaded 2021-11-17T22:36:26.855Z,1637188586.855 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2021-11-17T22:36:26.868Z,1637188586.868 [NavChart] Loaded 2021-11-17T22:36:26.869Z,1637188586.869 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2021-11-17T22:36:26.874Z,1637188586.874 [UniversalFixResidualReporter] Loaded 2021-11-17T22:36:26.875Z,1637188586.875 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2021-11-17T22:36:26.875Z,1637188586.875 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2021-11-17T22:36:26.876Z,1637188586.876 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2021-11-17T22:36:26.960Z,1637188586.960 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2021-11-17T22:36:26.962Z,1637188586.962 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2021-11-17T22:36:27.652Z,1637188587.652 [AHRS_M2] Loaded 2021-11-17T22:36:27.652Z,1637188587.652 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2021-11-17T22:36:28.903Z,1637188588.903 [BPC1] Loaded 2021-11-17T22:36:28.904Z,1637188588.904 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2021-11-17T22:36:28.923Z,1637188588.923 [Depth_Keller] Loaded 2021-11-17T22:36:28.924Z,1637188588.924 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2021-11-17T22:36:28.928Z,1637188588.928 [DropWeight] Loaded 2021-11-17T22:36:28.929Z,1637188588.929 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2021-11-17T22:36:28.987Z,1637188588.987 [NAL9602] Loaded 2021-11-17T22:36:28.988Z,1637188588.988 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2021-11-17T22:36:29.017Z,1637188589.017 [Onboard] Loaded 2021-11-17T22:36:29.018Z,1637188589.018 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2021-11-17T22:36:29.019Z,1637188589.019 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0 2021-11-17T22:36:29.019Z,1637188589.019 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 923 2021-11-17T22:36:29.032Z,1637188589.032 [Power24vConverter] Loaded 2021-11-17T22:36:29.032Z,1637188589.032 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2021-11-17T22:36:29.046Z,1637188589.046 [Radio_Surface] Loaded 2021-11-17T22:36:29.046Z,1637188589.046 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2021-11-17T22:36:29.047Z,1637188589.047 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0 2021-11-17T22:36:29.048Z,1637188589.048 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 924 2021-11-17T22:36:29.128Z,1637188589.128 [DAT] Loaded 2021-11-17T22:36:29.129Z,1637188589.129 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2021-11-17T22:36:29.129Z,1637188589.129 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2021-11-17T22:36:29.130Z,1637188589.130 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2021-11-17T22:36:29.190Z,1637188589.190 [DepthRateCalculator] Loaded 2021-11-17T22:36:29.190Z,1637188589.190 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2021-11-17T22:36:29.195Z,1637188589.195 [PitchRateCalculator] Loaded 2021-11-17T22:36:29.195Z,1637188589.195 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2021-11-17T22:36:29.204Z,1637188589.204 [SpeedCalculator] Loaded 2021-11-17T22:36:29.204Z,1637188589.204 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2021-11-17T22:36:29.218Z,1637188589.218 [TempGradientCalculator] Loaded 2021-11-17T22:36:29.218Z,1637188589.218 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2021-11-17T22:36:29.223Z,1637188589.223 [YawRateCalculator] Loaded 2021-11-17T22:36:29.223Z,1637188589.223 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2021-11-17T22:36:29.241Z,1637188589.241 [ElevatorOffsetCalculator] Loaded 2021-11-17T22:36:29.241Z,1637188589.241 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2021-11-17T22:36:29.242Z,1637188589.242 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2021-11-17T22:36:29.242Z,1637188589.242 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2021-11-17T22:36:29.423Z,1637188589.423 [CANONSampler] Loaded 2021-11-17T22:36:29.423Z,1637188589.423 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread. 2021-11-17T22:36:29.481Z,1637188589.481 [CTD_Seabird] Loaded 2021-11-17T22:36:29.482Z,1637188589.482 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2021-11-17T22:36:29.483Z,1637188589.483 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409AB4E0 2021-11-17T22:36:29.483Z,1637188589.483 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 925 2021-11-17T22:36:29.503Z,1637188589.503 [PAR_Licor] Loaded 2021-11-17T22:36:29.503Z,1637188589.503 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2021-11-17T22:36:29.535Z,1637188589.535 [WetLabsBB2FL] Loaded 2021-11-17T22:36:29.535Z,1637188589.535 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2021-11-17T22:36:29.536Z,1637188589.536 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DB4E0 2021-11-17T22:36:29.537Z,1637188589.537 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 926 2021-11-17T22:36:29.538Z,1637188589.538 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2021-11-17T22:36:29.538Z,1637188589.538 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2021-11-17T22:36:29.581Z,1637188589.581 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2021-11-17T22:36:29.581Z,1637188589.581 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2021-11-17T22:36:29.958Z,1637188589.958 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2021-11-17T22:36:29.960Z,1637188589.960 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2021-11-17T22:36:30.137Z,1637188590.137 [SBIT](DEBUG): Construct Startup Built In Test. 2021-11-17T22:36:30.146Z,1637188590.146 [SBIT] Loaded 2021-11-17T22:36:30.147Z,1637188590.147 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2021-11-17T22:36:30.149Z,1637188590.149 [IBIT](DEBUG): Construct Initiated Built In Test. 2021-11-17T22:36:30.163Z,1637188590.163 [IBIT] Loaded 2021-11-17T22:36:30.163Z,1637188590.163 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2021-11-17T22:36:30.169Z,1637188590.169 [CBIT](DEBUG): Construct Continuous Built In Test. 2021-11-17T22:36:30.271Z,1637188590.271 [CBIT] Loaded 2021-11-17T22:36:30.271Z,1637188590.271 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2021-11-17T22:36:30.272Z,1637188590.272 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2021-11-17T22:36:30.272Z,1637188590.272 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2021-11-17T22:36:30.391Z,1637188590.391 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2021-11-17T22:36:30.397Z,1637188590.397 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2021-11-17T22:36:30.400Z,1637188590.400 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2021-11-17T22:36:30.410Z,1637188590.410 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2021-11-17T22:36:30.411Z,1637188590.411 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B104E0 2021-11-17T22:36:30.412Z,1637188590.412 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 927 2021-11-17T22:36:30.416Z,1637188590.416 [Supervisor](INFO): Main Thread ID is 829 2021-11-17T22:36:30.416Z,1637188590.416 [Supervisor](DEBUG): Running supervisor. 2021-11-17T22:36:30.417Z,1637188590.417 [CommandExec ThreadHandler](INFO): Handler Thread ID is 928 2021-11-17T22:36:30.418Z,1637188590.418 [CommandExec](INFO): Initializing the command executive. 2021-11-17T22:36:30.419Z,1637188590.419 [CommandLine ThreadHandler](INFO): Handler Thread ID is 929 2021-11-17T22:36:30.421Z,1637188590.421 [controlThread ThreadHandler](INFO): Handler Thread ID is 930 2021-11-17T22:36:30.422Z,1637188590.422 [controlThread](DEBUG): Initializing ControlThread 2021-11-17T22:36:30.423Z,1637188590.423 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2021-11-17T22:36:30.425Z,1637188590.425 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2021-11-17T22:36:30.426Z,1637188590.426 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2021-11-17T22:36:30.426Z,1637188590.426 [LoopControl](DEBUG): Initialize LoopControlComponent. 2021-11-17T22:36:30.428Z,1637188590.428 [NavChart](DEBUG): Initialize NavChart Navigation. 2021-11-17T22:36:30.428Z,1637188590.428 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2021-11-17T22:36:30.434Z,1637188590.434 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2021-11-17T22:36:30.434Z,1637188590.434 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2021-11-17T22:36:30.434Z,1637188590.434 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2021-11-17T22:36:30.435Z,1637188590.435 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2021-11-17T22:36:30.435Z,1637188590.435 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2021-11-17T22:36:30.436Z,1637188590.436 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2021-11-17T22:36:30.440Z,1637188590.440 [SBIT](INFO): Initialize SBIT Component. 2021-11-17T22:36:30.441Z,1637188590.441 [SBIT](IMPORTANT): git: 2021-10-11a 2021-11-17T22:36:30.441Z,1637188590.441 [SBIT](INFO): git hash: 36f3a97de7a122c995f034a375e3cefac6406048 2021-11-17T22:36:30.441Z,1637188590.441 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2021-11-17T22:36:30.442Z,1637188590.442 [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 2021-11-17T22:36:30.444Z,1637188590.444 [SBIT](INFO): Beginning SBIT in 84.000000 seconds. 2021-11-17T22:36:30.444Z,1637188590.444 [IBIT](INFO): Initialize IBIT Component. 2021-11-17T22:36:30.445Z,1637188590.445 [CBIT](DEBUG): Initialize CBIT Component. 2021-11-17T22:36:30.446Z,1637188590.446 [logger ThreadHandler](INFO): Handler Thread ID is 931 2021-11-17T22:36:30.460Z,1637188590.460 [CBIT](DEBUG): Initialized mux pins. 2021-11-17T22:36:30.460Z,1637188590.460 [CBIT](DEBUG): Initializing the watchdog timer. 2021-11-17T22:36:30.465Z,1637188590.465 [Onboard ThreadHandler](INFO): Handler Thread ID is 932 2021-11-17T22:36:30.488Z,1637188590.488 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2021-11-17T22:36:30.488Z,1637188590.488 [CBIT](DEBUG): Initializing heartbeat. 2021-11-17T22:36:30.490Z,1637188590.490 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 933 2021-11-17T22:36:30.497Z,1637188590.497 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 934 2021-11-17T22:36:30.498Z,1637188590.498 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2021-11-17T22:36:30.504Z,1637188590.504 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 936 2021-11-17T22:36:30.508Z,1637188590.508 [WetLabsBB2FL](INFO): Powering up 2021-11-17T22:36:30.509Z,1637188590.509 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 938 2021-11-17T22:36:30.518Z,1637188590.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2021-11-17T22:36:30.518Z,1637188590.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2021-11-17T22:36:30.518Z,1637188590.518 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2021-11-17T22:36:30.518Z,1637188590.518 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2021-11-17T22:36:30.519Z,1637188590.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2021-11-17T22:36:30.519Z,1637188590.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2021-11-17T22:36:30.519Z,1637188590.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2021-11-17T22:36:30.519Z,1637188590.519 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2021-11-17T22:36:30.519Z,1637188590.519 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2021-11-17T22:36:30.520Z,1637188590.520 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2021-11-17T22:36:30.520Z,1637188590.520 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2021-11-17T22:36:30.520Z,1637188590.520 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2021-11-17T22:36:30.521Z,1637188590.521 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2021-11-17T22:36:30.521Z,1637188590.521 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2021-11-17T22:36:30.521Z,1637188590.521 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2021-11-17T22:36:30.521Z,1637188590.521 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2021-11-17T22:36:30.560Z,1637188590.560 [CBIT](DEBUG): Deactivating GF circuits. 2021-11-17T22:36:30.560Z,1637188590.560 [CBIT](DEBUG): Deactivating emergency mode. 2021-11-17T22:36:30.596Z,1637188590.596 [CBIT](DEBUG): Backplane powered. 2021-11-17T22:36:30.597Z,1637188590.597 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2021-11-17T22:36:30.627Z,1637188590.627 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2021-11-17T22:36:30.663Z,1637188590.663 [MissionManager](DEBUG): 2021-11-17T22:36:30.664Z,1637188590.664 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2021-11-17T22:36:30.757Z,1637188590.757 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2021-11-17T22:36:30.758Z,1637188590.758 [Default:A.Wait](DEBUG): Construct Wait. 2021-11-17T22:36:30.761Z,1637188590.761 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2021-11-17T22:36:30.803Z,1637188590.803 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2021-11-17T22:36:30.805Z,1637188590.805 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2021-11-17T22:36:30.831Z,1637188590.831 [Default:E.Execute](DEBUG): Construct Execute. 2021-11-17T22:36:30.834Z,1637188590.834 [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. 1 Default mission has been running for Restarting logs and Default mission. restart logs 2021-11-17T22:36:30.848Z,1637188590.848 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,DAT,CANONSampler,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2021-11-17T22:36:30.860Z,1637188590.860 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2021-11-17T22:36:30.896Z,1637188590.896 [Radio_Surface](INFO): Powering up 2021-11-17T22:36:30.998Z,1637188590.998 [Power24vConverter](INFO): Powering up. 2021-11-17T22:36:30.999Z,1637188590.999 [DAT](INFO): Powering up 2021-11-17T22:36:30.999Z,1637188590.999 [DAT](DEBUG): Initializing DAT. 2021-11-17T22:36:31.012Z,1637188591.012 [CANONSampler](INFO): Powering down 2021-11-17T22:36:31.054Z,1637188591.054 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:31.060Z,1637188591.060 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2021-11-17T22:36:31.061Z,1637188591.061 [ElevatorServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:31.068Z,1637188591.068 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2021-11-17T22:36:31.069Z,1637188591.069 [MassServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:31.076Z,1637188591.076 [MassServo](DEBUG): Initializing MassServo. 2021-11-17T22:36:31.077Z,1637188591.077 [RudderServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:31.088Z,1637188591.088 [RudderServo](DEBUG): Initializing RudderServo. 2021-11-17T22:36:31.089Z,1637188591.089 [ThrusterServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:31.097Z,1637188591.097 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2021-11-17T22:36:31.281Z,1637188591.281 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2021-11-17T22:36:31.281Z,1637188591.281 [DropWeight] Hardware Fault, FailCount= 1 2021-11-17T22:36:31.281Z,1637188591.281 [DropWeight](ERROR): Hardware Fault 2021-11-17T22:36:31.320Z,1637188591.320 [CommandExec](FAULT): Scheduling is paused 2021-11-17T22:36:31.321Z,1637188591.321 [CBIT](INFO): Critical error at 20211117T223631 2021-11-17T22:36:31.321Z,1637188591.321 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2021-11-17T22:36:31.323Z,1637188591.323 [CBIT](ERROR): Hardware Fault in component: DropWeight 2021-11-17T22:36:31.328Z,1637188591.328 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2021-11-17T22:36:31.996Z,1637188591.996 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2021-11-17T22:36:31.996Z,1637188591.996 [RudderServo](FAULT): Rudder failed to initialize 2021-11-17T22:36:31.996Z,1637188591.996 [RudderServo] Communications Fault, FailCount= 1 2021-11-17T22:36:31.996Z,1637188591.996 [RudderServo](ERROR): Communications Fault 2021-11-17T22:36:32.097Z,1637188592.097 [CBIT](INFO): Critical error at 20211117T223631 2021-11-17T22:36:32.100Z,1637188592.100 [CBIT](ERROR): Communications Fault in component: RudderServo 2021-11-17T22:36:32.265Z,1637188592.265 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-11-17T22:36:32.265Z,1637188592.265 [RudderServo](INFO): Powering down 2021-11-17T22:36:32.616Z,1637188592.616 [WetLabsBB2FL](INFO): Powering down 2021-11-17T22:36:32.945Z,1637188592.945 [RudderServo](DEBUG): Initializing EZServoServo. 2021-11-17T22:36:33.065Z,1637188593.065 [RudderServo](DEBUG): Initializing RudderServo. 2021-11-17T22:36:33.069Z,1637188593.069 [CBIT](INFO): Clearing failed state for component RudderServo 2021-11-17T22:36:33.069Z,1637188593.069 [RudderServo] No Fault, FailCount= 1 2021-11-17T22:36:37.544Z,1637188597.544 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2021-11-17T22:36:42.618Z,1637188602.618 [DAT](INFO): DAT read: 2021-11-17T22:36:42.619Z,1637188602.619 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2021-11-17T22:36:44.234Z,1637188604.234 [DAT](INFO): DAT read: MF Frequency Band 2021-11-17T22:36:44.235Z,1637188604.235 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2 2021-11-17T22:36:44.236Z,1637188604.236 [DAT](INFO): DAT read: Nov 17 2021 22:35:57 2021-11-17T22:36:45.446Z,1637188605.446 [DAT](INFO): DAT read: Features enabled [Bearing] 2021-11-17T22:36:45.447Z,1637188605.447 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC 2021-11-17T22:36:45.448Z,1637188605.448 [DAT](INFO): commRate: 1200 2021-11-17T22:36:47.466Z,1637188607.466 [DAT](INFO): entering command mode 2021-11-17T22:36:47.870Z,1637188607.870 [DAT](INFO): DAT read: 2021-11-17T22:36:47.870Z,1637188607.870 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:48.274Z,1637188608.274 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:48.678Z,1637188608.678 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:49.082Z,1637188609.082 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:49.486Z,1637188609.486 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:49.890Z,1637188609.890 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:50.302Z,1637188610.302 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:50.698Z,1637188610.698 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:51.102Z,1637188611.102 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:51.506Z,1637188611.506 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:51.909Z,1637188611.909 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:52.321Z,1637188612.321 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:52.718Z,1637188612.718 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:53.122Z,1637188613.122 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:53.526Z,1637188613.526 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:53.934Z,1637188613.934 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:54.334Z,1637188614.334 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:54.738Z,1637188614.738 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:55.142Z,1637188615.142 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:55.554Z,1637188615.554 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:55.950Z,1637188615.950 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:56.354Z,1637188616.354 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:56.757Z,1637188616.757 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:57.166Z,1637188617.166 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:57.566Z,1637188617.566 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:57.970Z,1637188617.970 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:58.374Z,1637188618.374 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:58.782Z,1637188618.782 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:59.181Z,1637188619.181 [NAL9602](INFO): Powering up NAL9602 2021-11-17T22:36:59.183Z,1637188619.183 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:59.586Z,1637188619.586 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:36:59.990Z,1637188619.990 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:00.398Z,1637188620.398 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:00.798Z,1637188620.798 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:01.202Z,1637188621.202 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:01.606Z,1637188621.606 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:02.014Z,1637188622.014 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:02.414Z,1637188622.414 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:02.818Z,1637188622.818 [DAT](DEBUG): checking for command mode acknowledgment 2021-11-17T22:37:02.818Z,1637188622.818 [DAT](FAULT): failed to enter command mode 2021-11-17T22:37:03.222Z,1637188623.222 [DAT](INFO): entering command mode 2021-11-17T22:37:03.634Z,1637188623.634 [DAT](INFO): DAT read: user:1> 2021-11-17T22:37:03.635Z,1637188623.635 [DAT](INFO): DAT read: Command '+++' not found 2021-11-17T22:37:03.636Z,1637188623.636 [DAT](INFO): DAT read: Error 2021-11-17T22:37:03.636Z,1637188623.636 [DAT](INFO): setting verbose to 3 2021-11-17T22:37:04.030Z,1637188624.030 [DAT](INFO): DAT read: user:2> 2021-11-17T22:37:04.031Z,1637188624.031 [DAT](INFO): DAT read: Verbose | 3 2021-11-17T22:37:04.031Z,1637188624.031 [DAT](INFO): set verbose to 3 2021-11-17T22:37:04.032Z,1637188624.032 [DAT](INFO): setting DatVerbose to 27440 2021-11-17T22:37:04.438Z,1637188624.438 [DAT](INFO): DAT read: user:3> 2021-11-17T22:37:04.439Z,1637188624.439 [DAT](INFO): DAT read: DatVerbose | 27440 2021-11-17T22:37:04.439Z,1637188624.439 [DAT](INFO): set DatVerbose to 27440 2021-11-17T22:37:04.440Z,1637188624.440 [DAT](INFO): setting transmit power to 8 2021-11-17T22:37:04.838Z,1637188624.838 [DAT](INFO): DAT read: user:4> 2021-11-17T22:37:04.839Z,1637188624.839 [DAT](INFO): DAT read: TxPower | 8 (Max) 2021-11-17T22:37:04.839Z,1637188624.839 [DAT](INFO): set transmit power to 8 2021-11-17T22:37:04.840Z,1637188624.840 [DAT](INFO): setting local address to 7 2021-11-17T22:37:05.242Z,1637188625.242 [DAT](INFO): DAT read: user:5> 2021-11-17T22:37:05.243Z,1637188625.243 [DAT](INFO): DAT read: LocalAddr | 7 2021-11-17T22:37:05.243Z,1637188625.243 [DAT](INFO): set local address to 7 2021-11-17T22:37:10.089Z,1637188630.089 [NAL9602](INFO): NAL9602 initialized 2021-11-17T22:37:54.976Z,1637188674.976 [SBIT](IMPORTANT): Beginning Startup BIT 2021-11-17T22:37:54.981Z,1637188674.981 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-17T22:38:05.902Z,1637188685.902 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2021-11-17T22:38:06.309Z,1637188686.309 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-17T22:38:17.301Z,1637188697.301 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2021-11-17T22:38:17.614Z,1637188697.614 [CBIT](IMPORTANT): Beginning ground fault scan 2021-11-17T22:38:28.494Z,1637188708.494 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan. 2021-11-17T22:38:28.494Z,1637188708.494 [CBIT](IMPORTANT): Ground fault scan returned out of bounds value in succession 3 times. Will re-run scan on normal schedule. 2021-11-17T22:38:49.098Z,1637188729.098 [SBIT](IMPORTANT): SBIT PASSED 2021-11-17T22:38:49.098Z,1637188729.098 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2021-11-17T22:38:49.099Z,1637188729.099 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool; 2021-11-17T22:38:49.099Z,1637188729.099 [SBIT](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter; 2021-11-17T22:38:49.099Z,1637188729.099 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool; 2021-11-17T22:38:49.099Z,1637188729.099 [SBIT](IMPORTANT): DAT.baud=9600 bit_per_second; 2021-11-17T22:38:49.100Z,1637188729.100 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool; 2021-11-17T22:38:49.100Z,1637188729.100 [SBIT](IMPORTANT): DAT.sbdAddress=1 enum; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): DAT.surfaceThreshold=0 meter; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): DAT.verbosity=3 count; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): DataOverHttps.loadAtStartup=0 bool; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=0 bool; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=296 cubic_centimeter; 2021-11-17T22:38:49.101Z,1637188729.101 [SBIT](IMPORTANT): VerticalControl.massDefault=-16 millimeter; 2021-11-17T22:38:49.102Z,1637188729.102 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=2 meter; 2021-11-17T22:38:49.490Z,1637188729.490 [MissionManager](IMPORTANT): Started mission Startup 2021-11-17T22:38:49.490Z,1637188729.490 [Startup] Running Loop=1 2021-11-17T22:38:49.490Z,1637188729.490 [Startup](DEBUG): Aggregate::initialize Startup 2021-11-17T22:38:49.490Z,1637188729.490 [Startup:A.GoToSurface] Running Loop=1 2021-11-17T22:38:49.490Z,1637188729.490 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-11-17T22:38:49.491Z,1637188729.491 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-11-17T22:38:49.492Z,1637188729.492 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-11-17T22:38:49.492Z,1637188729.492 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-11-17T22:38:49.493Z,1637188729.493 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-11-17T22:38:49.493Z,1637188729.493 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-11-17T22:38:49.494Z,1637188729.494 [Startup:StartupSatComms] Running Loop=1 2021-11-17T22:38:49.494Z,1637188729.494 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2021-11-17T22:38:49.495Z,1637188729.495 [Startup:StartupSatComms:A] Running Loop=1 2021-11-17T22:38:49.888Z,1637188729.888 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2021-11-17T22:39:30.723Z,1637188770.723 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2021-11-17T22:39:30.724Z,1637188770.724 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-17T22:39:30.747Z,1637188770.747 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-17T22:39:31.121Z,1637188771.121 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-17T22:39:31.121Z,1637188771.121 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2021-11-17T22:39:49.680Z,1637188789.680 [Startup:StartupSatComms:A](INFO): Timed out from 2021-11-17T22:38:49.5Z 2021-11-17T22:39:49.680Z,1637188789.680 [Startup:StartupSatComms:A] Stopped 2021-11-17T22:39:49.680Z,1637188789.680 [Startup:StartupSatComms:B] Running Loop=1 2021-11-17T22:39:50.094Z,1637188790.094 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-11-17T22:39:51.282Z,1637188791.282 [DAT](INFO): #Outgoing data=1 2021-11-17T22:39:51.283Z,1637188791.283 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:39:51.386Z,1637188791.386 [DAT](INFO): setting remote address to 1 2021-11-17T22:39:51.758Z,1637188791.758 [DAT](INFO): DAT read: user:6> 2021-11-17T22:39:51.759Z,1637188791.759 [DAT](INFO): DAT read: RemoteAddr | 1 2021-11-17T22:39:51.759Z,1637188791.759 [DAT](INFO): set remote address to 1 2021-11-17T22:39:51.760Z,1637188791.760 [DAT](INFO): entering online mode 2021-11-17T22:39:52.215Z,1637188792.215 [DAT](INFO): DAT read: user:7> 2021-11-17T22:39:52.215Z,1637188792.215 [DAT](INFO): DAT read: 2021-11-17T22:39:52.216Z,1637188792.216 [DAT](INFO): DAT read: CONNECT 01200 bits/sec 1 of 4, Rate 1/2 CC 2021-11-17T22:39:52.217Z,1637188792.217 [DAT](INFO): commRate: 1200 2021-11-17T22:39:52.217Z,1637188792.217 [DAT](INFO): online mode acknowledged 2021-11-17T22:39:52.218Z,1637188792.218 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:39:55.802Z,1637188795.802 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:39:18.3927 2021-11-17T22:39:55.803Z,1637188795.803 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:40:02.666Z,1637188802.666 [DAT](INFO): DAT read: Rx Time:22:39:24.8673 2021-11-17T22:40:02.666Z,1637188802.666 [DAT](INFO): received an acoustic signal 2021-11-17T22:40:03.471Z,1637188803.471 [DAT](INFO): DAT read: 22:39:24.8672 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 380,-0.48, 2.114, 2.063, 2.057, 2.032, PHS= 0.078, 0.074, 0.010, RAW= 32.8, -40.8, CAL= 35.7, -40.5, ROT= 174.3, 40.5 2021-11-17T22:40:03.472Z,1637188803.472 [DAT](INFO): got valid direction response: 22:39:24.8672 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 380,-0.48, 2.114, 2.063, 2.057, 2.032, PHS= 0.078, 0.074, 0.010, RAW= 32.8, -40.8, CAL= 35.7, -40.5, ROT= 174.3, 40.5 2021-11-17T22:40:03.473Z,1637188803.473 [DAT](INFO): DAT read: 2021-11-17T22:40:03.474Z,1637188803.474 [DAT](INFO): #Rx 1: Read direction message, but no range. 2021-11-17T22:40:03.475Z,1637188803.475 [DAT](INFO): direction in vehicle frame: [ -0.756646 forward, 0.075523 starboard, 0.649448 keelward ] 2021-11-17T22:40:03.872Z,1637188803.872 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:40:03.872Z,1637188803.872 [DAT](INFO): Got DATA 2 2021-11-17T22:40:03.873Z,1637188803.873 [DAT](INFO): DAT read: Source:001 Destination:007 2021-11-17T22:40:03.873Z,1637188803.873 [DAT](INFO): Got Src/Dest after DATA 2021-11-17T22:40:03.874Z,1637188803.874 [DAT](INFO): DATA Src=1, Dst=7 2021-11-17T22:40:03.875Z,1637188803.875 [DAT](INFO): DAT read: CRC:Pass MPD:03.6 PSNR:12.5 AGC:89 SPD:+0.0 CCERR:011 2021-11-17T22:40:03.875Z,1637188803.875 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:03.875Z,1637188803.875 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:03.875Z,1637188803.875 [DAT](INFO): Incoming data is intended for us 2021-11-17T22:40:03.876Z,1637188803.876 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED 2021-11-17T22:40:03.876Z,1637188803.876 [DAT](INFO): Got ack 2021-11-17T22:40:03.876Z,1637188803.876 [DAT](INFO): DAT read: 2021-11-17T22:40:03.889Z,1637188803.889 [DAT](INFO): DAT read: 2021-11-17T22:40:03.890Z,1637188803.890 [DAT](INFO): Sent 18 bytes from file Logs/20211117T215648/Courier0034.lzma.parts 2021-11-17T22:40:03.890Z,1637188803.890 [DAT](INFO): Packets left to send: 0 2021-11-17T22:40:03.897Z,1637188803.897 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-17T22:40:04.755Z,1637188804.755 [DAT](INFO): #Outgoing data=1 2021-11-17T22:40:04.755Z,1637188804.755 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:40:04.852Z,1637188804.852 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:40:08.432Z,1637188808.432 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:39:31.1926 2021-11-17T22:40:08.432Z,1637188808.432 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:40:16.552Z,1637188816.552 [DAT](INFO): DAT read: Rx Time:22:39:38.9674 2021-11-17T22:40:16.552Z,1637188816.552 [DAT](INFO): received an acoustic signal 2021-11-17T22:40:17.744Z,1637188817.744 [DAT](INFO): DAT read: 22:39:38.9674 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 176,-0.33, 1.634, 1.587, 1.564, 1.562, PHS= 0.069, 0.070,-0.013, RAW= 29.4, -28.6, CAL= 32.0, -30.3, ROT= 178.0, 30.3 2021-11-17T22:40:17.745Z,1637188817.745 [DAT](INFO): got valid direction response: 22:39:38.9674 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 176,-0.33, 1.634, 1.587, 1.564, 1.562, PHS= 0.069, 0.070,-0.013, RAW= 29.4, -28.6, CAL= 32.0, -30.3, ROT= 178.0, 30.3 2021-11-17T22:40:17.746Z,1637188817.746 [DAT](INFO): DAT read: 2021-11-17T22:40:17.746Z,1637188817.746 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:40:17.747Z,1637188817.747 [DAT](INFO): Got DATA 2 2021-11-17T22:40:17.747Z,1637188817.747 [DAT](INFO): DAT read: Source:001 Destination:007 2021-11-17T22:40:17.748Z,1637188817.748 [DAT](INFO): Got Src/Dest after DATA 2021-11-17T22:40:17.748Z,1637188817.748 [DAT](INFO): DATA Src=1, Dst=7 2021-11-17T22:40:17.749Z,1637188817.749 [DAT](INFO): DAT read: CRC:Pass MPD:03.6 PSNR:12.0 AGC:91 SPD:+0.0 CCERR:010 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](INFO): Incoming data is intended for us 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](INFO): Got ack 2021-11-17T22:40:17.750Z,1637188817.750 [DAT](INFO): DAT read: 2021-11-17T22:40:17.751Z,1637188817.751 [DAT](INFO): DAT read: 2021-11-17T22:40:17.752Z,1637188817.752 [DAT](INFO): Sent 184 bytes from file Logs/20211117T223619/Courier0000.lzma.parts 2021-11-17T22:40:17.752Z,1637188817.752 [DAT](INFO): Packets left to send: 1 2021-11-17T22:40:17.786Z,1637188817.786 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-17T22:40:17.787Z,1637188817.787 [DAT](INFO): #Rx 2: Read direction message, but no range. 2021-11-17T22:40:17.788Z,1637188817.788 [DAT](INFO): direction in vehicle frame: [ -0.862870 forward, 0.030132 starboard, 0.504528 keelward ] 2021-11-17T22:40:19.251Z,1637188819.251 [DAT](INFO): #Outgoing data=1 2021-11-17T22:40:19.252Z,1637188819.252 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:40:19.524Z,1637188819.524 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:40:23.039Z,1637188823.039 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:39:45.7424 2021-11-17T22:40:23.039Z,1637188823.039 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:40:30.243Z,1637188830.243 [DAT](INFO): DAT read: Rx Time:22:39:52.5177 2021-11-17T22:40:30.244Z,1637188830.244 [DAT](INFO): received an acoustic signal 2021-11-17T22:40:31.453Z,1637188831.453 [DAT](INFO): DAT read: 22:39:52.5177 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 180,-0.34, 1.503, 1.451, 1.430, 1.431, PHS= 0.068, 0.064,-0.016, RAW= 32.3, -26.4, CAL= 35.1, -28.4, ROT= 174.9, 28.4 2021-11-17T22:40:31.454Z,1637188831.454 [DAT](INFO): got valid direction response: 22:39:52.5177 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 180,-0.34, 1.503, 1.451, 1.430, 1.431, PHS= 0.068, 0.064,-0.016, RAW= 32.3, -26.4, CAL= 35.1, -28.4, ROT= 174.9, 28.4 2021-11-17T22:40:31.455Z,1637188831.455 [DAT](INFO): DAT read: 2021-11-17T22:40:31.456Z,1637188831.456 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:40:31.456Z,1637188831.456 [DAT](INFO): Got DATA 2 2021-11-17T22:40:31.457Z,1637188831.457 [DAT](INFO): DAT read: Source:001 Destination:007 2021-11-17T22:40:31.457Z,1637188831.457 [DAT](INFO): Got Src/Dest after DATA 2021-11-17T22:40:31.458Z,1637188831.458 [DAT](INFO): DATA Src=1, Dst=7 2021-11-17T22:40:31.459Z,1637188831.459 [DAT](INFO): DAT read: CRC:Pass MPD:03.6 PSNR:12.4 AGC:90 SPD:+0.0 CCERR:010 2021-11-17T22:40:31.459Z,1637188831.459 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:31.459Z,1637188831.459 [DAT](INFO): Got CRC:Pass 2021-11-17T22:40:31.459Z,1637188831.459 [DAT](INFO): Incoming data is intended for us 2021-11-17T22:40:31.459Z,1637188831.459 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED 2021-11-17T22:40:31.460Z,1637188831.460 [DAT](INFO): Got ack 2021-11-17T22:40:31.460Z,1637188831.460 [DAT](INFO): DAT read: 2021-11-17T22:40:31.460Z,1637188831.460 [DAT](INFO): DAT read: 2021-11-17T22:40:31.465Z,1637188831.465 [DAT](INFO): Sent 56 bytes from file Logs/20211117T223619/Courier0000.lzma.parts 2021-11-17T22:40:31.466Z,1637188831.466 [DAT](INFO): Packets left to send: 0 2021-11-17T22:40:31.468Z,1637188831.468 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-17T22:40:31.468Z,1637188831.468 [DAT](INFO): #Rx 3: Read direction message, but no range. 2021-11-17T22:40:31.478Z,1637188831.478 [DAT](INFO): direction in vehicle frame: [ -0.876166 forward, 0.078196 starboard, 0.475624 keelward ] 2021-11-17T22:40:32.744Z,1637188832.744 [Startup:StartupSatComms:B] Stopped 2021-11-17T22:40:32.754Z,1637188832.754 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2021-11-17T22:40:32.754Z,1637188832.754 [Startup:StartupSatComms] Stopped 2021-11-17T22:40:32.754Z,1637188832.754 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2021-11-17T22:40:32.755Z,1637188832.755 [Startup](INFO): Completed Startup 2021-11-17T22:40:32.755Z,1637188832.755 [MissionManager](INFO): Startup is completed. 2021-11-17T22:40:32.756Z,1637188832.756 [MissionManager](INFO): Uninitializing Mission Startup 2021-11-17T22:40:32.756Z,1637188832.756 [Startup] Stopped 2021-11-17T22:40:32.756Z,1637188832.756 [Startup](DEBUG): Aggregate::uninitialize Startup 2021-11-17T22:40:32.756Z,1637188832.756 [Startup:A.GoToSurface] Stopped 2021-11-17T22:40:32.756Z,1637188832.756 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-11-17T22:40:32.923Z,1637188832.923 [MissionManager](IMPORTANT): Started mission Default 2021-11-17T22:40:32.923Z,1637188832.923 [Default] Running Loop=1 2021-11-17T22:40:32.923Z,1637188832.923 [Default](DEBUG): Aggregate::initialize Default 2021-11-17T22:40:32.923Z,1637188832.923 [Default:B.GoToSurface] Running Loop=1 2021-11-17T22:40:32.923Z,1637188832.923 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-11-17T22:40:32.923Z,1637188832.923 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-11-17T22:40:32.924Z,1637188832.924 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-11-17T22:40:32.924Z,1637188832.924 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-11-17T22:40:32.925Z,1637188832.925 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-11-17T22:40:32.925Z,1637188832.925 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-11-17T22:40:32.925Z,1637188832.925 [Default:A.Wait] Running Loop=1 2021-11-17T22:40:32.925Z,1637188832.925 [Default:A.Wait](DEBUG): Initialize Wait Component. 2021-11-17T22:40:46.187Z,1637188846.187 [Default:A.Wait](INFO): Done Waiting. 2021-11-17T22:40:46.187Z,1637188846.187 [Default:A.Wait] Stopped 2021-11-17T22:40:46.187Z,1637188846.187 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-11-17T22:40:46.530Z,1637188846.530 [Default:CheckIn] Running Loop=1 2021-11-17T22:40:46.530Z,1637188846.530 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-17T22:40:46.531Z,1637188846.531 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-17T22:40:46.944Z,1637188846.944 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2021-11-17T22:41:46.734Z,1637188906.734 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T22:40:46.5Z 2021-11-17T22:41:46.734Z,1637188906.734 [Default:CheckIn:Read_GPS] Stopped 2021-11-17T22:41:46.734Z,1637188906.734 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-17T22:41:47.148Z,1637188907.148 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2021-11-17T22:41:48.005Z,1637188908.005 [DAT](INFO): #Outgoing data=1 2021-11-17T22:41:48.006Z,1637188908.006 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:41:48.096Z,1637188908.096 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:41:51.700Z,1637188911.700 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:41:14.2913 2021-11-17T22:41:51.701Z,1637188911.701 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:41:58.543Z,1637188918.543 [DAT](INFO): DAT read: Rx Time:22:41:20.9192 2021-11-17T22:41:58.544Z,1637188918.544 [DAT](INFO): received an acoustic signal 2021-11-17T22:41:59.763Z,1637188919.763 [DAT](INFO): DAT read: 22:41:20.9192 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 207,-0.20, 1.623, 1.573, 1.551, 1.551, PHS= 0.068, 0.066,-0.015, RAW= 30.7, -27.1, CAL= 33.4, -29.0, ROT= 176.6, 29.0 2021-11-17T22:41:59.782Z,1637188919.782 [DAT](INFO): got valid direction response: 22:41:20.9192 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 207,-0.20, 1.623, 1.573, 1.551, 1.551, PHS= 0.068, 0.066,-0.015, RAW= 30.7, -27.1, CAL= 33.4, -29.0, ROT= 176.6, 29.0 2021-11-17T22:41:59.783Z,1637188919.783 [DAT](INFO): DAT read: 2021-11-17T22:41:59.784Z,1637188919.784 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:41:59.784Z,1637188919.784 [DAT](INFO): Got DATA 2 2021-11-17T22:41:59.785Z,1637188919.785 [DAT](INFO): DAT read: Source:001 Destination:007 2021-11-17T22:41:59.785Z,1637188919.785 [DAT](INFO): Got Src/Dest after DATA 2021-11-17T22:41:59.785Z,1637188919.785 [DAT](INFO): DATA Src=1, Dst=7 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](INFO): DAT read: CRC:Pass MPD:03.6 PSNR:12.6 AGC:89 SPD:+0.0 CCERR:010 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](INFO): Got CRC:Pass 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](INFO): Got CRC:Pass 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](INFO): Incoming data is intended for us 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED 2021-11-17T22:41:59.787Z,1637188919.787 [DAT](INFO): Got ack 2021-11-17T22:41:59.788Z,1637188919.788 [DAT](INFO): DAT read: 2021-11-17T22:41:59.788Z,1637188919.788 [DAT](INFO): DAT read: 2021-11-17T22:41:59.789Z,1637188919.789 [DAT](INFO): Sent 39 bytes from file Logs/20211117T223619/Courier0004.lzma.parts 2021-11-17T22:41:59.789Z,1637188919.789 [DAT](INFO): Packets left to send: 0 2021-11-17T22:41:59.791Z,1637188919.791 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-17T22:41:59.792Z,1637188919.792 [DAT](INFO): #Rx 4: Read direction message, but no range. 2021-11-17T22:41:59.793Z,1637188919.793 [DAT](INFO): direction in vehicle frame: [ -0.873080 forward, 0.051870 starboard, 0.484810 keelward ] 2021-11-17T22:42:00.658Z,1637188920.658 [Default:CheckIn:Read_Iridium] Stopped 2021-11-17T22:42:00.658Z,1637188920.658 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-17T22:42:00.659Z,1637188920.659 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-17T22:42:13.618Z,1637188933.618 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-11-17T22:42:31.841Z,1637188951.841 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2021-11-17T22:42:31.841Z,1637188951.841 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-17T22:42:31.857Z,1637188951.857 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-17T22:42:32.269Z,1637188952.269 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-17T22:42:32.269Z,1637188952.269 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2021-11-17T22:43:00.905Z,1637188980.905 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-17T22:43:00.905Z,1637188980.905 [Default:CheckIn:C.Wait] Stopped 2021-11-17T22:43:00.905Z,1637188980.905 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-17T22:43:00.905Z,1637188980.905 [Default:CheckIn:D] Running Loop=1 2021-11-17T22:43:01.310Z,1637188981.310 [Default:CheckIn:D] Stopped 2021-11-17T22:43:01.310Z,1637188981.310 [Default:CheckIn:E] Running Loop=1 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 2.473117 min 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn:E] Stopped 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn] Stopped 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn](INFO): Running loop #2 2021-11-17T22:43:01.726Z,1637188981.726 [Default:CheckIn] Running Loop=2 2021-11-17T22:43:01.727Z,1637188981.727 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-17T22:43:01.727Z,1637188981.727 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-17T22:44:01.916Z,1637189041.916 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T22:43:01.7Z 2021-11-17T22:44:01.931Z,1637189041.931 [Default:CheckIn:Read_GPS] Stopped 2021-11-17T22:44:01.931Z,1637189041.931 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-17T22:44:03.182Z,1637189043.182 [DAT](INFO): #Outgoing data=1 2021-11-17T22:44:03.182Z,1637189043.182 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:44:03.277Z,1637189043.277 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:44:06.852Z,1637189046.852 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:43:29.4895 2021-11-17T22:44:06.852Z,1637189046.852 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:44:13.739Z,1637189053.739 [DAT](INFO): DAT read: Rx Time:22:43:36.1715 2021-11-17T22:44:13.740Z,1637189053.740 [DAT](INFO): received an acoustic signal 2021-11-17T22:44:14.945Z,1637189054.945 [DAT](INFO): DAT read: 22:43:36.1715 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 217, 0.02, 2.606, 2.556, 2.534, 2.532, PHS= 0.070, 0.068,-0.013, RAW= 31.2, -28.2, CAL= 33.9, -30.0, ROT= 176.1, 30.0 2021-11-17T22:44:14.946Z,1637189054.946 [DAT](INFO): got valid direction response: 22:43:36.1715 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 217, 0.02, 2.606, 2.556, 2.534, 2.532, PHS= 0.070, 0.068,-0.013, RAW= 31.2, -28.2, CAL= 33.9, -30.0, ROT= 176.1, 30.0 2021-11-17T22:44:14.946Z,1637189054.946 [DAT](INFO): DAT read: 2021-11-17T22:44:14.947Z,1637189054.947 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:44:14.947Z,1637189054.947 [DAT](INFO): Got DATA 2 2021-11-17T22:44:14.948Z,1637189054.948 [DAT](INFO): DAT read: Source:001 Destination:007 2021-11-17T22:44:14.949Z,1637189054.949 [DAT](INFO): Got Src/Dest after DATA 2021-11-17T22:44:14.949Z,1637189054.949 [DAT](INFO): DATA Src=1, Dst=7 2021-11-17T22:44:14.950Z,1637189054.950 [DAT](INFO): DAT read: CRC:Pass MPD:03.6 PSNR:12.1 AGC:91 SPD:+0.0 CCERR:010 2021-11-17T22:44:14.950Z,1637189054.950 [DAT](INFO): Got CRC:Pass 2021-11-17T22:44:14.951Z,1637189054.951 [DAT](INFO): Got CRC:Pass 2021-11-17T22:44:14.951Z,1637189054.951 [DAT](INFO): Incoming data is intended for us 2021-11-17T22:44:14.951Z,1637189054.951 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED 2021-11-17T22:44:14.951Z,1637189054.951 [DAT](INFO): Got ack 2021-11-17T22:44:14.951Z,1637189054.951 [DAT](INFO): DAT read: 2021-11-17T22:44:14.952Z,1637189054.952 [DAT](INFO): DAT read: 2021-11-17T22:44:14.952Z,1637189054.952 [DAT](INFO): Sent 39 bytes from file Logs/20211117T223619/Courier0007.lzma.parts 2021-11-17T22:44:14.973Z,1637189054.973 [DAT](INFO): Packets left to send: 0 2021-11-17T22:44:14.976Z,1637189054.976 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER 2021-11-17T22:44:14.983Z,1637189054.983 [DAT](INFO): #Rx 5: Read direction message, but no range. 2021-11-17T22:44:14.984Z,1637189054.984 [DAT](INFO): direction in vehicle frame: [ -0.864020 forward, 0.058903 starboard, 0.500000 keelward ] 2021-11-17T22:44:15.824Z,1637189055.824 [Default:CheckIn:Read_Iridium] Stopped 2021-11-17T22:44:15.824Z,1637189055.824 [Default:CheckIn:C.Wait] Running Loop=1 2021-11-17T22:44:15.825Z,1637189055.825 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-11-17T22:44:32.822Z,1637189072.822 [NAL9602](ERROR): Queried for signal strength and failed to receive proper response. 2021-11-17T22:44:32.905Z,1637189072.905 [NAL9602](ERROR): received: +CSQ:0 OK 2021-11-17T22:44:49.787Z,1637189089.787 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2021-11-17T22:44:49.790Z,1637189089.790 [BPC1](INFO): Received data from all battery sticks. 2021-11-17T22:45:16.064Z,1637189116.064 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-11-17T22:45:16.064Z,1637189116.064 [Default:CheckIn:C.Wait] Stopped 2021-11-17T22:45:16.065Z,1637189116.065 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-11-17T22:45:16.065Z,1637189116.065 [Default:CheckIn:D] Running Loop=1 2021-11-17T22:45:16.471Z,1637189116.471 [Default:CheckIn:D] Stopped 2021-11-17T22:45:16.471Z,1637189116.471 [Default:CheckIn:E] Running Loop=1 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 4.725803 min 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn:E] Stopped 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn] Stopped 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn](INFO): Running loop #3 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn] Running Loop=3 2021-11-17T22:45:16.858Z,1637189116.858 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-11-17T22:45:16.859Z,1637189116.859 [Default:CheckIn:Read_GPS] Running Loop=1 2021-11-17T22:45:32.627Z,1637189132.627 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2021-11-17T22:45:32.627Z,1637189132.627 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-11-17T22:45:32.638Z,1637189132.638 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-11-17T22:45:33.054Z,1637189133.054 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-11-17T22:45:33.054Z,1637189133.054 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2021-11-17T22:46:17.060Z,1637189177.060 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T22:45:16.9Z 2021-11-17T22:46:17.060Z,1637189177.060 [Default:CheckIn:Read_GPS] Stopped 2021-11-17T22:46:17.060Z,1637189177.060 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-11-17T22:46:18.353Z,1637189178.353 [DAT](INFO): #Outgoing data=1 2021-11-17T22:46:18.353Z,1637189178.353 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT 2021-11-17T22:46:18.476Z,1637189178.476 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY 2021-11-17T22:46:21.822Z,1637189181.822 [DAT](INFO): DAT read: Forwarding Delay UpTx time:22:45:44.7876 2021-11-17T22:46:21.822Z,1637189181.822 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING 2021-11-17T22:46:30.247Z,1637189190.247 [DAT](INFO): DAT read: Rx Time:22:45:52.4239 2021-11-17T22:46:30.247Z,1637189190.247 [DAT](INFO): received an acoustic signal 2021-11-17T22:46:31.063Z,1637189191.063 [DAT](INFO): DAT read: 22:45:52.4239 LVL= 32752, 32753, 32754, 32755, AGC= 91, IDX= 228,-0.09, 1.892, 1.839, 1.832, 1.811, PHS= 0.077, 0.072, 0.006, RAW= 33.6, -38.8, CAL= 36.5, -38.8, ROT= 173.5, 38.8 2021-11-17T22:46:31.065Z,1637189191.065 [DAT](INFO): got valid direction response: 22:45:52.4239 LVL= 32752, 32753, 32754, 32755, AGC= 91, IDX= 228,-0.09, 1.892, 1.839, 1.832, 1.811, PHS= 0.077, 0.072, 0.006, RAW= 33.6, -38.8, CAL= 36.5, -38.8, ROT= 173.5, 38.8 2021-11-17T22:46:31.065Z,1637189191.065 [DAT](INFO): DAT read: 2021-11-17T22:46:31.066Z,1637189191.066 [DAT](INFO): DAT read: DATA(0002):~~ 2021-11-17T22:46:31.066Z,1637189191.066 [DAT](INFO